#!/usr/bin/perl
+# -*- mode: cperl; cperl-indent-level: 4; cperl-continued-statement-offset: 0; cperl-extra-newline-before-brace: t; -*-
+#
# Copyright (C) 2002 Cluster File Systems, Inc.
# Author: Hariharan Thantry <thantry@users.sourceforge.net>
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_marked $e_treeparent
- $e_numchildren $e_youngestchild $e_next $e_pidhead
- $e_rpcsndrcv $e_rpcpid $e_rpcxid $e_rpcnid $e_rpcopc
+ %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,
- $e_processor,
- $e_time,
- $e_file,
- $e_line,
- $e_function,
- $e_pid,
- $e_stack,
- $e_fmtstr,
- $e_treeparent,
+($e_subsys,
+ $e_mask,
+ $e_processor,
+ $e_time,
+ $e_file,
+ $e_line,
+ $e_function,
+ $e_pid,
+ $e_stack,
+ $e_fmtstr,
+ $e_treeparent,
$e_numchildren,
- $e_youngestchild,
+ $e_youngestchild,
$e_pidhead,
- $e_next,
+ $e_next,
$e_backref,
- $e_marked) = (0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16);
+ $e_marked,
+ $e_rpcref) = (0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17);
-($e_rpcxid,
+($e_rpcuuid,
+ $e_rpcxid,
$e_rpcopc,
$e_rpcreint,
$e_rpcsndrcv,
$e_rpcpid,
- $e_rpcnid,
- $e_rpcmarked) = (0, 1, 2, 3, 4, 5, 6);
+ $e_rpcnid) = (0, 1, 2, 3, 4, 5, 6);
-($e_curline,
- $e_cliRPCent,
+ ($e_cliRPCent,
$e_srvRPCent,
$e_srvRPCexit,
- $e_cliRPCexit) = ($e_rpcmarked+1, $e_rpcmarked+2, $e_rpcmarked+3, $e_rpcmarked+4, $e_rpcmarked+5);
+ $e_cliRPCexit) = ($e_rpcnid+1, $e_rpcnid+2, $e_rpcnid+3, $e_rpcnid+4);
-$CLI_SEND = 1;
-$SRV_RCV = 2;
-$SRV_REPLY = 3;
-$CLI_COMPLETE = 4;
-$MDS_REINT = 5;
+($e_clirpctime,
+ $e_srvrpctime) = ($e_cliRPCexit+1, $e_cliRPCexit+2);
# Data structure for pidhashref
-($e_lineref, $e_pidcmd) = (0, 1);
+($e_lineref, $e_pidcmd) = (0, 1);
+
+# Data structure for ldlmref
+($e_rpckey, $e_ltype, $e_reqres, $e_grantedres, $e_reqmode, $e_grantmode) = (0, 1, 2, 3, 4, 5);
+
+
+# Data structure for HTML
+
+($e_htmline, $e_htmwritten, $e_htmbgcolor) = (0, 1, 2);
# 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+)\):(.*)$/;
+$REGEX= qr/^(\w+):(\d+):(\d+):(\d+\.(?:\d+))\s\(\s*([^:]+):(\d+):([^()]+)\(\)\s(\d+)(?:\s\|\s(?:\d+))?\+(\d+)\):(.*)$/;
#RPC REGEXES BELOW
$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*$/;
+$RPCREGEX = qr/^\s*($SENDING|$HANDLING|$HANDLED|$COMPLETED)\sRPC\scluuid:pid:xid:ni:nid:opc\s([-\w]+):(\d+):(?:0x)?(\w+):(?:\w+):(?:0x)?(\w+):(\d+)\s*$/;
+
#VFS REGEX BELOW
$VFS_REGEX = qr/VFS Op:(.+)/;
$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]+)/;
-#LDLMREGEX BELOW
-# This needs to change when I understand the LDLM statemachine better
+#LDLMREGEX
$LDLM_REGEX = qr/^\s*###/;
+$LDLM_FIELDS = qr/ns: ([-\w]+) lock: ([a-f\d]+)\/0x([a-f\d]+) lrc: (\d+)\/(\d+),(\d+) mode: ([-\w]+)\/([-\w]+) res: (\d+)\/(\d+) rrc: (\d+) type: (\w+)(?: \[(\d+)->(\d+)\])? remote: 0x([a-f\d]+)/;
-$LDLM_TEMP_REGEX = qr/^\s*client-side enqueue START/;
-$LDLM_TEMP_REGEX_2 = qr/^\s*client-side enqueue END/;
-#OTHER REGEXES
+$PLAIN = "PLN";
+$EXT = "EXT";
+$EMPTY = "EMPTY";
+$NOLOCK = "--";
+$INVALID = "invalid";
+#OTHER REGEXES
-$FILEOPTIONREGEX = qr/(--server)|(-s)/;
$PROCESS_MARKER = qr/Process (entered)|(leaving)/;
$MARKER_REGEX = qr/DEBUG MARKER:\s*====([\d+])=(.*)/;
"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" );
$tracemasks->{HA} = sprintf "%06x", 1 << 19; # /* recovery and failover */
$tracemasks->{RPCTRACE} = sprintf "%06x", 1 << 20; #
$tracemasks->{VFSTRACE} = sprintf "%06x", 1 << 21;
+
+@graph_colors;
+$graph_colors[0] = "#00cccc";
+$graph_colors[1] = "#ff0000";
+$graph_colors[2] = "#ffff66";
+$graph_colors[3] = "#99ff99";
+$graph_colors[4] = "#3333ff";
+$graph_colors[5] = "#cc9933";
+
+$MAX_GRAPH_COLOR = 5;
+$DEFAULT_BG_COLOR = "#ffffff";
+
+
+
# Contains all the file names, the first filename is the
# client. After that are all servers.
my @filearray = ();
+my @start_idx = ();
+
# Setup parent/child/sibling relationship between
# this line and the preceding line
sub setup_relations
my $lineref = shift;
my $pidprevious = shift;
- if ($lineref->[$e_stack] < $pidprevious->[$e_stack]) {
- # lineref is not a child of pidprevious, find its parent
+ if ($lineref->[$e_stack] < $pidprevious->[$e_stack]) {
+ # lineref is not a child of pidprevious, find its parent
while($lineref->[$e_stack] < $pidprevious->[$e_stack]) {
last if ($pidprevious->[$e_backref] == 0);
- $pidprevious = $pidprevious->[$e_backref];
- }
+ $pidprevious = $pidprevious->[$e_backref];
}
- if ($lineref->[$e_stack] > $pidprevious->[$e_stack]) {
+ }
+ if ($lineref->[$e_stack] > $pidprevious->[$e_stack]) {
# lineref is child of pidprevious,
- $lineref->[$e_backref] = $pidprevious;
- $pidprevious->[$e_numchildren]++;
+ $lineref->[$e_backref] = $pidprevious;
+ $pidprevious->[$e_numchildren]++;
+ } else {
+ # lineref is sibling of pidprevious
+ $lineref->[$e_numchildren] = 0;
+ $lineref->[$e_backref] = $pidprevious->[$e_backref];
+ ($lineref->[$e_backref])->[$e_numchildren]++;
+ }
+ $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;
+}
+
+
+sub handle_ldlm
+{
+ my $rpctype = shift;
+ my $rpckey = shift;
+ my $ldlmref = shift;
+ my $lineref = shift;
+ #LDLM ENQUEUE operation on SERVER
+ if ($rpctype eq $HANDLING) {
+ #print STDERR "***************************\n";
+ #print STDERRR "1st $lineref->[$e_fmtstr]\n";
+ if (exists $ldlmref->{$lineref->[$e_pid]}) {
+ # Reset for future LDLM on this service thread.
+ $ldlmref->{$lineref->[$e_pid]}->[$e_rpckey] = $rpckey;
+ $ldlmref->{$lineref->[$e_pid]}->[$e_reqres] = $EMPTY;
+ $ldlmref->{$lineref->[$e_pid]}->[$e_ltype] = 0;
+ $ldlmref->{$lineref->[$e_pid]}->[$e_grantedres] = 0;
+ $ldlmref->{$lineref->[$e_pid]}->[$e_reqmode] = $EMPTY;
+ $ldlmref->{$lineref->[$e_pid]}->[$e_grantmode] = 0;
} else {
- # lineref is sibling of pidprevious
- $lineref->[$e_numchildren] = 0;
- $lineref->[$e_backref] = $pidprevious->[$e_backref];
- ($lineref->[$e_backref])->[$e_numchildren]++;
+ # First time for this service thread
+ $ldlmref->{$lineref->[$e_pid]} = [$rpckey, 0, 0, 0, 0, 0];
+ $ldlmref->{$lineref->[$e_pid]}->[$e_reqres] = $EMPTY;
+ $ldlmref->{$lineref->[$e_pid]}->[$e_reqmode] = $EMPTY;
}
- $lineref->[$e_youngestchild] = $lineref;
- while ($pidprevious->[$e_backref] != 0) {
- $pidprevious->[$e_youngestchild] = $lineref;
- $pidprevious = $pidprevious->[$e_backref];
+ } elsif ($rpctype eq $HANDLED) {
+ $newkey = $ldlmref->{$lineref->[$e_pid]}->[$e_rpckey];
+ $ldlmref->{$newkey} = $ldlmref->{$lineref->[$e_pid]};
+ $ldlmcontent = $ldlmref->{$newkey};
+ delete $ldlmref->{$lineref->[$e_pid]};
+ #print "$newkey, CONTENT: $ldlmcontent->[$e_resname], $ldlmcontent->[$e_ltype],",
+ #"$ldlmcontent->[$e_mreq], $ldlmcontent->[$e_mgranted]\n";
+ }
+
+}
+
+sub update_ldlm
+{
+ my $ldlmref = shift;
+ my $lineref = shift;
+
+ my $tmpres;
+
+ if (exists($ldlmref->{$lineref->[$e_pid]})) {
+ $lineref->[$e_fmtstr] =~ $LDLM_FIELDS;
+ if (defined $12) {
+ $ldlmref->{$lineref->[$e_pid]}->[$e_ltype] = $12;
+ if ($ldlmref->{$lineref->[$e_pid]}->[$e_ltype] eq $PLAIN) {
+ if ($ldlmref->{$lineref->[$e_pid]}->[$e_reqres] eq $EMPTY) {
+ $ldlmref->{$lineref->[$e_pid]}->[$e_reqres] = "$9/$10";
+ $ldlmref->{$lineref->[$e_pid]}->[$e_reqmode] = "$8";
+ $ldlmref->{$lineref->[$e_pid]}->[$e_grantedres] = "$9/$10";
+ $ldlmref->{$lineref->[$e_pid]}->[$e_grantmode] = "$7";
+ }
+ $tmpres = "$9/$10";
+ } elsif ($ldlmref->{$lineref->[$e_pid]}->[$e_ltype] eq $EXT){
+ if (($ldlmref->{$lineref->[$e_pid]}->[$e_reqres] eq $EMPTY) && ($14 != 0)) {
+ $ldlmref->{$lineref->[$e_pid]}->[$e_reqres] = "$9/$10\{$13:$14\}";
+ $ldlmref->{$lineref->[$e_pid]}->[$e_reqmode] = "$8";
+ $ldlmref->{$lineref->[$e_pid]}->[$e_grantedres] = "$9/$10\{$13:$14\}";
+ $ldlmref->{$lineref->[$e_pid]}->[$e_grantmode] = "$7";
+ }
+ $tmpres = "$9/$10\{$13:$14\}";
+ }
+ # Update some fields, if there is any reason to do so.
+ if ($ldlmref->{$lineref->[$e_pid]}->[$e_grantmode] eq $NOLOCK) {
+ $ldlmref->{$lineref->[$e_pid]}->[$e_grantmode] = $ldlmref->{$lineref->[$e_pid]}->[$e_reqmode];
+ }
+ if (($tmpres ne $ldlmref->{$lineref->[$e_pid]}->[$e_grantedres]) &&
+ ($tmpres ne $ldlmref->{$lineref->[$e_pid]}->[$e_reqres])) {
+ $ldlmref->{$lineref->[$e_pid]}->[$e_grantedres] = $tmpres;
+ }
+ $tmpmode = "$7";
+ if (($tmpmode ne $ldlmref->{$lineref->[$e_pid]}->[$e_grantmode]) &&
+ ($tmpmode ne $ldlmref->{$lineref->[$e_pid]}->[$e_reqmode])) {
+ $ldlmref->{$lineref->[$e_pid]}->[$e_grantmode] = $tmpmode;
+ }
+ #$ldlmcontent = $ldlmref->{$lineref->[$e_pid]};
+ #print STDERR "LINE: $lineref->[$e_fmtstr]\n";
+ #print STDERR "(KEY): $lineref->[$e_pid] (CONTENT): $ldlmcontent->[$e_reqres],",
+ #"$ldlmcontent->[$e_ltype], $ldlmcontent->[$e_reqmode], $ldlmcontent->[$e_grantmode],",
+ #"$ldlmcontent->[$e_grantedres]\n";
}
- $pidprevious->[$e_youngestchild] = $lineref;
- $lineref->[$e_pidhead] = $pidprevious;
+ }
}
+
# Update the RPC hash table, if this line is an RPC (or
# related) line.
-
+
sub update_RPC
{
my $rpcref = shift;
+ my $ldlmref = shift;
my $lineref = shift;
-
+ my $filename = 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;
+ my $rpcuuid =$2;
+ my $rpctype = $1;
+ my $rpcxid = $4;
+ my $rpcopc = $6;
+ my $rpcpid = $3;
+ my $rpcnid = $5;
+ my $rpckey;
+
+ if ($rpcopc < 104) {
+ $rpckey = "$rpcopc:$rpcxid:$rpcpid:$rpcuuid";
+ } else {
+ $rpckey = "$rpcopc:$rpcxid:$rpcpid";
}
- else {
- print STDERR "Unknown RPC Expression: $lineref->[$e_fmtstr]\n";
+ if ($rpcopc >= 101) {
+ handle_ldlm($rpctype, $rpckey, $ldlmref, $lineref);
}
- insert_rpcref($rpcref, $tmpfmtref, $lineref);
- }
-}
-
-sub insert_rpcref
-{
- my $rpcref = shift;
- my $tmpfmtref = shift;
- my $lineref = shift;
+ my $thisrpc = $rpcref->{$rpckey};
+ if (!$thisrpc) {
+ # Initialize new RPC entry and insert into RPC hash
+ $thisrpc = [$rpcuuid, $rpcxid, $rpcopc, 0, 0, $rpcpid, $rpcnid, 0, 0, 0, 0, -1, -1];
+ $rpcref->{$rpckey} = $thisrpc;
+ }
+ # Backlink line to RPC
+ $lineref->[$e_rpcref] = $thisrpc;
+ # Now update Fields for this RPC
+ my $index;
+ if ($rpctype eq $SENDING) {
+ $index = $e_cliRPCent;
+ } elsif ($rpctype eq $HANDLING) {
+ $index = $e_srvRPCent;
+ } elsif ($rpctype eq $HANDLED) {
+ $index = $e_srvRPCexit;
+ } elsif ($rpctype eq $COMPLETED) {
+ $index = $e_cliRPCexit;
+ } else {
+ print STDERR "Unknown RPC Expression ($rpctype): $lineref->[$e_fmtstr]\n";
+ $index = -1;
+ }
+ if ($index >= 0) {
+ if ($thisrpc->[$index]==0) {
+ # This index is empty - add the current line to RPC
+ $thisrpc->[$index] = $lineref;
+ } else {
+ print STDERR "Duplicate $rpctype record for RPC [",
+ "uuid=$thisrpc->[$e_rpcuuid],",
+ "pid=$thisrpc->[$e_rpcpid],",
+ "xid=$thisrpc->[$e_rpcxid],",
+ "opc=$thisrpc->[$e_rpcopc]]\n";
+ print STDERR "Previous line: $thisrpc->[$index]\n";
+ print STDERR "Current line: $lineref\n";
+ }
+ }
+ # Check if client entry/exit times are present
+ if (($thisrpc->[$e_cliRPCent] != 0) && ($thisrpc->[$e_cliRPCexit] != 0)) {
+ $thisrpc->[$e_clirpctime] = compute_time_diff($thisrpc->[$e_cliRPCent],
+ $thisrpc->[$e_cliRPCexit]);
+ #print STDERR "Client time: $rpcxid, $thisrpc->[$e_clirpctime]\n";
+ }
+ if(($thisrpc->[$e_srvRPCent] != 0) && ($thisrpc->[$e_srvRPCexit] != 0)) {
+ $thisrpc->[$e_srvrpctime] = compute_time_diff($thisrpc->[$e_srvRPCent],
+ $thisrpc->[$e_srvRPCexit]);
+ #print STDERR "Server time: $rpcxid, $thisrpc->[$e_srvrpctime]\n";
+ }
+ $rpcref->{$rpckey} = $thisrpc;
- $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;
+ } elsif ($lineref->[$e_fmtstr] =~ qr/### /) {
+ update_ldlm($ldlmref, $lineref);
+ }
}
sub update_debugreqs
{
my $rpcref = shift;
my $lineref = shift;
-
@fields = $lineref->[$e_fmtstr] =~ $DEBUGREQ_REGEX;
if ($#fields) {
my $str = $fields[$e_drq_str];
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);
+ # No UUID ?
+ # insert_rpcref($rpcref, $tmpfmtref, $lineref);
}
} else {
printf STDERR "Failed to match DEBUGREQ line %d *********** str=%s\n",
$b <=> $a;
}
+
sub process_array
{
- my $arrayref = shift @_;
+ my $newarrayref = shift @_;
my $pidhashref = shift @_;
my $marker_ref = shift @_;
my $rpc_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;
+ $debugreq = 0;
+ $filearrayidx = 0;
+
+ while ($filearrayidx <= $#$newarrayref) {
+ $arrayref = $newarrayref->[$filearrayidx];
+ $arrayindex = 0;
+ while ($arrayindex <= $#$arrayref) {
+ $actualidx = ($arrayindex+$start_idx[$filearrayidx])%($#$arrayref+1);
+ $lineref = $arrayref->[$actualidx];
+ $arrayindex++;
+ next if ($lineref->[$e_time] == 0); #Ignoring all filemarker lines
+ next if ($lineref->[$e_fmtstr] eq $INVALID);
+ 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;
+ @cmdname = split(/:/, $lineref->[$e_pid]);
+ $pidhashref->{$lineref->[$e_pid]}->[$e_pidcmd] = $cmdname[0];
+ # print STDERR "LINE ADDED TO HASH: @$lineref\n";
+ $pidprevious = $lineref;
}
- # 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;
+ else {
+ $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 DEBUGREQ Lines
+ elsif ($lineref->[$e_fmtstr] =~ qr/@@@ /) {
+ $debugreq++;
+ update_debugreqs($rpc_ref, $lineref);
+ }
+ # Is this a process name ?
+ else {
+ my $tagged_pid = $lineref->[$e_pid];
+ $tagged_pid =~ /(\d+):(.+)/;
+ my $numericpid = $1;
+ my $pidtag = $2;
+ if (($numericpid == 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 $thispid = $1;
+ my $cmdline = $2;
+ my $lookuptag = "$thispid:$pidtag";
+ if (exists($pidhashref->{$lookuptag})) {
+ $pidhashref->{$lookuptag}->[$e_pidcmd] = $cmdline;
+ }
+ }
+ }
+ # Match RPCs
+ else {
+ update_RPC($rpc_ref, $ldlm_ref, $lineref);
}
}
+ # For all lines create parent/child relations
+ setup_relations($lineref, $pidprevious);
+ # Remember last line for this pid
+ $lastline{$lineref->[$e_pid]} = $lineref;
}
- # 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;
+ $filearrayidx++;
}
- 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_hash($ldlm_ref);
+ return $newarrayref;
+}
+
+sub print_hash
+{
+ my $ht = shift;
+ foreach $hashkey (%$ht) {
+ print STDERR "KEY: $hashkey CONTENT: $ht->{$hashkey}\n";
+ }
+
+}
+
+sub process_HTMLtext
+{
+ my $htmfile = shift;
+ my $pidhashref = shift;
+ if ($htmfile ne "") {
+ my $previous_pidfilename = "";
+ my $htmlfilename = sprintf "%s_left.html", $htmfile;
+ open (HTML, ">$htmlfilename");
+ print HTML "<HTML>";
+ print HTML "<HEAD>";
+ print HTML "<TITLE> llhtml view </TITLE>";
+ print HTML "</HEAD>";
+ print HTML "<BODY>\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_prev = $pidlines_ref;
+ $pidlines_ref = $next;
+ } until ($next == 0);
+ $pid =~ /(\d+):(.+)/;
+ my $numericpid = $1;
+ my $pidfname = $2;
+ my $graphhtmfile = join('_', split (/[\/, \.]/, $pidfname));
+ if ($numericpid) { # Skip pid 0 which are the lines listing all PIDs
+ #print STDERR "pid=$numericpid \[$pidhashref->{$pid}->[$e_pidcmd]\] lines=$linecnt ($pidfname)\n";
+ # Generate HTML Index Pane
+ if ($previous_pidfilename ne $pidfname) {
+ print HTML "<H3><A HREF = \"${htmfile}_${graphhtmfile}.html\" target=\"right\">$pidfname</A></H3>\n";
+ $previous_pidfilename = $pidfname;
+ }
+ my $anchorlinkpid = join('_', split(/[\/,:, \.]/, $pid));
+ print HTML "<a href = \"${htmfile}_right.html#$anchorlinkpid\" target=\"right\">$numericpid</a> \[$pidhashref->{$pid}->[$e_pidcmd]\]<br>\n";
+ }
}
+ print HTML "</BODY>";
+ print HTML "</HTML>\n";
+ close(HTML);
}
- 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
+# 100 microseconds is each table element
+$timebase = 1000;
+
+%gblstarttime;
+
sub parse_file
{
+ # File names that need to be slurped
my $input_files = shift;
+
+ # Hash tables that need to be populated
my $marker_ref = shift;
my $rpc_ref = shift;
my $vfs_ref = shift;
my $ldlm_ref = shift;
my $pid_ref = shift;
-
+
+ # All the options that should be processed
my $pid = shift;
my $rpctrace = shift;
my $trace = shift;
my $nodlm = shift;
my $noclass = shift;
my $nonet = shift;
- my $uml = shift;
+ my $htmfile = shift;
$backref = 0;
$treeparent = 0;
$next = 0;
$pidhead = 0;
$marked = 0;
- $iter = 0;
-
+ my $numfiles = 0;
foreach $file (@$input_files) {
my $linecnt = 0;
+ my $prev_time = 0;
+ # Initialize the starting index for this file to be zero
+ $start_idx[$numfiles] = 0;
+ # Initialize the starting time to be zero
open(FILEHANDLE, $file) or die "Can't open file: $file\n";
+ # Insert beginning of file marker, an all zero pattern
+ $fileline = [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0];
+ $new_file = join('_', split(/[\/, \.]/, $file));
+ $fileline->[$e_fmtstr] = $new_file;
+ push @{$array_parsed->[$numfiles]}, $fileline;
while(<FILEHANDLE>) {
-
$linecnt++;
- @parsed_line = get_parsed_line($uml, $file, $linecnt, $_);
+ @parsed_line = get_parsed_line($file, $linecnt, $_);
next if ($#parsed_line == 0);
-
next if (ignore_conditions(\@parsed_line, $pid,
$rpctrace, $trace, $nodlm,
- $noclass, $nonet, $iter));
-
- if (!exists($pid_ref{$parsed_line[$e_pid]})) {
+ $noclass, $nonet));
+ if (!exists($gblstarttime{$new_file})) {
+ $gblstarttime{$new_file} = $parsed_line[$e_time];
+ }
+
+ if ($prev_time > $parsed_line[$e_time]) {
+ # Wrapped log
+ if ($start_idx[$numfiles] != 0) {
+ print STDERR "Cannot repair file, log broken at lines: $start_idx[$numfiles]",
+ " AND at $linecnt \n";
+ exit;
+ }
+ print STDERR "Wrapped log at $linecnt in file $file\n";
+ $start_idx[$numfiles] = $linecnt; # Accounting for the dummy file line
+ $gblstarttime{$new_file} = $parsed_line[$e_time];
+ # Invalidate all the pid marker lines for this file, until now
+ @pids_file = split(/,/, $fileline->[$e_pid]);
+ foreach $pid (@pids_file) {
+ $invalid_ref = $pid_ref->{$pid};
+ $invalid_ref->[$e_fmtstr] = "invalid";
+ # Store in a temporary reference
+ $temp_ref->{$pid} = $pid_ref->{$pid};
+ delete $pid_ref->{$pid};
+ }
+ # remove all the fileline's pid value
+ $fileline->[$e_pid] = 0;
+ }
+ 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;
$marker_line[$e_numchildren] = 0;
$marker_line[$e_youngestchild] = 0;
$marker_line[$e_pidhead] = 0;
- $marker_line[$e_next]= 0; # No, no, no: \@parsed_line;
+ $marker_line[$e_next]= 0; # No, no, no: \@parsed_line;
$marker_line[$e_backref] = 0;
- $marker_line[$e_marked] = 0;
- $pid_ref{$parsed_line[$e_pid]} = \@marker_line;
- push @$array_parsed, [ @marker_line ];
-
+ $marker_line[$e_marked] = 0;
+ $pid_ref->{$parsed_line[$e_pid]}->[$e_lineref] = $marker_line;
+ $pid_ref->{$parsed_line[$e_pid]}->[$e_pidcmd] = $parsed_line[$e_pid];
+ # Update the current file line to provide info about all PIDS
+ if ($fileline->[$e_pid] == 0) {
+ $fileline->[$e_pid] = $parsed_line[$e_pid];
+ } elsif ($parsed_line[$e_pid] != 0) {
+ $fileline->[$e_pid] = sprintf "%s,%s", $fileline->[$e_pid], $parsed_line[$e_pid];
+ }
+ if (exists($temp_ref->{$parsed_line[$e_pid]})) {
+ delete $temp_ref->{$parsed_line[$e_pid]};
+ }
+ push @{$array_parsed->[$numfiles]}, [ @marker_line ];
}
- push @$array_parsed, [ @parsed_line ];
+ push @{$array_parsed->[$numfiles]}, [ @parsed_line ];
+ $prev_time = $parsed_line[$e_time];
+ }
+ # Determine if there are any outstanding pids that did not reappear
+ # in the log
+ foreach $pid (keys %$temp_ref) {
+ if (!exists($pid_ref->{$pid})) {
+ $valid_ref = $temp_ref->{$pid};
+ $valid_ref->[$e_fmtstr] = "XRT";
+ $pid_ref->{$pid} = $valid_ref;
+ $fileline->[$e_pid] = sprintf "%s,%s", $fileline->[$e_pid], $pid;
+ delete $temp_ref->{$pid};
}
- 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, 0);
- push @$array_parsed, [ @marker_line ];
}
- $iter++;
+ close(FILEHANDLE);
+ $numfiles++;
}
- $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++;
+sub process_HTMLgraph
+{
+ my $gbl_array_parsed = shift;
+ my $htmfile = shift;
+ my $pid_ref = shift;
+
+
+ my $file_idx = 0;
+ while ($file_idx <= $#$gbl_array_parsed) {
+ $array_parsed = $gbl_array_parsed->[$file_idx];
+ $lineref = $array_parsed->[0];
+ # Prepare the graph file for this file
+ $graph_file = sprintf "%s_%s.html", $htmfile, $lineref->[$e_fmtstr];
+ open(GRAPHHTML, ">$graph_file");
+ print GRAPHHTML "<HTML><HEAD><TITLE> Graphical view </TITLE></HEAD><BODY>";
+ print GRAPHHTML "<table cellpadding=\"0\" cellspacing=\"0\" border=\"1\" width=\"100\%\"><tbody><tr>";
+ @allpids = split(',', $lineref->[$e_pid]);
+ $colwidth = int 100/($#allpids+2);
+ print GRAPHHTML "<td valign=\"top\" width=\"$colwidth\%\"><font size=\"-1\">Time<br></font></td>";
+ $lasthtm = $pid_ref->{$allpids[0]}->[$e_lineref];
+ for ($idx = 0; $idx <= $#allpids; $idx ++) {
+ $graphidx = $idx%$MAX_GRAPH_COLOR;
+ $pid_name = $pid_ref->{$allpids[$idx]}->[$e_pidcmd];
+ $anchortag = join('_', split(/[\/,:, \.]/, $allpids[$idx]));
+ print GRAPHHTML "<td valign=\"top\" bgcolor=\"$graph_colors[$graphidx]\" width=\"$colwidth\%\">";
+ print GRAPHHTML "<a href = \"${htmfile}_right.html#$anchortag\" target=\"right\">";
+ print GRAPHHTML "<font size = \"-1\">$pid_name</font></a>";
+ print GRAPHHTML "</td>";
+ # Initialize the time origin
+ if (($pid_ref->{$allpids[$idx]}->[$e_lineref]->[$e_time]) < $lasthtm->[$e_time]) {
+ $lasthtm = $pid_ref->{$allpids[$idx]}->[$e_lineref];
}
- elsif ($cmpref->[$e_rpcsndrcv] == $MDS_REINT) {
- $tmpref->[$e_rpcreint] = $cmpref->[$e_rpcreint];
+ # Initialize the html state variables for this PID. Note that every PID can doing
+ # at most 2 RPCs at any time, i.e in the HANDLING, it could do a SENDING. We need
+ # to distinguish between the two, i.e we always maintain two html data structures
+ # for every PID
+ # Store the following for htm initialization, apart from the time origin
+ # (a) current RPC linereference, if any
+ # (b) iswritten : flag determining if the current text for RPC has already been written to HTML
+ # (c) colorcode
+ $htmstate{$allpids[$idx]}[0] = [0, 0, $graph_colors[$graphidx]];
+ $htmstate{$allpids[$idx]}[1] = [0, 0, $graph_colors[($graphidx+2)%$MAX_GRAPH_COLOR]];
+ $currtime = 0;
+ }
+ #print STDERR "File: $lineref->[$e_fmtstr]\n";
+ #print STDERR "Graph starttime: $lasthtm->[$e_time]\n";
+ #print STDERR "Txt starttime: $gblstarttime{$lineref->[$e_fmtstr]}\n";
+ print GRAPHHTML "</tr>";
+ # Do the first line again, we'll pass over it again, if it happens to be the fileline
+ $arrayidx = 0;
+ while( $arrayidx <= $#$array_parsed ) {
+ $lineref = $array_parsed->[($arrayidx+$start_idx[$file_idx])%($#$array_parsed+1)];
+ $arrayidx++;
+ next if ($lineref->[$e_rpcref] == 0);
+ # next if ($lineref->[$e_rpcref]->[$e_clirpctime] == -1);
+ # next if ($lineref->[$e_rpcref]->[$e_srvrpctime] == -1);
+ # this is an rpc line:
+ $htmduration = compute_time_diff($lasthtm, $lineref);
+ $flt_htmrows = $htmduration/$timebase;
+ $num_htmrows = sprintf("%.0f", $flt_htmrows);
+ # print everything upto now
+ for ($nrows = 0; $nrows <= $num_htmrows; $nrows ++) {
+ print GRAPHHTML "<tr>";
+ if ($nrows == 0) {
+ $newtime = pidoffset_time($lasthtm);
+ print GRAPHHTML "<td valign=\"top\" width=\"$colwidth\%\"><font size=\"-2\">$newtime</font></td>";
+ # Fill upto the next timebase
+ $more = $timebase-($newtime%$timebase);
+ if ($more > $htmduration) {
+ $more = $htmduration/2;
+ }
+ $newtime = $newtime + $more;
+ } else {
+ #Find if the current timebase will exceed the end of this RPC
+
+ print GRAPHHTML "<td valign=\"top\" width=\"$colwidth\%\"><font size=\"-2\">$newtime</font></td>";
+ $newtime += $timebase;
+ }
+ for ($idx = 0; $idx <= $#allpids; $idx ++) {
+ $current_htm = $htmstate{$allpids[$idx]}[1];
+ if ($current_htm->[$e_htmline] == 0) {
+ $current_htm = $htmstate{$allpids[$idx]}[0];
+ }
+ if ($current_htm->[$e_htmline] != 0) {
+ $bgcolor = $current_htm->[$e_htmbgcolor];
+ $text = $current_htm->[$e_htmwritten];
+ if ($text == 0) {
+ $htmline = $current_htm->[$e_htmline];
+ $htmrpcline = $htmline->[$e_rpcref];
+ $htmtmdisp = pidoffset_time($htmline);
+ if ($htmrpcline->[$e_rpcpid] == $htmline->[$e_pid]) {
+ $duration = $htmrpcline->[$e_clirpctime];
+ } else {
+ $duration = $htmrpcline->[$e_srvrpctime];
+ }
+ $until = $htmtmdisp+$duration;
+ $text = "$ll_opcodes{$htmrpcline->[$e_rpcopc]}\@$htmtmdisp\-$until";
+ $anchortxt = "TxID:$htmrpcline->[$e_rpcxid]\{$duration\}";
+ $current_htm->[$e_htmwritten] = 1;
+ } else {
+ $text = "";
+ }
+ } else {
+ $bgcolor = $DEFAULT_BG_COLOR;
+ $text = "";
+ }
+ # Now write it
+ if ($text ne "") {
+ $print_line = $current_htm->[$e_htmline];
+ $print_rpc_line = $print_line->[$e_rpcref];
+ $clientline = (($print_rpc_line->[$e_cliRPCent] == $print_line) ||
+ ($print_rpc_line->[$e_cliRPCexit] == $print_line));
+ if ($print_rpc_line->[$e_rpcopc] < 104) {
+ if ($clientline) {
+ $anchortag = sprintf "cli_%s_%s_%s_%s", $print_rpc_line->[$e_rpcopc],
+ $print_rpc_line->[$e_rpcxid],$print_rpc_line->[$e_rpcpid],
+ $print_rpc_line->[$e_rpcuuid];
+ } else {
+ $anchortag = sprintf "%s_%s_%s_%s", $print_rpc_line->[$e_rpcopc],
+ $print_rpc_line->[$e_rpcxid],$print_rpc_line->[$e_rpcpid],
+ $print_rpc_line->[$e_rpcuuid];
+ }
+ } else {
+ if ($clientline) {
+ $anchortag = sprintf "cli_%s_%s_%s", $print_rpc_line->[$e_rpcopc],
+ $print_rpc_line->[$e_rpcxid],$print_rpc_line->[$e_rpcpid];
+ } else {
+ $anchortag = sprintf "%s_%s_%s", $print_rpc_line->[$e_rpcopc],
+ $print_rpc_line->[$e_rpcxid],$print_rpc_line->[$e_rpcpid];
+ }
+ }
+ print GRAPHHTML "<td valign=\"top\" bgcolor=\"$bgcolor\" width=\"$colwidth\%\">";
+ print GRAPHHTML "<font size = \"-3\">";
+ print GRAPHHTML "<a href = \"${htmfile}_right.html#$anchortag\" target = \"right\">$anchortxt</a>";
+ print GRAPHHTML " $text";
+ print GRAPHHTML "</font></td>";
+ } else {
+ print GRAPHHTML "<td valign=\"top\" bgcolor=\"$bgcolor\" width=\"$colwidth\%\">";
+ print GRAPHHTML "</td>";
+ }
+ }
+ print GRAPHHTML "</tr>";
+
}
- else {
- print STDERR "Unexpected RPC sndrcv value $cmpref->[$e_rpcsndrcv] for line $tmpref->[$e_curline]->[$e_fmtstr]\n";
+ #$currtime = $newtime;
+ $rpc_line = $lineref->[$e_rpcref];
+ $clientry = ($rpc_line->[$e_cliRPCent] == $lineref);
+ $srventry = ($rpc_line->[$e_srvRPCent] == $lineref);
+ $lasthtm = $lineref;
+ $htm_elem = $htmstate{$lineref->[$e_pid]}[1];
+ if ($htm_elem->[$e_htmline] != 0) {
+ if ($clientry || $srventry) {
+ print STDERR "Impossible condition, third RPC entry point\n";
+ print STDERR "$lineref->[$e_pid], $lineref->[$e_fmtstr]\n";
+ exit ;
+ }
+ $htm_elem->[$e_htmline] = 0;
+ $htm_elem->[$e_htwritten] = 0;
+ next;
}
- $cmpref->[$e_rpcmarked] = 1;
- if ($rpc_refcnt == 4) {
- break;
+ $next_elem = $htmstate{$lineref->[$e_pid]}[0];
+ if ($next_elem->[$e_htmline] != 0) {
+ if ((!$clientry) && (!$srventry)) {
+ # i.e. this is an exit line
+ $next_elem->[$e_htmline] = 0;
+ $next_elem->[$e_htmwritten] = 0;
+ } else {
+ $htm_elem->[$e_htmline] = $lineref;
+ $htm_elem->[$e_htmwritten] = 0;
+ }
+ } else {
+ $next_elem->[$e_htmline] = $lineref;
+ $next_elem->[$e_htmwritten] = 0;
}
}
+ print GRAPHHTML "</BODY></HTML>";
+ close (GRAPHHTML);
+ $file_idx ++;
}
-
- # 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
{
my $inarg = shift;
my $idx = 0;
+ #print stderr "Files : ";
foreach $elem (@$inarg) {
- next if ($elem =~ /$FILEOPTIONREGEX/);
$filearray[$idx] = $elem;
+ #print stderr "$filearray[$idx] ";
$idx++;
}
+ #print stderr "\n";
return \@filearray;
}
{
my $first = shift;
my $second = shift;
-
my $diff =
sprintf "%8.0f",
((($second->[$e_time]) - ($first->[$e_time])) *1000000);
- return $diff;
+ return int($diff);
}
+sub pidoffset_time
+{
+ my $lineref = shift;
+ my $starttime = $lineref->[$e_time];
+ #my $pidheadtime = ($lineref->[$e_pidhead])->[$e_time];
+ my @tmpfilename = split(/:/, $lineref->[$e_pid]);
+ my $keyfilename = join('_', split(/[\/, \.]/, $tmpfilename[1]));
+ my $pidheadtime = $gblstarttime{$keyfilename};
+ my $offset_usecs =
+ sprintf "%8.0f", (($starttime - $pidheadtime) * 1000000);
+ return int($offset_usecs);
+}
# Given a line, compute the duration that this particular
# invocation took. Relies on pointers being set up correctly.
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;
#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) {
# 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;
- }
+ if ($in_line =~ /$REGEX/) {
+ my $tagged_pid = "${8}:${file}";
+ @parsed_line = ($1, $2, $3, $4, $5, $6, $7, $tagged_pid, $9, $10,
+ 0, 0, 0, 0, 0, 0, 0, 0);
+ #print "$1, $2, $3, $4, $5, $6, $7, $8, $9, $10\n";
} 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;
- }
+ chop $in_line;
+ print "Mismatch in the host file (file:$file, line:$linecnt)\n",
+ "\tOffending line: <$in_line>\n";
+ return 0;
+ return @parsed_line;
}
- 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)) {
+ if (($pid) && ($parsed_line->[$e_pid] != $pid)) {
return 1;
}
if (($rpctrace) && ($parsed_line->[$e_mask] != $tracemasks->{RPCTRACE})) {
# 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;
- my $cnt=0;
foreach $lineref (@$arrayref) {
- $cnt++;
- if ($cnt < 20) {
- if ($lineref->[$e_backref] == 0) {
- print "MARKER LINE(addr): $lineref contents: [@$lineref]\n";
+ if ($lineref->[$e_backref] == 0) {
+ print "MARKER LINE(addr): $lineref contents: [@$lineref]\n";
} else {
- print "REGULAR LINE (addr) :$lineref contents:[@$lineref]\n";
+ 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";
+ my $rpckey = "$rpc_line->[$e_rpcopc]:$rpc_line->[$e_rpcxid]:$rpc_line->[$e_rpcpid]:$rpc_line->[$e_rpcuuid]";
+ if ($rpc_line->[$e_rpcopc] > 102) {
+ print "RPC LINE: <$rpckey> ";
+ print "XID: $rpc_line->[$e_rpcxid], OPC: $rpc_line->[$e_rpcopc],",
+ "REINT: $rpc_line->[$e_rpcreint],",
+ "SNDRCV: $rpc_line->[$e_rpcsndrcv],",
+ "PID: $rpc_line->[$e_rpcpid], NID: $rpc_line->[$e_rpcnid]\n";
+ print "CLIENT ENTRY: $rpc_line->[$e_cliRPCent]->[$e_fmtstr]\n";
+ print "SRV ENTRY: $rpc_line->[$e_srvRPCent]->[$e_fmtstr]\n";
+ print "SRV EXIT: $rpc_line->[$e_srvRPCexit]->[$e_fmtstr]\n";
+ print "CLIENT EXIT: $rpc_line->[$e_cliRPCexit]->[$e_fmtstr]\n";
+ }
}
my $summary_indent = 0;
my $summary_indent_string = " ";
+$BREAK_LDLM_REGEXP=qr/(LDLM.+\) => \([^\(]+\))(.+)/;
+
+sub printHTML
+{
+ my $text = shift;
+ my $HTMHANDLE = shift;
+
+ my $htmlspacing;
+ print $HTMHANDLE "<PRE>";
+ if ($text =~ /Process\s*(\d+):(.*)/) {
+ @tmp = split(" ", $2);
+ $newtag = join('_', split(/[\/, \.]/, $tmp[0]));
+ $anchortag = sprintf "%s_%s", $1, $newtag;
+ print $HTMHANDLE "<A NAME = \"$anchortag\">";
+ for ($i=0; $i < $summary_indent; $i++) {
+ $htmlspacing = sprintf "%s", $summary_indent_string;
+ print $HTMHANDLE "$htmlspacing";
+ }
+ print $HTMHANDLE "$text\n</A>";
+ } elsif ($text =~ /rpcxid #(\d+)(.*)/) {
+ if ($text =~ /link=/) {
+ $tmprpc = shift;
+ $pidhashref = shift;
+ if ($tmprpc->[$e_rpcopc] < 104) {
+ $anchortag = sprintf "%s_%s_%s_%s",
+ $tmprpc->[$e_rpcopc], $tmprpc->[$e_rpcxid],
+ $tmprpc->[$e_rpcpid], $tmprpc->[$e_rpcuuid];
+ } else {
+ $anchortag = sprintf "%s_%s_%s",
+ $tmprpc->[$e_rpcopc], $tmprpc->[$e_rpcxid],
+ $tmprpc->[$e_rpcpid];
+ }
+ my $rpcpidname = ($tmprpc->[$e_cliRPCent])->[$e_pid];
+ my $clipidcmdname = ($pidhashref->{$rpcpidname})->[$e_pidcmd];
+ print $HTMHANDLE "<A NAME = \"$anchortag\">";
+ for ($i=0; $i < $summary_indent; $i++) {
+ $htmlspacing = sprintf "%s", $summary_indent_string;
+ print $HTMHANDLE "$htmlspacing";
+ }
+ # Creating back reference to the client
+ $text =~ qr/(rpcxid\s)(#\d+)(.+)\(link=.+\)/;
+ print $HTMHANDLE "</A>[${clipidcmdname}]:<A HREF = \"#cli_$anchortag\">xid $2</A>";
+ my $rpctext = $3;
+ if ($rpctext =~ /LDLM_.+/) {
+ $rpctext =~ $BREAK_LDLM_REGEXP;
+ print $HTMHANDLE " $1\n";
+ for ($i=0; $i < $summary_indent; $i++) {
+ $htmlspacing = sprintf "%s", $summary_indent_string;
+ print $HTMHANDLE "$htmlspacing";
+ }
+ print $HTMHANDLE " $2\n";
+ } else {
+ print $HTMHANDLE "$rpctext\n";
+ }
+ #@newtext = split(qr/link=/, $text);
+ # print $HTMHANDLE "$newtext[0]</A><A HREF = \"#cli_$anchortag\">link=$newtext[1]\n</A>";
+ } else {
+ $tmprpc = shift;
+ if ($tmprpc->[$e_rpcopc] < 104) {
+ $anchorref = sprintf "%s_%s_%s_%s",
+ $tmprpc->[$e_rpcopc], $tmprpc->[$e_rpcxid], $tmprpc->[$e_rpcpid], $tmprpc->[$e_rpcuuid];
+ } else {
+ $anchorref = sprintf "%s_%s_%s",
+ $tmprpc->[$e_rpcopc], $tmprpc->[$e_rpcxid], $tmprpc->[$e_rpcpid];
+ }
+ print $HTMHANDLE "<A NAME = \"cli_$anchorref\">";
+ for ($i=0; $i < $summary_indent; $i++) {
+ $htmlspacing = sprintf "%s", $summary_indent_string;
+ print $HTMHANDLE "$htmlspacing";
+ }
+ print $HTMHANDLE "</A><A HREF = \"#$anchorref\">rpcxid #$1</A>";
+ my $rpctext = $2;
+ if ($rpctext =~ /LDLM_.+/) {
+ $rpctext =~ $BREAK_LDLM_REGEXP;
+ print $HTMHANDLE " $1\n";
+ for ($i=0; $i < $summary_indent; $i++) {
+ $htmlspacing = sprintf "%s", $summary_indent_string;
+ print $HTMHANDLE "$htmlspacing";
+ }
+ print $HTMHANDLE " $2\n";
+ } else {
+ print $HTMHANDLE "$rpctext\n";
+ }
+ }
+ } elsif ($text =~ qr/\+\+\+marker\[([^\]]*)\](.*)/) {
+ for ($i=0; $i < $summary_indent; $i++) {
+ $htmlspacing = sprintf "%s", $summary_indent_string;
+ print $HTMHANDLE "$htmlspacing";
+ }
+ print $HTMHANDLE "+++marker\[<A HREF = \"#$1\">$1</A>\]$2\n";
+ } elsif ($text =~ qr/\+\+\+marker summary\[([^\]]*)\](.*)/ ){
+ print $HTMHANDLE "<A NAME = \"$1\">";
+ for ($i=0; $i < $summary_indent; $i++) {
+ $htmlspacing = sprintf "%s", $summary_indent_string;
+ print $HTMHANDLE "$htmlspacing";
+ }
+ print $HTMHANDLE "+++marker summary\[$1\]$2</A>";
+ }else{
+ for ($i=0; $i < $summary_indent; $i++) {
+ $htmlspacing = sprintf "%s", $summary_indent_string;
+ print $HTMHANDLE "$htmlspacing";
+ }
+ print $HTMHANDLE "$text\n";
+ }
+ print $HTMHANDLE "</PRE>";
+}
+
+
sub indent_print {
my $text = shift;
+ my $HTMHANDLE = shift;
+ my $temprpc = shift;
+ my $pidhashref = shift;
my $i;
+
+ # Print the regular stuff
for ($i=0; $i < $summary_indent; $i++) {
printf "%s", $summary_indent_string;
}
print "$text\n";
+
+ # Print HTML
+ if ($HTMHANDLE) {
+ printHTML($text, $HTMHANDLE, $temprpc, $pidhashref);
+ }
}
sub print_tx_totals {
my $tx_rpc_net_time = shift;
my $tx_total_rpcs = shift;
my $vfs_idx = shift;
-
+ my $HTMHANDLE = shift;
+
my $cli_compute_time;
if ($tx_total_rpcs == 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 .= ", $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);
+ indent_print($text, $HTMHANDLE, 0, 0);
if (($showtime =~ /c/) && ($showtime =~ /m/)) {
my $avgrpc_concurrency = $tx_rpc_cli_time / $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);
+ indent_print($ccline, $HTMHANDLE, 0, 0);
}
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;
+ my $htmfile = shift;
+ # HTML stuff
+ if ($htmfile ne "") {
+ my $htmfilename = sprintf "%s_right.html", $htmfile;
+ open(HTMLOG, ">$htmfilename");
+ print HTMLOG "<HTML><HEAD><TITLE> Outputlog </TITLE></HEAD><BODY>";
+ }
foreach $pid (sort (sort_by_number_descending keys %$pid_ref)) {
- next if ($pid==0);
+ $pid =~ /(\d+):(.+)/;
+ my $currentpid = $1;
+ next if ($currentpid==0);
+ my $curr_file = $2;
+
my $linecnt = 0;
my $lineref = $pid_ref->{$pid}->[$e_lineref];
- # print STDERR "pid=$pid \[$pid_ref->{$pid}->[$e_pidcmd]\]\n";
+ #print STDERR "pid=$pid \[$pid_ref->{$pid}->[$e_pidcmd]\]\n";
$summary_indent = 0;
- indent_print("Process $lineref->[$e_pid] \[$pid_ref->{$pid}->[$e_pidcmd]\]");
+ indent_print("Process $lineref->[$e_pid] \[$pid_ref->{$pid}->[$e_pidcmd]\]", HTMLOG, 0, 0);
my $vfs_rpc_cli_time;
my $vfs_rpc_srv_time;
my $vfs_rpc_net_time;
if (($ldlmdebug) && (exists($ldlm_ref->{$lineref->[$e_time]}))) {
# Needs to get better
$summary_indent++;
- indent_print("LDLM op: $lineref->[$e_fmtstr]");
+ indent_print("LDLM op: $lineref->[$e_fmtstr]", HTMLOG, 0, 0);
$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]};
+ # Known as RPC ?
+ my $rpc_line = $lineref->[$e_rpcref];
if ($rpc_line) {
- if (($rpc_line->[$e_cliRPCent] != 0) &&
- ($rpc_line->[$e_cliRPCexit] != 0)) {
+
+ my $clientside = ($rpc_line->[$e_rpcpid])==$currentpid;
+ my $client_entry = ($rpc_line->[$e_cliRPCent]==$lineref);
+ my $server_entry = ($rpc_line->[$e_srvRPCent]==$lineref);
+ #print STDERR "Clientside: $clientside, Cliententry: $client_entry",
+ #"Serverentry: $server_entry, clienttime: $rpc_line->[$e_clirpctime], srv_time: $rpc_line->[$e_srvrpctime]\n";
+
+ my $srv_time;
+ my $net_time;
+ my $cl_time;
+ my $pidoffset_time;
+ if ((($clientside) && ($client_entry)) ||
+ ((!$clientside) && ($server_entry))) {
$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;
+ if (($clientside) && ($client_entry) &&
+ ($rpc_line->[$e_clirpctime] != -1)) {
+ # Client Side RPC
+ $cl_time = $rpc_line->[$e_clirpctime];
+ #print STDERR "CLIENT TIME: $cl_time\n";
+ $pidoffset_time
+ = pidoffset_time($rpc_line->[$e_cliRPCent]);
+ $vfs_rpc_cli_time += $cl_time;
+ if ($rpc_line->[$e_srvrpctime] != -1){
+ $srv_time = $rpc_line->[$e_srvrpctime];
+ #print STDERR "SERVER TIME: $srv_time\n";
+ $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";
+ }
+ } elsif ((!$clientside) && ($server_entry) &&
+ ($rpc_line->[$e_srvrpctime] != -1)) {
+ # Server side RPC
+ $cl_time = $rpc_line->[$e_srvrpctime];
+ #print STDERR "Server time: $cl_time\n";
+ $pidoffset_time
+ = pidoffset_time($rpc_line->[$e_srvRPCent]);
} else {
- $srv_time = "unknown";
- $net_time = "unknown";
+ $cl_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 (($rpcopcode eq "LDLM_ENQUEUE") || ($rpcopcode eq "LDLM_CANCEL")) {
+ my $rpckey = "$rpc_line->[$e_rpcopc]:$rpc_line->[$e_rpcxid]:$rpc_line->[$e_rpcpid]:$rpc_line->[$e_rpcuuid]";
+ my $lockrec = $ldlm_ref->{$rpckey};
+ #print STDERR "LOCKREC: $lockrec->[$e_ltype]\n";
+ $line .= "($lockrec->[$e_ltype], $lockrec->[$e_reqres], $lockrec->[$e_reqmode])";
+ $line .= " => ($lockrec->[$e_grantedres], $lockrec->[$e_grantmode])";
+ }
+ if (($rpcopcode eq "LDLM_CP_CALLBACK") || ($rpcopcode eq "LDLM_BL_CALLBACK")) {
+ my $rpckey = "$rpc_line->[$e_rpcopc]:$rpc_line->[$e_rpcxid]:$rpc_line->[$e_rpcpid]";
+ my $lockrec = $ldlm_ref->{$rpckey};
+ $line .= "($lockrec->[$e_ltype], $lockrec->[$e_reqres], $lockrec->[$e_reqmode])";
+ $line .= " => ($lockrec->[$e_grantedres], $lockrec->[$e_grantmode])";
+ }
if ($showtime =~ /r/) {
- $cl_time =~ /\s+([0-9]+)/;
+ $cl_time =~ /\s*([0-9]+)/;
my $cl_time2 = $1;
- $srv_time =~ /\s+([0-9]+)/;
+ $srv_time =~ /\s*([0-9]+)/;
my $srv_time2 = $1;
- $line .= "\t\t[$cl_time2 usecs/rpc = (server=$srv_time2, network=$net_time)]";
+ $line .= "\t\t[$cl_time2 usecs";
+ if ($clientside) {
+ $line .= " (s=$srv_time2, n=$net_time)";
+ }
+ $line .= "] @ $pidoffset_time";
}
+ if (!$clientside) {
+ $line .= "\t(link=$rpc_line->[$e_rpcuuid])";
+ }
$summary_indent = 3;
- indent_print($line);
+ indent_print($line, HTMLOG, $rpc_line, $pid_ref);
}
}
# Check Marker line
# Check VFS Op
my $next_vfs_line = $vfs_ref->{$lineref->[$e_time]};
if (($showtime =~ /v/) && ($vfs_line) &&
- (($next == 0) || ($next_vfs_line)|| ($marker_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;
- }
+ 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)])";
+ my $text = "($vfs_line->[$e_function] summary: \t\t[#rpcs=$rpc_idx, $vfs_time2 usecs/total = (c=$client_time, s=$srv_time, n=$net_time)])";
$summary_indent = 3;
- indent_print($text);
+ indent_print($text, HTMLOG, 0, 0);
}
# 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\)");
+ indent_print("$vfs_line->[$e_function]\($1\) @ $vfs_tmp_time->[0]", HTMLOG, 0, 0);
$rpc_idx = 0;
}
# Process Marker Line
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);
+ $tx_total_rpcs, $vfs_idx, HTMLOG);
}
if ($marker_line) {
$markercnt++;
- indent_print("+++marker[$pid.$markercnt]: $marker_line->[1]\n");
+ indent_print("+++marker[$pid.$markercnt]: $marker_line->[1]\n", HTMLOG, 0, 0);
}
$clearcnts = 1;
}
$lineref = $next;
} until ($lineref == 0);
}
-}
-
-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";
-
- }
- }
-
- }
-
- $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 {
-
- 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";
+ if ($htmfile) {
+ print HTMLOG "<PRE>\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n</PRE>";
+ print HTMLOG "</BODY></HTML>";
+ close(HTMLOG);
}
-
- $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;
-
- }
+}
+sub print_rpc {
+ $rpc_ref = shift;
+ foreach $rpckey (sort keys %$rpc_ref) {
+ print_RPCfields($rpc_ref->{$rpckey});
}
- 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";
+sub gen_webpage {
+ my $htmname = shift;
+ if ($htmname ne "") {
+ my $mainhtml = sprintf "%s.html", $htmname;
+ open (HTMHANDLE, ">$mainhtml");
+ print HTMHANDLE "<HTML><HEAD><TITLE>\"Visualize Log\"</TITLE></HEAD>";
+ print HTMHANDLE "<FRAMESET COLS=\"20%, 80%\">";
+ print HTMHANDLE "<FRAME NAME=\"left\" SRC=\"${htmname}_left.html\">";
+ print HTMHANDLE "<FRAME NAME=\"right\" SRC=\"${htmname}_right.html\">";
+ print HTMLHANDEL "</FRAMESET></HTML>";
}
-
}
-
1;
git://git.whamcloud.com / fs / lustre-release.git / commitdiff