Crew,
I reposrted this speed issue before, but despite very
intensive debugging and testing, we have not found an external cause (meaning:
not sniffer) for the following:
When I use sniffer without the persisten flag, I get
this log:
h0t861s4 20040520214718 md50000845369.msg 125 16 Clean 0 0 0 2844 40
h0t861s4 20040520214718 md50000845370.msg 110 15 Clean 0 0 0 2747 36
h0t861s4 20040520214804 md50000845371.msg 109 16 Match 109406 62 43 93 43
h0t861s4 20040520214804 md50000845371.msg 109 16 Match 115560 58 2286 2307 43
h0t861s4 20040520214804 md50000845371.msg 109 16 Final 115560 58 0 3580 43
h0t861s4 20040520214825 md50000845372.msg 110 15 Match 29048 52 2757 2788 46
h0t861s4 20040520214825 md50000845372.msg 110 15 Match 122523 52 2930 2942 46
h0t861s4 20040520214825 md50000845372.msg 110 15 Match 122017 52 2968 2977 46
h0t861s4 20040520214825 md50000845372.msg 110 15 Match 122016 52 3346 3355 46
h0t861s4 20040520214825 md50000845372.msg 110 15 Final 29048 52 0 5504 46
h0t861s4 20040520214718 md50000845370.msg 110 15 Clean 0 0 0 2747 36
h0t861s4 20040520214804 md50000845371.msg 109 16 Match 109406 62 43 93 43
h0t861s4 20040520214804 md50000845371.msg 109 16 Match 115560 58 2286 2307 43
h0t861s4 20040520214804 md50000845371.msg 109 16 Final 115560 58 0 3580 43
h0t861s4 20040520214825 md50000845372.msg 110 15 Match 29048 52 2757 2788 46
h0t861s4 20040520214825 md50000845372.msg 110 15 Match 122523 52 2930 2942 46
h0t861s4 20040520214825 md50000845372.msg 110 15 Match 122017 52 2968 2977 46
h0t861s4 20040520214825 md50000845372.msg 110 15 Match 122016 52 3346 3355 46
h0t861s4 20040520214825 md50000845372.msg 110 15 Final 29048 52 0 5504 46
which
looks good (total execution time about 125ms)
When I
have a persistent version running (max 50 ms polling time), I
get:
h0t861s4 20040520214841 md50000845373.msg 0 16 Clean 0 0 0 3597 53
h0t861s4 20040520214852 md50000845374.msg 16 31 Match 119377 62 684 741 38
h0t861s4 20040520214852 md50000845374.msg 16 31 Final 119377 62 0 3810 38
h0t861s4 20040520215115 md50000845375.msg 0 31 Match 29081 63 2413 2432 44
h0t861s4 20040520215115 md50000845375.msg 0 31 Final 29081 63 0 9458 44
h0t861s4 20040520215134 md50000845376.msg 0 94 Clean 0 0 0 24370 42
h0t861s4 20040520215320 md50000845377.msg 47 15 Clean 0 0 0 1945 35
h0t861s4 20040520214852 md50000845374.msg 16 31 Match 119377 62 684 741 38
h0t861s4 20040520214852 md50000845374.msg 16 31 Final 119377 62 0 3810 38
h0t861s4 20040520215115 md50000845375.msg 0 31 Match 29081 63 2413 2432 44
h0t861s4 20040520215115 md50000845375.msg 0 31 Final 29081 63 0 9458 44
h0t861s4 20040520215134 md50000845376.msg 0 94 Clean 0 0 0 24370 42
h0t861s4 20040520215320 md50000845377.msg 47 15 Clean 0 0 0 1945 35
Which
are very good exec times (average 45 ms).
We
have created our own program that does lots of spam checking for messages. At
some point, it fires Sniffer. We log the time it takes for Sniffer to run, for
statistical purposes. When sniffer is NOT persistent, I get the following log
snippet (same messages as 1st sniffer log above, the second number after the
.msg is the time it takes for sniffer to run):
0,"2004-05-20
23:47:18",md50000845369.msg,172,157,0,15,15,0,43406,2
0,"2004-05-20 23:47:18",md50000845370.msg,172,156,16,0,0,0,43309,2
0,"2004-05-20 23:48:04",md50000845371.msg,188,172,0,15,0,15,3578,1
0,"2004-05-20 23:48:25",md50000845372.msg,186,156,14,0,0,0,5572,1
0,"2004-05-20 23:47:18",md50000845370.msg,172,156,16,0,0,0,43309,2
0,"2004-05-20 23:48:04",md50000845371.msg,188,172,0,15,0,15,3578,1
0,"2004-05-20 23:48:25",md50000845372.msg,186,156,14,0,0,0,5572,1
Average time to run sniffer is 160 ms (sniffer said 125 ms). That means,
sniffer can't report about 35 ms which is normal for application
startup and shutdown (also the log is written _after_ the exec time calculation
has been made, file operations also take time).
But,
now comes the big mystery: when persistent mode is ON, it takes a lot more time
to execute (while max polling is only 50ms!)
0,"2004-05-20
23:48:41",md50000845373.msg,827,812,15,0,0,0,3607,1
0,"2004-05-20 23:48:52",md50000845374.msg,842,812,0,0,0,0,3833,1
0,"2004-05-20 23:51:15",md50000845375.msg,936,874,0,0,0,0,9560,1
0,"2004-05-20 23:51:35",md50000845376.msg,889,859,15,0,0,0,26387,0
0,"2004-05-20 23:53:21",md50000845377.msg,937,922,0,15,0,15,1922,0
0,"2004-05-20 23:48:52",md50000845374.msg,842,812,0,0,0,0,3833,1
0,"2004-05-20 23:51:15",md50000845375.msg,936,874,0,0,0,0,9560,1
0,"2004-05-20 23:51:35",md50000845376.msg,889,859,15,0,0,0,26387,0
0,"2004-05-20 23:53:21",md50000845377.msg,937,922,0,15,0,15,1922,0
Which
averages at 850 ms! While I expected 45 + 25 ms (to compensate for average
waiting time) = 70 ms!
Pete,
could you please check why this is happening (particularly in code OUTSIDE
what's measured and logged)? I you can't find anything, I'll ask my collegue to
come up with a timing program, which I would like to release on this list so
other ppl can check how long it really takes to execute sniffer (measured from
'the outside').
Regards,
ing. Michiel Prins
SOS Small Office
Solutions / REJECT
Wannepad 27
1066
HW Amsterdam
tel. 020-4082627
fax. 020-4082628
----------------------------------------
Spamvrije zakelijke
e-mail? reject.nl!
----------------------------------------
Consultancy - Installation - Maintenance
Network Security
- Project Management
Software Development
- Internet - E-mail
----------------------------------------
