BUG - No immediate exit when pipeing ra output
Carter Bullard
carter at qosient.com
Wed May 25 11:15:29 EDT 2011
OK, so I did a little research. Under Linux, when writing to a pipe that has closed,
printf() or fprint(stdout, ) do not return any kind of indication that no one is listening.
Linux generates a SIGPIPE, which is good, but, fprintf(stdout, str) returns that it wrote
strlen(str) bytes. This is a difference between, Unix, Solaris, SunOS, BSD, Windows,
Mach, AIX, UniCOS, SGUX, RTOS, VxWorks, POSIX, and ...... Linux.
When you ignore SIGPIPE, system calls are suppose to return -1. printf() and fprintf()
are not system calls, but on all the systems other than Linux, printf and fprint(stdout,)
return 0, or an error code. Linux doesn't do this.
We historically have ignored SIGPIPE, as we have a number of variations of output,
multiple output files, with one being stdout, multiple output strategies, some using
sockets. SIGPIPE would generate different outcomes, depending on the output
strategy. Exit on some, close the output and wait on others, etc ....... When you get a
SIGPIPE, you don't necessarily know which socket, whatever generated it, so better
to ignore it, and then handle all the different conditions separately.
With this condition, I'll have to investigate how to turn on SIGPIPE. I know, seems
convoluted, but this is one of the issues with portability. Whose at fault here, Linux,
not returning 0, or me for ignoring SIGPIPE when writing to stdout?
Should have something today.
Carter
On May 25, 2011, at 7:43 AM, elof2 at sentor.se wrote:
>
> Hi Carter.
> I have some unfortunate news.
>
> Ra Version 3.0.5.11 still won't terminate swiftly upon pipe closure on linux:
>
> time ra -nr argus2.log | head -1
> real 0m6.984s
> user 0m6.708s
> sys 0m0.284s
>
> /Elof
>
>
> On Wed, 18 May 2011, elof2 at sentor.se wrote:
>
>>
>> Hi Carter!
>> It seems that the bugfix to detect closure of the pipe still have issues, at least on linux.
>>
>> I've compiled argus-clients 3.0.5.10 on both linux and FreeBSD.
>>
>> On FreeBSD, ra immediately terminates on pipe closure.
>> On linux however, ra keep processing the entire input file(s) even though the pipe has closed.
>>
>> Examples:
>>
>> FreeBSD:
>> time ra -r argus.log | grep -q "^."
>> real 0m0.015s
>> user 0m0.009s
>> sys 0m0.007s
>>
>> Linux:
>> time ra -r argus.log | grep -q "^."
>> real 0m6.555s
>> user 0m6.284s
>> sys 0m0.284s
>>
>>
>>
>> As a comparison, here is the time to process the entire argus.log:
>>
>> FreeBSD:
>> time ra -r argus-.log > /dev/null
>> real 0m5.909s
>> user 0m5.804s
>> sys 0m0.108s
>>
>> Linux:
>> time ra -r argus.log > /dev/null
>> real 0m6.461s
>> user 0m6.204s
>> sys 0m0.256s
>>
>>
>> Conclusion:
>> Both FreeBSD and Linux take approx 6 seconds to parse the entire logfile.
>> On FreeBSD, pipe closure is detected correctly and ra terminates after approx 0.015s. Good.
>> On linux, pipe closure seem not to be detected at all, and the *entire* file is processed. Ra terminates after approx 6s.
>> (if the logfile is huge, it takes a loooong time before the ra process terminates)
>>
>>
>> Please let me know if I can help with any additional details to solve this.
>>
>> /Elof
>>
>>
>>
>> On Wed, 11 May 2011, Carter Bullard wrote:
>>
>>> On my laptop, I am getting about 250K records per sec throughput with ra(), which is a lot of records per day, but, it's not 1M records per sec, so there is room for improvement.
>>> There is something in initialization that is very slow, and I'll look at it. strace() may show what it is.
>>> Carter
>>> On May 11, 2011, at 4:47 AM, elof2 at sentor.se wrote:
>>>> On Tue, 10 May 2011, Carter Bullard wrote:
>>>>> Not sure where the 288 files == 24 hours?
>>>> For example I have a directory with 288 argus-files. Each file hold 5 minutes worth of data. I.e. 288*5min=1440min=24h.
>>>> That was just an example to illustrate that if I want to perform some action on the argus data for this day, the shortest execution time even if I use -qN1 will be 0.40s using ra v3, where ra v2 take 0.008s.
>>>> Even though 0.40s is not a long time, it is 50 times longer than 0.008s.
>>>> This is not a biggie, I just wanted to inform you about the big difference between v2 and v3.
>>>>> 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 tried this just now. No change. The unthreaded ra still take 0.40s just to start and exit.
>>>> time ra -qN1 -r argus1.log ... argus288.log
>>>> real 0m0.406s
>>>> user 0m0.220s
>>>> sys 0m0.192s
>>>> As I said, not a biggie. Just FYI.
>>>>> I'll checkout why we may be processing all the input files if the output pipe closes.
>>>> Thanks! In my opinion this is a biggie.
>>>> /Elof
>>>>> 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
>>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 4367 bytes
Desc: not available
URL: <https://pairlist1.pair.net/pipermail/argus/attachments/20110525/f96bd435/attachment.bin>
More information about the argus
mailing list