[sniffer] Re: IP Change on rulebase delivery system
On 2013-03-28 12:10, Richard Stupek wrote: Ok looking at the log I see quite a few messages taking over a second to process (samples below): s u='20130328155503' m=\temp\1332407477322.msg' s='0' r='0' p s='1172' t='1109' l='72697' d='127'/ g o='0' i='12.130.136.172' t='u' c='0.486243' p='-0.625' r='Normal'/ /s Great! Now we're getting somewhere. It seems likely that your system is bound in 2 ways: * Allocating RAM * Reading / writing from the hard drive. The setup time s='1172' indicates that it took more than a second to allocate a 72K buffer and read the message. That is the only work done during setup. The scan time t='1109' indicates the amount of time it took to complete the rest of the process. I'm guessing that since the setup took more than a second that writing the message back with injected headers probably took a while too. A scan depth of 127 is nominal. The data you sent indicates this is a problem when the messages are fairly large. There is likely a boundary condition between smaller messages and larger ones that allow the smaller messages to be handled more efficiently. Since you are indicating that CPU utilization is high during these events and since you're not mentioning other performance issues, it seems likely that RAM fragmentation or RAM starvation might be the problem here. During the setup, SNF allocates a buffer large enough for the entire message and then reads it all at once. This is most efficient because there is a single system call for each of these events - so the OS has complete control over the entire step and it only happens once. After the scanning process is done, SNF will typically allocate another buffer large enough to include the message and all of it's headers. This new version of the message is constructed in the buffer and then written all at once to the file system. If the problem is RAM fragmentation or starvation then it could be taking as much as a second for the OS to allocate a 72K buffer --- that's the kind of thing that should be nearly undetectable, but in these cases where high CPU loads are reported with this kind of log data I have seen that happen. If the problem were simply IO then it is likely that CPU utilization would be low while the CPUs wait for the IO operations to happen. Of course it could be a combination of things -- it's hard to tell what's happening in the internals of the OS. Hope this helps, _M -- Pete McNeil Chief Scientist ARM Research Labs, LLC www.armresearch.com 866-770-1044 x7010 twitter/codedweller # This message is sent to you because you are subscribed to the mailing list sniffer@sortmonster.com. This list is for discussing Message Sniffer, Anti-spam, Anti-Malware, and related email topics. For More information see http://www.armresearch.com To unsubscribe, E-mail to: sniffer-...@sortmonster.com To switch to the DIGEST mode, E-mail to sniffer-dig...@sortmonster.com To switch to the INDEX mode, E-mail to sniffer-in...@sortmonster.com Send administrative queries to sniffer-requ...@sortmonster.com
[sniffer] Re: IP Change on rulebase delivery system
Richard, Do you have any directories with a large number of files (4k)? We had a similar problem a few months back with sniffer scans taking much longer to complete and sniffer temporary files being left over. We finally traced the performance issues to a frequently accessed directory with thousands of files. We’ve also seen issues in the past with directories with a large number of files being very poor performing. Darin. From: Richard Stupek Sent: Thursday, March 28, 2013 12:10 PM To: Message Sniffer Community Subject: [sniffer] Re: IP Change on rulebase delivery system Ok looking at the log I see quite a few messages taking over a second to process (samples below): s u='20130328155503' m=\temp\1332407477322.msg' s='0' r='0' p s='1172' t='1109' l='72697' d='127'/ g o='0' i='12.130.136.172' t='u' c='0.486243' p='-0.625' r='Normal'/ /s s u='20130328155506' m='\temp\1332407477336.msg' s='60' r='5113015' m s='60' r='5113015' i='235' e='280' f='m'/ m s='60' r='4346940' i='16722' e='16812' f='m'/ p s='1141' t='937' l='16658' d='129'/ g o='0' i='192.210.233.215' t='u' c='0.360316' p='0.575758' r='Normal'/ /s s u='20130328155513' m='\temp\1332407477360.msg' s='52' r='5470216' m s='52' r='5470216' i='235' e='295' f='m'/ m s='52' r='5471910' i='949' e='1009' f='m'/ m s='52' r='5431546' i='1074' e='1200' f='m'/ m s='52' r='5479780' i='1857' e='1933' f='m'/ m s='62' r='5303955' i='82' e='2688' f='m'/ m s='52' r='5400681' i='1818' e='9143' f='m'/ p s='1031' t='750' l='8538' d='130'/ g o='0' i='192.210.134.21' t='u' c='0.545993' p='0.82' r='Black'/ /s s u='20130328155622' m=\temp\1332407477655.msg' s='60' r='5538969' m s='60' r='5538969' i='221' e='236' f='m'/ m s='61' r='5448415' i='2283' e='2297' f='m'/ m s='61' r='5438936' i='2247' e='2337' f='m'/ m s='60' r='5404555' i='15832' e='15850' f='m'/ m s='60' r='5539002' i='16033' e='16074' f='m'/ m s='62' r='5437246' i='30967' e='30985' f='m'/ p s='1219' t='1312' l='17171' d='135'/ g o='0' i='205.234.138.240' t='u' c='0.634697' p='0.763214' r='Normal'/ /s On Wed, Mar 27, 2013 at 4:42 PM, Pete McNeil madscient...@armresearch.com wrote: On 2013-03-27 17:16, Richard Stupek wrote: The spikes aren't as prolonged at the present. Interesting. A short spike like that might be expected if the message was longer than usual, but on average SNF should be very light-weight. One thing you can check is the performance data in your logs. That will show how much time in cpu milleseconds it is taking for each scan and how long the scans are in bytes. This might shed some light. http://www.armresearch.com/support/articles/software/snfServer/logFiles/activityLogs.jsp Look for something like p s='10' t='8' l='3294' d='84'/ in each scan. From the documentation: sp//s - Scan Performance Monitoring (performance='yes') p:s = Setup time in milliseconds p:t = Scan time in milliseconds p:l = Scan length in bytes p:d = Scan depth (peak evaluator count) Best, _M -- Pete McNeil Chief Scientist ARM Research Labs, LLC www.armresearch.com 866-770-1044 x7010 twitter/codedweller # This message is sent to you because you are subscribed to the mailing list sniffer@sortmonster.com. This list is for discussing Message Sniffer, Anti-spam, Anti-Malware, and related email topics. For More information see http://www.armresearch.com To unsubscribe, E-mail to: sniffer-...@sortmonster.com To switch to the DIGEST mode, E-mail to sniffer-dig...@sortmonster.com To switch to the INDEX mode, E-mail to sniffer-in...@sortmonster.com Send administrative queries to sniffer-requ...@sortmonster.com
[sniffer] How fast is *my* MessageSniffer? (was: IP Change on rulebase delivery system)
Answer: pretty darn fast for a system that I think is slow anyway I think my MTA is a busy system, and I know that it's not MessageSniffer that keeps the server busy. A glance with Task Manager or Process Explorer shows very little CPU time is spent by MessageSniffer. I threw some grepping etc and then Excel at the xml file for one average business day and came up with... 25% of messages are scanned within 100ms 50% of messages are scanned within 140ms 99% of messages are scanned within 330ms I also looked at the setup time. I'll spare you the graph; my results are: 80% of messages are loaded so quickly that the time is recorded as zero ms 85% of messages are loaded in 15ms or fewer 95% of messages are loaded in 30ms or fewer 99% of messages are loaded 125ms or fewer Actually, everything above 98% of my volume takes longer to load but for ridiculously smaller volume of messages. A spot check shows that those are indeed rodents messages of unusual size. Thanks for the nudge, Pete. I knew MessageSniffer was fast, I just hadn't bothered to quantify it before. Andrew. -Original Message- From: Message Sniffer Community [mailto:sniffer@sortmonster.com] On Behalf Of Pete McNeil Sent: Wednesday, March 27, 2013 2:43 PM To: Message Sniffer Community Subject: [sniffer] Re: IP Change on rulebase delivery system On 2013-03-27 17:16, Richard Stupek wrote: The spikes aren't as prolonged at the present. Interesting. A short spike like that might be expected if the message was longer than usual, but on average SNF should be very light-weight. One thing you can check is the performance data in your logs. That will show how much time in cpu milleseconds it is taking for each scan and how long the scans are in bytes. This might shed some light. http://www.armresearch.com/support/articles/software/snfServer/logFiles/ activityLogs.jsp http://www.armresearch.com/support/articles/software/snfServer/logFiles /activityLogs.jsp Look for something like p s='10' t='8' l='3294' d='84'/ in each scan. From the documentation: sp//s - Scan Performance Monitoring (performance='yes') p:s = Setup time in milliseconds p:t = Scan time in milliseconds p:l = Scan length in bytes p:d = Scan depth (peak evaluator count) Best, _M -- Pete McNeil Chief Scientist ARM Research Labs, LLC www.armresearch.com http://www.armresearch.com 866-770-1044 x7010 twitter/codedweller # This message is sent to you because you are subscribed to the mailing list sniffer@sortmonster.com mailto:sniffer@sortmonster.com . This list is for discussing Message Sniffer, Anti-spam, Anti-Malware, and related email topics. For More information see http://www.armresearch.com http://www.armresearch.com To unsubscribe, E-mail to: sniffer-...@sortmonster.com mailto:sniffer-...@sortmonster.com To switch to the DIGEST mode, E-mail to sniffer-dig...@sortmonster.com mailto:sniffer-dig...@sortmonster.com To switch to the INDEX mode, E-mail to sniffer-in...@sortmonster.com mailto:sniffer-in...@sortmonster.com Send administrative queries to sniffer-requ...@sortmonster.com mailto:sniffer-requ...@sortmonster.com image001.png
[sniffer] Re: How fast is *my* MessageSniffer? (was: IP Change on rulebase delivery system)
Nice stats, Andrew! And Pete, thanks for spending so much time and effort to make it work so well, despite us beating on you because it doesn’t catch every spam campaign from the very first message! Sniffer has always been our number one tool in this battle. Darin. From: Colbeck, Andrew Sent: Thursday, March 28, 2013 7:50 PM To: Message Sniffer Community Subject: [sniffer] How fast is *my* MessageSniffer? (was: IP Change on rulebase delivery system) Answer: pretty darn fast for a system that I think is slow anyway I think my MTA is a busy system, and I know that it’s not MessageSniffer that keeps the server busy. A glance with Task Manager or Process Explorer shows very little CPU time is spent by MessageSniffer. I threw some grepping etc and then Excel at the xml file for one average business day and came up with… 25% of messages are scanned within 100ms 50% of messages are scanned within 140ms 99% of messages are scanned within 330ms I also looked at the “setup time”. I’ll spare you the graph; my results are: 80% of messages are loaded so quickly that the time is recorded as zero ms 85% of messages are loaded in 15ms or fewer 95% of messages are loaded in 30ms or fewer 99% of messages are loaded 125ms or fewer Actually, everything above 98% of my volume takes longer to load but for ridiculously smaller volume of messages. A spot check shows that those are indeed rodents messages of unusual size. Thanks for the nudge, Pete. I knew MessageSniffer was fast, I just hadn’t bothered to quantify it before. Andrew. -Original Message- From: Message Sniffer Community [mailto:sniffer@sortmonster.com] On Behalf Of Pete McNeil Sent: Wednesday, March 27, 2013 2:43 PM To: Message Sniffer Community Subject: [sniffer] Re: IP Change on rulebase delivery system On 2013-03-27 17:16, Richard Stupek wrote: The spikes aren't as prolonged at the present. Interesting. A short spike like that might be expected if the message was longer than usual, but on average SNF should be very light-weight. One thing you can check is the performance data in your logs. That will show how much time in cpu milleseconds it is taking for each scan and how long the scans are in bytes. This might shed some light. http://www.armresearch.com/support/articles/software/snfServer/logFiles/activityLogs.jsp Look for something like p s='10' t='8' l='3294' d='84'/ in each scan. From the documentation: sp//s - Scan Performance Monitoring (performance='yes') p:s = Setup time in milliseconds p:t = Scan time in milliseconds p:l = Scan length in bytes p:d = Scan depth (peak evaluator count) Best, _M -- Pete McNeil Chief Scientist ARM Research Labs, LLC www.armresearch.com 866-770-1044 x7010 twitter/codedweller # This message is sent to you because you are subscribed to the mailing list sniffer@sortmonster.com. This list is for discussing Message Sniffer, Anti-spam, Anti-Malware, and related email topics. For More information see http://www.armresearch.com To unsubscribe, E-mail to: sniffer-...@sortmonster.com To switch to the DIGEST mode, E-mail to sniffer-dig...@sortmonster.com To switch to the INDEX mode, E-mail to sniffer-in...@sortmonster.com Send administrative queries to sniffer-requ...@sortmonster.com image001.png
