You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@spamassassin.apache.org by Chris <cp...@embarqmail.com> on 2010/09/04 15:42:12 UTC

scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

I'm trying to figure out why I'm having ridiculous scan times such as
the above examples. Lower scan times such as in the 20 second range are
the exception rather than the rule. I'm running bind as a local caching
nameserver and it seems to be working correctly. I've just seen a ham
that has a scantime=172.2. Could there be something else on the system
that is affecting this? 

Any advice as to troubleshooting would be appreciated.

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Dave Funk <db...@engineering.uiowa.edu>.
On Sat, 4 Sep 2010, Emin Akbulut wrote:

> If cpu usage is normal then it's related to DNS or
> online things, it maybe wait for communication...
>
> I think the -L parameter disables online checks.
> Just try without online checks. Also use -D for debug.

Another posibility for delay would be waiting for locks for some
kind of DB update (autowhitelist or Bayes).

Good clue, check CPU during message processing. If high for duration
then probably bad rule regex or possibly some kind of spin lock on
DB access.
If mostly low then waiting for some kind of resource; DNS, communication
with external service (EG DCC), database access, etc.

-- 
Dave Funk                                  University of Iowa
<dbfunk (at) engineering.uiowa.edu>        College of Engineering
319/335-5751   FAX: 319/384-0549           1256 Seamans Center
Sys_admin/Postmaster/cell_admin            Iowa City, IA 52242-1527
#include <std_disclaimer.h>
Better is not better, 'standard' is better. B{

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Emin Akbulut <em...@gmail.com>.
If cpu usage is normal then it's related to DNS or
online things, it maybe wait for communication...

I think the -L parameter disables online checks.
Just try without online checks. Also use -D for debug.



On Sat, Sep 4, 2010 at 7:25 PM, Michael Scheidell <
michael.scheidell@secnap.com> wrote:

>  On 9/4/10 9:42 AM, Chris wrote:
>
>> I'm trying to figure out why I'm having ridiculous scan times such as
>> the above examples. Lower scan times such as in the 20 second range are
>> the exception rather than the rule. I'm running bind as a local caching
>> nameserver and it seems to be working correctly. I've just seen a ham
>> that has a scantime=172.2. Could there be something else on the system
>> that is affecting this?
>>
>> Any advice as to troubleshooting would be appreciated.
>>
>>  DNS or runaway regexp.
>
> run sa with debug and you will see where the problem is.
> most likely your are using a defunct dns rbl, or a custom rule. disable all
> custom rules and rbl's and try again.
>
> --
> Michael Scheidell, CTO
> o: 561-999-5000
> d: 561-948-2259
> ISN: 1259*1300
> > *| *SECNAP Network Security Corporation
>
>   * Certified SNORT Integrator
>   * 2008-9 Hot Company Award Winner, World Executive Alliance
>   * Five-Star Partner Program 2009, VARBusiness
>   * Best in Email Security,2010: Network Products Guide
>   * King of Spam Filters, SC Magazine 2008
>
> ______________________________________________________________________
> This email has been scanned and certified safe by SpammerTrap(r). For
> Information please see http://www.secnap.com/products/spammertrap/
> ______________________________________________________________________

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Michael Scheidell <mi...@secnap.com>.
  On 9/4/10 9:42 AM, Chris wrote:
> I'm trying to figure out why I'm having ridiculous scan times such as
> the above examples. Lower scan times such as in the 20 second range are
> the exception rather than the rule. I'm running bind as a local caching
> nameserver and it seems to be working correctly. I've just seen a ham
> that has a scantime=172.2. Could there be something else on the system
> that is affecting this?
>
> Any advice as to troubleshooting would be appreciated.
>
DNS or runaway regexp.

run sa with debug and you will see where the problem is.
most likely your are using a defunct dns rbl, or a custom rule. disable 
all custom rules and rbl's and try again.

-- 
Michael Scheidell, CTO
o: 561-999-5000
d: 561-948-2259
ISN: 1259*1300
 > *| *SECNAP Network Security Corporation

    * Certified SNORT Integrator
    * 2008-9 Hot Company Award Winner, World Executive Alliance
    * Five-Star Partner Program 2009, VARBusiness
    * Best in Email Security,2010: Network Products Guide
    * King of Spam Filters, SC Magazine 2008

______________________________________________________________________
This email has been scanned and certified safe by SpammerTrap(r). 
For Information please see http://www.secnap.com/products/spammertrap/
______________________________________________________________________  

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by John Hardin <jh...@impsec.org>.
On Mon, 6 Sep 2010, Martin Gregorie wrote:

> On Sun, 2010-09-05 at 14:55 -0500, Chris wrote:
>> On Sun, 2010-09-05 at 20:02 +0200, Karsten Bräckelmann wrote:
>>> On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
>>>> I'm trying to figure out why I'm having ridiculous scan times such as 
>>>> the above examples. Lower scan times such as in the 20 second range 
>>>> are the exception rather than the rule. I'm running bind as a local 
>>>> caching
>
> I'm running spamd on an 866 MHz P3 box with 512MB RAM and 2GB swap with
> a maximum of 5 spamd child processes.

You're probably _not_ running X and user apps on that box at the same 
time, though...


-- 
  John Hardin KA7OHZ                    http://www.impsec.org/~jhardin/
  jhardin@impsec.org    FALaholic #11174     pgpk -a jhardin@impsec.org
  key: 0xB8732E79 -- 2D8C 34F4 6411 F507 136C  AF76 D822 E6E6 B873 2E79
-----------------------------------------------------------------------
   ...every time I sit down in front of a Windows machine I feel as
   if the computer is just a place for the manufacturers to put their
   advertising.                                 -- fwadling on Y! SCOX
-----------------------------------------------------------------------
  11 days until the 223rd anniversary of the signing of the U.S. Constitution

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Martin Gregorie <ma...@gregorie.org>.
On Sun, 2010-09-05 at 14:55 -0500, Chris wrote:
> On Sun, 2010-09-05 at 20:02 +0200, Karsten Bräckelmann wrote:
> > On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
> > > I'm trying to figure out why I'm having ridiculous scan times such as
> > > the above examples. Lower scan times such as in the 20 second range are
> > > the exception rather than the rule. I'm running bind as a local caching
> >
How many child processes is spamd spawning?

I'm getting the following spamd stats:

                Min      Avg      Max
Scan times:     0.6      3.1     55.8
Msg sizes:     2079     7275   306976

I'm running spamd on an 866 MHz P3 box with 512MB RAM and 2GB swap with
a maximum of 5 spamd child processes. 

There's no exact correlation between message size and scan time:
- the smallest message took 8.0 seconds to scan
- the biggest message was scanned in 3.6 seconds
- the message that took 0.6 seconds was 3196 bytes 
- the message that took 55.6 seconds was 19118 bytes


Martin




Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Sun, 2010-09-05 at 20:02 +0200, Karsten Bräckelmann wrote:
> On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
> > I'm trying to figure out why I'm having ridiculous scan times such as
> > the above examples. Lower scan times such as in the 20 second range are
> > the exception rather than the rule. I'm running bind as a local caching
> 
> Do you use the URICountry plugin? It has been reported to cause
> exceptionally long processing time in some cases. It certainly was the
> cause on one machine for me.
> 
> 

Thanks Karsten, just checked and it's not among those that I'm using.

Chris

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Karsten Bräckelmann <gu...@rudersport.de>.
On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
> I'm trying to figure out why I'm having ridiculous scan times such as
> the above examples. Lower scan times such as in the 20 second range are
> the exception rather than the rule. I'm running bind as a local caching

Do you use the URICountry plugin? It has been reported to cause
exceptionally long processing time in some cases. It certainly was the
cause on one machine for me.


-- 
char *t="\10pse\0r\0dtu\0.@ghno\x4e\xc8\x79\xf4\xab\x51\x8a\x10\xf4\xf4\xc4";
main(){ char h,m=h=*t++,*x=t+2*h,c,i,l=*x,s=0; for (i=0;i<l;i++){ i%8? c<<=1:
(c=*++x); c&128 && (s+=h); if (!(h>>=1)||!t[s+h]){ putchar(t[s]);h=m;s=0; }}}


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Mikael Syska <mi...@syska.dk>.
Hi,

On Sun, Sep 5, 2010 at 12:00 AM, Chris <cp...@embarqmail.com> wrote:
> On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
> I've started SA now with -D
>
> OPTIONS="-d -D -c -H -m 4  --max-conn-per-child=3 --min-children=1"
>
> While looking at my syslog I noticed the following:
>
> Sep  4 16:21:46 localhost spamd[15797]: prefork: periodic ping from
> spamd parent
> Sep  4 16:21:46 localhost spamd[15800]: prefork: periodic ping from
> spamd parent
> Sep  4 16:21:46 localhost spamd[15800]: prefork: sysread(9) not ready,
> wait max 300 secs
> Sep  4 16:21:46 localhost spamd[15797]: prefork: sysread(8) not ready,
> wait max 300 secs

I have never used spamd before ... but I would look into that process
and debug it ...

>From what i could bing/google from the above message ... it could be
because of a timeout because of some permissions issue.

mvh
Mikael Syska

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Sat, 2010-09-04 at 17:00 -0500, Chris wrote:
> On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
> > I'm trying to figure out why I'm having ridiculous scan times such as
> > the above examples. Lower scan times such as in the 20 second range are
> > the exception rather than the rule. I'm running bind as a local caching
> > nameserver and it seems to be working correctly. I've just seen a ham
> > that has a scantime=172.2. Could there be something else on the system
> > that is affecting this? 
> > 
> > Any advice as to troubleshooting would be appreciated.
> > 
> 
> I've started SA now with -D
> 
> OPTIONS="-d -D -c -H -m 4  --max-conn-per-child=3 --min-children=1"
> 
> While looking at my syslog I noticed the following:
> 
> Sep  4 16:21:46 localhost spamd[15797]: prefork: periodic ping from
> spamd parent
> Sep  4 16:21:46 localhost spamd[15800]: prefork: periodic ping from
> spamd parent
> Sep  4 16:21:46 localhost spamd[15800]: prefork: sysread(9) not ready,
> wait max 300 secs
> Sep  4 16:21:46 localhost spamd[15797]: prefork: sysread(8) not ready,
> wait max 300 secs
> 
Awhile ago I logged out and logged back in again, I no longer am seeing
the above and scan times have decreased considerably,
ham - scantime=5.7
and for a spam that just came in
scantime=1.6

Things seem back to normal, for now, though I'm not sure how long
they'll last. Any idea what could be causing the above?

Chris

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Sun, 2010-09-05 at 07:35 -0500, Shane Williams wrote:
> In several places, Justin Mason has said the sysread debug line
> doesn't necessarily indicate an error (he actually says they're
> normal in debug mode), though these are fairly old posts.
> 
> http://www.mail-archive.com/users@spamassassin.apache.org/msg31175.html
> http://mail-archives.apache.org/mod_mbox/spamassassin-dev/200506.mbox/%3C4407.42B33D88.2F05AF5B.dev@spamassassin.apache.org%3E
> 
> So the sysread may be a red herring.
> 
> On Sat, 4 Sep 2010, Chris wrote:
> 
> > On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
> >> I'm trying to figure out why I'm having ridiculous scan times such as
> >> the above examples. Lower scan times such as in the 20 second range are
> >> the exception rather than the rule. I'm running bind as a local caching
> >> nameserver and it seems to be working correctly. I've just seen a ham
> >> that has a scantime=172.2. Could there be something else on the system
> >> that is affecting this?

Thanks, after reading Justin's input on the bug-report I see what's
happening as far as the 'pings' go. I'll see how things go as the day
progress regarding scan times.

Chris

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Shane Williams <sh...@shanew.net>.
In several places, Justin Mason has said the sysread debug line
doesn't necessarily indicate an error (he actually says they're
normal in debug mode), though these are fairly old posts.

http://www.mail-archive.com/users@spamassassin.apache.org/msg31175.html
http://mail-archives.apache.org/mod_mbox/spamassassin-dev/200506.mbox/%3C4407.42B33D88.2F05AF5B.dev@spamassassin.apache.org%3E

So the sysread may be a red herring.

On Sat, 4 Sep 2010, Chris wrote:

> On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
>> I'm trying to figure out why I'm having ridiculous scan times such as
>> the above examples. Lower scan times such as in the 20 second range are
>> the exception rather than the rule. I'm running bind as a local caching
>> nameserver and it seems to be working correctly. I've just seen a ham
>> that has a scantime=172.2. Could there be something else on the system
>> that is affecting this?
>>
>> Any advice as to troubleshooting would be appreciated.
>>
>
> I've started SA now with -D
>
> OPTIONS="-d -D -c -H -m 4  --max-conn-per-child=3 --min-children=1"
>
> While looking at my syslog I noticed the following:
>
> Sep  4 16:21:46 localhost spamd[15797]: prefork: periodic ping from
> spamd parent
> Sep  4 16:21:46 localhost spamd[15800]: prefork: periodic ping from
> spamd parent
> Sep  4 16:21:46 localhost spamd[15800]: prefork: sysread(9) not ready,
> wait max 300 secs
> Sep  4 16:21:46 localhost spamd[15797]: prefork: sysread(8) not ready,
> wait max 300 secs
>
> I've got the debug output on a ham, just waiting for a spam to come
> through then I'll post both to pastebin but the above doesn't look good.
> When this is happening my drive light seems to stay on forever and the
> system seems close to being unresponsive. Checking cpu usage when this
> is happening it stays around 4% for user and 3-4% for system. Link for a
> ham - http://pastebin.com/k55D79TL
> spam - http://pastebin.com/28qW2nga
>
> Though I hate to do it I've temporally shut down SA, hopefully some of
> you have a solution.
>
> Thanks
> Chris
>
>

-- 
Public key #7BBC68D9 at            |                 Shane Williams
http://pgp.mit.edu/                |      System Admin - UT iSchool
=----------------------------------+-------------------------------
All syllogisms contain three lines |              shanew@shanew.net
Therefore this is not a syllogism  | www.ischool.utexas.edu/~shanew

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Matus UHLAR - fantomas <uh...@fantomas.sk>.
> On Mon, 6 Sep 2010 13:20:56 +0200
> Matus UHLAR - fantomas <uh...@fantomas.sk> wrote:
> > using clamav directly, without SA, is more effective. ClamAV plugin
> > seems to be OK for checking for things like phishes or strustured
> > data like credit card numbers, in which case it may cause false
> > positives.

On 06.09.10 16:01, RW wrote:
> I don't see what you are saying here. The plugin simply passes the mail
> intact to clamd.

but SA has to load it first which I found less effective.

> And you don't have to score clamv as a single poison-pill rule if you
> don't want to. 

I found it better to imediately reject viruses. On my maching I only use
official signatures and clamav-milter to reject viruses at SMTP time. 

-- 
Matus UHLAR - fantomas, uhlar@fantomas.sk ; http://www.fantomas.sk/
Warning: I wish NOT to receive e-mail advertising to this address.
Varovanie: na tuto adresu chcem NEDOSTAVAT akukolvek reklamnu postu.
(R)etry, (A)bort, (C)ancer

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by RW <rw...@googlemail.com>.
On Mon, 6 Sep 2010 13:20:56 +0200
Matus UHLAR - fantomas <uh...@fantomas.sk> wrote:


> using clamav directly, without SA, is more effective. ClamAV plugin
> seems to be OK for checking for things like phishes or strustured
> data like credit card numbers, in which case it may cause false
> positives.

I don't see what you are saying here. The plugin simply passes the mail
intact to clamd.

And you don't have to score clamv as a single poison-pill rule if you
don't want to. 

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Mon, 2010-09-06 at 13:20 +0200, Matus UHLAR - fantomas wrote:
> >> On Mon, 06 Sep 2010 12:26:08 +0200
> >> Yet Another Ninja <sa...@alexb.ch> wrote:
> 
> >>> You're using the SA ClamAV plugin which isn't the most effcient
> >>> method do do AV checks.
> 
> > On 2010-09-06 12:49, RW wrote:
> >> What's wrong with it?
> 
> On 06.09.10 13:14, Yet Another Ninja wrote:
> > nothing "wrong" but my first choice would be to reject infected files at  
> > MTA level (via milter, proxy, etc) instead of parsing with SA and tag  
> > it... imo, unnecessary overhead.
> 
> using clamav directly, without SA, is more effective. ClamAV plugin seems to
> be OK for checking for things like phishes or strustured data like credit
> card numbers, in which case it may cause false positives.
> 

That's what I basically use it for. The majority of my hits are from the
unofficial clam sigs and since my ISP/DSL provider doesn't do any virus
checking, they say it violates some kind of personal rights, I feel I
should do it especially since I forward some of the mail I get onto my
friends who run windows machines.

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Matus UHLAR - fantomas <uh...@fantomas.sk>.
>> On Mon, 06 Sep 2010 12:26:08 +0200
>> Yet Another Ninja <sa...@alexb.ch> wrote:

>>> You're using the SA ClamAV plugin which isn't the most effcient
>>> method do do AV checks.

> On 2010-09-06 12:49, RW wrote:
>> What's wrong with it?

On 06.09.10 13:14, Yet Another Ninja wrote:
> nothing "wrong" but my first choice would be to reject infected files at  
> MTA level (via milter, proxy, etc) instead of parsing with SA and tag  
> it... imo, unnecessary overhead.

using clamav directly, without SA, is more effective. ClamAV plugin seems to
be OK for checking for things like phishes or strustured data like credit
card numbers, in which case it may cause false positives.

-- 
Matus UHLAR - fantomas, uhlar@fantomas.sk ; http://www.fantomas.sk/
Warning: I wish NOT to receive e-mail advertising to this address.
Varovanie: na tuto adresu chcem NEDOSTAVAT akukolvek reklamnu postu.
"The box said 'Requires Windows 95 or better', so I bought a Macintosh".

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Mon, 2010-09-06 at 13:14 +0200, Yet Another Ninja wrote:
> On 2010-09-06 12:49, RW wrote:
> > On Mon, 06 Sep 2010 12:26:08 +0200
> > Yet Another Ninja <sa...@alexb.ch> wrote:
> > 
> > 
> >> You're using the SA ClamAV plugin which isn't the most effcient
> >> method do do AV checks.
> > 
> > What's wrong with it?
> 
> nothing "wrong" but my first choice would be to reject infected files at 
> MTA level (via milter, proxy, etc) instead of parsing with SA and tag 
> it... imo, unnecessary overhead.

But this isn't a full blown mail server. Fetchmail picks-up from my
various mail accounts and is processed by procmail, what isn't tossed
over to the various mailing lists is processed through SA.

:0 fw : $ASSASSINLOCK
* < 150000 
| /usr/local/bin/spamc -f


-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Yet Another Ninja <sa...@alexb.ch>.
On 2010-09-06 12:49, RW wrote:
> On Mon, 06 Sep 2010 12:26:08 +0200
> Yet Another Ninja <sa...@alexb.ch> wrote:
> 
> 
>> You're using the SA ClamAV plugin which isn't the most effcient
>> method do do AV checks.
> 
> What's wrong with it?

nothing "wrong" but my first choice would be to reject infected files at 
MTA level (via milter, proxy, etc) instead of parsing with SA and tag 
it... imo, unnecessary overhead.

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by RW <rw...@googlemail.com>.
On Mon, 06 Sep 2010 12:26:08 +0200
Yet Another Ninja <sa...@alexb.ch> wrote:


> You're using the SA ClamAV plugin which isn't the most effcient
> method do do AV checks.

What's wrong with it?

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Yet Another Ninja <sa...@alexb.ch>.
On 2010-09-05 0:00, Chris wrote:
> On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
>> I'm trying to figure out why I'm having ridiculous scan times such as
>> the above examples. Lower scan times such as in the 20 second range are
>> the exception rather than the rule. I'm running bind as a local caching
>> nameserver and it seems to be working correctly. I've just seen a ham
>> that has a scantime=172.2. Could there be something else on the system
>> that is affecting this? 
>>
>> Any advice as to troubleshooting would be appreciated.
>>
> 
> I've started SA now with -D
> 
> OPTIONS="-d -D -c -H -m 4  --max-conn-per-child=3 --min-children=1"
> 
> While looking at my syslog I noticed the following:
> 
> Sep  4 16:21:46 localhost spamd[15797]: prefork: periodic ping from
> spamd parent
> Sep  4 16:21:46 localhost spamd[15800]: prefork: periodic ping from
> spamd parent
> Sep  4 16:21:46 localhost spamd[15800]: prefork: sysread(9) not ready,
> wait max 300 secs
> Sep  4 16:21:46 localhost spamd[15797]: prefork: sysread(8) not ready,
> wait max 300 secs
> 
> I've got the debug output on a ham, just waiting for a spam to come
> through then I'll post both to pastebin but the above doesn't look good.
> When this is happening my drive light seems to stay on forever and the
> system seems close to being unresponsive. Checking cpu usage when this
> is happening it stays around 4% for user and 3-4% for system. Link for a
> ham - http://pastebin.com/k55D79TL
> spam - http://pastebin.com/28qW2nga


"Sep  4 16:32:31 localhost spamd[15797]: ClamAV: invoking 
File::Scan::ClamAV, port/socket: /var/lib/clamav/clamd.socket"

You're using the SA ClamAV plugin which isn't the most effcient method 
do do AV checks.

There are more efficient methods to interface with Clamd.

You may also want to remove legacy or inneficient rule files.





Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Sat, 2010-09-04 at 08:42 -0500, Chris wrote:
> I'm trying to figure out why I'm having ridiculous scan times such as
> the above examples. Lower scan times such as in the 20 second range are
> the exception rather than the rule. I'm running bind as a local caching
> nameserver and it seems to be working correctly. I've just seen a ham
> that has a scantime=172.2. Could there be something else on the system
> that is affecting this? 
> 
> Any advice as to troubleshooting would be appreciated.
> 

I've started SA now with -D

OPTIONS="-d -D -c -H -m 4  --max-conn-per-child=3 --min-children=1"

While looking at my syslog I noticed the following:

Sep  4 16:21:46 localhost spamd[15797]: prefork: periodic ping from
spamd parent
Sep  4 16:21:46 localhost spamd[15800]: prefork: periodic ping from
spamd parent
Sep  4 16:21:46 localhost spamd[15800]: prefork: sysread(9) not ready,
wait max 300 secs
Sep  4 16:21:46 localhost spamd[15797]: prefork: sysread(8) not ready,
wait max 300 secs

I've got the debug output on a ham, just waiting for a spam to come
through then I'll post both to pastebin but the above doesn't look good.
When this is happening my drive light seems to stay on forever and the
system seems close to being unresponsive. Checking cpu usage when this
is happening it stays around 4% for user and 3-4% for system. Link for a
ham - http://pastebin.com/k55D79TL
spam - http://pastebin.com/28qW2nga

Though I hate to do it I've temporally shut down SA, hopefully some of
you have a solution.

Thanks
Chris

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Emin Akbulut <em...@gmail.com>.
Plus; parallel  scans give a clue too. Next time compare one session
vs. 2 or more sessions . If both times are nearly equal then it's not
related
to cpu usage or any other machine related bottleneck, coz probably SA waits
for something -then timeout occurs? -

On Sun, Sep 5, 2010 at 3:55 AM, John Hardin <jh...@impsec.org> wrote:

> On Sat, 4 Sep 2010, Chris wrote:
>
>  On Sat, 2010-09-04 at 14:33 -0700, John Hardin wrote:
>>
>>> On Sat, 4 Sep 2010, Chris wrote:
>>>
>>>  I'm trying to figure out why I'm having ridiculous scan times such as
>>>> the above examples. Lower scan times such as in the 20 second range are
>>>> the exception rather than the rule. I'm running bind as a local caching
>>>> nameserver and it seems to be working correctly. I've just seen a ham
>>>> that has a scantime=172.2. Could there be something else on the system
>>>> that is affecting this?
>>>>
>>>> Any advice as to troubleshooting would be appreciated.
>>>>
>>>
>>> What version of SA, and are you current on updates (have you run
>>> sa-update
>>> recently)?
>>>
>>> Would it be possible to post an example message that exhibits the
>>> problem?
>>>
>>
>> Hi John, version is 3.3.0 and updates was last run at 5:11pm. Here is a
>> link to a spam that took 302s to process http://ez-files.net/445403
>>
>
> Thanks.
>
> ClamAV took almost a minute and a half to scan that message.
>
> All of the steps seem slow. I'd suggest that it isn't any particular bad
> rule, so much as the system appears overloaded.
>
>
>  Awhile ago I logged out and logged back in again, I no longer am seeing
>> the above and scan times have decreased considerably,
>> ham - scantime=5.7
>> and for a spam that just came in
>> scantime=1.6
>>
>> Things seem back to normal, for now, though I'm not sure how long
>> they'll last. Any idea what could be causing the above?
>>
>
> That's odd. Are you running in an X session or character? Was there some
> other process bogging the system or taking up lots of memory such that it
> was swapping, which got killed when you logged out?
>
>
>

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by RW <rw...@googlemail.com>.
On Mon, 06 Sep 2010 17:03:02 +0200
Karsten Bräckelmann <gu...@rudersport.de> wrote:


> Since you mentioned procmail, your spamc calling recipe is *with*
> locking, right? Limiting concurrent SA processes pretty much to one as
> far as filtering is concerned. 


And start spamd with --max-children=1. That not only frees up
processes, but with --max-conn-per-child=3 it avoids frequently
replacing the "hot child" with a paged-out spare.


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Tue, 2010-09-07 at 00:54 +0200, Karsten Bräckelmann wrote:
> On Mon, 2010-09-06 at 17:32 -0500, Chris wrote:
> > On Mon, 2010-09-06 at 17:03 +0200, Karsten Bräckelmann wrote:
> 
> > > Unless the limit of 50k results in quite some spam ending up unprocessed
> > > by SA, I doubt this will help.
> > > 
> > > Dropping large-ish third-party rule sets, if any, is much more likely to
> > > make a noticeable difference. SA, as well as ClamAV. If memory serves me
> > > right, you are using ClamAV third-party signatures -- some of which have
> > > been reported to hog memory galore.
> 
> > > Since you mentioned procmail, your spamc calling recipe is *with*
> > > locking, right? Limiting concurrent SA processes pretty much to one as
> > > far as filtering is concerned. (As Bernd and previously others in this
> > > thread have pointed out, limit the concurrency.)
> > 
> > I believe I have this right Karsten
> > 
> > :0 fw : $ASSASSINLOCK
> 
> Indeed, you do. Well, if $ASSASSINLOCK evaluates to something, always
> evaluates to the same, and actually is writable. ;)
> 
> > * < 150000 
> > | /usr/local/bin/spamc -f
> > 
> > I've trimmed my third party rule sets down to the sought rules and
> > disabled unnecessary rule sets I had setup in my local.cf
> 
> Good one, particular if constrained with that "unnecessary". That part
> of my previous post strongly aimed at ClamAV third-party sigs, though.
> (Ah, well, and not loading them twice. But I believe we got that
> settled. ;)
> 
> 
I removed some of the third party sigs also Karsten, and memory usage
for clamd has dropped considerably:

28239 clamav    20   0  160m 132m 5304 S  0.0 17.6   0:27.65 clamd 

Memory usage does look a bit better than it did when I started this
thread:

Mem:    772880k total,   744904k used,    27976k free,    34384k buffers
Swap:  1076312k total,   167580k used,   908732k free,   135420k cached

Still going into swap but until I upgrade memory that will have to be
sufficient. I can probably still remove some of the third party clam
sigs and have it do what I want.

Chris

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Karsten Bräckelmann <gu...@rudersport.de>.
On Mon, 2010-09-06 at 17:32 -0500, Chris wrote:
> On Mon, 2010-09-06 at 17:03 +0200, Karsten Bräckelmann wrote:

> > Unless the limit of 50k results in quite some spam ending up unprocessed
> > by SA, I doubt this will help.
> > 
> > Dropping large-ish third-party rule sets, if any, is much more likely to
> > make a noticeable difference. SA, as well as ClamAV. If memory serves me
> > right, you are using ClamAV third-party signatures -- some of which have
> > been reported to hog memory galore.

> > Since you mentioned procmail, your spamc calling recipe is *with*
> > locking, right? Limiting concurrent SA processes pretty much to one as
> > far as filtering is concerned. (As Bernd and previously others in this
> > thread have pointed out, limit the concurrency.)
> 
> I believe I have this right Karsten
> 
> :0 fw : $ASSASSINLOCK

Indeed, you do. Well, if $ASSASSINLOCK evaluates to something, always
evaluates to the same, and actually is writable. ;)

> * < 150000 
> | /usr/local/bin/spamc -f
> 
> I've trimmed my third party rule sets down to the sought rules and
> disabled unnecessary rule sets I had setup in my local.cf

Good one, particular if constrained with that "unnecessary". That part
of my previous post strongly aimed at ClamAV third-party sigs, though.
(Ah, well, and not loading them twice. But I believe we got that
settled. ;)


-- 
char *t="\10pse\0r\0dtu\0.@ghno\x4e\xc8\x79\xf4\xab\x51\x8a\x10\xf4\xf4\xc4";
main(){ char h,m=h=*t++,*x=t+2*h,c,i,l=*x,s=0; for (i=0;i<l;i++){ i%8? c<<=1:
(c=*++x); c&128 && (s+=h); if (!(h>>=1)||!t[s+h]){ putchar(t[s]);h=m;s=0; }}}


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Mon, 2010-09-06 at 17:03 +0200, Karsten Bräckelmann wrote:
> On Sun, 2010-09-05 at 17:44 -0500, Chris wrote:
> > Thanks for the input John, I can accept 30 or 45 seconds of drive access
> > however when it comes to 300 I can't accept that. And you're absolutely
> > correct, the problem is my lack of memory I realize that now. 
> 
> > Just one user, me, though I already have procmail setup to not pass mail
> > destined for mailing list through SA or ClamAv. I had SA set to check
> > message size less than 250k in my procmailrc I've dropped it to 50k and
> 
> Unless the limit of 50k results in quite some spam ending up unprocessed
> by SA, I doubt this will help.
> 
> Dropping large-ish third-party rule sets, if any, is much more likely to
> make a noticeable difference. SA, as well as ClamAV. If memory serves me
> right, you are using ClamAV third-party signatures -- some of which have
> been reported to hog memory galore.
> 
> 
> > will see what happens. I could probably drop some of the extra rulesets
> > I run also which would probably cut down on access until I can upgrade
> > my memory. I'm going to consider this thread closed then as being solved
> > with "upgrade to more memory". Many thanks to all who replied and
> > offered suggestions. And to the SA Team, keep up the great work!
> 
> Since you mentioned procmail, your spamc calling recipe is *with*
> locking, right? Limiting concurrent SA processes pretty much to one as
> far as filtering is concerned. (As Bernd and previously others in this
> thread have pointed out, limit the concurrency.)
> 
> 
I believe I have this right Karsten

:0 fw : $ASSASSINLOCK
* < 150000 
| /usr/local/bin/spamc -f

I've trimmed my third party rule sets down to the sought rules and
disabled unnecessary rule sets I had setup in my local.cf

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Karsten Bräckelmann <gu...@rudersport.de>.
On Sun, 2010-09-05 at 17:44 -0500, Chris wrote:
> Thanks for the input John, I can accept 30 or 45 seconds of drive access
> however when it comes to 300 I can't accept that. And you're absolutely
> correct, the problem is my lack of memory I realize that now. 

> Just one user, me, though I already have procmail setup to not pass mail
> destined for mailing list through SA or ClamAv. I had SA set to check
> message size less than 250k in my procmailrc I've dropped it to 50k and

Unless the limit of 50k results in quite some spam ending up unprocessed
by SA, I doubt this will help.

Dropping large-ish third-party rule sets, if any, is much more likely to
make a noticeable difference. SA, as well as ClamAV. If memory serves me
right, you are using ClamAV third-party signatures -- some of which have
been reported to hog memory galore.


> will see what happens. I could probably drop some of the extra rulesets
> I run also which would probably cut down on access until I can upgrade
> my memory. I'm going to consider this thread closed then as being solved
> with "upgrade to more memory". Many thanks to all who replied and
> offered suggestions. And to the SA Team, keep up the great work!

Since you mentioned procmail, your spamc calling recipe is *with*
locking, right? Limiting concurrent SA processes pretty much to one as
far as filtering is concerned. (As Bernd and previously others in this
thread have pointed out, limit the concurrency.)


-- 
char *t="\10pse\0r\0dtu\0.@ghno\x4e\xc8\x79\xf4\xab\x51\x8a\x10\xf4\xf4\xc4";
main(){ char h,m=h=*t++,*x=t+2*h,c,i,l=*x,s=0; for (i=0;i<l;i++){ i%8? c<<=1:
(c=*++x); c&128 && (s+=h); if (!(h>>=1)||!t[s+h]){ putchar(t[s]);h=m;s=0; }}}


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Mon, 2010-09-06 at 12:09 +0200, Bernd Petrovitsch wrote:
> On Son, 2010-09-05 at 17:44 -0500, Chris wrote:
> > On Sun, 2010-09-05 at 12:54 -0700, John Hardin wrote:
> > > On Sun, 5 Sep 2010, Chris wrote:
> > > 
> > > > On Sun, 2010-09-05 at 12:33 -0500, Len Conrad wrote:
> > > >>> Mem:    772880k total,   685316k used,    87564k free,    31344k buffers
> > > >>> Swap:  1076312k total,   249032k used,   827280k free,   156328k cached
> > > >>
> > > >> 250MB swapped, for less than 1 GB RAM, used is disastrous for an MTA.
> > > >>
> > > >> Increase RAM to 2GB, or until swap is always "0k used"
> > > >
> > > > It's just a single user home system. True, I probably do need to 
> > > > increase ram but I 'don't' think this has a bearing on this issue though 
> > > > I may be wrong.
> > > 
> > > Your system is swapping. That kills performance, pretty much across the 
> > > board. Either buy more memory or accept the impact of an underprovisioned 
> > > machine on the performance of mail delivery.
> > > 
> > > Do you really need your mail to be delivered _that_ promptly? If 
> > > interactive performance is acceptable then what does it matter if an email 
> > > (delivered in the background) takes 30 seconds or 300 seconds to be 
> > > stuffed into your inbox?
> >
> > Thanks for the input John, I can accept 30 or 45 seconds of drive access
> > however when it comes to 300 I can't accept that. And you're absolutely
> 
> If it's really drive access, it smells like trashing (or you have an
> awfully and incredibly slow I/O subsystem).
> 5 minutes is almost zero in the email world. SMTP never was real-time
> anyway.
> 
> > correct, the problem is my lack of memory I realize that now. 
> 
> How many of the various daemons (spamd, clamd, mimedefang, MTAs) do you
> run (even potentially) in parallel?
> And how much (unshared) RSS do they take?
> Just limit that to, say 2 or 3 of each, if only to avoid trashing.
> 
> FWIW I had a similar situation (on much larger hardware. But running 80
> mimedefang processes in parallel doesn't make too much sense anyways -
> even with 4 CPUs).
> 
> 	Bernd

One spamd process now (had two before), one clamd process (since
stopped) and postfix to process spam reports and local mail
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
18330 root      20   0 66504  56m  632 S  0.0  7.5   0:00.00 spamd 

USER    PID  %CPU %MEM    VSZ   RSS TTY      STAT  START   TIME COMMAND
root    11589 0.3  7.5  67936  58676 ?        S    16:21   0:05
spamdchild
postfix 6582  0.0  0.1   4024  1252 ?        S    15:53   0:00 pickup -l
-t fifo
postfix 20985 0.0  0.0   4164   684 ?        S    Aug04   0:05 qmgr -l
-t fifo -



-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Bernd Petrovitsch <be...@petrovitsch.priv.at>.
On Son, 2010-09-05 at 17:44 -0500, Chris wrote:
> On Sun, 2010-09-05 at 12:54 -0700, John Hardin wrote:
> > On Sun, 5 Sep 2010, Chris wrote:
> > 
> > > On Sun, 2010-09-05 at 12:33 -0500, Len Conrad wrote:
> > >>> Mem:    772880k total,   685316k used,    87564k free,    31344k buffers
> > >>> Swap:  1076312k total,   249032k used,   827280k free,   156328k cached
> > >>
> > >> 250MB swapped, for less than 1 GB RAM, used is disastrous for an MTA.
> > >>
> > >> Increase RAM to 2GB, or until swap is always "0k used"
> > >
> > > It's just a single user home system. True, I probably do need to 
> > > increase ram but I 'don't' think this has a bearing on this issue though 
> > > I may be wrong.
> > 
> > Your system is swapping. That kills performance, pretty much across the 
> > board. Either buy more memory or accept the impact of an underprovisioned 
> > machine on the performance of mail delivery.
> > 
> > Do you really need your mail to be delivered _that_ promptly? If 
> > interactive performance is acceptable then what does it matter if an email 
> > (delivered in the background) takes 30 seconds or 300 seconds to be 
> > stuffed into your inbox?
>
> Thanks for the input John, I can accept 30 or 45 seconds of drive access
> however when it comes to 300 I can't accept that. And you're absolutely

If it's really drive access, it smells like trashing (or you have an
awfully and incredibly slow I/O subsystem).
5 minutes is almost zero in the email world. SMTP never was real-time
anyway.

> correct, the problem is my lack of memory I realize that now. 

How many of the various daemons (spamd, clamd, mimedefang, MTAs) do you
run (even potentially) in parallel?
And how much (unshared) RSS do they take?
Just limit that to, say 2 or 3 of each, if only to avoid trashing.

FWIW I had a similar situation (on much larger hardware. But running 80
mimedefang processes in parallel doesn't make too much sense anyways -
even with 4 CPUs).

	Bernd
-- 
Bernd Petrovitsch                  Email : bernd@petrovitsch.priv.at
                     LUGA : http://www.luga.at


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Sun, 2010-09-05 at 12:54 -0700, John Hardin wrote:
> On Sun, 5 Sep 2010, Chris wrote:
> 
> > On Sun, 2010-09-05 at 12:33 -0500, Len Conrad wrote:
> >>> Mem:    772880k total,   685316k used,    87564k free,    31344k buffers
> >>> Swap:  1076312k total,   249032k used,   827280k free,   156328k cached
> >>
> >> 250MB swapped, for less than 1 GB RAM, used is disastrous for an MTA.
> >>
> >> Increase RAM to 2GB, or until swap is always "0k used"
> >
> > It's just a single user home system. True, I probably do need to 
> > increase ram but I 'don't' think this has a bearing on this issue though 
> > I may be wrong.
> 
> Your system is swapping. That kills performance, pretty much across the 
> board. Either buy more memory or accept the impact of an underprovisioned 
> machine on the performance of mail delivery.
> 
> Do you really need your mail to be delivered _that_ promptly? If 
> interactive performance is acceptable then what does it matter if an email 
> (delivered in the background) takes 30 seconds or 300 seconds to be 
> stuffed into your inbox?

Thanks for the input John, I can accept 30 or 45 seconds of drive access
however when it comes to 300 I can't accept that. And you're absolutely
correct, the problem is my lack of memory I realize that now. 

> How many email users is this supporting? You might want to consider some 
> glue-level performance hacks - for example, if your box is supporting 
> email for your family members, and all delivery for that is local, then 
> you could configure your MTA to not pass locally-originated-and-destined 
> messages through clamav or SA at all.
> 
Just one user, me, though I already have procmail setup to not pass mail
destined for mailing list through SA or ClamAv. I had SA set to check
message size less than 250k in my procmailrc I've dropped it to 50k and
will see what happens. I could probably drop some of the extra rulesets
I run also which would probably cut down on access until I can upgrade
my memory. I'm going to consider this thread closed then as being solved
with "upgrade to more memory". Many thanks to all who replied and
offered suggestions. And to the SA Team, keep up the great work!

Chris
 
-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by John Hardin <jh...@impsec.org>.
On Sun, 5 Sep 2010, Chris wrote:

> On Sun, 2010-09-05 at 12:33 -0500, Len Conrad wrote:
>>> Mem:    772880k total,   685316k used,    87564k free,    31344k buffers
>>> Swap:  1076312k total,   249032k used,   827280k free,   156328k cached
>>
>> 250MB swapped, for less than 1 GB RAM, used is disastrous for an MTA.
>>
>> Increase RAM to 2GB, or until swap is always "0k used"
>
> It's just a single user home system. True, I probably do need to 
> increase ram but I 'don't' think this has a bearing on this issue though 
> I may be wrong.

Your system is swapping. That kills performance, pretty much across the 
board. Either buy more memory or accept the impact of an underprovisioned 
machine on the performance of mail delivery.

Do you really need your mail to be delivered _that_ promptly? If 
interactive performance is acceptable then what does it matter if an email 
(delivered in the background) takes 30 seconds or 300 seconds to be 
stuffed into your inbox?

How many email users is this supporting? You might want to consider some 
glue-level performance hacks - for example, if your box is supporting 
email for your family members, and all delivery for that is local, then 
you could configure your MTA to not pass locally-originated-and-destined 
messages through clamav or SA at all.

-- 
  John Hardin KA7OHZ                    http://www.impsec.org/~jhardin/
  jhardin@impsec.org    FALaholic #11174     pgpk -a jhardin@impsec.org
  key: 0xB8732E79 -- 2D8C 34F4 6411 F507 136C  AF76 D822 E6E6 B873 2E79
-----------------------------------------------------------------------
   Sheep have only two speeds: graze and stampede.     -- LTC Grossman
-----------------------------------------------------------------------
  12 days until the 223rd anniversary of the signing of the U.S. Constitution

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Sun, 2010-09-05 at 12:33 -0500, Len Conrad wrote:
> >Mem:    772880k total,   685316k used,    87564k free,    31344k buffers
> >Swap:  1076312k total,   249032k used,   827280k free,   156328k cached
> 
> 250MB swapped, for less than 1 GB RAM, used is disastrous for an MTA.  
> 
> Increase RAM to 2GB, or until swap is always "0k used"
> 
> Len
> 
It's just a single user home system. True, I probably do need to
increase ram but I 'don't' think this has a bearing on this issue though
I may be wrong.

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Len Conrad <LC...@Go2France.com>.
>Mem:    772880k total,   685316k used,    87564k free,    31344k buffers
>Swap:  1076312k total,   249032k used,   827280k free,   156328k cached

250MB swapped, for less than 1 GB RAM, used is disastrous for an MTA.  

Increase RAM to 2GB, or until swap is always "0k used"

Len




Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Sun, 2010-09-05 at 09:18 -0700, John Hardin wrote:
> On Sat, 4 Sep 2010, Chris wrote:
> 
> > Running an X session, and I noticed that this is back:
> 
> How much memory in that box?
> 

754Mb and 1Gb swap, top shows

top - 12:16:19 up 51 days, 16:18,  2 users,  load average: 0.31, 0.37,
0.65
Tasks: 179 total,   1 running, 178 sleeping,   0 stopped,   0 zombie
Cpu(s): 10.3%us,  4.7%sy,  0.0%ni, 85.0%id,  0.0%wa,  0.0%hi,  0.0%si,
0.0%st
Mem:    772880k total,   685316k used,    87564k free,    31344k buffers
Swap:  1076312k total,   249032k used,   827280k free,   156328k cached

Spamd shows

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
22587 root      20   0 86500  77m 3192 S  0.0 10.3   0:11.96 spamd 


-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by John Hardin <jh...@impsec.org>.
On Sat, 4 Sep 2010, Chris wrote:

> Running an X session, and I noticed that this is back:

How much memory in that box?

-- 
  John Hardin KA7OHZ                    http://www.impsec.org/~jhardin/
  jhardin@impsec.org    FALaholic #11174     pgpk -a jhardin@impsec.org
  key: 0xB8732E79 -- 2D8C 34F4 6411 F507 136C  AF76 D822 E6E6 B873 2E79
-----------------------------------------------------------------------
   If Microsoft made hammers, everyone would whine about how poorly
   screws were designed and about how they are hard to hammer in, and
   wonder why it takes so long to paint a wall using the hammer.
-----------------------------------------------------------------------
  12 days until the 223rd anniversary of the signing of the U.S. Constitution

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Sat, 2010-09-04 at 17:55 -0700, John Hardin wrote: 
> On Sat, 4 Sep 2010, Chris wrote:
> 
> > On Sat, 2010-09-04 at 14:33 -0700, John Hardin wrote:
> >> On Sat, 4 Sep 2010, Chris wrote:
> >>
> >>> I'm trying to figure out why I'm having ridiculous scan times such as
> >>> the above examples. Lower scan times such as in the 20 second range are
> >>> the exception rather than the rule. I'm running bind as a local caching
> >>> nameserver and it seems to be working correctly. I've just seen a ham
> >>> that has a scantime=172.2. Could there be something else on the system
> >>> that is affecting this?
> >>>
> >>> Any advice as to troubleshooting would be appreciated.
> >>
> >> What version of SA, and are you current on updates (have you run sa-update
> >> recently)?
> >>
> >> Would it be possible to post an example message that exhibits the problem?
> >
> > Hi John, version is 3.3.0 and updates was last run at 5:11pm. Here is a
> > link to a spam that took 302s to process http://ez-files.net/445403
> 
> Thanks.
> 
> ClamAV took almost a minute and a half to scan that message.
> 
> All of the steps seem slow. I'd suggest that it isn't any particular bad 
> rule, so much as the system appears overloaded.
> 
> > Awhile ago I logged out and logged back in again, I no longer am seeing
> > the above and scan times have decreased considerably,
> > ham - scantime=5.7
> > and for a spam that just came in
> > scantime=1.6
> >
> > Things seem back to normal, for now, though I'm not sure how long
> > they'll last. Any idea what could be causing the above?
> 
> That's odd. Are you running in an X session or character? Was there some 
> other process bogging the system or taking up lots of memory such that it 
> was swapping, which got killed when you logged out?
> 

Running an X session, and I noticed that this is back:

Sep  4 21:03:50 localhost spamd[8668]: spamd: server successfully
spawned child process, pid 8761
Sep  4 21:03:50 localhost spamd[8668]: prefork: child 8761: entering
state 0
Sep  4 21:03:50 localhost spamd[8668]: prefork: new lowest idle kid:
none
Sep  4 21:03:50 localhost spamd[8761]: prefork: sysread(8) not ready,
wait max 300 secs
Sep  4 21:03:50 localhost spamd[8668]: spamd: server successfully
spawned child process, pid 8766
Sep  4 21:03:50 localhost spamd[8668]: prefork: child 8766: entering
state 0
Sep  4 21:03:50 localhost spamd[8668]: prefork: new lowest idle kid:
none
Sep  4 21:03:50 localhost spamd[8766]: prefork: sysread(9) not ready,
wait max 300 secs
Sep  4 21:03:50 localhost spamd[8668]: prefork: child 8761: entering
state 1
Sep  4 21:03:50 localhost spamd[8668]: prefork: new lowest idle kid:
8761
Sep  4 21:03:50 localhost spamd[8668]: prefork: child reports idle
Sep  4 21:03:50 localhost spamd[8668]: prefork: child states: IS

I've logged out and in again and restarted SA so the above is from
running 'service spamassassin restart'. Just what is the sysread(#) not
ready error mean?

-- 
Chris
KeyID 0xE372A7DA98E6705C




Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by John Hardin <jh...@impsec.org>.
On Sat, 4 Sep 2010, Chris wrote:

> On Sat, 2010-09-04 at 14:33 -0700, John Hardin wrote:
>> On Sat, 4 Sep 2010, Chris wrote:
>>
>>> I'm trying to figure out why I'm having ridiculous scan times such as
>>> the above examples. Lower scan times such as in the 20 second range are
>>> the exception rather than the rule. I'm running bind as a local caching
>>> nameserver and it seems to be working correctly. I've just seen a ham
>>> that has a scantime=172.2. Could there be something else on the system
>>> that is affecting this?
>>>
>>> Any advice as to troubleshooting would be appreciated.
>>
>> What version of SA, and are you current on updates (have you run sa-update
>> recently)?
>>
>> Would it be possible to post an example message that exhibits the problem?
>
> Hi John, version is 3.3.0 and updates was last run at 5:11pm. Here is a
> link to a spam that took 302s to process http://ez-files.net/445403

Thanks.

ClamAV took almost a minute and a half to scan that message.

All of the steps seem slow. I'd suggest that it isn't any particular bad 
rule, so much as the system appears overloaded.

> Awhile ago I logged out and logged back in again, I no longer am seeing
> the above and scan times have decreased considerably,
> ham - scantime=5.7
> and for a spam that just came in
> scantime=1.6
>
> Things seem back to normal, for now, though I'm not sure how long
> they'll last. Any idea what could be causing the above?

That's odd. Are you running in an X session or character? Was there some 
other process bogging the system or taking up lots of memory such that it 
was swapping, which got killed when you logged out?

-- 
  John Hardin KA7OHZ                    http://www.impsec.org/~jhardin/
  jhardin@impsec.org    FALaholic #11174     pgpk -a jhardin@impsec.org
  key: 0xB8732E79 -- 2D8C 34F4 6411 F507 136C  AF76 D822 E6E6 B873 2E79
-----------------------------------------------------------------------
   It is criminal to teach a man not to defend himself when he is the
   constant victim of brutal attacks.              -- Malcolm X (1964)
-----------------------------------------------------------------------
  13 days until the 223rd anniversary of the signing of the U.S. Constitution

Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by Chris <cp...@embarqmail.com>.
On Sat, 2010-09-04 at 14:33 -0700, John Hardin wrote:
> On Sat, 4 Sep 2010, Chris wrote:
> 
> > I'm trying to figure out why I'm having ridiculous scan times such as
> > the above examples. Lower scan times such as in the 20 second range are
> > the exception rather than the rule. I'm running bind as a local caching
> > nameserver and it seems to be working correctly. I've just seen a ham
> > that has a scantime=172.2. Could there be something else on the system
> > that is affecting this?
> >
> > Any advice as to troubleshooting would be appreciated.
> 
> What version of SA, and are you current on updates (have you run sa-update 
> recently)?
> 
> Would it be possible to post an example message that exhibits the problem?
> 

Hi John, version is 3.3.0 and updates was last run at 5:11pm. Here is a
link to a spam that took 302s to process http://ez-files.net/445403

-- 
Chris
KeyID 0xE372A7DA98E6705C


Re: scantime=249.2; scantime=175.0; scantime=190.9; scantime=68.9

Posted by John Hardin <jh...@impsec.org>.
On Sat, 4 Sep 2010, Chris wrote:

> I'm trying to figure out why I'm having ridiculous scan times such as
> the above examples. Lower scan times such as in the 20 second range are
> the exception rather than the rule. I'm running bind as a local caching
> nameserver and it seems to be working correctly. I've just seen a ham
> that has a scantime=172.2. Could there be something else on the system
> that is affecting this?
>
> Any advice as to troubleshooting would be appreciated.

What version of SA, and are you current on updates (have you run sa-update 
recently)?

Would it be possible to post an example message that exhibits the problem?

-- 
  John Hardin KA7OHZ                    http://www.impsec.org/~jhardin/
  jhardin@impsec.org    FALaholic #11174     pgpk -a jhardin@impsec.org
  key: 0xB8732E79 -- 2D8C 34F4 6411 F507 136C  AF76 D822 E6E6 B873 2E79
-----------------------------------------------------------------------
   Microsoft is not a standards body.
-----------------------------------------------------------------------
  13 days until the 223rd anniversary of the signing of the U.S. Constitution