time test
Matthias Andree
matthias.andree at gmx.de
Mon Nov 25 04:38:04 CET 2002
David Relson <relson at osagesoftware.com> writes:
> Greg,
>
> For laughs, I built bogofilter with four different optimization levels.
> The compiler switches used were '-G' (no optimization), '-O1, '-O2', and
> '-O3'. bogofilter was run 1000 times on a test message.
Was that on 2.95.something or 3.2? Did you give any -march options or
what's default mandrake default -march?
Reducing on the overhead, I used a big mailbox.
SuSE Linux 8.1, default athlon kernel RPM, gcc 3.2, AMD Duron 700
("Spitfire") (model 3 stepping 1), 320 MB RAM, from hot reiserfs buffer
cache (I have some really useful data below):
-O6 -march=athlon: 31.45user 0.21system 0:38.98elapsed 81%CPU
-O2 -march=athlon: 31.36user 0.15system 0:32.48elapsed 97%CPU
-Os -march=athlon: 30.96user 0.42system 0:33.23elapsed 94%CPU
-O1 -march=athlon: 31.69user 0.25system 0:33.86elapsed 94%CPU
-O0 -march=athlon: 39.56user 0.36system 0:42.03elapsed 94%CPU
-Os -march=athlon: 30.96user 0.42system 0:33.23elapsed 94%CPU
-Os -march=pentium3: 30.73user 0.38system 0:31.95elapsed 97%CPU
-Os -march=pentium2: 31.15user 0.23system 0:33.74elapsed 92%CPU
-Os -march=i686: 30.91user 0.21system 0:32.00elapsed 97%CPU
-Os -march=i586: 31.03user 0.27system 0:35.51elapsed 88%CPU
-Os -march=i486: 31.01user 0.28system 0:33.21elapsed 94%CPU
-Os -march=i386: 30.72user 0.44system 0:32.33elapsed 96%CPU
-Os -march=pentium3 -mmx -malign-double -fomit-frame-pointer:
29.56user 0.13system 0:30.51elapsed 97%CPU
-O2 -march=pentium3 -mmx -malign-double -fomit-frame-pointer:
29.17user 0.23system 0:30.27elapsed 97%CPU
-O3 -march=pentium3 -mmx -malign-double -fomit-frame-pointer:
29.12user 0.20system 0:30.15elapsed 97%CPU
-O2 -march=pentium3 -mmx -malign-double -fomit-frame-pointer -fbranch-probabilities:
28.90user 0.19system 0:29.85elapsed 97%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (2692major+719minor)pagefaults 0swaps
So we can tweak 'bout 10%.
Running bogofilter on the individual mails, with formail -ds and
-march=pentium -mcpu=i686 -Os:
55.39user 17.87system 1:16.98elapsed 95%CPU
Not sure how much overhead formail generated, that would have to be
figured, but I'm too tired to think now.
Bogolexer takes approx. 3 s to read the input, it parses 1.93 million
tokens; showing the top three:
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
73.44 2.00 2.00 1984944 1.01 1.25 yylex
8.79 2.25 0.24 1925422 0.12 1.41 get_token
8.79 2.48 0.24 587385 0.41 0.41 lexer_fgets
And now for the real good stuff, the gprof output of bogofilter. Most of
the time is spent in collect_words and wordhash_next (as called from
collect_words). The input file has c. 587,000 lines and 2.77 million
words. The sheer number of wordhash_next calls scares me. we have
approx. 70 times the number of tokens as call amount. Is the algorithm
right? I'd thought hashes are REALLY fast. (as in O(1)). Even O(n log n)
would require a scale of 5 for the calls; n log n is 28
million. Collision issue? Or my ignorance of how wordhash_next works?
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
58.62 19.34 19.34 1 19.34 32.89 collect_words
27.96 28.57 9.22 138833114 0.00 0.00 wordhash_next
6.59 30.74 2.17 1984944 0.00 0.00 yylex
2.91 31.70 0.96 1922182 0.00 0.00 wordhash_insert
1.06 32.05 0.35 1925422 0.00 0.00 get_token
0.70 32.28 0.23 1922182 0.00 0.00 hash
0.67 32.50 0.22 587385 0.00 0.00 lexer_fgets
0.65 32.72 0.21 3241 0.00 0.00 wordhash_first
0.27 32.80 0.09 584769 0.00 0.00 yyinput
0.14 32.85 0.04 584769 0.00 0.00 yy_get_next_buffer
0.12 32.89 0.04 132155 0.00 0.00 db_getvalue
0.06 32.91 0.02 584768 0.00 0.00 yy_get_previous_state
0.06 32.93 0.02 66076 0.00 0.00 compute_probability
0.03 32.94 0.01 132401 0.00 0.00 xmalloc
0.03 32.95 0.01 132162 0.00 0.00 xstrdup
0.03 32.96 0.01 132155 0.00 0.00 db_enforce_locking
0.03 32.97 0.01 66076 0.00 0.00 nmalloc
0.03 32.98 0.01 66076 0.00 0.00 wordprop_init
0.03 32.99 0.01 1 0.01 0.10 rob_compute_spamicity
0.00 32.99 0.00 132400 0.00 0.00 xfree
0.00 32.99 0.00 132152 0.00 0.00 smalloc
0.00 32.99 0.00 66076 0.00 0.00 wordprob_init
0.00 32.99 0.00 66076 0.00 0.00 wordprob_result
0.00 32.99 0.00 65174 0.00 0.00 wordprob_add
[[ I killed all from here with < 10 calls ]]
% the percentage of the total running time of the
time program used by this function.
cumulative a running sum of the number of seconds accounted
seconds for by this function and those listed above it.
self the number of seconds accounted for by this
seconds function alone. This is the major sort for this
listing.
calls the number of times this function was invoked, if
this function is profiled, else blank.
self the average number of milliseconds spent in this
ms/call function per call, if this function is profiled,
else blank.
total the average number of milliseconds spent in this
ms/call function and its descendents per call, if this
function is profiled, else blank.
name the name of the function. This is the minor sort
for this listing. The index shows the location of
the function in the gprof listing. If the index is
in parenthesis it shows where it would appear in
the gprof listing if it were to be printed.
Call graph (explanation follows)
granularity: each sample hit covers 4 byte(s) for 0.03% of 32.99 seconds
index % time self children called name
<spontaneous>
[1] 100.0 0.00 32.99 main [1]
0.00 32.99 1/1 bogofilter [2]
0.00 0.00 1/1 setup_lists [25]
0.00 0.00 1/1 process_config_files [30]
0.00 0.00 2/2 set_dir_from_env [43]
0.00 0.00 1/1 validate_args [61]
0.00 0.00 1/1 process_args [54]
0.00 0.00 1/1 check_directory [47]
0.00 0.00 1/1 close_lists [48]
-----------------------------------------------
0.00 32.99 1/1 main [1]
[2] 100.0 0.00 32.99 1 bogofilter [2]
19.34 13.55 1/1 collect_words [3]
0.01 0.09 1/1 rob_compute_spamicity [13]
0.00 0.00 2/2 db_getcount [23]
0.00 0.00 1/1 db_lock_reader_list [51]
0.00 0.00 1/1 rob_initialize_constants [57]
0.00 0.00 1/1 rob_bogofilter [55]
0.00 0.00 1/1 db_lock_release_list [52]
0.00 0.00 1/132400 xfree [33]
0.00 0.00 1/1 wordhash_free [62]
-----------------------------------------------
19.34 13.55 1/1 bogofilter [2]
[3] 99.7 19.34 13.55 1 collect_words [3]
9.22 0.00 138767038/138833114 wordhash_next [4]
0.35 2.55 1925422/1925422 get_token [5]
0.96 0.25 1922182/1922182 wordhash_insert [7]
0.21 0.00 3240/3241 wordhash_first [12]
0.00 0.00 1/1 wordhash_init [31]
-----------------------------------------------
0.00 0.00 66076/138833114 rob_compute_spamicity [13]
9.22 0.00 138767038/138833114 collect_words [3]
[4] 28.0 9.22 0.00 138833114 wordhash_next [4]
-----------------------------------------------
0.35 2.55 1925422/1925422 collect_words [3]
[5] 8.8 0.35 2.55 1925422 get_token [5]
2.17 0.38 1984944/1984944 yylex [6]
-----------------------------------------------
2.17 0.38 1984944/1984944 get_token [5]
[6] 7.7 2.17 0.38 1984944 yylex [6]
0.04 0.31 584769/584769 yy_get_next_buffer [8]
0.02 0.00 584768/584768 yy_get_previous_state [16]
0.00 0.00 1/3 yy_load_buffer_state [38]
0.00 0.00 1/1 yy_create_buffer [63]
-----------------------------------------------
0.96 0.25 1922182/1922182 collect_words [3]
[7] 3.7 0.96 0.25 1922182 wordhash_insert [7]
0.23 0.00 1922182/1922182 hash [10]
0.01 0.00 66076/66076 nmalloc [18]
0.01 0.00 66076/66076 wordprop_init [20]
0.00 0.00 132152/132152 smalloc [22]
-----------------------------------------------
0.04 0.31 584769/584769 yylex [6]
[8] 1.1 0.04 0.31 584769 yy_get_next_buffer [8]
0.09 0.22 584769/584769 yyinput [9]
0.00 0.00 1/3 yy_load_buffer_state [38]
0.00 0.00 1/1 yyrestart [64]
-----------------------------------------------
0.09 0.22 584769/584769 yy_get_next_buffer [8]
[9] 0.9 0.09 0.22 584769 yyinput [9]
0.22 0.00 587385/587385 lexer_fgets [11]
-----------------------------------------------
0.23 0.00 1922182/1922182 wordhash_insert [7]
[10] 0.7 0.23 0.00 1922182 hash [10]
-----------------------------------------------
0.22 0.00 587385/587385 yyinput [9]
[11] 0.7 0.22 0.00 587385 lexer_fgets [11]
-----------------------------------------------
0.00 0.00 1/3241 rob_compute_spamicity [13]
0.21 0.00 3240/3241 collect_words [3]
[12] 0.7 0.21 0.00 3241 wordhash_first [12]
-----------------------------------------------
0.01 0.09 1/1 bogofilter [2]
[13] 0.3 0.01 0.09 1 rob_compute_spamicity [13]
0.02 0.07 66076/66076 compute_probability [14]
0.00 0.00 66076/138833114 wordhash_next [4]
0.00 0.00 1/3241 wordhash_first [12]
0.00 0.00 1/132155 db_getvalue [15]
0.00 0.00 1/1 rob_get_spamicity [56]
-----------------------------------------------
0.02 0.07 66076/66076 rob_compute_spamicity [13]
[14] 0.3 0.02 0.07 66076 compute_probability [14]
0.04 0.03 132152/132155 db_getvalue [15]
0.00 0.00 66076/66076 wordprob_init [34]
0.00 0.00 66076/66076 wordprob_result [35]
0.00 0.00 65174/65174 wordprob_add [36]
-----------------------------------------------
0.00 0.00 1/132155 rob_compute_spamicity [13]
0.00 0.00 2/132155 db_getcount [23]
0.04 0.03 132152/132155 compute_probability [14]
[15] 0.2 0.04 0.03 132155 db_getvalue [15]
0.01 0.01 132155/132162 xstrdup [17]
0.01 0.00 132155/132155 db_enforce_locking [19]
0.00 0.00 132155/132400 xfree [33]
-----------------------------------------------
0.02 0.00 584768/584768 yylex [6]
[16] 0.1 0.02 0.00 584768 yy_get_previous_state [16]
-----------------------------------------------
0.00 0.00 1/132162 read_config_file [29]
0.00 0.00 2/132162 init_list [24]
0.00 0.00 4/132162 dbh_init [27]
0.01 0.01 132155/132162 db_getvalue [15]
[17] 0.1 0.01 0.01 132162 xstrdup [17]
0.01 0.00 132162/132401 xmalloc [21]
-----------------------------------------------
0.01 0.00 66076/66076 wordhash_insert [7]
[18] 0.0 0.01 0.00 66076 nmalloc [18]
0.00 0.00 68/132401 xmalloc [21]
-----------------------------------------------
0.01 0.00 132155/132155 db_getvalue [15]
[19] 0.0 0.01 0.00 132155 db_enforce_locking [19]
-----------------------------------------------
0.01 0.00 66076/66076 wordhash_insert [7]
[20] 0.0 0.01 0.00 66076 wordprop_init [20]
-----------------------------------------------
0.00 0.00 1/132401 tildeexpand [32]
0.00 0.00 2/132401 dbh_init [27]
0.00 0.00 2/132401 wordhash_init [31]
0.00 0.00 68/132401 nmalloc [18]
0.00 0.00 166/132401 smalloc [22]
0.01 0.00 132162/132401 xstrdup [17]
[21] 0.0 0.01 0.00 132401 xmalloc [21]
-----------------------------------------------
0.00 0.00 132152/132152 wordhash_insert [7]
[22] 0.0 0.00 0.00 132152 smalloc [22]
0.00 0.00 166/132401 xmalloc [21]
-----------------------------------------------
0.00 0.00 2/2 bogofilter [2]
[23] 0.0 0.00 0.00 2 db_getcount [23]
0.00 0.00 2/132155 db_getvalue [15]
-----------------------------------------------
0.00 0.00 2/2 setup_lists [25]
[24] 0.0 0.00 0.00 2 init_list [24]
0.00 0.00 2/2 open_wordlist [28]
0.00 0.00 2/132162 xstrdup [17]
-----------------------------------------------
0.00 0.00 1/1 main [1]
[25] 0.0 0.00 0.00 1 setup_lists [25]
0.00 0.00 2/2 init_list [24]
0.00 0.00 2/2 build_path [39]
-----------------------------------------------
0.00 0.00 2/2 open_wordlist [28]
[26] 0.0 0.00 0.00 2 db_open [26]
0.00 0.00 2/2 dbh_init [27]
-----------------------------------------------
0.00 0.00 2/2 db_open [26]
[27] 0.0 0.00 0.00 2 dbh_init [27]
0.00 0.00 4/132162 xstrdup [17]
0.00 0.00 2/132401 xmalloc [21]
-----------------------------------------------
0.00 0.00 2/2 init_list [24]
[28] 0.0 0.00 0.00 2 open_wordlist [28]
0.00 0.00 2/2 db_open [26]
-----------------------------------------------
0.00 0.00 2/2 process_config_files [30]
[29] 0.0 0.00 0.00 2 read_config_file [29]
0.00 0.00 1/132162 xstrdup [17]
0.00 0.00 1/1 tildeexpand [32]
0.00 0.00 2/132400 xfree [33]
-----------------------------------------------
0.00 0.00 1/1 main [1]
[30] 0.0 0.00 0.00 1 process_config_files [30]
0.00 0.00 2/2 read_config_file [29]
0.00 0.00 1/1 select_method [59]
-----------------------------------------------
0.00 0.00 1/1 collect_words [3]
[31] 0.0 0.00 0.00 1 wordhash_init [31]
0.00 0.00 2/132401 xmalloc [21]
-----------------------------------------------
0.00 0.00 1/1 read_config_file [29]
[32] 0.0 0.00 0.00 1 tildeexpand [32]
0.00 0.00 1/132401 xmalloc [21]
0.00 0.00 1/132400 xfree [33]
0.00 0.00 1/1 find_home [53]
-----------------------------------------------
0.00 0.00 1/132400 bogofilter [2]
0.00 0.00 1/132400 tildeexpand [32]
0.00 0.00 2/132400 read_config_file [29]
0.00 0.00 2/132400 close_lists [48]
0.00 0.00 4/132400 dbh_free [42]
0.00 0.00 235/132400 wordhash_free [62]
0.00 0.00 132155/132400 db_getvalue [15]
[33] 0.0 0.00 0.00 132400 xfree [33]
-----------------------------------------------
0.00 0.00 66076/66076 compute_probability [14]
[34] 0.0 0.00 0.00 66076 wordprob_init [34]
-----------------------------------------------
0.00 0.00 66076/66076 compute_probability [14]
[35] 0.0 0.00 0.00 66076 wordprob_result [35]
-----------------------------------------------
0.00 0.00 65174/65174 compute_probability [14]
[36] 0.0 0.00 0.00 65174 wordprob_add [36]
-----------------------------------------------
This table describes the call tree of the program, and was sorted by
the total amount of time spent in each function and its children.
Each entry in this table consists of several lines. The line with the
index number at the left hand margin lists the current function.
The lines above it list the functions that called this function,
and the lines below it list the functions this one called.
This line lists:
index A unique number given to each element of the table.
Index numbers are sorted numerically.
The index number is printed next to every function name so
it is easier to look up where the function in the table.
% time This is the percentage of the `total' time that was spent
in this function and its children. Note that due to
different viewpoints, functions excluded by options, etc,
these numbers will NOT add up to 100%.
self This is the total amount of time spent in this function.
children This is the total amount of time propagated into this
function by its children.
called This is the number of times the function was called.
If the function called itself recursively, the number
only includes non-recursive calls, and is followed by
a `+' and the number of recursive calls.
name The name of the current function. The index number is
printed after it. If the function is a member of a
cycle, the cycle number is printed between the
function's name and the index number.
For the function's parents, the fields have the following meanings:
self This is the amount of time that was propagated directly
from the function into this parent.
children This is the amount of time that was propagated from
the function's children into this parent.
called This is the number of times this parent called the
function `/' the total number of times the function
was called. Recursive calls to the function are not
included in the number after the `/'.
name This is the name of the parent. The parent's index
number is printed after it. If the parent is a
member of a cycle, the cycle number is printed between
the name and the index number.
If the parents of the function cannot be determined, the word
`<spontaneous>' is printed in the `name' field, and all the other
fields are blank.
For the function's children, the fields have the following meanings:
self This is the amount of time that was propagated directly
from the child into the function.
children This is the amount of time that was propagated from the
child's children to the function.
called This is the number of times the function called
this child `/' the total number of times the child
was called. Recursive calls by the child are not
listed in the number after the `/'.
name This is the name of the child. The child's index
number is printed after it. If the child is a
member of a cycle, the cycle number is printed
between the name and the index number.
If there are any cycles (circles) in the call graph, there is an
entry for the cycle-as-a-whole. This entry shows who called the
cycle (as parents) and the members of the cycle (as children.)
The `+' recursive calls entry shows the number of function calls that
were internal to the cycle, and the calls entry for each member shows,
for that member, how many times it was called from other members of
the cycle.
Index by function name
[2] bogofilter [10] hash (wordhash.c) [62] wordhash_free
[39] build_path [24] init_list (wordlists.c) [31] wordhash_init
[47] check_directory (main.c) [11] lexer_fgets [7] wordhash_insert
[48] close_lists [18] nmalloc (wordhash.c) [4] wordhash_next
[3] collect_words [28] open_wordlist [36] wordprob_add (robinson.c)
[14] compute_probability (robinson.c) [54] process_args [34] wordprob_init (robinson.c)
[49] compute_scale (robinson.c) [30] process_config_files [35] wordprob_result (robinson.c)
[40] db_close [29] read_config_file (config.c) [20] wordprop_init (register.c)
[19] db_enforce_locking (datastore_db.c) [55] rob_bogofilter [33] xfree
[23] db_getcount [13] rob_compute_spamicity [21] xmalloc
[15] db_getvalue [56] rob_get_spamicity [17] xstrdup
[37] db_lock (datastore_db.c) [57] rob_initialize_constants [63] yy_create_buffer
[50] db_lock_list (datastore_db.c) [58] rob_initialize_with_parameters [44] yy_flex_alloc (lexer.c)
[51] db_lock_reader_list [59] select_method (config.c) [45] yy_flush_buffer
[41] db_lock_release [43] set_dir_from_env (main.c) [8] yy_get_next_buffer (lexer.c)
[52] db_lock_release_list [60] set_good_weight [16] yy_get_previous_state (lexer.c)
[26] db_open [25] setup_lists [46] yy_init_buffer
[42] dbh_free (datastore_db.c) [22] smalloc (wordhash.c) [38] yy_load_buffer_state
[27] dbh_init (datastore_db.c) [32] tildeexpand [9] yyinput (lexer.l)
[53] find_home [61] validate_args (config.c) [6] yylex
[5] get_token [12] wordhash_first [64] yyrestart
--
Matthias Andree
More information about the Bogofilter
mailing list