Interpreting trace

Use the information in a formatted trace file to identify unexpected behavior.

About this task

A formatted log file, like the one in Formatting trace, contains a sequence of IBM® Integration Bus messages. These messages record the activity in a specific part of the system (the part that you identify when you start the trace). You can use this sequence to understand what is happening, and to check that the behavior that is recorded is what you are expecting.

For example, message flow trace records the path that a message takes through the message flow. You can see why decisions result in this path (where a choice is available).

Procedure

  1. Verify that the trace file is complete.

    If the size of the trace log is too small to contain all events, trace output continues at the start of the trace log, overwriting existing entries. This is known as wrapping.

    An indication that a trace has wrapped is the relationship between the first and last timestamp in it, and the time that trace was enabled. For example, assume that you start tracing at 10:15, and collect the trace at 10:30. If the trace timestamps run from 10:20 to 10:30, it is probable that trace wrapped. Of course it could mean that nothing happened between 10:15 and 10:20.

    Examine the trace and decide whether the beginning of it makes sense, and whether it looks complete. For example, if you want to trace the passage of three messages through a flow, and trace starts half way through the second message, it could have wrapped, or trace might not have been enabled early enough.

  2. If trace has wrapped, increase the size of the trace file, and rerun trace.
    For information on trace settings, see mqsichangetrace command.
  3. If you see unexpected behavior in a message flow or integration server, use this trace information to check the actions that have been taken and identify the source of an error or other discrepancy.

Results

The messages contain identifiers for the resources that are being traced, for example the integration servers and message flows. The identifier that is given is typically the label (the name) that you gave to the resource when you defined it.

Here is an extract from a user trace file. In the example, each column has been labeled:
Timestamp                 Thread ID Trace type  Message
2005-07-12 16:17:18.242605   5344   UserTrace   BIP2537I: Node 'Reply.MapToRequestor': 
                                                Executing statement   ''SET I = I + 1;''
                                                at ('.MapToRequestor.CopyMessageHeaders',
                                                '6.4'). 
2005-07-12 16:17:18.242605   5344   UserTrace   BIP2539I: Node 'Reply.MapToRequestor': 
                                                Evaluating expression ''I'' at 
                                                ('.MapToRequestor.CopyMessageHeaders', 
                                                '6.12'). This resolved to ''I''. The 
                                                result was ''1''. 
2005-07-12 16:17:18.242605   5344   UserTrace   BIP2539I: Node 'Reply.MapToRequestor': 
                                                Evaluating expression ''I + 1'' at 
                                                ('.MapToRequestor.CopyMessageHeaders',      
                                                '6.14'). This resolved to ''1 + 1''. 
                                                The result was ''2''. 
2005-07-12 16:17:18.242605   5344   UserTrace   BIP2566I: Node 'Reply.MapToRequestor': 
                                                Assigning value ''2'' to field / variable   
                                                ''I''. 
References such as '6.12' apply to the row and column number within a function that specify the location of the command that is being executed; in this case, row 6, column 12.