Insight into Models and Debugging SimPy Programs

Authors:Klaus Muller
Date:April 2010

Introduction

Much has been written about debugging programs, and Python provides good interactive debugging tools (such as pydb, pdb and ipython). They are very useful for a SimPy developer in debugging at a low (Python) level.

A SimPy simulation developer has additional requirements, though. She needs to understand how an implemented model behaves, and she needs to be able to debug the process interactions/synchronizations. Program control does not flow linearly through the code. Generators (the SimPy Process Execution Methods or PEMs) are entered, re-entered and left somewhere in the middle. When multiple instances of a Process class are active, program control for each of them can be in a different position in the PEM.

None of this is basically difficult, but for programmers coming from a language with sequential program execution, the quasi-parallelism of SimPy processes is a paradigm shift. To develop correct models, it is essential for them to be able to visualise and understand how their models are executed.

Fortunately, SimPy has a good range of tools to help a simulation developer with gaining insight into their models’ implementation in SimPy and with debugging:

  • allEventNotices, a method/function to display all scheduled events, with event times and and the names of the Process instances involved.
  • allEventTimes, a method/function to display all scheduled events’ event times.
  • peek, a method/function returning the next event time (or infinity, if there are no more events scheduled. (New in SimPy 2.1.0.)
  • step, a method which executes the next scheduled event and then returns. (New in SimPy 2.1.0.)
  • SimPy.SimulationTrace, a library which allows tracing of all or a selected range of SimPy events.

The tools

peek – time of next event

New in SimPy 2.1

This function returns the simulation time of the next event on the event list. At that time, the Process Execution Method of the associated process will be re-entered when the simulation is continued. If there are no more events, a SimPy-defined constant infinity will be returned.

Call:
peek(), or <simulation>.peek() (advanced OO mode)
Returns:
next event time (float or integer number), or infinity if no more events are scheduled.

step – execute next event

New in SimPy 2.1

This function executes the next scheduled event.

Call:
step(), or <simulation>.step() (advanced OO mode)
Returns:
next event time (float or integer number), or None if no more events are scheduled.

allEventNotices – show event times and processes

A function returning the times and process names of all scheduled events as a multi-line string.

Call:
allEventNotices(), or <simulation>.allEventNotices() (advanced OO mode)
Returns:

a string of the format:

*t1: proc1-name, proc2-name, . . .*
*t2: procn-name*, procm-name, . . .*
. . . .

i.e., one line per event time

Example of output of print allEventNotices():

25: Caddy, Vette
45: Beemer, Beatle

allEventTimes – show event times

A function returning the times of all scheduled events as a list.

Call:
allEventTimes(), or **<simulation>.allEventTimes() (advanced OO mode)
Returns:
a list of times of all scheduled vents without duplicates (each time is given only once)

SimPy.SimulationTrace – trace all events

This module prints a detailed trace of all events executed during a simulation run. It has a rich set of commands and options which are documented in the manual Simulation with Tracing. Because of the large amount of output which can be produced by a simulation run with many events, it can be advantageous to re-direct the output to a file. SimulationTrace has a command for this, but it can also be done at the command line by executing python mysim.py > mysimtrace.txt.

Invocation:
Use from SimPy.SimulationTrace import *, instead of from SimPy.Simulation import *

Example of output:

0 activate <Beemer > at time: 0 prior: False
0 activate <Caddy > at time: 25 prior: False
0 request  < Beemer >  <Parking>  priority: default
. . . .

Using SimPy’s insight/debugging tools

Let’s put the tools to use on an example model. The scenario is that two cars (Beemer and Caddy) want to park in the same parking space. Beemer arrives at time 0, and Caddy at time 25.

The model in SimPy to be debugged looks like this:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
from SimPy.Simulation import *

class Car(Process):
    def drive(self, parking, howlong):
        yield request,self,parking
        yield hold,self,howlong
        print "At time %s, %s leaves parking"%(now(), self.name)
        
initialize()
p = Resource(name = "Parking")
b = Car(name = "Beemer")
activate(b, b.drive(parking = p, howlong = 45))
c = Car(name = "Caddy")
activate(c, c.drive(parking = p, howlong = 120), at = 25)
simulate(until = 200)       

When run, the output is:

At time 45, Beemer leaves parking

There is a problem – the Caddy car never comes out of the parking space. Did it ever get into the parking space? What is wrong here? There is a bug!

Obviously, the example is a trivially small program. Use your imagination and think of this as a large simulation program with thousands of lines of code. Your boss is breathing down your neck, wanting results. Can you feel the problem now?

Using peek, step and allEventNotices

As a first attempt to see what is going in, let’s use peek, step and allEventNotices to see which events get scheduled during the simulation run. We comment out the simulate(until = 200) and replace it by a loop which steps through the simulation event by event:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
from SimPy.Simulation import *

class Car(Process):
    def drive(self, parking, howlong):
        yield request,self,parking
        yield hold,self,howlong
        print "At time %s, %s leaves parking"%(now(), self.name)
        
initialize()
p = Resource(name = "Parking")
b = Car(name = "Beemer")
activate(b, b.drive(parking = p, howlong = 45))
c = Car(name = "Caddy")
activate(c, c.drive(parking = p, howlong = 120), at = 25)
# simulate(until = 200) 
while True:
    tEvt = peek()
    if tEvt < infinity:
        print "Event-notices at t=%s:"%now()
        print allEventNotices()
        step()
    else:
        break
           

The stepping/tracing loop has the following logic:

do forever:
    get time of next event (line 17)
    is there another event scheduled? (line 18)
        yes:
            print the simulation time and event notices (lines 19 - 20)
            execute the next event on the event list (line 21)
        no:
            get out of the loop (line 23)

When run, we get the following output:

Event-notices at t=0:
0: Beemer
25: Caddy

Event-notices at t=0:
0: Beemer
25: Caddy

Event-notices at t=0:
25: Caddy
45: Beemer

Event-notices at t=25:
45: Beemer

At time 45, Beemer leaves parking

We can see that there are four events, and each line Event-notices at . . . is output just before their execution:

Before event 1 (t = 0):

Event 1 is the entry into Beemer `s drive PEM, including the yield request for process Beemer (the attempt to acquire the parking resource)

  • Beemer `s drive PEM is scheduled at t = 0 (scheduled by activate)
  • Caddy `s drive PEM is scheduled at t = 25 (scheduled by activate)
Before event 2 (t = 0):

Event 2 is the yield hold for process Beemer, the scheduling of the holding period of the parking resource.

  • Beemer `s drive PEM is scheduled to resume at t = 0 after the successful yield request completion
  • Caddy `s drive PEM is still scheduled at t = 25
Before event 3 (t = 0):

Event 3 is the entry into Caddy `s drive PEM, including the yield request for process Caddy (the attempt to acquire the parking resource)

  • Caddy `s PEM is scheduled to resume at t = 25
  • Beemer `s PEM is scheduled to resume at t = 45, at the end of the hold period
Before event 4 (t = 25):

Event 4 is the completion of Beemer `s hold period, the end of its parking time.

  • Beemer `s PEM is scheduled to resume at t = 45, at the end of the hold period
  • There is no event scheduled for Caddy. It clearly did not acquire the parking resource. It is blocked, waiting for it to become available.

As there is no further event after Beemer `s exit from the parking (completion of its PEM), Caddy never acquired the parking resource! Aha, here is the bug! Beemer never released the parking resource. (You noticed this a long while ago, of course. But keep up the illusion of being puzzled by a large, misbehaving SimPy program.)

Using SimPy.SimulationTrace

This approach of stepping through a simulation by peek and step, printing out the event list before every event, is nice, but it is still a bit nebulous to understand. What is missing is the context, the trace of the actual event execution.

That is easy to add – just import SimPy.SimulationTrace instead of SimPy.Simulation in line 1:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
from SimPy.SimulationTrace import *

class Car(Process):
    def drive(self, parking, howlong):
        yield request,self,parking
        yield hold,self,howlong
        print "At time %s, %s leaves parking"%(now(), self.name)
        
initialize()
p = Resource(name = "Parking")
b = Car(name = "Beemer")
activate(b, b.drive(parking = p, howlong = 45))
c = Car(name = "Caddy")
activate(c, c.drive(parking = p, howlong = 120), at = 25)
# simulate(until = 200) 
while True:
    tEvt = peek()
    if tEvt < infinity:
        print "Event-notices at t=%s:"%now()
        print allEventNotices()
        step()
    else:
        break
           

When run, this is the output:

0 activate <Beemer > at time: 0 prior: False
0 activate <Caddy > at time: 25 prior: False
Event-notices at t=0:
0: Beemer
25: Caddy

0 request  < Beemer >  <Parking>  priority: default 
. . .waitQ: [] 
. . .activeQ: ['Beemer']
Event-notices at t=0:
0: Beemer
25: Caddy

0 hold  < Beemer >  delay: 45
Event-notices at t=0:
25: Caddy
45: Beemer

25 request  < Caddy >  <Parking>  priority: default 
. . .waitQ: ['Caddy'] 
. . .activeQ: ['Beemer']
Event-notices at t=25:
45: Beemer

At time 45, Beemer leaves parking
45 <Beemer > terminated

The detailed trace clearly shows what the events are and how they change the event list.

Using the interactive SimPy debugger

New in SimPy 2.1

SimPy now includes a simple interactive debugger/insight tool stepping.py as part of its library. It is based on peek, step and allEventNotices, but also uses knowledge about internals, such as the even list and event implementation structures. This tool allows stepping through a simulation interactively, with options such as inspecting the event list, skipping to an event time, skipping to the next event for a given process, ending a run, or running the simulation to the end without interaction..

stepping is easy to use. Let’s use it in our buggy model. Two changes are enough: import of stepping (line 2) and replacement of the while True-loop with a call stepping(Globals) (line 16).

This gives us the following program:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
from SimPy.SimulationTrace import *
from SimPy.stepping import *

class Car(Process):
    def drive(self, parking, howlong):
        yield request,self,parking
        yield hold,self,howlong
        print "At time %s, %s leaves parking"%(now(), self.name)
        
initialize()
p = Resource(name = "Parking")
b = Car(name = "Beemer")
activate(b, b.drive(parking = p, howlong = 45))
c = Car(name = "Caddy")
activate(c, c.drive(parking = p, howlong = 120), at = 25)
stepping(Globals)
# simulate(until = 200)       

Here is a possible interactive session:

0 activate <Beemer > at time: 0 prior: False
0 activate <Caddy > at time: 25 prior: False

Time now: 0, next event at: t=0 for process: Beemer
Command ('h' for help): h
e : end run
p<name> : skip to event for <name>
h : help
<time> : skip to event at <time>
l : show eventlist
s : next event
r : run to end
Command ('h' for help): s
0 request  < Beemer >  <Parking>  priority: default
. . .waitQ: [] 
. . .activeQ: ['Beemer']

Time now: 0, next event at: t=0 for process: Beemer 
Command ('h' for help): s
0 hold  < Beemer >  delay: 45

Time now: 0, next event at: t=25 for process: Caddy 
Command ('h' for help): r
25 request  < Caddy >  <Parking>  priority: default
. . .waitQ: ['Caddy'] 
. . .activeQ: ['Beemer']
At time 45, Beemer leaves parking
45 <Beemer > terminated
Run ended at t=45

Finally, the corrected model

Just so that we don’t forget, ALL the model implementations shown so far had a bug (remember?). They were missing the yield release statement for the parking resource. Add it after the yield hold, and the bug is exterminated.

For completeness sake, here is the corrected model:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
from SimPy.Simulation import *

class Car(Process):
    def drive(self, parking, howlong):
        yield request,self,parking
        yield hold,self,howlong
        yield release,self,parking
        print "At time %s, %s leaves parking"%(now(), self.name)
        
initialize()
p = Resource(name = "Parking")
b = Car(name = "Beemer")
activate(b, b.drive(parking = p, howlong = 45))
c = Car(name = "Caddy")
activate(c, c.drive(parking = p, howlong = 120), at = 25)
simulate(until = 200) 

This simulation model produces the correct output:

At time 45, Beemer leaves parking
At time 165, Caddy leaves parking

Debugging done (and hopefully, some insight gained)!

Strategies

When should you use which tools? For debugging, I would use SimPy.SimulationTrace. When I start a new SimPy simulation script, I use from SimPy.SimulationTrace import * right away until the model is correct. Only then do I replace it by from SimPy.Simulation import *. I strongly recommend reading the Simulation with Tracing manual and to experiment with the tracing options. This investment of time will pay great dividends when you start developing large, complex simulation models in SimPy.

For gaining (or teaching) insight into the event handling of SimPy, I would use code with peek, get, and allEventNotices. The easiest is to use stepping out-of-the-box, but there may be reasons to “roll my own”, e.g. when the interaction would be too much work or I want to keep the output in a file.