profiling

[David Relson]

Greetings,

With all the recent commentary about lexer size and speed, I decided to do 
some profiling.  For a "standard" task I wanted to know total run time, 
time spent in the lexer, and the percent.  I was also curious to see if 
reordering the lexer statements would affect the speed.  I ended up with 4 
versions of the lexer and profiled each 9 times.

The "standard" task used was registering messages.  I created a mbox 25 
copies each of bogofilter/src/tests/inputs/*.mbx.  It has 1725 messages, 
201,825 lines, and 8,990,800 bytes.

Here are the 5 routines that appeared in the top 3 for the 36 runs.  For 
each is shown how many times it was in the top 3:

      36  lexer_v3_lex
      35  wordhash_insert
      18  xfgetsl
      13  hash
       6  get_token

Run time variation: 3.12 to 3.80 seconds

Top 3 functions - times (and percents):

lexer_v3_lex    1.41 to 1.98 seconds (41.95% to 53.51%)
wordhash_insert 0.20 to 0.50 seconds ( 5.97% to 14.04%)
xfgetsl         0.12 to 0.33 seconds ( 3.50% to  9.61%)

Summary: reordering the lexer statements can save up to 0.57 seconds, i.e. 
speed parsing by 29%.

I'm going to compare the fastest lexer to the current one and see if I can 
deduce a reason for the improvement.  If so, I'll apply that reason to see 
if I can achieve additional speed!

David
-------------- next part --------------
                 time     lexer_v3_lex  wordhash_insert     xfgetsl
lexer_v3.2.3.l   3.12s    1.45s 46.47%    0.35s 11.22%    0.12s  3.85%
lexer_v3.4.3.l   3.17s    1.41s 44.48%    0.25s  7.89%    0.23s  7.26%
lexer_v3.3.1.l   3.20s    1.58s 49.38%    0.29s  9.06%    0.19s  5.94%
lexer_v3.3.2.l   3.25s    1.59s 48.92%    0.25s  7.69%    0.23s  7.08%
lexer_v3.2.8.l   3.26s    1.60s 49.08%    0.43s 13.19%    0.14s  4.29%
lexer_v3.4.5.l   3.27s    1.44s 44.04%    0.36s 11.01%    0.31s  9.48%
lexer_v3.4.9.l   3.29s    1.58s 48.02%    0.27s  8.21%    0.14s  4.26%
lexer_v3.1.6.l   3.29s    1.65s 50.15%    0.33s 10.03%    0.15s  4.56%
lexer_v3.3.4.l   3.32s    1.55s 46.69%    0.44s 13.25%    0.19s  5.72%
lexer_v3.1.3.l   3.33s    1.53s 45.95%    0.40s 12.01%    0.32s  9.61%
lexer_v3.3.9.l   3.34s    1.55s 46.41%    0.36s 10.78%    0.23s  6.89%
lexer_v3.1.1.l   3.34s    1.63s 48.80%    0.31s  9.28%    0.17s  5.09%
lexer_v3.4.2.l   3.35s    1.66s 49.55%    0.20s  5.97%    0.20s  5.97%
lexer_v3.2.9.l   3.36s    1.53s 45.54%    0.32s  9.52%    0.22s  6.55%
lexer_v3.2.2.l   3.37s    1.63s 48.37%    0.39s 11.57%    0.23s  6.82%
lexer_v3.4.4.l   3.38s    1.62s 47.93%    0.38s 11.24%    0.23s  6.80%
lexer_v3.1.9.l   3.39s    1.55s 45.72%    0.32s  9.44%    0.22s  6.49%
lexer_v3.1.5.l   3.40s    1.55s 45.59%    0.44s 12.94%    0.19s  5.59%
lexer_v3.3.6.l   3.43s    1.56s 45.48%    0.40s 11.66%    0.12s  3.50%
lexer_v3.2.4.l   3.44s    1.74s 50.58%    0.36s 10.47%    0.25s  7.27%
lexer_v3.2.1.l   3.49s    1.72s 49.28%    0.32s  9.17%    0.20s  5.73%
lexer_v3.4.1.l   3.50s    1.72s 49.14%    0.27s  7.71%    0.22s  6.29%
lexer_v3.4.7.l   3.53s    1.69s 47.88%    0.28s  7.93%    0.14s  3.97%
lexer_v3.2.6.l   3.54s    1.65s 46.61%    0.29s  8.19%    0.30s  8.47%
lexer_v3.4.6.l   3.56s    1.70s 47.75%    0.35s  9.83%    0.19s  5.34%
lexer_v3.1.4.l   3.56s    1.72s 48.31%    0.50s 14.04%    0.20s  5.62%
lexer_v3.3.5.l   3.57s    1.82s 50.98%    0.30s  8.40%    0.22s  6.16%
lexer_v3.1.7.l   3.57s    1.88s 52.66%    0.33s  9.24%    0.25s  7.00%
lexer_v3.3.3.l   3.62s    1.67s 46.13%    0.41s 11.33%    0.23s  6.35%
lexer_v3.2.7.l   3.62s    1.73s 47.79%    0.39s 10.77%    0.23s  6.35%
lexer_v3.1.8.l   3.62s    1.74s 48.07%    0.36s  9.94%    0.23s  6.35%
lexer_v3.3.7.l   3.64s    1.64s 45.05%    0.32s  8.79%    0.28s  7.69%
lexer_v3.2.5.l   3.68s    1.73s 47.01%    0.33s  8.97%    0.24s  6.52%
lexer_v3.1.2.l   3.70s    1.98s 53.51%    0.37s 10.00%    0.17s  4.59%
lexer_v3.4.8.l   3.79s    1.59s 41.95%    0.41s 10.82%    0.33s  8.71%
lexer_v3.3.8.l   3.80s    1.82s 47.89%    0.31s  8.16%    0.19s  5.00%