### Navigation

- index
- next |
- previous |
- SimPy v2.1.0 documentation »
- Using SimPy »

# Insight into Models and Debugging SimPy Programs

Authors: | Klaus Muller
Date: | April 2010

Contents

- Insight into Models and Debugging SimPy Programs
  - Introduction
  - The tools
  - Using SimPy’s insight/debugging tools
  - Strategies

## 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.

### Navigation

- index
- next |
- previous |
- SimPy v2.1.0 documentation »
- Using SimPy »