From: thantry Date: Sat, 15 Mar 2003 02:35:56 +0000 (+0000) Subject: Bugzilla 895 X-Git-Tag: v1_7_110~2^11~161 X-Git-Url: https://git.whamcloud.com/?a=commitdiff_plain;h=3b76499e95d85255671b3fbe5884fb69738816cc;p=fs%2Flustre-release.git Bugzilla 895 --- diff --git a/lustre/utils/llparser.pm b/lustre/utils/llparser.pm index 5cee31f..7657e11 100644 --- a/lustre/utils/llparser.pm +++ b/lustre/utils/llparser.pm @@ -22,12 +22,13 @@ package llparser; require Exporter; @ISA = qw(Exporter); -@EXPORT = qw(parse_file print_rpcrelations parse_foptions %ll_subsystems - %subsysnum %trace_masks $e_subsys $e_mask $e_processor $e_time - $e_file $e_line $e_function $e_pid $e_stack $e_fmtstr $e_backref - $e_treeparent $e_numchildren $e_youngestchild $e_next $e_pidhead - $e_rpcsndrcv $e_rpcpid $e_rpcxid $e_rpcnid $e_rpcopc $e_rpcnext - $e_curlineref $SEND $RCV); +@EXPORT = qw(parse_file print_rpcrelations parse_foptions + %ll_subsystems %subsysnum %trace_masks $e_subsys $e_mask + $e_processor $e_time $e_file $e_line $e_function $e_pid + $e_stack $e_fmtstr $e_backref $e_marked $e_treeparent + $e_numchildren $e_youngestchild $e_next $e_pidhead + $e_rpcsndrcv $e_rpcpid $e_rpcxid $e_rpcnid $e_rpcopc + $e_rpcnext $e_curlineref $SEND $RCV); ($e_subsys, $e_mask, @@ -44,33 +45,107 @@ require Exporter; $e_youngestchild, $e_pidhead, $e_next, - $e_backref) = (0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15); + $e_backref, + $e_marked) = (0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16); -($e_rpcpid, - $e_rpcxid, - $e_rpcnid, +($e_rpcxid, $e_rpcopc, - $e_rpcnext, + $e_rpcreint, $e_rpcsndrcv, - $e_curlineref) = (0, 1, 2, 3, 4, 5, 6); + $e_rpcpid, + $e_rpcnid, + $e_rpcmarked) = (0, 1, 2, 3, 4, 5, 6); + +($e_curline, + $e_cliRPCent, + $e_srvRPCent, + $e_srvRPCexit, + $e_cliRPCexit) = ($e_rpcmarked+1, $e_rpcmarked+2, $e_rpcmarked+3, $e_rpcmarked+4, $e_rpcmarked+5); + +$CLI_SEND = 1; +$SRV_RCV = 2; +$SRV_REPLY = 3; +$CLI_COMPLETE = 4; +$MDS_REINT = 5; + +# Data structure for pidhashref +($e_lineref, $e_pidcmd) = (0, 1); + +# Define the lowest stack values for MARKER/VFS +$MARKER_STACK_VAL = 0; +$VFS_STACK_VAL = 1; + +# Main parser regexes, these break down each line into all its components + +# Previous REGEXP (kept here just in case....) +$UMLREGEX = qr/^\s*(\w+)\s*:\s*(\d+)\s*:\s*(\d+)\s*:\s*(\d+\.(?:\d+))\s*\(\s*([^:]+)\s*:\s*(\d+)\s*:\s*([^()]+)\s*\(\)\s*(\d+)\s*\|\s*(?:\d+)\s*\+\s*(\d+)\s*\):(.*)$/; +$HOSTREGEX= qr/^\s*(\w+)\s*:\s*(\d+)\s*:\s*(\d+)\s*:\s*(\d+\.(?:\d+))\s*\(\s*([^:]+)\s*:\s*(\d+)\s*:\s*([^()]+)\s*\(\)\s*(?:(?:\d+)\s*\|\s*)?(\d+)\s*\+\s*(\d+)\s*(?:.*)\):(.*)$/; + +# Regexpression that is used (works for both HOST and UML log files) +$HOSTREGEX2= qr/^(\w+):(\d+):(\d+):(\d+\.(?:\d+))\s\(\s*([^:]+):(\d+):([^()]+)\(\)\s(\d+)(?:\s\|\s(?:\d+))?\+(\d+)\):(.*)$/; + + +#RPC REGEXES BELOW +$SENDING = "Sending"; +$COMPLETED = "Completed"; +$HANDLING = "Handling"; +$HANDLED = "Handled"; +$RPCREGEX = qr/^\s*($SENDING|$HANDLING|$HANDLED|$COMPLETED)\s*RPC\s*pid:xid:ni:nid:opc\s*(\d+):(?:0x)?(\w+):(?:\w+):(?:0x)?(\w+):(\d+)\s*$/; + +#VFS REGEX BELOW +$VFS_REGEX = qr/VFS Op:(.+)/; + +# DEBUG_REQ parser +( $e_drq_str, $e_drq_reqadr, $e_drq_xid, $e_drq_transno, $e_drq_opcode, + $e_drq_uuid , $e_drq_portal, $e_drq_reqlen, $e_drq_replen, + $e_drq_refcnt, $e_drq_rqflags, $e_drq_reqmsgflags, $e_drq_repmsgflags, + $e_drq_rc) = (0,1,2,3,4,5,6,7,8,9,10,11,12,13,14); + +$DEBUGREQ_REGEX= qr/@@@\s([^@]+)\sreq@([a-f\d]+)\sx(\d+)\/t(\d+)\so(\d+)->([\w]+):([-\d]+)\slens\s(\d+)\/(\d+)\sref\s(\d+)\sfl\s([-a-f\d]+)\/([-a-f\d]+)\/([-a-f\d]+)\src\s([-a-f\d]+)/; + -$SEND = 0; -$RCV = 1; +#LDLMREGEX BELOW +# This needs to change when I understand the LDLM statemachine better +$LDLM_REGEX = qr/^\s*###/; + +$LDLM_TEMP_REGEX = qr/^\s*client-side enqueue START/; +$LDLM_TEMP_REGEX_2 = qr/^\s*client-side enqueue END/; +#OTHER REGEXES -$REGEX=qr/^\s*(\w+)\s*:\s*(\d+)\s*:\s*(\d+)\s*:\s*(\d+\.(?:\d+))\s*\(\s*([^:]+)\s*:\s*(\d+)\s*:\s*([^()]+)\s*\(\)\s*(?:(?:\d+)\s*\|\s*)?(\d+)\s*\+\s*(\d+)\s*(?:.*)\):(.*)$/; -$RPCREGEX = qr/^\s*(?:Sending|Handling)\s*RPC\s*pid:xid:nid:opc\s*(\d+):(?:0x)?(\w+):(?:0x)?(\w+):(\d+)\s*$/; $FILEOPTIONREGEX = qr/(--server)|(-s)/; -$SENDING = qr/Sending/; +$PROCESS_MARKER = qr/Process (entered)|(leaving)/; +$MARKER_REGEX = qr/DEBUG MARKER:\s*====([\d+])=(.*)/; + +#Global variables +#Needs to match opcode definitions in lustre/include/linux/lustre_idl.h + +%ll_opcodes = ("0" => "OST_REPLY", "1" => "OST_GETATTR", "2" => "OST_SETATTR", + "3" => "OST_READ", "4" => "OST_WRITE", + "5" => "OST_CREATE", "6" => "OST_DESTROY", + "7" => "OST_GET_INFO", "8" => "OST_CONNECT", + "9" => "OST_DISCONNECT", "10" => "OST_PUNCH", + "11" => "OST_OPEN", "12" => "OST_CLOSE", "13" => "OST_STATFS", + "33" => "MDS_GETATTR", "34" => "MDS_GETATTR_NAME", + "35" => "MDS_CLOSE", "36" => "MDS_REINT", + "37" => "MDS_READPAGE", "38" => "MDS_CONNECT", + "39" => "MDS_DISCONNECT", "40" => "MDS_GETSTATUS", + "41" => "MDS_STATFS", "42" => "MDS_GETLOVINFO", + "101" => "LDLM_ENQUEUE", "102" => "LDLM_CONVERT", + "103" => "LDLM_CANCEL", "104" => "LDLM_BL_CALLBACK", + "105" => "LDLM_CP_CALLBACK" ); + +%ll_reint_opcodes = ("1" => "setattr", "2" => "create", "3" => "link", + "4" => "unlink", "5" => "rename", "6" => "open" ); # Needs to match definition in portals/include/linux/kp30.h %ll_subsystems = ("00" => "UNDEFINED", "01" => "MDC", "02" => "MDS", "03" => "OSC", "04" => "OST", "05" => "CLASS", "06" => "OBDFS","07" => "LLITE","08" => "RPC", - "09" => "EXT2OBD","0a" => "PORTALS","0b" => "SOCKNAL", - "0c" => "QSWNAL","0d" => "PINGER","0e" => "FILTER", - "0f" => "TRACE","10" => "ECHO","11" => "LDLM", + "09" => "EXT2OBD", "0a" => "PORTALS", "0b" => "SOCKNAL", + "0c" => "QSWNAL", "0d" => "PINGER", "0e" => "FILTER", + "0f" => "TRACE", "10" => "ECHO", "11" => "LDLM", "12" => "LOV", "13" => "GMNAL","14" => "PTLROUTER" ); %subsysnum; @@ -97,84 +172,48 @@ $subsysnum->{GMNAL} = 19; $subsysnum->{PTLROUTER} = 20; %tracemasks; -$tracemasks->{TRACE} = 1 << 0; # /* ENTRY/EXIT markers */ -$tracemasks->{INODE} = 1 << 1; # -$tracemasks->{SUPER} = 1 << 2; # -$tracemasks->{EXT2} = 1 << 3; # /* anything from ext2_debug */ -$tracemasks->{MALLOC} = 1 << 4; # /* print malloc, free information */ -$tracemasks->{CACHE} = 1 << 5; # /* cache-related items */ -$tracemasks->{INFO} = 1 << 6; # /* general information */ -$tracemasks->{IOCTL} = 1 << 7; # /* ioctl related information */ -$tracemasks->{BLOCKS} = 1 << 8; # /* ext2 block allocation */ -$tracemasks->{NET} = 1 << 9; # /* network communications */ -$tracemasks->{WARNING} = 1 << 10; # -$tracemasks->{BUFFS} = 1 << 11; # -$tracemasks->{OTHER} = 1 << 12; # -$tracemasks->{DENTRY} = 1 << 13; # -$tracemasks->{PORTALS} = 1 << 14; # /* ENTRY/EXIT markers */ -$tracemasks->{PAGE} = 1 << 15; # /* bulk page handling */ -$tracemasks->{DLMTRACE} = 1 << 16; # -$tracemasks->{ERROR} = 1 << 17; # /* CERROR} = ...) == CDEBUG} = D_ERROR, ...) */ -$tracemasks->{EMERG} = 1 << 18; # /* CEMERG} = ...) == CDEBUG} = D_EMERG, ...) */ -$tracemasks->{HA} = 1 << 19; # /* recovery and failover */ -$tracemasks->{RPCTRACE} = 1 << 19; # /* recovery and failover */ - +$tracemasks->{TRACE} = sprintf "%06x", 1 << 0 ; # /* ENTRY/EXIT markers */ +$tracemasks->{INODE} = sprintf "%06x", 1 << 1; # +$tracemasks->{SUPER} = sprintf "%06x", 1 << 2; # +$tracemasks->{EXT2} = sprintf "%06x", 1 << 3; # /* anything from ext2_debug */ +$tracemasks->{MALLOC} = sprintf "%06x", 1 << 4; # /* print malloc, free info */ +$tracemasks->{CACHE} = sprintf "%06x", 1 << 5; # /* cache-related items */ +$tracemasks->{INFO} = sprintf "%06x", 1 << 6; # /* general information */ +$tracemasks->{IOCTL} = sprintf "%06x", 1 << 7; # /* ioctl related info */ +$tracemasks->{BLOCKS} = sprintf "%06x", 1 << 8; # /* ext2 block allocation */ +$tracemasks->{NET} = sprintf "%06x", 1 << 9; # /* network communications */ +$tracemasks->{WARNING} = sprintf "%06x", 1 << 10; # +$tracemasks->{BUFFS} = sprintf "%06x", 1 << 11; # +$tracemasks->{OTHER} = sprintf "%06x", 1 << 12; # +$tracemasks->{DENTRY} = sprintf "%06x", 1 << 13; # +$tracemasks->{PORTALS} = sprintf "%06x", 1 << 14; # /* ENTRY/EXIT markers */ +$tracemasks->{PAGE} = sprintf "%06x", 1 << 15; # /* bulk page handling */ +$tracemasks->{DLMTRACE} = sprintf "%06x", 1 << 16; # +$tracemasks->{ERROR} = sprintf "%06x", 1 << 17; # /* CERROR +$tracemasks->{EMERG} = sprintf "%06x", 1 << 18; # /* CEMERG +$tracemasks->{HA} = sprintf "%06x", 1 << 19; # /* recovery and failover */ +$tracemasks->{RPCTRACE} = sprintf "%06x", 1 << 20; # +$tracemasks->{VFSTRACE} = sprintf "%06x", 1 << 21; # Contains all the file names, the first filename is the # client. After that are all servers. my @filearray = (); +# Setup parent/child/sibling relationship between +# this line and the preceding line +sub setup_relations +{ + my $lineref = shift; + my $pidprevious = shift; -# Create backlinks between array entries based on the calling sequence -# For each new PID encountered, the first entry will be present in the -# PID hash. - -sub create_links { - my $arrayref = shift @_; - my $pidhashref = shift @_; - my $stitchref = shift @_; - my %local_hash; - my $hash_lineref; - my $tmpfmtref; - my $tmpref; - my $firstlineaftermarker = 0; - - foreach $lineref (@$arrayref) { - next if ($lineref->[$e_time] == 0); # Skip the client marker line - my $pidprevious = $pidhashref->{$lineref->[$e_pid]}; - if ($pidprevious->[$e_next] == 0) { - $pidprevious->[$e_next] = $lineref; - if (exists $local_hash{$lineref->[$e_pid]} - && $firstlineaftermarker) { - $hash_lineref=$local_hash{$lineref->[$e_pid]}; - $hash_lineref->[$e_next] =$lineref; - $firstlineaftermarker = 0; - } - } elsif ($local_hash{$lineref->[$e_pid]} == 0) { - # True only for the first line, the marker line. - $local_hash{$lineref->[$e_pid]}=$lineref; - #print "LINE ADDED TO HASH: @$lineref\n"; - $firstlineaftermarker = 1; - } - # Stack grows upward (assumes x86 kernel) if ($lineref->[$e_stack] < $pidprevious->[$e_stack]) { # lineref is not a child of pidprevious, find its parent - LINE: while(($lineref->[$e_stack] < $pidprevious->[$e_stack]) && - ($lineref->[$e_function] == $pidprevious->[$e_function]) - ) { - #This second part of the comparision is a HACK - last LINE if ($pidprevious->[$e_backref] == 0); + while($lineref->[$e_stack] < $pidprevious->[$e_stack]) { + last if ($pidprevious->[$e_backref] == 0); $pidprevious = $pidprevious->[$e_backref]; } } if ($lineref->[$e_stack] > $pidprevious->[$e_stack]) { - # lineref is child of pidprevious, with the caveat that they must - # belong to different functions. This is a HACK - # until CDEBUG is modified - while($lineref->[$e_function] eq $pidprevious->[$e_function]) { - last if ($pidprevious->[$e_backref] == 0); - $pidprevious = $pidprevious->[$e_backref]; - } - + # lineref is child of pidprevious, $lineref->[$e_backref] = $pidprevious; $pidprevious->[$e_numchildren]++; } else { @@ -183,92 +222,237 @@ sub create_links { $lineref->[$e_backref] = $pidprevious->[$e_backref]; ($lineref->[$e_backref])->[$e_numchildren]++; } - - $pidhashref->{$lineref->[$e_pid]} = $lineref; $lineref->[$e_youngestchild] = $lineref; while ($pidprevious->[$e_backref] != 0) { $pidprevious->[$e_youngestchild] = $lineref; $pidprevious = $pidprevious->[$e_backref]; } $pidprevious->[$e_youngestchild] = $lineref; - $lineref->[$e_pidhead]=$pidprevious; + $lineref->[$e_pidhead] = $pidprevious; +} + +# Update the RPC hash table, if this line is an RPC (or +# related) line. - # Stitch together rpc's - if($lineref->[$e_fmtstr] =~ $RPCREGEX) { - #print "RPC LINE: @$lineref\n"; - $tmpfmtref = [$1, $2, $3, $4, 0, 0, 0]; - if ($lineref->[$e_fmtstr] =~ $SENDING) { - $tmpfmtref->[$e_rpcsndrcv] = $SEND; - } else { $tmpfmtref->[$e_rpcsndrcv] = $RCV; } - $tmpfmtref->[$e_curlineref] = $lineref; - $stitchref->{$lineref->[$e_time]} = $tmpfmtref; +sub update_RPC +{ + my $rpcref = shift; + my $lineref = shift; + + my $tmpfmtref; + my $contextstr; + if ($lineref->[$e_fmtstr] =~ $RPCREGEX) { + $tmpfmtref = [$3, $5, 0, 0, $2, $4, 0]; + if ($1 eq $SENDING) { + $tmpfmtref->[$e_rpcsndrcv] = $CLI_SEND; + } elsif ($1 eq $HANDLING) { + $tmpfmtref->[$e_rpcsndrcv] = $SRV_RCV; + } elsif ($1 eq $HANDLED) { + $tmpfmtref->[$e_rpcsndrcv] = $SRV_REPLY; + } elsif ($1 eq $COMPLETED) { + $tmpfmtref->[$e_rpcsndrcv] = $CLI_COMPLETE; } + else { + print STDERR "Unknown RPC Expression: $lineref->[$e_fmtstr]\n"; + } + insert_rpcref($rpcref, $tmpfmtref, $lineref); + } +} +sub insert_rpcref +{ + my $rpcref = shift; + my $tmpfmtref = shift; + my $lineref = shift; + + $tmpfmtref->[$e_cliRPCent] = 0; + $tmpfmtref->[$e_srvRPCent] = 0; + $tmpfmtref->[$e_srvRPCexit] = 0; + $tmpfmtref->[$e_cliRPCexit] = 0; + + $tmpfmtref->[$e_curline] = $lineref; + # print_RPCfields($tmpfmtref); + $rpcref->{$lineref->[$e_time]} = $tmpfmtref; +} + +sub update_debugreqs +{ + my $rpcref = shift; + my $lineref = shift; + + @fields = $lineref->[$e_fmtstr] =~ $DEBUGREQ_REGEX; + if ($#fields) { + my $str = $fields[$e_drq_str]; + my $xid = $fields[$e_drq_xid]; + my $opc = $fields[$e_drq_opcode]; + # printf STDERR "str=%s\n", $str; + # Check for MDS_REINT subopcode + if (($opc == 36) && ($str =~ /reint \((\w+)\).*/)) { + my $subopcode = $1; + my $pid = $lineref->[$e_pid]; + #print STDERR "reint $xid $opc $subopcode $pid\n"; + my $tmpfmtref = [ $xid, $opc, $subopcode, $MDS_REINT, $pid, 0 ,0]; + insert_rpcref($rpcref, $tmpfmtref, $lineref); + } + } else { + printf STDERR "Failed to match DEBUGREQ line %d *********** str=%s\n", + $debugreq, $lineref->[$e_fmtstr]; } -match_rpcs($stitchref); -return $arrayref; } +# Create backlinks between array entries based on the calling sequence +# For each new PID encountered, the first entry will be present in the +# PID hash. + +sub sort_by_number_descending +{ + $b <=> $a; +} + +sub process_array +{ + my $arrayref = shift @_; + my $pidhashref = shift @_; + my $marker_ref = shift @_; + my $rpc_ref = shift @_; + my $vfs_ref = shift @_; + my $ldlm_ref = shift @_; + + my %lastline; # Hash of last line by pid + + print STDERR "Building PID/RPC list.....\n"; + $debugreq=0; + foreach $lineref (@$arrayref) { + next if ($lineref->[$e_time] == 0); + + my $pidprevious = $lastline->{$lineref->[$e_pid]}; + if ($pidprevious == 0) { + # True only for the first line, the PID marker line. + $pidhashref->{$lineref->[$e_pid]}->[$e_lineref] = $lineref; + $pidhashref->{$lineref->[$e_pid]}->[$e_pidcmd] = "unknown command line"; + # print STDERR "LINE ADDED TO HASH: @$lineref\n"; + $pidprevious = $lineref; + } + else { + if ($pidprevious->[$e_next] != 0) { + print STDERR "Fatal: Previous line next field !=0\n"; + print STDERR "Line: @$pidprevious\n"; + exit 1; + } + # Path for all lines except the PID marker + $pidprevious->[$e_next] = $lineref; + } + # Match VFS lines & force VFS Stack Value to be 1 (markers are 0) + if ($lineref->[$e_fmtstr] =~ $VFS_REGEX) { + $vfs_ref->{$lineref->[$e_time]} = $lineref; + $lineref->[$e_stack] = $VFS_STACK_VAL; + } + # Match Markers + elsif ($lineref->[$e_fmtstr] =~ $MARKER_REGEX) { + $marker_ref->{$lineref->[$e_time]} = [$1, $2, $lineref]; + } + # Match LDLM + elsif ($lineref->[$e_fmtstr] =~ $LDLM_REGEX) { + $ldlm_ref->{$lineref->[$e_time]} = $lineref; + } + # Match DEBUGREQ Lines + if ($lineref->[$e_fmtstr] =~ qr/@@@ /) { + $debugreq++; + update_debugreqs($rpc_ref, $lineref); + } + # Is this a process name ? + elsif (($lineref->[$e_pid] == 0) && + ($lineref->[$e_subsys] == $subsysnum->{RPC}) && + ($lineref->[$e_mask] == $tracemasks->{VFSTRACE})) { + if ($lineref->[$e_fmtstr] =~ /\s*(\d+)\s+(\w+)/) { + # first is pid, second is cmd + my $pid = $1; + my $cmdline = $2; + if (exists $pidhashref->{$pid}) { + $pidhashref->{$pid}->[$e_pidcmd] = $cmdline; + # printf "XXX pid=%d, cmd=%s\n", $1, $2; + } + } + } + # Match RPCs + else { + update_RPC($rpc_ref, $lineref); + } + # For all lines create parent/child relations + setup_relations($lineref, $pidprevious); + # Remember last line for this pid + $lastline->{$lineref->[$e_pid]} = $lineref; + } + print STDERR "#debugreq= $debugreq\n"; + foreach $pid (sort (sort_by_number_descending keys %$pidhashref)) { + # print STDERR "pid: $pid \[$pidhashref->{$pid}->[$e_pidcmd]\]\n"; + my $linecnt = 0; + my $pidlines_ref = $pidhashref->{$pid}->[$e_lineref]; + my $next = 0; + do { + $next = $pidlines_ref->[$e_next]; + $linecnt++; + $pidlines_ref = $next; + } until ($next == 0); + if ($pid) { # Skip pid 0 which are the lines listing all PIDs + print STDERR "pid=$pid \[$pidhashref->{$pid}->[$e_pidcmd]\] lines=$linecnt\n"; + } + } + + print STDERR "Matching RPCs.....\n"; + + match_RPC($rpc_ref); + # print_RPCmatrix($rpc_ref); + #exit 0; + #match_LDLM($ldlm_ref); + return $arrayref; +} # Main loop, parses the debug log -sub parse_file { - my %hasharray; +sub parse_file +{ my $input_files = shift; + my $marker_ref = shift; + my $rpc_ref = shift; + my $vfs_ref = shift; + my $ldlm_ref = shift; + my $pid_ref = shift; - my $stitch_ref = shift; my $pid = shift; my $rpctrace = shift; my $trace = shift; my $nodlm = shift; my $noclass = shift; my $nonet = shift; + my $uml = shift; - print "$pid, $rpctrace, $nodlm, $noclass, $nonet\n"; $backref = 0; $treeparent = 0; $numchildren = 0; $youngestchild = 0; $next = 0; $pidhead = 0; + $marked = 0; $iter = 0; foreach $file (@$input_files) { - + my $linecnt = 0; open(FILEHANDLE, $file) or die "Can't open file: $file\n"; while() { - if (/$REGEX/) { - @parsed_line=($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, - $treeparent, $numchildren, $youngestchild, - $pidhead, $next, $backref); - next if (($parsed_line[$e_pid] != $pid) && - ($pid) && ($iter == 0)); - next if (($parsed_line[$e_mask] != $tracemasks->{RPCTRACE}) - && ($rpctrace)); - next if ($trace && $parsed_line[$e_mask] != - $tracemasks->{TRACE}); - next if ($nodlm && hex($parsed_line[$e_subsys]) == - $subsysnum->{LDLM}); - next if ($noclass && hex($parsed_line[$e_subsys]) == - $subsysnum->{CLASS}); - next if ($nonet && (hex($parsed_line[$e_subsys]) == - $subsysnum->{RPC} || - hex($parsed_line[$e_subsys]) == - $subsysnum->{NET} || - hex($parsed_line[$e_subsys]) == - $subsysnum->{PORTALS} || - hex($parsed_line[$e_subsys]) == - $subsysnum->{SOCKNAL} || - hex($parsed_line[$e_subsys]) == - $subsysnum->{QSWNAL} || - hex($parsed_line[$e_subsys]) == - $subsysnum->{GMNAL})); + $linecnt++; + @parsed_line = get_parsed_line($uml, $file, $linecnt, $_); + next if ($#parsed_line == 0); + + next if (ignore_conditions(\@parsed_line, $pid, + $rpctrace, $trace, $nodlm, + $noclass, $nonet, $iter)); - if (!exists($hasharray{$parsed_line[$e_pid]})) { + if (!exists($pid_ref{$parsed_line[$e_pid]})) { # Push a marker for the beginning of this PID my @marker_line; $marker_line[$e_subsys] = 0; @@ -281,119 +465,747 @@ sub parse_file { $marker_line[$e_pid] = $parsed_line[$e_pid]; # marker lines are everyone's parent, so stack value zero $marker_line[$e_stack] = 0; - $marker_line[$e_fmtstr] = ""; + $marker_line[$e_fmtstr] = "XRT"; $marker_line[$e_treeparent] = 0; $marker_line[$e_numchildren] = 0; $marker_line[$e_youngestchild] = 0; $marker_line[$e_pidhead] = 0; - $marker_line[$e_next]= \@parsed_line; + $marker_line[$e_next]= 0; # No, no, no: \@parsed_line; $marker_line[$e_backref] = 0; - $hasharray{$parsed_line[$e_pid]} = \@marker_line; + $marker_line[$e_marked] = 0; + $pid_ref{$parsed_line[$e_pid]} = \@marker_line; push @$array_parsed, [ @marker_line ]; } push @$array_parsed, [ @parsed_line ]; } - - } close(FILEHANDLE); if ($iter == 0) { # Insert end of client line marker, an all zero pattern; - @marker_line = (0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0); + @marker_line = (0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0); push @$array_parsed, [ @marker_line ]; + } + $iter++; + } + $array_parsed = process_array($array_parsed, $pid_ref, $marker_ref, + $rpc_ref, $vfs_ref, $ldlm_ref); + # print_array($array_parsed); + return $array_parsed; +} + +sub match_RPC { + my $rpc_ref = shift; + my @sorted_key_list = sort keys %$rpc_ref; + my $num_rpc = 0; + my $i = 0; + + my $rpclistcnt = $#sorted_key_list ; + + foreach $rpckeys (@sorted_key_list) { + my $rpc_refcnt = 1; + $i++; + $tmpref = $rpc_ref->{$rpckeys}; + next if ($tmpref->[$e_rpcmarked] == 1); + $tmpref->[$e_rpcmarked] = 1; + # This has to be the first for this xid & opcode + if ($tmpref->[$e_rpcsndrcv] == $CLI_SEND) { + $tmpref->[$e_cliRPCent] = $tmpref->[$e_curline]; + $num_rpc++; + } else { + print STDERR "SKIPPING RPC LINE (INCORRECT ENTRY):", + "$tmpref->[$e_curline]->[$e_fmtstr]\n"; + next; + } + #print "CLIENT ENTRY POINT :$tmpref->[$e_curline]->[$e_fmtstr]\n"; + foreach $j ($i .. $rpclistcnt) { + $cmpkeys = $sorted_key_list[$j]; + # next if ($cmpkeys == $rpckeys); + $cmpref = $rpc_ref->{$cmpkeys}; + next if ($cmpref->[$e_rpcxid] != $tmpref->[$e_rpcxid]); + next if ($cmpref->[$e_rpcopc] != $tmpref->[$e_rpcopc]); + if ($cmpref->[$e_rpcsndrcv] == $SRV_RCV) { + $tmpref->[$e_srvRPCent] = $cmpref->[$e_curline]; + $rpc_refcnt++; + } + elsif ($cmpref->[$e_rpcsndrcv] == $SRV_REPLY) { + $tmpref->[$e_srvRPCexit] = $cmpref->[$e_curline]; + $rpc_refcnt++; + } + elsif ($cmpref->[$e_rpcsndrcv] == $CLI_COMPLETE) { + $tmpref->[$e_cliRPCexit] = $cmpref->[$e_curline]; + $rpc_refcnt++; + } + elsif ($cmpref->[$e_rpcsndrcv] == $MDS_REINT) { + $tmpref->[$e_rpcreint] = $cmpref->[$e_rpcreint]; + } + else { + print STDERR "Unexpected RPC sndrcv value $cmpref->[$e_rpcsndrcv] for line $tmpref->[$e_curline]->[$e_fmtstr]\n"; + } + $cmpref->[$e_rpcmarked] = 1; + if ($rpc_refcnt == 4) { + break; + } } - $iter ++; } - $array_parsed=create_links($array_parsed, \%hasharray, $stitch_ref); - #print_array($array_parsed); - return $array_parsed; + # Now delete all unmatched RPC hashes & set all marked back to zero + foreach $rpckeys (@sorted_key_list) { + $rpc_line = $rpc_ref->{$rpckeys}; + if ($rpc_line->[$e_cliRPCent] == 0 || + $rpc_line->[$e_cliRPCexit] == 0) { + # printf "Unmatched RPC Line: %s\n", $rpc_line->[$e_curline]->[$e_fmtstr]; + delete $rpc_ref->{$rpckeys}; + } + else { + $rpc_line->[$e_rpcmarked] = 0; + } + } + printf STDERR "Matched $num_rpc RPCs\n"; +} + +sub getnextchild +{ + my $rootline = shift; + my $lineref = shift; + my $tempref = $lineref->[$e_next]; + if (($tempref != 0) && ($tempref->[$e_stack] > $rootline->[$e_stack])) { + return $tempref; + } + return 0; +} + +# Parse out the file names given on the command line +sub parse_foptions +{ + my $inarg = shift; + my $idx = 0; + foreach $elem (@$inarg) { + next if ($elem =~ /$FILEOPTIONREGEX/); + $filearray[$idx] = $elem; + $idx++; + } + return \@filearray; } -sub print_array { +sub compute_time_diff +{ + my $first = shift; + my $second = shift; + + my $diff = + sprintf "%8.0f", + ((($second->[$e_time]) - ($first->[$e_time])) *1000000); + return $diff; +} + + +# Given a line, compute the duration that this particular +# invocation took. Relies on pointers being set up correctly. +# For the last function, performs an approximation. +# Useful for timing analysis + + +sub compute_time +{ + my $lineref = shift; + my $starttime = $lineref->[$e_time]; + my $pidheadtime = ($lineref->[$e_pidhead])->[$e_time]; + my $offset_usecs = + sprintf "%8.0f", (($starttime - $pidheadtime) * 1000000); + + my $youngestchild = $lineref->[$e_youngestchild]; + my $nextofyoungest = $youngestchild->[$e_next]; + my $youngesttime = 0; + if ($nextofyoungest != 0) { + $youngesttime = $nextofyoungest->[$e_time]; + } else { + #This is an approximation, at best for the last tree + $youngesttime=$youngestchild->[$e_time]; + } + + my $isleaf = ($lineref->[$e_numchildren] == 0); + my $nexttime = 0; + if ($lineref->[$e_next] != 0) { + $nexttime = ($lineref->[$e_next])->[$e_time]; + } else { + # Approximation.. + $nexttime = $lineref->[$e_time]; + } + my $duration_usecs = + sprintf "%8.0f", + ((($isleaf ? $nexttime : $youngesttime) - $starttime) * 1000000); + + return [$offset_usecs, $duration_usecs]; +} + +# Get the parsed line. +sub get_parsed_line() +{ + my $uml = shift; + my $file = shift; + my $linecnt = shift; + my $in_line = shift; + + if ($uml) { + # This if clause is redundant as now HOSTREGEX2 matches both UML + # and HOST CDEBUG log files (the --uml option kept just in case) + if($in_line =~ /$UMLREGEX/) { + @parsed_line = ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, + 0, 0, 0, 0, 0, 0, 0); + #print "$1, $2, $3, $4, $5, $6, $7, $8, $9, $10\n"; + } + else { + chop $in_line; + print "Mismatch in UML regular expression (file:$file, line:$linecnt)\n", + "\tOffending line: <$in_line>\n"; + return 0; + } + } else { + if ($in_line =~ /$HOSTREGEX2/) { + @parsed_line = ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, + 0, 0, 0, 0, 0, 0, 0); + #print "$1, $2, $3, $4, $5, $6, $7, $8, $9, $10\n"; + } else { + chop $in_line; + print "Mismatch in the host file (file:$file, line:$linecnt)\n", + "\tOffending line: <$in_line>\n"; + return 0; + } + } + return @parsed_line; +} + +# Function to skip over all stuff that the user +# doesn't want +sub ignore_conditions +{ + my $parsed_line = shift; + + my $pid = shift; + my $rpctrace = shift; + my $trace = shift; + my $nodlm = shift; + my $noclass = shift; + my $nonet = shift; + my $iter = shift; + + + if (($pid) && ($iter == 0) && ($parsed_line->[$e_pid] != $pid)) { + return 1; + } + if (($rpctrace) && ($parsed_line->[$e_mask] != $tracemasks->{RPCTRACE})) { + print "From rpctrace\n"; + return 1; + } + if ($trace && $parsed_line->[$e_mask] != $tracemasks->{TRACE}) { + return 1; + } + if ($nodlm && hex($parsed_line->[$e_subsys]) == $subsysnum->{LDLM}) { + return 1; + } + if ($noclass && hex($parsed_line->[$e_subsys]) == $subsysnum->{CLASS}) { + return 1; + } + if ($nonet && (hex($parsed_line->[$e_subsys]) == $subsysnum->{RPC} || + hex($parsed_line->[$e_subsys]) == $subsysnum->{NET} || + hex($parsed_line->[$e_subsys]) == $subsysnum->{PORTALS} || + hex($parsed_line->[$e_subsys]) == $subsysnum->{SOCKNAL} || + hex($parsed_line->[$e_subsys]) == $subsysnum->{QSWNAL} || + hex($parsed_line->[$e_subsys]) == $subsysnum->{GMNAL})) { + return 1; + } + # No use for ENTRY/EXIT markers + if ($parsed_line->[$e_fmtstr] =~ $PROCESS_MARKER) { + return 1; + } + return 0; +} + +# All print functions reside below here. + +sub print_RPCmatrix +{ + my $rpc_ref = shift; + foreach $rpckeys (sort keys %$rpc_ref) { + $rpc_line = $rpc_ref->{$rpckeys}; + $cl_ent_line = $rpc_line->[$e_cliRPCent]; + $cl_ext_line = $rpc_line->[$e_cliRPCexit]; + $srv_ent_line = $rpc_line->[$e_srvRPCent]; + $srv_ext_line = $rpc_line->[$e_srvRPCexit]; + print "*************************\n"; + print "Client entry(Time: $cl_ent_line->[$e_time]): $cl_ent_line->[$e_fmtstr]\n"; + print "Client exit(Time: $cl_ext_line->[$e_time]): $cl_ext_line->[$e_fmtstr]\n"; + print "Server entry(Time: $srv_ent_line->[$e_time]): $srv_ent_line->[$e_fmtstr]\n"; + print "Server exit(Time: $srv_ext_line->[$e_time]): $srv_ext_line->[$e_fmtstr]\n"; + print "**************************\n"; + } +} + +sub print_array +{ my $arrayref = shift; - foreach $lineref(@$arrayref){ - if ($lineref->[$e_backref]==0){ + my $cnt=0; + foreach $lineref (@$arrayref) { + $cnt++; + if ($cnt < 20) { + if ($lineref->[$e_backref] == 0) { print "MARKER LINE(addr): $lineref contents: [@$lineref]\n"; } else { - print "REGULAR LINE (addr) :$lineref contents:[@$lineref]\n"; } } + } +} +sub print_RPCfields +{ + my $rpc_line = shift; + print "RPC LINE: "; + print "XID: $rpc_line->[$e_rpcxid], OPC: $rpc_line->[$e_rpcopc],", + "REINT: $rpc_line->[$e_rpcreint],", + "SNDRCV: $rpc_line->[$e_rpcsndrcv], MARKED: $rpc_line->[$e_rpcmarked] ", + "PID: $rpc_line->[$e_rpcpid], NID: $rpc_line->[$e_rpcnid]\n"; } -sub print_rpcrelations { +my $summary_indent = 0; +my $summary_indent_string = " "; - my $rpchashref = shift; - foreach $rpckeys (sort keys %$rpchashref) { - $tmpref = $rpchashref->{$rpckeys}; - #print "Key: $rpckeys, Contents: @$tmpref\n"; +sub indent_print { + my $text = shift; + my $i; + for ($i=0; $i < $summary_indent; $i++) { + printf "%s", $summary_indent_string; + } + print "$text\n"; +} + +sub print_tx_totals { + my $pid = shift; + my $markercnt = shift; + my $showtime = shift; + my $tx_total_vfs_time = shift; + my $tx_rpc_cli_time = shift; + my $tx_rpc_srv_time = shift; + my $tx_rpc_net_time = shift; + my $tx_total_rpcs = shift; + my $vfs_idx = shift; + + my $cli_compute_time; + + if ($tx_total_rpcs == 0) { + $cli_compute_time = $tx_total_vfs_time; + } + else { + $cli_compute_time = $tx_total_vfs_time - $tx_rpc_cli_time; + } + if ($tx_rpc_srv_time == 0) { + $tx_rpc_srv_time = "unknown"; + $tx_rpc_net_time = "unknown"; + } + if ($tx_total_vfs_time != 0) { + my $textheader = "+++marker summary[$pid.$markercnt]:"; + my $textheaderlen = length($textheader); + my $text = "$textheader\t[#ll_ops=$vfs_idx, #rpcs=$tx_total_rpcs"; + + if ($showtime =~ /m/) { + $text .= ", $tx_total_vfs_time usecs/total (client=$cli_compute_time, server=$tx_rpc_srv_time, network= $tx_rpc_net_time)"; + } + $text .= "]"; + + print "\n"; + indent_print($text); + if (($showtime =~ /c/) && ($showtime =~ /m/)) { + my $avgrpc_concurrency = $tx_rpc_cli_time / $tx_total_vfs_time; + my $pct_client = ($cli_compute_time *100) / $tx_total_vfs_time; + my $pct_srv = 0; + my $pct_net = 0; + if ($tx_rpc_srv_time != 0) { + $pct_srv = ($tx_rpc_srv_time *100) / $tx_total_vfs_time; + $pct_net = 100 - $pct_client - $pct_srv; + } + my $ccline = sprintf "%${textheaderlen}s\t[rpc_concurrency=%d/%d= %.1f (avg), (client=%.0f%%, server=%.0f%%, network=%.0f%%)]", " ", $tx_rpc_cli_time, $tx_total_vfs_time, $avgrpc_concurrency, $pct_client, $pct_srv, $pct_net ; + indent_print($ccline); + } + print "\n"; } +} +sub print_summary_terse +{ + my $showtime = shift; + my $array_ref = shift; + my $marker_ref = shift; + my $vfs_ref = shift; + my $rpc_ref = shift; + my $ldlm_ref = shift; + my $pid_ref = shift; + my $ldlmdebug = shift; + + foreach $pid (sort (sort_by_number_descending keys %$pid_ref)) { + next if ($pid==0); + my $linecnt = 0; + my $lineref = $pid_ref->{$pid}->[$e_lineref]; + # print STDERR "pid=$pid \[$pid_ref->{$pid}->[$e_pidcmd]\]\n"; + $summary_indent = 0; + indent_print("Process $lineref->[$e_pid] \[$pid_ref->{$pid}->[$e_pidcmd]\]"); + my $vfs_rpc_cli_time; + my $vfs_rpc_srv_time; + my $vfs_rpc_net_time; + my $vfs_time; + my $rpc_idx; + my $vfs_idx; + my $tx_total_rpcs; + my $tx_rpc_cli_time; + my $tx_rpc_srv_time; + my $tx_rpc_net_time; + my $tx_total_vfs_time; + my $markercnt = 0; + my $clearcnts = 1; + my $vfs_line; + + $lineref = $lineref->[$e_next]; + + do { + $linecnt++; + # Clear counts + if ($clearcnts) { + $rpc_idx = 0; + $vfs_idx = 0; + $tx_total_rpcs = 0; + $clearcnts = 0; + $vfs_rpc_cli_time = 0; + $vfs_rpc_srv_time = 0; + $vfs_rpc_net_time = 0; + $vfs_time = 0; + $tx_rpc_cli_time = 0; + $tx_rpc_srv_time = 0; + $tx_rpc_net_time = 0; + $tx_total_vfs_time = 0; + $vfs_line = 0; + } + # $lineref = getnextchild($vfs_line, $lineref); + my $next = $lineref->[$e_next]; + # LDLM ? + if (($ldlmdebug) && (exists($ldlm_ref->{$lineref->[$e_time]}))) { + # Needs to get better + $summary_indent++; + indent_print("LDLM op: $lineref->[$e_fmtstr]"); + $summary_indent--; + # $ldlm_time = compute_time ($lineref); + # print "\t\t\t Completion time (us) : $ldlm_time->[1]\n"; + } + + # Known as Client RPC ? + my $rpc_line = $rpc_ref->{$lineref->[$e_time]}; + if ($rpc_line) { + if (($rpc_line->[$e_cliRPCent] != 0) && + ($rpc_line->[$e_cliRPCexit] != 0)) { + $rpc_idx++; + # + my $srv_time; + my $net_time; + # RPC time computation + my $cl_time = compute_time_diff($rpc_line->[$e_cliRPCent], + $rpc_line->[$e_cliRPCexit]); + $vfs_rpc_cli_time += $cl_time; + if (($rpc_line->[$e_srvRPCent] != 0) && + ($rpc_line->[$e_srvRPCexit] != 0)) { + $srv_time = compute_time_diff($rpc_line->[$e_srvRPCent], + $rpc_line->[$e_srvRPCexit]); + $net_time = $cl_time - $srv_time; + $vfs_rpc_srv_time += $srv_time; + $vfs_rpc_net_time += $net_time; + } else { + $srv_time = "unknown"; + $net_time = "unknown"; + } + my $rpcopcode = $ll_opcodes{$rpc_line->[$e_rpcopc]}; + my $line = "rpcxid #$rpc_line->[$e_rpcxid] $rpcopcode"; + if ($rpcopcode eq "MDS_REINT") { + my $reint_opcode = $rpc_line->[$e_rpcreint]; + $line .= "($reint_opcode)"; + } + if ($showtime =~ /r/) { + $cl_time =~ /\s+([0-9]+)/; + my $cl_time2 = $1; + $srv_time =~ /\s+([0-9]+)/; + my $srv_time2 = $1; + $line .= "\t\t[$cl_time2 usecs/rpc = (server=$srv_time2, network=$net_time)]"; + } + $summary_indent = 3; + indent_print($line); + } + } + # Check Marker line + my $marker_line = $marker_ref->{$lineref->[$e_time]}; + # Check VFS Op + my $next_vfs_line = $vfs_ref->{$lineref->[$e_time]}; + if (($showtime =~ /v/) && ($vfs_line) && + (($next == 0) || ($next_vfs_line)|| ($marker_line))) { + # Print per-VFS call RPC statistics + my $client_time = int($vfs_time); + my $srv_time = 0; + my $net_time = 0; + if ($rpc_idx != 0) { + if ($vfs_rpc_srv_time == 0) { + $srv_time = "unknown"; + $net_time = "unknown"; + } else { + $srv_time = $vfs_rpc_srv_time; + $net_time = $vfs_rpc_net_time; + } + $client_time = $vfs_time - $vfs_rpc_cli_time; + } + my $vfs_time2 = int($vfs_time); + my $text = "($vfs_line->[$e_function] summary: \t\t[#rpcs=$rpc_idx, $vfs_time2 usecs/total = (client=$client_time, server=$srv_time, network=$net_time)])"; + $summary_indent = 3; + indent_print($text); + } + # Process the VFS call + if ($next_vfs_line) { + $vfs_line = $next_vfs_line; + $tx_total_rpcs += $rpc_idx; + $vfs_idx++; + + $tx_rpc_cli_time += $vfs_rpc_cli_time; + $tx_rpc_srv_time += $vfs_rpc_srv_time; + $tx_rpc_net_time += $vfs_rpc_net_time; + $tx_total_vfs_time += $vfs_time; + + $vfs_rpc_cli_time = 0; + $vfs_rpc_srv_time = 0; + $vfs_rpc_net_time = 0; + $vfs_time = 0; + + $vfs_tmp_time = compute_time($vfs_line); + $vfs_time = $vfs_tmp_time->[1]; + + $vfs_line->[$e_fmtstr] =~ $VFS_REGEX; + $summary_indent = 2; + indent_print("$vfs_line->[$e_function]\($1\)"); + $rpc_idx = 0; + } + # Process Marker Line + if (($next == 0) || ($marker_line)) { + $summary_indent = 1; + if (($next == 0) || ($linecnt > 1)) { + $tx_total_rpcs += $rpc_idx; + $tx_rpc_cli_time += $vfs_rpc_cli_time; + $tx_rpc_srv_time += $vfs_rpc_srv_time; + $tx_rpc_net_time += $vfs_rpc_net_time; + $tx_total_vfs_time += $vfs_time; + # Print total Transaction time of previous TxN + print_tx_totals($pid, $markercnt, $showtime, + $tx_total_vfs_time, $tx_rpc_cli_time, + $tx_rpc_srv_time, $tx_rpc_net_time, + $tx_total_rpcs, $vfs_idx); + } + if ($marker_line) { + $markercnt++; + indent_print("+++marker[$pid.$markercnt]: $marker_line->[1]\n"); + } + $clearcnts = 1; + } + $lineref = $next; + } until ($lineref == 0); + } } -sub match_rpcs { - my $rpchashref = shift; - foreach $rpckeys (sort keys %$rpchashref) { - $tmpref = $rpchashref->{$rpckeys}; - #print "MATCHING: $@tmpref...\n"; - foreach $cmpkeys (sort keys %$rpchashref) { - next if($cmpkeys == $rpckeys); - $cmpref = $rpchashref->{$cmpkeys}; - # print "Line compared: @$cmpref\n"; - next if ($tmpref->[$e_rpcsndrcv] == $cmpref->[$e_rpcsndrcv]); - next if ($tmpref->[$e_rpcpid] != $cmpref->[$e_rpcpid]); - next if ($tmpref->[$e_rpcxid] != $cmpref->[$e_rpcxid]); - if ($tmpref->[$e_rpcsndrcv] == $SEND) { - $tmpref->[$e_rpcnext] = $cmpkeys; - #print "MACTHED: KEY 1: $rpckeys CONTENTS: @$tmpref", - #"KEY2: $cmpkeys CONTENTS: @$cmpref\n" +sub print_summary_verbose +{ + my $showtime = shift; + my $array_ref = shift; + my $marker_ref = shift; + my $vfs_ref = shift; + my $rpc_ref = shift; + my $ldlm_ref = shift; + my $pid_ref = shift; + my $ldlmdebug = shift; + + my $bool = 0; + my $firsttime; + + foreach $lineref (@$array_ref) { + next if ($lineref->[$e_time] == 0); + + if($lineref->[$e_backref] == 0) { + $firsttime = 1; + + } + # First see if any marker exists + if (exists $marker_ref->{$lineref->[$e_time]}) { + if ($bool) { + # Print total Transaction time of previous TxN + + if ($tx_total_vfs_time == 0) { + print "\n\t TX SUMMARY : No VFS Operation invoked for this transaction\n"; + } else { + print "\n\t TX SUMMARY : Operation Time (total): $tx_total_vfs_time\n "; + if ($tx_total_rpcs == 0) { + print "\t TX SUMMARY : NO RPCs performed for this transaction\n"; + } else { + print "\t TX SUMMARY : Total No of RPCs done : $tx_total_rpcs\n"; + print "\t TX SUMMARY : Operation Time (client): $tx_rpc_cli_time\n "; + if ($tx_rpc_srv_time == 0) { + print "\t TX SUMMARY : Operation Time (server): UNKNOWN\n "; + print "\t TX SUMMARY : Operation Time (network): UNKNOWN\n "; + + } else { + print "\t TX SUMMARY : Operation Time (server): $tx_rpc_srv_time\n "; + print "\t TX SUMMARY : Operation Time (network): $tx_rpc_net_time\n "; + + } + } } + print "\n\n\t +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++\n"; } + $marker_line = $marker_ref->{$lineref->[$e_time]}; + if ($firsttime && $prevpid != $lineref->[$e_pid]) { + print "\n*******************************Process $lineref->[$e_pid] Summary**************************************\n"; + $firsttime = 0; + $prevpid = $lineref->[$e_pid]; + } + print "\n\t ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++\n"; + print "\tOPERATION PERFORMED: $marker_line->[1]\n"; + $vfs_idx = 0; + $bool = 1; + $tx_total_rpcs = 0; + $tx_rpc_cli_time = 0; + $tx_rpc_srv_time = 0; + $tx_rpc_net_time = 0; + $tx_total_vfs_time = 0; + + } + # Next see if there is any VFS op this one's performing + + if (exists $vfs_ref->{$lineref->[$e_time]}) { + $vfs_line = $vfs_ref->{$lineref->[$e_time]}; + $vfs_idx++; + + $vfs_rpc_cli_time = 0; + $vfs_rpc_srv_time = 0; + $vfs_rpc_net_time = 0; + $vfs_time = 0; + + print "\n\t\t%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%\n"; + print "\t\t LLITE/VFS Operation # $vfs_idx: $vfs_line->[$e_function]:$vfs_line->[$e_time]\n"; + $vfs_tmp_time = compute_time($vfs_line); + $vfs_time = $vfs_tmp_time->[1]; + print "\t\t Total time for completion: $vfs_time\n"; + # Now iterate over for this VFS operation + $tmpref = $vfs_line; + $rpc_idx = 0; + do { + + if ((exists($ldlm_ref->{$tmpref->[$e_time]})) && + ($ldlmdebug)) { + # Needs to get better + print "\n\t\t\t LDLM Operation: $tmpref->[$e_fmtstr]\n"; + $ldlm_time = compute_time ($tmpref); + print "\t\t\t Completion time (us) : $ldlm_time->[1]\n"; + } + if (exists($rpc_ref->{$tmpref->[$e_time]})) { + $rpc_line = $rpc_ref->{$tmpref->[$e_time]}; + if (($rpc_line->[$e_cliRPCent] != 0) && + ($rpc_line->[$e_cliRPCexit] != 0)) { + $rpc_idx ++; + print "\n\t\t\t$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$\n"; + print "\t\t\t RPC # $rpc_idx\n"; + print "\t\t\t RPC-TxID: $rpc_line->[$e_rpcxid]\n"; + print "\t\t\t RPC-OpCde:$ll_opcodes{$rpc_line->[$e_rpcopc]}\n"; + print "\t\t\t RPC-Starttime(Client): $rpc_line->[$e_cliRPCent]->[$e_time]\n"; + print "\t\t\t RPC-Endtime(Client): $rpc_line->[$e_cliRPCexit]->[$e_time]\n"; + $cl_time = compute_time_diff($rpc_line->[$e_cliRPCent], + $rpc_line->[$e_cliRPCexit]); + $vfs_rpc_cli_time += $cl_time; + print "\t\t\t Client RPC Completion Time(us): $cl_time\n"; + if (($rpc_line->[$e_srvRPCent] != 0) && + ($rpc_line->[$e_srvRPCexit] != 0)) { + + $srv_time = compute_time_diff($rpc_line->[$e_srvRPCent], + $rpc_line->[$e_srvRPCexit]); + $net_time = $cl_time - $srv_time; + $vfs_rpc_srv_time += $srv_time; + $vfs_rpc_net_time += $net_time; + print "\t\t\t Server RPC Start time (us): $rpc_line->[$e_srvRPCent]->[$e_time]\n"; + print "\t\t\t Server RPC End time (us): $rpc_line->[$e_srvRPCexit]->[$e_time]\n"; + + print "\t\t\t Server RPC Time (us): $srv_time\n"; + print "\t\t\t Network RPC Time (us): $net_time\n"; + + } else { + print "\t\t\t Server RPC Time (us): UNKNOWN\n"; + print "\t\t\t Network RPC Time (us): UNKNOWN\n"; + + } } -} + } -sub getnextchild { - my $rootline = shift; - my $lineref = shift; - my $tempref = $lineref->[$e_next]; - if ($tempref == 0) { - return 0; + $tmpref = getnextchild($vfs_line, $tmpref); + } until ($tmpref == 0); + + # Print BASIC RPC statistics + if ($rpc_idx != 0) { + print "\n\t\t LLite Op $vfs_line->[$e_function] # RPCs: $rpc_idx\n"; } + if ($vfs_rpc_cli_time != 0) { + print "\t\t LLITE Op $vfs_line->[$e_function] RPC Client Time (us): $vfs_rpc_cli_time\n"; + if ($vfs_rpc_srv_time == 0) { + print "\t\t LLITE Op $vfs_line->[$e_function] RPC Server Time (us): UNKNOWN\n"; + print "\t\t LLITE OP $vfs_line->[$e_function] RPC Network Time (us) : UNKNOWN\n"; + } else { - if (($tempref->[$e_stack] > $rootline->[$e_stack]) || - (($tempref->[$e_stack] <= $rootline->[$e_stack]) && - ($tempref->[$e_function] == $rootline->[$e_function]) - )){ - # Child - return $tempref; + print "\t\t LLITE OP $vfs_line->[$e_function] RPC Server Time (us): $vfs_rpc_srv_time\n"; + print "\t\t LLITE OP $vfs_line->[$e_function] NET Network time (us): $vfs_rpc_net_time\n"; + } + } else { + print "\n\t\t No RPCs performed for this operation\n"; } - return 0; + $tx_total_rpcs += $rpc_idx; + $tx_rpc_cli_time += $vfs_rpc_cli_time; + $tx_rpc_srv_time += $vfs_rpc_srv_time; + $tx_rpc_net_time += $vfs_rpc_net_time; + $tx_total_vfs_time += $vfs_time; -} + } + } + if ($bool) { + # Print total Transaction time of previous TxN -sub parse_foptions { + if ($tx_total_vfs_time == 0) { + print "\n\t TX SUMMARY : No VFS Operation invoked for this transaction\n"; + } else { + print "\n\t TX SUMMARY : Operation Time (total): $tx_total_vfs_time\n "; + if ($tx_total_rpcs == 0) { + print "\t TX SUMMARY : NO RPCs performed for this transaction\n"; + } else { + print "\t TX SUMMARY : Total No of RPCs done : $tx_total_rpcs\n"; + print "\t TX SUMMARY : Operation Time (client): $tx_rpc_cli_time\n "; + if ($tx_rpc_srv_time == 0) { + print "\t TX SUMMARY : Operation Time (server): UNKNOWN\n "; + print "\t TX SUMMARY : Operation Time (network): UNKNOWN\n "; + + } else { + print "\t TX SUMMARY : Operation Time (server): $tx_rpc_srv_time\n "; + print "\t TX SUMMARY : Operation Time (network): $tx_rpc_net_time\n "; - my $inarg = shift; - my $idx = 0; - foreach $elem(@$inarg) { - next if ($elem =~ /$FILEOPTIONREGEX/); - $filearray[$idx] = $elem; - $idx++; } - return \@filearray; + } + } + + print "\n\n\t +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++\n"; + } + } 1; -#$array_parsed=parse_file(); -#print_array($array_parsed); +