scripts/trace-master.pl

   1 #!/usr/bin/perl -w
   2 #
   3 ## Copyright (C) 1996-2021 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 sub enterJob {
  73     my ($id) = @_;
  74     my $job = &getJob($id);
  75 }
  76
  77 sub updateJob {
  78     my ($id, $line) = @_;
  79
  80     my $job = &getJob($id);
  81     $job->{history} .= $line;
  82
  83     if ($line =~ /\bFD (\d+)/) {
  84         $job->{fds}->{$1} = 1;
  85     }
  86 }
  87
  88 sub linkJobs {
  89     my ($parentId, $kidId, $line) = @_;
  90
  91     my $parent = $Jobs{$parentId} or die("missing linked job $parentId");
  92     push @{$parent->{kids}}, $kidId;
  93
  94     my $kid = &getJob($kidId);
  95     die("two parents for $kidId: ". $kid->{parent}. " and $parentId") if $kid->{parent};
  96     $kid->{parent} = $parentId;
  97
  98     $kid->{history} .= $line; # birth
  99 }
 100
 101 sub getJob {
 102     my $id = shift;
 103
 104     my $job = $Jobs{$id};
 105     return $job if $job;
 106
 107     $job = {
 108         id => $id,
 109         kids => [],
 110         fds => {},
 111         parent => undef(),
 112         start => undef(),
 113         history => '',
 114         reported => 0,
 115         };
 116
 117     $Jobs{$id} = $job;
 118     return $job;
 119 }
 120
 121
 122 sub reportJob {
 123     my ($id, $recursive) = @_;
 124
 125     my $job = $Jobs{$id} or die("Did not see job$id\n");
 126
 127     # several kids may try to report their common parent
 128     return if $job->{reported};
 129     $job->{reported} = 1;
 130
 131     &reportJob($job->{parent}, 0) if $job->{parent};
 132
 133     &reportJobParam($id, 'parent');
 134     &reportJobParam($id, 'kids', join(', ', @{$job->{kids}}));
 135     &reportJobParam($id, 'FDs', join(', ', keys %{$job->{fds}}));
 136     &reportJobHistory($id);
 137
 138     return unless $recursive;
 139
 140     foreach my $kidId (@{$job->{kids}}) {
 141         &reportJob($kidId, $recursive);
 142     }
 143 }
 144
 145 sub reportJobParam {
 146     my ($id, $name, $value) = @_;
 147     my $job = $Jobs{$id} or die;
 148
 149     $value = $job->{$name} if @_ < 3;
 150     $value = '?' unless defined $value;
 151     $value = "\n$value" if $value =~ /\n/m;
 152     printf("job%d %s: %s\n", $id, $name, $value);
 153 }
 154
 155 sub reportJobHistory {
 156     my ($id) = @_;
 157     my $job = $Jobs{$id} or die;
 158
 159     my $history = $job->{history};
 160     my @lines = split(/\n/, $history);
 161     &reportJobParam($id, 'history', (scalar @lines) . " entries");
 162
 163     foreach my $line (@lines) {
 164         print "$line\n";
 165         print "\n" if $line =~ /[|:] leaving\b/;
 166     }
 167 }