BUG - No immediate exit when pipeing ra output

[Carter Bullard]

Not sure where the 288 files == 24 hours?
ra() is threaded, and may read most of the file in before it starts to write any output.  You could remove the threads and see if it picks up.
   % ./configure --without-threads; make clean; make

I'll checkout why we may be processing all the input files if the output pipe closes.
Some of the overhead relates to initializing hostname structures, port names, protocol labels, etc...  It's pretty expensive.  If you didn't have to print the records, it would go really fast.

Carter

On May 10, 2011, at 11:43 AM, elof2 at sentor.se wrote:

> 
> Hi Carter!
> 
> It seems that the bugfix to detect closure of the pipe still have issues.
> 
> In ra v2.x I was used to having the ra command terminate in 0.004s.
> With the new ra 3.0.5.8, it won't terminate as swiftly.
> 
> ra v3.0.5.8:
> time ra -nr argus.log - > /dev/null
> real    0m4.499s
> user    0m4.288s
> sys     0m0.212s
> Time to parse through 100% of this test-file is apparently ~4.5s.
> 
> 
> Now lets see the time when grep or head terminates directly on the first line:
> time ra -nr argus.log - | grep -q "."
> real    0m4.562s
> user    0m4.392s
> sys     0m0.176s
> time ra -nr argus.log - | head -1
> real    0m4.588s
> user    0m4.428s
> sys     0m0.168s
> 
> Both commands take the full 4.5s (plus a little more) to finish.
> 
> If I add another (or the same) logfile, it will double the execution time:
> time ra -nr argus.log argus.log - | head -1
> real    0m9.002s
> user    0m8.617s
> sys     0m0.392s
> 
> Conclusion:
> ra 3.0.5.8 don't immediately terminate upon pipe closure.
> 
> 
> 
> Speaking of latency and execution times...
> 
> Even when using the builtin -N1 option, ra v2 is way faster than v3:
> ra v2.x:
> time ra -N1 -nr argus.log -
> real    0m0.003s
> user    0m0.000s
> sys     0m0.000s
> 
> ra 3.0.5.8:
> real    0m0.024s
> user    0m0.000s
> sys     0m0.021s
> 
> v3 is 8 times slower than v2 when it comes to swift termination.
> Can this be improved?
> 
> 
> Also, no matter how many files I add to ra v2, it still terminates after 0.003 seconds where as ra v3 will increase its 0.024s by approx 0.002 per file:
> ra v2.x:
> time ra -N1 -nr argus.log argus.log argus.log argus.log argus.log argus.log argus.log argus.log argus.log argus.log -
> real    0m0.003s  <-  still 0.003s
> user    0m0.000s
> sys     0m0.002s
> 
> ra 3.0.5.8:
> real    0m0.032s  <-  increases more and more for every file added
> user    0m0.007s
> sys     0m0.024s
> 
> If you have 288 argus files in a log dir and use ra -nr argus*.log to do some simple processing, you will always have a noticeable lag just for the sake of the 288 files, even if you use -N1. Can this be improved to be as swift as v2?
> (288 files á 5 minutes = 24 hours)
> 
> /Elof
> 
> 
> On Fri, 29 Apr 2011, Carter Bullard wrote:
> 
>> Hey Elof,
>> I have the closed piped issue fixed now.  Its a small fix in every client, so you should wait to get a new client release.
> 
>> Carter
> 
> 
> 
>>>>> Two examples using the old ra v2.x :
>>>>> 
>>>>> 1)
>>>>> time ra -Zb -nr argus.log - ip | head -1
>>>>> 04-27-11 23:54:00.925018  s        tcp             10.10.10.10.46382 ->   20.20.20.20.1503   5467  5550  967561   2559850     PA_PA
>>>>> 
>>>>> real    0m0.004s
>>>>> user    0m0.000s
>>>>> sys     0m0.000s
>>>>> 
>>>>> 
>>>>> 2)
>>>>> time ra -Zb -nr argus-20110428.log - ip | grep -q "PA_PA$"
>>>>> 
>>>>> real    0m0.004s
>>>>> user    0m0.000s
>>>>> sys     0m0.000s
>>>>> 
>>>>> 
>>>>> Both examples only take 0.004s to execute.
>>>>> Good!
>>>>> 
>>>>> 
>>>>> 
>>>>> Now I try the same using ra v3 :
>>>>> 
>>>>> 1)
>>>>> time ra -Zb -nr argus.log - ip | head -1
>>>>> 04-27-11 23:54:00.925018  s        tcp             30.30.30.30.32451 ->   40.40.40.40.25    52  97  1151   12274     PA_PA
>>>>> 
>>>>> real    0m50.043s
>>>>> user    0m48.171s
>>>>> sys     0m1.892s
>>>>> 
>>>>> 
>>>>> 2)
>>>>> time ra -Zb -nr argus-20110429.13.log - ip | grep -q "PA_PA$"
>>>>> 
>>>>> real    0m50.161s
>>>>> user    0m48.103s
>>>>> sys     0m2.068s
>>>>> 
>>>>> 
>>>>> The commands take 50 seconds (!!!) to complete when they should have taken approx 0.004 seconds.
>>>>> 
>>>>> The argus.log file is 96 MB and hold 828 372 rows of data.
>>>>> (The larger the file, the longer I have to wait until the command terminates. If I have an old argus.log holding 24 hours of data, it will take ~30 minutes to parse it (even longer if it is bzipped))
>>>>> 
>>>>> 
>>>>> It takes 50 seconds just to parse through 100% of the file:
>>>>> time ra -nr argus.log - ip > /dev/null
>>>>> 
>>>>> real    0m50.257s
>>>>> user    0m48.599s
>>>>> sys     0m1.596s