“””
Python processing of an IBM MQ trace file.
This script extracts key data from an IBM MQ client trace file, and calculates
the duration of various functions.
Author: Colin Paice(colinpaiceMQ@gmail.com)
Instructions
Extract the information for one thread from the file. For example
grep 17291.6 AMQ17291.0.FMT |grep -e ” }” -e ” {” -e “ccxSend” -e xcsWaitThreadEvent -e xcsRequestThreadMutexSem > aa.FMT
where
17291.6 is the thread of interest
AMQ17291.0.FMT is the formatted trace file.
grep … selects the rows with interesting data
> aa.FMT put the output in this file
cat cat aa.FMT |python3 mqtrace.py |grep -e ” }” -e ” {“|less
or (for more details)
cat aa.FMT |python3 mqtrace.py |less
DISCLAIMER
You are free to use this code in any way you like, subject to the
Python & IBM disclaimers & copyrights. I make no representations
about the suitability of this software for any purpose. It is
provided “AS-IS” without warranty of any kind, either express or
implied.
“””
import sys
mutexTime = 0.0
lastOpTime = 0
sendTime = 0.0
sendMutex=0.0
waitTime = 0.0
sendCount = 0
while True:
line = sys.stdin.readline()
if not line: break
l = line.rstrip() # strip trailing new line and line feed
a = l.split() # tokenis it
norx = a[3][-1:] # get eNtry or eXit string – the last character
verb = a[4] # function name
time = a[0].strip() # remove training and leading blanks from timestamp
if time[0] ==’*’: # some time stamps have a “*” to show long gap
time = time[1:]
a[0]=a[0][1:]
# convert to seconds and microseconds
t = 3600 * float(time[0:2]) + 60 * float(time[3:5]) + float(time[6:15])
# if entry… the string has …{
if norx == “{” :
oldT = t; # save the previous time
if verb == “xcsRequestThreadMutexSem”:
pass # do nothing as we saved the time above
elif verb == “ccxSend”:
sendT = t
sendCount += 1
elif verb == “xcsWaitThreadEvent”:
pass # do nothing as we saved the time above
elif a[3] == “{“: # we are the high level so “{” instead of “–{”
if lastOpTime == 0: # first time
lastOpTime = t
delta = t – lastOpTime # save the delta since last mq call
print(“%s %s %12.12s %s %-10s %8.6f”%(a[0],a[1],a[2],a[3],a[4],delta ) )
opStart = t; # start time of MQ Verb
else:
print(“Unhandled”,l)
else:
# exit from function
# calculate the time spent getting the mutex prior to send
if verb == “xcsRequestThreadMutexSem”:
delta = t-oldT
mutexTime += delta
sendMutex += delta
# dont print it
# print(“%s %8.6f %s %12.12s %s”%(a[0], delta,a[1],a[2],a[4]))
elif verb == “ccxSend”:
delta = t – sendT # from time of start send, to time of end send
sendTime += delta # accumulate time for send
sendT = 0
print(“%s %8.6f %s %12.12s %s mutex %8.6f “%(a[0], delta,a[1],a[2],a[4],sendMutex) )
sendMutex = 0
# the suspended waiting for the work to be done, and to be woken up
elif verb == “xcsWaitThreadEvent”:
delta = t – oldT
print(“%s %8.6f %s %s wait for reply %8.6f”%(a[0], delta,a[1],a[2],delta))
waitTime += delta
elif a[3] == “}”: # end of high level function ie “}” and not “–}”
delta = t – opStart;
print(“%s %s %12.12s } %-10s %8.6f sendCount %6.d sendTime %8.6f waitTIme %8.6f”%(a[0],a[1],a[2],a[4],delta,sendCount,sendTime,waitTime))
# print(“%s %s %12.12s } %-10s %8.6f mutexTime %8.6f sendTime %8.6f waitTIme %8.6f”%(a[0],a[1],a[2],a[4],delta,mutexTime,sendTime,waitTime))
mutexTime = 0
sendTime = 0
lastOpTime = t
waitTime = 0.0
sendCount = 0
else :
print(“ELSE”,verb)
print(l)
ColinPaice 