http://issues.apache.org/SpamAssassin/show_bug.cgi?id=5356
[EMAIL PROTECTED] changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|RESOLVED |REOPENED
Resolution|FIXED |
------- Additional Comments From [EMAIL PROTECTED] 2007-11-20 08:36 -------
(In reply to comment #5)
> Now here is one (rather small) diff which may deserve attention of others.
> It provides access to the timing report for a caller through a tag TIMING
> through the usual $pms->get mechanism. I find it very convenient (amavisd),
> not having to turn up SpamAssassin debugging just in order to get that report.
>
> I'm checking it in to trunk, it is easy to take it out if it turns out
> not to be desired:
>
> svn -m 'Make a timing report accessible to a caller as a tag TIMING' ci
> Sending lib/Mail/SpamAssassin/PerMsgStatus.pm
> Sending lib/Mail/SpamAssassin.pm
> Transmitting file data ..
> Committed revision 569445.
>
>
> One gocha is that timestamps need to be collected regardless
> of would_log('timing'), so I'm commenting out jm's changes in #4.
>
> >> What is the performance impact of adding all those calls?
> > I've made it all conditional on would_log('timing') -- so now,
> > lost in the noise, unless debug is active
>
> A call to HiRes::time is very quick. There are some other simple
> statements around, but it all looks very straightforward.
> I'd say that taking out a call to would_log() already saves
> a substantial proportion of the added overhead :)
we may need to revisit this. I noticed in an strace of svn trunk that we now
call time() or gettimeofday() excessively:
strace -f ./spamassassin --lint
...
brk(0x9f05000) = 0x9f05000
brk(0x9f26000) = 0x9f26000
brk(0x9f47000) = 0x9f47000
brk(0x9f68000) = 0x9f68000
brk(0x9f89000) = 0x9f89000
brk(0x9faa000) = 0x9faa000
brk(0x9fcb000) = 0x9fcb000
brk(0x9fec000) = 0x9fec000
brk(0xa00d000) = 0xa00d000
brk(0xa02f000) = 0xa02f000
brk(0xa050000) = 0xa050000
brk(0xa071000) = 0xa071000
brk(0xa092000) = 0xa092000
brk(0xa0b3000) = 0xa0b3000
brk(0xa0d4000) = 0xa0d4000
brk(0xa0f5000) = 0xa0f5000
brk(0xa120000) = 0xa120000
brk(0xa149000) = 0xa149000
munmap(0xb77ea000, 618496) = 0
gettimeofday({1195576396, 845330}, NULL) = 0
gettimeofday({1195576396, 845362}, NULL) = 0
brk(0xa16b000) = 0xa16b000
gettimeofday({1195576396, 852767}, NULL) = 0
gettimeofday({1195576396, 852956}, NULL) = 0
brk(0xa19d000) = 0xa19d000
brk(0xa1c0000) = 0xa1c0000
brk(0xa1e4000) = 0xa1e4000
brk(0xa205000) = 0xa205000
brk(0xa227000) = 0xa227000
brk(0xa248000) = 0xa248000
gettimeofday({1195576396, 870791}, NULL) = 0
gettimeofday({1195576396, 870909}, NULL) = 0
gettimeofday({1195576396, 876527}, NULL) = 0
gettimeofday({1195576396, 876644}, NULL) = 0
gettimeofday({1195576396, 877492}, NULL) = 0
gettimeofday({1195576396, 877603}, NULL) = 0
brk(0xa269000) = 0xa269000
gettimeofday({1195576396, 878512}, NULL) = 0
gettimeofday({1195576396, 878634}, NULL) = 0
gettimeofday({1195576396, 878953}, NULL) = 0
gettimeofday({1195576396, 879074}, NULL) = 0
gettimeofday({1195576396, 879477}, NULL) = 0
gettimeofday({1195576396, 879590}, NULL) = 0
gettimeofday({1195576396, 879718}, NULL) = 0
gettimeofday({1195576396, 879830}, NULL) = 0
gettimeofday({1195576396, 879958}, NULL) = 0
gettimeofday({1195576396, 880090}, NULL) = 0
gettimeofday({1195576396, 880232}, NULL) = 0
gettimeofday({1195576396, 880341}, NULL) = 0
gettimeofday({1195576396, 880458}, NULL) = 0
gettimeofday({1195576396, 880784}, NULL) = 0
gettimeofday({1195576396, 880894}, NULL) = 0
gettimeofday({1195576396, 881206}, NULL) = 0
gettimeofday({1195576396, 881316}, NULL) = 0
gettimeofday({1195576396, 881439}, NULL) = 0
gettimeofday({1195576396, 881549}, NULL) = 0
gettimeofday({1195576396, 881804}, NULL) = 0
gettimeofday({1195576396, 881915}, NULL) = 0
gettimeofday({1195576396, 882164}, NULL) = 0
gettimeofday({1195576396, 882276}, NULL) = 0
gettimeofday({1195576396, 882399}, NULL) = 0
gettimeofday({1195576396, 882509}, NULL) = 0
gettimeofday({1195576396, 882765}, NULL) = 0
gettimeofday({1195576396, 882878}, NULL) = 0
gettimeofday({1195576396, 883000}, NULL) = 0
gettimeofday({1195576396, 883110}, NULL) = 0
gettimeofday({1195576396, 883391}, NULL) = 0
gettimeofday({1195576396, 883503}, NULL) = 0
gettimeofday({1195576396, 883626}, NULL) = 0
gettimeofday({1195576396, 883736}, NULL) = 0
brk(0xa28b000) = 0xa28b000
brk(0xa2ae000) = 0xa2ae000
brk(0xa2d0000) = 0xa2d0000
brk(0xa2fa000) = 0xa2fa000
brk(0xa31b000) = 0xa31b000
brk(0xa33c000) = 0xa33c000
brk(0xa35d000) = 0xa35d000
brk(0xa37e000) = 0xa37e000
brk(0xa39f000) = 0xa39f000
brk(0xa3c0000) = 0xa3c0000
brk(0xa3e1000) = 0xa3e1000
brk(0xa40f000) = 0xa40f000
gettimeofday({1195576396, 936268}, NULL) = 0
gettimeofday({1195576396, 936297}, NULL) = 0
gettimeofday({1195576396, 936343}, NULL) = 0
gettimeofday({1195576396, 936363}, NULL) = 0
gettimeofday({1195576396, 936480}, NULL) = 0
gettimeofday({1195576396, 936528}, NULL) = 0
gettimeofday({1195576396, 936574}, NULL) = 0
gettimeofday({1195576396, 936594}, NULL) = 0
gettimeofday({1195576396, 936876}, NULL) = 0
gettimeofday({1195576396, 936899}, NULL) = 0
gettimeofday({1195576396, 937280}, NULL) = 0
gettimeofday({1195576396, 937303}, NULL) = 0
gettimeofday({1195576396, 937484}, NULL) = 0
gettimeofday({1195576396, 937507}, NULL) = 0
gettimeofday({1195576396, 937694}, NULL) = 0
gettimeofday({1195576396, 937717}, NULL) = 0
gettimeofday({1195576396, 937765}, NULL) = 0
gettimeofday({1195576396, 937785}, NULL) = 0
gettimeofday({1195576396, 937963}, NULL) = 0
gettimeofday({1195576396, 937985}, NULL) = 0
gettimeofday({1195576396, 938029}, NULL) = 0
gettimeofday({1195576396, 938049}, NULL) = 0
gettimeofday({1195576396, 938219}, NULL) = 0
gettimeofday({1195576396, 938241}, NULL) = 0
gettimeofday({1195576396, 938290}, NULL) = 0
gettimeofday({1195576396, 938310}, NULL) = 0
gettimeofday({1195576396, 938538}, NULL) = 0
gettimeofday({1195576396, 938560}, NULL) = 0
gettimeofday({1195576396, 938600}, NULL) = 0
gettimeofday({1195576396, 938620}, NULL) = 0
gettimeofday({1195576396, 938654}, NULL) = 0
stat64("/usr/lib/perl5/auto/DBI/DESTROY.al", 0x81520c8) = -1 ENOENT (No such
file or directory)
stat64("lib/auto/DBI/DESTROY.al", 0xbfcb278c) = -1 ENOENT (No such file or
directory)
stat64("/usr/local/share/perl/5.8.8/auto/DBI/DESTROY.al", 0xbfcb278c) = -1
ENOENT (No such file or directory)
stat64("/etc/perl/auto/DBI/DESTROY.al", 0xbfcb278c) = -1 ENOENT (No such file or
directory)
stat64("/usr/local/lib/perl/5.8.8/auto/DBI/DESTROY.al", 0xbfcb278c) = -1 ENOENT
(No such file or directory)
stat64("/usr/lib/perl5/auto/DBI/DESTROY.al", 0xbfcb278c) = -1 ENOENT (No such
file or directory)
stat64("/usr/share/perl5/auto/DBI/DESTROY.al", 0xbfcb278c) = -1 ENOENT (No such
file or directory)
stat64("/usr/lib/perl/5.8/auto/DBI/DESTROY.al", 0xbfcb278c) = -1 ENOENT (No such
file or directory)
stat64("/usr/share/perl/5.8/auto/DBI/DESTROY.al", 0xbfcb278c) = -1 ENOENT (No
such file or directory)
stat64("/usr/local/lib/site_perl/auto/DBI/DESTROY.al", 0xbfcb278c) = -1 ENOENT
(No such file or directory)
exit_group(0) = ?
Process 7763 detached
I'm pretty sure these are from this code.
Perhaps we can make it dependent on *either* debugs *or* a flag in the Mail::SA
constructor? then callers who wish to get the timing info via the tag, withouth
debugs active, can set the latter.
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.
