List Info

Thread: TimeElapsedReceiving




TimeElapsedReceiving
country flaguser name
Germany
2008-01-15 07:12:10
Hi Mark,

I am using Amavisd-new only for virus scanning and have the
following
timings in amavisd-agent:

TimeElapsedReceiving                 10992 s      0.397
s/msg (InMsgs)
TimeElapsedSending                      44 s      0.002
s/msg (InMsgs)
TimeElapsedTotal                     17688 s      0.711
s/msg (InMsgs)
TimeElapsedVirusCheck                 5917 s      0.282
s/msg (InMsgs)

Could you explain what TimeElapsedReceiving is? I have
$bypass_decode_parts=1.

Thank you!
David

PS: It would be cool to have in amavisd-agent statistics
about running
    times for the different AV engines, like there is in the
timing
    report with $log_level=2

------------------------------------------------------------
-------------
Check out the new SourceForge.net Marketplace.
It's the best place to buy or sell services for
just about anything Open Source.
http://ad.doubleclick.net/clk;164216
239;13503038;w?http://sf.net/marketplace
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Re: TimeElapsedReceiving
country flaguser name
Slovenia
2008-01-15 07:51:09
David,

> I am using Amavisd-new only for virus scanning and have
the following
> timings in amavisd-agent:
> TimeElapsedReceiving                 10992 s      0.397
s/msg (InMsgs)
> TimeElapsedSending                      44 s      0.002
s/msg (InMsgs)
> TimeElapsedTotal                     17688 s      0.711
s/msg (InMsgs)
> TimeElapsedVirusCheck                 5917 s      0.282
s/msg (InMsgs)
>
> Could you explain what TimeElapsedReceiving is? I have
> $bypass_decode_parts=1.

TimeElapsedReceiving is the elapsed time (wall clock)
between
the reception of a MAIL FROM smtp command from a MTA (this
is where
a new smtp transaction starts) and the time when content
checking
begins (when check_mail() is called), so this time interval
consists
mostly of a data transfer of a message from MTA to amavisd
(RCPT TO and DATA smtp commands).

> PS: It would be cool to have in amavisd-agent
statistics about running
>     times for the different AV engines, like there is
in the timing
>     report with $log_level=2

The TimeElapsed* counters are collected at a top level of a
program
flow and are of rather course granularity. The fine
granularity timing
measurements are more finely intertwined in the code and end
up
in log level 2 logging. In principle there could be more
TimeElapsed*
counters, but then one could always say: why this one and
not also
that one, so I have to draw a line somewhere.

For occasional assessment you could run a one-liner Perl
command
across a log to collect times of interesting tasks, and
perhaps
plot a scattergram (gnuplot) for each such task. The
diagram
could be more revealing than a cumulative value.

  Mark

------------------------------------------------------------
-------------
Check out the new SourceForge.net Marketplace.
It's the best place to buy or sell services for
just about anything Open Source.
http://ad.doubleclick.net/clk;164216
239;13503038;w?http://sf.net/marketplace
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Re: TimeElapsedReceiving
country flaguser name
Germany
2008-01-15 08:22:32
On Tue, Jan 15, 2008 at 14:51:09 +0100, Mark Martinec
wrote:
> TimeElapsedReceiving is the elapsed time (wall clock)
between
> the reception of a MAIL FROM smtp command from a MTA
(this is where
> a new smtp transaction starts) and the time when
content checking
> begins (when check_mail() is called), so this time
interval consists
> mostly of a data transfer of a message from MTA to
amavisd
> (RCPT TO and DATA smtp commands).

Ah, OK. So basically this a value that describes more the
behaviour of
the SMTP clients than the performance of the content
scanner.

> The TimeElapsed* counters are collected at a top level
of a program
> flow and are of rather course granularity. The fine
granularity timing
> measurements are more finely intertwined in the code
and end up
> in log level 2 logging. In principle there could be
more TimeElapsed*
> counters, but then one could always say: why this one
and not also
> that one, so I have to draw a line somewhere.

I understand. log_level=2 is not really an option for us,
however,
because we don't want to log that much for every mail. I can
live with
it though 

> For occasional assessment you could run a one-liner
Perl command
> across a log to collect times of interesting tasks, and
perhaps
> plot a scattergram (gnuplot) for each such task. The
diagram
> could be more revealing than a cumulative value.

Yep, that's what I am going to do if we have performance
issues and I
want to find out where the bottleneck is. The timing report
is really
cool.

Thanks again for all the answers
David

------------------------------------------------------------
-------------
This SF.net email is sponsored by: Microsoft
Defy all challenges. Microsoft(R) Visual Studio 2008.
http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Re: TimeElapsedReceiving
country flaguser name
Slovenia
2008-01-15 08:46:41
David,

> > TimeElapsedReceiving is the ...
>
> Ah, OK. So basically this a value that describes more
the behaviour of
> the SMTP clients than the performance of the content
scanner.

Yes. Actually this time is dominated by the tight loop which
unfortunately 
needs to read input line-by-line to do dot-destuffing, and
to reset
a watchdog timer with each line, as expected for a SMTP
server.
A CHUNKING support on the Postfix client-side would improve
the
transfer rate, although it is not too bad as it is.

Interestingly, the sending side (smtp from amavisd to MTA)
is an order of magnitude faster, due to the use of large
buffers (avoiding line-by-line I/O). The pipelining brings
its benefits there too.


> I understand. log_level=2 is not really an option for
us, however,
> because we don't want to log that much for every mail.
I can live with
> it though 

We keep three log files for amavisd at different syslog
priorities:

user.notice   /var/log/amavisd.log
user.info     /var/log/amavisd-info.log
user.debug    /var/log/amavisd-debug.log

The compact amavisd.log is kept for long times and
archived.

The amavisd-info.log (corresponds to log level 2) is kept
for
a week or two, and consulted for problem and timing
analysis,
then is discarded.

The amavisd-debug.log is kept for few days and is used for
analysis of problems which might have occurred in the last
few days, and sometimes for selective displaying of some
particular log entry, e.g.
  tail -f /var/log/amavisd-debug.log | 
    pcregrep 'SA dbg: dkim: |_WARN:|_DIE:|TROUBLE'

The $log_level is set to 5, and the log level to syslog
priority
mapping is as described in 2.6.0-pre3 release notes:


  The following table shows mapping of SpamAssassin log
levels to amavisd
  log levels, and for completeness also shows mapping of
amavisd log levels
  to syslog priorities (which has not changed since previous
version):

    SA     amavisd  syslog
    -----  -------  -----------
             -3     LOG_CRIT
             -2     LOG_ERR
    error    -1     LOG_WARNING
    warn      0     LOG_NOTICE
    info      1     LOG_INFO
              2     LOG_INFO
    dbg       3     LOG_DEBUG
              4     LOG_DEBUG
              5     LOG_DEBUG


One needs to make sure the syslogd does not sync a log file
to disk
on every write (a default on Linux).

  Mark

------------------------------------------------------------
-------------
This SF.net email is sponsored by: Microsoft
Defy all challenges. Microsoft(R) Visual Studio 2008.
http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Re: TimeElapsedReceiving
country flaguser name
Germany
2008-01-15 10:39:05
Hi Mark,

On Tue, Jan 15, 2008 at 15:46:41 +0100, Mark Martinec
wrote:
> We keep three log files for amavisd at different syslog
priorities:
> 
> user.notice   /var/log/amavisd.log
> user.info     /var/log/amavisd-info.log
> user.debug    /var/log/amavisd-debug.log
> 
> The compact amavisd.log is kept for long times and
archived.
> 
> The amavisd-info.log (corresponds to log level 2) is
kept for
> a week or two, and consulted for problem and timing
analysis,
> then is discarded.
>
> [...]

Yes, that could work for us too. Thanks again for the help!

Cheers
David

------------------------------------------------------------
-------------
This SF.net email is sponsored by: Microsoft
Defy all challenges. Microsoft(R) Visual Studio 2008.
http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

[1-5]

about | contact  Other archives ( Real Estate discussion Medical topics )