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