Event Trace - openmpp/openmpp.github.io GitHub Wiki

Home > Model Development Topics > Event Trace

This topic describes a model developer feature which reports the evolution of individual entities during a simulation.

Related topics

Topic contents

Introduction and outline

Event trace allows a model developer to probe the simulation of individual entities or groups of entities in detail. This can help to understand a model, to verify that it is working as intended, or to probe anomalies.

After an entity enters the simulation it undergoes a series of events which change attributes, either its own or those of linked entities. Changes in attributes can in turn condition the time of future events. An entity in a model with event trace capability generates event trace messages when it enters the simulation and during events. Event trace messages include simulation entry, simulation exit, event occurrence, conditional times of future events, and changes in attributes, links, and multilinks. Event trace messages are blocked or passed depending on run-time event trace options. Unblocked messages are written to the run trace file in a readable columnar format designed for visual scanning. Alternatively, messages can be written in a csv format to facilitate use in external applications.

Quick Start shows how to build a model with event trace capability and how to enable that capability in a model run.

The quick start is followed by several worked examples with illustrative inputs and outputs using the RiskPaths and Alpha2 models:
Worked example 1 which illustrates tracing events,
Worked example 2 which illustrates tracing attributes,
Worked example 3 which illustrates tracing links and multilinks. and Worked example 4 which illustrates tracing table increments.

Please note that the output of the quick start and worked examples shown in this topic may differ slightly due to OpenM++ version differences.

The worked examples are followed by general information about event trace.

This is followed by three subtopics with reference material:
Event trace columns which describes the meaning of the output columns,
Event trace messages which describes all possible event trace messages,
and Event trace options which decribes all options to control and filter event trace messages.

This topic concludes with two specialized technical subtopics related to event trace.

[back to topic contents]

Quick start

This quick start example uses the RiskPaths model in OM_ROOT/models/RiskPaths in the OpenM++ distribution. By default a model is not built with event trace functionality, and without it the examples in this topic will not work.

This subtopic contains the following sections.

[continue to worked example 1]
[back to topic contents]

1. Build model with event trace capability

Edit the model source code file RiskPaths/code/TraceOptions.mpp to change the event_trace option from off to on:

options event_trace = on;

Build the Release version of RiskPaths.
In Windows, the model executable will be RiskPaths/ompp/bin/RiskPaths.exe.
In Linux, the model executable will be RiskPaths/ompp-linux/bin/RiskPaths.

[back to quick start]
[back to topic contents]

2. Modify model ini file with event trace options

In the same folder as the RiskPaths executable there may already be a copy of the default model ini file RiskPaths.ini. If not create it using your IDE or a text editor such as Notepad.

Edit RiskPaths.ini to have the following content:

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 5

[EventTrace]
ReportStyle = readable

The following Windows screenshot shows RiskPaths.ini being edited in Visual Studio in the RiskPaths project:

Model event trace ini-file

[back to quick start]
[back to topic contents]

3. Run model using event trace

Launch the model in its bin directory using the ini file created in the previous step, being sure to also specify the OpenM.IniAnyKey option.

RiskPaths -ini RiskPaths.ini -OpenM.IniAnyKey true

In Windows you can run the Release version of RiskPaths from inside Visual Studio as follows:

  • Solution Configurations to Release and Solution Platforms to x64
  • Project Properties > Configuration Properties > Debugging > Command Arguments to
    -ini RiskPaths.ini -OpenM.IniAnyKey true
  • Project Properties > Configuration Properties > Debugging > Working Directory to $(TargetDir)
  • To launch the model, do Debug > Start without debugging or Press Ctrl-F5.

After the model runs the trace file RiskPaths.trace.txt should be present in the model bin directory and look like this:

         Time   Entity        Age       Id Trace               Value Name                                         Remarks
     0.000000   Person   0.000000        1 ENTER                                                             
    24.260999   Person  24.260999        1   EVENT                   Union1FormationEvent                    
    26.537813   Person  26.537813        1   EVENT                   FirstPregEvent                          
    27.260999   Person  27.260999        1   EVENT                   UnionPeriod2Event                       
   100.000000   Person 100.000000        1   EVENT                   DeathEvent                              
   100.000000   Person 100.000000        1 EXIT                                                              
     0.000000   Person   0.000000        2 ENTER                                                             
    22.052373   Person  22.052373        2   EVENT                   Union1FormationEvent                    
    24.678078   Person  24.678078        2   EVENT                   FirstPregEvent                          
    25.052373   Person  25.052373        2   EVENT                   UnionPeriod2Event                       
   100.000000   Person 100.000000        2   EVENT                   DeathEvent                              
   100.000000   Person 100.000000        2 EXIT                                                              
     0.000000   Person   0.000000        3 ENTER                                                             
    17.050111   Person  17.050111        3   EVENT                   Union1FormationEvent                    
    20.024665   Person  20.024665        3   EVENT                   FirstPregEvent                          
    20.050111   Person  20.050111        3   EVENT                   UnionPeriod2Event                       
   100.000000   Person 100.000000        3   EVENT                   DeathEvent                              
   100.000000   Person 100.000000        3 EXIT                                                              
     0.000000   Person   0.000000        4 ENTER                                                             
    17.410717   Person  17.410717        4   EVENT                   FirstPregEvent                          
   100.000000   Person 100.000000        4   EVENT                   DeathEvent                              
   100.000000   Person 100.000000        4 EXIT                                                              
     0.000000   Person   0.000000        5 ENTER                                                             
    24.157739   Person  24.157739        5   EVENT                   FirstPregEvent                          
   100.000000   Person 100.000000        5   EVENT                   DeathEvent                              
   100.000000   Person 100.000000        5 EXIT

The following Windows screenshot shows RiskPaths.trace.txt open in Visual Studio in the RiskPaths project. The screenshot also shows the command window and log output for the run, and highlights the expected warning generated by a model with event trace capability.

Run model using event trace

[back to quick start]
[back to topic contents]

Worked example 1

This section continues the quick start example to explore using EventTrace filters to find and probe entities in the simulation.

This subtopic contains the following sections:

[back to topic contents]

Find entities with a specific event

RiskPaths simulates how first and second unions affect first birth frequency. To probe entities which experience a second union, change SelectedEvents to only show the event Union2FormationEvent.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 5

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
; events
ShowEnterSimulation = no
ShowExitSimulation = no
ShowEvents = yes
SelectedEvents = Union2FormationEvent

The trace file RiskPaths.trace.txt now looks like this:

That's right, it's empty! That's because the run had only 5 cases and in those 5 cases the Union2FormationEvent never occurred. Expand the run to 10,000 cases by changing SimulationCases and set MaximumLines to report only the first 10. The width of the name column has been shortened to 20 from the default of 40 for more compact output.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 10000

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
MaximumLines = 10
; events
ShowEnterSimulation = no
ShowExitSimulation = no
ShowEvents = yes
SelectedEvents = Union2FormationEvent

The trace file looks like this:

         Time   Entity        Age       Id Trace               Value Name                     Remarks
    85.748654   Person  85.748654       11   EVENT                   Union2FormationEvent
    46.987741   Person  46.987741       13   EVENT                   Union2FormationEvent
    24.942941   Person  24.942941       65   EVENT                   Union2FormationEvent
    26.208783   Person  26.208783       94   EVENT                   Union2FormationEvent
    67.733676   Person  67.733676      101   EVENT                   Union2FormationEvent
    36.152105   Person  36.152105      135   EVENT                   Union2FormationEvent
    22.466353   Person  22.466353      211   EVENT                   Union2FormationEvent
    20.010964   Person  20.010964      222   EVENT                   Union2FormationEvent
    60.116048   Person  60.116048      262   EVENT                   Union2FormationEvent
Maximum lines exceeded, increase using EventTrace.MaximumLines

[back to worked example 1]
[back to topic contents]

Report on specific entities

In the previous section, the entity_id of the youngest of the 10 is 222 and the oldest is 266. To probe those two entities in more detail, set MaximumLines to 1000, set SelectedEvents to empty to report on all events, and set SelectedEntities to report only on those two entities. Also, set SimulationCases to 500 to increase run speed (RiskPaths has only one entity in each case, so this is sufficient to simulate the two cases we're after).

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 500

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
MaximumLines = 1000
; filters
SelectedEntities = 222,266
; events
ShowEnterSimulation = no
ShowExitSimulation = no
ShowEvents = yes
SelectedEvents =

Re-run RiskPaths. The trace file now looks like this:

         Time   Entity        Age       Id Trace               Value Name                     Remarks
    18.198452   Person  18.198452      222   EVENT                   Union1FormationEvent
    19.944885   Person  19.944885      222   EVENT                   Union1DissolutionEvent
    20.010964   Person  20.010964      222   EVENT                   Union2FormationEvent
    20.212818   Person  20.212818      222   EVENT                   FirstPregEvent      
    21.198452   Person  21.198452      222   EVENT                   UnionPeriod2Event   
   100.000000   Person 100.000000      222   EVENT                   DeathEvent          
    39.395331   Person  39.395331      266   EVENT                   Union1FormationEvent
    42.395331   Person  42.395331      266   EVENT                   UnionPeriod2Event   
    65.159506   Person  65.159506      266   EVENT                   Union1DissolutionEvent
    87.325967   Person  87.325967      266   EVENT                   Union2FormationEvent
   100.000000   Person 100.000000      266   EVENT                   DeathEvent

The evolution of entity_id 222 looks a bit odd. RiskPaths documents UnionPeriod2Event as a 3-year period after first union formation which can affect fertility:

/*NOTE(Person.UnionPeriod2Event, EN)
	Clock event which changes the union duration state union_status from
	US_FIRST_UNION_PERIOD1 to US_FIRST_UNION_PERIOD2. This event occurs 
	after 3 years in 1st union. The clock is set at first union formation.
*/

The event trace shows that for entity_id 222 a second union occurred at time=20.010964 and UnionPeriod2Event occurred later at time=21.198452 (exactly 3 years after the Union1FormationEvent event). It would be incoherent for union_status, which affects fertility, to change 3 years after the start of a first union if the Person is already in a second union. It might be good to investigate the model logic to confirm that the UnionPeriod2Event event has no effect if a second union has already formed.

[back to worked example 1]
[back to topic contents]

Report detailed history for a given entity

Probe entity_id 222 in more detail by setting SelectedEntities to 222 and observing scheduled future event times by turning on ShowQueuedEvents. All model events except for DeathEvent are listed in SelectedEvents to remove DeathEvent messages from the report. Otherwise, the report would be cluttered with lines showing the recomputation of time of death because the mortality rate changes at each birthday.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 500

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 25
MaximumLines = 10000
; filters
SelectedEntities = 222
; events
ShowEnterSimulation = no
ShowExitSimulation = no
ShowEvents = yes
ShowQueuedEvents = yes
SelectedEvents = \
    FirstPregEvent, \
    Union1FormationEvent, \
    Union1DissolutionEvent, \
    Union2FormationEvent, \
    Union2DissolutionEvent, \
    UnionPeriod2Event

The line continuation character \ is used to split the list of event names into multiple lines for readability and ease of editing.

The resulting trace report looks like this:

         Time   Entity        Age       Id Trace               Value Name                          Remarks
    15.000000   Person  15.000000      222     queued      81.828627     FirstPregEvent            was inf
    15.000000   Person  15.000000      222     queued      58.463729     Union1FormationEvent      was inf
    17.500000   Person  17.500000      222     queued      18.987406     FirstPregEvent            was 81.828627
    17.500000   Person  17.500000      222     queued      18.198452     Union1FormationEvent      was 58.463729
    18.198452   Person  18.198452      222   EVENT                   Union1FormationEvent     
    18.198452   Person  18.198452      222     queued      20.173365     FirstPregEvent            was 18.987406
    18.198452   Person  18.198452      222     queued      53.059542     Union1DissolutionEvent    was inf
    18.198452   Person  18.198452      222     queued            inf     Union1FormationEvent      was 18.198452
    18.198452   Person  18.198452      222     queued      21.198452     UnionPeriod2Event         was inf
    19.198452   Person  19.198452      222     queued      19.944885     Union1DissolutionEvent    was 53.059542
    19.944885   Person  19.944885      222   EVENT                   Union1DissolutionEvent   
    19.944885   Person  19.944885      222     queued      43.387166     FirstPregEvent            was 20.173365
    19.944885   Person  19.944885      222     queued            inf     Union1DissolutionEvent    was 19.944885
    19.944885   Person  19.944885      222     queued      20.010964     Union2FormationEvent      was inf
    20.000000   Person  20.000000      222     queued      55.173852     FirstPregEvent            was 43.387166
    20.010964   Person  20.010964      222   EVENT                   Union2FormationEvent     
    20.010964   Person  20.010964      222     queued      20.212818     FirstPregEvent            was 55.173852
    20.010964   Person  20.010964      222     queued      59.958810     Union2DissolutionEvent    was inf
    20.010964   Person  20.010964      222     queued            inf     Union2FormationEvent      was 20.010964
    20.212818   Person  20.212818      222   EVENT                   FirstPregEvent           
    20.212818   Person  20.212818      222     queued            inf     FirstPregEvent            was 20.212818
    20.212818   Person  20.212818      222     queued            inf     Union2DissolutionEvent    was 59.958810
    21.198452   Person  21.198452      222   EVENT                   UnionPeriod2Event        
    21.198452   Person  21.198452      222     queued            inf     UnionPeriod2Event         was 21.198452

No events of interest occurred in entity_id 222 after UnionPeriod2Event. On the other hand, this entity does not probe what might happen if a first birth had not already occurred prior to UnionPeriod2Event.

In this trace report, we see recalculation of future events triggered by other events. Recalculations are triggered by changes in an entity's attributes, and that only happens at events. The report shows, however, a recomputation of the time of event Union1DissolutionEvent occurring at time=19.198452, exactly one year after Union1FormationEvent occurs, with no associated event. This must be due to a self-scheduling event which is not shown in the output.

[back to worked example 1]
[back to topic contents]

Probe a time window

To probe in detail what's happening in entity_id 222 at time 19.198452 (the time of the event not shown in the previous run), turn on ShowSelfSchedulingEvents and ShowQueuedSelfSchedulingEvents, and set up a time restriction window which brackets that time by setting
MinimumTime=19.1 and MaximumTime=19.2.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 500

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 45
MaximumLines = 10000
; filters
SelectedEntities = 222
MinimumTime = 19.1
MaximumTime = 19.2
; events
ShowEnterSimulation = no
ShowExitSimulation = no
ShowEvents = yes
ShowSelfSchedulingEvents = yes
ShowQueuedEvents = yes
ShowQueuedSelfSchedulingEvents = yes
SelectedEvents = \
    FirstPregEvent, \
    Union1FormationEvent, \
    Union1DissolutionEvent, \
    Union2FormationEvent, \
    Union2DissolutionEvent, \
    UnionPeriod2Event

The trace report looks like this:

         Time   Entity        Age       Id Trace               Value Name                                              Remarks
    19.198452   Person  19.198452      222   EVENT                   self_scheduling_split(active_spell_duration(in_union,true),UNION_DURATION)
    19.198452   Person  19.198452      222     queued      21.198452     self_scheduling_split(active_spell_duration(in_union,true),UNION_DURATION)
    19.198452   Person  19.198452      222     queued      19.944885     Union1DissolutionEvent                        was 53.059542

The missing event is revealed to be the self-scheduling attribute self_scheduling_split(active_spell_duration(in_union,true),UNION_DURATION).
Perusing the RiskPaths code reveals that this self-scheduling attribute is assigned to the identity attribute union_duration, which is in turn used in the computation of the time of the Union1DissolutionEvent event.

[back to worked example 1]
[back to topic contents]

Worked example 2

This subtopic illustrates tracing attributes. It contains the following sections:

[back to topic contents]

Attributes with event context

Worked example 1 suggested that the derived attribute union_duration played a role in explaining the recomputation of an event time. Trace that attribute as well as in_union by turning on attribute tracing with ShowAttributes, and specifying the attributes to be traced with SelectedAttributes.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 500

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
MaximumLines = 10000
; filters
SelectedEntities = 222
; events
ShowEnterSimulation = yes
ShowExitSimulation = yes
ShowEvents = yes
; attributes
ShowAttributes = yes
SelectedAttributes = \
	in_union, \
	union_duration

The trace output looks like this:

         Time   Entity        Age       Id Trace               Value Name                     Remarks
     0.000000   Person   0.000000      222 ENTER                                         
     0.000000   Person   0.000000      222     attr                0   in_union               initial
     0.000000   Person   0.000000      222     attr                0   union_duration         initial
    18.198452   Person  18.198452      222   EVENT                   Union1FormationEvent
    18.198452   Person  18.198452      222     attr                1   in_union               was 0
    19.198452   Person  19.198452      222     attr                1   union_duration         was 0
    19.944885   Person  19.944885      222   EVENT                   Union1DissolutionEvent
    19.944885   Person  19.944885      222     attr                0   in_union               was 1
    19.944885   Person  19.944885      222     attr                0   union_duration         was 1
    20.010964   Person  20.010964      222   EVENT                   Union2FormationEvent
    20.010964   Person  20.010964      222     attr                1   in_union               was 0
    20.212818   Person  20.212818      222   EVENT                   FirstPregEvent      
    21.010964   Person  21.010964      222     attr                1   union_duration         was 0
    21.198452   Person  21.198452      222   EVENT                   UnionPeriod2Event   
    23.010964   Person  23.010964      222     attr                2   union_duration         was 1
    25.010964   Person  25.010964      222     attr                3   union_duration         was 2
    29.010964   Person  29.010964      222     attr                4   union_duration         was 3
    33.010964   Person  33.010964      222     attr                5   union_duration         was 4
   100.000000   Person 100.000000      222   EVENT                   DeathEvent          
   100.000000   Person 100.000000      222 EXIT

The output shows the the initial values of the attributes when the entity enters the simulation and changes in attributes as the simulation progresses. The attribute in_union changes in response to union formation events as expected. The attribute union_duration changes with no preceding event message because self-scheduling event messages are blocked with these EventTrace settings.

[back to worked example 2]
[back to topic contents]

Attributes without event context

Event messages can be be removed from the output by setting ShowEvents to off. The following settings trace some key attributes of RiskPaths for a single case.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 500

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
MaximumLines = 10000
; filters
SelectedEntities = 222
; events
ShowEnterSimulation = no
ShowExitSimulation = no
ShowEvents = no
; attributes
ShowAttributes = yes
SelectedAttributes = \
	case_seed, \
	union_status, \
	parity_status, \
	union_duration, \
	dissolution_duration

The trace output looks like this:

         Time   Entity        Age       Id Trace               Value Name                     Remarks
     0.000000   Person   0.000000      222     attr       1214330268   case_seed              initial
     0.000000   Person   0.000000      222     attr                0   dissolution_duration   initial
     0.000000   Person   0.000000      222     attr                0   parity_status          initial
     0.000000   Person   0.000000      222     attr                0   union_duration         initial
     0.000000   Person   0.000000      222     attr                0   union_status           initial
    18.198452   Person  18.198452      222     attr                1   union_status           was 0
    19.198452   Person  19.198452      222     attr                1   union_duration         was 0
    19.944885   Person  19.944885      222     attr                0   union_duration         was 1
    19.944885   Person  19.944885      222     attr                3   union_status           was 1
    20.010964   Person  20.010964      222     attr                4   union_status           was 3
    20.212818   Person  20.212818      222     attr                1   parity_status          was 0
    21.010964   Person  21.010964      222     attr                1   union_duration         was 0
    23.010964   Person  23.010964      222     attr                2   union_duration         was 1
    25.010964   Person  25.010964      222     attr                3   union_duration         was 2
    29.010964   Person  29.010964      222     attr                4   union_duration         was 3
    33.010964   Person  33.010964      222     attr                5   union_duration         was 4

[back to worked example 2]
[back to topic contents]

Find entities using an attribute

In this example, we use event trace to identify entities which were pregnant during a second union, and output a detailed history of the oldest.

First, we add the new attribute my_filter to RiskPaths by editing Fertility.mpp and adding the following lines:

actor Person									               
{
    //EN Pregnant in second union
    bool my_filter = (parity_status == PS_PREGNANT) && (union_status == US_SECOND_UNION);
};

and rebuild RiskPaths. Next we set event trace options to block all messages except attribute messages for my_filter which have the value true. In C++ true has the value 1 and false has the value 0.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 500

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
MaximumLines = 10000
; filters
; events
ShowEnterSimulation = no
ShowExitSimulation = no
ShowEvents = no
; attributes
ShowAttributes = yes
SelectedAttributes = my_filter
MinimumAttribute = 1
MaximumAttribute = 1

The output is:

         Time   Entity        Age       Id Trace               Value Name                     Remarks
    26.196550   Person  26.196550       65     attr                1   my_filter              was 0
    26.395338   Person  26.395338       94     attr                1   my_filter              was 0
    24.133799   Person  24.133799      211     attr                1   my_filter              was 0
    20.212818   Person  20.212818      222     attr                1   my_filter              was 0
    33.073613   Person  33.073613      279     attr                1   my_filter              was 0
    32.492563   Person  32.492563      479     attr                1   my_filter              was 0
    23.148798   Person  23.148798      481     attr                1   my_filter              was 0

The output displays the 7 entities among the 500 which satisfied the condition during their lifetime. The Id column shows the entity_id of each, and the Age column shows the age at which the condition first become true.

Among the 7, the oldest was entity_id 279.

The following settings probe the lifetime of that entity in more detail:

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 500

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
MaximumLines = 10000
; filters
SelectedEntities = 279
; events
ShowEnterSimulation = yes
ShowExitSimulation = yes
ShowEvents = yes

The output is

         Time   Entity        Age       Id Trace               Value Name                     Remarks
     0.000000   Person   0.000000      279 ENTER                                              initial time=0.000000,age=0.000000
    27.167907   Person  27.167907      279   EVENT                   Union1FormationEvent
    29.155224   Person  29.155224      279   EVENT                   Union1DissolutionEvent
    30.167907   Person  30.167907      279   EVENT                   UnionPeriod2Event   
    32.105193   Person  32.105193      279   EVENT                   Union2FormationEvent
    33.073613   Person  33.073613      279   EVENT                   FirstPregEvent      
   100.000000   Person 100.000000      279   EVENT                   DeathEvent          
   100.000000   Person 100.000000      279 EXIT

[back to worked example 2]
[back to topic contents]

Using the case_seed attribute

The example Attributes without event context above traced case_seed, which is a built-in attribute of a case-based model. Case seeds of interest can also be obtained from aggregate output tables using an expression like max_value_out(case_seed) to identify the seed of a case for each populated cell of a table.

case_seed can be useful to speed exploration of a specific case in a case-based model by arranging that a run simulate only that single case. The following settings set the parameter SimulationSeed to 1214330268 from the previous trace output. The number of cases is also reduced from 500 to 1, for a very fast run. The SelectedEntities filter was removed.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 1
SimulationSeed = 1214330268

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
MaximumLines = 10000
; filters
; events
ShowEnterSimulation = no
ShowExitSimulation = no
ShowEvents = no
; attributes
ShowAttributes = yes
SelectedAttributes = \
	case_seed, \
	union_status, \
	parity_status, \
	union_duration, \
	dissolution_duration

With these settings, the trace file looks like this:

         Time   Entity        Age       Id Trace               Value Name                     Remarks
     0.000000   Person   0.000000        1     attr       1214330268   case_seed              initial
     0.000000   Person   0.000000        1     attr                0   dissolution_duration   initial
     0.000000   Person   0.000000        1     attr                0   parity_status          initial
     0.000000   Person   0.000000        1     attr                0   union_duration         initial
     0.000000   Person   0.000000        1     attr                0   union_status           initial
    18.198452   Person  18.198452        1     attr                1   union_status           was 0
    19.198452   Person  19.198452        1     attr                1   union_duration         was 0
    19.944885   Person  19.944885        1     attr                0   union_duration         was 1
    19.944885   Person  19.944885        1     attr                3   union_status           was 1
    20.010964   Person  20.010964        1     attr                4   union_status           was 3
    20.212818   Person  20.212818        1     attr                1   parity_status          was 0
    21.010964   Person  21.010964        1     attr                1   union_duration         was 0
    23.010964   Person  23.010964        1     attr                2   union_duration         was 1
    25.010964   Person  25.010964        1     attr                3   union_duration         was 2
    29.010964   Person  29.010964        1     attr                4   union_duration         was 3
    33.010964   Person  33.010964        1     attr                5   union_duration         was 4

The trace output (and simulation) is identical to the previous output except for the Id column, which changed from 222 to 1. The Id column shows the entity_id of the entity which produced the message. In a case-based model, entity_id is a unique sequentially increasing counter for entities in the run.

Case-based models which construct cases by reading a file of microdata may not be able to reproduce a case of interest using this technique. OzProj in the OpenM++ distribution is an example. Such models can filter on one or more case seeds directly using SelectedCaseSeeds, as in the following example.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 500

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
MaximumLines = 10000
; filters
SelectedCaseSeeds = 1214330268
; events
ShowEnterSimulation = no
ShowExitSimulation = no
ShowEvents = no
; attributes
ShowAttributes = yes
SelectedAttributes = \
	case_seed, \
	union_status, \
	parity_status, \
	union_duration, \
	dissolution_duration

With these options, the output is as before.

         Time   Entity        Age       Id Trace               Value Name                     Remarks
     0.000000   Person   0.000000      222     attr       1214330268   case_seed              initial
     0.000000   Person   0.000000      222     attr                0   dissolution_duration   initial
     0.000000   Person   0.000000      222     attr                0   parity_status          initial
     0.000000   Person   0.000000      222     attr                0   union_duration         initial
     0.000000   Person   0.000000      222     attr                0   union_status           initial
    18.198452   Person  18.198452      222     attr                1   union_status           was 0
    19.198452   Person  19.198452      222     attr                1   union_duration         was 0
    19.944885   Person  19.944885      222     attr                0   union_duration         was 1
    19.944885   Person  19.944885      222     attr                3   union_status           was 1
    20.010964   Person  20.010964      222     attr                4   union_status           was 3
    20.212818   Person  20.212818      222     attr                1   parity_status          was 0
    21.010964   Person  21.010964      222     attr                1   union_duration         was 0
    23.010964   Person  23.010964      222     attr                2   union_duration         was 1
    25.010964   Person  25.010964      222     attr                3   union_duration         was 2
    29.010964   Person  29.010964      222     attr                4   union_duration         was 3
    33.010964   Person  33.010964      222     attr                5   union_duration         was 4

If a case-based model is designed to generate multiple cloned entities within a case, SelectedCaseSeeds can be helpful to probe all clones within a case.

[back to worked example 2]
[back to topic contents]

Worked example 3

This subtopic illustrates tracing link attributes and multilinks. It contains the following sections:

[back to topic contents]

Links and multiple entity types

This section uses the Alpha2 model, which is part of the OpenM++ distribution. To make Alpha2 capable of event trace, the statement

options event_trace = on;

was added to the model source module ompp_framework.ompp, and a default ini file Alpha2.ini added to the model bin folder, as described in Quick start. Also as described in Quick start, the model command line arguments were set to
-ini Alpha2.ini -OpenM.IniAnyKey true

Alpha2 has several different kinds of entities, two of which are Person and Thing. A one-to-one link between a Person and a Thing is declared in the model source statement

link Person.my_thing1 Thing.my_person1;

which declares the link attribute my_thing1 in Person and the reciprocal link my_person1 in Thing.

Both Person and Thing have an event named MortalityEvent. Person has a SpawnEvent which occurs immediately after a Person enters the simulation and which creates other entities.

The following run settings in Alpha2.ini trace selected events and attributes for entities 1 and 2.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 1

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
; filters
SelectedEntities = 1,2
; events
ShowEnterSimulation = yes
ShowExitSimulation = yes
ShowEvents = yes
SelectedEvents = \
    SpawnEvent, \
    MortalityEvent
; attributes
ShowAttributes = yes
SelectedAttributes = \
    my_thing1, \
    my_person1

The resulting trace output looks like this:

The answer is  42!
         Time   Entity        Age       Id Trace               Value Name                     Remarks
     0.000000   Person   0.000000        1 ENTER                                         
     0.000000   Person   0.000000        1     link          nullptr   my_thing1              initial
     0.000000   Person   0.000000        1   EVENT                   SpawnEvent          
     0.000000    Thing   0.000000        2 ENTER                                         
     0.000000    Thing   0.000000        2     link          nullptr   my_person1             initial
     0.000000   Person   0.000000        1     link                2   my_thing1              was nullptr
     0.000000    Thing   0.000000        2     link                1   my_person1             was nullptr
    48.288955   Person  48.288955        1   EVENT                   MortalityEvent      
    48.288955   Person  48.288955        1 EXIT                                          
    48.288955    Thing  48.288955        2     link          nullptr   my_person1             was 1
   117.760965    Thing 117.760965        2   EVENT                   MortalityEvent      
   117.760965    Thing 117.760965        2 EXIT

The first line in the trace output is produced by model code in Alpha2 which tests the trace file API. It is irrelevant to this example, but does illustrate that the trace file can contain output from model code, not just from event trace.

The kind of entity (Person or Thing) is shown in the Entity column and the entity_id which produced the message is shown in the Id column. MortalityEvent is actually two different events with the same name, one in Person and one in Thing. SpawnEvent in Person 1 creates a Thing (entity_id 2) and links to it through the link attribute my_thing1. Here's the corresponding model code extract:

void Person::SpawnEvent()
{
	// Create things and add to simulation
	Thing *thing1 = new Thing;
	thing1->Start();

	// Link Person to thing1
	my_thing1 = thing1;
...

When MortalityEvent causes Person 1 to exit the simulation, all its links are automatically emptied. That causes the link my_person1 in Thing 2 to become nullptr as shown in the trace output above.

[back to worked example 3]
[back to topic contents]

Multilinks

In Alpha2 each Person can have more than one Thing. The relationship is declared in the one-to-many link statement in model code

link Thing.spawner Person.things[];

which associates the link attribute spawner in Thing to the Person that spawned the Thing. A Person has a reciprocal multilink things which contains all the Thing entities it spawned. The following model code extract adds two Thing entities to the things multilink:

void Person::SpawnEvent()
{
	// Create things and add to simulation
	Thing *thing1 = new Thing;
	thing1->Start();

	Thing *thing2 = new Thing;
	thing2->Start();

	// populate multi-link of things
	things->Add(thing1);
	things->Add(thing2);
...  
}

The statement things->Add(thing1); automatically assigns the reciprocal spawner attribute in Thing to the Person entity.

The following run settings explore the multilink things and the reciprocal spawner link attribute.

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 1

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
; filters
SelectedEntities = 1,2,13
; events
ShowEnterSimulation = yes
ShowExitSimulation = yes
ShowEvents = yes
SelectedEvents = \
    SpawnEvent, \
    MortalityEvent
; attributes
ShowAttributes = yes
SelectedAttributes = \
    spawner, \
    things

The resulting trace output is:

The answer is  42!
         Time   Entity        Age       Id Trace               Value Name                     Remarks
     0.000000   Person   0.000000        1 ENTER                                         
     0.000000   Person   0.000000        1     multi                   things                 initial {}
     0.000000   Person   0.000000        1   EVENT                   SpawnEvent          
     0.000000    Thing   0.000000        2 ENTER                                         
     0.000000    Thing   0.000000        2     link          nullptr   spawner                initial
     0.000000    Thing   0.000000       13 ENTER                                         
     0.000000    Thing   0.000000       13     link          nullptr   spawner                initial
     0.000000   Person   0.000000        1     multi++             2   things                 is {2}
     0.000000    Thing   0.000000        2     link                1   spawner                was nullptr
     0.000000   Person   0.000000        1     multi++            13   things                 is {2,13}
     0.000000    Thing   0.000000       13     link                1   spawner                was nullptr
    48.288955   Person  48.288955        1   EVENT                   MortalityEvent      
    48.288955   Person  48.288955        1 EXIT                                          
    48.288955    Thing  48.288955        2     link          nullptr   spawner                was 1
    48.288955    Thing  48.288955       13     link          nullptr   spawner                was 1
   117.760965    Thing 117.760965        2   EVENT                   MortalityEvent      
   117.760965    Thing 117.760965        2 EXIT                                          
   144.675208    Thing 144.675208       13   EVENT                   MortalityEvent      
   144.675208    Thing 144.675208       13 EXIT

Each trace message for the things multilink shows the current contents of the multilink in the Remarks column. The initial value of things is empty, and multi++ in the Trace column notes when an entity is added to the multilink. There are no multi-- messages in this example, because the two Thing entities happened to outlive the Person entity. The spawner link attribute in each Thing was set automatically to nullptr when the Person exited the simulation during age 48.

Incidentally, the second Thing has entity_id 13 because each Thing spawns 10 Toy entities, but that's another story!

[back to worked example 3]
[back to topic contents]

Expanding the selected entities

This example uses the option SelectLinkedEntities to automatically select entities added through a link or multilink to an active selected entity. The following settings set selected entities to the single entity with 'entity_id' 1.

[OpenM]
TraceToFile = true
ProgressPercent = 25

[Parameter]
SimulationCases = 1

[EventTrace]
; format
ReportStyle = readable
NameColumnWidth = 20
; filters
SelectedEntities = 1
SelectLinkedEntities = yes
; events
ShowEnterSimulation = yes
ShowExitSimulation = yes
ShowEvents = yes
SelectedEvents = \
    SpawnEvent, \
    MortalityEvent

The trace output is

The answer is  42!
         Time   Entity        Age       Id Trace               Value Name                     Remarks
     0.000000   Person   0.000000        1 ENTER                                         
     0.000000   Person   0.000000        1   EVENT                   SpawnEvent          
     0.000000   Person   0.000000        1  selected++             2   my_thing1           
     0.000000   Person   0.000000        1  selected++            13   my_thing2           
    48.288955   Person  48.288955        1   EVENT                   MortalityEvent      
    48.288955   Person  48.288955        1 EXIT                                          
   117.760965    Thing 117.760965        2   EVENT                   MortalityEvent      
   117.760965    Thing 117.760965        2 EXIT                                          
   144.675208    Thing 144.675208       13   EVENT                   MortalityEvent      
   144.675208    Thing 144.675208       13 EXIT

The messages with selected++ in the Trace column show two entities 2 and 13 added to the set of selected entities. Subsequent messages include contributions from the three entities 1,2, and 13. Had entity 2 or 3 added links to other entities during the simulation, the set of selected entities would have been expanded to include them, too.

[back to worked example 3]
[back to topic contents]

Worked example 4

This worked example illustrates Event Trace options which show RiskPaths pushing table increments to accumulators for the entity table T06_BirthsByUnion. Generally, model developers don't need to probe the low-level mechanics of entity tabulation in OpenM++, but it can sometimes be useful.
Here's the declaration of that table:

table Person T06_BirthsByUnion  //EN Pregnancies by union status & order
[trigger_entrances(parity_status, PS_PREGNANT)]
{
   {
      unit    //EN Number of pregnancies
   }
   * union_status+  //EN Union Status at pregnancy
};

With a 5,000 case run, that table looks like this:

Union Status at pregnancy Number of pregnancies
Never in union 1,285
First union < 3 years 2,986
First Union > 3 years 293
After first union 11
Second union 57
After second union 1
All 4,633

When analyzing table increments, it's generally best to restrict the table to a single entity of interest, because otherwise the output may be too voluminous to be useful.

Here's what that table looks like in a run with only 1 case:

Union Status at pregnancy Number of pregnancies
Never in union 0
First union < 3 years 1
First Union > 3 years 0
After first union 0
Second union 0
After second union 0
All 1

The table shows that the one Person in the run had a single pregnancy which occurred in the first 3 years of the first union. The marginal total over all union_status categories is necessarily also 1.

The following run settings trace events, increments to this table, and changes to the two attributes parity_status and union_status used in the table declaration:

[OpenM]
TraceToFile = true

[Parameter]
SimulationCases = 1

[EventTrace]
ReportStyle = readable
NameColumnWidth = 25
MaximumLines = 20000
ShowEnterSimulation = yes
ShowExitSimulation = yes
ShowAttributes = yes
SelectedAttributes = parity_status, union_status
ShowEvents = yes
ShowTableIncrements = yes
SelectedTables = T06_BirthsByUnion

With these settings, the trace output looks like this:

         Time   Entity        Age       Id Trace               Value Name                          Remarks
     0.000000   Person   0.000000        1 ENTER                                              
     0.000000   Person   0.000000        1     attr                0   parity_status               initial
     0.000000   Person   0.000000        1     attr                0   union_status                initial
    24.260999   Person  24.260999        1   EVENT                   Union1FormationEvent     
    24.260999   Person  24.260999        1     attr                1   union_status                was 0
    26.537813   Person  26.537813        1   EVENT                   FirstPregEvent           
    26.537813   Person  26.537813        1     attr                1   parity_status               was 0
    27.260999   Person  27.260999        1   EVENT                   UnionPeriod2Event        
    27.260999   Person  27.260999        1   INCREMENT             1   T06_BirthsByUnion.acc0      cell=[1] accumulator=1
    27.260999   Person  27.260999        1   INCREMENT             1   T06_BirthsByUnion.acc0      cell=[6] accumulator=1
    27.260999   Person  27.260999        1     attr                2   union_status                was 1
   100.000000   Person 100.000000        1   EVENT                   DeathEvent               
   100.000000   Person 100.000000        1 EXIT

The trace output is coherent with the table shown above: The Person experienced a FirstPregEvent at age 26.537813, when union_status was at its second level First union < 3 years (which has integer value 1).

The event trace shows two INCREMENT lines. The first pushes an increment with value 1 to cell [1] of the table, which is correct (index [1] is the second cell, corresponding to First union < 3 years). The second pushes the same increment to cell [6] of the table. That's correct because [6] is the margin index for the table dimension. An increment is always pushed to the body and to all margin dimensions, and to all crossings of margin dimensions. For example, if a table has two dimensions and both have a margin, an increment will be pushed to 4 cells: one for the table body, one for each margin, and one for the crossed margins.

The INCREMENT lines above are correct, but their timing in the Person timeline may be puzzling. That's because by design a table increment is pushed to an accumulator ‘lazily’. The push happens only when an upcoming attribute change would invalidate the pending increment. Pushes can also happen when the entity exits the simulation. So, an increment may appear in the timeline later than might be expected. You can see that in action in the event trace output above when an upcoming change to union_status at time 27.260999 causes the pending increment to be pushed immediately before union_status changes. That increment was originally created when the table filter flashed true at time 26.537813 when the pregnancy occurred.

Table increments are 'lazy' to ensure that changes in multiple classificatory dimensions and/or filter settle down before being treated as a single finalized and coherent table increment.

For INCREMENT rows, the Value column is the value of the increment being pushed to an accumulator (always 1 in this example because ‘unit’). There are two increments shown, one is for the body of the table, the other for the margin. Each cell of a table has an accumulator (more than one if table expressions use multiple accumulators). The cell indices of the increment/accumulator are shown in the Remarks column, as is the value of the accumulator after the increment (from all cases so far in the sub). The two accumulators shown in the trace output are both 1 because the run had no other cases.

[back to topic contents]

General information

A model built with event trace capability can be run repeatedly with different trace options with no need to rebuild.

Event trace works with Release versions of models, so can be used to probe details in large simulations.

Event trace is intended for model development, not production. A model built with event trace will output the following warning to the log whenever it is run:

Warning : possible performance impact - model built with event_trace = on

A model built with event trace will also output the following warning to the log whenever it is run:

 Warning : model can expose microdata at run-time with event_trace = on

If this is not a concern, for example the model generates a synthetic population, this warning can be disabled by the following statement:

options event_trace_warning = off;

Some entity attributes are created by the OpenM++ compiler to implement model functionality. For example, if an entity table has a filter, an identity attribute is created to implement it. These internal generated attributes are normally hidden but they can be made visible by the following statement:

options all_attributes_visible = on;

An event trace message can only be produced by an active entity. Event trace messages are not produced before the entity enters the simulation or after the entity exits the simulation.

Event trace messages are produced directly and immediately as model code executes. The messages are output to the trace file if EventTrace filter conditions are met. For example, if an attribute is selected, an event trace message will be produced immediately whenever the valus changes. If the attribute is changed more than once during the implementation of an event, each change will produce a separate message.

Trace output is disabled by default when a model is run. Use OpenM.TraceToFile to enable it, e.g.

[OpenM]
TraceToFile = true

See the subtopic Trace file options for a complete listing of trace file options.

Event trace options are processed only if the model is run with the command line option -OpenM.IniAnyKey true. Unlike other options, OpenM.IniAnyKey must be specified on the command line, not in an ini file.

To avoid confusing output, event trace should be used in runs with a single sub/replicate/member.

A model can write lines to the trace file directly, in which case those lines will be interleaved with any event trace messages.

[back to topic contents]

Event trace columns

Each event trace message has up to 8 columns of information. Values for Time, Entity, Age, Id, and Trace are always present. Values for Value, Name, and Remarks may be absent, depending on the nature of the message.

The order, left- or right-justification, capitalization, and indentation of columns varies by message to help peruse voluminous output for salient features.

Column Column header Description
1 Time The time of the entity when it produced the message.
2 Entity The type of entity which produced the message, e.g. Person.
3 Age The age of the entity when it produced the message.
4 Id The entity_id of the entity which produced the message.
5 Trace The kind of message, e.g. EVENT is a message for event occurrence. See Event trace messages for all possible values.
6 Value A value associated with the message, e.g. the current value of an attribute.
7 Name A name associated with the message, e.g. the name of the event or attribute.
8 Remarks Supplementary information, e.g. the value of the attribute before it changed, or the contents of a multilink

If ReportStyle is csv, an additional leading column Line is present. For more information, see Event trace options - format.

[back to topic contents]

Event trace messages

The following table lists all possible kinds of event trace message. Values noted as 'initial' are those when the entity first enters the simulation before it experiences any events. The initial value of time does not necessarily correspond to the global time when the message was produced.

Kind of message Trace (5) Value (6) Name (7) Remarks (8)
Entity enters simulation ENTER
Entity exits simulation EXIT
Event occurrence EVENT event name
Event future time queued The future time event name The previous value of the future event time.
Attribute - initial attr The initial value attribute name
Attribute - change attr The current value attribute name The previous value of the attribute.
Link - initial link The entity_id or nullptr link name
Link - change link The entity_id or nullptr link name The previous value of the link.
Multilink - initial multi multilink name A list of all entities in the multilink.
Multilink - add multi++ The entity_id of the added entity multilink name A list of all entities in the multilink.
Multilink - remove multi-- The entity_id of the removed entity multilink name A list of all entities in the multilink.
Entity added to list of selected entities selected++ The entity_id of the added entity link or multilink name
Table increment pushed to accumulator INCREMENT The value of the increment table name and accumulator # The table cell indices of the accumulator to which the increment was pushed, and the updated value of the accumulator.
[back to topic contents]

Event trace options

Event trace options fall into five broad categories which are described in the following sections.

  • Format ReportStyle, MaximumLines, NameColumnWidth
  • Filters Block/pass messages based on entity characteristics
  • Events Block/pass messages on events and entity life cycle
  • Attributes Block/pass messages on attribute changes
  • Increments Block/pass messages on push table increment to accumulator

For reference, here is an extract of a model run .ini file with all event trace options:

;#============================================================================
;#
;# event trace model development options
;#
;# Requires activation of model development options using -OpenM.IniAnyKey (see above).
;# Requires that model code contains the statement
;#   options event_trace = on;
;# Requires OpenM.TraceToFile = true
;# 
;# See wiki for explanation of EventTrace options
;
; [EventTrace]
;
; format
;
; ReportStyle = readable              ; "modgen", "readable", or "csv", default: modgen
; MaximumLines = 100000               ; integer value, default: 20000
; NameColumnWidth = 20                ; integer value, default: 40
;
; filters
;
; SelectedEntityKinds = e1,e2,e3      ; comma separated list of entity kinds, if empty all entity kinds
; SelectedEntities = 1,2,3            ; comma separated list of integers, if empty all entities
; SelectLinkedEntities = no           ; default: no
; SelectedCaseSeeds = 1,2,3           ; comma separated list of case seeds, if empty all cases
; MinimumTime = 2025                  ; double value, default: -inf
; MaximumTime = 2025                  ; double value, default: +inf
; MinimumAge = 65                     ; double value, default: -inf
; MaximumAge = 66                     ; double value, default: +inf
;
; events
;
; ShowEnterSimulation = yes           ; default: yes
; ShowExitSimulation = yes            ; default: yes
; ShowEvents = yes                    ; default: yes
; SelectedEvents =  e1,e2,e3          ; comma separated list of event names, if empty all events
; ShowQueuedEvents = no               ; default: no
; ShowQueuedUnchanged = no            ; default: no
; ShowSelfSchedulingEvents = no       ; default: no
; ShowQueuedSelfSchedulingEvents = no ; default: no
;
; attributes
;
; ShowAttributes = no                 ; default: no
; SelectedAttributes = year,alive     ; comma separated list of attribute names, if empty all attributes
; MinimumAttribute = 1                ; double value, default: -inf
; MaximumAttribute = 1                ; double value, default: +inf
;
; table increments
;
; ShowTableIncrements = no            ; default: no
; SelectedTables = t1,t2,t3           ; comma separated list of table names, if empty all tables

[back to topic contents]

Event trace options - format

Option Type Default Description
ReportStyle string modgen One of readable, csv, or modgen (see below in this section).
MaximumLines integer 20000 Blocks messages if the line count exceeds this value. A final message is written to the trace.
NameColumnWidth integer 40 The width of the Name column (column 7) in message output.

The ReportStyle option specifies the content and format of trace output. It can be readable, csv, or modgen. For compatibility for x-compatible models, the default value is modgen.

The examples earlier in this topic illustrate the readable style.

The csv style has almost the same content and layout as the readable style, except transformed into csv format for use by downstream applications such as Excel. The csv style contains an additional leading column Line which contains the original line number. This can be useful as a secondary sort key to disambiguate the order of otherwise tied records. In the example below, lines 8 and 9 have identical Time but Line indicates the order in which the two attributes changed value. The exact order can be particularly important if events have tied times, or if an attribute changes value more than once at a given time.

In csv format some columns may have additional numeric precision compared to readable format.

The trace file name extension can be changed from the default .txt to .csv using the OpenM.TraceFilePath model run option, e.g. in a run ini file. See Trace file options.

Here is the output for the previous example Attributes with event context using ReportStyle = csv:

Line,Time,Entity,Age,Id,Trace,Value,Name,Remarks
1,0,"Person",0,222,"ENTER",,,
2,0,"Person",0,222,"attr",0,"in_union","initial"
3,0,"Person",0,222,"attr",0,"union_duration","initial"
4,18.19845239664,"Person",18.19845239664,222,"EVENT",,"Union1FormationEvent",
5,18.19845239664,"Person",18.19845239664,222,"attr",1,"in_union","was 0"
6,19.19845239664,"Person",19.19845239664,222,"attr",1,"union_duration","was 0"
7,19.94488519046,"Person",19.94488519046,222,"EVENT",,"Union1DissolutionEvent",
8,19.94488519046,"Person",19.94488519046,222,"attr",0,"in_union","was 1"
9,19.94488519046,"Person",19.94488519046,222,"attr",0,"union_duration","was 1"
10,20.01096416538,"Person",20.01096416538,222,"EVENT",,"Union2FormationEvent",
11,20.01096416538,"Person",20.01096416538,222,"attr",1,"in_union","was 0"
12,20.21281842274,"Person",20.21281842274,222,"EVENT",,"FirstPregEvent",
13,21.01096416538,"Person",21.01096416538,222,"attr",1,"union_duration","was 0"
14,21.19845239664,"Person",21.19845239664,222,"EVENT",,"UnionPeriod2Event",
15,23.01096416538,"Person",23.01096416538,222,"attr",2,"union_duration","was 1"
16,25.01096416538,"Person",25.01096416538,222,"attr",3,"union_duration","was 2"
17,29.01096416538,"Person",29.01096416538,222,"attr",4,"union_duration","was 3"
18,33.01096416538,"Person",33.01096416538,222,"attr",5,"union_duration","was 4"
19,100,"Person",100,222,"EVENT",,"DeathEvent",
20,100,"Person",100,222,"EXIT",,,

Here is the same output, displayed in a table as it might look in Excel:

Line Time Entity Age Id Trace Value Name Remarks
1 0 Person 0 222 ENTER
2 0 Person 0 222 attr 0 in_union initial
3 0 Person 0 222 attr 0 union_duration initial
4 18.19845239664 Person 18.19845239664 222 EVENT Union1FormationEvent
5 18.19845239664 Person 18.19845239664 222 attr 1 in_union was 0
6 19.19845239664 Person 19.19845239664 222 attr 1 union_duration was 0
7 19.94488519046 Person 19.94488519046 222 EVENT Union1DissolutionEvent
8 19.94488519046 Person 19.94488519046 222 attr 0 in_union was 1
9 19.94488519046 Person 19.94488519046 222 attr 0 union_duration was 1
10 20.01096416538 Person 20.01096416538 222 EVENT Union2FormationEvent
11 20.01096416538 Person 20.01096416538 222 attr 1 in_union was 0
12 20.21281842274 Person 20.21281842274 222 EVENT FirstPregEvent
13 21.01096416538 Person 21.01096416538 222 attr 1 union_duration was 0
14 21.19845239664 Person 21.19845239664 222 EVENT UnionPeriod2Event
15 23.01096416538 Person 23.01096416538 222 attr 2 union_duration was 1
16 25.01096416538 Person 25.01096416538 222 attr 3 union_duration was 2
17 29.01096416538 Person 29.01096416538 222 attr 4 union_duration was 3
18 33.01096416538 Person 33.01096416538 222 attr 5 union_duration was 4
19 100 Person 100 222 EVENT DeathEvent
20 100 Person 100 222 EXIT

The modgen output style looks like this:

Person - actor_id=1 - case_seed=1 -  : event=timeDeathEvent - time=100.000000000000000
Person - actor_id=1 - case_seed=1 -  : event=timeFirstPregEvent - time=inf
Person - actor_id=1 - case_seed=1 -  : event=timeUnion1DissolutionEvent - time=inf
Person - actor_id=1 - case_seed=1 -  : event=timeUnion1FormationEvent - time=inf
Person - actor_id=1 - case_seed=1 -  : event=timeUnion2DissolutionEvent - time=inf
Person - actor_id=1 - case_seed=1 -  : event=timeUnion2FormationEvent - time=inf
Person - actor_id=1 - case_seed=1 -  : event=timeUnionPeriod2Event - time=inf
Person - actor_id=1 - case_seed=1 -  : event=scheduled - 0 - time=1.000000000000000
Person - actor_id=1 - case_seed=1 -  : event=timeDeathEvent - time=100.000000000000000
Person - actor_id=1 - case_seed=1 -  : event=scheduled - 0 - time=2.000000000000000
Person - actor_id=1 - case_seed=1 -  : event=timeDeathEvent - time=100.000000000000000
...

The modgen report style allows detailed comparison of modgen and ompp versions of a x-compatible model. The Test Models utility rearranges, reformats, and normalizes modgen style of event trace output of both Modgen and OpenM++ versions of a model to improve comparability and help understand differences.

[back to event trace options]
[back to topic contents]

Event trace options - filters

Filter options pass or block any kind of event trace message based on the characteristics of the entity when it produced the message.

Option Type Default Description
SelectedEntityKinds comma separated list empty Block any message if entity kind (e.g. Person) not in this list (unless list is empty).
SelectedEntities comma separated list empty Block any message if entity not in this list (unless list is empty).
SelectLinkedEntities yes/no no An active entity in SelectedEntities will add new linked entities to SelectedEntities.
SelectedCaseSeeds comma separated list empty Block any message if case seed not in this list (unless list is empty).
MinimumTime floating point number -inf Block any message if global time < this.
MaximumTime floating point number +inf Block any message if global time > this.
MinimumAge floating point number -inf Block any message if entity age < this.
MaximumAge floating point number +inf Block any message if entity age > this.

For examples, see Worked example 1 Using filters

[back to event trace options]
[back to topic contents]

Event trace options - events

Event options pass or block specific kinds of message associated with entity lifecycle and events.

Option Type Default Description
ShowEnterSimulation yes/no yes Pass/block entity entrance message.
ShowExitSimulation yes/no yes Pass/block entity exit message.
ShowEvents yes/no yes Pass/block event occurrence message.
SelectedEvents comma separated list empty Block event message if event not in this list (unless list is empty).
ShowQueuedEvents yes/no no Pass/block event time message.
ShowQueuedUnchanged yes/no no Pass/block event time message if future time did not change.
ShowSelfSchedulingEvents yes/no no Pass/block self-scheduling event occurrence message.
ShowQueuedSelfSchedulingEvents yes/no no Pass/block self-scheduling event time message.

An entity produces a message when it recalculates the future scheduled time of an event. However, the default setting ShowQueuedUnchanged = no blocks the message if the recalculated future scheduled time did not change.

For examples, see Worked example 1 Using filters

[back to event trace options]
[back to topic contents]

Event trace options - attributes

Attribute options pass or block messages for attributes, links, and multilinks. An entity produces a message for an attribute when it enters the simulation and whenever the attribute changes.

Option Type Default Description
ShowAttributes yes/no no Pass/block attribute message
SelectedAttributes comma separated list empty Block attribute message if attribute not in this list (unless list is empty).
MinimumAttribute floating point number -inf Block attribute message if attribute value < this.
MaximumAttribute floating point number +inf Block attribute message if attribute value > this value.

If SelectedAttributes is not specified, all attribute messages are passed, including for attributes created by the OpenM++ compiler.

MinimumAttribute and MaximumAttribute apply only to normal numerical attributes, not links or multilinks.

The value of an attribute of type bool is 0 for false and 1 for true. The value of an attribute of type classification or partition is {0,1,2,...}.

For examples, see
Worked example 2 Tracing attributes
Worked example 3 Tracing links and multilinks

[back to event trace options]
[back to topic contents]

Event trace options - table increments

Table increment options pass or block messages related to pushing table increments to accumulators. An entity produces a table increment message whenever it pushes a completed increment to an accumulator.

Option Type Default Description
ShowTableIncrements yes/no no Pass/block push increment message
SelectedTables comma separated list empty Block table increment message if table not in this list (unless list is empty).

If SelectedTables is not specified, all push increment messages are passed.

For an example, see Worked example 4.

[back to event trace options]
[back to topic contents]

Trace file options

A number of OpenM options control if, how, and where the trace file is produced. The following is extracted from OM_ROOT/props/model/Model-example.ini.

;# trace settings:
;# trace can be enabled/disabled for 3 independent streams:
;#   console         - cout stream
;#   "last run" file - trace file with specified name, overwritten on every model run
;#   "stamped" file  - trace file with unique name, created for every model run
;#
;# "stamped" name produced from "last run" name by adding time-stamp and/or pid-stamp, i.e.:
;#   trace.txt => trace.2012_08_17_16_04_59_148.987654.txt
;#
;# If trace to file is enabled
;# then existing "last run" trace file is overwritten even if model does not write anything to trace output
;
; TraceToConsole     = false      ; trace to console, default false
; TraceToFile        = false      ; trace to file
; TraceToStampedFile = false      ; trace to "stamped" file
; TraceFilePath      = trace.txt  ; trace file path, default: current/dir/modelExeName.trace.txt
; TraceUseTimeStamp  = false      ; use time-stamp in trace "stamped" file name
; TraceUsePidStamp   = false      ; use pid-stamp in trace "stamped" file name
; TraceNoMsgTime     = true       ; if true then do not prefix trace messages with date-time
; TraceRank          = false      ; if true then prefix trace messages with MPI process rank

[back to topic contents]

Trace file API

Trace output can be toggled off or on from model code provided the model was built with event trace capability. The API consists of the two functions

void StartEventTrace(void);
void StopEventTrace(void);

This can be helpful in situations where the filtering functionality described in this topic is insufficient. For example, a rare condition in model code can be used to toggle event trace on to identify entities which experienced the condition for further exploration. Event trace is on at the beginning of a run, so an initial call to StopEventTrace at the beginning of a run (or case) is required for a subsequent call to StartEventTrace to have an effect.

[back to topic contents]

⚠️ **GitHub.com Fallback** ⚠️