28 Basic Debugging Tactics

Author

Acknowledgements

The trace() function is based on that in HEP by Alison Harper and Tom Monks .
The SimLogger class is adapted from the Python DES RAP Template by Amy Heather and Tom Monks .

When working with your model, it can be hard to know whether it is working correctly. There are a range of different approaches we can take. These include:

Using simple print() statements.
Using a function (e.g. trace()) to control the print() statements.
Using the logging module.
Tests.
Event logging.

28.1 The model

Where code examples are provided, this chapter uses the model from the chapter “An Example SimPy Model”.

Tip

Throughout the code, anything new that’s been added will be followed by the comment ##NEW - so look out for that in the following code chunks.

In each of these examples, we will just run the model once.

class g:
    patient_inter = 5
    mean_n_consult_time = 6
    number_of_nurses = 1
    sim_duration = 120
    number_of_runs = 1  ##NEW - single run

1: Just run the model once.

28.2 Using simple `print()` statements

To get a running record of what is happening in your model, you can add print() statements at key points.

For example, we can add:

A print statement recording when each patient arrives.
A print statement recording when each patient is seen by the nurse (including how long they waited, and how long their consultation then was).

Tip

For another example using print() statements, see the “Reneging, Balking and Jockeying” chapter where they are used, for example, to record:

print (f"Patient {patient.id} reneged after waiting",
       f"{patient.patience_nurse} minutes")

28.2.1 Coding the model

We will modify the Model class to add print statements within the generator_patient_arrivals() and attend_clinic() functions.

def generator_patient_arrivals(self):
    while True:
        self.patient_counter += 1
        p = Patient(self.patient_counter)

        ##NEW - Print message stating patient ID and arrival time
        print(f"Patient {p.id} arrives at: {self.env.now:.3f}.")

        self.env.process(self.attend_clinic(p))
        sampled_inter = random.expovariate(1.0 / g.patient_inter)
        yield self.env.timeout(sampled_inter)

def attend_clinic(self, patient):
    start_q_nurse = self.env.now
    with self.nurse.request() as req:
        yield req
        end_q_nurse = self.env.now
        patient.q_time_nurse = end_q_nurse - start_q_nurse
        sampled_nurse_act_time = random.expovariate(1.0 /
                                                    g.mean_n_consult_time)

        ##NEW - Print message with patient wait and consultation length
        print(
          f"Patient {patient.id} waits for {patient.q_time_nurse:.3f} " +
          f"and is seen at {end_q_nurse}. Consultation length: " +
          f"{sampled_nurse_act_time:.3f}.")

        self.results_df.at[patient.id, "Q Time Nurse"] = (
            patient.q_time_nurse)
        self.results_df.at[patient.id, "Time with Nurse"] = (
            sampled_nurse_act_time)
        yield self.env.timeout(sampled_nurse_act_time)

1: Add print messages with the patient arrival time, wait time, and time with the nurse.

28.2.2 The full code

The full updated code for the model is given below.

Click here to view the full code

import simpy
import random
import pandas as pd


# Class to store global parameter values.  We don't create an instance of this
# class - we just refer to the class blueprint itself to access the numbers
# inside.
class g:
    patient_inter = 5
    mean_n_consult_time = 6
    number_of_nurses = 1
    sim_duration = 120
    number_of_runs = 1  ##NEW - single run


# Class representing patients coming in to the clinic.  Here, patients have
# two attributes that they carry with them - their ID, and the amount of time
# they spent queuing for the nurse.  The ID is passed in when a new patient is
# created.
class Patient:
    def __init__(self, p_id):
        self.id = p_id
        self.q_time_nurse = 0


# Class representing our model of the clinic.
class Model:
    # Constructor to set up the model for a run.  We pass in a run number when
    # we create a new model.
    def __init__(self, run_number):
        # Create a SimPy environment in which everything will live
        self.env = simpy.Environment()

        # Create a patient counter (which we'll use as a patient ID)
        self.patient_counter = 0

        # Create a SimPy resource to represent a nurse, that will live in the
        # environment created above.  The number of this resource we have is
        # specified by the capacity, and we grab this value from our g class.
        self.nurse = simpy.Resource(self.env, capacity=g.number_of_nurses)

        # Store the passed in run number
        self.run_number = run_number

        # Create a new Pandas DataFrame that will store some results against
        # the patient ID (which we'll use as the index).
        self.results_df = pd.DataFrame()
        self.results_df["Patient ID"] = [1]
        self.results_df["Q Time Nurse"] = [0.0]
        self.results_df["Time with Nurse"] = [0.0]
        self.results_df.set_index("Patient ID", inplace=True)

        # Create an attribute to store the mean queuing time for the nurse
        # across this run of the model
        self.mean_q_time_nurse = 0

    # A generator function that represents the DES generator for patient
    # arrivals
    def generator_patient_arrivals(self):
        # We use an infinite loop here to keep doing this indefinitely whilst
        # the simulation runs
        while True:
            # Increment the patient counter by 1 (this means our first patient
            # will have an ID of 1)
            self.patient_counter += 1

            # Create a new patient - an instance of the Patient Class we
            # defined above.  Remember, we pass in the ID when creating a
            # patient - so here we pass the patient counter to use as the ID.
            p = Patient(self.patient_counter)

            ##NEW - Print message stating patient ID and arrival time
            print(f"Patient {p.id} arrives at: {self.env.now:.3f}.")

            # Tell SimPy to start up the attend_clinic generator function with
            # this patient (the generator function that will model the
            # patient's journey through the system)
            self.env.process(self.attend_clinic(p))

            # Randomly sample the time to the next patient arriving.  Here, we
            # sample from an exponential distribution (common for inter-arrival
            # times), and pass in a lambda value of 1 / mean.  The mean
            # inter-arrival time is stored in the g class.
            sampled_inter = random.expovariate(1.0 / g.patient_inter)

            # Freeze this instance of this function in place until the
            # inter-arrival time we sampled above has elapsed.  Note - time in
            # SimPy progresses in "Time Units", which can represent anything
            # you like (just make sure you're consistent within the model)
            yield self.env.timeout(sampled_inter)

    # A generator function that represents the pathway for a patient going
    # through the clinic.  Here the pathway is extremely simple - a patient
    # arrives, waits to see a nurse, and then leaves.
    # The patient object is passed in to the generator function so we can
    # extract information from / record information to it
    def attend_clinic(self, patient):
        # Record the time the patient started queuing for a nurse
        start_q_nurse = self.env.now

        # This code says request a nurse resource, and do all of the following
        # block of code with that nurse resource held in place (and therefore
        # not usable by another patient)
        with self.nurse.request() as req:
            # Freeze the function until the request for a nurse can be met.
            # The patient is currently queuing.
            yield req

            # When we get to this bit of code, control has been passed back to
            # the generator function, and therefore the request for a nurse has
            # been met.  We now have the nurse, and have stopped queuing, so we
            # can record the current time as the time we finished queuing.
            end_q_nurse = self.env.now

            # Calculate the time this patient was queuing for the nurse, and
            # record it in the patient's attribute for this.
            patient.q_time_nurse = end_q_nurse - start_q_nurse

            # Now we'll randomly sample the time this patient with the nurse.
            # Here, we use an Exponential distribution for simplicity, but you
            # would typically use a Log Normal distribution for a real model
            # (we'll come back to that).  As with sampling the inter-arrival
            # times, we grab the mean from the g class, and pass in 1 / mean
            # as the lambda value.
            sampled_nurse_act_time = random.expovariate(1.0 /
                                                        g.mean_n_consult_time)

            ##NEW - Print message with patient wait and consultation length
            print(
              f"Patient {patient.id} waits for {patient.q_time_nurse:.3f} " +
              f"and is seen at {end_q_nurse}. Consultation length: " +
              f"{sampled_nurse_act_time:.3f}.")

            # Here we'll store the queuing time for the nurse and the sampled
            # time to spend with the nurse in the results DataFrame against the
            # ID for this patient.  In real world models, you may not want to
            # bother storing the sampled activity times - but as this is a
            # simple model, we'll do it here.
            # We use a handy property of pandas called .at, which works a bit
            # like .loc.  .at allows us to access (and therefore change) a
            # particular cell in our DataFrame by providing the row and column.
            # Here, we specify the row as the patient ID (the index), and the
            # column for the value we want to update for that patient.
            self.results_df.at[patient.id, "Q Time Nurse"] = (
                patient.q_time_nurse)
            self.results_df.at[patient.id, "Time with Nurse"] = (
                sampled_nurse_act_time)

            # Freeze this function in place for the activity time we sampled
            # above.  This is the patient spending time with the nurse.
            yield self.env.timeout(sampled_nurse_act_time)

            # When the time above elapses, the generator function will return
            # here.  As there's nothing more that we've written, the function
            # will simply end.  This is a sink.  We could choose to add
            # something here if we wanted to record something - e.g. a counter
            # for number of patients that left, recording something about the
            # patients that left at a particular sink etc.

    # This method calculates results over a single run.  Here we just calculate
    # a mean, but in real world models you'd probably want to calculate more.
    def calculate_run_results(self):
        # Take the mean of the queuing times for the nurse across patients in
        # this run of the model.
        self.mean_q_time_nurse = self.results_df["Q Time Nurse"].mean()

    # The run method starts up the DES entity generators, runs the simulation,
    # and in turns calls anything we need to generate results for the run
    def run(self):
        # Start up our DES entity generators that create new patients.  We've
        # only got one in this model, but we'd need to do this for each one if
        # we had multiple generators.
        self.env.process(self.generator_patient_arrivals())

        # Run the model for the duration specified in g class
        self.env.run(until=g.sim_duration)

        # Now the simulation run has finished, call the method that calculates
        # run results
        self.calculate_run_results()

        # Print the run number with the patient-level results from this run of
        # the model
        print (f"Run Number {self.run_number}")
        print (self.results_df)


# Class representing a Trial for our simulation - a batch of simulation runs.
class Trial:
    # The constructor sets up a pandas dataframe that will store the key
    # results from each run (just the mean queuing time for the nurse here)
    # against run number, with run number as the index.
    def  __init__(self):
        self.df_trial_results = pd.DataFrame()
        self.df_trial_results["Run Number"] = [0]
        self.df_trial_results["Mean Q Time Nurse"] = [0.0]
        self.df_trial_results.set_index("Run Number", inplace=True)

    # Method to print out the results from the trial.  In real world models,
    # you'd likely save them as well as (or instead of) printing them
    def print_trial_results(self):
        print ("Trial Results")
        print (self.df_trial_results)

    # Method to run a trial
    def run_trial(self):
        # Run the simulation for the number of runs specified in g class.
        # For each run, we create a new instance of the Model class and call its
        # run method, which sets everything else in motion.  Once the run has
        # completed, we grab out the stored run results (just mean queuing time
        # here) and store it against the run number in the trial results
        # dataframe.
        for run in range(g.number_of_runs):
            my_model = Model(run)
            my_model.run()

            self.df_trial_results.loc[run] = [my_model.mean_q_time_nurse]

        # Once the trial (ie all runs) has completed, print the final results
        self.print_trial_results()

28.2.3 Exploring the outputs

Running the model, we’ll see the following output…

trial = Trial()
trial.run_trial()

Patient 1 arrives at: 0.000.
Patient 1 waits for 0.000 and is seen at 0. Consultation length: 10.724.
Patient 2 arrives at: 0.150.
Patient 3 arrives at: 5.309.
Patient 4 arrives at: 6.371.
Patient 5 arrives at: 7.962.
Patient 2 waits for 10.574 and is seen at 10.724016899760096. Consultation length: 0.200.
Patient 3 waits for 5.615 and is seen at 10.923618999278593. Consultation length: 0.086.
Patient 4 waits for 4.639 and is seen at 11.010046767046207. Consultation length: 8.038.
Patient 5 waits for 11.086 and is seen at 19.04810698254277. Consultation length: 2.322.
Patient 6 arrives at: 23.236.
Patient 6 waits for 0.000 and is seen at 23.23637375971412. Consultation length: 2.582.
Patient 7 arrives at: 24.742.
Patient 7 waits for 1.076 and is seen at 25.818359178321167. Consultation length: 4.804.
Patient 8 arrives at: 28.219.
Patient 8 waits for 2.404 and is seen at 30.622399428034093. Consultation length: 0.806.
Patient 9 arrives at: 31.606.
Patient 9 waits for 0.000 and is seen at 31.6058048759237. Consultation length: 5.891.
Patient 10 arrives at: 37.518.
Patient 10 waits for 0.000 and is seen at 37.518138074459074. Consultation length: 4.926.
Patient 11 arrives at: 43.757.
Patient 11 waits for 0.000 and is seen at 43.75672280585052. Consultation length: 3.754.
Patient 12 arrives at: 47.837.
Patient 12 waits for 0.000 and is seen at 47.83716109080116. Consultation length: 7.447.
Patient 13 arrives at: 51.575.
Patient 13 waits for 3.709 and is seen at 55.283961262528265. Consultation length: 1.232.
Patient 14 arrives at: 56.303.
Patient 14 waits for 0.212 and is seen at 56.51591826312143. Consultation length: 10.233.
Patient 15 arrives at: 57.747.
Patient 16 arrives at: 60.308.
Patient 17 arrives at: 61.744.
Patient 15 waits for 9.002 and is seen at 66.74892482841393. Consultation length: 2.210.
Patient 18 arrives at: 67.211.
Patient 19 arrives at: 67.843.
Patient 16 waits for 8.651 and is seen at 68.95866493071166. Consultation length: 0.340.
Patient 17 waits for 7.555 and is seen at 69.2986542797349. Consultation length: 5.792.
Patient 20 arrives at: 72.047.
Patient 21 arrives at: 74.530.
Patient 18 waits for 7.880 and is seen at 75.09038363936328. Consultation length: 11.580.
Patient 22 arrives at: 76.224.
Patient 23 arrives at: 76.378.
Patient 24 arrives at: 78.546.
Patient 25 arrives at: 84.580.
Patient 19 waits for 18.827 and is seen at 86.66992435703258. Consultation length: 0.061.
Patient 20 waits for 14.684 and is seen at 86.73073461746797. Consultation length: 3.013.
Patient 21 waits for 15.213 and is seen at 89.74391099742128. Consultation length: 0.320.
Patient 22 waits for 13.840 and is seen at 90.06408226252125. Consultation length: 3.324.
Patient 23 waits for 17.010 and is seen at 93.38789010749436. Consultation length: 0.945.
Patient 24 waits for 15.787 and is seen at 94.33269125218459. Consultation length: 7.140.
Patient 25 waits for 16.893 and is seen at 101.47273147144615. Consultation length: 1.942.
Patient 26 arrives at: 101.587.
Patient 27 arrives at: 102.331.
Patient 26 waits for 1.828 and is seen at 103.4147428371654. Consultation length: 2.334.
Patient 28 arrives at: 104.156.
Patient 27 waits for 3.418 and is seen at 105.74893838517372. Consultation length: 6.063.
Patient 29 arrives at: 106.335.
Patient 30 arrives at: 108.924.
Patient 31 arrives at: 109.592.
Patient 32 arrives at: 110.299.
Patient 33 arrives at: 110.538.
Patient 28 waits for 7.656 and is seen at 111.81212331183262. Consultation length: 0.322.
Patient 29 waits for 5.799 and is seen at 112.13404701043532. Consultation length: 6.933.
Patient 34 arrives at: 117.495.
Patient 30 waits for 10.143 and is seen at 119.06730549093024. Consultation length: 0.289.
Patient 31 waits for 9.764 and is seen at 119.35603766629579. Consultation length: 2.345.
Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000        10.724017
2              10.574291         0.199602
3               5.614699         0.086428
4               4.638661         8.038060
5              11.086170         2.321768
6               0.000000         2.581985
7               1.076460         4.804040
8               2.403821         0.806189
9               0.000000         5.891071
10              0.000000         4.926228
11              0.000000         3.754320
12              0.000000         7.446800
13              3.709055         1.231957
14              0.212443        10.233007
15              9.001625         2.209740
16              8.651064         0.339989
17              7.554838         5.791729
18              7.879701        11.579541
19             18.826528         0.060810
20             14.684001         3.013176
21             15.213417         0.320171
22             13.839593         3.323808
23             17.009595         0.944801
24             15.786730         7.140040
25             16.892926         1.942011
26              1.827984         2.334196
27              3.417988         6.063185
28              7.656284         0.321924
29              5.799302         6.933258
30             10.142826         0.288732
31              9.764481         2.344893
Trial Results
            Mean Q Time Nurse
Run Number                   
0                     7.20208

28.3 Using `trace()` to control the `print()` statements

This output is helpful when debugging a single run of the model, but the behaviour is undesirable when running multiple replications.

We can write a function which will toggle whether to run the print() statements or not.

28.3.1 Coding the model

In our parameter class, we add a parameter trace which will control whether the print() statements are executed or not.

class g:
    patient_inter = 5
    mean_n_consult_time = 6
    number_of_nurses = 1
    sim_duration = 120
    number_of_runs = 1  ##NEW - single run
    trace = True  ##NEW - controls whether the print statements are executed

1: Just run the model once.
2: Add trace parameter which will determine whether the print statements are executed.

We then define a new function trace() which will only run if g.trace is true.

##NEW
def trace(msg):
    """ 
    If TRUE will return all patient-level message outputs.

    Arguments:
      msg (string):
        Message output.
    """
    if g.trace:
        print(msg)

1: Define a new function trace() which will print messages if g.trace is true.

Then, in our model, we alter our print() statements so that the message is input to the trace() function.

def generator_patient_arrivals(self):
    while True:
        self.patient_counter += 1
        p = Patient(self.patient_counter)

        ##NEW - Print message stating patient ID and arrival time
        trace(f"Patient {p.id} arrives at: {self.env.now:.3f}.")

        self.env.process(self.attend_clinic(p))
        sampled_inter = random.expovariate(1.0 / g.patient_inter)
        yield self.env.timeout(sampled_inter)

def attend_clinic(self, patient):
    start_q_nurse = self.env.now
    with self.nurse.request() as req:
        yield req
        end_q_nurse = self.env.now
        patient.q_time_nurse = end_q_nurse - start_q_nurse
        sampled_nurse_act_time = random.expovariate(1.0 /
                                                    g.mean_n_consult_time)

        ##NEW - Print message with patient wait and consultation length
        trace(
          f"Patient {patient.id} waits for {patient.q_time_nurse:.3f} " +
          f"and is seen at {end_q_nurse}. Consultation length: " +
          f"{sampled_nurse_act_time:.3f}.")

        self.results_df.at[patient.id, "Q Time Nurse"] = (
            patient.q_time_nurse)
        self.results_df.at[patient.id, "Time with Nurse"] = (
            sampled_nurse_act_time)
        yield self.env.timeout(sampled_nurse_act_time)

1: Change our print() statements to trace().

28.3.2 The full code

The full updated code for the model is given below.

Click here to view the full code

import simpy
import random
import pandas as pd


# Class to store global parameter values.  We don't create an instance of this
# class - we just refer to the class blueprint itself to access the numbers
# inside.
class g:
    patient_inter = 5
    mean_n_consult_time = 6
    number_of_nurses = 1
    sim_duration = 120
    number_of_runs = 1  ##NEW - single run
    trace = True  ##NEW - controls whether the print statements are executed


##NEW
def trace(msg):
    """ 
    If TRUE will return all patient-level message outputs.

    Arguments:
      msg (string):
        Message output.
    """
    if g.trace:
        print(msg)


# Class representing patients coming in to the clinic.  Here, patients have
# two attributes that they carry with them - their ID, and the amount of time
# they spent queuing for the nurse.  The ID is passed in when a new patient is
# created.
class Patient:
    def __init__(self, p_id):
        self.id = p_id
        self.q_time_nurse = 0


# Class representing our model of the clinic.
class Model:
    # Constructor to set up the model for a run.  We pass in a run number when
    # we create a new model.
    def __init__(self, run_number):
        # Create a SimPy environment in which everything will live
        self.env = simpy.Environment()

        # Create a patient counter (which we'll use as a patient ID)
        self.patient_counter = 0

        # Create a SimPy resource to represent a nurse, that will live in the
        # environment created above.  The number of this resource we have is
        # specified by the capacity, and we grab this value from our g class.
        self.nurse = simpy.Resource(self.env, capacity=g.number_of_nurses)

        # Store the passed in run number
        self.run_number = run_number

        # Create a new Pandas DataFrame that will store some results against
        # the patient ID (which we'll use as the index).
        self.results_df = pd.DataFrame()
        self.results_df["Patient ID"] = [1]
        self.results_df["Q Time Nurse"] = [0.0]
        self.results_df["Time with Nurse"] = [0.0]
        self.results_df.set_index("Patient ID", inplace=True)

        # Create an attribute to store the mean queuing time for the nurse
        # across this run of the model
        self.mean_q_time_nurse = 0

    # A generator function that represents the DES generator for patient
    # arrivals
    def generator_patient_arrivals(self):
        # We use an infinite loop here to keep doing this indefinitely whilst
        # the simulation runs
        while True:
            # Increment the patient counter by 1 (this means our first patient
            # will have an ID of 1)
            self.patient_counter += 1

            # Create a new patient - an instance of the Patient Class we
            # defined above.  Remember, we pass in the ID when creating a
            # patient - so here we pass the patient counter to use as the ID.
            p = Patient(self.patient_counter)

            ##NEW - Print message stating patient ID and arrival time
            trace(f"Patient {p.id} arrives at: {self.env.now:.3f}.")

            # Tell SimPy to start up the attend_clinic generator function with
            # this patient (the generator function that will model the
            # patient's journey through the system)
            self.env.process(self.attend_clinic(p))

            # Randomly sample the time to the next patient arriving.  Here, we
            # sample from an exponential distribution (common for inter-arrival
            # times), and pass in a lambda value of 1 / mean.  The mean
            # inter-arrival time is stored in the g class.
            sampled_inter = random.expovariate(1.0 / g.patient_inter)

            # Freeze this instance of this function in place until the
            # inter-arrival time we sampled above has elapsed.  Note - time in
            # SimPy progresses in "Time Units", which can represent anything
            # you like (just make sure you're consistent within the model)
            yield self.env.timeout(sampled_inter)

    # A generator function that represents the pathway for a patient going
    # through the clinic.  Here the pathway is extremely simple - a patient
    # arrives, waits to see a nurse, and then leaves.
    # The patient object is passed in to the generator function so we can
    # extract information from / record information to it
    def attend_clinic(self, patient):
        # Record the time the patient started queuing for a nurse
        start_q_nurse = self.env.now

        # This code says request a nurse resource, and do all of the following
        # block of code with that nurse resource held in place (and therefore
        # not usable by another patient)
        with self.nurse.request() as req:
            # Freeze the function until the request for a nurse can be met.
            # The patient is currently queuing.
            yield req

            # When we get to this bit of code, control has been passed back to
            # the generator function, and therefore the request for a nurse has
            # been met.  We now have the nurse, and have stopped queuing, so we
            # can record the current time as the time we finished queuing.
            end_q_nurse = self.env.now

            # Calculate the time this patient was queuing for the nurse, and
            # record it in the patient's attribute for this.
            patient.q_time_nurse = end_q_nurse - start_q_nurse

            # Now we'll randomly sample the time this patient with the nurse.
            # Here, we use an Exponential distribution for simplicity, but you
            # would typically use a Log Normal distribution for a real model
            # (we'll come back to that).  As with sampling the inter-arrival
            # times, we grab the mean from the g class, and pass in 1 / mean
            # as the lambda value.
            sampled_nurse_act_time = random.expovariate(1.0 /
                                                        g.mean_n_consult_time)

            ##NEW - Print message with patient wait and consultation length
            trace(
              f"Patient {patient.id} waits for {patient.q_time_nurse:.3f} " +
              f"and is seen at {end_q_nurse}. Consultation length: " +
              f"{sampled_nurse_act_time:.3f}.")

            # Here we'll store the queuing time for the nurse and the sampled
            # time to spend with the nurse in the results DataFrame against the
            # ID for this patient.  In real world models, you may not want to
            # bother storing the sampled activity times - but as this is a
            # simple model, we'll do it here.
            # We use a handy property of pandas called .at, which works a bit
            # like .loc.  .at allows us to access (and therefore change) a
            # particular cell in our DataFrame by providing the row and column.
            # Here, we specify the row as the patient ID (the index), and the
            # column for the value we want to update for that patient.
            self.results_df.at[patient.id, "Q Time Nurse"] = (
                patient.q_time_nurse)
            self.results_df.at[patient.id, "Time with Nurse"] = (
                sampled_nurse_act_time)

            # Freeze this function in place for the activity time we sampled
            # above.  This is the patient spending time with the nurse.
            yield self.env.timeout(sampled_nurse_act_time)

            # When the time above elapses, the generator function will return
            # here.  As there's nothing more that we've written, the function
            # will simply end.  This is a sink.  We could choose to add
            # something here if we wanted to record something - e.g. a counter
            # for number of patients that left, recording something about the
            # patients that left at a particular sink etc.

    # This method calculates results over a single run.  Here we just calculate
    # a mean, but in real world models you'd probably want to calculate more.
    def calculate_run_results(self):
        # Take the mean of the queuing times for the nurse across patients in
        # this run of the model.
        self.mean_q_time_nurse = self.results_df["Q Time Nurse"].mean()

    # The run method starts up the DES entity generators, runs the simulation,
    # and in turns calls anything we need to generate results for the run
    def run(self):
        # Start up our DES entity generators that create new patients.  We've
        # only got one in this model, but we'd need to do this for each one if
        # we had multiple generators.
        self.env.process(self.generator_patient_arrivals())

        # Run the model for the duration specified in g class
        self.env.run(until=g.sim_duration)

        # Now the simulation run has finished, call the method that calculates
        # run results
        self.calculate_run_results()

        # Print the run number with the patient-level results from this run of
        # the model
        print (f"Run Number {self.run_number}")
        print (self.results_df)


# Class representing a Trial for our simulation - a batch of simulation runs.
class Trial:
    # The constructor sets up a pandas dataframe that will store the key
    # results from each run (just the mean queuing time for the nurse here)
    # against run number, with run number as the index.
    def  __init__(self):
        self.df_trial_results = pd.DataFrame()
        self.df_trial_results["Run Number"] = [0]
        self.df_trial_results["Mean Q Time Nurse"] = [0.0]
        self.df_trial_results.set_index("Run Number", inplace=True)

    # Method to print out the results from the trial.  In real world models,
    # you'd likely save them as well as (or instead of) printing them
    def print_trial_results(self):
        print ("Trial Results")
        print (self.df_trial_results)

    # Method to run a trial
    def run_trial(self):
        # Run the simulation for the number of runs specified in g class.
        # For each run, we create a new instance of the Model class and call its
        # run method, which sets everything else in motion.  Once the run has
        # completed, we grab out the stored run results (just mean queuing time
        # here) and store it against the run number in the trial results
        # dataframe.
        for run in range(g.number_of_runs):
            my_model = Model(run)
            my_model.run()

            self.df_trial_results.loc[run] = [my_model.mean_q_time_nurse]

        # Once the trial (ie all runs) has completed, print the final results
        self.print_trial_results()

28.3.3 Exploring the outputs

If we set g.trace = False, we will see none of the patient messages are printed (and only our results from print_trial_results() are).

g.trace = False
trial = Trial()
trial.run_trial()

Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000         0.515033
2               0.000000        16.105676
3              13.725436         6.471818
4              16.432416         1.761055
5              15.016513         8.896223
6               3.109157         0.881718
7               0.000000         8.643518
8               8.225063         9.053969
9              12.012615         6.340599
10             14.435000         2.933931
11             17.155207         0.689076
12             13.000332         0.799066
13              8.791537         0.923040
14              0.000000         4.718291
15              4.311246         9.033027
16              9.024959         1.792199
17              8.051979         2.034575
18              0.000000         4.907508
19              0.501197         2.779236
20              0.000000         4.841451
Trial Results
            Mean Q Time Nurse
Run Number                   
0                    7.189633

Meanwhile, if g.trace = True…

g.trace = True
trial = Trial()
trial.run_trial()

Patient 1 arrives at: 0.000.
Patient 1 waits for 0.000 and is seen at 0. Consultation length: 0.949.
Patient 2 arrives at: 2.523.
Patient 2 waits for 0.000 and is seen at 2.5228663887406113. Consultation length: 0.583.
Patient 3 arrives at: 4.029.
Patient 3 waits for 0.000 and is seen at 4.028668137656526. Consultation length: 3.192.
Patient 4 arrives at: 9.921.
Patient 4 waits for 0.000 and is seen at 9.921203417940536. Consultation length: 0.018.
Patient 5 arrives at: 12.577.
Patient 5 waits for 0.000 and is seen at 12.577134658714382. Consultation length: 2.112.
Patient 6 arrives at: 13.534.
Patient 7 arrives at: 14.184.
Patient 6 waits for 1.156 and is seen at 14.689547869979073. Consultation length: 3.523.
Patient 7 waits for 4.029 and is seen at 18.212652512617925. Consultation length: 4.645.
Patient 8 arrives at: 18.886.
Patient 8 waits for 3.972 and is seen at 22.8581446432479. Consultation length: 7.315.
Patient 9 arrives at: 32.497.
Patient 9 waits for 0.000 and is seen at 32.49747626810915. Consultation length: 1.357.
Patient 10 arrives at: 34.010.
Patient 10 waits for 0.000 and is seen at 34.0102442456301. Consultation length: 2.387.
Patient 11 arrives at: 37.645.
Patient 11 waits for 0.000 and is seen at 37.64471969428669. Consultation length: 0.221.
Patient 12 arrives at: 41.007.
Patient 12 waits for 0.000 and is seen at 41.00722601865192. Consultation length: 16.012.
Patient 13 arrives at: 41.038.
Patient 13 waits for 15.981 and is seen at 57.01906588571015. Consultation length: 29.464.
Patient 14 arrives at: 68.510.
Patient 15 arrives at: 74.225.
Patient 14 waits for 17.974 and is seen at 86.48342300181554. Consultation length: 5.123.
Patient 16 arrives at: 87.589.
Patient 15 waits for 17.382 and is seen at 91.6067331429726. Consultation length: 0.934.
Patient 16 waits for 4.951 and is seen at 92.54060165275669. Consultation length: 7.241.
Patient 17 arrives at: 92.939.
Patient 18 arrives at: 94.248.
Patient 17 waits for 6.842 and is seen at 99.78143093758239. Consultation length: 6.249.
Patient 19 arrives at: 100.160.
Patient 18 waits for 11.782 and is seen at 106.03032597390029. Consultation length: 5.033.
Patient 20 arrives at: 110.124.
Patient 19 waits for 10.904 and is seen at 111.06378953900895. Consultation length: 6.669.
Patient 21 arrives at: 114.464.
Patient 20 waits for 7.609 and is seen at 117.73288671184125. Consultation length: 2.026.
Patient 21 waits for 5.295 and is seen at 119.75916138885063. Consultation length: 8.047.
Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000         0.949483
2               0.000000         0.583333
3               0.000000         3.191868
4               0.000000         0.018307
5               0.000000         2.112413
6               1.155695         3.523105
7               4.028798         4.645492
8               3.971928         7.315200
9               0.000000         1.356641
10              0.000000         2.387203
11              0.000000         0.221378
12              0.000000        16.011840
13             15.981472        29.464357
14             17.973793         5.123310
15             17.381797         0.933869
16              4.951300         7.240829
17              6.842006         6.248895
18             11.782468         5.033464
19             10.903800         6.669097
20              7.608666         2.026275
21              5.295051         8.047447
Trial Results
            Mean Q Time Nurse
Run Number                   
0                    5.136989

28.4 Using the logging module

The logging module is a step up from the use of print() statements.

It enables us to choose between printing the messages or saving them to a .log file.

It can also be extended with different types of log message (e.g. INFO, WARNING, ERROR), customised with different colours, and more. Here, we just demonstrate a simple implementation.

28.4.1 Coding the model

28.4.1.1 Imports

First, we need to update our imports.

import logging  ##NEW
import sys  ##NEW
import time  ##NEW

import simpy
import random
import pandas as pd

1: Add logging which we will use to create logs.
2: Add sys which is required when setting up the handler for logging to the console.
3: Add time which we will use is it is desired to save logs to a file with the current date and time.

28.4.1.2 SimLogger class

Next, we will create a new class called SimLogger. This accepts three inputs when setting up:

log_to_console - which determines whether to print log messages.
log_to_file - which determines whether to save the log to a file.
file_path - if saving to file, the path to use.

The class configures handlers for logging (_configure_logging()), and then has a log() method which will be used to save messages to the log in our model.

##NEW
class SimLogger:
    """
    Provides log of events as the simulation runs.
    """
    def __init__(self, log_to_console=False, log_to_file=False,
                file_path=("../outputs/logs/" +
                            f"{time.strftime('%Y-%m-%d_%H-%M-%S')}.log")
      ):
        """
        Initialise the Logger class.

        Arguments:
            log_to_console (boolean):
                Whether to print log messages to the console.
            log_to_file (boolean):
                Whether to save log to a file.
            file_path (str):
                Path to save log to file. Note, if you use an existing .log
                file name, it will append to that log. Defaults to filename
                based on current date and time, and folder '../outputs/log/'.
        """
        self.log_to_console = log_to_console
        self.log_to_file = log_to_file
        self.file_path = file_path
        self.logger = None

        # If logging enabled (either printing to console, file or both), then
        # create logger and configure settings
        if self.log_to_console or self.log_to_file:
            self.logger = logging.getLogger(__name__)
            self._configure_logging()

    def _configure_logging(self):
        """
        Configure the logger.
        """
        # Ensure any existing handlers are removed to avoid duplication
        for handler in self.logger.handlers[:]:
            self.logger.removeHandler(handler)

        # Add handlers for saving messages to file and/or printing to console
        handlers = []
        if self.log_to_file:
            # In write mode, meaning will overwrite existing log of same name
            # (append mode 'a' would add to the end of the log)
            handlers.append(logging.FileHandler(self.file_path, mode='w'))
        if self.log_to_console:
            handlers.append(logging.StreamHandler(sys.stdout))

        # Add handlers directly to the logger
        for handler in handlers:
            self.logger.addHandler(handler)

        # Set logging level and format. If don't set level info, it would
        # only show log messages which are warning, error or critical.
        self.logger.setLevel(logging.INFO)
        formatter = logging.Formatter("%(message)s")
        for handler in handlers:
            handler.setFormatter(formatter)

    def log(self, msg):
        """
        Log a message if logging is enabled.

        Arguments:
            msg (str):
                Message to log.
        """
        if self.log_to_console or self.log_to_file:
            self.logger.info(msg)

1: Set up for the SimLogger class which accepts three inputs, and will call the _configure_logging() method
2: This method configures the loggers, setting up appropriate handlers depending on whether we are printing logs to the console, saving them to the file, or both.
3: This is the equivalent to print() or trace() above.

28.4.1.3 g class

In our g class, we will add an instance of the logging class.

class g:
    patient_inter = 5
    mean_n_consult_time = 6
    number_of_nurses = 1
    sim_duration = 120
    number_of_runs = 1  ##NEW - single run
    ##NEW - instance of the SimLogger class
    logger = SimLogger(log_to_console = True,
                       log_to_file = True,
                       file_path = "./outputs/example_log.log")

1: Just run the model once.
2: Set up SimLogger instance.

28.4.1.4 Model class

For our messages in Model, we now change print() or trace() instead to g.logger.log().

def generator_patient_arrivals(self):
    while True:
        self.patient_counter += 1
        p = Patient(self.patient_counter)

        ##NEW - Log message stating patient ID and arrival time
        g.logger.log(f"Patient {p.id} arrives at: {self.env.now:.3f}.")

        self.env.process(self.attend_clinic(p))
        sampled_inter = random.expovariate(1.0 / g.patient_inter)
        yield self.env.timeout(sampled_inter)

def attend_clinic(self, patient):
    start_q_nurse = self.env.now
    with self.nurse.request() as req:
        yield req
        end_q_nurse = self.env.now
        patient.q_time_nurse = end_q_nurse - start_q_nurse
        sampled_nurse_act_time = random.expovariate(1.0 /
                                                    g.mean_n_consult_time)

        ##NEW - Log message with patient wait and consultation length
        g.logger.log(
          f"Patient {patient.id} waits for {patient.q_time_nurse:.3f} " +
          f"and is seen at {end_q_nurse}. Consultation length: " +
          f"{sampled_nurse_act_time:.3f}.")

        self.results_df.at[patient.id, "Q Time Nurse"] = (
            patient.q_time_nurse)
        self.results_df.at[patient.id, "Time with Nurse"] = (
            sampled_nurse_act_time)
        yield self.env.timeout(sampled_nurse_act_time)

1: Change print()/trace() to log().

28.4.2 The full code

The full updated code for the model is given below.

Click here to view the full code

import logging  ##NEW
import sys  ##NEW
import time  ##NEW

import simpy
import random
import pandas as pd


##NEW
class SimLogger:
    """
    Provides log of events as the simulation runs.
    """
    def __init__(self, log_to_console=False, log_to_file=False,
                file_path=("../outputs/logs/" +
                            f"{time.strftime('%Y-%m-%d_%H-%M-%S')}.log")
      ):
        """
        Initialise the Logger class.

        Arguments:
            log_to_console (boolean):
                Whether to print log messages to the console.
            log_to_file (boolean):
                Whether to save log to a file.
            file_path (str):
                Path to save log to file. Note, if you use an existing .log
                file name, it will append to that log. Defaults to filename
                based on current date and time, and folder '../outputs/log/'.
        """
        self.log_to_console = log_to_console
        self.log_to_file = log_to_file
        self.file_path = file_path
        self.logger = None

        # If logging enabled (either printing to console, file or both), then
        # create logger and configure settings
        if self.log_to_console or self.log_to_file:
            self.logger = logging.getLogger(__name__)
            self._configure_logging()

    def _configure_logging(self):
        """
        Configure the logger.
        """
        # Ensure any existing handlers are removed to avoid duplication
        for handler in self.logger.handlers[:]:
            self.logger.removeHandler(handler)

        # Add handlers for saving messages to file and/or printing to console
        handlers = []
        if self.log_to_file:
            # In write mode, meaning will overwrite existing log of same name
            # (append mode 'a' would add to the end of the log)
            handlers.append(logging.FileHandler(self.file_path, mode='w'))
        if self.log_to_console:
            handlers.append(logging.StreamHandler(sys.stdout))

        # Add handlers directly to the logger
        for handler in handlers:
            self.logger.addHandler(handler)

        # Set logging level and format. If don't set level info, it would
        # only show log messages which are warning, error or critical.
        self.logger.setLevel(logging.INFO)
        formatter = logging.Formatter("%(message)s")
        for handler in handlers:
            handler.setFormatter(formatter)

    def log(self, msg):
        """
        Log a message if logging is enabled.

        Arguments:
            msg (str):
                Message to log.
        """
        if self.log_to_console or self.log_to_file:
            self.logger.info(msg)


# Class to store global parameter values.  We don't create an instance of this
# class - we just refer to the class blueprint itself to access the numbers
# inside.
class g:
    patient_inter = 5
    mean_n_consult_time = 6
    number_of_nurses = 1
    sim_duration = 120
    number_of_runs = 1  ##NEW - single run
    ##NEW - instance of the SimLogger class
    logger = SimLogger(log_to_console = True,
                       log_to_file = True,
                       file_path = "./outputs/example_log.log")


# Class representing patients coming in to the clinic.  Here, patients have
# two attributes that they carry with them - their ID, and the amount of time
# they spent queuing for the nurse.  The ID is passed in when a new patient is
# created.
class Patient:
    def __init__(self, p_id):
        self.id = p_id
        self.q_time_nurse = 0


# Class representing our model of the clinic.
class Model:
    # Constructor to set up the model for a run.  We pass in a run number when
    # we create a new model.
    def __init__(self, run_number):
        # Create a SimPy environment in which everything will live
        self.env = simpy.Environment()

        # Create a patient counter (which we'll use as a patient ID)
        self.patient_counter = 0

        # Create a SimPy resource to represent a nurse, that will live in the
        # environment created above.  The number of this resource we have is
        # specified by the capacity, and we grab this value from our g class.
        self.nurse = simpy.Resource(self.env, capacity=g.number_of_nurses)

        # Store the passed in run number
        self.run_number = run_number

        # Create a new Pandas DataFrame that will store some results against
        # the patient ID (which we'll use as the index).
        self.results_df = pd.DataFrame()
        self.results_df["Patient ID"] = [1]
        self.results_df["Q Time Nurse"] = [0.0]
        self.results_df["Time with Nurse"] = [0.0]
        self.results_df.set_index("Patient ID", inplace=True)

        # Create an attribute to store the mean queuing time for the nurse
        # across this run of the model
        self.mean_q_time_nurse = 0

    # A generator function that represents the DES generator for patient
    # arrivals
    def generator_patient_arrivals(self):
        # We use an infinite loop here to keep doing this indefinitely whilst
        # the simulation runs
        while True:
            # Increment the patient counter by 1 (this means our first patient
            # will have an ID of 1)
            self.patient_counter += 1

            # Create a new patient - an instance of the Patient Class we
            # defined above.  Remember, we pass in the ID when creating a
            # patient - so here we pass the patient counter to use as the ID.
            p = Patient(self.patient_counter)

            ##NEW - Log message stating patient ID and arrival time
            g.logger.log(f"Patient {p.id} arrives at: {self.env.now:.3f}.")

            # Tell SimPy to start up the attend_clinic generator function with
            # this patient (the generator function that will model the
            # patient's journey through the system)
            self.env.process(self.attend_clinic(p))

            # Randomly sample the time to the next patient arriving.  Here, we
            # sample from an exponential distribution (common for inter-arrival
            # times), and pass in a lambda value of 1 / mean.  The mean
            # inter-arrival time is stored in the g class.
            sampled_inter = random.expovariate(1.0 / g.patient_inter)

            # Freeze this instance of this function in place until the
            # inter-arrival time we sampled above has elapsed.  Note - time in
            # SimPy progresses in "Time Units", which can represent anything
            # you like (just make sure you're consistent within the model)
            yield self.env.timeout(sampled_inter)

    # A generator function that represents the pathway for a patient going
    # through the clinic.  Here the pathway is extremely simple - a patient
    # arrives, waits to see a nurse, and then leaves.
    # The patient object is passed in to the generator function so we can
    # extract information from / record information to it
    def attend_clinic(self, patient):
        # Record the time the patient started queuing for a nurse
        start_q_nurse = self.env.now

        # This code says request a nurse resource, and do all of the following
        # block of code with that nurse resource held in place (and therefore
        # not usable by another patient)
        with self.nurse.request() as req:
            # Freeze the function until the request for a nurse can be met.
            # The patient is currently queuing.
            yield req

            # When we get to this bit of code, control has been passed back to
            # the generator function, and therefore the request for a nurse has
            # been met.  We now have the nurse, and have stopped queuing, so we
            # can record the current time as the time we finished queuing.
            end_q_nurse = self.env.now

            # Calculate the time this patient was queuing for the nurse, and
            # record it in the patient's attribute for this.
            patient.q_time_nurse = end_q_nurse - start_q_nurse

            # Now we'll randomly sample the time this patient with the nurse.
            # Here, we use an Exponential distribution for simplicity, but you
            # would typically use a Log Normal distribution for a real model
            # (we'll come back to that).  As with sampling the inter-arrival
            # times, we grab the mean from the g class, and pass in 1 / mean
            # as the lambda value.
            sampled_nurse_act_time = random.expovariate(1.0 /
                                                        g.mean_n_consult_time)

            ##NEW - Log message with patient wait and consultation length
            g.logger.log(
              f"Patient {patient.id} waits for {patient.q_time_nurse:.3f} " +
              f"and is seen at {end_q_nurse}. Consultation length: " +
              f"{sampled_nurse_act_time:.3f}.")

            # Here we'll store the queuing time for the nurse and the sampled
            # time to spend with the nurse in the results DataFrame against the
            # ID for this patient.  In real world models, you may not want to
            # bother storing the sampled activity times - but as this is a
            # simple model, we'll do it here.
            # We use a handy property of pandas called .at, which works a bit
            # like .loc.  .at allows us to access (and therefore change) a
            # particular cell in our DataFrame by providing the row and column.
            # Here, we specify the row as the patient ID (the index), and the
            # column for the value we want to update for that patient.
            self.results_df.at[patient.id, "Q Time Nurse"] = (
                patient.q_time_nurse)
            self.results_df.at[patient.id, "Time with Nurse"] = (
                sampled_nurse_act_time)

            # Freeze this function in place for the activity time we sampled
            # above.  This is the patient spending time with the nurse.
            yield self.env.timeout(sampled_nurse_act_time)

            # When the time above elapses, the generator function will return
            # here.  As there's nothing more that we've written, the function
            # will simply end.  This is a sink.  We could choose to add
            # something here if we wanted to record something - e.g. a counter
            # for number of patients that left, recording something about the
            # patients that left at a particular sink etc.

    # This method calculates results over a single run.  Here we just calculate
    # a mean, but in real world models you'd probably want to calculate more.
    def calculate_run_results(self):
        # Take the mean of the queuing times for the nurse across patients in
        # this run of the model.
        self.mean_q_time_nurse = self.results_df["Q Time Nurse"].mean()

    # The run method starts up the DES entity generators, runs the simulation,
    # and in turns calls anything we need to generate results for the run
    def run(self):
        # Start up our DES entity generators that create new patients.  We've
        # only got one in this model, but we'd need to do this for each one if
        # we had multiple generators.
        self.env.process(self.generator_patient_arrivals())

        # Run the model for the duration specified in g class
        self.env.run(until=g.sim_duration)

        # Now the simulation run has finished, call the method that calculates
        # run results
        self.calculate_run_results()

        # Print the run number with the patient-level results from this run of
        # the model
        print (f"Run Number {self.run_number}")
        print (self.results_df)


# Class representing a Trial for our simulation - a batch of simulation runs.
class Trial:
    # The constructor sets up a pandas dataframe that will store the key
    # results from each run (just the mean queuing time for the nurse here)
    # against run number, with run number as the index.
    def  __init__(self):
        self.df_trial_results = pd.DataFrame()
        self.df_trial_results["Run Number"] = [0]
        self.df_trial_results["Mean Q Time Nurse"] = [0.0]
        self.df_trial_results.set_index("Run Number", inplace=True)

    # Method to print out the results from the trial.  In real world models,
    # you'd likely save them as well as (or instead of) printing them
    def print_trial_results(self):
        print ("Trial Results")
        print (self.df_trial_results)

    # Method to run a trial
    def run_trial(self):
        # Run the simulation for the number of runs specified in g class.
        # For each run, we create a new instance of the Model class and call its
        # run method, which sets everything else in motion.  Once the run has
        # completed, we grab out the stored run results (just mean queuing time
        # here) and store it against the run number in the trial results
        # dataframe.
        for run in range(g.number_of_runs):
            my_model = Model(run)
            my_model.run()

            self.df_trial_results.loc[run] = [my_model.mean_q_time_nurse]

        # Once the trial (ie all runs) has completed, print the final results
        self.print_trial_results()

28.4.3 Exploring the outputs

We will run the model with log_to_console and log_to_file both enabled.

You’ll see that the logs are printed as before…

trial = Trial()
trial.run_trial()

Patient 1 arrives at: 0.000.
Patient 1 waits for 0.000 and is seen at 0. Consultation length: 20.445.
Patient 2 arrives at: 3.228.
Patient 3 arrives at: 4.778.
Patient 4 arrives at: 11.542.
Patient 5 arrives at: 17.416.
Patient 6 arrives at: 18.391.
Patient 2 waits for 17.217 and is seen at 20.444720365535566. Consultation length: 1.084.
Patient 3 waits for 16.751 and is seen at 21.528518818320162. Consultation length: 14.875.
Patient 7 arrives at: 27.049.
Patient 8 arrives at: 28.655.
Patient 4 waits for 24.862 and is seen at 36.40390758388942. Consultation length: 4.679.
Patient 5 waits for 23.667 and is seen at 41.082495475966006. Consultation length: 2.006.
Patient 6 waits for 24.698 and is seen at 43.08886529597139. Consultation length: 7.335.
Patient 7 waits for 23.376 and is seen at 50.42416096680088. Consultation length: 5.859.
Patient 9 arrives at: 53.623.
Patient 10 arrives at: 55.255.
Patient 8 waits for 27.629 and is seen at 56.283553427328705. Consultation length: 12.748.
Patient 11 arrives at: 60.851.
Patient 12 arrives at: 63.044.
Patient 13 arrives at: 65.438.
Patient 14 arrives at: 67.370.
Patient 9 waits for 15.409 and is seen at 69.03203453539484. Consultation length: 2.009.
Patient 10 waits for 15.786 and is seen at 71.04113540869592. Consultation length: 4.370.
Patient 15 arrives at: 72.523.
Patient 16 arrives at: 73.250.
Patient 11 waits for 14.560 and is seen at 75.41091250233481. Consultation length: 3.733.
Patient 12 waits for 16.100 and is seen at 79.14375033636888. Consultation length: 3.217.
Patient 17 arrives at: 79.729.
Patient 18 arrives at: 82.031.
Patient 19 arrives at: 82.323.
Patient 13 waits for 16.923 and is seen at 82.36092079540045. Consultation length: 11.472.
Patient 20 arrives at: 90.199.
Patient 14 waits for 26.463 and is seen at 93.83269016595533. Consultation length: 1.226.
Patient 15 waits for 22.536 and is seen at 95.05869993983505. Consultation length: 9.555.
Patient 21 arrives at: 98.437.
Patient 22 arrives at: 99.959.
Patient 23 arrives at: 102.641.
Patient 16 waits for 31.363 and is seen at 104.61344903851816. Consultation length: 1.378.
Patient 17 waits for 26.263 and is seen at 105.99147015629434. Consultation length: 16.713.
Patient 24 arrives at: 113.694.
Patient 25 arrives at: 118.770.
Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000        20.444720
2              17.217182         1.083798
3              16.750729        14.875389
4              24.862249         4.678588
5              23.666877         2.006370
6              24.698140         7.335296
7              23.375503         5.859392
8              27.629033        12.748481
9              15.409151         2.009101
10             15.785961         4.369777
11             14.560386         3.732838
12             16.099564         3.217170
13             16.922809        11.471769
14             26.462548         1.226010
15             22.535522         9.554749
16             31.363139         1.378021
17             26.262731        16.713489
Trial Results
            Mean Q Time Nurse
Run Number                   
0                   20.211854

…but also, a .log file has been generated containing the logs:

with open("outputs/example_log.log") as f:
    print(f.read())

Patient 1 arrives at: 0.000.
Patient 1 waits for 0.000 and is seen at 0. Consultation length: 20.445.
Patient 2 arrives at: 3.228.
Patient 3 arrives at: 4.778.
Patient 4 arrives at: 11.542.
Patient 5 arrives at: 17.416.
Patient 6 arrives at: 18.391.
Patient 2 waits for 17.217 and is seen at 20.444720365535566. Consultation length: 1.084.
Patient 3 waits for 16.751 and is seen at 21.528518818320162. Consultation length: 14.875.
Patient 7 arrives at: 27.049.
Patient 8 arrives at: 28.655.
Patient 4 waits for 24.862 and is seen at 36.40390758388942. Consultation length: 4.679.
Patient 5 waits for 23.667 and is seen at 41.082495475966006. Consultation length: 2.006.
Patient 6 waits for 24.698 and is seen at 43.08886529597139. Consultation length: 7.335.
Patient 7 waits for 23.376 and is seen at 50.42416096680088. Consultation length: 5.859.
Patient 9 arrives at: 53.623.
Patient 10 arrives at: 55.255.
Patient 8 waits for 27.629 and is seen at 56.283553427328705. Consultation length: 12.748.
Patient 11 arrives at: 60.851.
Patient 12 arrives at: 63.044.
Patient 13 arrives at: 65.438.
Patient 14 arrives at: 67.370.
Patient 9 waits for 15.409 and is seen at 69.03203453539484. Consultation length: 2.009.
Patient 10 waits for 15.786 and is seen at 71.04113540869592. Consultation length: 4.370.
Patient 15 arrives at: 72.523.
Patient 16 arrives at: 73.250.
Patient 11 waits for 14.560 and is seen at 75.41091250233481. Consultation length: 3.733.
Patient 12 waits for 16.100 and is seen at 79.14375033636888. Consultation length: 3.217.
Patient 17 arrives at: 79.729.
Patient 18 arrives at: 82.031.
Patient 19 arrives at: 82.323.
Patient 13 waits for 16.923 and is seen at 82.36092079540045. Consultation length: 11.472.
Patient 20 arrives at: 90.199.
Patient 14 waits for 26.463 and is seen at 93.83269016595533. Consultation length: 1.226.
Patient 15 waits for 22.536 and is seen at 95.05869993983505. Consultation length: 9.555.
Patient 21 arrives at: 98.437.
Patient 22 arrives at: 99.959.
Patient 23 arrives at: 102.641.
Patient 16 waits for 31.363 and is seen at 104.61344903851816. Consultation length: 1.378.
Patient 17 waits for 26.263 and is seen at 105.99147015629434. Consultation length: 16.713.
Patient 24 arrives at: 113.694.
Patient 25 arrives at: 118.770.

Tip

For a more detailed logging implementation, see the Python DES RAP Template - the file notebooks/logs.ipynb is a good place to start.

That implementation includes:

Log of the model state at initialisation and parameters used.
A sanitise_object function which removes object references when logging things like a simpy.Resource.
Simulation time at the start of every log message.
Different emojis for different patient types and activities (including distinguishing warm-up and non-warm-up patients).
A nicely formatted output including colours thanks to the rich module.

28.5 Tests

Testing is the process of evaluating a model to ensure it works as expected, gives reliable results, and can handle different conditions.

By checking for errors and unexpected results, it helps improve the quality of the model, catch errors and prevent future issues.

Testing is explored in more detail in its own chapter: Chapter 29.

28.6 Event logging

Building up our own event logs give us a very clear picture of what is happening to every entity throughout our model.

They are a valuable debugging technique, and by structuring them correctly, we can start to build up a bank of code that can be used to debug very different models with no or minimal changes to our code that processes the event logs. They can also then be used for building animated visuals of the flow of entities through our model.

As this is a more involved approach, it has been placed in its own chapter here.

28.1 The model

28.2 Using simple print() statements

28.2.1 Coding the model

28.2.2 The full code

28.2.3 Exploring the outputs

28.3 Using trace() to control the print() statements

28.3.1 Coding the model

28.3.2 The full code

28.3.3 Exploring the outputs

28.4 Using the logging module

28.4.1 Coding the model

28.4.1.1 Imports

28.4.1.2 SimLogger class

28.4.1.3 g class

28.4.1.4 Model class

28.4.2 The full code

28.4.3 Exploring the outputs

28.5 Tests

28.6 Event logging

28.2 Using simple `print()` statements

28.3 Using `trace()` to control the `print()` statements