On 11 Feb 2004 09:42:27 -0500
Tom Anderson wrote:
> On Sat, 2004-02-07 at 11:12, Tom Anderson wrote:
> > Total running time was 21 wallclock secs, 8.01 CPU secs.
> > 0.003 CPU secs/line, 0.4 CPU secs/email.
> > Bfproxy required 0.41 usr + 0.22 sys = 0.63 CPU secs.
> > Bogofilter required 0.99 usr + 6.39 sys = 7.38 CPU secs.
> >
> > It seems that the Bogofilter child process required lots of system
> > time compared to user time, which I think is unusual. This could
> > have to do with running through Open2, but I was wondering if anyone
> > benchmarked bogofilter from the command line and had a similar
> > ratio.
>
> Just to follow up on this observation, I also timed bogofilter from
> the command line, and it still showed a very high ratio of system time
> to user time. The system time was consistently on the order of 10x
> greater than the user time. As noted at
> http://oscinfo.osc.edu/computing/gen-perf.shtml, "the user time is
> usually significantly greater than the system time. Indeed, a high
> ratio of system to user CPU time may indicate a problem. Exceptions
> such as page faults, misaligned memory references, and floating-point
> exceptions consume a large amount of system time."
>
> Moreover, the verbose output of "time" shows consistently 308 major
> page faults, and varies between 300-600 minor page faults. The
> results follow:
Tom,
Below are some timings from my 500Mhz PIII system using the current
release (which has no significant differences compared to what you're
using).
With my 66M wordlist, none of the 5 messages took longer than 0.81s cpu
time. Running all 5 as a batch took 3.64s of clock time:
0.18user 0.19system 0:03.64elapsed 10%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (2143major+2820minor)pagefaults 0swaps
Wed Feb 11 20:57:34 EST 2004
I don't presently have any idea why you're seeing the slow times you
report. There _are_ page faults, but they don't much seem to matter.
If you can find info on why they matter and how to find their cause,
I'll look further into page faults and how they can be minimized.
That's all I know :-)
David
[relson at osage 2004-02-Spam]$ bogofilter -V
bogofilter version 0.17.1
Database: BerkeleyDB (4.1.25)
Copyright (C) 2002-2004 Eric S. Raymond,
David Relson, Matthias Andree, Greg Louis
[relson at osage 2004-02-Spam]$ ls -lh $BOGOFILTER_DIR/*.db
-rw-r----- 1 relson relson 66M Feb 11 20:45
spam-fixups/wordlist.h.16/wordlist.db
[relson at osage 2004-02-Spam]$ for n in 1019 1036 1037 1046 1067 ; do \
time -v bogofilter -sv -I $n \
echo "" \
done
# 599 words, 1 message
Command being timed: "bogofilter -sv -I 1019"
User time (seconds): 0.03
System time (seconds): 0.06
Percent of CPU this job got: 11%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.81
Major (requiring I/O) page faults: 281
Minor (reclaiming a frame) page faults: 607
# 518 words, 1 message
Command being timed: "bogofilter -sv -I 1036"
User time (seconds): 0.04
System time (seconds): 0.03
Percent of CPU this job got: 10%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.68
Major (requiring I/O) page faults: 284
Minor (reclaiming a frame) page faults: 471
# 642 words, 1 message
Command being timed: "bogofilter -sv -I 1037"
User time (seconds): 0.03
System time (seconds): 0.03
Percent of CPU this job got: 8%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.72
Major (requiring I/O) page faults: 284
Minor (reclaiming a frame) page faults: 495
# 642 words, 1 message
Command being timed: "bogofilter -sv -I 1046"
User time (seconds): 0.03
System time (seconds): 0.05
Percent of CPU this job got: 11%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.66
Major (requiring I/O) page faults: 282
Minor (reclaiming a frame) page faults: 491
# 1007 words, 1 message
Command being timed: "bogofilter -sv -I 1067"
User time (seconds): 0.00
System time (seconds): 0.05
Percent of CPU this job got: 6%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.73
Major (requiring I/O) page faults: 284
Minor (reclaiming a frame) page faults: 462
*** as above, but with "-k 100" (db_cachesize=100)
# 599 words, 1 message
Command being timed: "bogofilter -sv -I 1019 -k 100"
User time (seconds): 0.06
System time (seconds): 0.04
Percent of CPU this job got: 12%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.81
Major (requiring I/O) page faults: 281
Minor (reclaiming a frame) page faults: 918
# 518 words, 1 message
Command being timed: "bogofilter -sv -I 1036 -k 100"
User time (seconds): 0.04
System time (seconds): 0.02
Percent of CPU this job got: 10%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.59
Major (requiring I/O) page faults: 281
Minor (reclaiming a frame) page faults: 771
# 642 words, 1 message
Command being timed: "bogofilter -sv -I 1037 -k 100"
User time (seconds): 0.04
System time (seconds): 0.02
Percent of CPU this job got: 8%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.69
Major (requiring I/O) page faults: 281
Minor (reclaiming a frame) page faults: 800
# 642 words, 1 message
Command being timed: "bogofilter -sv -I 1046 -k 100"
User time (seconds): 0.03
System time (seconds): 0.04
Percent of CPU this job got: 10%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.67
Major (requiring I/O) page faults: 281
Minor (reclaiming a frame) page faults: 800
# 1007 words, 1 message
Command being timed: "bogofilter -sv -I 1067 -k 100"
User time (seconds): 0.03
System time (seconds): 0.05
Percent of CPU this job got: 10%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.77
Major (requiring I/O) page faults: 281
Minor (reclaiming a frame) page faults: 770