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