inn-STABLE: innfeed eating 100% CPU time

[Julien ÉLIE]

Hi Miquel,

> I've moved one of my production boxes over to inn-STABLE about a week
> ago or so. It appeared to be running just fine for a couple of days,
> but today I did a 'top' and saw that my innfeeds (I run 3 in parallel)
> were using way too much CPU time.

What is "too much CPU time"?

I tried to run 3 innfeeds in parallel but I do not have much load:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
news     14034  0.1  0.4   4532  1180 ?        SN   11:39   0:00 /home/news/work/testserver/bin/innfeed
news     14035  0.1  0.5   4528  1184 ?        SN   11:39   0:00 /home/news/work/testserver/bin/innfeed
news     14036  0.1  0.4   4400  1180 ?        SN   11:39   0:00 /home/news/work/testserver/bin/innfeed


Maybe it is because I only send/receive about 8,000 articles per day
and it is not enough to see CPU consumption.


> As you can see, the select gets a {0, 0} timeout argument.  Innfeed will
> still work, but it will spin in a loop eating CPU.

I also see them in inn-CURRENT:

select(20, [0 15 19], [], [15 19], {30, 0}) = 1 (in [0], left {29, 628000})
readv(0, [{"@0201480F05433349000000000000000"..., 8192}], 1) = 145
select(20, [0 15 19], [], [0 15 19], {30, 0}) = 1 (in [0], left {26, 336000})
readv(0, [{"@030A415554524531000000174DE7000"..., 8192}], 1) = 111
select(20, [0 15 19], [], [0 15 19], {26, 0}) = 1 (in [0], left {20, 256000})
readv(0, [{"@03034652330000000000001B7CA8000"..., 8192}], 1) = 121
select(20, [0 15 19], [], [0 15 19], {20, 0}) = 1 (in [0], left {7, 276000})
readv(0, [{"@03034652330000000000001B7CAB000"..., 8192}], 1) = 142
select(20, [0 15 19], [], [0 15 19], {7, 0}) = 0 (Timeout)
select(20, [0 15 19], [], [0 15 19], {0, 0}) = 0 (Timeout)
select(20, [0 15 19], [], [0 15 19], {28, 0}) = 1 (in [0], left {24, 596000})
readv(0, [{"@03034652330000000000001B7CAF000"..., 8192}], 1) = 134
select(20, [0 15 19], [], [0 15 19], {25, 0}) = 1 (in [0], left {22, 984000})
readv(0, [{"@03034652330000000000001B7CB3000"..., 8192}], 1) = 171
select(20, [0 15 19], [], [0 15 19], {23, 0}) = 1 (in [0], left {20, 632000})
readv(0, [{"@03034652330000000000001B7CB7000"..., 8192}], 1) = 123
select(20, [0 15 19], [], [0 15 19], {21, 0}) = 1 (in [0], left {12, 144000})
readv(0, [{"@03034652330000000000001B7CC5000"..., 8192}], 1) = 153
select(20, [0 15 19], [], [0 15 19], {12, 0}) = 0 (Timeout)


> Here's what I reverted. Unless someone can find out why this is
> happening, I think this should be patch -R 'ed in -STABLE before 2.4.4.

According to the log entry:

    Whenever doSomeWrites is called with writes still pending, add a work
    callback to do the write at the next opportunity.  This should eliminate a
    temporary connection deadlock state on flushing, where the response to the
    IHAVE body arrived before we finished writing it.  Before, doSomeWrites
    would have failed to call issueQUIT because writes were still pending, and
    then after the writes complete, there's no code to go back and issue it
    until the read timeout expires.


I think it is especially triggered off here:

> --- inn-2.4.3/innfeed/connection.c 2006-03-20 05:14:57.000000000 +0100
> +++ inn-STABLE-20080414/innfeed/connection.c 2008-04-14 11:08:15.000000000 +0200
> @@ -3917,7 +3927,10 @@
>
>   /* If there's a write pending we can't do anything now. */
>   if ( writeIsPending (cxn->myEp) )
> -    return ;
> +    {
> +      addWorkCallback (cxn->myEp,cxnWorkProc,cxn) ;
> +      return ;
> +    }
>   else if ( writesNeeded (cxn) ) /* something on a queue. */
>     {
>       if (cxn->doesStreaming)


Of course it can be patch -R 'ed in inn-STABLE (and also in inn-CURRENT which
suffers from the same problem).  But I do not know whether it is very
annoying as for CPU usage.
Do other people with a full-feed have the same problem?  (And isn't it also
caused by spooled <pathspool>/innfeed/* files which often adds CPU consumption?)

Normally, this patch should fix some deadlocks and assertion errors about
which lots of people complain...

-- 
Julien ÉLIE

« Ta remise sur pied lui a fait perdre la tête ! » (Astérix)