INN not keeping up with incoming news

[Fabien Tassin]

According to Fabien Tassin:
> > > We've just taken to locking the history.{hash,index} in core; its worked
> > > wonders - we've gone from spending hours per day in HIS* to under 10
> > > minutes (although I've no doubt that some of the time is hidden
> > > elsewhere).
> > 
> > Here's something to try if you have a test box for it:  only mlock
> > history.index and see if you still get the same win.  I wouldn't be
> > surprised if you did.
> 
> I've tried to mlock() only history.index.
> 
> Before :
> hiswrite 41992(5063)
> hiswrite 40724(5485)
> hiswrite 44661(5521)
> hiswrite 40876(4972)
> hiswrite 40325(4853)
> hiswrite 44043(5292)
> hiswrite 42554(5076)
> 
> After :
> hiswrite 339(5054)
> hiswrite 374(5513)
> hiswrite 440(5917)
> hiswrite 469(6115)
> hiswrite 455(6024)
> 
> No other timer impacted. It is under Linux 2.4.1.
> I'm still waiting to see if it make things faster...

argh!!

Look at this.

Before expire, with mlock() working in the background..

news at newsfeed:~/log $ zgrep 'innd: ME time' OLD/news.notice.1.gz | tail  | cut -d\  -f-16
Feb 25 23:14:23 newsfeed innd: ME time 300002 idle 207573(529846) hishave 131(59286) hiswrite 428(5844) hissync 4(118)
Feb 25 23:19:23 newsfeed innd: ME time 300000 idle 212033(508283) hishave 139(66238) hiswrite 454(6089) hissync 5(122)
Feb 25 23:24:23 newsfeed innd: ME time 300000 idle 213123(512827) hishave 131(67009) hiswrite 424(6325) hissync 4(127)
Feb 25 23:29:23 newsfeed innd: ME time 300000 idle 217750(492362) hishave 139(62421) hiswrite 396(6047) hissync 6(122)
Feb 25 23:34:23 newsfeed innd: ME time 300000 idle 220691(488136) hishave 112(53546) hiswrite 360(5324) hissync 2(107)
Feb 25 23:39:23 newsfeed innd: ME time 300000 idle 212504(523550) hishave 116(54873) hiswrite 363(5548) hissync 4(112)
Feb 25 23:44:23 newsfeed innd: ME time 300000 idle 205299(507589) hishave 117(59914) hiswrite 410(6471) hissync 1(130)
Feb 25 23:49:23 newsfeed innd: ME time 300000 idle 200116(503298) hishave 129(65980) hiswrite 454(6552) hissync 2(132)
Feb 25 23:54:23 newsfeed innd: ME time 300001 idle 208368(533057) hishave 133(61802) hiswrite 363(6103) hissync 4(123)
Feb 25 23:59:23 newsfeed innd: ME time 300000 idle 202286(547493) hishave 114(50497) hiswrite 359(5216) hissync 4(104)

Looks fine but now, after news.daily (expire running from 00:08:22 to 00:13:02,
all done at 00:15:04) :

news at newsfeed:~/log $ grep 'innd: ME time' news.notice | cut -d\  -f-16
Feb 26 00:04:23 newsfeed innd: ME time 300000 idle 187231(494077) hishave 17586(57289) hiswrite 446(6068) hissync 26(126)
Feb 26 00:09:23 newsfeed innd: ME time 300041 idle 160440(346046) hishave 49902(45306) hiswrite 352(4809) hissync 0(97)
Feb 26 00:14:24 newsfeed innd: ME time 300954 idle 235538(142070) hishave 29618(23173) hiswrite 181(2265) hissync 61(49)

hishave is now 300 to 400 times what it used to be.
I've tried to restart the mlock() helper, just in case...

Feb 26 00:19:24 newsfeed innd: ME time 300053 idle 176034(360970) hishave 41945(65663) hiswrite 4411(5727) hissync 2(115)
Feb 26 00:24:24 newsfeed innd: ME time 300000 idle 177631(489361) hishave 31161(58454) hiswrite 335(5172) hissync 5(104)

not better. I've tried to restart both INN and the helper..

Feb 26 00:31:05 newsfeed innd: ME time 300028 idle 184287(451718) hishave 35081(48142) hiswrite 330(5423) hissync 3(108)
Feb 26 00:36:05 newsfeed innd: ME time 300000 idle 178878(478572) hishave 32858(46647) hiswrite 358(5073) hissync 3(102)

still not better. I've then tried to re-run expire (news.daily notdaily)
without the mlock() helper.. (all done at 00:45:26)

Feb 26 00:41:05 newsfeed innd: ME time 300047 idle 132101(358209) hishave 41531(42236) hiswrite 44349(4599) hissync 3(92)
Feb 26 00:46:06 newsfeed innd: ME time 300314 idle 209747(128385) hishave 11465(32850) hiswrite 34406(3726) hissync 19(77)
Feb 26 00:51:06 newsfeed innd: ME time 300173 idle 141592(386114) hishave 33751(46927) hiswrite 40312(5494) hissync 5(111)
Feb 26 00:56:06 newsfeed innd: ME time 300007 idle 164899(401506) hishave 26619(41571) hiswrite 32634(4365) hissync 4(87)

very bad. Last chance, reboot and restart INN without mlock() :

Feb 26 01:11:24 newsfeed innd: ME time 300000 idle 101941(321621) hishave 42396(71520) hiswrite 71023(9156) hissync 9(183)
Feb 26 01:16:24 newsfeed innd: ME time 300000 idle 121642(383617) hishave 28648(58090) hiswrite 54546(6594) hissync 8(132)

I've also tried to run expire once again (all done 01:24:19) :

Feb 26 01:21:24 newsfeed innd: ME time 300102 idle 82579(226958) hishave 34846(58704) hiswrite 100020(6256) hissync 6(126)
Feb 26 01:26:24 newsfeed innd: ME time 300035 idle 206674(201125) hishave 13085(49760) hiswrite 20559(5506) hissync 16(113)
Feb 26 01:31:24 newsfeed innd: ME time 300004 idle 119668(389574) hishave 33875(56309) hiswrite 50306(6431) hissync 6(129)
Feb 26 01:36:24 newsfeed innd: ME time 300000 idle 143362(376413) hishave 24646(58885) hiswrite 45450(6049) hissync 8(121)

I'm lost. How can I recover my hishave < 150 ??
I don't understand why hishave started to change even before the first expire
has been started (my news.daily usually starts at 00:03:00).
Any idea ?

-- 
Fabien Tassin -+- fta at sofaraway.org