Tracing

This section describes how to produce a trace for WebSphere MQ.

Tracing WebSphere MQ for Windows

In WebSphere MQ for Windows, you enable or modify tracing using the strmqtrc control command, described in strmqtrc (Start trace). To stop tracing, you use the endmqtrc control command, described in endmqtrc (end trace).

For WebSphere MQ for Windows, you can also start and stop trace using the trace icon in the WebSphere MQ Services snap-in.

Selective component tracing on WebSphere MQ for Windows

Use the -t and -x options to control the amount of trace detail to record. By default, all trace points are enabled. The -x option enables you to specify the points you do not want to trace. So if, for example, you want to trace, for queue manager QM1, only data flowing over communications networks, use: 

strmqtrc -m QM1 -x all -t comms

For a full description of the trace command, see strmqtrc (Start trace).

Trace files

During the installation process, you can choose the drive on which trace files are to be located. The trace files are always placed in the directory \<mqmwork>\errors, where <mqmwork> is the directory selected when WebSphere MQ was installed to hold WebSphere MQ data files.

Trace-file names have the following format: 

 AMQppppp.TRC

where ppppp is the process identifier (PID) of the process producing the trace.

Notes:

  1. The process identifier can contain fewer, or more, digits than shown in the example.

  2. There is one trace file for each process running as part of the entity being traced.

An example of WebSphere MQ for Windows trace data

Figure 31 shows an extract from a WebSphere MQ for Windows trace:

Figure 31. Sample WebSphere MQ for Windows trace


Process : C:\Program Files\IBM\WebSphere MQ\bin\amqxssvn.exe
Version : 530 Level : p000-L020213
Date : 02/25/02  Time : 16:35:47
 
Counter  TimeStamp       Process.Thread    Data
============================================================
 
0000062F 16:35:47.348386 6278.1       --{  InitProcessInitialisation
00000630 16:35:47.348455 6278.1       ---{  xcsCreateNTSecurityAtts
00000631 16:35:47.348516 6278.1       ----{  xcsRequestThreadMutexSem
00000632 16:35:47.348583 6278.1       ----}  xcsRequestThreadMutexSem (rc=OK)
00000633 16:35:47.348639 6278.1       ----{  xcsInitGlobalSecurityData
00000634 16:35:47.349111 6278.1       ----}  xcsInitGlobalSecurityData (rc=OK)
00000635 16:35:47.349239 6278.1       ----{  xcsReleaseThreadMutexSem
00000636 16:35:47.349261 6278.1       ----}  xcsReleaseThreadMutexSem (rc=OK)
00000637 16:35:47.349275 6278.1       ---}  xcsCreateNTSecurityAtts (rc=OK)
00000638 16:35:47.349303 6278.1       ---{  xcsReleaseThreadMutexSem
00000639 16:35:47.349319 6278.1       ---}  xcsReleaseThreadMutexSem (rc=OK)
0000063A 16:35:47.349344 6278.1       --}  InitProcessInitialisation (rc=OK)
0000063B 16:35:47.349359 6278.1       --{  xcsCreateThreadMutexSem
0000063C 16:35:47.349395 6278.1       --}  xcsCreateThreadMutexSem (rc=OK)
0000063D 16:35:47.349872 6278.1       --{  xcsProgramInit
0000063E 16:35:47.349900 6278.1       --}  xcsProgramInit (rc=OK)
0000063F 16:35:47.350027 6278.1       --{  xcsInitialize
00000640 16:35:47.350048 6278.1       ---{  xcsRequestThreadMutexSem
00000641 16:35:47.350065 6278.1       ---}  xcsRequestThreadMutexSem (rc=OK)
00000642 16:35:47.350079 6278.1       ---{  xihCheckThreadList
00000643 16:35:47.350101 6278.1       ---}  xihCheckThreadList (rc=OK)
00000644 16:35:47.350115 6278.1       ---{  InitPrivateServices
00000645 16:35:47.350165 6278.1       attributes 32768
00000646 16:35:47.350204 6278.1       ----{  xcsCreateThreadMutexSem
00000647 16:35:47.350233 6278.1       ----}  xcsCreateThreadMutexSem (rc=OK)
00000648 16:35:47.350255 6278.1       pid MQ(6) system(6278)
00000649 16:35:47.350337 6278.1       ---}  InitPrivateServices (rc=OK)
0000064A 16:35:47.350360 6278.1       --{  xxxInitialize
0000064B 16:35:47.350977 6278.1       ---{  xcsGetMem

Tracing WebSphere MQ for AIX

WebSphere MQ for AIX uses the standard AIX system trace. Tracing is a two-step process:

  1. Gathering the data
  2. Formatting the results

WebSphere MQ uses two trace hook identifiers:

X'30D'
This event is recorded by WebSphere MQ on entry to or exit from a subroutine.

X'30E'
This event is recorded by WebSphere MQ to trace data such as that being sent or received across a communications network.

Trace provides detailed execution tracing to help you to analyze problems. IBM service support personnel might ask for a problem to be re-created with trace enabled. The files produced by trace can be very large so it is important to qualify a trace, where possible. For example, you can optionally qualify a trace by time and by component.

There are two ways to run trace:

  1. Interactively.

    The following sequence of commands runs an interactive trace on the program myprog and ends the trace. 

    trace -j30D,30E -o trace.file
->!myprog
->q
  2. Asynchronously.

    The following sequence of commands runs an asynchronous trace on the program myprog and ends the trace. 

    trace -a -j30D,30E -o trace.file
myprog
trcstop

You can format the trace file with the command: 

trcrpt -t /usr/mqm/lib/amqtrc.fmt trace.file > report.file

report.file is the name of the file where you want to put the formatted trace output.

Note:All WebSphere MQ activity on the machine is traced while the trace is active.

Selective component tracing on WebSphere MQ for AIX

Use the environment variable MQS_TRACE_OPTIONS to activate the high detail and parameter tracing functions individually. Because it enables tracing to be active without these functions, you can use it to reduce the overhead on execution speed when you are trying to reproduce a problem with tracing switched on. Table 18 defines the trace behavior under the various settings of MQS_TRACE_OPTIONS.

Table 18. MQS_TRACE_OPTIONS settings

MQS_TRACE_OPTIONS Value What will be traced
Unset (default) Default trace (all except high detail)
0 No WebSphere MQ trace
262148 Entry, exit and parameter trace
786436 Entry, exit, parameter, and high detail trace
4980740 Entry, exit, parameter, high detail, and SSL tracing
3407871 Default trace without parameter trace
3670015 Default trace, including parameter trace
7864319 Default trace, including parameter trace and SSL tracing
4194303 All tracing, including high detail trace

Notes:

  1. Set the environment variable MQS_TRACE_OPTIONS only if you have been instructed to do so by your service personnel.

  2. Typically MQS_TRACE_OPTIONS must be set in the process that starts the queue manager, and before the queue manager is started, or it is not recognized.

  3. Set MQS_TRACE_OPTIONS before tracing starts. If it is set after tracing starts it is not recognized.

SSL trace

If you request SSL trace, note the following:

An example of WebSphere MQ for AIX trace data

The following example is an extract of an AIX trace:

Figure 32. Sample WebSphere MQ for AIX trace


ID     ELAPSED_SEC     DELTA_MSEC   APPL    SYSCALL KERNEL  INTERRUPT
 
30D    0.000000000       0.000000   MQS FNC Entry. 71540.1 zcpSendOnPipe 
30E    0.000000038       0.000038   Msg Unencumbered (T/F)(0) 
30D    0.000000176       0.000138   MQS FNC Exit............. 51604.55 
                                    aqhCheckMsgUnencumbered rc=00000000
30E    0.000000418       0.000242   aqhCheckMsgChains : internal retcode
                                       208007d3
                                     
30D    0.000000516       0.000098   MQS FNC Entry.. 71540.14 xcsWaitEventSem 
30E    0.000000590       0.000074   MessageSent (24 bytes) 
30E    0.000000847       0.000257   aqhCheckMsgChains : internal retcode 
                                       208007d3
                                     
30E    0.000000936       0.000089   hev=1::0::0-307724 TimeOut(-1) 
30E    0.000001173       0.000237   aqhCheckMsgChains : internal retcode 
                                       208007d3
                                     
30D    0.000001313       0.000140   MQS FNC Entry............ 51604.55  
                                    aqtIdxToSpcFn 
30D    0.000001395       0.000082   MQS FNC Exit............. 51604.55 
                                    aqtIdxToSpcFn rc=00000000
30D    0.000001439       0.000044   MQS FNC Entry........ 36124.51 
                                    xcsCheckProcess 
30D    0.000001501       0.000062   MQS FNC Entry............ 51604.55 
                                    aqhCheckMsgUnencumbered
30E    0.000001645       0.000144   MQS Data from zcpSendOnPipe Length=0018                                        
                                        5A525354 000007E5 00000000 00000000
                                        ZRST 00000000 00000000   
30E    0.000001765       0.000120   pBCrsr (0) 
30D    0.000001907       0.000142   MQS FNC Entry............. 51604.55 
                                    aqhInTrans 
30D    0.000001997       0.000090   MQS FNC Exit.............. 51604.55 
                                    aqhInTrans rc=00000000
30D    0.000002025       0.000028   MQS FNC Entry.. 71540.1 xcsResetEventSem 
30E    0.000002243       0.000218   Msg Unencumbered (T/F)(0) 
30D    0.000002363       0.000120   MQS FNC Exit............. 51604.55 
                                    aqhCheckMsgUnencumbered rc=00000000
30E    0.000002392       0.000029   hev=1::0::0-305876 
30D    0.000002522       0.000130   MQS FNC Entry... 71540.14 xlsLockEvent 
30E    0.000002630       0.000108   aqhCheckMsgChains : internal retcode 
                                       208007d3

Tracing WebSphere MQ for HP-UX, WebSphere MQ for Solaris, and WebSphere MQ for Linux for Intel and Linux for zSeries

In WebSphere MQ for HP-UX, Solaris, and Linux, you enable or modify tracing using the strmqtrc control command, which is described in strmqtrc (Start trace). To stop tracing, you use the endmqtrc control command, which is described in endmqtrc (end trace). You can display formatted trace output using the dspmqtrc control command, which is described in dspmqtrc (display formatted trace output).

Selective component tracing on WebSphere MQ for HP-UX, WebSphere MQ for Solaris, and WebSphere MQ for Linux for Intel and Linux for zSeries

Use the -t and -x options to control the amount of trace detail to record. By default, all trace points are enabled. The -x option enables you to specify the points you do not want to trace. So if, for example, you want to trace, for queue manager QM1, only output data associated with using Secure Sockets Layer (SSL) channel security, use: 

strmqtrc -m QM1 -t ssl

For a full description of the trace command, see strmqtrc (Start trace).

Example trace data for WebSphere MQ for HP-UX, WebSphere MQ for Solaris, and WebSphere MQ for Linux for Intel and Linux for zSeries

Figure 33 shows an extract from a WebSphere MQ for HP-UX trace:

Figure 33. Sample WebSphere MQ for HP-UX trace


ID     ELAPSED_MICROSEC DELTA_MICROSEC  APPL    SYSCALL KERNEL  INTERRUPT
 
30d     0                0         	MQS FNC Exit.......... 24864.1
                                          xllSpinLockRequest rc=00000000
30d     117              117       	MQS FNC Entry......... 24864.1 
                                          xllSpinLockRelease 
30d     150              33        	MQS FNC Exit.......... 24864.1 
                                          xllSpinLockRelease rc=00000000
30d     180              30        	MQS FNC Entry......... 24864.1 
                                          xllSpinLockRequest 
30d     212              32        	MQS FNC Exit.......... 24864.1 
                                          xllSpinLockRequest rc=00000000
30d     246              34        	MQS FNC Entry......... 24864.1 
                                          xllSpinLockRelease 
30d     275              29        	MQS FNC Exit.......... 24864.1 
                                          xllSpinLockRelease rc=00000000
30d     304              29        	MQS FNC Exit!........ 24864.1 
                                          xllWaitSocketEvent rc=10806020
30d     335              31        	MQS FNC Exit!....... 24864.1 
                                          xcsWaitEventSem rc=10806020
30d     374              39        	MQS FNC Exit!...... 24864.1 
                                          zcpReceiveOnPipe rc=20805311
30d     408              34        	MQS FNC Entry...... 24864.1 ziiHealthCheck 
30d     439              31        	MQS FNC Entry....... 24864.1 xcsCheckProcess 
30e     506              67        	pid(24860)

Figure 34 shows an extract from a WebSphere MQ for Solaris trace:

Figure 34. Sample WebSphere MQ for Solaris trace


Timestamp        Process.Thread  Trace Data
===========================================
 12:25:03.559508     8887.1          Version : 530 Level : p000-L020308
 12:25:03.560647     8887.1          Date : 11/03/02  Time : 12:25:03
 12:25:03.560944     8887.1          PID : 8887 Process : strmqtrc
 12:25:03.560974     8887.1          --------------------------------
 12:25:03.561057     8887.1     -{  TermPrivateServices
 12:25:03.561092     8887.1     --{  xxxTerminate
 12:25:03.561142     8887.1     ---{  xcsDestroyThreadMutexSem
 12:25:03.561203     8887.1     ---}  xcsDestroyThreadMutexSem rc=OK
 12:25:03.561227     8887.1     ---{  xcsFreeMem
 12:25:03.561346     8887.1          component:23 pointer:3d4e8
 12:25:03.561378     8887.1     ---}  xcsFreeMem rc=OK
 12:25:03.561413     8887.1     ---{  xcsFreeMem
 12:25:03.561445     8887.1          component:23 pointer:3f670
 12:25:03.561469     8887.1     ---}  xcsFreeMem rc=OK
 12:25:03.561491     8887.1     --}  xxxTerminate rc=OK
 12:25:03.561532     8887.1     --{  xehTerminateAsySignalHandling
 12:25:03.561567     8887.1     ---{  xehStopAsySignalMonitor
 12:25:03.561640     8887.1          xihAsySignalMonitorMutex holder
                                     tid(0) mod(0)
 12:25:03.561667     8887.1     ----{  xcsRequestThreadMutexSem
 12:25:03.561690     8887.1     ----}  xcsRequestThreadMutexSem rc=OK
 12:25:03.561714     8887.1     ----{  xcsFreeMem
 12:25:03.561745     8887.1          component:23 pointer:3c398
 12:25:03.561769     8887.1     ----}  xcsFreeMem rc=OK
 12:25:03.561791     8887.1     ----{  xcsFreeMem
 12:25:03.561820     8887.1          component:23 pointer:3c360
 12:25:03.561844     8887.1     ----}  xcsFreeMem rc=OK
 12:25:03.561948     8887.1     ----{  xcsFreeMem
 12:25:03.561980     8887.1          component:23 pointer:3c328
 12:25:03.562005     8887.1     ----}  xcsFreeMem rc=OK
 12:25:03.562026     8887.1     ----{  xcsFreeMem
 12:25:03.562055     8887.1          component:23 pointer:3b880
 12:25:03.562079     8887.1     ----}  xcsFreeMem rc=OK
 12:25:03.562101     8887.1     ----{  xcsReleaseThreadMutexSem
 12:25:03.562123     8887.1     ----}  xcsReleaseThreadMutexSem rc=OK
 12:25:03.562159     8887.1     ----{  xcsThreadRaise
 12:25:03.562192     8887.1          tid(2) sig(19)
 12:25:03.562219     8887.1          xcsThreadRaise: Before Lock
 12:25:03.562246     8887.1          xcsThreadRaise: After Lock
 12:25:03.562273     8887.1          top of loop
 12:25:03.562307     8887.1          In Loop: pCtl = 0x0003ae00
 12:25:03.562337     8887.1          calling pthread_kill for pCtl(3b8d8)
 12:25:03.562452     8887.1          thread kill ok
 12:25:03.562482     8887.1     ----}  xcsThreadRaise rc=OK
 12:25:03.562515     8887.1          Successfully raised SIGPWR for tid(2)
 12:25:03.562898     8887.1          Destroyed xihAsy
                                     Started condition variable

Figure 35 shows an extract from a WebSphere MQ for Linux for Intel and Linux for zSeries trace:

Figure 35. Sample WebSphere MQ for Linux for Intel and Linux for zSeries trace


Timestamp        Process.Thread  Trace Data
===========================================
 13:14:57.514231      406.1     --------}! xlsWaitEvent rc=xecL_W_TIMEOUT
 13:14:57.514250      406.1     -------}! xcsWaitEventSem rc=xecL_W_TIMEOUT
 13:14:57.514256      406.1     ------}! zcpReceiveOnPipe rc=zrcC_E_TIMEOUT
 13:14:57.514262      406.1     ------{  ziiHealthCheck
 13:14:57.514266      406.1     -------{  xcsCheckProcess
 13:14:57.514276      406.1          pid(390)
 13:14:57.514283      406.1     -------}  xcsCheckProcess rc=OK
 13:14:57.514286      406.1     -------{  xcsCheckProcess
 13:14:57.514293      406.1          pid(413)
 13:14:57.514298      406.1     -------}  xcsCheckProcess rc=OK
 13:14:57.514302      406.1     ------}  ziiHealthCheck rc=OK
 13:14:57.514306      406.1     ------{  zcpReceiveOnPipe
 13:14:57.514310      406.1     -------{  xcsWaitEventSem
 13:14:57.514315      406.1     --------{  xlsWaitEvent
 13:14:57.514323      406.1          Event(0x4090f724) Timeout(10000) Posted(0)
 13:14:57.514327      406.1     ---------{  xlsLockEvent
 13:14:57.514333      406.1     ---------}  xlsLockEvent rc=OK
 13:14:57.514336      406.1     ---------{  xlsUnlockEvent
 13:14:57.514341      406.1     ---------}  xlsUnlockEvent rc=OK
 13:14:57.514345      406.1     ---------{  xtmRequestCallback
 13:14:57.514350      406.1     ----------{  xtmStartTimerThread
 13:14:57.514354      406.1     -----------{  xcsCreateThread
 13:14:57.514365      406.1          Attr(260) pThread(0x401a5068) pArg(0)
 13:14:57.514374      406.1          pthread_mutex_lock ok
 13:14:57.514382      406.1          rejected non-pool thread (0x8078b40)
 13:14:57.514390      406.1          rejected poolThreadP(0x807a270)
                                          - !mayBeSleeping
 13:14:57.514421      406.25663      pthread_cond_timedwait completed 
                                          poolThreadP(0x8082f30) rc(0)
 13:14:57.514437      406.25663      pool thread with poolThreadP(0x8082f30)
                                          redispatched for tid(25663)
 13:14:57.514443      406.25663 {  xppInitialiseDestructorRegistrations
 13:14:57.514451      406.25663      tP(0x8082f30)
 13:14:57.514455      406.25663 }  xppInitialiseDestructorRegistrations rc=OK

Trace files

All trace files are created in the directory /var/mqm/trace.

Note:You can accommodate production of large trace files by mounting a temporary file system over this directory.

SSL trace files have the names AMQ.SSL.TRC and AMQ.SSL.TRC.1. You cannot format SSL trace files; send them unchanged to IBM support.

Non-SSL trace-file names have the following format: 

 AMQppppp.TRC

where ppppp is the process identifier (PID) of the process producing the trace.

Notes:

  1. The process identifier can contain fewer, or more, digits than shown in the example.

  2. There is one trace file for each process running as part of the entity being traced.

© IBM Corporation 1994, 2002. All Rights Reserved