/scripts/dhcp/prefixes.php 100% CPU usage - caused by sylogd's clog

[niziak]

Hello.
Today I've upgraded OPNSense to latest devel version:

Code: [Select]

User-Agent Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Firefox/68.0
FreeBSD 11.2-RELEASE-p20-HBSD  07ef86ce9ca(stable/20.1) amd64
OPNsense 20.7.b_157 c2123d540
Plugins os-debug-1.3 os-dmidecode-1.1 os-dyndns-1.20 os-etpro-telemetry-1.4_1 os-iperf-1.0 os-mail-backup-devel-1.1 os-net-snmp-1.4 os-ntopng-1.2 os-nut-1.7 os-redis-1.1 os-siproxd-1.3 os-smart-2.1 os-vnstat-1.2 os-wol-2.3 os-zabbix-agent-1.7
Time Mon, 25 May 2020 09:35:32 +0000
OpenSSL 1.1.1g  21 Apr 2020
PHP 7.3.18

Now CPU is constantly almost at 100%:

Code: [Select]

last pid: 84990;  load averages: 26.49, 24.59, 24.22                                                                                                                                       up 0+01:57:54  09:44:47
106 processes: 28 running, 78 sleeping
CPU: 80.6% user,  0.0% nice, 18.4% system,  1.0% interrupt,  0.0% idle
Mem: 1263M Active, 46M Inact, 508K Laundry, 522M Wired, 317M Buf, 1294M Free
Swap: 8192M Total, 1859M Used, 6332M Free, 22% Inuse, 136K In

  PID USERNAME    THR PRI NICE   SIZE    RES STATE   C   TIME    WCPU COMMAND
91567 root          1  75    0 91752K 73220K RUN     0   0:10  18.54% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
37485 root          1  75    0 91752K 73172K CPU0    0   0:26  16.99% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
97250 root          1  74    0 91752K 23836K RUN     1   7:37  10.54% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
52661 root          1  74    0 91752K 22608K RUN     1   4:57   6.50% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
77188 root          1  73    0 91752K 22440K RUN     1   5:32   6.41% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
90577 root          1  73    0 91752K 23320K RUN     1   4:39   6.06% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
 3382 root          1  74    0 91752K 23080K RUN     1   5:37   6.01% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
37066 root          1  74    0 91752K 22732K RUN     1   5:18   6.00% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
  261 root          1  74    0 91752K 23540K RUN     1   5:03   5.97% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
70014 root          1  74    0 91752K 24572K RUN     1   7:12   5.88% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
24852 root          1  74    0 91752K 24800K RUN     1   8:38   5.80% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
21193 root          1  74    0 91752K 28356K RUN     1   9:19   5.38% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
32245 root          1  74    0 91752K 22296K RUN     1   6:31   5.21% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
41259 root          1  73    0 91752K 23084K RUN     1   4:48   5.18% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
89979 root          1  73    0 91752K 23132K RUN     1   5:51   5.16% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
19120 root          1  73    0 91752K 22856K RUN     1   6:48   4.96% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
37070 root          1  73    0 91752K 22760K RUN     1   4:06   4.95% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php
71332 root          1  73    0 91752K 22792K RUN     1   3:40   4.88% /usr/local/bin/php /usr/local/opnsense/scripts/dhcp/prefixes.php

Update:

I found root cause:
Some times ago I've increased log file size to 100MB each. I'm running OPNsense on normal PC, with very big storage, not resource restricted embedded system. I knew that circular log files are used. But I never thought that clog implementation is  so archaic and not touched since 2001. It is creating ring buffer in "memory" region obtained from mmap call on log file.

After system update something was changed. Something related to how system flushes dirty pages. I don't know what and I don't want to dig into it. After system update my HDD was constanly killing by lots of writes by syslog and lots of stucks readers like python/php scripts.

Now it is not possible to switch to other logging mechanism - only remote syslog is a solution.
Internal components depends on this archaic clog solution (php/python scripts to live view log files).

As a workaround I will recommend to add some restriction on configuration page to limit maximum log size to some reasonable value and add information how this will affect overall system performance.

[Remington]

Have you tried to reduce the logsize for this specifiv log:

`clog -s 500000 -i /var/log/dhcpd.log`

Should make it fast again. And it should stay until you change the logsize via UI again.

[franco]

Clog file size should be done with care as the clog approach is for continuous write on a fixed size but reading larger logs can take forever. It's better in such cases to switch to a file based syslog.

System: Settings: Logging: Disable circular logs

In fact I think we should make it the default in 21.7 except for nano images.


Cheers,
Franco

[foggy]

Hi,

I'm suffering this problem. 100% CPU and a bunch of prefixes.php running.

I've disabled circular logging as suggested.

Running 21.1.5

Any ideas?

[franco]

Not without at least some facts about your setup like log file size, version used and whether you delegate prefixes to your clients via DHCPv6.


Cheers,
Franco

[foggy]

Hi!

I said above 21.1.5. I since upgraded to 21.1.6 and the behaviour persisted.

Logs set to expire entries older than 365 days.

I disabled IPv6 on the WAN and it has started behaving. Now I don't see high CPU utilisation or errant prefixes.php processes. But I've lost IPv6.

foggy

[franco]

So that means you actually disabled clog? I can see that prefix.php does not support non-clog files yet and that might explain it.


Cheers,
Franco

[foggy]

yeah - per your response on the 8th Feb in system/settings/logging:- I checked "disable circular logging" which changed the "Log File Size" box to "Preserve Logs (days)" where I entered 365 and <save>.