Jim Klimov
2023-Jun-13 09:53 UTC
[Nut-upsdev] [Nut-upsuser] Upssched 100% CPU after updating Debian 12
FWIW, I wonder if this is a fallout of PR #1274 : https://github.com/networkupstools/nut/pull/1274/files and specifically https://github.com/networkupstools/nut/commit/550064930e369fb3a322c3b28ffff8b4acf53532 which added a `sock_read()` loop continuation effectively if `pconf_char()` returned 0. Just grasping at straws here (since it is a change a couple of months before the release was cut), because if ALL of those 128 reads (skipped above) did return 0, we should not have got to this line. The comment added here "*O_NDELAY with zero bytes means nothing to read but since read() follows a successful select() with ready file descriptor, ret shouldn't be 0*" - that might be misleading too, since per internet:> The result of O_nonblock and O_ndelay is to make I/O into non-blockingmode (non-blocking), return immediately without reading the data or the write buffer full, without blocking the wait.> > The difference is that, in a read operation, if the data is not read,O_ndelay causes the I/O function to return 0 immediately, but this gives rise to a problem, because the read to the end of the file (EOF) is returned 0, so it is impossible to distinguish between the cases. Therefore, O_nonblock is generated, it will return 1 when the data is not read, and set errno to Eagain.> > O_ndelay was introduced in earlier versions of System V, and when coding,it is recommended that POSIX-defined o_nonblock,o_nonblock be set at open and Fcntl. Jim On Tue, Jun 13, 2023 at 10:41?AM Jim Klimov <jimklimov+nut at gmail.com> wrote:> Thanks for the interesting puzzle to crunch! > > Looking at these few bread-crumbs, I wager an educated guess that this > loops in `sendcmd()` (where CLI child processes talk to a daemonized copy > which tracks the timers for events), around here: > https://github.com/networkupstools/nut/blob/v2.8.0/clients/upssched.c#L583-L626 > for the daemon and here for the child: > https://github.com/networkupstools/nut/blob/v2.8.0/clients/upssched.c#L762-L787 > > In both cases we run an infinite loop with `select()` to wait up to 1 > second and `read()` from the pipe. The common expectation is that if there > is nothing to read, the program blocks in `select()` waiting for a reply > from the kernel, and only returns after the specified timeout - to the > point that some `sleep()` with sub-second precision implementations do just > that on systems that lack `usleep()`. > > With `select()` in your capture posting an array of FDs `[7 10]` I'd say > it is the parent loop, and one of those is the `pipefd` and another is the > FD for socket connection to talk to a particular child on the other side of > the pipe. > > Here I must guess that either the `pselect6()` implementation behaves > differently which would be surprising after decades worth of expected > behavior, or that it for some reason decides that the FD #7 (whoever that > is) raised the hand but was then silent (0 bytes read). > > The next clue is 128 reads, which leads to > https://github.com/networkupstools/nut/blob/v2.8.0/clients/upssched.c#L485 > `sock_read()` method which indeed does up to `US_MAX_READ==128` attempts to > read one byte from a connection (so from the CLI/child counterpart) at a > time - so that is who FD#7 gotta be. > > So it is just at this point that I get stuck explaining what happens and > why :) Possibly there was a child or CLI counterpart process which died and > somehow the connection did not get closed (which would return a `read()` > error and evict it from the conn list), e.g. frozen/zombified, or something > else connected to the pipe (antivirus heh?) and loiters there, or something > else I could not think of quickly... > > The next clue could be to look at who is connected to the pipe file, maybe > with `fuser`, or look in `ps -ef` if there are other `upssched` processes > present, or look in `/proc/PIDNUM/fd/` of the daemonized and looping > `upssched`... > > If anyone decides to track through the code, the potential processing loop > goes > checkconf -> conf_arg -> parse_at -> sendcmd -> daemon if needed -> > start_daemon -> conn_add(pipefd) or sock_read(conn) > with short-lived child processes (command-line launched from `upsmon`) > parsing the configuration to pick the part relevant to them per envvars, > and talk to the daemon (fork one if needed) to start/cancel the timers. > > Jim > > On Tue, Jun 13, 2023 at 8:33?AM Kari Lempi?inen < > kari.lempiainen at summerday.net> wrote: > >> Hi, >> >> I ran the strace command while upssched was 100% CPU hungry. This is what >> I got: >> >> 1686633611.702798 read(7, "", 1) = 0 <0.000004> >> 1686633611.702816 read(7, "", 1) = 0 <0.000004> >> 1686633611.702834 pselect6(11, [7 10], NULL, NULL, {tv_sec=1, tv_nsec=0}, >> NULL) = 1 (in [7], left {tv_sec=0, tv_nsec=999998800}) <0.000006> >> 1686633611.702862 read(7, "", 1) = 0 <0.000004> >> 1686633611.702880 read(7, "", 1) = 0 <0.000004> >> . >> . >> . >> 1686633611.705206 read(7, "", 1) = 0 <0.000004> >> 1686633611.705224 read(7, "", 1) = 0 <0.000004> >> 1686633611.705242 pselect6(11, [7 10], NULL, NULL, {tv_sec=1, tv_nsec=0}, >> NULL) = 1 (in [7], left {tv_sec=0, tv_nsec=999999204}) <0.000005> >> 1686633611.705268 read(7, "", 1) = 0 <0.000004> >> 1686633611.705288 read(7, "", 1) = 0 <0.000302> >> >> there are 128 "read(7" lines between every pselect6 lines (I did count >> the read lines for couple of blocks, 128 in each of them). Nothing else in >> the strace log, just read and pselect lines for the short time I let strace >> to run. >> >> Any help from this? >> >> Best regards, >> Kari >> ------------------------------ >> >> *<more history snapped>* >> >-------------- next part -------------- An HTML attachment was scrubbed... URL: <http://alioth-lists.debian.net/pipermail/nut-upsdev/attachments/20230613/77dc9849/attachment-0001.htm>
Jim Klimov
2023-Jun-13 11:17 UTC
[Nut-upsdev] [Nut-upsuser] Upssched 100% CPU after updating Debian 12
FWIW, cross-posted the issue to NUT GitHub tracker: https://github.com/networkupstools/nut/issues/1964 Jim -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://alioth-lists.debian.net/pipermail/nut-upsdev/attachments/20230613/471bdeaf/attachment.htm>
Kari Lempiäinen
2023-Jun-13 11:58 UTC
[Nut-upsuser] Upssched 100% CPU after updating Debian 12
Hi,
Thanks Jim! Here is more system information from the commands you mentioned.
Kari
root at fricka:~# lsof -p 1716171
lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1002/gvfs
Output information may be incomplete.
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
upssched 1716171 root cwd DIR 8,2 4096 2 /
upssched 1716171 root rtd DIR 8,2 4096 2 /
upssched 1716171 root txt REG 8,2 39240 21762148
/usr/sbin/upssched
upssched 1716171 root mem REG 8,2 1922136 21764230
/usr/lib/x86_64-linux-gnu/libc.so.6
upssched 1716171 root mem REG 8,2 210968 21764476
/usr/lib/x86_64-linux-gnu/ld-linux-x86-64.so.2
upssched 1716171 root 0u CHR 1,3 0t0 4 /dev/null
upssched 1716171 root 1u CHR 1,3 0t0 4 /dev/null
upssched 1716171 root 2u CHR 1,3 0t0 4 /dev/null
upssched 1716171 root 3u unix 0x00000000eeb52825 0t0 16427010
type=DGRAM (CONNECTED)
upssched 1716171 root 4r REG 8,2 545 39847858
/etc/nut/upssched.conf
upssched 1716171 root 5u unix 0x00000000a035b466 0t0 16426351
type=STREAM (UNCONNECTED)
upssched 1716171 root 6u unix 0x0000000050820b2b 0t0 16426352
type=STREAM (UNCONNECTED)
upssched 1716171 root 7u unix 0x00000000447aac0e 0t0 16424724
/var/run/nut/upssched.pipe type=STREAM (CONNECTED)
upssched 1716171 root 10u unix 0x00000000d7bd8088 0t0 16424722
/var/run/nut/upssched.pipe type=STREAM (LISTEN)
root at fricka:~# ps -ef|grep ups
root 1425 1 0 Jun11 ? 00:00:00 sshd: /usr/sbin/sshd -D
[listener] 0 of 10-100 startups
root 1156722 1 0 00:00 ? 00:00:00 /usr/sbin/cupsd -l
root 1156723 1 0 00:00 ? 00:00:00 /usr/sbin/cups-browsed
lp 1156748 1156722 0 00:00 ? 00:00:00 /usr/lib/cups/notifier/dbus
dbus://
nut 1713117 1 0 14:30 ? 00:00:00 /lib/nut/dummy-ups -a
heartbeat
nut 1713154 1 0 14:30 ? 00:00:00 /lib/nut/usbhid-ups -a
eaton5s
nut 1713155 1 0 14:30 ? 00:00:00 /lib/nut/upsd -F
root 1713156 1 0 14:30 ? 00:00:00 /lib/nut/upsmon -F
root 1713157 1713156 0 14:30 ? 00:00:00 /lib/nut/upsmon -F
root 1716171 1 99 14:35 ? 00:05:10 /sbin/upssched UPS heartbeat
at localhost: On battery.
root 1719510 1550505 0 14:40 pts/2 00:00:00 grep ups
root at fricka:~# fuser /var/run/nut/upssched.pipe
/run/nut/upssched.pipe: 1716171
root at fricka:/proc/1716171/fd# ls -la
total 0
dr-x------ 2 root root 0 Jun 13 14:36 .
dr-xr-xr-x 9 root root 0 Jun 13 14:35 ..
lrwx------ 1 root root 64 Jun 13 14:36 0 -> /dev/null
lrwx------ 1 root root 64 Jun 13 14:36 1 -> /dev/null
lrwx------ 1 root root 64 Jun 13 14:36 10 -> 'socket:[16424722]'
lrwx------ 1 root root 64 Jun 13 14:36 2 -> /dev/null
lrwx------ 1 root root 64 Jun 13 14:36 3 -> 'socket:[16427010]'
lr-x------ 1 root root 64 Jun 13 14:36 4 -> /etc/nut/upssched.conf
lrwx------ 1 root root 64 Jun 13 14:36 5 -> 'socket:[16426351]'
lrwx------ 1 root root 64 Jun 13 14:36 6 -> 'socket:[16426352]'
lrwx------ 1 root root 64 Jun 13 14:36 7 -> 'socket:[16424724]'
________________________________
From: Jim Klimov <jimklimov+nut at gmail.com>
Sent: Tuesday, June 13, 2023 14:17
To: Kari Lempi?inen <kari.lempiainen at summerday.net>
Cc: Arnaud Quette via Nut-upsuser <nut-upsuser at
alioth-lists.debian.net>; nut-upsdev <nut-upsdev at
alioth-lists.debian.net>; Dimitris Economou <dimitris.s.economou at
gmail.com>
Subject: Re: [Nut-upsuser] Upssched 100% CPU after updating Debian 12
FWIW, cross-posted the issue to NUT GitHub tracker:
https://github.com/networkupstools/nut/issues/1964
Jim
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://alioth-lists.debian.net/pipermail/nut-upsuser/attachments/20230613/a19605e6/attachment.htm>