From 23646bd1eaeba03b6d64f413e3b7044881ae7c80 Mon Sep 17 00:00:00 2001 From: zab Date: Sat, 17 Apr 2004 04:11:08 +0000 Subject: [PATCH] - add a cute script that uses 'ploticus' to graph the rpcs from a D_RPCTRACE log. the script should be easy to use and has pointers to ploticus. http://tetsuo.zabbo.net/~zab/rpc-graph.ps is an example. --- lustre/scripts/graph-rpcs.sh | 351 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 351 insertions(+) create mode 100755 lustre/scripts/graph-rpcs.sh diff --git a/lustre/scripts/graph-rpcs.sh b/lustre/scripts/graph-rpcs.sh new file mode 100755 index 0000000..08a2d24 --- /dev/null +++ b/lustre/scripts/graph-rpcs.sh @@ -0,0 +1,351 @@ +#!/bin/bash + +# I'm sure this could be one cleaner perl script instead of a weird combination +# of awk and shell. This was the fastest path to feeding 'pl' for me. I'm +# all for improvements. Let me know. -- zab + +die() { + echo $* 1>&2 + exit 1 +} +pct() { + echo "$1 "'('`echo "($1 * 100) / $2" | bc`'%)' +} + +tmpdir=`mktemp -d /tmp/.tmpdirXXXXXX` || die "couldn't create tmp dir" +cleanup() { + [ ${#tmpdir} == 18 ] && [ -d $tmpdir ] && rm -rf $tmpdir +} +trap cleanup EXIT + +rpc_name() { + case "$1" in + 0) echo "OST_REPLY" ;; + 1) echo "OST_GETATTR" ;; + 2) echo "OST_SETATTR" ;; + 3) echo "OST_READ" ;; + 4) echo "OST_WRITE" ;; + 5) echo "OST_CREATE" ;; + 6) echo "OST_DESTROY" ;; + 7) echo "OST_GET_INFO" ;; + 8) echo "OST_CONNECT" ;; + 9) echo "OST_DISCONNECT" ;; + 10) echo "OST_PUNCH" ;; + 11) echo "OST_OPEN" ;; + 12) echo "OST_CLOSE" ;; + 13) echo "OST_STATFS" ;; + 14) echo "OST_SAN_READ" ;; + 15) echo "OST_SAN_WRITE" ;; + 16) echo "OST_SYNC" ;; + 17) echo "OST_SET_INFO" ;; + 33) echo "MDS_GETATTR" ;; + 34) echo "MDS_GETATTR_NAME" ;; + 35) echo "MDS_CLOSE" ;; + 36) echo "MDS_REINT" ;; + 37) echo "MDS_READPAGE" ;; + 38) echo "MDS_CONNECT" ;; + 39) echo "MDS_DISCONNECT" ;; + 40) echo "MDS_GETSTATUS" ;; + 41) echo "MDS_STATFS" ;; + 42) echo "MDS_PIN" ;; + 43) echo "MDS_UNPIN" ;; + 44) echo "MDS_SYNC" ;; + 45) echo "MDS_DONE_WRITING" ;; + 101) echo "LDLM_ENQUEUE" ;; + 102) echo "LDLM_CONVERT" ;; + 103) echo "LDLM_CANCEL" ;; + 104) echo "LDLM_BL_CALLBACK" ;; + 105) echo "LDLM_CP_CALLBACK" ;; + 106) echo "LDLM_GL_CALLBACK" ;; + 400) echo "OBD_PING" ;; + 401) echo "OBD_LOG_CANCEL" ;; + + *) echo "unknown" ;; + esac +} + +usage() { + echo " -l file (required)" + echo " Specifies a debug log that contains RPC 'Sending' and" + echo " 'Completed' entries generated by D_RPCTRACE." + echo " -o file" + echo " Usually the PostScript output is temporary and only" + echo " used for the gv instance during the script. This" + echo " option specifies a file to save the ps to." + echo " -p file" + echo " Usually the pl script is generated in a temporary" + echo " directoriy that is wiped as the script exits. This" + echo " saves the script as 'file' instead." + echo " -x" + echo " Label the tail of each RPC bar with the XID of the" + echo " RPC. This can be illegible with dense bars." + echo + echo "Example:" + echo " $0 -l /tmp/my-log -o out.ps && gv -landscape out.ps" + echo + exit; +} + +[ ${#*} == 0 ] && usage + +if ! which pl > /dev/null 2>&1 ; then + echo "The ploticus 'pl' binary isn't in the PATH." + echo " ----" + echo " (cd /tmp && wget http://ploticus.sourceforge.net/download/pl220linux.tar.gz)" + echo " (mkdir ~/ploticus && cd ~/ploticus && tar -zxf /tmp/pl220linux.tar.gz)" + echo ' export PATH=$PATH:~/ploticus/pl220linux/bin' + echo " chmod +x ~/ploticus/pl220linux/bin/pl" + echo " ----" + echo "is sufficient. There are also rpms near" + echo " http://ploticus.sourceforge.net/doc/download.html" + exit 1; +fi + +labelfield="//" +while getopts ":l:o:p:x" opt; do + case $opt in + l) log=$OPTARG ;; + o) output=$OPTARG ;; + p) pl_save_file=$OPTARG ;; + x) labelfield="labelfield: 5" ;; + \?) usage + esac +done + +[ -z "$log" ] && die "need to specify a log file with -l" +[ ! -f "$log" ] && die "$log needs to be a file" + +pl_script="$tmpdir/ploticus.script" +to_pl() { + echo "$*" >> $pl_script +} + +awk_vars="$tmpdir/awk_vars" +awk -F"[$IFS:]" ' + BEGIN { num_xids = 0 } + ($11 == "Sending") { + tvtime = $4 + pname = $20 + xid = $23 + opc = $26 + + # the y position of the rpc bar in the graph is determined + # by the category which we use the process name for. when + # a process has multiple rpcs concurrently we generate + # seperate categories by appending ___slot to the name + # and then hide these slot categories in the graph. + + # find the next slot that is empty + for (slot = 0; (pname, slot) in pname_slots; slot++) { + ; + } + + pname_slots[pname, slot] = xid + xid_slot[xid] = slot + + if (slot == 0) { + xid_pname[xid] = pname + } else { + xid_pname[xid] = pname "_____" slot + } + xid_start[xid] = tvtime + xid_opcode[xid] = opc + xids[num_xids] = xid + num_xids = num_xids + 1 + opcodes[opc] = 1 + + + if (initialized != 1) { + min = tvtime + max = tvtime + first_xid = xid + last_xid = xid + initialized = 1 + + } + if (tvtime < min) { + min = tvtime + first_xid = xid + } + if (tvtime > max) { + max = tvtime + last_xid = xid + } + } + ($11 == "Completed") { + tvtime = $4 + pname = $20 + xid = $23 + opc = $26 + + + total_rpcs++; + rpc_count[opc]++; + + xid_stop[xid] = tvtime + this_time = xid_stop[xid] - xid_start[xid] + total_rpc_time = total_rpc_time + this_time; + rpc_total_time[opc] = rpc_total_time[opc] + this_time + + slot = xid_slot[xid] + delete xid_slot[xid] + delete pname_slots[pname, slot] + } + END { + for (ind = 0; ind < num_xids; ind++) { + xid = xids[ind] + print xid_pname[xid], xid_start[xid] - min, \ + xid_stop[xid] - min, xid_opcode[xid], xid \ + >> "'$tmpdir/data'" + } + print "FIRST_XID=" first_xid >> "'$awk_vars'" + print "LAST_XID=" last_xid >> "'$awk_vars'" + print "MIN=" 0.0 >> "'$awk_vars'" + print "TOTAL_RPCS=" total_rpcs >> "'$awk_vars'" + print "TOTAL_RPC_TIME=" total_rpc_time >> "'$awk_vars'" + print "MAX=" max - min >> "'$awk_vars'" + + for (op in opcodes) { + all_opcodes = all_opcodes " " op + print "rpc_total_time[" op "]=\"" \ + rpc_total_time[op] "\"" \ + >> "'$awk_vars'" + print "rpc_count[" op "]=\"" \ + rpc_count[op] "\"" \ + >> "'$awk_vars'" + } + print "OP_CODES=\"" all_opcodes "\"" >> "'$awk_vars'" + print "NUM_OP_CODES=" asort(opcodes) >> "'$awk_vars'" + } + ' $log || die "awk failed" + +. $awk_vars + +to_pl '#proc getdata + data:' + +# it seems neccesary to batch by category, sadly. +sort -n $tmpdir/data >> $pl_script || die "sorting failed" +# jeez. without another newline at the end pl doesn't read the last data row. +echo >> $pl_script + +# could be smarter here +# http://ploticus.sourceforge.net/doc/color.html +colors=("red" "orange" "green" "blue" "purple" "pink" "powderblue" "yellow" \ + "brown") +num_colors=9 + +legend_index=0 +legend_pane=0 +ops_per_pane=$(((NUM_OP_CODES + 2)/ 3)) + +i=0 +for op in $OP_CODES; do + name=`rpc_name $op` + [ $name == "unknown" ] && die "unknown op code $op" + + [ $i == $num_colors ] && die "ran out of colors" + + label="$name "`pct ${rpc_count[$op]} $TOTAL_RPCS` + label="$label, "`pct ${rpc_total_time[$op]} $TOTAL_RPC_TIME` + + # this "tag:" is also included in the data and is used by the + # bar plot to define the color of the bar + # http://ploticus.sourceforge.net/doc/bars.html + # http://ploticus.sourceforge.net/doc/legendentry.html#legenddriven + to_pl "#proc legendentry + sampletype: color + label: $label + details: ${colors[$i]} + tag: $op" + + # ploticus makes you construct seperage legends stacked next to each + # other if you want to have a legend with multiple rows _and_ multiple + # columns. + # http://ploticus.sourceforge.net/doc/legend.html + # http://ploticus.sourceforge.net/gallery/propbars1.htm + # we put each op code in part of a legend pane and then emit them + # all later on at the end of the script + if [ $legend_index == 0 ]; then + # XXX this should be standard + loc="min+$(($legend_pane * 3)) min-.5" +# loc="$loc min-"`echo "($ops_per_pane * .3)" | bc` + + leg=" $leg + + #proc legend + location: $loc" + + # all but the last get noclear + if [ $legend_pane != 2 ]; then + leg="$leg + noclear: yes" + fi + leg="$leg + specifyorder: $name" + else + leg="$leg + $name" + fi + + legend_index=$(($legend_index + 1)) + if [ $legend_index == $ops_per_pane ]; then + legend_index=0 + legend_pane=$(($legend_pane + 1)) + fi + + i=$(($i + 1)) +done + +to_pl " +#proc areadef + rectangle: 1 1 9.5 8 + xautorange datafields=2,3 + xrange: $MIN $MAX + yscaletype: categories + ycategories: datafield 1 + title: $TOTAL_RPCS RPCs found in \"$log\" + titledetails: align=C + +#proc yaxis + stubs: categories + grid: color=gray(0.9) + labeldistance: 1 + label: Process name + stubomit: *_____* + +#proc xaxis + stubs: inc + stubformat: %.3f + grid: color=gray(0.9) + label: Elapsed seconds + +#proc bars + axis: x + locfield: 1 + segmentfields: 2 3 + barwidth: 0.06 + outline: no + $labelfield +// see the legendentry generation above + colorfield 4 + +$leg" + +if [ ! -z "$pl_save_file" ]; then + mv $pl_script $pl_save_file || \ + die "couldn't save pl script as $pl_save_file" + pl_script="$pl_save_file" +fi + +# pl is very excited about not doing dynamic allocation. +NURR=$((TOTAL_RPCS * 10)) + +pl -maxproclines $NURR -maxfields $NURR -landscape -ps $pl_script \ + -o $tmpdir/ps || die "pl failed" + +if [ -z "$output" ]; then + gv -landscape $tmpdir/ps || die "couldn't start gv" +else + mv $tmpdir/ps $output || die "couldn't save ps output as $output" +fi -- 1.8.3.1