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 github.com/pythonhealthdatascience/pydesrap_mms 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: 11.361.
Patient 2 arrives at: 1.215.
Patient 3 arrives at: 10.075.
Patient 2 waits for 10.146 and is seen at 11.361223025647098. Consultation length: 0.959.
Patient 3 waits for 2.245 and is seen at 12.32034533137447. Consultation length: 0.907.
Patient 4 arrives at: 15.757.
Patient 4 waits for 0.000 and is seen at 15.757401416310442. Consultation length: 0.610.
Patient 5 arrives at: 33.968.
Patient 5 waits for 0.000 and is seen at 33.967948139194725. Consultation length: 0.067.
Patient 6 arrives at: 36.620.
Patient 6 waits for 0.000 and is seen at 36.61957464339469. Consultation length: 4.306.
Patient 7 arrives at: 38.515.
Patient 7 waits for 2.410 and is seen at 40.9250964328741. Consultation length: 10.170.
Patient 8 arrives at: 43.678.
Patient 9 arrives at: 45.997.
Patient 10 arrives at: 48.131.
Patient 8 waits for 7.416 and is seen at 51.09466250463547. Consultation length: 1.758.
Patient 9 waits for 6.856 and is seen at 52.85276746710498. Consultation length: 2.712.
Patient 10 waits for 7.434 and is seen at 55.56499932459664. Consultation length: 11.540.
Patient 11 arrives at: 56.949.
Patient 12 arrives at: 60.595.
Patient 13 arrives at: 60.925.
Patient 14 arrives at: 65.965.
Patient 11 waits for 10.156 and is seen at 67.10491921961064. Consultation length: 4.495.
Patient 15 arrives at: 68.633.
Patient 12 waits for 11.005 and is seen at 71.59988421947992. Consultation length: 16.689.
Patient 16 arrives at: 79.913.
Patient 17 arrives at: 82.325.
Patient 18 arrives at: 85.720.
Patient 19 arrives at: 87.917.
Patient 13 waits for 27.364 and is seen at 88.28882818825394. Consultation length: 4.029.
Patient 14 waits for 26.353 and is seen at 92.3180506782778. Consultation length: 6.969.
Patient 20 arrives at: 97.912.
Patient 15 waits for 30.654 and is seen at 99.28672464687374. Consultation length: 4.239.
Patient 16 waits for 23.612 and is seen at 103.52563052473577. Consultation length: 1.578.
Patient 17 waits for 22.779 and is seen at 105.10345262949843. Consultation length: 5.395.
Patient 18 waits for 24.779 and is seen at 110.49860806360809. Consultation length: 3.680.
Patient 19 waits for 26.262 and is seen at 114.17902377795998. Consultation length: 1.405.
Patient 21 arrives at: 114.251.
Patient 20 waits for 17.671 and is seen at 115.58372983343091. Consultation length: 5.300.
Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000        11.361223
2              10.146495         0.959122
3               2.244904         0.906995
4               0.000000         0.609612
5               0.000000         0.067498
6               0.000000         4.305522
7               2.410242        10.169566
8               7.416351         1.758105
9               6.855537         2.712232
10              7.434386        11.539920
11             10.155822         4.494965
12             11.005306        16.688944
13             27.363862         4.029222
14             26.353187         6.968674
15             30.654051         4.238906
16             23.612260         1.577822
17             22.778801         5.395155
18             24.779021         3.680416
19             26.262079         1.404706
20             17.671425         5.299847
Trial Results
            Mean Q Time Nurse
Run Number                   
0                   12.857186

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         5.103945
2               3.205187         3.580706
3               0.000000         0.503247
4               0.000000         0.896004
5               0.000000         5.748758
6               0.000000        10.149807
7               9.637806         4.585700
8               0.000000         5.527218
9               1.010662         2.061586
10              2.998741        10.759707
11              9.620443         7.915775
12             10.729670         2.675265
13              0.000000         8.109009
14              0.000000         0.061867
15              0.000000         4.307998
16              0.000000         7.668730
17              3.331483         5.361548
Trial Results
            Mean Q Time Nurse
Run Number                   
0                    2.384352

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: 3.126.
Patient 2 arrives at: 1.696.
Patient 3 arrives at: 2.349.
Patient 2 waits for 1.430 and is seen at 3.1260207599169982. Consultation length: 2.219.
Patient 4 arrives at: 4.717.
Patient 3 waits for 2.996 and is seen at 5.345189285439252. Consultation length: 2.612.
Patient 5 arrives at: 7.114.
Patient 4 waits for 3.241 and is seen at 7.9576771428229875. Consultation length: 6.805.
Patient 6 arrives at: 8.607.
Patient 7 arrives at: 9.141.
Patient 8 arrives at: 9.422.
Patient 9 arrives at: 13.422.
Patient 5 waits for 7.649 and is seen at 14.762467383472185. Consultation length: 19.089.
Patient 10 arrives at: 16.385.
Patient 11 arrives at: 16.754.
Patient 12 arrives at: 18.134.
Patient 13 arrives at: 23.749.
Patient 14 arrives at: 29.109.
Patient 6 waits for 25.244 and is seen at 33.851342781034816. Consultation length: 0.761.
Patient 15 arrives at: 34.216.
Patient 7 waits for 25.472 and is seen at 34.612624100823204. Consultation length: 5.148.
Patient 16 arrives at: 34.887.
Patient 17 arrives at: 35.198.
Patient 8 waits for 30.339 and is seen at 39.76059632656547. Consultation length: 4.396.
Patient 18 arrives at: 42.284.
Patient 19 arrives at: 42.972.
Patient 9 waits for 30.734 and is seen at 44.156181695096606. Consultation length: 2.544.
Patient 20 arrives at: 45.245.
Patient 21 arrives at: 46.425.
Patient 10 waits for 30.315 and is seen at 46.70064901323655. Consultation length: 8.921.
Patient 11 waits for 38.868 and is seen at 55.62155311077225. Consultation length: 5.424.
Patient 12 waits for 42.912 and is seen at 61.04508087266179. Consultation length: 5.044.
Patient 22 arrives at: 62.545.
Patient 23 arrives at: 64.688.
Patient 13 waits for 42.339 and is seen at 66.08868476452511. Consultation length: 9.011.
Patient 24 arrives at: 66.853.
Patient 25 arrives at: 70.124.
Patient 26 arrives at: 72.730.
Patient 27 arrives at: 73.084.
Patient 28 arrives at: 74.011.
Patient 29 arrives at: 74.474.
Patient 14 waits for 45.991 and is seen at 75.09968668142447. Consultation length: 2.752.
Patient 30 arrives at: 77.167.
Patient 15 waits for 43.636 and is seen at 77.8518724867598. Consultation length: 10.258.
Patient 31 arrives at: 82.113.
Patient 32 arrives at: 86.365.
Patient 33 arrives at: 86.666.
Patient 34 arrives at: 86.890.
Patient 35 arrives at: 87.264.
Patient 16 waits for 53.222 and is seen at 88.10945802603159. Consultation length: 5.908.
Patient 36 arrives at: 92.168.
Patient 17 waits for 58.819 and is seen at 94.01771955843867. Consultation length: 2.189.
Patient 37 arrives at: 95.648.
Patient 38 arrives at: 95.791.
Patient 18 waits for 53.923 and is seen at 96.20630520809446. Consultation length: 7.337.
Patient 39 arrives at: 97.463.
Patient 40 arrives at: 101.843.
Patient 19 waits for 60.571 and is seen at 103.54343472409994. Consultation length: 11.985.
Patient 41 arrives at: 105.232.
Patient 42 arrives at: 106.756.
Patient 43 arrives at: 108.859.
Patient 44 arrives at: 110.643.
Patient 20 waits for 70.283 and is seen at 115.52811535654938. Consultation length: 0.933.
Patient 45 arrives at: 116.434.
Patient 21 waits for 70.036 and is seen at 116.46093882214575. Consultation length: 8.852.
Patient 46 arrives at: 116.548.
Patient 47 arrives at: 117.991.
Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000         3.126021
2               1.429616         2.219169
3               2.996034         2.612488
4               3.240551         6.804790
5               7.648827        19.088875
6              25.243963         0.761281
7              25.471680         5.147972
8              30.338507         4.395585
9              30.734043         2.544467
10             30.315451         8.920904
11             38.867700         5.423528
12             42.911571         5.043604
13             42.339401         9.011002
14             45.990538         2.752186
15             43.636037        10.257586
16             53.222234         5.908262
17             58.819284         2.188586
18             53.922779         7.337130
19             60.571367        11.984681
20             70.283145         0.932823
21             70.035632         8.851560
Trial Results
            Mean Q Time Nurse
Run Number                   
0                   35.143731

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: 9.128.
Patient 2 arrives at: 1.390.
Patient 2 waits for 7.738 and is seen at 9.128216275837325. Consultation length: 0.325.
Patient 3 arrives at: 21.178.
Patient 3 waits for 0.000 and is seen at 21.177969726684417. Consultation length: 13.762.
Patient 4 arrives at: 30.770.
Patient 5 arrives at: 32.450.
Patient 4 waits for 4.171 and is seen at 34.940392821031836. Consultation length: 0.807.
Patient 5 waits for 3.297 and is seen at 35.747504482065075. Consultation length: 3.522.
Patient 6 arrives at: 37.079.
Patient 6 waits for 2.190 and is seen at 39.2693440979408. Consultation length: 10.124.
Patient 7 arrives at: 42.210.
Patient 8 arrives at: 44.802.
Patient 9 arrives at: 48.804.
Patient 7 waits for 7.184 and is seen at 49.3932266384662. Consultation length: 12.451.
Patient 10 arrives at: 54.891.
Patient 11 arrives at: 55.136.
Patient 12 arrives at: 55.743.
Patient 8 waits for 17.042 and is seen at 61.8441640569845. Consultation length: 7.606.
Patient 13 arrives at: 64.568.
Patient 14 arrives at: 65.082.
Patient 15 arrives at: 65.756.
Patient 16 arrives at: 67.081.
Patient 17 arrives at: 67.639.
Patient 9 waits for 20.646 and is seen at 69.44972369061622. Consultation length: 12.086.
Patient 18 arrives at: 80.132.
Patient 10 waits for 26.644 and is seen at 81.5356596517137. Consultation length: 7.752.
Patient 19 arrives at: 83.164.
Patient 20 arrives at: 83.816.
Patient 21 arrives at: 87.314.
Patient 11 waits for 34.151 and is seen at 89.28746953697762. Consultation length: 1.815.
Patient 12 waits for 35.360 and is seen at 91.10257771342164. Consultation length: 3.558.
Patient 13 waits for 30.093 and is seen at 94.6610386462429. Consultation length: 1.240.
Patient 14 waits for 30.819 and is seen at 95.90100881905825. Consultation length: 0.904.
Patient 15 waits for 31.049 and is seen at 96.80513148137655. Consultation length: 7.041.
Patient 16 waits for 36.765 and is seen at 103.84660101836144. Consultation length: 6.569.
Patient 22 arrives at: 106.052.
Patient 17 waits for 42.776 and is seen at 110.41570607219107. Consultation length: 6.170.
Patient 23 arrives at: 111.508.
Patient 18 waits for 36.455 and is seen at 116.58616982145658. Consultation length: 1.077.
Patient 19 waits for 34.499 and is seen at 117.6630718354606. Consultation length: 0.098.
Patient 20 waits for 33.945 and is seen at 117.76095925666442. Consultation length: 12.722.
Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000         9.128216
2               7.737856         0.325456
3               0.000000        13.762423
4               4.170533         0.807112
5               3.297285         3.521840
6               2.190234        10.123883
7               7.183670        12.450937
8              17.042214         7.605560
9              20.645588        12.085936
10             26.644418         7.751810
11             34.151279         1.815108
12             35.359538         3.558461
13             30.092986         1.239970
14             30.819039         0.904123
15             31.049421         7.041470
16             36.765274         6.569105
17             42.776282         6.170464
18             36.454576         1.076902
19             34.499073         0.097887
20             33.945194        12.721683
Trial Results
            Mean Q Time Nurse
Run Number                   
0                   21.741223

…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: 9.128.
Patient 2 arrives at: 1.390.
Patient 2 waits for 7.738 and is seen at 9.128216275837325. Consultation length: 0.325.
Patient 3 arrives at: 21.178.
Patient 3 waits for 0.000 and is seen at 21.177969726684417. Consultation length: 13.762.
Patient 4 arrives at: 30.770.
Patient 5 arrives at: 32.450.
Patient 4 waits for 4.171 and is seen at 34.940392821031836. Consultation length: 0.807.
Patient 5 waits for 3.297 and is seen at 35.747504482065075. Consultation length: 3.522.
Patient 6 arrives at: 37.079.
Patient 6 waits for 2.190 and is seen at 39.2693440979408. Consultation length: 10.124.
Patient 7 arrives at: 42.210.
Patient 8 arrives at: 44.802.
Patient 9 arrives at: 48.804.
Patient 7 waits for 7.184 and is seen at 49.3932266384662. Consultation length: 12.451.
Patient 10 arrives at: 54.891.
Patient 11 arrives at: 55.136.
Patient 12 arrives at: 55.743.
Patient 8 waits for 17.042 and is seen at 61.8441640569845. Consultation length: 7.606.
Patient 13 arrives at: 64.568.
Patient 14 arrives at: 65.082.
Patient 15 arrives at: 65.756.
Patient 16 arrives at: 67.081.
Patient 17 arrives at: 67.639.
Patient 9 waits for 20.646 and is seen at 69.44972369061622. Consultation length: 12.086.
Patient 18 arrives at: 80.132.
Patient 10 waits for 26.644 and is seen at 81.5356596517137. Consultation length: 7.752.
Patient 19 arrives at: 83.164.
Patient 20 arrives at: 83.816.
Patient 21 arrives at: 87.314.
Patient 11 waits for 34.151 and is seen at 89.28746953697762. Consultation length: 1.815.
Patient 12 waits for 35.360 and is seen at 91.10257771342164. Consultation length: 3.558.
Patient 13 waits for 30.093 and is seen at 94.6610386462429. Consultation length: 1.240.
Patient 14 waits for 30.819 and is seen at 95.90100881905825. Consultation length: 0.904.
Patient 15 waits for 31.049 and is seen at 96.80513148137655. Consultation length: 7.041.
Patient 16 waits for 36.765 and is seen at 103.84660101836144. Consultation length: 6.569.
Patient 22 arrives at: 106.052.
Patient 17 waits for 42.776 and is seen at 110.41570607219107. Consultation length: 6.170.
Patient 23 arrives at: 111.508.
Patient 18 waits for 36.455 and is seen at 116.58616982145658. Consultation length: 1.077.
Patient 19 waits for 34.499 and is seen at 117.6630718354606. Consultation length: 0.098.
Patient 20 waits for 33.945 and is seen at 117.76095925666442. Consultation length: 12.722.

Tip

For a more detailed logging implementation, see github.com/pythonhealthdatascience/pydesrap_mms - 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