Last call for 2.4.3 problems

Ulrich Schmid schmid at switch.ch
Thu Feb 2 14:09:01 UTC 2006


on 27/1/06 21:08 Russ Allbery wrote:
> Ulrich Schmid <schmid at switch.ch> writes:
> 
> 
>>from the ChangeLog of 2.4.2 (missing in 2.4.3 ChangeLog):
>>2004-06-02 20:11  hkehoe
>>    * history/hisv6/hisv6.c: In hisv6_reopen(), if MMAP_NEEDS_MSYNC and
>>      INND_DBZINCORE are set and nfsreader is false, override INCORE_NO
>>      to INCORE_MMAP
> 
> 
>>2004-06-02 20:02  hkehoe
>>    * lib/dbz.c: Put msync call in putcore for INCORE_MMAP Move
>>      writethrough test from dbzsync to putcore because it only applies
>>      to INCORE_MEM
> 
> 
>>whereas I assume that my problem is due to the changes in dbzsync /
>>putcore.  If I use in 2.4.3 dbzsync as of 2.4.1 I got the same history
>>performance as with 2.4.1. Is the writethrough test correct in putcore?
> 
> 
> Well, it's working for everyone else....  This is my timing from a box
> running the 2.4.3 prerelease:
> 
> INND timer:
> Code region                   Time    Pct    Invoked  Min(ms)  Avg(ms)  Max(ms)
> article cancel        00:00:30.339   0.0%       2963    0.200   10.239  131.000
> article cleanup       00:03:46.943   0.3%     765822    0.260    0.296    0.506
> article logging       00:03:48.709   0.3%     767065    0.257    0.298    0.483
> article parse         02:30:18.922  10.4%   24586049    0.265    0.367    0.638
> article write         00:09:09.753   0.6%     152777    0.812    3.598    8.803
> artlog/artcncl        00:00:00.779   0.0%       2320    0.000    0.336    3.636
> artlog/artparse       00:00:01.335   0.0%       4152    0.000    0.322    2.189
> data move             00:05:40.135   0.4%   28167766    0.007    0.012    0.024
> hisgrep/artcncl       00:00:15.519   0.0%       2037    0.000    7.619   23.750
> hishave/artcncl       00:00:00.277   0.0%       2963    0.000    0.093    0.689
> history grep          00:00:00.000   0.0%          0    0.000    0.000    0.000
> history lookup        00:03:30.670   0.2%    3224302    0.055    0.065    0.267
> history sync          00:00:29.634   0.0%        290    0.000  102.186  274.000
> history write         02:34:00.357  10.7%     767656    9.966   12.037   25.172
> hiswrite/artcncl      00:00:09.341   0.0%        926    0.000   10.087  241.500
> idle                  13:23:41.101  55.8%   20194447    1.592    2.388    4.849
> nntp read             02:56:15.477  12.2%   25689788    0.326    0.412    0.550
> overview write        00:00:00.000   0.0%          0    0.000    0.000    0.000
> perl filter           00:48:59.092   3.4%     764238    2.626    3.846    6.378
> python filter         00:00:00.000   0.0%          0    0.000    0.000    0.000
> site send             00:13:34.637   0.9%     288804    2.037    2.821    3.480
> 
> TOTAL: 24:00:02.767   22:54:13.020  95.4%          -        -        -        -
> 
> According to your previous message, your system is taking over two
> *seconds* for each call HISsync, which really makes no sense.  Could you
> be tickling a bad disk block, perhaps?

Sorry, something went wrong as I did the ctlinnd stathist test.
It's working, but my box needs with 2.4.3 more time for history lookup and
history write as with 2.4.1. These results in about 10% less overall performance
(incoming volume/articles) on my box.

Here are complete timings of 2.4.3 and 2.4.1 on the same box:
**INN 2.4.3
INND timer:
Code region              Time    Pct    Invoked   Min(ms)    Avg(ms)    Max(ms)
article cancel   00:01:35.042   0.1%       6242     0.000     15.226     78.429
article cleanup  00:01:58.738   0.1%    4232019     0.025      0.028      0.031
article logging  00:01:35.482   0.1%    4240166     0.018      0.023      0.032
article parse    01:30:26.384   6.3%   53675335     0.090      0.101      0.112
article write    15:35:38.952  65.4%    4156510    10.876     13.506     15.969
artlog/artcncl   00:00:00.065   0.0%       6099     0.000      0.011      0.333
artlog/artparse  00:00:00.002   0.0%         58     0.000      0.034      1.000
data move        00:10:23.512   0.7%   72105404     0.006      0.009      0.010
hisgrep/artcncl  00:01:03.848   0.1%       2327     0.000     27.438     98.500
hishave/artcncl  00:00:13.188   0.0%       6242     0.000      2.113      9.571
history grep     00:00:00.000   0.0%          0     0.000      0.000      0.000
history lookup   01:01:05.786   4.3%    8572187     0.009      0.428      3.169
history sync     00:00:08.818   0.0%        286     8.000     30.832     95.000
history write    03:14:16.750  13.6%    4156510     1.534      2.804     10.074
hiswrite/artcnc  00:00:16.232   0.0%       3915     0.000      4.146     54.500
idle             00:03:12.830   0.2%    2456047     0.037      0.079      0.692
nntp read        01:42:20.455   7.2%   50410233     0.087      0.122      0.132
overview write   00:00:00.000   0.0%          0     0.000      0.000      0.000
perl filter      00:06:36.966   0.5%    4156510     0.086      0.096      0.107
python filter    00:00:00.000   0.0%          0     0.000      0.000      0.000
site send        00:01:51.319   0.1%   11271644     0.009      0.010      0.011

TOTAL: 23:50:13  23:32:44.369  98.8%          -         -          -          -


**INN 2.4.1
INND timer:
Code region              Time    Pct    Invoked   Min(ms)    Avg(ms)    Max(ms)
article cancel   00:00:31.907   0.0%       5549     0.873      5.750     41.500
article cleanup  00:02:11.173   0.2%    4696027     0.026      0.028      0.032
article logging  00:01:37.527   0.1%    4707556     0.018      0.021      0.028
article parse    01:30:32.328   6.3%   64165752     0.069      0.085      0.111
article write    17:48:39.303  74.2%    4632349    11.385     13.842     15.204
artlog/artcncl   00:00:00.061   0.0%       5439     0.000      0.011      0.118
artlog/artparse  00:00:00.002   0.0%         47     0.000      0.043      1.000
data move        00:12:15.398   0.9%   85989213     0.007      0.009      0.009
hisgrep/artcncl  00:00:21.448   0.0%       3569     0.000      6.010     45.680
hishave/artcncl  00:00:01.128   0.0%       5549     0.000      0.203      4.429
history grep     00:00:00.000   0.0%          0     0.000      0.000      0.000
history lookup   00:36:08.978   2.5%    9626974     0.027      0.225      3.059
history sync     00:00:00.012   0.0%        288     0.000      0.042      0.500
history write    01:13:37.539   5.1%    4632350     0.335      0.954      6.701
hiswrite/artcnc  00:00:01.458   0.0%       1980     0.000      0.736     16.556
idle             00:09:33.425   0.7%    3781979     0.029      0.152     11.380
nntp read        02:03:29.663   8.6%   60485257     0.093      0.123      0.144
overview write   00:00:00.000   0.0%          0     0.000      0.000      0.000
perl filter      00:00:06.385   0.0%    4632349     0.001      0.001      0.002
python filter    00:00:00.000   0.0%          0     0.000      0.000      0.000
site send        00:02:10.771   0.2%   12877066     0.009      0.010      0.011

TOTAL: 24:00:13  23:41:18.506  98.7%          -         -          -          -




More information about the inn-workers mailing list