Profiling nnrpd

[Jeffrey M. Vinocur]

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.

Right, uh, will try this in a minute.


> So most of the time is consumed looking at index entries and seeing if
> they correspond to real entries.  Is this a group with a lot of holes?

Since it would be nice to have nnrpdcheckart actually be usable with
tradspool, I thought I'd see if we can find anything on the critical path
there to slim down.  I did XOVER 1- on a group with some holes.  (I
actually did it a few dozen times, to get better statistical data.)

Here's with nnrpdcheckart: false...

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  us/call  us/call  name
 59.65      0.68     0.68  1528680     0.44     0.44  tdx_search
 18.42      0.89     0.21  1528680     0.14     0.58  tradindexed_search
 11.40      1.02     0.13       40  3250.00 28003.18  CMDxover
  6.14      1.09     0.07  1528680     0.05     0.63  OVsearch
  2.63      1.12     0.03  1528680     0.02     0.02  SendIOv
  0.88      1.13     0.01     6206     1.61     1.61  DeDotify
  0.88      1.14     0.01     3144     3.18     3.18  md5_transform


And with nnrpdcheckart: true...

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  us/call  us/call  name
 19.33      0.92     0.92  1490385     0.62     0.62  tdx_search
 10.29      1.41     0.49  1490346     0.33     0.33  FindNGByNum
  9.45      1.86     0.45  1490346     0.30     1.29  tradspool_retrieve
  7.98      2.24     0.38  1490385     0.25     0.87  tradindexed_search
  7.98      2.62     0.38  1490346     0.25     1.88  ARTinstorebytoken
  7.98      3.00     0.38       39  9743.59 121409.37  CMDxover
  6.93      3.33     0.33  1490346     0.22     0.83  TokenToPath
  6.51      3.64     0.31  1490346     0.21     1.50  SMretrieve
  4.83      3.87     0.23  1490348     0.15     0.15  GetTimeInfo
  3.78      4.05     0.18  1490346     0.12     0.16  OpenArticle
  2.94      4.19     0.14  1490229     0.09     0.13  SMfreearticle
  2.73      4.32     0.13  1490268     0.09     0.09  SendIOv
  2.52      4.44     0.12  1490346     0.08     0.24  CheckNeedReloadDB
  2.31      4.55     0.11  2987169     0.04     0.04  x_malloc
  2.31      4.66     0.11  1490385     0.07     0.95  OVsearch
  1.05      4.71     0.05  1490229     0.03     0.03  tradspool_freearticle
  0.63      4.74     0.03     6246     4.80     4.80  md5_transform
  0.21      4.75     0.01       39   256.41   256.45  xwritev
  0.21      4.76     0.01        1 10000.00 10000.00  index_unmap

Ok, the thing I'm finding most surprising is FindNGByNum.  That seems like 
an awful lot of time...especially since most of the articles from XOVER 
are going to be in the same newsgroups, so even the most trivial of caches 
might help.


I won't bother giving the detailed breakdowns of all the functions, since 
most of them end up only being useful to tell where the children are using 
a lot of time (this has to do with how gprof works, I think).  But 
FindNGByNum, since we discussed it above, and also the tradindexed 
functions in case Russ is curious...


  0.74      3.58     0.04    FindNGByNum (tradspool.c:251)
  0.32      4.37     0.01    FindNGByNum (tradspool.c:255)
  2.31      1.46     0.11    FindNGByNum (tradspool.c:257)
  3.15      1.35     0.15    FindNGByNum (tradspool.c:258)
  0.21      4.47     0.01    FindNGByNum (tradspool.c:260)
  1.26      2.50     0.06    FindNGByNum (tradspool.c:262)
  0.53      4.00     0.03    FindNGByNum (tradspool.c:263)
  0.11      4.75     0.01    FindNGByNum (tradspool.c:264)
  1.26      2.56     0.06    FindNGByNum (tradspool.c:265)
  0.21      4.48     0.01    FindNGByNum (tradspool.c:267)
  0.21      4.49     0.01    FindNGByNum (tradspool.c:270)

  1.47      2.17     0.07    tdx_search (tdx-data.c:401)
  0.42      4.21     0.02    tdx_search (tdx-data.c:405)
  1.26      2.62     0.06    tdx_search (tdx-data.c:407)
  0.42      4.22     0.02    tdx_search (tdx-data.c:410)
  0.21      4.66     0.01    tdx_search (tdx-data.c:411)
  0.84      3.39     0.04    tdx_search (tdx-data.c:412)
  0.95      2.98     0.04    tdx_search (tdx-data.c:413)
  0.32      4.38     0.01    tdx_search (tdx-data.c:414)
  1.05      2.85     0.05    tdx_search (tdx-data.c:418)
  0.84      3.43     0.04    tdx_search (tdx-data.c:425)
  0.21      4.67     0.01    tdx_search (tdx-data.c:426)
  0.84      3.47     0.04    tdx_search (tdx-data.c:431)
  0.84      3.51     0.04    tdx_search (tdx-data.c:438)
  0.21      4.68     0.01    tdx_search (tdx-data.c:439)
  4.20      0.64     0.20    tdx_search (tdx-data.c:441)
  3.99      0.83     0.19    tdx_search (tdx-data.c:442)
  0.63      3.94     0.03    tdx_search (tdx-data.c:443)
  0.21      4.69     0.01    tdx_search (tdx-data.c:446)
  0.42      4.25     0.02    tdx_search (tdx-data.c:447)

  2.10      1.56     0.10    tradindexed_search (tradindexed.c:261)
  1.26      2.68     0.06    tradindexed_search (tradindexed.c:268)
  0.42      4.26     0.02    tradindexed_search (tradindexed.c:270)
  0.32      4.40     0.01    tradindexed_search (tradindexed.c:271)
  0.53      4.04     0.03    tradindexed_search (tradindexed.c:272)
  0.42      4.29     0.02    tradindexed_search (tradindexed.c:275)
  0.11      4.75     0.01    tradindexed_search (tradindexed.c:276)
  1.79      1.94     0.09    tradindexed_search (tradindexed.c:277)
  0.42      4.30     0.02    tradindexed_search (tradindexed.c:278)
  0.42      4.33     0.02    tradindexed_search (tradindexed.c:280)
  0.21      4.70     0.01    tradindexed_search (tradindexed.c:281)


-- 
Jeffrey M. Vinocur
jeff at litech.org