Re: trying to figure out 100% CPU usage in nntpd...

[Konstantin Ryabitsev <konstantin@linuxfoundation.org>]

On Mon, Sep 09, 2019 at 05:53:41PM +0000, Eric Wong wrote:
> Konstantin Ryabitsev <konstantin@linuxfoundation.org> wrote:
> > There also was a weird problem a couple of days ago where one of the
> > httpd daemons started returning "Internal Server Error" to all requests.
> > Restarting public-inbox-httpd fixed the problem, but I am not sure how I
> > would troubleshoot the causes if it happens next time -- is there a way
> > to enable error logging for the httpd daemon?
> 
> That's a new one... I haven't seen any problems from -httpd myself
> in ages.  So -httpd could not handle requests at all?
> 
> The daemons already spits errors to stderr which typically ends up
> in syslog via systemd.  So, that's the first place to look
> (also "systemctl status $SERVICE"); anything in there?

Bah, I hadn't even considered looking in syslog. I blame jet lag. Well,
the explanation is simple, then:

Sep  7 22:22:35 lore.kernel.org public-inbox-httpd: pipe failed: Too many open files at /usr/local/share/perl5/PublicInbox/Git.pm line 210.
Sep  7 22:22:36 lore.kernel.org public-inbox-httpd: pipe: Too many open files
Sep  7 22:23:01 lore.kernel.org public-inbox-httpd: pipe: Too many open files
Sep  7 22:23:02 lore.kernel.org public-inbox-httpd: pipe: Too many open files
Sep  7 22:23:02 lore.kernel.org public-inbox-httpd: pipe: Too many open files

I see that there's already a LimitNOFILE=30000 -- is exhausting 30,000
open files a reasonable sort of thing for a system as busy as
lore.kernel.org, or should we look for a leak. Currently:

publici+ 13125     1  0 52297 25096   0 Sep09 ?        00:00:00 /usr/bin/perl -w /usr/local/bin/public-inbox-httpd -W4 -1 /var/log/public-inbox/httpd.out.log
publici+ 13128 13125  1 200056 591376 4 Sep09 ?        00:21:06 /usr/bin/perl -w /usr/local/bin/public-inbox-httpd -W4 -1 /var/log/public-inbox/httpd.out.log
publici+ 13129 13125  1 117789 262000 2 Sep09 ?        00:16:09 /usr/bin/perl -w /usr/local/bin/public-inbox-httpd -W4 -1 /var/log/public-inbox/httpd.out.log
publici+ 13130 13125  0 103569 204772 9 Sep09 ?        00:08:06 /usr/bin/perl -w /usr/local/bin/public-inbox-httpd -W4 -1 /var/log/public-inbox/httpd.out.log
publici+ 13131 13125  0 101510 199268 1 Sep09 ?        00:03:33 /usr/bin/perl -w /usr/local/bin/public-inbox-httpd -W4 -1 /var/log/public-inbox/httpd.out.log

# ls /proc/13125/fd/ | wc -l
9
# ls /proc/13128/fd/ | wc -l
17776
# ls /proc/13129/fd/ | wc -l
3937
# ls /proc/13130/fd/ | wc -l
648
# ls /proc/13131/fd/ | wc -l
68

17776 since Sep 09 seems... fairly excessive. Most of them are pipes:

# lsof -p 13128 | grep pipe | wc -l
14741

a bunch of them are to (deleted) entries in /tmp:

# lsof -p 13128 | grep deleted | wc -l
3015

(e.g.):

public-in 13128 publicinbox   45u      REG              259,4        984   4200094 /tmp/PerlIO_yd43mN (deleted)
public-in 13128 publicinbox   46r     FIFO                0,9        0t0  21818751 pipe
public-in 13128 publicinbox   47u      REG              259,4        984   4200096 /tmp/PerlIO_siY3Pb (deleted)
public-in 13128 publicinbox   48r     FIFO                0,9        0t0  21818758 pipe
public-in 13128 publicinbox   49u      REG              259,4        984   4200100 /tmp/PerlIO_WyIaaC (deleted)

It does seem like there's perhaps a leak somewhere?

-K