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: 6.869.
Patient 2 arrives at: 8.467.
Patient 2 waits for 0.000 and is seen at 8.46737394127876. Consultation length: 6.699.
Patient 3 arrives at: 13.283.
Patient 4 arrives at: 13.423.
Patient 5 arrives at: 13.796.
Patient 3 waits for 1.883 and is seen at 15.165977547811924. Consultation length: 0.115.
Patient 4 waits for 1.857 and is seen at 15.280555793911933. Consultation length: 2.188.
Patient 6 arrives at: 17.420.
Patient 5 waits for 3.672 and is seen at 17.468071529990556. Consultation length: 0.258.
Patient 6 waits for 0.305 and is seen at 17.725572268538652. Consultation length: 1.164.
Patient 7 arrives at: 26.341.
Patient 7 waits for 0.000 and is seen at 26.341407580540494. Consultation length: 3.168.
Patient 8 arrives at: 30.059.
Patient 8 waits for 0.000 and is seen at 30.05941226057878. Consultation length: 2.085.
Patient 9 arrives at: 45.702.
Patient 9 waits for 0.000 and is seen at 45.702092599836135. Consultation length: 4.599.
Patient 10 arrives at: 46.935.
Patient 10 waits for 3.366 and is seen at 50.300810625456954. Consultation length: 1.184.
Patient 11 arrives at: 55.532.
Patient 11 waits for 0.000 and is seen at 55.53178926631925. Consultation length: 2.130.
Patient 12 arrives at: 60.275.
Patient 12 waits for 0.000 and is seen at 60.2746546077804. Consultation length: 19.821.
Patient 13 arrives at: 66.603.
Patient 14 arrives at: 75.200.
Patient 13 waits for 13.493 and is seen at 80.09610969284469. Consultation length: 6.779.
Patient 15 arrives at: 80.466.
Patient 16 arrives at: 81.190.
Patient 14 waits for 11.675 and is seen at 86.8748233394179. Consultation length: 1.647.
Patient 17 arrives at: 87.147.
Patient 15 waits for 8.056 and is seen at 88.52208969375222. Consultation length: 5.570.
Patient 18 arrives at: 89.835.
Patient 19 arrives at: 90.970.
Patient 16 waits for 12.903 and is seen at 94.0924346843826. Consultation length: 32.076.
Patient 20 arrives at: 101.062.
Patient 21 arrives at: 103.573.
Patient 22 arrives at: 106.823.
Patient 23 arrives at: 106.994.
Patient 24 arrives at: 108.721.
Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000         6.868775
2               0.000000         6.698604
3               1.882747         0.114578
4               1.857359         2.187516
5               3.672333         0.257501
6               0.305274         1.163964
7               0.000000         3.168051
8               0.000000         2.084570
9               0.000000         4.598718
10              3.365978         1.184084
11              0.000000         2.129827
12              0.000000        19.821455
13             13.492848         6.778714
14             11.675292         1.647266
15              8.056320         5.570345
16             12.902816        32.075630
Trial Results
            Mean Q Time Nurse
Run Number                   
0                    3.575685

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         4.786202
2               3.371985         3.147962
3               6.030889         4.588366
4               0.363829        31.758473
5              30.345827         0.184645
6              29.002493        15.834206
7              44.174796         8.549246
8              49.690965         5.063280
9              50.019425         5.607272
10             47.716098         4.908256
11             50.363360        10.081026
12             44.516284        11.820329
13             41.065399         7.212214
14             40.900743         3.578487
15             42.041844         0.578683
16             38.222891         1.821623
17             30.173905        16.481696
Trial Results
            Mean Q Time Nurse
Run Number                   
0                   32.235337

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: 1.722.
Patient 2 arrives at: 7.899.
Patient 2 waits for 0.000 and is seen at 7.8988933801574595. Consultation length: 3.138.
Patient 3 arrives at: 10.438.
Patient 3 waits for 0.599 and is seen at 11.037215033020054. Consultation length: 2.245.
Patient 4 arrives at: 12.828.
Patient 4 waits for 0.454 and is seen at 13.28245064931658. Consultation length: 8.090.
Patient 5 arrives at: 29.005.
Patient 5 waits for 0.000 and is seen at 29.004527697998423. Consultation length: 1.428.
Patient 6 arrives at: 36.925.
Patient 6 waits for 0.000 and is seen at 36.924558421331675. Consultation length: 4.057.
Patient 7 arrives at: 37.460.
Patient 8 arrives at: 38.056.
Patient 7 waits for 3.521 and is seen at 40.98173980383347. Consultation length: 4.875.
Patient 8 waits for 7.801 and is seen at 45.856588302379876. Consultation length: 17.478.
Patient 9 arrives at: 54.207.
Patient 10 arrives at: 60.768.
Patient 11 arrives at: 63.331.
Patient 9 waits for 9.128 and is seen at 63.33498122025894. Consultation length: 7.181.
Patient 12 arrives at: 63.600.
Patient 13 arrives at: 68.192.
Patient 14 arrives at: 68.443.
Patient 10 waits for 9.749 and is seen at 70.51632140691177. Consultation length: 7.118.
Patient 15 arrives at: 71.519.
Patient 16 arrives at: 72.731.
Patient 11 waits for 14.304 and is seen at 77.6346511089829. Consultation length: 15.768.
Patient 17 arrives at: 80.689.
Patient 18 arrives at: 87.456.
Patient 12 waits for 29.803 and is seen at 93.40305897594509. Consultation length: 0.198.
Patient 13 waits for 25.409 and is seen at 93.60107678897859. Consultation length: 9.477.
Patient 19 arrives at: 95.182.
Patient 20 arrives at: 96.495.
Patient 21 arrives at: 98.243.
Patient 22 arrives at: 102.655.
Patient 14 waits for 34.636 and is seen at 103.07808176608025. Consultation length: 4.045.
Patient 23 arrives at: 103.090.
Patient 24 arrives at: 103.091.
Patient 25 arrives at: 106.825.
Patient 15 waits for 35.604 and is seen at 107.1234592373643. Consultation length: 17.414.
Patient 26 arrives at: 108.618.
Patient 27 arrives at: 113.673.
Patient 28 arrives at: 113.915.
Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000         1.722453
2               0.000000         3.138322
3               0.598776         2.245236
4               0.454041         8.090141
5               0.000000         1.427947
6               0.000000         4.057181
7               3.521482         4.874848
8               7.800764        17.478393
9               9.127525         7.181340
10              9.748586         7.118330
11             14.303882        15.768408
12             29.802739         0.198018
13             25.409319         9.477005
14             34.635538         4.045377
15             35.603966        17.414264
Trial Results
            Mean Q Time Nurse
Run Number                   
0                   11.400441

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: 3.453.
Patient 2 arrives at: 1.561.
Patient 3 arrives at: 3.388.
Patient 2 waits for 1.892 and is seen at 3.452737581375565. Consultation length: 3.470.
Patient 4 arrives at: 5.125.
Patient 3 waits for 3.535 and is seen at 6.922778260489453. Consultation length: 0.999.
Patient 4 waits for 2.798 and is seen at 7.922266342288247. Consultation length: 2.248.
Patient 5 arrives at: 17.808.
Patient 5 waits for 0.000 and is seen at 17.808379127806987. Consultation length: 3.454.
Patient 6 arrives at: 18.614.
Patient 7 arrives at: 20.102.
Patient 6 waits for 2.649 and is seen at 21.2628614723856. Consultation length: 6.012.
Patient 8 arrives at: 22.332.
Patient 9 arrives at: 22.922.
Patient 7 waits for 7.173 and is seen at 27.27494121516684. Consultation length: 4.650.
Patient 10 arrives at: 28.510.
Patient 11 arrives at: 31.334.
Patient 8 waits for 9.593 and is seen at 31.925029981445412. Consultation length: 2.840.
Patient 9 waits for 11.844 and is seen at 34.76551789122649. Consultation length: 4.355.
Patient 10 waits for 10.611 and is seen at 39.12083540152581. Consultation length: 8.898.
Patient 12 arrives at: 39.874.
Patient 11 waits for 16.685 and is seen at 48.01903953672405. Consultation length: 11.388.
Patient 13 arrives at: 57.316.
Patient 12 waits for 19.533 and is seen at 59.40720444012097. Consultation length: 9.076.
Patient 14 arrives at: 59.680.
Patient 15 arrives at: 61.667.
Patient 16 arrives at: 65.468.
Patient 13 waits for 11.168 and is seen at 68.48326070331736. Consultation length: 2.979.
Patient 14 waits for 11.783 and is seen at 71.46237987766989. Consultation length: 12.373.
Patient 17 arrives at: 77.802.
Patient 18 arrives at: 79.094.
Patient 19 arrives at: 79.669.
Patient 15 waits for 22.168 and is seen at 83.83495417269661. Consultation length: 1.018.
Patient 16 waits for 19.385 and is seen at 84.85251550276232. Consultation length: 3.305.
Patient 17 waits for 10.356 and is seen at 88.15743611701436. Consultation length: 21.321.
Patient 20 arrives at: 88.357.
Patient 21 arrives at: 103.520.
Patient 22 arrives at: 103.920.
Patient 18 waits for 30.384 and is seen at 109.47857948367383. Consultation length: 10.951.
Patient 23 arrives at: 118.202.
Run Number 0
            Q Time Nurse  Time with Nurse
Patient ID                               
1               0.000000         3.452738
2               1.892125         3.470041
3               3.534654         0.999488
4               2.797525         2.247655
5               0.000000         3.454482
6               2.649262         6.012080
7               7.172888         4.650089
8               9.593278         2.840488
9              11.843591         4.355318
10             10.611124         8.898204
11             16.685215        11.388165
12             19.533150         9.076056
13             11.167705         2.979119
14             11.782863        12.372574
15             22.168030         1.017561
16             19.384520         3.304921
17             10.355810        21.321143
18             30.384247        10.950821
Trial Results
            Mean Q Time Nurse
Run Number                   
0                   10.641999

…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: 3.453.
Patient 2 arrives at: 1.561.
Patient 3 arrives at: 3.388.
Patient 2 waits for 1.892 and is seen at 3.452737581375565. Consultation length: 3.470.
Patient 4 arrives at: 5.125.
Patient 3 waits for 3.535 and is seen at 6.922778260489453. Consultation length: 0.999.
Patient 4 waits for 2.798 and is seen at 7.922266342288247. Consultation length: 2.248.
Patient 5 arrives at: 17.808.
Patient 5 waits for 0.000 and is seen at 17.808379127806987. Consultation length: 3.454.
Patient 6 arrives at: 18.614.
Patient 7 arrives at: 20.102.
Patient 6 waits for 2.649 and is seen at 21.2628614723856. Consultation length: 6.012.
Patient 8 arrives at: 22.332.
Patient 9 arrives at: 22.922.
Patient 7 waits for 7.173 and is seen at 27.27494121516684. Consultation length: 4.650.
Patient 10 arrives at: 28.510.
Patient 11 arrives at: 31.334.
Patient 8 waits for 9.593 and is seen at 31.925029981445412. Consultation length: 2.840.
Patient 9 waits for 11.844 and is seen at 34.76551789122649. Consultation length: 4.355.
Patient 10 waits for 10.611 and is seen at 39.12083540152581. Consultation length: 8.898.
Patient 12 arrives at: 39.874.
Patient 11 waits for 16.685 and is seen at 48.01903953672405. Consultation length: 11.388.
Patient 13 arrives at: 57.316.
Patient 12 waits for 19.533 and is seen at 59.40720444012097. Consultation length: 9.076.
Patient 14 arrives at: 59.680.
Patient 15 arrives at: 61.667.
Patient 16 arrives at: 65.468.
Patient 13 waits for 11.168 and is seen at 68.48326070331736. Consultation length: 2.979.
Patient 14 waits for 11.783 and is seen at 71.46237987766989. Consultation length: 12.373.
Patient 17 arrives at: 77.802.
Patient 18 arrives at: 79.094.
Patient 19 arrives at: 79.669.
Patient 15 waits for 22.168 and is seen at 83.83495417269661. Consultation length: 1.018.
Patient 16 waits for 19.385 and is seen at 84.85251550276232. Consultation length: 3.305.
Patient 17 waits for 10.356 and is seen at 88.15743611701436. Consultation length: 21.321.
Patient 20 arrives at: 88.357.
Patient 21 arrives at: 103.520.
Patient 22 arrives at: 103.920.
Patient 18 waits for 30.384 and is seen at 109.47857948367383. Consultation length: 10.951.
Patient 23 arrives at: 118.202.

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