391 lines
12 KiB
Perl
391 lines
12 KiB
Perl
#!/usr/bin/perl -w
|
|
#
|
|
# Generate stats of Cron messages sent to syslog
|
|
#
|
|
#
|
|
# This script can be used to generate per-user and per-task
|
|
# statistics in order to determine how much time do cron tasks take
|
|
# and audit cron use. It might be useful to debug issues related
|
|
# to cron tasks that take too much time to run, or overlap, or get executed
|
|
# too fast..
|
|
#
|
|
# Hint: In some systems, cron tasks might not properly use lockfiles to
|
|
# prevent themselves from being run twice in a row and some "strange"
|
|
# things might happen if the system is overloaded and a cron task takes
|
|
# more than expected. And, no, this is not something that Cron should
|
|
# prevent (for more information see Debian bug #194805).
|
|
#
|
|
# In order for this script to work
|
|
#
|
|
# together with the logging enhancements included
|
|
# in Debian's vixie cron (3.0pl1-95) that make it possible to log
|
|
# when do cron tasks end.
|
|
#
|
|
#
|
|
# How to use:
|
|
# - Modify /etc/init.d/cron so that the calls to cron pass the '-L 2'
|
|
# argument
|
|
# (Hint: change lines 27 and 47 so that they end with '-- -L 2 $LSBNAMES'
|
|
# instead of '-- $LSBNAMES')
|
|
# In Debian you need cron-3.0pl1-95 or later.
|
|
# Note: future versions of cron might use an /etc/default/cron file
|
|
# to provide arguments to cron.
|
|
#
|
|
# - Review /etc/syslog.conf to determine where does the output of the cron
|
|
# facility goes to (might be /var/log/syslog together with other messages
|
|
# but you can also configure syslog to store them at /var/log/cron.log)
|
|
#
|
|
# - Run the script (by default it will read input /var/log/syslog but you
|
|
# can point to other file using the '-f' switch) and review the output
|
|
#
|
|
# - (Optionally) If you want to analyse log files for a long period
|
|
# concatenate different log files, extract all CRON related entries
|
|
# to a file and process that.
|
|
#
|
|
# You could do, for example, this:
|
|
#
|
|
# zcat -f /var/log/syslog* | grep CRON >cron-log ; \
|
|
# perl stats-cron.pl -f cron-log
|
|
#
|
|
#
|
|
# This program is copyright 2006 by Javier Fernandez-Sanguino <jfs@debian.org>
|
|
#
|
|
# This program is free software; you can redistribute it and/or modify
|
|
# it under the terms of the GNU General Public License as published by
|
|
# the Free Software Foundation; either version 2 of the License, or
|
|
# (at your option) any later version.
|
|
#
|
|
# This program is distributed in the hope that it will be useful,
|
|
# but WITHOUT ANY WARRANTY; without even the implied warranty of
|
|
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
|
|
# GNU General Public License for more details.
|
|
#
|
|
# You should have received a copy of the GNU General Public License
|
|
# along with this program; if not, write to the Free Software
|
|
# Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
|
|
#
|
|
# For more information please see
|
|
# http://www.gnu.org/licenses/licenses.html#GPL
|
|
|
|
# TODO:
|
|
# - Print time internal of file analysis (from 'XXX' to 'XXX') based on the
|
|
# first and the last log entry read.
|
|
#
|
|
# - Detect overlaped entries for the same task (start of an entry before the
|
|
# previous one finished)
|
|
#
|
|
# - Make it possible to filter by users
|
|
#
|
|
# - Consider adapting to other log formats (other cron programs? Solaris?) by
|
|
# separating analysis and extraction in the code and making it possible
|
|
# to switch to different analysis methods.
|
|
|
|
|
|
# Required modules
|
|
eval 'use Parse::Syslog';
|
|
if ($@) {
|
|
print STDERR "ERROR: Parse::Syslog not installed, please install this Perl library\n";
|
|
print STDERR "ERROR: (in Debian it is provided by the 'libparse-syslog-perl' package)\n";
|
|
exit 1;
|
|
}
|
|
use Parse::Syslog;
|
|
use Getopt::Std;
|
|
# Parse command line
|
|
getopts('dhvf:');
|
|
$opt_d = 0 if ! defined ($opt_d) ;
|
|
|
|
if ( $opt_h ) {
|
|
print "Usage: $ARGV[0] [-dhv] [-f syslog file]";
|
|
exit 1;
|
|
}
|
|
|
|
# Note: in Debian's default syslog configuration log messages are
|
|
# sent to /var/log/syslog but you might have edited it to use
|
|
# /var/log/cron.log instead. Which, BTW, is more efficient because
|
|
# we do not need to parse the syslog to extract only cron messages.
|
|
my $LOGFILE = $opt_f || "/var/log/syslog";
|
|
|
|
# Sanity checks
|
|
if ( ! -r $LOGFILE ) {
|
|
print STDERR "ERROR: Cannot read logfile $LOGFILE";
|
|
}
|
|
|
|
my $parser = Parse::Syslog->new( $LOGFILE);
|
|
print STDERR "Starting parse of file $LOGFILE\n" if $opt_v;
|
|
while(my $log = $parser->next) {
|
|
if ( $log->{program} =~ /CRON/ ) {
|
|
print STDERR "DEBUG: Found syslog entry: $log->{pid}\n" if $opt_d;
|
|
# We extract the entries with the same text but with 'CMD' (start)
|
|
# and 'END' (end) to check if it's the same we use the PID reported
|
|
# by cron.
|
|
if ($log->{text} =~ /CMD \(/) {
|
|
my $pid;
|
|
if ($log->{text} =~ /\(\[(\d+)\]/ ) {
|
|
# Debian - with loglevel 8, the child process id is
|
|
# reported
|
|
$pid = $1;
|
|
} else {
|
|
# All the other cases, the process ID of the
|
|
# child process is the same one as the log entry
|
|
$pid = $log->{pid};
|
|
}
|
|
add_entry($log->{timestamp},$log->{text},$pid, $log->{pid})
|
|
}
|
|
if ($log->{text} =~ /END \(/) {
|
|
my $pid;
|
|
if ($log->{text} =~ /\(\[(\d+)\]/ ) {
|
|
# Debian - with loglevel 8
|
|
$pid = $1;
|
|
} else {
|
|
# Other cases
|
|
$pid = "UNKNOWN";
|
|
}
|
|
clear_entry($log->{timestamp},$log->{text},$pid,$log->{pid});
|
|
}
|
|
}
|
|
}
|
|
print STDERR "Finished parse of file $LOGFILE\n" if $opt_v;
|
|
|
|
|
|
# Analysis, we find all entries with a start and stop timestamp
|
|
# and print them
|
|
generate_analysis();
|
|
|
|
# Stats:
|
|
# - average time of execution of cron jobs
|
|
# - cronjob which executed slowest
|
|
# - cronjob which executed fastes
|
|
# - cronjobs which start before they finish
|
|
print_stats();
|
|
|
|
exit 0;
|
|
|
|
sub find_user {
|
|
# Extract a user from a cron entry
|
|
my ($text) = @_;
|
|
my $user = "";
|
|
if ( $text =~ /^\((.*?)\)/ ) {
|
|
$user = $1;
|
|
}
|
|
return $user;
|
|
}
|
|
|
|
sub find_prg {
|
|
# Extract a program from a cron entry
|
|
my ($text) = @_;
|
|
my $prg = "";
|
|
if ( $text =~ /(CM|EN)D\s*\((.*)\s*\)\s*$/ ) {
|
|
$prg = $2;
|
|
$prg =~ s/^\[\d+\]\s+//; # Strip off child process numbers
|
|
# (Debian loglevel 8)
|
|
}
|
|
return $prg;
|
|
}
|
|
|
|
sub add_entry {
|
|
# Get a syslog entry and add it to the table of entries for analysis
|
|
my ($time, $text, $pid, $ppid) = @_;
|
|
my ($user, $prg);
|
|
print STDERR "DEBUG: Entering add_entry with @_\n" if $opt_d;
|
|
$user = find_user($text);
|
|
if ( ! defined ($user) ) {
|
|
print STDERR "WARN: Cannot find user for cron job (pid $pid)\n";
|
|
return;
|
|
}
|
|
$prg = find_prg($text);
|
|
if ( ! defined ($prg) ) {
|
|
print STDERR "WARN: Cannot find program for cron job (pid $pid)\n";
|
|
return;
|
|
}
|
|
my $value = $pid."-".$time;
|
|
print STDERR "DEBUG: Adding cronjob of user $user to list: $prg\n" if $opt_d;
|
|
add_cron_entry($user, $prg, $value, $ppid);
|
|
$cron_entries{$user}{$prg}{'count'}++;
|
|
return;
|
|
}
|
|
|
|
sub clear_entry {
|
|
# Get a syslog entry, find the start entry and add the timestamp difference
|
|
# to the list of timestamps for that user
|
|
#
|
|
# There's two ways to match entries:
|
|
# - (in Debian, using loglevel 8): By matching the child process ID
|
|
# between the entries
|
|
# - in all the other cases: By matching the process ID of the
|
|
# END message (which belongs to the parent) with the process IF
|
|
# of the CMD message (which belongs to the child)
|
|
my ($timestamp, $text, $pid, $ppid) = @_;
|
|
my ($user, $prg, $entry, $count);
|
|
my @array; my @stack;
|
|
print STDERR "DEBUG: Entering clear_entry with @_\n" if $opt_d;
|
|
$user = find_user($text);
|
|
if ( $user eq "" ) {
|
|
print STDERR "WARN: Cannot find user for cron job (pid $pid)\n";
|
|
return;
|
|
}
|
|
$prg = find_prg($text);
|
|
if ( $prg eq "" ) {
|
|
print STDERR "WARN: Cannot find program for cron job (pid $pid)\n";
|
|
return;
|
|
}
|
|
if ( ! defined ( $cron_entries{$user}{$prg}{'item'} ) ) {
|
|
print STDERR "WARN: End entry without start entry (pid $pid)\n";
|
|
return;
|
|
}
|
|
@array = split(':', $cron_entries{$user}{$prg}{'item'});
|
|
$count = $#array + 1 ;
|
|
print STDERR "DEBUG: $count cron entries for $user, task '$prg'\n" if $opt_d;
|
|
my $finish = 0;
|
|
while ( $finish == 0 ) {
|
|
$entry = pop @array;
|
|
last if ! defined ($entry) ;
|
|
# Pop all entries and look for one whose pid matches
|
|
my ($spid, $stimestamp) = split ("-", $entry);
|
|
print STDERR "DEBUG: Comparing entry $spid to $pid\n" if $opt_d;
|
|
if ( ( $pid ne "UNKNOWN" && $pid == $spid ) || $ppid-$spid == 1 ) {
|
|
my $timediff = $timestamp-$stimestamp;
|
|
$timediff = 0 if $timediff < 0;
|
|
print STDERR "DEBUG: Entries match, time difference of $timediff\n" if $opt_d ;
|
|
$cron_entries{$user}{$prg}{'finished'}++;
|
|
if (defined ( $cron_times{$user}{$prg} ) ) {
|
|
$cron_times{$user}{$prg} = join(":", $cron_times{$user}{$prg}, $timediff);
|
|
} else {
|
|
$cron_times{$user}{$prg} = $timediff;
|
|
}
|
|
$finish = 1;
|
|
} else {
|
|
print STDERR "DEBUG: Pushing entry $spid into stack\n" if $opt_d;
|
|
push @stack, $entry;
|
|
}
|
|
}
|
|
# Push all remaining entries to the stack
|
|
$cron_entries{$user}{$prg}{'item'}="";
|
|
$count = $#array + 1 ;
|
|
if ($opt_d) {
|
|
print STDERR "DEBUG: Restoring all entries (size: array $count";
|
|
$count = $#stack + 1 ;
|
|
print STDERR ", stack $count)\n";
|
|
}
|
|
print STDERR "DEBUG: Total finished tasks: $cron_entries{$user}{$prg}{'finished'} out of $cron_entries{$user}{$prg}{'count'}\n" if defined $cron_entries{$user}{$prg}{'finished'} && $opt_d;
|
|
print STDERR "DEBUG: Unmatched now: $cron_entries{$user}{$prg}{'item'}\n" if $opt_d;
|
|
while ( $entry = pop @array ) {
|
|
add_cron_entry($user, $prg, $entry);
|
|
}
|
|
while ( $entry = pop @stack ) {
|
|
add_cron_entry($user, $prg, $entry);
|
|
}
|
|
print STDERR "DEBUG: Finish execution of clear_entry\n" if $opt_d;
|
|
return;
|
|
}
|
|
|
|
sub add_cron_entry {
|
|
my ($user, $prg, $entry) = @_;
|
|
if ( defined ($cron_entries{$user}{$prg}) && $cron_entries{$user}{$prg} ne "" ) {
|
|
$cron_entries{$user}{$prg}{'item'} = join(":", $cron_entries{$user}{$prg}{'item'}, $entry);
|
|
} else {
|
|
$cron_entries{$user}{$prg}{'item'} = $entry;
|
|
$cron_entries{$user}{$prg}{'count'} = 0;
|
|
$cron_entries{$user}{$prg}{'finished'} = 0;
|
|
$cron_entries{$user}{$prg}{'unmatched'} = 0 ;
|
|
$cron_entries{$user}{$prg}{'average'} = 0 ;
|
|
$cron_entries{$user}{$prg}{'minimum'} = 0 ;
|
|
$cron_entries{$user}{$prg}{'maximum'} = 0;
|
|
}
|
|
}
|
|
|
|
sub count_unmatched {
|
|
my ($user, $prg) = @_;
|
|
my ($count, @array);
|
|
return 0 if ! defined ( $cron_entries{$user}{$prg}{'item'} );
|
|
@array = split(':', $cron_entries{$user}{$prg}{'item'});
|
|
$count = $#array + 1 ;
|
|
return $count;
|
|
}
|
|
|
|
sub find_average {
|
|
my ($user, $prg) = @_;
|
|
my ($average, $count, $total, @array, $entry);
|
|
$total = 0 ;
|
|
return -1 if ! defined ( $cron_times{$user}{$prg} );
|
|
@array = split(':', $cron_times{$user}{$prg});
|
|
$count = $#array + 1 ;
|
|
while ( defined ( $entry = pop @array ) ) {
|
|
$total += $entry;
|
|
}
|
|
$average = $total / $count;
|
|
return $average;
|
|
}
|
|
|
|
sub find_minimum {
|
|
my ($user, $prg) = @_;
|
|
my ($minimum, @array, $entry);
|
|
$minimum = -1;
|
|
return -1 if ! defined ( $cron_times{$user}{$prg} );
|
|
@array = split(':', $cron_times{$user}{$prg});
|
|
while ( defined ( $entry = pop @array ) ) {
|
|
if ( $minimum == -1 ) {
|
|
$minimum = $entry;
|
|
} else {
|
|
$minimum = $entry if $entry < $minimum;
|
|
}
|
|
}
|
|
return $minimum;
|
|
}
|
|
|
|
sub find_maximum {
|
|
my ($user, $prg) = @_;
|
|
my ($maximum, @array);
|
|
$maximum = -1;
|
|
return -1 if ! defined ( $cron_times{$user}{$prg} );
|
|
@array = split(':', $cron_times{$user}{$prg});
|
|
while ( defined ( $entry = pop @array ) ) {
|
|
if ( $maximum == -1 ) {
|
|
$maximum = $entry ;
|
|
} else {
|
|
$maximum = $entry if $entry > $maximum;
|
|
}
|
|
}
|
|
return $maximum;
|
|
}
|
|
|
|
|
|
|
|
sub generate_analysis {
|
|
# For each user and program calculate the average time for the task
|
|
my ($user, $prg);
|
|
foreach $user (keys %cron_entries) {
|
|
print STDERR "DEBUG: Calculating data for user '$user'\n" if $opt_d;
|
|
foreach my $prg ( keys %{$cron_entries{$user}} ) {
|
|
print STDERR "DEBUG: Calculating data for task '$prg'\n" if $opt_d;
|
|
my $unmatched = count_unmatched($user, $prg);
|
|
my $average = find_average($user, $prg);
|
|
my $minimum = find_minimum($user, $prg);
|
|
my $maximum = find_maximum($user, $prg);
|
|
$cron_entries{$user}{$prg}{'unmatched'} = $unmatched;
|
|
$cron_entries{$user}{$prg}{'average'} = $average;
|
|
$cron_entries{$user}{$prg}{'minimum'} = $minimum;
|
|
$cron_entries{$user}{$prg}{'maximum'} = $maximum;
|
|
}
|
|
}
|
|
}
|
|
|
|
sub print_stats {
|
|
# Print information of cron statistics
|
|
my ($user, $prg);
|
|
foreach $user (keys %cron_entries) {
|
|
print "Cron statistics for user '$user'\n";
|
|
foreach $prg ( keys %{$cron_entries{$user}} ) {
|
|
print "\tTask: '$prg'\n";
|
|
print "\t\tDEBUG: $cron_times{$user}{$prg}\n" if $opt_d;
|
|
print <<EOF
|
|
\t\tTotal: $cron_entries{$user}{$prg}{'count'}
|
|
\t\tFinished: $cron_entries{$user}{$prg}{'finished'}
|
|
\t\tUnmatched: $cron_entries{$user}{$prg}{'unmatched'}
|
|
\t\tAvg time: $cron_entries{$user}{$prg}{'average'}
|
|
\t\tMin time: $cron_entries{$user}{$prg}{'minimum'}
|
|
\t\tMax time: $cron_entries{$user}{$prg}{'maximum'}
|
|
EOF
|
|
}
|
|
}
|
|
}
|