# Simulation with Tracing

Authors:

  - Klaus Muller <Muller@users.sourceforge.net>

SimPy release:

  2.3.1

Web-site:

  http://simpy.sourceforge.net/

Python-Version:

  2.6 and later

Date:

  December 2011

## Introduction

The tracing utility has been developed to give users insight into the dynamics of the execution of SimPy simulation programs. It can help developers with testing and users with explaining SimPy models to themselves and others (e.g. for documentation or teaching purposes).

## Tracing SimPy programs

Tracing any SimPy program is as simple as replacing:

    from SimPy.Simulation import *

with:

    from SimPy.SimulationTrace import *

This will give a complete trace of all the scheduling statements executed during the program’s execution.

An even nicer way is to replace this import by:

    if __debug__:
            from SimPy.SimulationTrace import *
    else:
            from SimPy.Simulation import *

This gives a trace during the development and debugging. If one then executes the program with python -O myprog.py, tracing is switched off, and no run-time overhead is incurred. (__debug__ is a global Python constant which is set to False by commandline options -O and -OO.)

For the same reason, any user call to trace methods should be written as:

    if __debug__:
            trace.ttext("This will only show during debugging")

Here is an example (bank02.py from the Bank Tutorial):

     1from SimPy.SimulationTrace import * #   <== changed for tracing
     2##from SimPy.Simulation import *
     3
     4""" Simulate a single customer """
     5class Customer(Process):
     6        """ Customer arrives, looks around and leaves """
     7        def __init__(self,name):
     8                Process.__init__(self)
     9                self.name = name
    10
    11def visit(self,timeInBank=0):
    12        print "%7.4f %s: Here I am"%(now(),self.name)
    13        yield hold,self,timeInBank
    14        print "%7.4f %s: I must leave"%(now(),self.name)
    15
    16def model():
    17        initialize()
    18        c1=Customer(name="Klaus")
    19        activate(c1,c1.visit(timeInBank=10.0),delay=5.0)
    20        c2=Customer(name="Tony")
    21        activate(c2,c2.visit(timeInBank=8.0),delay=2.0)
    22        c3=Customer(name="Evelyn")
    23        activate(c3,c3.visit(timeInBank=20.0),delay=12.0)
    24        simulate(until=400.0)
    25
    26model()

This program produces the following output:

     10 activate <Klaus> at time: 5.0 prior: 0
     20 activate <Tony> at time: 2.0 prior: 0
     30 activate <Evelyn> at time: 12.0 prior: 0
     42.0000 Tony: Here I am
     52.0 hold <Tony> delay: 8.0
     65.0000 Klaus: Here I am
     75.0 hold <Klaus> delay: 10.0
     810.0000 Tony: I must leave
     910.0 <Tony> terminated
    1012.0000 Evelyn: Here I am
    1112.0 hold <Evelyn> delay: 20.0
    1215.0000 Klaus: I must leave
    1315.0 <Klaus> terminated
    1432.0000 Evelyn: I must leave
    1532.0 <Evelyn> terminated

Another example:

     1""" bank09.py: Simulate customers arriving
     2    at random, using a Source requesting service
     3    from several clerks but a single queue
     4    with a random servicetime
     5"""
     6from __future__ import generators
     7from SimPy.SimulationTrace  import *
     8from random import Random
     9
    10class Source(Process):
    11    """ Source generates customers randomly"""
    12    def __init__(self,seed=333):
    13        Process.__init__(self)
    14        self.SEED = seed
    15
    16    def generate(self,number,interval):
    17        rv = Random(self.SEED)
    18        for i in range(number):
    19            c = Customer(name = "Customer%02d"%(i,))
    20            activate(c,c.visit(timeInBank=12.0))
    21            t = rv.expovariate(1.0/interval)
    22            yield hold,self,t
    23
    24class Customer(Process):
    25    """ Customer arrives, is served and leaves """
    26    def __init__(self,name):
    27        Process.__init__(self)
    28        self.name = name
    29
    30    def visit(self,timeInBank=0):
    31        arrive=now()
    32        print "%7.4f %s: Here I am "%(now(),self.name)
    33        yield request,self,counter
    34        wait=now()-arrive
    35        print "%7.4f %s: Waited %6.3f"%(now(),self.name,wait)
    36        tib = counterRV.expovariate(1.0/timeInBank)
    37        yield hold,self,tib
    38        yield release,self,counter
    39        print "%7.4f %s: Finished"%(now(),self.name)
    40
    41def model(counterseed=3939393):
    42    global counter,counterRV
    43    counter = Resource(name="Clerk",capacity = 2) #Lcapacity
    44    counterRV = Random(counterseed)
    45    initialize()
    46    sourceseed = 1133
    47    source = Source(seed = sourceseed)
    48    activate(source,source.generate(5,10.0),0.0)
    49    simulate(until=400.0)
    50
    51model()

This produces:

     1  0 activate <a_process> at time: 0 prior: 0
     20 activate <Customer00> at time: 0 prior: 0
     30 hold <a_process> delay: 8.73140489458
     4 0.0000 Customer00: Here I am
     50 request <Customer00> <Clerk>  priority: default
     6. . .waitQ: []
     7. . .activeQ: ['Customer00']
     8 0.0000 Customer00: Waited  0.000
     90 hold <Customer00> delay: 8.90355092634
    108.73140489458 activate <Customer01> at time: 8.73140489458 prior: 0
    118.73140489458 hold <a_process> delay: 8.76709801376
    12 8.7314 Customer01: Here I am
    138.73140489458 request <Customer01> <Clerk>  priority: default
    14. . .waitQ: []
    15. . .activeQ: ['Customer00', 'Customer01']
    16 8.7314 Customer01: Waited  0.000
    178.73140489458 hold <Customer01> delay: 21.6676883425
    188.90355092634 release <Customer00> <Clerk>
    19. . .waitQ: []
    20. . .activeQ: ['Customer01']
    21 8.9036 Customer00: Finished
    228.90355092634 <Customer00> terminated
    2317.4985029083 activate <Customer02> at time: 17.4985029083 prior: 0
    24
    25. . . . .

And here is an example showing the trace output for compound yield statements:

     1from SimPy.SimulationTrace import *
     2class Client(Process):
     3    def __init__(self,name):
     4        Process.__init__(self,name)
     5    def getServed(self,tank):
     6        yield (get,self,tank,10),(hold,self,1.5)
     7        if self.acquired(tank):
     8            print "%s got 10 %s"%(self.name,tank.unitName)
     9        else:
    10            print "%s reneged"%self.name
    11class Filler(Process):
    12    def __init__(self,name):
    13        Process.__init__(self,name)
    14    def fill(self,tank):
    15        for i in range(3):
    16            yield hold,self,1
    17            yield put,self,tank,10
    18initialize()
    19tank=Level(name="Tank",unitName="gallons")
    20for i in range(2):
    21    c=Client("Client %s"%i)
    22    activate(c,c.getServed(tank))
    23f=Filler("Tanker")
    24activate(f,f.fill(tank))
    25simulate(until=10)

It produces this output:

     10 get <Client 0>to get: 10 gallons from <Tank>  priority: default
     2. . .getQ: ['Client 0']
     3. . .putQ: []
     4. . .in buffer: 0
     5|| RENEGE COMMAND:
     6||  hold <Client 0> delay: 1.5
     70 get <Client 1>to get: 10 gallons from <Tank>  priority: default
     8. . .getQ: ['Client 0', 'Client 1']
     9. . .putQ: []
    10. . .in buffer: 0
    11|| RENEGE COMMAND:
    12||  hold <Client 1> delay: 1.5
    130 hold <Tanker> delay: 1
    140 hold <RENEGE-hold for Client 0> delay: 1.5
    150 hold <RENEGE-hold for Client 1> delay: 1.5
    161 put <Tanker> to put: 10 gallons into <Tank>  priority: default
    17. . .getQ: ['Client 1']
    18. . .putQ: []
    19. . .in buffer: 0
    201 hold <Tanker> delay: 1
    21Client 0 got 10 gallons
    221 <Client 0> terminated
    231.5 <RENEGE-hold for Client 1> terminated
    24Client 1 reneged
    251.5 <Client 1> terminated
    262 put <Tanker> to put: 10 gallons into <Tank>  priority: default
    27. . .getQ: []
    28. . .putQ: []
    29. . .in buffer: 10
    302 hold <Tanker> delay: 1
    313 put <Tanker> to put: 10 gallons into <Tank>  priority: default
    32. . .getQ: []
    33. . .putQ: []
    34. . .in buffer: 20
    353 <Tanker> terminated

In this example, the Client entities are requesting 10 gallons from the tank (a Level object). If they can’t get them within 1.5 time units, they renege (give up waiting). The renege command parts of the compound statements (hold,self,1.5)are shown in the trace output with a prefix of || to indicate that they are being executed in parallel with the primary command part (get,self,tank,10). They are being executed by behind-the-scenes processes (e.g. RENEGE-hold for Client 0).

The trace contains all calls of scheduling statements (yield …, activate(), reactivate(), cancel() and also the termination of processes (at completion of all their scheduling statements). For yield request and yield release calls, it provides also the queue status (waiting customers in waitQ and customers being served in activeQ.

## trace.tchange(): Changing the tracing

trace is an instance of the Trace class defined in SimulationTrace.py. This gets automatically initialized upon importing SimulationTrace..

The tracing can be changed at runtime by calling trace.tchange() with one or more of the following named parameters:

> start:

> > changes the tracing start time. Default is 0. Example: trace.tchange(start=222.2) to start tracing at simulation time 222.2.

> end :

> > changes the tracing end time. Default is a very large number (hopefully past any simulation endtime you will ever use). Example: trace.tchange(end=33) to stop tracing at time 33.

> toTrace:

> > changes the commands to be traced. Default is [“hold”,”activate”,”cancel”,”reactivate”,”passivate”,”request”, “release”,”interrupt”,”waitevent”,”queueevent”, “signal”,”waituntil”,”put”,”get”,”terminated”]. Value must be a list containing one or more of those values in the default. Note: “terminated” causes tracing of all process terminations. Example: trace.tchange(toTrace=[“hold”,”activate”]) traces only the yield hold and activate() statements.

> outfile:

> > redirects the trace out put to a file (default is sys.stdout). Value must be a file object open for writing. Example: trace.tchange(outfile=open(r”c:\python25\bank02trace.txt”,”w”))

All these parameters can be combined. Example: trace.tchange(start=45.0,toTrace=[“terminated”]) will trace all process terminations from time 45.0 till the end of the simulation.

The changes become effective at the time trace.tchange() is called. This implies for example that, if the call trace.tchange(start=50) is made at time 100, it has no effect before now()==100.

## treset(): Resetting the trace to default values

The trace parameters can be reset to their default values by calling trace.treset().

## trace.tstart(), trace.tstop(): Enabling/disabling the trace

Calling trace.tstart() enables the tracing, and trace.tstop() disables it. Neither call changes any tracing parameters.

## trace.ttext(): Annotating the trace

The event-by-event trace output is already very useful in showing the sequence in which SimPy’s quasi-parallel processes are executed.

For documentation, publishing or teaching purposes, it is even more useful if the trace output can be intermingled with output which not only shows the command executed, but also contextual information such as the values of state variables. If one outputs the reason why a specific scheduling command is executed, the trace can give a natural language description of the simulation scenario.

For such in-line annotation, the trace.ttext(<string>) method is available. It provides a string which is output together with the trace of the next scheduling statement. This string is valid only for the scheduling statement following it.

Example:

     1class Bus(Process):
     2    def __init__(self,name):
     3        Process.__init__(self,name)
     4
     5    def operate(self,repairduration=0):
     6        tripleft = 1000
     7        while tripleft > 0:
     8            trace.ttext("Try to go for %s"%tripleft)
     9            yield hold,self,tripleft
    10            if self.interrupted():
    11                tripleft=self.interruptLeft
    12                self.interruptReset()
    13                trace.ttext("Start repair taking %s time units"%repairduration)
    14                yield hold,self,repairduration
    15            else:
    16                break # no breakdown, ergo bus arrived
    17        trace.ttext("<%s> has arrived"%self.name)
    18
    19class Breakdown(Process):
    20    def __init__(self,myBus):
    21        Process.__init__(self,name="Breakdown "+myBus.name)
    22        self.bus=myBus
    23
    24    def breakBus(self,interval):
    25
    26        while True:
    27            trace.ttext("Breakdown process waiting for %s"%interval)
    28            yield hold,self,interval
    29            if self.bus.terminated(): break
    30            trace.ttext("Breakdown of %s"%self.bus.name)
    31            self.interrupt(self.bus)
    32
    33print"\n\n+++test_interrupt"
    34initialize()
    35b=Bus("Bus 1")
    36trace.ttext("Start %s"%b.name)
    37activate(b,b.operate(repairduration=20))
    38br=Breakdown(b)
    39trace.ttext("Start the Breakdown process for %s"%b.name)
    40activate(br,br.breakBus(200))
    41trace.start=100
    42print simulate(until=4000)
    43
    44This produces:
    45
    460 activate <Bus 1> at time: 0 prior: 0
    47---- Start Bus 1
    480 activate <Breakdown Bus 1> at time: 0 prior: 0
    49---- Start the Breakdown process for Bus 1
    50200 reactivate <Bus 1> time: 200 prior: 0
    51200 interrupt by: <Breakdown Bus 1> of: <Bus 1>
    52---- Breakdown of Bus 1
    53200 hold <Breakdown Bus 1> delay: 200
    54---- Breakdown process waiting for 200
    55200 hold <Bus 1> delay: 20
    56---- Start repair taking 20 time units
    57220 hold <Bus 1> delay: 800
    58---- Try to go for 800
    59400 reactivate <Bus 1> time: 400 prior: 0
    60400 interrupt by: <Breakdown Bus 1> of: <Bus 1>
    61---- Breakdown of Bus 1
    62400 hold <Breakdown Bus 1> delay: 200
    63---- Breakdown process waiting for 200
    64400 hold <Bus 1> delay: 20
    65---- Start repair taking 20 time units
    66420 hold <Bus 1> delay: 620
    67
    68 . . . . .

The line starting with “—-” is the comment related to the command traced in the preceding output line.

## Nice output of class instances

After the import of SimPy.SimulationTrace, all instances of classes Process and Resource (and all their subclasses) have a nice string representation like so:

     1   >>> class Bus(Process):
     2...         def __init__(self,id):
     3...                 Process.__init__(self,name=id)
     4...                 self.typ="Bus"
     5...
     6>>> b=Bus("Line 15")
     7>>> b
     8<Instance of Bus, id 21860960:
     9     .name=Line 15
    10     .typ=Bus
    11>
    12>>>

This can be handy in statements like trace.ttext(“Status of %s”%b).