Viewing: llanalyze
#!/usr/bin/perl
use Getopt::Long;
use Term::ANSIColor;
GetOptions("pid=i" => \$pid,
"trace!" => \$trace,
"silent!" => \$silent,
"rpctrace!" => \$rpctrace,
"nodlm!" => \$nodlm,
"dlm_ns=s" => \$dlm_ns,
"noclass!" => \$noclass,
"nonet!" => \$nonet,
"extract_start=s" => \$extract_start,
"extract_end=s" => \$extract_end);
$subsys->{UNDEFINED} = 1 << 0;
$subsys->{MDC} = 1 << 1;
$subsys->{MDS} = 1 << 2;
$subsys->{OSC} = 1 << 3;
$subsys->{OST} = 1 << 4;
$subsys->{CLASS} = 1 << 5;
$subsys->{LOG} = 1 << 6;
$subsys->{LLITE} = 1 << 7;
$subsys->{RPC} = 1 << 8;
$subsys->{MGMT} = 1 << 9;
$subsys->{LNET} = 1 << 10;
$subsys->{LND} = 1 << 11;
$subsys->{PINGER} = 1 << 12;
$subsys->{FILTER} = 1 << 13;
# /* 1<< 14 unused */
$subsys->{ECHO} = 1 << 15;
$subsys->{LDLM} = 1 << 16;
$subsys->{LOV} = 1 << 17;
$subsys->{LQUOTA} = 1 << 18;
$subsys->{OSD} = 1 << 19;
$subsys->{LFSCK} = 1 << 20;
# /* 1<< 21 unused */
# /* 1<< 22 unused */
$subsys->{LMV} = 1 << 23; #/* b_new_cmd */
# /* 1<< 24 unused */
$subsys->{SEC} = 1 << 25; #/* upcall cache */
$subsys->{GSS} = 1 << 26; #/* b_new_cmd */
# /* 1<< 27 unused */
$subsys->{MGC} = 1 << 28;
$usbsys->{MGS} = 1 << 29;
$subsys->{FID} = 1 << 30; #/* b_new_cmd */
$subsys->{FLD} = 1 << 31; #/* b_new_cmd */
$masks->{TRACE} = 1 << 0; # /* ENTRY/EXIT markers */
$masks->{INODE} = 1 << 1; #
$masks->{SUPER} = 1 << 2; #
$masks->{TTY} = 1 << 3; # /* notification printed to TTY */
$masks->{MALLOC} = 1 << 4; # /* print malloc, free information */
$masks->{CACHE} = 1 << 5; # /* cache-related items */
$masks->{INFO} = 1 << 6; # /* general information */
$masks->{IOCTL} = 1 << 7; # /* ioctl related information */
$masks->{NETERROR} = 1 << 8; # /* network errors */
$masks->{NET} = 1 << 9; # /* network communications */
$masks->{WARNING} = 1 << 10; #
$masks->{BUFFS} = 1 << 11; #
$masks->{OTHER} = 1 << 12; #
$masks->{DENTRY} = 1 << 13; #
$masks->{NETTRACE} = 1 << 14; # /* ENTRY/EXIT markers */
$masks->{PAGE} = 1 << 15; # /* bulk page handling */
$masks->{DLMTRACE} = 1 << 16; #
$masks->{ERROR} = 1 << 17; # /* CERROR} = ...) == CDEBUG} = D_ERROR, ...) */
$masks->{EMERG} = 1 << 18; # /* CEMERG} = ...) == CDEBUG} = D_EMERG, ...) */
$masks->{HA} = 1 << 19; # /* recovery and failover */
$masks->{RPCTRACE} = 1 << 20; # /* recovery and failover */
$masks->{VFSTRACE} = 1 << 21;
$masks->{READA} = 1 << 22; #/* read-ahead */
$masks->{MMAP} = 1 << 23;
$masks->{CONFIG} = 1 << 24;
$masks->{CONSOLE} = 1 << 25;
$masks->{QUOTA} = 1 << 26;
$masks->{SEC} = 1 << 27;
$masks->{LFSCK} = 1 << 28;
$masks->{HSM} = 1 << 29;
sub extractpid
{
$line = shift;
# print "$_\n";
if ($line =~ /(\d+)\:(\d+)\:(\d+\.\d+)\:(\d+\.\d+)\:(\d+)\:(\d+)\:.*/) {
return $6;
}
}
sub extracthostpid
{
$line = shift;
# print "$_\n";
if ($line =~ /(\d+)\:(\d+)\:(\d+\.\d+)\:(\d+)\:(\d+)\:(\d+)\:(\d+)\:.*/) {
return $7;
}
}
sub entering_rpc
{
$_ = shift;
$entering_rpc = /Handling RPC/;
if($entering_rpc) {
$oldpid=$pid;
$pid = extractpid($_);
$leaving_rpc = 0;
}
}
sub leaving_rpc
{
$_ = shift;
$leaving_rpc = /Handled RPC/;
if($leaving_rpc) {
$pid = $oldpid;
$entering_rpc = 0;
}
}
sub entering
{
$_ = shift;
$entering = /Process entered/;
}
sub leaving
{
$_ = shift;
$entering = /Process leaving/;
}
sub getsubsys
{
my ($subsys, $mask) = split ":";
return hex($subsys);
}
sub getmask
{
my ($subsys, $mask) = split ":";
return hex($mask);
}
sub setcolor
{
my $linemask = shift;
my $line = shift;
if ($linemask == $masks->{TRACE}) {
if(leaving($line)){
print color("yellow on_black");
} else {
print color("green on_black");
}
}
if ($linemask == $masks->{DLMTRACE}) {
print color("magenta on_black");
}
if ($linemask == $masks->{DLM}) {
print color("magenta on_black");
}
if ($linemask == $masks->{DENTRY}) {
print color("red on_black");
}
}
sub study_lock
{
$_ = shift;
my $rc;
$rc = /client-side enqueue returned a blocked.* ns: (.*) lock: (.*) lrc: (.*) mode/;
if ($rc) {
$completion_callbacks{$1}->{$2} = $3;
# print color("white");
# print "---CP CB START: $1 $2 $3\n";
# print color("reset");
}
$rc = /client-side enqueue:.* ns: (.*) lock: (.*) lrc: (.*) mode/;
if ($rc) {
# print color("white");
# print "---CP CB END: $1 $2 $3 deleting $completion_callbacks{$1}->{$2}\n";
# print color("reset");
delete $completion_callbacks{$1}->{$2};
}
$rc = /client blocking AST callback handler ns: (.*) lock: (.*) lrc: (.*) mode/;
if ($rc) {
$blocking_callbacks{$1}->{$2} = $3;
# print color("white");
# print "---BL CB START: $1 $2\n";
# print color("reset");
}
$rc = /client blocking callback handler END ns: (.*) lock: (.*) lrc: (.*) mode/;
if ($rc) {
# print color("white");
# print "---BL CB END: $1 $2 $3 deleting $blocking_callbacks{$1}->{$2}\n";
# print color("reset");
delete $blocking_callbacks{$1}->{$2};
}
$rc = /ldlm_lock_addref.*ns: (.*) lock: (.*) lrc: (.*) mode/;
# print color("white");
# print "------>addref ns: $1 lock: $2 lrc: $3\n" if ($rc);
# print color("reset");
$locks{$1}->{$2} = {$3} if ($rc);
$rc = /ldlm_lock_decref.*ns: (.*) lock: (.*) lrc: (.*) mode/;
# print color("white");
# print "------>decref ns: $1 lock: $2 lrc: $3\n" if ($rc);
# print color("reset");
$locks{$1}->{$2} = {$3} if ($rc);
}
sub hanging_locks
{
my $found;
my $ns;
foreach (keys %completion_callbacks) {
$ns = $_;
$found = 0;
foreach (keys %{$completion_callbacks{$ns}}) {
if (!$found) {
print "Unfinished completions in ns $ns: \n";
$found =1;
}
print " lock: $_ lrc: $completion_callbacks{$ns}->{$_}\n";
}
}
foreach (keys %blocking_callbacks) {
$ns = $_;
$found = 0;
foreach (keys %{$blocking_callbacks{$ns}}) {
if (!$found) {
print "Unfinished blocking in ns $ns: \n";
$found =1;
}
printf(" lock: $_ lrc: %s\n", $blocking_callbacks{$ns}->{$_});
}
}
}
sub study_intent
{
$_ = shift;
my $rc;
$rc = /D_IT UP dentry (.*) fsdata/;
delete $it{$1} if ($rc);
$rc = /D_IT DOWN dentry (.*) fsdata/;
$it{$1} = "yes" if ($rc);
}
sub unmatched_intents {
my $found;
foreach (keys %it) {
if (!$found) {
print "Unmatched intents: \n";
$found =1;
}
print " $_\n";
}
}
sub usage
{
print "Usage : llanalyze LOGFILE\n";
exit;
}
if ($ARGV[0]) {
if(!open(LOG, "<$ARGV[0]")){
print "Cannot open $ARGV[0]\n";
exit;
}
} else {
usage();
}
$width = 0;
if ($ARGV[1]) {
$width = $ARGV[1];
}
print "nodlm $nodlm, nonet $nonet, trace $trace\n";
print "pid: $pid, dlm_ns: $dlm_ns\n";
print "rpctrace: $rpctrace\n";
print "extract_start: $extract_start\n";
print "extract_end: $extract_end\n";
print "width: $width\n";
while (<LOG>) {
if ($extract_start && $extract_start ne "LLANAYZE_FOUND") {
next if (index($_, $extract_start, 0) == -1);
$extract_start = "LLANAYZE_FOUND";
}
if ($extract_end) {
next if ($extract_end eq "LLANAYZE_FOUND");
if (index($_, $extract_end, 0) != -1) {
$extract_end = "LLANAYZE_FOUND";
}
}
$linepid = extractpid($_);
$linehpid = extracthostpid($_);
$linemask = getmask($_);
$linesubsys = getsubsys($_);
# printf "---> mask %x subsys %x\n", $linemask, $linesubsys;
if (leaving($_)) {
chop $prefix->{$linepid};
chop $prefix->{$linepid};
}
if ($linemask == $masks->{DENTRY}) {
study_intent($_);
}
if ($linemask == $masks->{DLMTRACE}) {
study_lock($_);
}
if ( !$pid || $linepid == $pid || $linehpid == $pid) {
next if ($rpctrace && !$entering_rpc && $linemask != $masks->{RPCTRACE});
next if ($trace && $linemask != $masks->{TRACE});
next if ($nodlm &&
( $linesubsys == $subsys->{LDLM}));
next if ($dlm_ns &&
( $linesubsys != $subsys->{LDLM}));
next if (($found_dlm_ns = index( $_, $dlm_ns, 0)) == -1);
next if ($noclass &&
( $linesubsys == $subsys->{CLASS}));
next if ($nonet &&
( $linesubsys == $subsys->{RPC} ||
$linesubsys == $subsys->{NET} ||
$linesubsys == $subsys->{LNET} ||
$linesubsys == $subsys->{LND}));
if($rpctrace && !$entering_rpc) {entering_rpc($_);}
if($rpctrace && !$leaving_rpc) {leaving_rpc($_);}
# printf "sub/mask: %s - %s\n", getsubsys($_), getmask($_);
if (!$silent) {
setcolor($linemask, $_);
my $string = $prefix->{$linepid}.$_;
if($width){
$string = substr($string, 0, $width)."\n";
}
printf("%s", $string);
print color("reset");
}
# last if $count++ > 100;
}
if (entering($_)) {
$prefix->{$linepid} .= ' ';
}
}
unmatched_intents();
hanging_locks();
# printf "argv %s pid %d\n", $ARGV[0], extractpid($ARGV[0]);
