Profiling nnrpd
Jeffrey M. Vinocur
jeff at litech.org
Sat Dec 14 21:27:59 UTC 2002
On Thu, 28 Nov 2002, Russ Allbery wrote:
> That looks about like what I'd expect; all of the time is spent in the
> routine that actually pulls the data off of disk. For the original
> problem, I think the next step would be to do XOVER 1- on a large group
> and then do XOVER in 20 article chunks for the same group and see how the
> profile changes.
Ok, here we go. With nnrpdcheckart: false, in comp.lang.c, doing XOVER
100000- gets:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
71.43 0.35 0.35 451240 0.78 0.78 tdx_search
14.29 0.42 0.07 451240 0.16 0.93 tradindexed_search
10.20 0.47 0.05 40 1250.00 11753.18 CMDxover
2.04 0.48 0.01 6206 1.61 1.61 DeDotify
2.04 0.49 0.01 3144 3.18 3.18 md5_transform
And a breakdown of tdx_search() for good measure (I can't explain the
blip at the end, but lines 412-414 are a tight loop that perhaps can be
optimized a bit):
0.00 0.48 0.00 tdx_search (tdx-data.c:401)
2.08 0.41 0.01 tdx_search (tdx-data.c:407)
22.92 0.11 0.11 tdx_search (tdx-data.c:413)
18.75 0.20 0.09 tdx_search (tdx-data.c:414)
2.08 0.42 0.01 tdx_search (tdx-data.c:418)
1.04 0.47 0.01 tdx_search (tdx-data.c:431)
1.04 0.48 0.01 tdx_search (tdx-data.c:432)
11.46 0.26 0.06 tdx_search (tdx-data.c:441)
11.46 0.31 0.06 tdx_search (tdx-data.c:442)
2.08 0.43 0.01 tdx_search (tdx-data.c:447)
Now if I do it in chunks of 20 articles, it looks like this (I actually
did it another time, and got tdx_search at about 24% and CMDxover at about
9%, which was rather inconsistent, but perhaps still useful):
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
31.25 0.55 0.55 533240 1.03 1.03 tdx_search
15.91 0.83 0.28 84944 3.30 3.30 md5_transform
4.55 0.91 0.08 81840 0.98 17.51 CMDxover
4.55 0.99 0.08 81840 0.98 1.02 tdx_search_open
3.98 1.06 0.07 533240 0.13 1.16 tradindexed_search
3.98 1.13 0.07 81840 0.86 0.86 xwritev
3.98 1.20 0.07 main
3.41 1.26 0.06 81855 0.73 0.81 Argify
3.41 1.32 0.06 81842 0.73 1.22 line_read
2.84 1.37 0.05 81842 0.61 0.61 setproctitle
2.27 1.41 0.04 81841 0.49 0.61 OVctl
1.70 1.44 0.03 533240 0.06 0.06 SendIOv
1.70 1.47 0.03 84944 0.35 3.71 md5_final
1.70 1.50 0.03 82078 0.37 0.61 hash_find_slot
1.70 1.53 0.03 81843 0.37 0.43 TMRstart
1.70 1.56 0.03 81840 0.37 1.36 data_cache_open
1.70 1.59 0.03 81840 0.37 0.98 tdx_cache_lookup
1.14 1.61 0.02 81841 0.24 0.24 entry_hash
1.14 1.63 0.02 81841 0.24 4.13 index_find
0.57 1.64 0.01 533240 0.02 1.18 OVsearch
0.57 1.65 0.01 252782 0.04 0.04 x_malloc
0.57 1.66 0.01 169888 0.06 0.06 md5_update
0.57 1.67 0.01 163689 0.06 0.06 TMRgettime
0.57 1.68 0.01 84944 0.12 0.12 md5_init
0.57 1.69 0.01 81843 0.12 0.12 Reply
0.57 1.70 0.01 81841 0.12 0.12 tradindexed_ctl
0.57 1.71 0.01 81840 0.12 0.12 CMDgetrange
0.57 1.72 0.01 81840 0.12 0.98 PushIOv
0.57 1.73 0.01 81840 0.12 6.63 tradindexed_opensearch
0.57 1.74 0.01 6583 1.52 1.52 x_strdup
0.57 1.75 0.01 3103 3.22 10.22 AddNG
0.57 1.76 0.01 12 833.33 833.37 concat
I'm not sure where the time goes, except that maybe we should look into
why Hash() gets called so much.
And some of the major functions:
4.40 0.43 0.04 tdx_search (tdx-data.c:401)
1.10 0.84 0.01 tdx_search (tdx-data.c:405)
5.49 0.34 0.05 tdx_search (tdx-data.c:407)
1.10 0.85 0.01 tdx_search (tdx-data.c:410)
2.20 0.57 0.02 tdx_search (tdx-data.c:412)
13.19 0.12 0.12 tdx_search (tdx-data.c:413)
13.19 0.24 0.12 tdx_search (tdx-data.c:414)
0.55 0.90 0.01 tdx_search (tdx-data.c:425)
0.55 0.91 0.01 tdx_search (tdx-data.c:426)
2.75 0.46 0.03 tdx_search (tdx-data.c:431)
0.55 0.91 0.01 tdx_search (tdx-data.c:432)
1.10 0.86 0.01 tdx_search (tdx-data.c:438)
1.10 0.88 0.01 tdx_search (tdx-data.c:439)
6.04 0.29 0.06 tdx_search (tdx-data.c:441)
4.95 0.39 0.04 tdx_search (tdx-data.c:442)
2.20 0.59 0.02 tdx_search (tdx-data.c:447)
0.00 0.91 0.00 CMDxover (article.c:917)
1.10 0.60 0.01 CMDxover (article.c:924)
1.10 0.61 0.01 CMDxover (article.c:935)
1.10 0.62 0.01 CMDxover (article.c:965)
1.10 0.64 0.01 CMDxover (article.c:983)
2.20 0.49 0.02 CMDxover (article.c:990)
0.55 0.88 0.01 CMDxover (article.c:1026)
0.55 0.89 0.01 CMDxover (article.c:1028)
1.10 0.65 0.01 CMDxover (article.c:1052)
2.20 0.47 0.02 md5_transform (md5.c:431)
1.10 0.66 0.01 md5_transform (md5.c:438)
1.10 0.67 0.01 md5_transform (md5.c:439)
1.10 0.68 0.01 md5_transform (md5.c:443)
1.10 0.69 0.01 md5_transform (md5.c:446)
1.10 0.69 0.01 md5_transform (md5.c:450)
1.10 0.70 0.01 md5_transform (md5.c:451)
1.10 0.71 0.01 md5_transform (md5.c:457)
1.10 0.72 0.01 md5_transform (md5.c:461)
1.10 0.73 0.01 md5_transform (md5.c:464)
0.55 0.89 0.01 md5_transform (md5.c:465)
0.55 0.90 0.01 md5_transform (md5.c:466)
1.10 0.74 0.01 md5_transform (md5.c:470)
1.10 0.76 0.01 md5_transform (md5.c:471)
1.10 0.77 0.01 md5_transform (md5.c:479)
1.10 0.78 0.01 md5_transform (md5.c:483)
1.10 0.79 0.01 md5_transform (md5.c:484)
1.10 0.80 0.01 md5_transform (md5.c:489)
2.20 0.52 0.02 md5_transform (md5.c:493)
1.10 0.81 0.01 md5_transform (md5.c:495)
2.20 0.54 0.02 md5_transform (md5.c:497)
1.10 0.81 0.01 md5_transform (md5.c:501)
2.20 0.56 0.02 md5_transform (md5.c:502)
1.10 0.82 0.01 md5_transform (md5.c:504)
1.10 0.83 0.01 md5_transform (md5.c:506)
--
Jeffrey M. Vinocur
jeff at litech.org
More information about the inn-workers
mailing list