|
| |
Using tracing to debug a SimPy
program
(Author: Klaus G. Muller; kgmuller at users.sourceforge.net)
Debugging programs is a difficult art, and debugging simulation programs,
with their parallel processes, time dependencies and synchronization issues is
even more difficult.
A fine introduction to debugging of SimPy programs can be found in Prof.
Matloff's SimPy
tutorial.
This HowTo will look at a powerful debugging tool built into SimPy, namely
the SimulationTrace module. It provides insight
into the execution of the quasi-parallel processes, the events in SimPy
programs. This can help to gain insight into the logic of simulations written by
others and also into what is going on in a malfunctioning program one has
written.
Let's look at a trivial example: a workshop has two machines in series which
produce widgets. Each machine can only process one raw widget at a time. This is
modelled by the following (erroneous) SimPy program:
from SimPy.Simulation import *
class Widget(Process):
def lifetime(self):
yield request,self,machine0
yield hold,self,12
yield request,self,machine1
yield hold,self,24
yield release,self,machine1
print "Widget %s produced"%self.name
initialize()
machine0=Resource(name="Machine 0")
machine1=Resource(name="Machine 1")
for i in range(4):
w=Widget(name="Widget %s"%i)
activate(w,w.lifetime())
simulate(until=1000)
OUTPUT:
Widget 0 produced
|
Although 4 raw widgets go into the workshop, only 1 finished widget comes
out. In this small program, the reason is easy to spot, but in larger, more
complex programs, with random arrivals and delays, it may not be so easy.
To trace the event sequence in order to find the bug(s), we change just the
second line to 'from SimPy.SimulationTrace
import *'. That gives us
an automatic trace of all the 'yield'
(scheduling) statements. So here are the changed program and its output:
from SimPy.SimulationTrace import * ## Only change in program!
class Widget(Process):
def lifetime(self):
yield request,self,machine0
yield hold,self,12
yield request,self,machine1
yield hold,self,24
yield release,self,machine1
print "Widget %s produced"%self.name
initialize()
machine0=Resource(name="Machine 0")
machine1=Resource(name="Machine 1")
for i in range(4):
w=Widget(name="Widget %s"%i)
activate(w,w.lifetime())
simulate(until=1000)
OUTPUT:
0 activate <Widget 0> at time: 0 prior: 0
0 activate <Widget 1> at time: 0 prior: 0
0 activate <Widget 2> at time: 0 prior: 0
0 activate <Widget 3> at time: 0 prior: 0
0 request <Widget 0> <Machine 0> priority: default
. . .waitQ: []
. . .activeQ: ['Widget 0']
0 hold <Widget 0> delay: 12
0 request <Widget 1> <Machine 0> priority: default
. . .waitQ: ['Widget 1']
. . .activeQ: ['Widget 0']
0 request <Widget 2> <Machine 0> priority: default
. . .waitQ: ['Widget 1', 'Widget 2']
. . .activeQ: ['Widget 0']
0 request <Widget 3> <Machine 0> priority: default
. . .waitQ: ['Widget 1', 'Widget 2', 'Widget 3']
. . .activeQ: ['Widget 0']
12 request <Widget 0> <Machine 1> priority: default
. . .waitQ: []
. . .activeQ: ['Widget 0']
12 hold <Widget 0> delay: 24
36 release <Widget 0> <Machine 1>
. . .waitQ: []
. . .activeQ: []
Widget 0 produced
36 <Widget 0> terminated
|
The first column is the event time. We see the process activations, request
and release of resources and hold delays.
The program ends at time 36. By this time, only Widget 0 has been finished.
Why are the other widgets not being finished? At time 0, they were waiting for
Machine 0 (waitQ), while Widget 0 was being
processed (activeQ). Why are they not
progressing further to Machine 1?
At the interactive prompt (say, in IDLE), we inspect the Machine 1 object's
queues:
>>> machine0
<Instance of Resource, id 19883880:
.preemptable=0
.capacity=1
.name=Machine 0
.waitQ=[<Instance of Widget, id 19884328:
.name=Widget 1
>, <Instance of Widget, id 12128032:
.name=Widget 2
>, <Instance of Widget, id 19892736:
.name=Widget 3
>]
.unitName=units
.priority_default=0
.activeQ=[<Instance of Widget, id 19872904:
.interruptCause=None
.name=Widget 0
.interruptLeft=24
>]
.n=0
> |
So, Widget 1, Widget 2 and Widget 3 are still queuing (waitQ),
while Widget 0 is still occupying the machine (activeQ).
Widget 0 has never released Machine 0!
The solution is simple -- just add the missing 'yield
release' statement and run:
from SimPy.SimulationTrace import *
class Widget(Process):
def lifetime(self):
yield request,self,machine0
yield hold,self,12
yield release,self,machine0 ##this cured the bug!
yield request,self,machine1
yield hold,self,24
yield release,self,machine1
print "%s produced"%self.name
initialize()
machine0=Resource(name="Machine 0")
machine1=Resource(name="Machine 1")
for i in range(4):
w=Widget(name="Widget %s"%i)
activate(w,w.lifetime())
simulate(until=1000)
OUTPUT:
0 activate <Widget 0> at time: 0 prior: 0
0 activate <Widget 1> at time: 0 prior: 0
0 activate <Widget 2> at time: 0 prior: 0
0 activate <Widget 3> at time: 0 prior: 0
0 request <Widget 0> <Machine 0> priority: default
. . .waitQ: []
. . .activeQ: ['Widget 0']
0 hold <Widget 0> delay: 12
0 request <Widget 1> <Machine 0> priority: default
. . .waitQ: ['Widget 1']
. . .activeQ: ['Widget 0']
0 request <Widget 2> <Machine 0> priority: default
. . .waitQ: ['Widget 1', 'Widget 2']
. . .activeQ: ['Widget 0']
0 request <Widget 3> <Machine 0> priority: default
. . .waitQ: ['Widget 1', 'Widget 2', 'Widget 3']
. . .activeQ: ['Widget 0']
12 cancel by: <a_process> of: <Widget 1>
12 reactivate <Widget 1> time: 12 prior: 1
12 release <Widget 0> <Machine 0>
. . .waitQ: ['Widget 2', 'Widget 3']
. . .activeQ: ['Widget 1']
12 request <Widget 0> <Machine 1> priority: default
. . .waitQ: []
. . .activeQ: ['Widget 0']
12 hold <Widget 0> delay: 24
12 hold <Widget 1> delay: 12
24 cancel by: <a_process> of: <Widget 2>
24 reactivate <Widget 2> time: 24 prior: 1
24 release <Widget 1> <Machine 0>
. . .waitQ: ['Widget 3']
. . .activeQ: ['Widget 2']
24 request <Widget 1> <Machine 1> priority: default
. . .waitQ: ['Widget 1']
. . .activeQ: ['Widget 0']
24 hold <Widget 2> delay: 12
36 cancel by: <a_process> of: <Widget 1>
36 reactivate <Widget 1> time: 36 prior: 1
36 release <Widget 0> <Machine 1>
. . .waitQ: []
. . .activeQ: ['Widget 1']
Widget 0 produced
36 <Widget 0> terminated
36 hold <Widget 1> delay: 24
36 cancel by: <a_process> of: <Widget 3>
36 reactivate <Widget 3> time: 36 prior: 1
36 release <Widget 2> <Machine 0>
. . .waitQ: []
. . .activeQ: ['Widget 3']
36 request <Widget 2> <Machine 1> priority: default
. . .waitQ: ['Widget 2']
. . .activeQ: ['Widget 1']
36 hold <Widget 3> delay: 12
48 release <Widget 3> <Machine 0>
. . .waitQ: []
. . .activeQ: []
48 request <Widget 3> <Machine 1> priority: default
. . .waitQ: ['Widget 2', 'Widget 3']
. . .activeQ: ['Widget 1']
60 cancel by: <a_process> of: <Widget 2>
60 reactivate <Widget 2> time: 60 prior: 1
60 release <Widget 1> <Machine 1>
. . .waitQ: ['Widget 3']
. . .activeQ: ['Widget 2']
Widget 1 produced
60 <Widget 1> terminated
60 hold <Widget 2> delay: 24
84 cancel by: <a_process> of: <Widget 3>
84 reactivate <Widget 3> time: 84 prior: 1
84 release <Widget 2> <Machine 1>
. . .waitQ: []
. . .activeQ: ['Widget 3']
Widget 2 produced
84 <Widget 2> terminated
84 hold <Widget 3> delay: 24
108 release <Widget 3> <Machine 1>
. . .waitQ: []
. . .activeQ: []
Widget 3 produced
108 <Widget 3> terminated |
All four widgets get produced, the program runs correctly. Mission
accomplished!
For the full range of SimPy's tracing capabilities, have a look at the SimulationTrace
manual.
|
