source: gpfs_3.1_ker2.6.20/lpp/mmfs/samples/debugtools/trsum.awk @ 69

Last change on this file since 69 was 16, checked in by rock, 17 years ago
  • Property svn:executable set to *
File size: 78.4 KB
RevLine 
[16]1#!/usr/bin/awk -f
2# You need a formatted trace file to analyze with this script first.
3# Turn on trace :  mmtrace trace={io | def | all} 
4# Stop trace and format the file : mmtrace stop
5BEGIN {
6  if (ARGC < 2)
7  {
8    print "Usage: trsum.awk "
9    print "       [traceBR=1] [traceTok=1] [traceNew=1] [traceCond=1]"
10    print "       [traceMutex=1] [mutexDetails=1]"
11    print "       [traceIO=0] [traceMsg=0] [IOhist=0] [details=0]"
12    print "       [tidcol=n] [timecol=m] [tickfactor=24] [addtime=secs]"
13    print "       trcfile [trcfile2 ...]"
14    terminate=1
15    exit 1
16  }
17#  Default settings
18  details=1
19  traceIO=1
20  traceMsg=1
21  IOhist=1
22  lockhist=1
23  tidcol = 5
24  timecol = 14
25  tickfactor = 1
26  lockbucketsize = 0.0005
27  reqbucketsize = 0.0005
28  iobucketsize = 0.0005
29  sendbucketsize = 0.0001
30  handbucketsize = 0.0001
31  timebucketsize = 1.0
32  minlockbucket = 999999
33  minreqbucket = 999999
34  miniobucket = 999999
35  mintimebucket = 999999
36
37  newtid=-1
38  hex[0]="0"; hex[1]="1"; hex[2]="2"; hex[3]="3"
39  hex[4]="4"; hex[5]="5"; hex[6]="6"; hex[7]="7"
40  hex[8]="8"; hex[9]="9"; hex[10]="A"; hex[11]="B"
41  hex[12]="C"; hex[13]="D"; hex[14]="E"; hex[15]="F"
42}
43
44function d2x(dec, cnt, ch, i, val) # change decimal to hex
45{
46  ch = ""
47  for (i=1 ; i<=cnt ; i++)
48  {
49    val = dec%16
50    dec=(dec-val)/16
51    ch = hex[val] ch
52  }
53  return ch
54}
55
56function stuffafter(haystack, needle, pos) #find a particular string if it exists
57{
58  pos = index(haystack, needle)
59  if (pos > 0)
60    return substr(haystack, pos+length(needle))
61  return ""
62}
63
64function wordbefore(haystack, needle, pos, endpos) #return the string before a particular string if it exists
65{
66  endpos = index(haystack, needle)
67  if (endpos <= 1)
68    return ""
69  for (pos = endpos-1; pos >= 1; pos--)
70    if (substr(haystack,pos,1) != " ") break
71  endpos = pos + 1
72  for (pos = endpos-1; pos >= 1; pos--)
73    if (substr(haystack,pos,1) == " ") break
74  return substr(haystack, pos+1, endpos-pos)
75}
76
77function lastpos(haystack, needle, pos)  # return the position of a particular string if it exists
78{
79  for (pos = length(haystack); pos > 0 ; pos--)
80    if (substr(haystack,pos,1) == needle) return pos
81  return pos
82}
83
84function pad(level, chr, i)  # for formatting
85{
86  chr=""
87#  for (i=1; i < level; i++)
88#    chr = chr "--"
89  return chr
90}
91
92function firstword(line, pos)  #return first string
93{
94  pos = index(line, " ")
95  while (pos == 1)
96  {
97    line = substr(line,2)
98    pos = index(line, " ")
99  }
100  if (pos > 0)
101    return substr(line, 1, pos-1)
102  return line
103}
104
105function x2d(hex, d, ch, i, val) #convert hex to decimal
106{
107  d = 0
108  for (i=1 ; i<=length(hex) ; i++)
109  {
110    ch = substr(hex,i,1)
111    val = index("0123456789ABCDEF", ch)
112    if (val == 0)
113      val = index("0123456789abcdef", ch)
114    d = d*16 + val - 1
115  }
116  return d
117}
118
119function getmutextype(pos, ret)
120{
121  ret=$pos
122  if (substr(ret,2,2) == "0x")
123  {
124    pos++
125    ret=$pos
126  }
127  while (pos <= NF && substr($pos,length($pos)) != ")")
128  {
129    pos++
130    ret=ret" "$pos
131  }
132  return ret
133}
134
135#tracereport entrys
136#
137# Timestamp    Pid  COMPONENT_TAG: application trace record
138#----------- ------ ---------------------------------------
139#   0.000000   1302 TRACE_VNODE: cxiSleep: end delay 1000 HZ 100
140/COMPONENT_TAG: application trace record/ {
141  cpucol = 0
142  tidcol = index($0,"  Pid ")
143  timecol = tidcol - 12
144  lxtrace = 1
145  getline  # toss next line
146}
147
148/APPL    SYSCALL KERNEL/ {
149  cpucol = index($0,"CPU ")
150  tidcol = index($0,"TID ")
151  if (tidcol == 0) tidcol = index($0,"PID ")
152  timecol = index($0,"ELAPSED")-3
153}
154
155#006 1929377     7.160342830       0.000826                   TRACEBUFFER WRAPAROUND 5D88 C77A missed entries
156#006
157/TRACEBUFFER WRAPAROUND/ {
158  if (tidcol > 0)
159    newtid = firstword(substr($0, tidcol))
160  else
161    newtid = oldtid[newcpu]
162  if (timecol > 0)
163  {
164    newtime = firstword(substr($0, timecol))
165    if (addtime > 0) newtime += addtime
166    if (tickfactor > 1 && newtime != "")
167      newtime = newtime * tickfactor
168  }
169  if (index($0,"missed entries") > 0)
170  {
171    if (details)
172      printf("%8d %17.9f MISSED %8d TRACES\n", newtid, newtime, x2d(substr($(NF-2),8)))
173  }
174}
175
176# 101
177/_exit LR / {
178  if (tidcol > 0)
179    newtid = firstword(substr($0, tidcol))
180  else
181    newtid = oldtid[newcpu]
182  if (timecol > 0)
183  {
184    newtime = firstword(substr($0, timecol))
185    if (addtime > 0) newtime += addtime
186    if (tickfactor > 1 && newtime != "")
187      newtime = newtime * tickfactor
188  }
189  if (details)
190    printf("%8d %17.9f _exit\n", newtid, newtime)
191}
192
193# 106
194/dispatch: / {
195  if (cpucol > 0)
196  {
197    if (timecol > 0)
198    {
199      newtime = firstword(substr($0, timecol))
200      if (addtime > 0) newtime += addtime
201      if (tickfactor > 1 && newtime != "")
202        newtime = newtime * tickfactor
203    }
204
205    rec = stuffafter($0, "dispatch: ")
206
207    if (firstword(rec) == "idle") newcmd = "idle"
208    else newcmd = firstword(stuffafter(rec,"cmd="))
209    newtid = firstword(stuffafter(rec,"tid="))
210    newcpu = firstword(stuffafter(rec,"CPUID="))
211    if (numcpu < newcpu+1) numcpu = newcpu+1
212
213    if (oldtid[newcpu] != 0) {
214      delta = (newtime-oldtime[newcpu])*1000000
215      if (oldcmd[newcpu] == "idle") str="---"
216      else str= "[" oldcmd[newcpu] "]"
217      totcpu[oldtid[newcpu]" "str] += delta/1000000
218      tidname[oldtid[newcpu]] = str
219      if (details)
220        printf("%8d %17.9f %-20s %12.3f\n", oldtid[newcpu], newtime, str, delta)
221    }
222    oldtid[newcpu] = newtid
223    oldcmd[newcpu] = newcmd
224    oldtime[newcpu] = newtime
225    oldcpu = newcpu
226  }
227}
228
229# 102
230/slih cpuid/ {
231  if (cpucol > 0)
232  {
233    newcpu = firstword(substr($0, cpucol, 6))
234    if (numcpu < newcpu+1) numcpu = newcpu+1
235    if (tidcol > 0)
236      newtid = firstword(substr($0, tidcol))
237    else
238      newtid = oldtid[newcpu]
239    if (timecol > 0)
240    {
241      newtime = firstword(substr($0, timecol))
242      if (addtime > 0) newtime += addtime
243      if (tickfactor > 1 && newtime != "")
244        newtime = newtime * tickfactor
245    }
246
247    rec = stuffafter($0, "slih cpuid=")
248    newcmd = firstword(substr(rec,3))
249
250    if (oldtid[newcpu] != 0) {
251      delta = (newtime-oldtime[newcpu])*1000000
252      if (oldcmd[newcpu] == "idle") str="---"
253      else str= "[" oldcmd[newcpu] "]"
254      totcpu[oldtid[newcpu]" "str] += delta/1000000
255      tidname[oldtid[newcpu]] = str
256      if (details)
257        printf("%8d %17.9f %-20s %12.3f\n", oldtid[newcpu], newtime, str, delta)
258    }
259    slihresumes[newcpu] = oldcmd[newcpu]
260    oldtid[newcpu] = newtid
261    oldcmd[newcpu] = newcmd
262    oldtime[newcpu] = newtime
263    oldcpu = newcpu
264  }
265}
266
267# 103
268/return from slih/ {
269  if (cpucol > 0)
270  {
271    newcpu = firstword(substr($0, cpucol, 6))
272    if (numcpu < newcpu+1) numcpu = newcpu+1
273    if (tidcol > 0)
274      newtid = firstword(substr($0, tidcol))
275    else
276      newtid = oldtid[newcpu]
277    if (timecol > 0)
278    {
279      newtime = firstword(substr($0, timecol))
280      if (addtime > 0) newtime += addtime
281      if (tickfactor > 1 && newtime != "")
282        newtime = newtime * tickfactor
283    }
284
285    newcmd = slihresumes[newcpu]
286    delete slihresumes[newcpu]
287
288    if (oldtid[newcpu] != 0) {
289      delta = (newtime-oldtime[newcpu])*1000000
290      if (oldcmd[newcpu] == "idle") str="---"
291      else str= "[" oldcmd[newcpu] "]"
292      totcpu[oldtid[newcpu]" "str] += delta/1000000
293      tidname[oldtid[newcpu]] = str
294      if (details)
295        printf("%8d %17.9f %-20s %12.3f\n", oldtid[newcpu], newtime, str, delta)
296    }
297    oldtid[newcpu] = newtid
298    oldcmd[newcpu] = newcmd
299    oldtime[newcpu] = newtime
300    oldcpu = newcpu
301  }
302}
303
304# 100
305/INTERRUPT iar=/ {
306  if (cpucol > 0)
307  {
308    newcpu = firstword(substr($0, cpucol, 6))
309    if (numcpu < newcpu+1) numcpu = newcpu+1
310    if (newcpu >= 0)
311    {
312      if (tidcol > 0)
313        newtid = firstword(substr($0, tidcol))
314      else
315        newtid = oldtid[newcpu]
316      if (timecol > 0)
317      {
318        newtime = firstword(substr($0, timecol))
319        if (addtime > 0) newtime += addtime
320        if (tickfactor > 1 && newtime != "")
321          newtime = newtime * tickfactor
322      }
323
324      newcmd = wordbefore($0, " INTERRUPT iar=") "INTERRUPT"
325      if (newcmd == "DECREMENTER") newcmd = "DECR"
326
327      if (oldtid[newcpu] != 0) {
328        delta = (newtime-oldtime[newcpu])*1000000
329        if (oldcmd[newcpu] == "idle") str="---"
330        else str= "[" oldcmd[newcpu] "]"
331        totcpu[oldtid[newcpu]" "str] += delta/1000000
332        tidname[oldtid[newcpu]] = str
333        if (details)
334          printf("%8d %17.9f %-20s %12.3f\n", oldtid[newcpu], newtime, str, delta)
335      }
336      oldtid[newcpu] = newtid
337      oldcmd[newcpu] = newcmd
338      oldtime[newcpu] = newtime
339      oldcpu = newcpu
340    }
341  }
342}
343
344# 200
345/resume/ {
346  if (cpucol > 0)
347  {
348    newcpu = firstword(substr($0, cpucol, 6))
349    if (numcpu < newcpu+1) numcpu = newcpu+1
350    if (tidcol > 0)
351      newtid = firstword(substr($0, tidcol))
352    else
353      newtid = oldtid[newcpu]
354    if (timecol > 0)
355    {
356      newtime = firstword(substr($0, timecol))
357      if (addtime > 0) newtime += addtime
358      if (tickfactor > 1 && newtime != "")
359        newtime = newtime * tickfactor
360    }
361
362    newcmd = firstword(stuffafter($0, "resume "))
363    if (newcmd == "wait") newcmd = "---"
364
365    if (oldtid[newcpu] != 0) {
366      delta = (newtime-oldtime[newcpu])*1000000
367      if (oldcmd[newcpu] == "idle") str="---"
368      else str= "[" oldcmd[newcpu] "]"
369      totcpu[oldtid[newcpu]" "str] += delta/1000000
370      tidname[oldtid[newcpu]] = str
371      if (details)
372        printf("%8d %17.9f %-20s %12.3f\n", oldtid[newcpu], newtime, str, delta)
373    }
374    oldtid[newcpu] = newtid
375    oldcmd[newcpu] = newcmd
376    oldtime[newcpu] = newtime
377    oldcpu = newcpu
378  }
379}
380
381# 306,307,308,309
382
383# Timestamp    Pid  COMPONENT_TAG: application trace record
384#----------- ------ ---------------------------------------
385#   0.000000   1302 TRACE_VNODE: cxiSleep: end delay 1000 HZ 100
386/MMFS | TRACE_/ {
387  rec = $0
388  trinx = index($0," TRACE_")
389  if (trinx > 0)
390  {
391    recrest = substr($0,trinx+7)
392    lxtrace=1
393    tidcol = trinx - 6
394    timecol = tidcol - 12
395    if (timecol <= 0) timecol = 1
396  }
397  else
398    recrest = stuffafter($0, "MMFS ")
399
400  if (cpucol > 0)
401    newcpu = firstword(substr($0, cpucol, 6))
402  else
403    newcpu = oldcpu
404  if (tidcol > 0)
405    newtid = firstword(substr($0, tidcol))
406  else
407    newtid = oldtid[newcpu]
408  if (timecol > 0)
409  {
410    newtime = firstword(substr($0, timecol))
411    if (addtime > 0) newtime += addtime
412    if (tickfactor > 1 && newtime != "")
413      newtime = newtime * tickfactor
414  }
415
416  if (index(recrest, "ERRLOG") > 0)
417  {
418    rest=stuffafter(recrest, "ERRLOG: ")
419    printf("%8d %17.9f ERRLOG: %s\n", newtid, newtime, rest)
420  }
421  else if (index(recrest, "VNODE: mmfs_") > 0 ||
422           index(recrest, "VNODE: gpfs_v_") > 0 ||
423           index(recrest, "VNODE: vnodeLockctlInternal") > 0 )
424  {
425    if (index(recrest, "VNODE: mmfs_") > 0)
426    {
427      # Parse Var recrest "mmfs_"req entexit rest
428      rest=stuffafter(recrest, "mmfs_")
429    }
430    else if (index(recrest, "VNODE: gpfs_v_") > 0)
431    {
432      # Parse Var recrest "gpfs_v_"req entexit rest
433      rest=stuffafter(recrest, "gpfs_v_")
434    }
435    else if (index(recrest, "VNODE: vnodeLockctlInternal") > 0)
436      rest="lockctl" stuffafter(recrest, "vnodeLockctlInternal")
437    treq=firstword(rest)
438    rest=stuffafter(rest, treq)
439    entexit=firstword(rest)
440    rest=stuffafter(rest, entexit)
441    for (i = 1; i <= tidcount; i++)
442      if (tids[i] == newtid) break
443    if (i > tidcount)
444    {
445      tids[i] = newtid
446      tidcount = i
447    }
448    if (treq == "rele" || treq == hold) entexit = ""
449    if (entexit == "enter:") {
450      if (substr(treq,1,4) == "rdwr") {
451        op = firstword(stuffafter(rest, " op "))
452        if (op == "0") uioop[newtid] = "1"
453        else if (op == "1") uioop[newtid] = "0"
454        if (IOhist)
455        {
456          rdwrinprog++
457          inpbucket[rdwrinprog]++
458        }
459      }
460      if (treq == "lookup") extra = stuffafter(rest, " name ")
461      else if (treq == "root")
462      {
463        # Parse Var rest extra " vPP "
464        pos = index(rest, " vPP ")
465        if (pos > 0) extra = substr(rest,1,pos-1)
466        else extra = rest
467      }
468      else if (treq == "mkdir") extra = stuffafter(rest, " dirName ")
469      else if (treq == "rmdir") extra = stuffafter(rest, " name ")
470      else if (treq == "vget") extra = "inode "stuffafter(rest, " ino ")
471      else if (treq == "rename") {
472        if (substr(rest,1,1) == "v")
473          extra = stuffafter(rest, " name ")
474        else {
475          extra = stuffafter(rest, " new name ")
476          if (details)
477            printf("%s%8d %17.9f rename to (%s) %s\n", pad(tlevel), newtid, newtime, oldcmd[newcpu], extra)
478          continue
479        }
480      }
481      else extra=""
482      if (tlevel == 0)
483      {
484        if (firstVFStime == 0) firstVFStime = newtime
485        if (idleVFSstart != 0)
486        {
487          idleVFS += newtime - idleVFSstart
488          idleVFSstart = 0
489        }
490      }
491      tlevel = tlevel + 1
492      reqi = reqs[newtid]+1
493      reqs[newtid] = reqi
494      req[newtid,reqi] = treq
495      time[newtid,reqi] = newtime
496      level[newtid,reqi] = tlevel
497      if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
498      else str=treq
499      if (extra != "") str = str " " extra
500      if (idlestart[newtid] != "") {
501        idletime = newtime-idlestart[newtid]
502        if (details)
503          printf("%s%8d %17.9f %-33s ext %12.3f\n", pad(tlevel), newtid, newtime, str, idletime*1000000)
504      }
505      else {
506        if (details)
507          printf("%s%8d %17.9f %s\n", pad(tlevel), newtid, newtime, str)
508      }
509      if (idlestart[newtid] != "") {
510        timeout[newtid] += idletime
511        idlestart[newtid] = ""
512      }
513    }
514
515    else if (entexit == "exit:") {
516      exrc = firstword(stuffafter(rest, " rc "))
517      if (exrc == "0") exrc = ""
518      else if (exrc == "2" && treq == "lookup") exrc = " NOTFOUND"
519      else if (exrc == "25" && treq == "ioctl") exrc = " NOTTY"
520      else if (exrc != "") exrc = " err="exrc
521      for (wp = reqs[newtid]; wp >= 1; wp--)
522        if (treq == req[newtid,wp])
523          break;
524      if (wp > 0) {
525        oldtimex = time[newtid,wp]
526        oldlevel = level[newtid,wp]
527        for (; wp < reqs[newtid]; wp++)
528        {
529          req[newtid,wp] = req[newtid,wp+1]
530          time[newtid,wp] = time[newtid,wp+1]
531          level[newtid,wp] = level[newtid,wp+1]
532        }
533        reqs[newtid]--
534        delta = (newtime-oldtimex)*1000000
535        if (delta >= 1000) mark = " +"
536        else mark = ""
537        if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
538        else str=treq
539        if (details)
540          printf("%s%8d %17.9f %-20s %12.3f%s%s\n", pad(oldlevel), newtid, newtime, str, delta, mark, exrc)
541        if (tlevel <= 0)
542        {
543          idleVFS = 0
544          firstVFStime = 0.000000001
545        }
546        if (tlevel >= oldlevel && oldlevel >= 1)
547        {
548          tlevel = oldlevel - 1
549          if (tlevel <= 0)
550            idleVFSstart = newtime
551        }
552        lastVFStime = newtime
553        if (reqs[newtid] == 0) {
554          timein[newtid] += newtime-oldtimex
555          idlestart[newtid] = newtime
556          tidopcnt[newtid]++
557        }
558        timeop[treq] += newtime-oldtimex
559        cntop[treq]++
560      }
561      else if (treq != "hold") {
562        if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
563        else str=treq
564        if (details)
565          printf("%8d %17.9f %-20s*************%s\n", newtid, newtime, str, exrc)
566        if (tlevel <= 0)
567        {
568          idleVFS = 0
569          firstVFStime = 0.000000001
570        }
571        else
572        {
573          tlevel = tlevel - 1
574          if (tlevel <= 0)
575            idleVFSstart = newtime
576        }
577        lastVFStime = newtime
578      }
579      if (IOhist && wp > 0 && substr(treq,1,4) == "rdwr")
580      {
581        delta = delta/1000000
582        totaldelta += delta
583        totalrdwrs++
584        if (rdwrinprog > maxrdwrinprog) maxrdwrinprog=rdwrinprog
585        rdwrinprog--
586        if (rdwrinprog < 0) rdwrinprog = 0
587        bucket = int(delta / reqbucketsize)
588        if (minreqbucket > bucket) minreqbucket = bucket
589        if (maxreqbucket < bucket) maxreqbucket = bucket
590        if (rdwrKey[newtid] == "WRITE:")
591          wrbuckets[bucket]++
592        else if (rdwrKey[newtid] == "READ:")
593          rdbuckets[bucket]++
594        else
595          buckets[bucket]++
596        if (rdwrLen[newtid] != "")
597        {
598          buck=int(newtime/timebucketsize);
599          if (rdwrKey[newtid] == "WRITE:")
600            wrbytessum[buck]+=rdwrLen[newtid];
601          else
602            rdbytessum[buck]+=rdwrLen[newtid];
603          if (mintimebucket > buck) mintimebucket=buck;
604          if (highbuck < buck) highbuck=buck
605          delete rdwrLen[newtid]
606          delete rdwrKey[newtid]
607        }
608      }
609      else if (lockhist && wp > 0 && treq == "lockctl")
610      {
611        delta = delta/1000000
612        totallockdelta += delta
613        totallockctls++
614        bucket = int(delta / lockbucketsize)
615        if (minlockbucket > bucket) minlockbucket = bucket
616        if (maxlockbucket < bucket) maxlockbucket = bucket
617        lockbuckets[bucket]++
618      }
619    }
620    else if (index(recrest, "fastopen") > 0) {           # ????
621      # Parse Var recrest "oiP" rest
622      rest = stuffafter(recrest, "oiP")
623      if (details)
624        printf("%8d %17.9f Open  %s\n", newtid, newtime, rest)
625    }
626  }
627
628  else if (index(recrest, "VNODE: gpfs_i_") > 0 ||
629           index(recrest, "VNODE: gpfs_f_") > 0 ||
630           index(recrest, "VNODE: gpfs_s_") > 0 ||
631           index(recrest, "VNODE: gpfs_d_") > 0)
632  {
633    rest=stuffafter(recrest, "VNODE: gpfs_")
634    if (substr(rest,1,1) != "d")
635      rest=substr(rest, 3)
636    treq=firstword(rest)
637    rest=stuffafter(rest, treq)
638    # hack: gpfs_i_lookup: new -> gpfs_i_lookup exit: new
639    if (treq == "lookup:" && firstword(rest) == "new")
640    {
641      treq = "lookup"
642      rest = "exit: " rest
643    }
644    entexit=firstword(rest)
645    rest=stuffafter(rest, entexit)
646    # hack: exit2: -> exit:
647    if (entexit == "exit2:") entexit = "exit:"
648    for (i = 1; i <= tidcount; i++)
649      if (tids[i] == newtid) break
650    if (i > tidcount)
651    {
652      tids[i] = newtid
653      tidcount = i
654    }
655    if (treq == "rele" || treq == hold) entexit = ""
656    if (entexit == "enter:") {
657      if (substr(treq,1,4) == "rdwr") {
658        op = firstword(stuffafter(rest, " op "))
659        if (op == "0") uioop[newtid] = "1"
660        else if (op == "1") uioop[newtid] = "0"
661        if (IOhist)
662        {
663          rdwrinprog++
664          inpbucket[rdwrinprog]++
665        }
666      }
667      if (treq == "lookup") extra = stuffafter(rest, " name ")
668      else if (treq == "mkdir") extra = stuffafter(rest, " name ")
669      else if (treq == "rmdir") extra = stuffafter(rest, " name ")
670      else if (treq == "rename") extra = stuffafter(rest, " name ")
671      else extra=""
672      if (tlevel == 0)
673      {
674        if (firstVFStime == 0) firstVFStime = newtime
675        if (idleVFSstart != 0)
676        {
677          idleVFS += newtime - idleVFSstart
678          idleVFSstart = 0
679        }
680      }
681      tlevel = tlevel + 1
682      reqi = reqs[newtid]+1
683      reqs[newtid] = reqi
684      req[newtid,reqi] = treq
685      time[newtid,reqi] = newtime
686      level[newtid,reqi] = tlevel
687      if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
688      else str=treq
689      if (extra != "") str = str " " extra
690      if (idlestart[newtid] != "") {
691        idletime = newtime-idlestart[newtid]
692        if (details)
693          printf("%s%8d %17.9f %-33s ext %12.3f\n", pad(tlevel), newtid, newtime, str, idletime*1000000)
694      }
695      else if (details)
696        printf("%s%8d %17.9f %s\n", pad(tlevel), newtid, newtime, str)
697      if (idlestart[newtid] != "") {
698        timeout[newtid] += idletime
699        idlestart[newtid] = ""
700      }
701    }
702
703    else if (entexit == "exit:") {
704      exrc = firstword(stuffafter(rest, " rc "))
705      if (exrc == "0") exrc = ""
706      else if (exrc == "2" && treq == "lookup") exrc = " NOTFOUND"
707      else if (exrc == "25" && treq == "ioctl") exrc = " NOTTY"
708      else if (treq == "llseek" && substr(exrc,1,2) == "0x") exrc = ""
709      else if (exrc != "") exrc = " err="exrc
710      if (treq == "rdwr" && exrc == "")
711      {
712        resid = firstword(stuffafter(rest, "resid "))
713        if (resid != "" && resid != 0)
714          exrc = " resid="resid
715      }
716      for (wp = reqs[newtid]; wp >= 1; wp--)
717        if (treq == req[newtid,wp])
718          break;
719      if (wp > 0) {
720        oldtimex = time[newtid,wp]
721        oldlevel = level[newtid,wp]
722        for (; wp < reqs[newtid]; wp++)
723        {
724          req[newtid,wp] = req[newtid,wp+1]
725          time[newtid,wp] = time[newtid,wp+1]
726          level[newtid,wp] = level[newtid,wp+1]
727        }
728        reqs[newtid]--
729        delta = (newtime-oldtimex)*1000000
730        if (delta >= 1000) mark = " +"
731        else mark = ""
732        if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
733        else str=treq
734        if (details)
735          printf("%s%8d %17.9f %-20s %12.3f%s%s\n", pad(oldlevel), newtid, newtime, str, delta, mark, exrc)
736        if (tlevel <= 0)
737        {
738          idleVFS = 0
739          firstVFStime = 0.000000001
740        }
741        if (tlevel >= oldlevel && oldlevel >= 1)
742        {
743          tlevel = oldlevel - 1
744          if (tlevel <= 0)
745            idleVFSstart = newtime
746        }
747        lastVFStime = newtime
748        if (reqs[newtid] == 0) {
749          timein[newtid] += newtime-oldtimex
750          idlestart[newtid] = newtime
751          tidopcnt[newtid]++
752        }
753        timeop[treq] += newtime-oldtimex
754        cntop[treq]++
755      }
756      else if (treq != "hold") {
757        if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
758        else str=treq
759        if (details)
760          printf("%8d %17.9f %-20s*************%s\n", newtid, newtime, str, exrc)
761        if (tlevel <= 0)
762        {
763          idleVFS = 0
764          firstVFStime = 0.000000001
765        }
766        else
767        {
768          tlevel = tlevel - 1
769          if (tlevel <= 0)
770            idleVFSstart = newtime
771        }
772        lastVFStime = newtime
773      }
774      if (IOhist && wp > 0 && substr(treq,1,4) == "rdwr")
775      {
776        delta = delta/1000000
777        totaldelta += delta
778        totalrdwrs++
779        if (rdwrinprog > maxrdwrinprog) maxrdwrinprog=rdwrinprog
780        rdwrinprog--
781        if (rdwrinprog < 0) rdwrinprog = 0
782        bucket = int(delta / reqbucketsize)
783        if (minreqbucket > bucket) minreqbucket = bucket
784        if (maxreqbucket < bucket) maxreqbucket = bucket
785        if (rdwrKey[newtid] == "WRITE:")
786          wrbuckets[bucket]++
787        else if (rdwrKey[newtid] == "READ:")
788          rdbuckets[bucket]++
789        else
790          buckets[bucket]++
791        if (rdwrLen[newtid] != "")
792        {
793          buck=int(newtime/timebucketsize);
794          if (rdwrKey[newtid] == "WRITE:")
795            wrbytessum[buck]+=rdwrLen[newtid];
796          else
797            rdbytessum[buck]+=rdwrLen[newtid];
798          if (mintimebucket > buck) mintimebucket=buck;
799          if (highbuck < buck) highbuck=buck
800          delete rdwrLen[newtid]
801          delete rdwrKey[newtid]
802        }
803      }
804    }
805    else if (index(recrest, "fastopen") > 0) {           # ????
806      # Parse Var recrest "oiP" rest
807      rest = stuffafter(recrest, "oiP")
808      if (details)
809        printf("%8d %17.9f Open  %s\n", newtid, newtime, rest)
810    }
811  }
812
813  else if (index(recrest, "mmap process") > 0)
814  {
815    #old: mmap processBuf: bufP 0x54260E58 ...
816    #     mmap processBuf exit: code 0 err 0
817    #new: mmap processRead/Write enter: gnP 0x53677700
818    #     mmap processRead/Write exit: code 0 err 0
819    treq="mapbuf"
820    ok=0
821    if (index(recrest, "processRead") > 0)
822    {
823      treq="pagein"
824      uioop[newtid] = 1
825      ok=1
826      rest = stuffafter(recrest, "processRead ")
827      entexit = firstword(rest)
828      rest = stuffafter(rest, entexit)
829      if (entexit == "enter:") sawNewProcessRW = 1
830    }
831    else if (index(recrest, "processWrite") > 0)
832    {
833      treq="pageout"
834      uioop[newtid] = 0
835      ok=1
836      rest = stuffafter(recrest, "processWrite ")
837      entexit = firstword(rest)
838      rest = stuffafter(rest, entexit)
839      if (entexit == "enter:") sawNewProcessRW = 1
840    }
841    else if (index(recrest, "processBuf") > 0)
842    {
843      ok=1
844      rest = stuffafter(recrest, "processBuf")
845      if (substr(rest,1,6) == ": bufP")
846      {
847        entexit="enter:"
848        rest = stuffafter(rest, ": ")
849      }
850      else
851      {
852        entexit = firstword(rest)
853        rest = stuffafter(rest, entexit)
854      }
855      if (entexit == "enter:")
856      {
857        isrd = firstword(stuffafter(rest, "flags 0x"))
858        isrd = substr(isrd,length(isrd),1)
859        if (isrd == "1" || isrd == "3" || isrd == "5" || isrd == "7" ||
860            isrd == "9" || isrd == "B" || isrd == "D" || isrd == "F")
861          uioop[newtid] = 1
862        else
863          uioop[newtid] = 0
864      }
865      if (uioop[newtid] == 1)
866        treq="pagein"
867      else
868        treq="pageout"
869    }
870    else if (index(recrest, "processClump:") > 0 && !sawNewProcessRW)
871    {
872      rest = stuffafter(recrest, "processClump:")
873      entexit = "enter:"
874      ok=1
875      if (index(rest, "isRead 1") > 0)
876      {
877        treq="pagein"
878        uioop[newtid] = 1
879      }
880      else
881      {
882        treq="pageout"
883        uioop[newtid] = 0
884      }
885    }
886    if (ok)
887    {
888      for (i = 1; i <= tidcount; i++)
889        if (tids[i] == newtid) break
890      if (i > tidcount)
891      {
892        tids[i] = newtid
893        tidcount = i
894      }
895      if (entexit == "enter:")
896      {
897        for (wp = reqs[newtid]; wp >= 1; wp--)
898          if (treq == req[newtid,wp])
899            break;
900        if (wp > 0)
901        {
902          # missed the exit from previous call, pretend like we are seeing one now
903          exrc = ""  # unknown return code
904          oldtimex = time[newtid,wp]
905          oldlevel = level[newtid,wp]
906          for (; wp < reqs[newtid]; wp++)
907          {
908            req[newtid,wp] = req[newtid,wp+1]
909            time[newtid,wp] = time[newtid,wp+1]
910            level[newtid,wp] = level[newtid,wp+1]
911          }
912          reqs[newtid]--
913          delta = (newtime-oldtimex)*1000000
914          if (delta >= 1000) mark = " +"
915          else mark = ""
916          if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
917          else str=treq
918          if (details)
919            printf("%s%8d %17.9f %-20s %12.3f%s%s\n", pad(oldlevel), newtid, newtime, str, delta, mark, exrc)
920          if (tlevel <= 0)
921          {
922            idleVFS = 0
923            firstVFStime = 0.000000001
924          }
925          if (tlevel >= oldlevel && oldlevel >= 1)
926          {
927            tlevel = oldlevel - 1
928            if (tlevel <= 0)
929              idleVFSstart = newtime
930          }
931          lastVFStime = newtime
932          if (reqs[newtid] == 0) {
933            timein[newtid] += newtime-oldtimex
934            idlestart[newtid] = newtime
935            tidopcnt[newtid]++
936          }
937          timeop[treq] += newtime-oldtimex
938          cntop[treq]++
939          if (IOhist)
940          {
941            delta = delta/1000000
942            totaldelta += delta
943            totalrdwrs++
944            if (rdwrinprog > maxrdwrinprog) maxrdwrinprog=rdwrinprog
945            rdwrinprog--
946            if (rdwrinprog < 0) rdwrinprog = 0
947            bucket = int(delta / reqbucketsize)
948            if (minreqbucket > bucket) minreqbucket = bucket
949            if (maxreqbucket < bucket) maxreqbucket = bucket
950            if (rdwrKey[newtid] == "WRITE:")
951              wrbuckets[bucket]++
952            else if (rdwrKey[newtid] == "READ:")
953              rdbuckets[bucket]++
954            else
955              buckets[bucket]++
956            if (rdwrLen[newtid] != "")
957            {
958              buck=int(newtime/timebucketsize);
959              if (rdwrKey[newtid] == "WRITE:")
960                wrbytessum[buck]+=rdwrLen[newtid];
961              else
962                rdbytessum[buck]+=rdwrLen[newtid];
963              if (mintimebucket > buck) mintimebucket=buck;
964              if (highbuck < buck) highbuck=buck
965              delete rdwrLen[newtid]
966              delete rdwrKey[newtid]
967            }
968          }
969        }
970        pbgnp[newtid] = firstword(stuffafter(rest, "gnP "))
971        if (IOhist)
972        {
973          rdwrinprog++
974          inpbucket[rdwrinprog]++
975        }
976        if (tlevel == 0)
977        {
978          if (firstVFStime == 0) firstVFStime = newtime
979          if (idleVFSstart != 0)
980          {
981            idleVFS += newtime - idleVFSstart
982            idleVFSstart = 0
983          }
984        }
985        tlevel = tlevel + 1
986        reqi = reqs[newtid]+1
987        reqs[newtid] = reqi
988        req[newtid,reqi] = treq
989        time[newtid,reqi] = newtime
990        level[newtid,reqi] = tlevel
991        if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
992        else str=treq
993        if (idlestart[newtid] != "") {
994          idletime = newtime-idlestart[newtid]
995          if (details)
996            printf("%s%8d %17.9f %-33s ext %12.3f\n", pad(tlevel), newtid, newtime, str, idletime*1000000)
997        }
998        else if (details)
999          printf("%s%8d %17.9f %s\n", pad(tlevel), newtid, newtime, str)
1000        if (idlestart[newtid] != "") {
1001          timeout[newtid] += idletime
1002          idlestart[newtid] = ""
1003        }
1004      }
1005
1006      else if (entexit == "exit:") {
1007        exrc = firstword(stuffafter(rest, " rc "))
1008        if (exrc == "") exrc = firstword(stuffafter(rest, " err "))
1009        if (exrc == "0") exrc = ""
1010        else if (exrc == "2" && treq == "lookup") exrc = " NOTFOUND"
1011        else if (exrc == "25" && treq == "ioctl") exrc = " NOTTY"
1012        else if (exrc != "") exrc = " err="exrc
1013        for (wp = reqs[newtid]; wp >= 1; wp--)
1014          if (treq == req[newtid,wp])
1015            break;
1016        if (wp > 0) {
1017          oldtimex = time[newtid,wp]
1018          oldlevel = level[newtid,wp]
1019          for (; wp < reqs[newtid]; wp++)
1020          {
1021            req[newtid,wp] = req[newtid,wp+1]
1022            time[newtid,wp] = time[newtid,wp+1]
1023            level[newtid,wp] = level[newtid,wp+1]
1024          }
1025          reqs[newtid]--
1026          delta = (newtime-oldtimex)*1000000
1027          if (delta >= 1000) mark = " +"
1028          else mark = ""
1029          if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
1030          else str=treq
1031          if (details)
1032            printf("%s%8d %17.9f %-20s %12.3f%s%s\n", pad(oldlevel), newtid, newtime, str, delta, mark, exrc)
1033          if (tlevel <= 0)
1034          {
1035            idleVFS = 0
1036            firstVFStime = 0.000000001
1037          }
1038          if (tlevel >= oldlevel && oldlevel >= 1)
1039          {
1040            tlevel = oldlevel - 1
1041            if (tlevel <= 0)
1042              idleVFSstart = newtime
1043          }
1044          lastVFStime = newtime
1045          if (reqs[newtid] == 0) {
1046            timein[newtid] += newtime-oldtimex
1047            idlestart[newtid] = newtime
1048            tidopcnt[newtid]++
1049          }
1050          timeop[treq] += newtime-oldtimex
1051          cntop[treq]++
1052          if (IOhist)
1053          {
1054            delta = delta/1000000
1055            totaldelta += delta
1056            totalrdwrs++
1057            if (rdwrinprog > maxrdwrinprog) maxrdwrinprog=rdwrinprog
1058            rdwrinprog--
1059            if (rdwrinprog < 0) rdwrinprog = 0
1060            bucket = int(delta / reqbucketsize)
1061            if (minreqbucket > bucket) minreqbucket = bucket
1062            if (maxreqbucket < bucket) maxreqbucket = bucket
1063            if (rdwrKey[newtid] == "WRITE:")
1064              wrbuckets[bucket]++
1065            else if (rdwrKey[newtid] == "READ:")
1066              rdbuckets[bucket]++
1067            else
1068              buckets[bucket]++
1069            if (rdwrLen[newtid] != "")
1070            {
1071              buck=int(newtime/timebucketsize);
1072              if (rdwrKey[newtid] == "WRITE:")
1073                wrbytessum[buck]+=rdwrLen[newtid];
1074              else
1075                rdbytessum[buck]+=rdwrLen[newtid];
1076              if (mintimebucket > buck) mintimebucket=buck;
1077              if (highbuck < buck) highbuck=buck
1078              delete rdwrLen[newtid]
1079              delete rdwrKey[newtid]
1080            }
1081          }
1082        }
1083        else {
1084          if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
1085          else str=treq
1086          if (details)
1087            printf("%8d %17.9f %-20s **************%s\n", newtid, newtime, str, exrc)
1088          if (tlevel <= 0)
1089          {
1090            idleVFS = 0
1091            firstVFStime = 0.000000001
1092          }
1093          else
1094          {
1095            tlevel = tlevel - 1
1096            if (tlevel <= 0)
1097              idleVFSstart = newtime
1098          }
1099          lastVFStime = newtime
1100        }
1101      }
1102      else if (!havemmapwrite && substr(rest,1,5) == " lock")
1103      {
1104        #  lock block 0:233 offset 0 pos 0x0000000000E90000
1105        $0 = rest
1106        if (IOhist)
1107        {
1108          rdwrKey[newtid] = "WRITE:"
1109          rdwrLen[newtid] = 4096
1110        }
1111        gnP = pbgnp[newtid]
1112        if (inodeOFgnode[gnP] != "") inode = inodeOFgnode[gnP]
1113        else inode = -1
1114        if ($3 == "0:0")
1115        {
1116          if (sectorsPerBlockA[inode] != "")
1117            blocklen = sectorsPerBlockA[inode]
1118          else
1119            blocklen = -1
1120        }
1121        else
1122        {
1123          blocklen = (x2d(substr($NF,3)) - $5) / substr($3,3)
1124          sectorsPerBlockA[inode] = blocklen / 512
1125        }
1126        if (details)
1127          printf("%8d %17.9f WRITE: gnP %s inode %s snap 0 oiP 0xFFFFFFFF offset %s len 4096 blkSize %s opt 00000008\n", newtid, newtime, gnP, inode, $NF, blocklen)
1128      }
1129    }
1130  }
1131  else if (index(recrest, "DMAPI: mmfs_") > 0)
1132  {
1133    rest=stuffafter(recrest, "DMAPI: mmfs_")
1134    treq=firstword(rest)
1135    rest=stuffafter(rest, treq)
1136    entexit=firstword(rest)
1137    rest=stuffafter(rest, entexit)
1138    for (i = 1; i <= tidcount; i++)
1139      if (tids[i] == newtid) break
1140    if (i > tidcount)
1141    {
1142      tids[i] = newtid
1143      tidcount = i
1144    }
1145    if (entexit == "enter:") {
1146      if (substr(treq,1,4) == "rdwr") {
1147        op = firstword(stuffafter(rest, " op "))
1148        if (op == "0") uioop[newtid] = "1"
1149        else if (op == "1") uioop[newtid] = "0"
1150        if (IOhist)
1151        {
1152          rdwrinprog++
1153          inpbucket[rdwrinprog]++
1154        }
1155      }
1156      if (tlevel == 0)
1157      {
1158        if (firstVFStime == 0) firstVFStime = newtime
1159        if (idleVFSstart != 0)
1160        {
1161          idleVFS += newtime - idleVFSstart
1162          idleVFSstart = 0
1163        }
1164      }
1165      tlevel = tlevel + 1
1166      reqi = reqs[newtid]+1
1167      reqs[newtid] = reqi
1168      req[newtid,reqi] = treq
1169      time[newtid,reqi] = newtime
1170      level[newtid,reqi] = tlevel
1171      if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
1172      else str=treq
1173      if (idlestart[newtid] != "") {
1174        idletime = newtime-idlestart[newtid]
1175        if (details)
1176          printf("%s%8d %17.9f %-33s ext %12.3f\n", pad(tlevel), newtid, newtime, str, idletime*1000000)
1177      }
1178      else if (details)
1179        printf("%s%8d %17.9f %s\n", pad(tlevel), newtid, newtime, str)
1180      if (idlestart[newtid] != "") {
1181        timeout[newtid] += idletime
1182        idlestart[newtid] = ""
1183      }
1184    }
1185
1186    else if (entexit == "exit:") {
1187      exrc = firstword(stuffafter(rest, " rc "))
1188      if (exrc == "0") exrc = ""
1189      else if (exrc == "2" && treq == "lookup") exrc = " NOTFOUND"
1190      else if (exrc == "25" && treq == "ioctl") exrc = " NOTTY"
1191      else if (exrc != "") exrc = " err="exrc
1192      for (wp = reqs[newtid]; wp >= 1; wp--)
1193        if (treq == req[newtid,wp])
1194          break;
1195      if (wp > 0) {
1196        oldtimex = time[newtid,wp]
1197        oldlevel = level[newtid,wp]
1198        for (; wp < reqs[newtid]; wp++)
1199        {
1200          req[newtid,wp] = req[newtid,wp+1]
1201          time[newtid,wp] = time[newtid,wp+1]
1202          level[newtid,wp] = level[newtid,wp+1]
1203        }
1204        reqs[newtid]--
1205        delta = (newtime-oldtimex)*1000000
1206        if (delta >= 1000) mark = " +"
1207        else mark = ""
1208        if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
1209        else str=treq
1210        if (details)
1211          printf("%s%8d %17.9f %-20s %12.3f%s%s\n", pad(oldlevel), newtid, newtime, str, delta, mark, exrc)
1212        if (tlevel <= 0)
1213        {
1214          idleVFS = 0
1215          firstVFStime = 0.000000001
1216        }
1217        if (tlevel >= oldlevel && oldlevel >= 1)
1218        {
1219          tlevel = oldlevel - 1
1220          if (tlevel <= 0)
1221            idleVFSstart = newtime
1222        }
1223        lastVFStime = newtime
1224        if (reqs[newtid] == 0) {
1225          timein[newtid] += newtime-oldtimex
1226          idlestart[newtid] = newtime
1227          tidopcnt[newtid]++
1228        }
1229        timeop[treq] += newtime-oldtimex
1230        cntop[treq]++
1231      }
1232      else
1233      {
1234        if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
1235        else str=treq
1236        if (details)
1237          printf("%8d %17.9f %-20s*************%s\n", newtid, newtime, str, exrc)
1238        if (tlevel <= 0)
1239        {
1240          idleVFS = 0
1241          firstVFStime = 0.000000001
1242        }
1243        else
1244        {
1245          tlevel = tlevel - 1
1246          if (tlevel <= 0)
1247            idleVFSstart = newtime
1248        }
1249        lastVFStime = newtime
1250      }
1251      if (IOhist && wp > 0 && substr(treq,1,4) == "rdwr")
1252      {
1253        delta = delta/1000000
1254        totaldelta += delta
1255        totalrdwrs++
1256        if (rdwrinprog > maxrdwrinprog) maxrdwrinprog=rdwrinprog
1257        rdwrinprog--
1258        if (rdwrinprog < 0) rdwrinprog = 0
1259        bucket = int(delta / reqbucketsize)
1260        if (minreqbucket > bucket) minreqbucket = bucket
1261        if (maxreqbucket < bucket) maxreqbucket = bucket
1262        if (rdwrKey[newtid] == "WRITE:")
1263          wrbuckets[bucket]++
1264        else if (rdwrKey[newtid] == "READ:")
1265          rdbuckets[bucket]++
1266        else
1267          buckets[bucket]++
1268        if (rdwrLen[newtid] != "")
1269        {
1270          buck=int(newtime/timebucketsize);
1271          if (rdwrKey[newtid] == "WRITE:")
1272            wrbytessum[buck]+=rdwrLen[newtid];
1273          else
1274            rdbytessum[buck]+=rdwrLen[newtid];
1275          if (mintimebucket > buck) mintimebucket=buck;
1276          if (highbuck < buck) highbuck=buck
1277          delete rdwrLen[newtid]
1278          delete rdwrKey[newtid]
1279        }
1280      }
1281    }
1282  }
1283
1284  else if (index(recrest, "ESTALE") > 0)
1285  {
1286    rest = stuffafter(recrest, "VNODE:")
1287    for (i = 1; i <= tidcount; i++)
1288      if (tids[i] == newtid) break
1289    if (i > tidcount)
1290    {
1291      tids[i] = newtid
1292      tidcount = i
1293    }
1294    exrc = " err=ESTALE"
1295    wp = reqs[newtid]
1296    if (wp > 0) {
1297      treq = req[newtid,wp]
1298      oldtimex = time[newtid,wp]
1299      oldlevel = level[newtid,wp]
1300      for (; wp < reqs[newtid]; wp++)
1301      {
1302        req[newtid,wp] = req[newtid,wp+1]
1303        time[newtid,wp] = time[newtid,wp+1]
1304        level[newtid,wp] = level[newtid,wp+1]
1305      }
1306      reqs[newtid]--
1307      delta = (newtime-oldtimex)*1000000
1308      if (delta >= 1000) mark = " +"
1309      else mark = ""
1310      if (oldcmd[newcpu] != "") str=treq "(" oldcmd[newcpu] ")"
1311      else str=treq
1312      if (details)
1313        printf("%s%8d %17.9f %-20s %12.3f%s%s\n", pad(oldlevel), newtid, newtime, str, delta, mark, exrc)
1314      if (tlevel <= 0)
1315      {
1316        idleVFS = 0
1317        firstVFStime = 0.000000001
1318      }
1319      if (tlevel >= oldlevel && oldlevel >= 1)
1320      {
1321        tlevel = oldlevel - 1
1322        if (tlevel <= 0)
1323          idleVFSstart = newtime
1324      }
1325      lastVFStime = newtime
1326    }
1327  }
1328
1329  else if (index(recrest, "kSFSAcquireFcntlBRT exit:") > 0) {
1330  }
1331
1332  else if (index(recrest, "VNOP:") > 0) {
1333    rest = stuffafter(recrest, "VNOP: ")
1334    $0 = rest
1335    gni =index($0, "gnP ")
1336    ini =index($0, "inode ")
1337    if (gni > 0 && ini > 0)
1338    {
1339      gnP = firstword(substr($0,gni+4))
1340      inode = firstword(substr($0,ini+6))
1341      inodeOFgnode[gnP] = inode
1342      gnodeOFinode[inode] = gnP
1343    }
1344    if ($1 == "READ:" || $1 == "WRITE:")
1345    {
1346      if (IOhist && (key == "READ:" || $NF != "0000000C"))
1347      {
1348        rdwrKey[newtid] = $1
1349        if ($2 == "inode")
1350          rdwrLen[newtid] = $9
1351        else if ($6 != "snap")
1352          rdwrLen[newtid] = $11
1353        else
1354          rdwrLen[newtid] = $13
1355      }
1356      if ($NF == "00000008") havemmapwrite=1
1357    }
1358    else if ($1 == "GETVATTR:")
1359    {
1360      if ($5 == "3") nameofvp[$3] = "."
1361      else if (nameofvp[$3] != "")  rest = rest " " nameofvp[$3]
1362    }
1363    else if ($1 == "LOCKCTL:")
1364    {
1365      if (index(rest, "lckdat") > 0)
1366      {
1367        lcmd = firstword(stuffafter(rest, "cmd 0x0000000"))
1368        ltyp = firstword(stuffafter(rest, "type "))
1369        if (lcmd == 2) lcmd = "SET"
1370        else if (lcmd == 6) lcmd = "SET+WAIT"
1371        else if (lcmd == 0) lcmd = "QUERY"
1372        else if (lcmd == 1) lcmd = "QUERY+INOFLCK"
1373        else if (lcmd == 3) lcmd = "SET+INOFLCK"
1374        else if (lcmd == 4) lcmd = "QUERY+WAIT"
1375        else if (lcmd == 5) lcmd = "QUERY+INOFLCK+WAIT"
1376        else if (lcmd == 7) lcmd = "SET+INOFLCK+WAIT"
1377        if (ltyp == 1) ltyp = "RDLCK"
1378        else if (ltyp == 2) ltyp = "WRLCK"
1379        else if (ltyp == 3) {ltyp = "UNLCK"; if (lcmd == "SET") lcmd=""}
1380        rest = substr(rest, 1, index(rest, "lckdat")-1) lcmd " " ltyp
1381      }
1382      if (nameofvp[$2] != "")  rest = rest " " nameofvp[$2]
1383    }
1384    else if ($1 == "LOOKUP:")
1385    {
1386      # LOOKUP: vP 0x34CF58C4 inode 838030 snap 0 dvP 0x35146DA4 name 'wrfrst_01_000288'
1387      # LOOKUP: vP 0x32E31418 gnP 0x331FDF00 inode 39937 snap 0 dvP 0x32E43F44 name 'testfile'
1388      # LOOKUP: not found dvP 0x3512AE0C gnDirP 0x3512AE0C name 'external'
1389      name = substr($0, index($0, "'")+1)
1390      name = substr(name,1,length(name)-1)
1391      dvp = firstword(stuffafter(rest, "dvP"))
1392      if ($2 == "vP")
1393      {
1394        inode=firstword(stuffafter(rest, "inode "))
1395        if (nameofvp[dvp] != "")
1396        {
1397          if (name == ".")
1398          {
1399            if (nameofvp[dvp] == ".") name = dvp
1400            else name = nameofvp[dvp]
1401          }
1402          else if (name == "..")
1403          {
1404            #?? check inode of xxx/yyy/.. == inode of xxx
1405            pos = lastpos(nameofvp[dvp], "/")
1406            if (pos > 0) name = substr(nameofvp[dvp],1,pos-1)
1407            else name = $3
1408          }
1409          else
1410            name = nameofvp[dvp]"/"name
1411        }
1412        if (name == ".") nameofvp[$3] = $3
1413        else nameofvp[$3] = name
1414      }
1415      else
1416      {
1417        inode="notfound"
1418        if (nameofvp[dvp] != "") name = nameofvp[dvp]"/"name
1419      }
1420      lookups[inode,name] ++
1421      if (nameofvp[dvp] != "") rest = rest " in " nameofvp[dvp]
1422    }
1423    else if ($2 == "vP" && nameofvp[$3] != "")  rest = rest " " nameofvp[$3]
1424    else if ($2 == "dvP" && nameofvp[$3] != "")  rest = rest " in " nameofvp[$3]
1425    if (details)
1426      printf("%8d %17.9f %s\n", newtid, newtime, rest)
1427  }
1428
1429  else if (details && index(recrest, "kSFSOpen enter") > 0) {
1430    rest = stuffafter(recrest, "genNum")
1431    printf("%8d %17.9f Open gen %s\n", newtid, newtime, rest)
1432  }
1433
1434  if (traceIO)
1435  {
1436    if (index(recrest, "IO:") > 0) {
1437      rest = stuffafter(recrest, "IO: ")
1438      if (index(rest, "QIO:") > 0)
1439      {
1440        if (index(rest, "DIOQIO:") > 0) noDIOSIO=1
1441        buffer = firstword(stuffafter(rest,"buf "))
1442        if (substr(buffer,1,2) == "0x") buffer = substr(buffer,3)
1443        if (index(rest, "nsdId") > 0)
1444          disk = firstword(stuffafter(rest,"nsdId "))
1445        else if (index(rest, "nsdName") > 0)
1446        {
1447          disk = firstword(stuffafter(rest,"nsdName "))
1448          da = firstword(stuffafter(rest," da "))
1449          nsdname[da] = disk
1450        }
1451        else
1452        {
1453          disk = firstword(stuffafter(rest,"disk "))
1454          # old traces for nsd disks, can be 2 writes using same buffer
1455          if (disk == "FFFFFFFF" && QIOtime[buffer,disk] != "")
1456            disk = "FFFFFFFE"
1457        }
1458        QIOtime[buffer,disk] = newtime
1459        QIOtid[buffer,disk] = newtid
1460        qios++
1461        ioinpbucket[qios]++
1462        qiosdisk[disk]++
1463        if (idlediskFirst[disk] == 0) idlediskFirst[disk] = newtime
1464        if (idlediskStart[disk] != 0 && qiosdisk[disk] == 1)
1465        {
1466          idlediskTime[disk] += newtime-idlediskStart[disk]
1467          idlediskStart[disk] = 0
1468        }
1469
1470        if (details)
1471          printf("%8d %17.9f %s qlen %d\n", newtid, newtime, rest, qiosdisk[disk])
1472      }
1473      else if (index(rest, "DIOSIO:") > 0 && !noDIOSIO)
1474      {   # do this only if DIOQIO trace does not exist
1475        buffer = firstword(stuffafter(rest,"buffer "))
1476        if (substr(buffer,1,2) == "0x") buffer = substr(buffer,3)
1477        if (index(rest, "nsdId") > 0)
1478          disk = firstword(stuffafter(rest,"nsdId "))
1479        else if (index(rest, "nsdName") > 0)
1480        {
1481          disk = firstword(stuffafter(rest,"nsdName "))
1482          da = firstword(stuffafter(rest," da "))
1483          nsdname[da] = disk
1484        }
1485        else if (index(rest, "file") > 0)
1486          disk = firstword(stuffafter(rest,"file "))
1487        else
1488          disk = firstword(stuffafter(rest,"disk "))
1489        QIOtime[buffer,disk] = newtime
1490        QIOtid[buffer,disk] = newtid
1491        qios++
1492        ioinpbucket[qios]++
1493        qiosdisk[disk]++
1494        if (idlediskFirst[disk] == 0)
1495        {
1496          idlediskFirst[disk] = newtime
1497          idlediskLast[disk] = newtime
1498        }
1499        if (idlediskStart[disk] != 0 && qiosdisk[disk] == 1)
1500        {
1501          idlediskTime[disk] += newtime-idlediskStart[disk]
1502          idlediskStart[disk] = 0
1503        }
1504
1505        if (details)
1506          printf("%8d %17.9f %s qlen %d\n", newtid, newtime, rest, qiosdisk[disk])
1507      }
1508      else if (index(rest, "FIO:") > 0)
1509      {
1510        buffer = firstword(stuffafter(rest,"buf "))
1511        if (substr(buffer,1,2) == "0x") buffer = substr(buffer,3)
1512        if (index(rest, "nsdId") > 0 || index(rest, "nsdName") > 0)
1513        {
1514          da = firstword(stuffafter(rest," da "))
1515          if (index(rest, "nsdId") > 0)
1516          {
1517            disk = firstword(stuffafter(rest,"nsdId "))
1518            if (nsdname[da] != "") disk = nsdname[da]
1519          }
1520          else if (index(rest, "nsdName") > 0)
1521            disk = firstword(stuffafter(rest,"nsdName "))
1522          delete nsdname[da]
1523          if (QIOtime[buffer,disk] == "")
1524            if (QIOtime[buffer,"FFFFFFFF"] != "")
1525              tdsk = "FFFFFFFF"
1526            else if (QIOtime[buffer,"FFFFFFFE"] != "")
1527              tdsk = "FFFFFFFE"
1528            else tdsk=""
1529            if (tdsk != "")
1530            {
1531              QIOtime[buffer,disk] = QIOtime[buffer,tdsk]
1532              delete QIOtime[buffer,tdsk]
1533            }
1534        }
1535        else
1536          disk = firstword(stuffafter(rest,"disk "))
1537        if (QIOtime[buffer,disk] != "")
1538          delta = (newtime-QIOtime[buffer,disk])*1000000
1539        else delta = 0
1540        if (QIOtime[buffer,disk] > 0)
1541        {
1542          nios[disk]++
1543          if (maxqios < qios) maxqios = qios
1544          if (qios > 0) qios--
1545          if (maxqiosdisk[disk] < qiosdisk[disk]) maxqiosdisk[disk] = qiosdisk[disk]
1546          if (qiosdisk[disk] > 0) qiosdisk[disk]--
1547          if (qiosdisk[disk] == 0)
1548          {
1549            idlediskStart[disk] = newtime
1550            idlediskLast[disk] = newtime
1551          }
1552        }
1553        if (details)
1554          printf("%8d %17.9f %s qlen %d duration %.3f\n", QIOtid[buffer,disk], newtime, rest, qiosdisk[disk], delta)
1555        if (IOhist)
1556        {
1557          $0 = rest
1558          nSectors = $14
1559          if (QIOtime[buffer,disk] > 0)
1560          {
1561            delta = newtime-QIOtime[buffer,disk]
1562            totaliodelta += delta
1563            totalios++
1564            bucket = int(delta / iobucketsize)
1565            if (miniobucket > bucket) miniobucket = bucket
1566            if (maxiobucket < bucket) maxiobucket = bucket
1567
1568            buck=int(newtime/timebucketsize);
1569            if (mintimebucket > buck) mintimebucket=buck;
1570            if (highbuck < buck) highbuck=buck
1571            if (nSectors > maxSectors) maxSectors = nSectors
1572            if ($2 == "read")
1573            {
1574              rdiobuckets[bucket]++
1575              rdsectsum[buck]+=nSectors;
1576              rdsectbucket[nSectors]++
1577            }
1578            else
1579            {
1580              wriobuckets[bucket]++
1581              wrsectsum[buck]+=nSectors;
1582              wrsectbucket[nSectors]++
1583            }
1584          }
1585        }
1586        delete QIOtime[buffer,disk]
1587      }
1588    }
1589
1590    else if (index(recrest, "SFSRelAll") > 0) {
1591      rest = stuffafter(recrest, "SFSRelAll")
1592      if (details)
1593        printf("%8d %17.9f release all%s\n", newtid, newtime, rest)
1594    }
1595
1596    else if (index(recrest, "relAll") > 0) {
1597      rest = stuffafter(recrest, "discarding")
1598      if (details)
1599        printf("%8d %17.9f release all discarding:%s\n", newtid, newtime, rest)
1600    }
1601
1602    else if (index(recrest, "startSeqStream") > 0) {
1603      rest = stuffafter(recrest, "startSeqStream")
1604      if (details)
1605        printf("%8d %17.9f startSeqStream%s\n", newtid, newtime, rest)
1606    }
1607
1608    else if (index(recrest, "Buffer release") > 0) {
1609      rest = stuffafter(recrest, ": ")
1610      if (details)
1611        printf("%8d %17.9f %s\n", newtid, newtime, rest)
1612    }
1613
1614    else if (index(recrest, "uiomove") > 0) {
1615      rest = stuffafter(recrest, "kSFSRdWr")
1616      # if (details)
1617        # printf("%8d %17.9f kSFSRdWr%s\n", newtid, newtime, rest)
1618    }
1619  }
1620
1621  if (traceBR)
1622  {
1623    # TSTM: HandleTellRequest: downgrade BR key 09010DCE:3C0FB53B:00000003:00000000 0x0000000000018000-0x0000000000019FFF to nl node 1
1624    # TSTM: HandleBRTellRequest: downgrade BR key 09010DCE:3D41D263:0000005B:00000000 range 0x0000000000380000-0x00000000003BFFFF to nl node 1 seqNum 0:140 client seqNum 0:140
1625    # TSTM: HandleBRTellRequest: granting tokType BR range 0x0000000000018000-0x0000000000019FFF mode xw key 09010DCE:3C0FB53B:00000003:00000000 to node 1
1626    # TSTM: HandleBRTellRequest: granting tokType BR key 09010DCE:3D41D263:0000005B:00000000 range 0x0000000000380000-0x00000000003BFFFF mode xw to node 2 seqNum 0:144
1627    if (index(recrest, "downgrade BR key") > 0)
1628    {
1629      key = firstword(stuffafter(recrest, "key "))
1630      rest = stuffafter(recrest, key)
1631      range = firstword(rest)
1632      if (range == "range") range = firstword(stuffafter(rest,"range "))
1633      mode = firstword(stuffafter(rest,"to "))
1634      node = firstword(stuffafter(rest,"node "))
1635      if (details)
1636        printf("%8d %17.9f BR: downgrade mode %s node %s key %s range %s\n", newtid, newtime, mode, node, key, range)
1637    }
1638    else if (index(recrest, "granting tokType BR") > 0)
1639    {
1640      rest = stuffafter(recrest, "BR ")
1641      range = firstword(stuffafter(rest,"range "))
1642      key = firstword(stuffafter(rest,"key "))
1643      mode = firstword(stuffafter(rest,"mode "))
1644      node = firstword(stuffafter(rest,"node "))
1645      if (details)
1646        printf("%8d %17.9f BR: granting  mode %s node %s key %s range %s\n", newtid, newtime, mode, node, key, range)
1647    }
1648  }
1649
1650  if (traceTok)
1651  {
1652    if (index(recrest, ": -BR") > 0|| index(recrest, ": +BR") > 0) {
1653      # Parse Var recrest "TSTM: " rest
1654      rest = stuffafter(recrest, "TSTM: ")
1655      if (details)
1656        printf("%8d %17.9f TM: %s\n", newtid, newtime, rest)
1657    }
1658    else if (index(recrest, "TellServer upgrade token") > 0) {
1659      upgrademode = firstword(stuffafter(recrest, "mode"))
1660    }
1661
1662    else if (index(recrest, "              Range:") > 0) {
1663      # Parse Var recrest "Range:0x"s1" - 0x"e1", DesRange:0x"ds1" - 0x"de1
1664      s1 = firstword(stuffafter(recrest, " Range:0x"))
1665      e1 = firstword(stuffafter(recrest, " - 0x"))
1666      if (substr(e1,length(e1)) == ",") e1 = substr(e1,1,length(e1)-1)
1667      ds1 = firstword(stuffafter(recrest, ", DesRange:0x"))
1668      de1 = firstword(stuffafter(recrest, ds1 " - 0x"))
1669      if (details)
1670        printf("%8d %17.9f change token mode %s range %s-%s desrange %s-%s\n", newtid, newtime, upgrademode, s1, e1, ds1, de1)
1671    }
1672
1673    else if (index(recrest, "relinquishBRT") > 0) {
1674      # Parse Var recrest "relinquishBRT "entex" range "s1":"s2"-"e1":"e2 rest
1675      entex = firstword(stuffafter(recrest, "relinquishBRT"))
1676      inode = firstword(stuffafter(recrest, "inode "))
1677      ranges = firstword(stuffafter(recrest, "range "))
1678      rest = stuffafter(recrest, ranges)
1679      pos = index(ranges,":")
1680      if (pos > 0)
1681      {
1682        pos = index(ranges,"-")
1683        range1 = substr(ranges,1,pos-1)
1684        range2 = substr(ranges,pos+1)
1685        pos = index(range1,":")
1686        if (pos > 0) s1 = substr(range1,1,pos-1) substr(range1, pos+1)
1687        else s1 = range1
1688        pos = index(range2,":")
1689        if (pos > 0) e1 = substr(range2,1,pos-1) substr(range2, pos+1)
1690        else e1 = range1
1691        ranges = d2x(s1,16) "-" d2x(e1,16)
1692      }
1693      if (details)
1694        printf("%8d %17.9f relinquishBRT %s inode %s range %s %s\n", newtid, newtime, entex, inode, ranges, rest)
1695    }
1696
1697    else if (index(recrest, "GetSubIndirectBlock inode") > 0) {
1698      # Parse Var recrest "GetSubIndirectBlock" rest
1699      rest = stuffafter(recrest, "GetSubIndirectBlock")
1700      if (details)
1701        printf("%8d %17.9f GetSubIndirectBlock %s\n", newtid, newtime, rest)
1702    }
1703
1704    else if (index(recrest, "token_revoke enter") > 0) {
1705      # Parse Var recrest "token_revoke enter" rest
1706      rest = stuffafter(recrest, "token_revoke enter")
1707      if (details)
1708        printf("%8d %17.9f token_revoke %s\n", newtid, newtime, rest)
1709    }
1710
1711    else if (index(recrest, "acquireBRT") > 0) {
1712      if (index(recrest, "acquireBRT(): enter") > 0) {
1713        # Parse Var recrest "acquireBRT(): "entex" req" s1":"s2"-"e1":"e2 rest
1714        entex = firstword(stuffafter(recrest, "acquireBRT(): "))
1715        inode = firstword(stuffafter(recrest, "inode "))
1716        ranges = firstword(stuffafter(recrest, " req "))
1717        rest = stuffafter(recrest, ranges)
1718        pos = index(ranges,":")
1719        if (pos > 0)
1720        {
1721          pos = index(ranges,"-")
1722          range1 = substr(ranges,1,pos-1)
1723          range2 = substr(ranges,pos+1)
1724          pos = index(range1,":")
1725          if (pos > 0) s1 = substr(range1,1,pos-1) substr(range1, pos+1)
1726          else s1 = range1
1727          pos = index(range2,":")
1728          if (pos > 0) e1 = substr(range2,1,pos-1) substr(range2, pos+1)
1729          else e1 = range1
1730          ranges = d2x(s1,16) "-" d2x(e1,16)
1731        }
1732        if (details)
1733          printf("%8d %17.9f acquireBRT %s inode %s req %s %s\n", newtid, newtime, entex, inode, ranges, rest)
1734      }
1735      else if (index(recrest, "acquireBRT: inode") > 0) {
1736        # Parse Var recrest "acquireBRT: "entex" gra" s1":"s2"-"e1":"e2 rest
1737        entex = "inode"
1738        inode = firstword(stuffafter(recrest, "inode "))
1739        ranges = firstword(stuffafter(recrest, " gra "))
1740        rest = stuffafter(rest, ranges)
1741        pos = index(ranges,":")
1742        if (pos > 0)
1743        {
1744          pos = index(ranges,"-")
1745          range1 = substr(ranges,1,pos-1)
1746          range2 = substr(ranges,pos+1)
1747          pos = index(range1,":")
1748          if (pos > 0) s1 = substr(range1,1,pos-1) substr(range1, pos+1)
1749          else s1 = range1
1750          pos = index(range2,":")
1751          if (pos > 0) e1 = substr(range2,1,pos-1) substr(range2, pos+1)
1752          else e1 = range1
1753          ranges = d2x(s1,16) "-" d2x(e1,16)
1754        }
1755        if (details)
1756          printf("%8d %17.9f acquireBRT %s inode %s gra %s %s\n", newtid, newtime, entex, inode, ranges, rest)
1757      }
1758      else if (index(recrest, "acquireBRT(): exit") > 0) {
1759        rest = stuffafter(recrest, "acquireBRT():")
1760        if (details)
1761          printf("%8d %17.9f acquireBRT%s\n", newtid, newtime, rest)
1762      }
1763    }
1764
1765    else if (index(recrest, "RevokeFromClients") > 0) {
1766      if (index(recrest, "newmode") > 0 ||
1767          index(recrest, "revoking from ") > 0 ||
1768          index(recrest, "returning") > 0)
1769      {
1770        rest = stuffafter(recrest, "RevokeFromClients")
1771        if (substr(rest,1,6) == "() -- ")
1772          rest = substr(rest,7)
1773        if (details)
1774          printf("%8d %17.9f RevokeFromClients %s\n", newtid, newtime, rest)
1775      }
1776    }
1777
1778    else if (index(recrest, "check_dc: enter") > 0) {
1779      rest = stuffafter(recrest, "check_dc")
1780      if (details)
1781        printf("%8d %17.9f check_dc%s\n", newtid, newtime, rest)
1782    }
1783
1784  }
1785
1786  if (traceNew && index(recrest, "MALLOC") > 0)
1787  {
1788    if (index(recrest, "Global operator new") > 0)
1789    {
1790      rest = stuffafter(recrest, "new allocated ")
1791      bytes = firstword(rest)
1792      rest = stuffafter(rest, "bytes at 0x")
1793      bytesat = firstword(rest)
1794      if (allocatedseen[bytesat] == "")
1795      {
1796        allocatedseen[bytesat] = 1
1797        allocatedlist[allocatedctr] = bytesat
1798        allocatedctr++
1799      }
1800      allocatedby[bytesat] = newtid
1801      allocatedtime[bytesat] = newtime
1802      allocatedbytes[bytesat] = bytes
1803      allocatedtype[bytesat] = "malloc"
1804    }
1805    else if (index(recrest, "Global operator delete") > 0)
1806    {
1807      rest = stuffafter(recrest, "delete called for object at 0x")
1808      bytesat = firstword(rest)
1809      allocatedby[bytesat] = ""
1810    }
1811    #MMFS MALLOC: shAlloc: bytesAllocated 88 bytesRequested 24 duration 2 use 1 at 0x323036C8 pool 3 label 'Client'
1812    else if (index(recrest, "shAlloc: bytesAllocated") > 0)
1813    {
1814      rest = stuffafter(recrest, "bytesRequested ")
1815      bytes = firstword(rest)
1816      rest = stuffafter(rest, " at 0x")
1817      bytesat = firstword(rest)
1818      reqtype = stuffafter(rest, "label '")
1819      reqtype = substr(reqtype,1,length(reqtype)-1)
1820      if (allocatedseen[bytesat] == "")
1821      {
1822        allocatedseen[bytesat] = 1
1823        allocatedlist[allocatedctr] = bytesat
1824        allocatedctr++
1825      }
1826      allocatedby[bytesat] = newtid
1827      allocatedtime[bytesat] = newtime
1828      allocatedbytes[bytesat] = bytes
1829      allocatedtype[bytesat] = reqtype
1830    }
1831    #MMFS MALLOC: Freeing memory at 0x4078B340 back to pool 2
1832    else if (index(recrest, "Freeing memory") > 0)
1833    {
1834      rest = stuffafter(recrest, "Freeing memory at 0x")
1835      bytesat = firstword(rest)
1836      allocatedby[bytesat] = ""
1837    }
1838    #(obsolete)MMFS MALLOC: Freeing storage at 0x34F20B40 back to pool 3
1839    else if (index(recrest, "Freeing storage") > 0)
1840    {
1841      rest = stuffafter(recrest, "Freeing storage at 0x")
1842      bytesat = firstword(rest)
1843      allocatedby[bytesat] = ""
1844    }
1845  }
1846
1847  if (traceMsg && ((index(recrest, "msg_id") > 0) || (index(recrest, "tscSend") > 0)))
1848  {
1849    if (index(recrest, "passing msg to idle worker") > 0) ;
1850    else if (index(recrest, "service_message: enter") > 0) ;
1851    else if (index(recrest, "tscSend: service") > 0) {
1852      # Parse Var recrest " msg '"type"'" rest", msg "
1853      rest = stuffafter(recrest, " msg '")
1854      type = firstword(rest)
1855      rest = stuffafter(rest, type)
1856      pos = index(type, "'")
1857      if (pos > 0) type = substr(type,1,pos-1)
1858      pos = index(rest,", msg ")
1859      if (pos > 0) rest = substr(rest,1,pos-1)
1860      msgid = stuffafter(rest, "msg_id ")
1861      msgid = firstword(msgid)
1862      MSGtime[msgid] = newtime
1863      MSGtid[msgid] = newtid
1864      MSGtype[msgid] = type
1865      MSGmid[newtid] = msgid
1866      if (details)
1867        printf("%8d %17.9f MSG Send: %s %s\n", newtid, newtime, type, rest)
1868    }
1869    else if (index(recrest, "llc_send_msg:") > 0) {
1870      rest = stuffafter(recrest, "llc_send_msg: ")
1871      if (details)
1872        printf("%8d %17.9f MSG:      %s\n", newtid, newtime, rest)
1873    }
1874    else if (index(recrest, "tscSend: rc") > 0) {
1875      rest = stuffafter(recrest, " tscSend: rc = ")
1876      if (rest != "0x00000000" && rest != "0x0") rest = "err="rest
1877      else rest = ""
1878      msgid = MSGmid[newtid]
1879      if (msgid != "")
1880      {
1881        delete MSGmid[newtid]
1882        type = MSGtype[msgid]
1883        sttime = MSGtime[msgid]
1884        if (sttime != "")
1885          delta = (newtime-sttime)*1000000
1886        else delta = 0
1887        if (details)
1888          printf("%8d %17.9f MSG FSnd: %s msg_id %d Sduration %.3f %s\n", newtid, newtime, type, msgid, delta, rest)
1889        if (delta > 0)
1890        {
1891          delta = delta/1000000
1892          totalsends++
1893          if (totalsenddelta[type] == 0) minsendbucket[type] = 999999
1894          totalsenddelta[type] += delta
1895          totalsend[type]++
1896          bucket = int(delta / sendbucketsize)
1897          if (minsendbucket[type] > bucket) minsendbucket[type] = bucket
1898          if (maxsendbucket[type] < bucket) maxsendbucket[type] = bucket
1899          sendbuckets[type,bucket]++
1900        }
1901      }
1902    }
1903    else if (index(recrest, "tscSend: replies") > 0) {
1904      rest = stuffafter(recrest, " tscSend: ")
1905      if (details)
1906        printf("%8d %17.9f MSG Rerr: %s\n", newtid, newtime, rest)
1907    }
1908    else if (index(recrest, "tscHandleMsg: service") > 0 ||
1909             index(recrest, "tscHandleMsgDirectly: service") > 0) {
1910      # Parse Var recrest " msg '"type"'"rest", msg "
1911      rest = stuffafter(recrest, " msg '")
1912      type = firstword(rest)
1913      rest = stuffafter(rest, type)
1914      pos = index(type, "',")
1915      if (pos > 0) type = substr(type,1,pos-1)
1916      pos = index(rest,", msg ")
1917      if (pos > 0) rest = substr(rest,1,pos-1)
1918      msgid = stuffafter(recrest, "msg_id ")
1919      msgid = firstword(msgid)
1920      msgid = substr(msgid,1,length(msgid)-1)
1921      if (type == "reply")
1922        type = type" "MSGHtype[msgid]
1923      else
1924      {
1925        MSGHtime[msgid] = newtime
1926        MSGHtid[msgid] = newtid
1927        MSGHtype[msgid] = type
1928        #possibly wrong tid, tscSendReply will set it: MSGHmid[newtid] = msgid
1929      }
1930      if (details)
1931        printf("%8d %17.9f MSG Recv: %s %s\n", newtid, newtime, type, rest)
1932    }
1933    else if (index(recrest, "tscSendReply: service") > 0) {
1934      # Parse Var recrest ", msg '"type"'" rest", msg "
1935      rest = stuffafter(recrest, ", msg '")
1936      type = firstword(rest)
1937      rest = stuffafter(rest, type)
1938      pos = index(type, "',")
1939      if (pos > 0) type = substr(type,1,pos-1)
1940      msgid = stuffafter(rest, "msg_id ")
1941      msgid = firstword(msgid)
1942      msgid = substr(msgid,1,length(msgid)-1)
1943      MSGRepltime[msgid] = newtime
1944      MSGHmid[newtid] = msgid
1945      if (details)
1946        printf("%8d %17.9f MSG Repl: %s %s\n", newtid, newtime, type, rest)
1947    }
1948    else if (index(recrest, "tscSendReply1:") > 0) {
1949      rest = stuffafter(recrest, "tscSendReply1: err = ")
1950      if (rest != 0) rest = "err="rest
1951      else rest = ""
1952      msgid = MSGHmid[newtid]
1953      if (msgid != "")
1954      {
1955        delete MSGHmid[newtid]
1956        type = MSGHtype[msgid]
1957        sttime = MSGHtime[msgid]
1958        srtime = MSGRepltime[msgid]
1959        if (sttime != "")
1960          delta = (newtime-sttime)*1000000
1961        else delta = 0
1962        if (srtime != "")
1963          rdelta = (newtime-srtime)*1000000
1964        else rdelta = 0
1965        if (details)
1966          printf("%8d %17.9f MSG FRep: %s msg_id %d Rduration %.3f Hduration %.3f %s\n", newtid, newtime, type, msgid, rdelta, delta, rest)
1967        if (delta > 0)
1968        {
1969          delta = delta/1000000
1970          totalhands++
1971          if (totalhanddelta[type] == 0) minhandbucket[type] = 999999
1972          totalhanddelta[type] += delta
1973          totalhand[type]++
1974          bucket = int(delta / handbucketsize)
1975          if (minhandbucket[type] > bucket) minhandbucket[type] = bucket
1976          if (maxhandbucket[type] < bucket) maxhandbucket[type] = bucket
1977          handbuckets[type,bucket]++
1978        }
1979      }
1980      else if (details)
1981        printf("%8d %17.9f MSG FRep: %s %s\n", newtid, newtime, type, rest)
1982    }
1983    else {
1984      rest = stuffafter(recrest, "TS: ")
1985      if (details && rest != "")
1986        printf("%8d %17.9f MSG: %s\n", newtid, newtime, rest)
1987    }
1988  }
1989
1990  if (traceMutex && index(recrest, "MUTEX") > 0)
1991  {
1992    if (index(recrest, "waiting for mute") > 0)
1993    {
1994      timest[newtid]=newtime
1995      $0=substr($0,index($0, "waiting for mute"));
1996      mutexst[newtid]=$4
1997      typest[newtid]=getmutextype(5)
1998    }
1999    else if (index(recrest, "Waiting for mute") > 0)
2000    {
2001      timest[newtid]=newtime
2002      $0=substr($0,index($0, "Waiting for mute"))
2003      mutexst[newtid]=$4
2004      typest[newtid]=getmutextype(5)
2005    }
2006    else if (index(recrest, "Acquired mutex") > 0)
2007    {
2008      $0=substr($0,index($0, "Acquired mutex"))
2009      mutex=$3
2010      type=getmutextype(4)
2011      mutexholder[mutex] = newtid
2012      mutexholdtim[mutex] = newtime
2013      if (mutexDetails)
2014        printf("%8d %17.9f MUTEX Acq: %15.9f %15s %15s %s %s\n", newtid, newtime, newtime, "Holding", "-", mutex, type )
2015    }
2016    else if (index(recrest, "Releasing mutex") > 0)
2017    {
2018      $0=substr($0,index($0, "Releasing mutex"))
2019      mutex=$3
2020      type=getmutextype(4)
2021      if (mutexholder[mutex] == newtid)
2022      {
2023        delta = 1000*(newtime-mutexholdtim[mutex])
2024        holdercnt[mutex" "type]++
2025        totholdtime[mutex" "type] += delta
2026        if (mutexDetails)
2027          printf("%8d %17.9f MUTEX Rel: %15s %15.9f %15.9f %s %s\n", newtid, newtime, "Releasing", newtime, delta, mutex, type )
2028      }
2029      else
2030        if (mutexDetails)
2031          printf("%8d %17.9f MUTEX Rel: %15s %15.9f %15s %s %s\n", newtid, newtime, "Releasing", newtime, "-", mutex, type )
2032      delete mutexholder[mutex]
2033    }
2034    else if (index(recrest, "now owns mutex") > 0)
2035    {
2036      $0=substr($0,index($0, "now owns mutex"))
2037      mutex=$4
2038      type=getmutextype(5)
2039      mutexholder[mutex] = newtid
2040      mutexholdtim[mutex] = newtime
2041      if (timest[newtid] != "")
2042      {
2043        delta=1000*(newtime-timest[newtid])
2044        if (mutexDetails)
2045          printf("%8d %17.9f MUTEX Own: %15.9f %15.9f %15.9f %s %s\n", newtid, newtime, timest[newtid], newtime, delta, mutex, type )
2046        delete timest[newtid]
2047        dwaiters[mutex" "type]++
2048        dwaiterstim[mutex" "type]+=delta
2049      }
2050      else
2051        if (mutexDetails)
2052          printf("%8d %17.9f MUTEX Own: %15s %15.9f %15s %s %s\n", newtid, newtime, "***", newtime, "*awoken*", mutex, type )
2053    }
2054    else if (index(recrest, "Awakened after wait") > 0)
2055    {
2056      $0=substr($0,index($0, "Awakened after wait"))
2057      mutex=$6
2058      type=getmutextype(7)
2059      if (timest[newtid] != "")
2060      {
2061        delta=1000*(newtime-timest[newtid])
2062        if (mutexDetails)
2063          printf("%8d %17.9f MUTEX Awa: %15.9f %15.9f %15.9f %s %s\n", newtid, newtime, timest[newtid], newtime, delta, mutex, type)
2064        delete timest[newtid]
2065        kwaiters[mutex" "type]++
2066        kwaiterstim[mutex" "type]+=delta
2067      }
2068      else
2069        if (mutexDetails)
2070          printf("%8d %17.9f MUTEX Awa: %15s %15.9f %15s %s %s\n", newtid, newtime, "***", newtime, "*awoken*", mutex, type)
2071    }
2072  }
2073
2074  if (traceCond && index(recrest, "condvar") > 0)
2075  {
2076    cond = firstword(stuffafter(recrest, "condvar "))
2077    wcount = firstword(stuffafter(recrest, "waitCount "))
2078    if (cond != "")
2079    {
2080      if (index(recrest,"decremented") > 0)
2081      {
2082        waitCount[cond] -= 1
2083        if (seenCond[cond] == "")
2084        {
2085          waitCount[cond] = wcount
2086          seenCond[cond] = cond
2087        }
2088        else if (details && waitCount[cond] != wcount)
2089          printf("%8d %17.9f CONDVAR: %s wake  count %s does not match calc count %d\n",
2090                 newtid, newtime, cond, wcount, waitCount[cond])
2091      }
2092      else if (index(recrest,"incremented") > 0)
2093      {
2094        waitCount[cond] += 1
2095        if (seenCond[cond] == "")
2096        {
2097          waitCount[cond] = wcount
2098          seenCond[cond] = cond
2099        }
2100        else if (details && waitCount[cond] != wcount)
2101          printf("%8d %17.9f CONDVAR: %s wait  count %s does not match calc count %d\n",
2102                 newtid, newtime, cond, wcount, waitCount[cond])
2103      }
2104      else if (index(recrest,"roadcasting") > 0 || index(recrest,"ignalling") > 0)
2105      {
2106        if (index(recrest,"no waiters") > 0) wcount = 0
2107        if (seenCond[cond] == "")
2108        {
2109          waitCount[cond] = wcount
2110          seenCond[cond] = cond
2111        }
2112        else if (waitCount[cond] != wcount)
2113          printf("%8d %17.9f CONDVAR: %s bcast count %s does not match calc count %d\n",
2114                 newtid, newtime, cond, wcount, waitCount[cond])
2115      }
2116    }
2117  }
2118}
2119
2120/SSA DASD / {
2121  rec = $0
2122  if (cpucol > 0)
2123    newcpu = firstword(substr($0, cpucol, 6))
2124  else
2125    newcpu = oldcpu
2126  if (tidcol > 0)
2127    newtid = firstword(substr($0, tidcol))
2128  else
2129    newtid = oldtid[newcpu]
2130  if (timecol > 0)
2131  {
2132    newtime = firstword(substr($0, timecol))
2133    if (addtime > 0) newtime += addtime
2134    if (tickfactor > 1 && newtime != "")
2135      newtime = newtime * tickfactor
2136  }
2137
2138  rest = stuffafter($0, "SSA DASD ")
2139
2140  if (traceIO)
2141  {
2142    if (index(rest, "bstart:") > 0)
2143    {
2144      # SSA DASD bstart: hdisk2 bp=52B8E520 pblock=838EC00 bcount=40000 B_WRITE
2145      disk = firstword(stuffafter(rest,"bstart: "))
2146      buffer = firstword(stuffafter(rest,"bp="))
2147      SSAQIOtime[buffer,disk] = newtime
2148      SSAQIOtid[buffer,disk] = newtid
2149      printf("%8d %17.9f SSA DASD %s\n", newtid, newtime, rest)
2150    }
2151    else if (index(rest, "iodone:") > 0)
2152    {
2153      # SSA DASD iodone: hdisk4 bp=52B8E520
2154      disk = firstword(stuffafter(rest,"iodone: "))
2155      buffer = firstword(stuffafter(rest,"bp="))
2156      if (SSAQIOtime[buffer,disk] != "")
2157        delta = (newtime-SSAQIOtime[buffer,disk])*1000000
2158      else delta = 0
2159      printf("%8d %17.9f SSA DASD %s SSAduration %.3f\n", SSAQIOtid[buffer,disk], newtime, rest, delta)
2160    }
2161  }
2162}
2163
2164
2165END {
2166  if (terminate) exit 1
2167
2168  print "\nUnfinished operations:\n"
2169  for (i = 1; i <= tidcount; i++)
2170  {
2171    tid = tids[i]
2172    for (reqi = reqs[tid]; reqi > 0; reqi--)
2173      printf("%8d ***************** %-20s ************** %s\n", tid, req[tid,reqi], time[tid,reqi])
2174  }
2175  if (traceIO)
2176  {
2177     for (buffer in QIOtime)
2178       printf("%8d %17.9f *********  Unfinished IO: buffer/disk %s\n", QIOtid[buffer], QIOtime[buffer], buffer)
2179  }
2180  if (traceMsg)
2181  {
2182    for (tid in MSGmid)
2183    {
2184      msgid = MSGmid[tid]
2185      if ( MSGtime[msgid] != "")
2186        delta = (newtime-MSGtime[msgid])*1000000
2187      else delta = 0
2188      printf("%8d %17.9f MSG FSnd: %s msg_id %d Sduration %.3f +\n", tid, MSGtime[msgid], MSGtype[msgid], msgid, delta)
2189    }
2190    for (tid in MSGHmid)
2191    {
2192      msgid = MSGHmid[tid]
2193      if ( MSGHtime[msgid] != "")
2194        delta = (newtime-MSGHtime[msgid])*1000000
2195      else delta = 0
2196      if (MSGRepltime[msgid] != "")
2197        rdelta = (newtime-MSGRepltime[msgid])*1000000
2198      else rdelta = 0
2199      printf("%8d %17.9f MSG FRep: %s msg_id %d Rduration %.3f Hduration %.3f +\n", tid, MSGRepltime[msgid], type, msgid, rdelta, delta)
2200    }
2201  }
2202  if (traceNew)
2203  {
2204    printf("\nUnfreed storage:\n")
2205    for (alli = 0; alli < allocatedctr; alli++)
2206    {
2207      bytesat = allocatedlist[alli]
2208      if (allocatedby[bytesat] != "")
2209        printf("%8d %s alloc 0x%s %d %s\n", allocatedby[bytesat], allocatedtime[bytesat], bytesat, allocatedbytes[bytesat], allocatedtype[bytesat])
2210    }
2211  }
2212
2213  if (numcpu > 0)
2214    printf("\nElapsed trace time:                              %17.9f on %d cpus\n", newtime, numcpu)
2215  else
2216    printf("\nElapsed trace time:                              %17.9f\n", newtime)
2217  if (tlevel > 0) lastVFStime = newtime
2218  printf("Elapsed trace time from first VFS call to last:  %17.9f\n",
2219         lastVFStime-firstVFStime)
2220  printf("Time idle between VFS calls:                     %17.9f\n", idleVFS)
2221  printf("\nOperations stats:             total time     count  average-usecs\n")
2222  ops=0
2223  for (treq in timeop)
2224  {
2225    ops += cntop[treq]
2226    printf("  %-20s %17.9f %9d %12.3f\n", treq, timeop[treq], cntop[treq], timeop[treq]/cntop[treq]*1000000)
2227  }
2228  if (lastVFStime > firstVFStime)
2229  printf("Ops %9d Secs %17.9f  Ops/Sec %12.3f\n", ops, lastVFStime-firstVFStime-idleVFS, ops/(lastVFStime-firstVFStime-idleVFS))
2230  printf("\nUser thread stats: GPFS-time         Appl-time  GPFS-%%  Appl-%%     Ops\n")
2231  for (tid in timein)
2232  {
2233    intm=timein[tid]
2234    outm=timeout[tid]
2235    if (intm+outm != 0)
2236      printf("%10d %17.9f %17.9f %6.2f%% %6.2f%% %7d %s\n", tid, intm, outm, 100*intm/(intm+outm), 100*outm/(intm+outm), tidopcnt[tid], tidname[tid])
2237    else
2238      printf("%10d %17.9f %17.9f %6.2f%% %6.2f%% %7d %s\n", tid, intm, outm, 0, 0, tidopcnt[tid], tidname[tid])
2239  }
2240
2241  cnt=0
2242  for (tidstr in totcpu)
2243  {
2244    cnt++
2245    accumcpu += totcpu[tidstr]
2246    procname = substr(tidstr,index(tidstr," ")+1)
2247    proccpu[procname] += totcpu[tidstr]
2248    proctids[procname]++
2249  }
2250  if (cnt > 0)
2251  {
2252    if (numcpu > 0)
2253    {
2254      dispavail = numcpu*newtime
2255      printf("\nAvailable dispatch time %d cpu * %.9f = %.9f seconds\n", numcpu, newtime, dispavail)
2256    }
2257    else
2258    {
2259      dispavail = accumcpu
2260      printf("\nAccumulated dispatch time %.9f seconds\n", accumcpu)
2261    }
2262    printf("\nProcess name:                 Dispatched-time       %%\n")
2263    for (str in proccpu)
2264    {
2265      tcpu = proccpu[str]
2266      if (proctids[str] > 1)
2267        namestr=str"*"proctids[str]
2268      else
2269        namestr=str
2270      printf("%27s %17.9f %6.2f%%\n", namestr, tcpu, 100*tcpu/dispavail)
2271    }
2272    printf("\nAccumulated CPU             %17.9f %6.2f%% of Available\n", accumcpu, 100*accumcpu/dispavail)
2273    if (printTIDdispatch)
2274    {
2275      printf("\nThread ID:   Dispatched-time       %% Name\n")
2276      for (tidstr in totcpu)
2277      {
2278        inx = index(tidstr," ")
2279        tid = substr(tidstr,1,inx-1)
2280        str = substr(tidstr,inx+1)
2281        tcpu = totcpu[tidstr]
2282        printf("%10d %17.9f %6.2f%% %s\n", tid, tcpu, 100*tcpu/dispavail, str)
2283      }
2284    }
2285  }
2286
2287  if (lockhist && totallockctls > 0)
2288  {
2289    print ""
2290    cnt=0
2291    printf("# total App-lockctl = %d Average duration = %0.9f\n", totallockctls, totallockdelta/totallockctls)
2292    print "#  time       count         %     %ile"
2293    for (i=minlockbucket ; i<=maxlockbucket ; i++)
2294    {
2295      j=lockbuckets[i]
2296      if (j > 0)
2297      {
2298        cnt+=j
2299        printf("%0.6f %10d  %0.6f %0.6f\n",(i+1)*lockbucketsize, j, j/totallockctls, cnt/totallockctls)
2300      }
2301    }
2302  }
2303
2304  if (IOhist)
2305  {
2306    print ""
2307    if (totalrdwrs > 0)
2308    {
2309      cnt=0
2310      printf("# total App-read/write = %d Average duration = %0.9f\n", totalrdwrs, totaldelta/totalrdwrs)
2311      print "#  time       count         %     %ile       read      write"
2312      for (i=minreqbucket ; i<=maxreqbucket ; i++)
2313      {
2314        jr=rdbuckets[i]
2315        jw=wrbuckets[i]
2316        ju=buckets[i]
2317        j=jr+jw+ju
2318        if (j > 0)
2319        {
2320          cnt+=j
2321          printf("%0.6f %10d  %0.6f %0.6f %10d %10d\n",(i+1)*reqbucketsize, j, j/totalrdwrs, cnt/totalrdwrs, jr, jw)
2322        }
2323      }
2324
2325      if (maxrdwrinprog > 0)
2326      {
2327        cnt=0
2328        print "\n# max concurrant App-read/write = " maxrdwrinprog
2329        print "# conc    count         %     %ile"
2330        for (i=0 ; i<=maxrdwrinprog ; i++)
2331        {
2332          j=inpbucket[i]
2333          if (j > 0)
2334          {
2335            cnt+=j
2336            printf("%4d %10d  %0.6f %0.6f\n",i, j, j/totalrdwrs, cnt/totalrdwrs)
2337          }
2338        }
2339      }
2340    }
2341    if (totalios > 0)
2342    {
2343      printf("\n# total IOs = %d average duration = %0.9f\n", totalios, totaliodelta/totalios)
2344      print "#  time       count         %     %ile       read      write"
2345      cnt=0
2346      for (i=miniobucket ; i<=maxiobucket ; i++)
2347      {
2348        jr=rdiobuckets[i]
2349        jw=wriobuckets[i]
2350        j=jr+jw
2351        if (j > 0)
2352        {
2353          cnt+=j
2354          printf("%0.6f %10d  %0.6f %0.6f %10d %10d\n",(i+1)*iobucketsize, j, j/totalios, cnt/totalios, jr, jw)
2355        }
2356      }
2357      if (maxqios > 0)
2358      {
2359        cnt=0
2360        print "\n# max concurrant IOs = " maxqios
2361        for (i=0 ; i<=maxqios ; i++)
2362        {
2363          j=ioinpbucket[i]
2364          if (j > 0)
2365          {
2366            cnt+=j
2367            printf("%4d %10d  %0.6f %0.6f\n",i, j, j/totalios, cnt/totalios)
2368          }
2369        }
2370        print "\n# disk utilization between firstuse and lastuse     #IOs maxQdepth"
2371        firstiotime = newtime
2372        lastiotime = 0
2373        cntnios = 0
2374        totidle = 0
2375        cntdisks = 0
2376        for (disk in idlediskFirst)
2377        {
2378          if (idlediskStart[disk] == 0 )
2379            idlediskLast[disk] = newtime  # io still going on at end
2380          diskelap = idlediskLast[disk]-idlediskFirst[disk]
2381          disknonidle = diskelap-idlediskTime[disk]
2382          if (diskelap > 0)
2383          {
2384            if (firstiotime > idlediskFirst[disk]) firstiotime = idlediskFirst[disk]
2385            if (lastiotime < idlediskLast[disk]) lastiotime = idlediskLast[disk]
2386            totidle += idlediskTime[disk]
2387            cntnios += nios[disk]
2388            cntdisks++
2389            if (nios[disk] > 1)
2390              printf("%s %6.2f%% %s %s %7d %4d\n", disk, 100*disknonidle/diskelap, idlediskFirst[disk], idlediskLast[disk], nios[disk], maxqiosdisk[disk])
2391            else
2392              printf("%s         %s %s %7d %4d\n", disk, idlediskFirst[disk], idlediskLast[disk], nios[disk], maxqiosdisk[disk])
2393          }
2394        }
2395        diskelap = cntdisks*(lastiotime-firstiotime)
2396        disknonidle = diskelap-totidle
2397        if (diskelap == 0) diskelap=1
2398        printf("\nAverage          %6.2f%% %s %s %7d\n", 100*disknonidle/diskelap, firstiotime, lastiotime, cntnios)
2399      }
2400
2401      cnt=0
2402      print "\n# sectors      count         %     %ile       read      write"
2403      for (i=1; i<=maxSectors;i++)
2404      {
2405        jr=rdsectbucket[i]
2406        jw=wrsectbucket[i]
2407        j=jr+jw
2408        if (j > 0)
2409        {
2410          cnt+=j
2411          printf("%9d %10d  %0.6f %0.6f %10d %10d\n",i, j, j/totalios, cnt/totalios, jr, jw)
2412        }
2413      }
2414    }
2415    print "\n#    time      IO-read     IO-write     App-read    App-write  (MB/s)"
2416    MBpersec=1/(1000000*timebucketsize)
2417    for (i=mintimebucket; i<=highbuck;i++)
2418    {
2419      jr=rdsectsum[i]
2420      jw=wrsectsum[i]
2421      j=jr+jw
2422      if (j > 0 || wrbytessum[i] || rdbytessum[i])
2423        printf("%9.3f %12.3f %12.3f %12.3f %12.3f\n", i*timebucketsize,jr*512*MBpersec, jw*512*MBpersec, rdbytessum[i]*MBpersec, wrbytessum[i]*MBpersec)
2424    }
2425  }
2426  if (traceMsg)
2427  {
2428    if (totalsends > 0)
2429    {
2430      for (type in totalsend)
2431      {
2432        print ""
2433        cnt=0
2434        printf("# Send msg %-32s total = %8d   Average duration = %0.9f\n", type, totalsend[type], totalsenddelta[type]/totalsend[type])
2435        print "#  time       count         %     %ile"
2436        for (i=minsendbucket[type] ; i<=maxsendbucket[type] ; i++)
2437        {
2438          j=sendbuckets[type,i]
2439          if (j > 0)
2440          {
2441            cnt+=j
2442            printf("%0.6f %10d  %0.6f %0.6f\n",(i+1)*sendbucketsize, j, j/totalsend[type], cnt/totalsend[type])
2443          }
2444        }
2445      }
2446    }
2447    if (totalhands > 0)
2448    {
2449      for (type in totalhand)
2450      {
2451        print ""
2452        cnt=0
2453        printf("# Handle msg %-30s total = %8d   Average duration = %0.9f\n", type, totalhand[type], totalhanddelta[type]/totalhand[type])
2454        print "#  time       count         %     %ile"
2455        for (i=minhandbucket[type] ; i<=maxhandbucket[type] ; i++)
2456        {
2457          j=handbuckets[type,i]
2458          if (j > 0)
2459          {
2460            cnt+=j
2461            printf("%0.6f %10d  %0.6f %0.6f\n",(i+1)*handbucketsize, j, j/totalhand[type], cnt/totalhand[type])
2462          }
2463        }
2464      }
2465    }
2466  }
2467  if (traceMutex)
2468  {
2469    if (mutexDetails)
2470    {
2471      print "\n# Outstanding mutex waiters"
2472      for (tid in timest)
2473        printf("%8d %17.9f MUTEX ***: %15.9f %15s %15s %s %s\n", tid, timest[tid], timest[tid], "*still*","*waiting*", mutexst[tid], typest[tid])
2474    }
2475    print "\n# Mutex statistics"
2476    print "\n    Count  Total Wait(ms)    Avg Wait(ms) Address    Type  (in kernel)"
2477    for (i in kwaiters)
2478      printf("%9d %15.9f %15.9f %s\n", kwaiters[i], kwaiterstim[i], kwaiterstim[i]/kwaiters[i], i)
2479    print "\n    Count  Total Wait(ms)    Avg Wait(ms) Address    Type  (in daemon)"
2480    for (i in dwaiters)
2481      printf("%9d %15.9f %15.9f %s\n", dwaiters[i], dwaiterstim[i], dwaiterstim[i]/dwaiters[i], i)
2482    print "\n    Count  Total Hold(ms)    Avg Hold(ms) Address    Type"
2483    for (i in holdercnt)
2484      printf("%9d %15.9f %15.9f %s\n", holdercnt[i], totholdtime[i], totholdtime[i]/holdercnt[i], i)
2485  }
2486
2487  print "\n# Lookup results:\n     Inode      Count Name"
2488  for (inonam in lookups)
2489  {
2490    pos=index(inonam,SUBSEP)
2491    inode=substr(inonam,1,pos-1)
2492    name=substr(inonam,pos+1)
2493    if (inode == "notfound")
2494      printf("%10s %10d %s\n",inode,lookups[inonam],name)
2495    else
2496      printf("%10d %10d %s\n",inode,lookups[inonam],name)
2497  }
2498
2499}
Note: See TracBrowser for help on using the repository browser.