Re: removeheaders

Mike Cappella wrote:
>>> The diff below corrects these issues. I've only tested it with data 
>>> that matches the first expression.
> 
> I think the removeheaders optimization you posted can be further reduced...

Actually the patch I posted was broken, and a reflection of my limited 
test data. It incorrectly handles the Solaris format because it short 
circuits on the first match, which is the simpler expression to extract 
the date-host-service: portion.

(BTW, any thoughts on writing unit tests for these scripts?)


> potentially avoiding calling the RE generator twice for non-matching lines...

The only good way to answer these questions is to benchamark the 
variations, which I've done below.

Here are the subroutines and what they represent:

rh1 # original
rh2 # reduced (your version)
rh3 # consolidated (3 REs consolidated to 1)
rh4 # consolidated + validation
rh5 # optimized for speed (minimal use of RE)

They were ran against the 3 different log line formats, with a sample 
log line printed before the benchmark results (the left column is 
ordered from slowest to fastest):

Jun 24 06:58:11 host service[2531]: message
         Rate  rh2  rh4  rh1  rh3  rh5
rh2 207039/s   --  -4%  -8%  -8% -27%
rh4 214592/s   4%   --  -4%  -5% -24%
rh1 224215/s   8%   4%   --  -1% -21%
rh3 225734/s   9%   5%   1%   -- -21%
rh5 284091/s  37%  32%  27%  26%   --

Jun 24 06:48:54 host syslogd 1.4.1#18: restart (remote reception).
         Rate  rh2  rh4  rh1  rh3  rh5
rh2 211416/s   --  -3%  -4%  -7% -26%
rh4 218818/s   4%   --  -1%  -4% -23%
rh1 221239/s   5%   1%   --  -3% -22%
rh3 228311/s   8%   4%   3%   -- -20%
rh5 284900/s  35%  30%  29%  25%   --

Jun 24 06:48:54 host service[2531]: [ID 1234 word.word] Solaris message
         Rate rh2 rh5 rh3 rh4 rh1
rh2 165837/s  -- -1% -3% -3% -7%
rh5 168350/s  2%  -- -2% -2% -6%
rh3 171233/s  3%  2%  -- -0% -4%
rh4 171527/s  3%  2%  0%  -- -4%
rh1 178571/s  8%  6%  4%  4%  --


In all cases rh2 (reduced) actually ends up being the slowest.

In the first two (supposedly most common) cases, the original is the 
second slowest.

The overall speed winner, rh5, which is ~30% faster than the original on 
the most common log line format, takes a quick-and-dirty approach, and 
makes minimal use of regular expressions in exchange for performing the 
least validation of the data.

On the "no colon" data, rh5 also produces different results from the 
other methods:

Jun 24 06:48:54 host syslogd 1.4.1#18: restart (remote reception).
rh1:  restart (remote reception).
rh2:  restart (remote reception).
rh3:  restart (remote reception).
rh4:  restart (remote reception).
rh5:  1.4.1#18: restart (remote reception).

Note how it isn't stripping off the syslog version. I'm not entirely 
sure which way is actually more correct. It seems arguable to me that 
the version number is part of the log message and should be included.

The original code appeared to be somewhat sloppy in the validation it 
was performing. If you consider this RE:

s/^... .. ..:..:.. [^ ]* [^\[:]*(\[\d*\])?: //

it's saying that the dates can be composed of any characters, as long as 
they have the right number of characters and the spaces and colons in 
the right place, and that the host name and service name can be zero 
length. That doesn't seem right. But maybe things are checked more 
rigorously upstream.

I'd say if validation was happening upstream, I'd use rh5, otherwise I'd 
probably pick rh4, which maximizes validation, and I'd add in error 
handling code to warn about lines that don't match. Though this ends up 
being about the same performance as the original (+/-2%).

Benchmark script attached. Feel free to try your own variations.

Of course now that we've optimized this, I'd like to voice my agreement 
with a comment made recently that dates and other "header" information 
should probably not get stripped off before handing the data to the 
service filter. As I noted in another message, having a common 
intermediate log format would permit building an infrastructure for 
doing common things, like splitting a line into a standard set of 
components (date, host, service, PID, message), making the job of the 
service filter just as easy, wile still giving it access to the greater 
detail if it needs it.

  -Tom

-- 
Tom Metro
Venture Logic, Newton, MA, USA
"Enterprise solutions through open source."
Professional Profile: http://tmetro.venturelogic.com/

_______________________________________________
Logwatch-Devel mailing list
[email protected]
http://www2.list.logwatch.org:81/mailman/listinfo/logwatch-devel

#!/usr/bin/perl

use Benchmark qw(:all);
#use strict;

my $line1 = 'Jun 24 06:58:11 host service[2531]: message';
my $line2 = 'Jun 24 06:48:54 host syslogd 1.4.1#18: restart (remote reception).';
my $line3 = 'Jun 24 06:48:54 host service[2531]: [ID 1234 word.word] Solaris message';


# original
sub rh1 {
    $_ = shift;

    s/^... .. ..:..:.. [^ ]* [^\[:]*(\[\d*\])?: \[ID \d+( \w+\.\w+)?] //;
    s/^... .. ..:..:.. [^ ]* [^\[:]*(\[\d*\])?: //;
    s/^... .. ..:..:.. [^ ]* //;
    return $_;
}

# reduced
sub rh2 {
    $_ = shift;

    if (s/^... .. ..:..:.. [^ ]* //) {     # Strip date, time, service
        if (s/^[^\[:]*(?:\[\d*\])?: //) {  # ":" after service name may not exist
            s/^\[ID \d+(?: \w+\.\w+)?] //; # Strip Solaris ID tag style -mgt
        }
    }
    return $_;
}

# consolidated
sub rh3 {
    $_ = shift;

    s/^... .. ..:..:.. [^ ]* ([^\[:]*(\[\d*\])?: )?(\[ID \d+( \w+\.\w+)?] )?//;
    return $_;
}

# consolidated + validation
sub rh4 {
    $_ = shift;

    s/^\w\w\w \d\d \d\d:\d\d:\d\d [^ ]+ ([^\[:]+(\[\d+\])?: )?(\[ID \d+( \w+\.\w+)?] )?//o;
    return $_;
}

# optimized for speed
sub rh5 {
    $_ = shift;

    $_ = substr($_,16);
    $_ = (split(' ',$_,3))[2];

    s/^\[ID \d+( \w+\.\w+)?] //;
    return $_;
}


# demo
foreach my $line ($line1,$line2,$line3) {
    print "$line\n";
    print "rh1:  ", rh1($line), "\n";
    print "rh2:  ", rh2($line), "\n";
    print "rh3:  ", rh3($line), "\n";
    print "rh4:  ", rh4($line), "\n";
    print "rh5:  ", rh5($line), "\n";
    print "\n";
}

# benchmark
my $count = 1000000;

foreach my $line ($line1,$line2,$line3) {
    print "$line\n";
    cmpthese($count, {
        'rh1' => sub {rh1($line)},
        'rh2' => sub {rh2($line)},
        'rh3' => sub {rh3($line)},
        'rh4' => sub {rh4($line)},
        'rh5' => sub {rh5($line)},
    });
    print "\n";
}