http://www.perlmonks.org?node_id=1041287

Azur has asked for the wisdom of the Perl Monks concerning the following question:

I've got a website using the reverse proxy Varnish. I want to find objects which take more than X seconds to serve. Varnishlog is a small app which on-the-fly outputs Varnish's log, like this:

...
   11 SessionOpen  c 123.234.56.78 63618 123.234.56.89:80
   11 RxURL        c /example.php
   11 RxHeader     c Host: 123.234.56.89
   11 RxHeader     c User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; r
+v:22.0) Gecko/20100101 Firefox/22.0
   11 RxHeader     c Accept-Language: en-US,en;q=0.5
   11 RxHeader     c Accept-Encoding: gzip, deflate
   11 ReqEnd       c 1832330560 1372436083.710740089 1372436083.711302
+519 0.000174284 0.000352383 0.000210047
...

[download]

The interesting line is the ReqEnd one, the fifth group of digits (0.000352383) is the time in seconds it took to serve the object. Searching the net I found this command, which is supposed to extract entries which have taken more than 10 seconds to load:

varnishlog -o -i Backend,RxURL,ReqEnd,RxHeader | perl -ne 'BEGIN { $/=
+ "";} print if (/ReqEnd(?:[\sc]+)\d+\s\d+.\d+\s+\d+.\d+\s+\d+.\d+\s+(
+\d+.\d+)/ and $1 > 10.0)'

[download]

...but it outputs nothing. Can someone help me find the problem with that command?

Replies are listed 'Best First'.
Re: Extracting time from a log
by toolic (Bishop) on Jun 28, 2013 at 17:02 UTC
    The problem is that 0.000352383 (which is stored in $1) is not greater than 10.0. You should also escape all the periods because they have special meaning in regexes (perlre).
[reply]
      1) Yes, that output was just an example of the log format. There are several pages which take 2-3 seconds, but even changing 10.0 to 1 or 0 result in no output. 2)Thank you, I thought as much. However, the command doesn't work any better with the periods escaped:  varnishlog -o -i Backend,RxURL,ReqEnd,RxHeader | perl -ne 'BEGIN { $/= "";} print if (/ReqEnd(?:[\sc]+)\d+\s\d+\.\d+\s+\d+\.\d+\s+\d+\.\d+\s+(\d+\.\d+)/ and $1 > 1.0)'
[reply]
[d/l]
        but even changing 10.0 to 1 or 0 result in no output

        I beg to differ:

        $ echo "   11 SessionOpen  c 123.234.56.78 63618 123.234.56.89:80
   11 RxURL        c /example.php
   11 RxHeader     c Host: 123.234.56.89
   11 RxHeader     c User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; r
+v:22.0) Gecko/20100101 Firefox/22.0
   11 RxHeader     c Accept-Language: en-US,en;q=0.5
   11 RxHeader     c Accept-Encoding: gzip, deflate
   11 ReqEnd       c 1832330560 1372436083.710740089 1372436083.711302
+519 0.000174284 0.000352383 0.000210047" | perl -ne 'BEGIN { $/="";} 
+print if (/ReqEnd(?:[\sc]+)\d+\s\d+\.\d+\s+\d+\.\d+\s+\d+\.\d+\s+(\d+
+\.\d+)/ and $1 > 0)'

        [download]

        Output:

           11 SessionOpen  c 123.234.56.78 63618 123.234.56.89:80
   11 RxURL        c /example.php
   11 RxHeader     c Host: 123.234.56.89
   11 RxHeader     c User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; r
+v:22.0) Gecko/20100101 Firefox/22.0
   11 RxHeader     c Accept-Language: en-US,en;q=0.5
   11 RxHeader     c Accept-Encoding: gzip, deflate
   11 ReqEnd       c 1832330560 1372436083.710740089 1372436083.711302
+519 0.000174284 0.000352383 0.000210047

        [download]

        I changed the 10.0 to 0 and it outputted successfully. Perhaps you are overlooking something?

[reply]
[d/l]
[select]

Back to Seekers of Perl Wisdom