Authors: | Klaus Muller |
---|---|
Date: | April 2010 |
Contents
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:
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.
New in SimPy 2.1
This function executes the next scheduled event.
A function returning the times and process names of all scheduled events as a multi-line string.
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
A function returning the times of all scheduled events as a list.
allEventTimes(), or **<simulation>.allEventTimes() (advanced OO mode)
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.
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
. . . .
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?
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:
Event 1 is the entry into Beemer `s drive PEM, including the yield request for process Beemer (the attempt to acquire the parking resource)
Event 2 is the yield hold for process Beemer, the scheduling of the holding period of the parking resource.
Event 3 is the entry into Caddy `s drive PEM, including the yield request for process Caddy (the attempt to acquire the parking resource)
Event 4 is the completion of Beemer `s hold period, the end of its parking time.
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.)
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.
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
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)!
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.