scripts/trace-master.pl

   1 #!/usr/bin/perl -w
   2 #
   3 ## Copyright (C) 1996-2018 The Squid Software Foundation and contributors
   4 ##
   5 ## Squid software is distributed under GPLv2+ license and includes
   6 ## contributions from numerous individuals and organizations.
   7 ## Please see the COPYING and CONTRIBUTORS files for details.
   8 ##
   9
  10 # Reads cache.log and displays lines that correspond to the master transaction
  11 # that has a given async job. Master transaction is all activities tied to a
  12 # a single received HTTP request (client side, ACL, ICAP, server side, etc.).
  13 #
  14 # See trace-job.pl for tracing a single job instead of all jobs related to
  15 # a master transaction.
  16 #
  17 # Currently, many master transaction activities are not tracked because they
  18 # do not use AsyncJob API. Eventually, most activities should be identifiable.
  19 #
  20 # Currently, the script reads and remembers all master transactions because it
  21 # does not know which one should be tracked in advance. Eventually, we may
  22 # have a more efficient way of tying master transaction to a job.
  23 #
  24
  25
  26 use strict;
  27 use warnings;
  28
  29 my @InterestingJobs = @ARGV or die("usage: $0 <job id> ...\n");
  30
  31 my %Jobs = ();
  32
  33 my $inside = 0;
  34 my $entering;
  35
  36 while (<STDIN>) {
  37         $entering = $_ if !$inside && /[|:] entering\b/;
  38         undef $entering if /[|:] leaving\b/;
  39
  40         if (!$inside && /\bstatus in\b.*\b(?:async|job|icapx)(\d+)\b/o) {
  41                 $inside = $1;
  42                 &enterJob($inside);
  43                 &updateJob($inside, $entering) if defined $entering;
  44                 undef $entering;
  45         }
  46         elsif (!$inside && /\b(?:async|job|icapx)(\d+)\b/o) {
  47                 updateJob($1, "$_\n"); # isolated line
  48         }
  49
  50         next unless $inside;
  51
  52         &updateJob($inside, $_);
  53
  54         if (/AsyncJob constructed.*\[\S+?(\d+)\]/) {
  55                 &linkJobs($inside, $1, $_);
  56         }
  57
  58         if (/[|:] leaving\b/) {
  59                 $inside = 0;
  60         }
  61 }
  62
  63 foreach my $id (@InterestingJobs) {
  64         # Squid uses asyncNNN, jobNNN, icapxNNN for the same job/transaction
  65         $id =~ s/^(?:async|job|icapx)(\d+)$/$1/;
  66         reportJob($id, 1);
  67 }
  68
  69 exit(0);
  70
  71
  72
  73 sub enterJob {
  74         my ($id) = @_;
  75         my $job = &getJob($id);
  76 }
  77
  78 sub updateJob {
  79         my ($id, $line) = @_;
  80
  81         my $job = &getJob($id);
  82         $job->{history} .= $line;
  83
  84         if ($line =~ /\bFD (\d+)/) {
  85                 $job->{fds}->{$1} = 1;
  86         }
  87 }
  88
  89 sub linkJobs {
  90         my ($parentId, $kidId, $line) = @_;
  91
  92         my $parent = $Jobs{$parentId} or die("missing linked job $parentId");
  93         push @{$parent->{kids}}, $kidId;
  94
  95         my $kid = &getJob($kidId);
  96         die("two parents for $kidId: ". $kid->{parent}. " and $parentId") if $kid->{parent};
  97         $kid->{parent} = $parentId;
  98
  99         $kid->{history} .= $line; # birth
 100 }
 101
 102 sub getJob {
 103         my $id = shift;
 104
 105         my $job = $Jobs{$id};
 106         return $job if $job;
 107
 108         $job = {
 109                 id => $id,
 110                 kids => [],
 111                 fds => {},
 112                 parent => undef(),
 113
 114                 start => undef(),
 115                 history => '',
 116
 117                 reported => 0,
 118         };
 119
 120         $Jobs{$id} = $job;
 121         return $job;
 122 }
 123
 124
 125 sub reportJob {
 126         my ($id, $recursive) = @_;
 127
 128         my $job = $Jobs{$id} or die("Did not see job$id\n");
 129
 130         # several kids may try to report their common parent
 131         return if $job->{reported};
 132         $job->{reported} = 1;
 133
 134         &reportJob($job->{parent}, 0) if $job->{parent};
 135
 136         &reportJobParam($id, 'parent');
 137         &reportJobParam($id, 'kids', join(', ', @{$job->{kids}}));
 138         &reportJobParam($id, 'FDs', join(', ', keys %{$job->{fds}}));
 139         &reportJobHistory($id);
 140
 141         return unless $recursive;
 142
 143         foreach my $kidId (@{$job->{kids}}) {
 144                 &reportJob($kidId, $recursive);
 145         }
 146 }
 147
 148 sub reportJobParam {
 149         my ($id, $name, $value) = @_;
 150         my $job = $Jobs{$id} or die;
 151
 152         $value = $job->{$name} if @_ < 3;
 153         $value = '?' unless defined $value;
 154         $value = "\n$value" if $value =~ /\n/m;
 155         printf("job%d %s: %s\n", $id, $name, $value);
 156 }
 157
 158 sub reportJobHistory {
 159         my ($id) = @_;
 160         my $job = $Jobs{$id} or die;
 161
 162         my $history = $job->{history};
 163         my @lines = split(/\n/, $history);
 164         &reportJobParam($id, 'history', (scalar @lines) . " entries");
 165
 166         foreach my $line (@lines) {
 167                 print "$line\n";
 168                 print "\n" if $line =~ /[|:] leaving\b/;
 169         }
 170 }