VERY HIGH CPU after upgrade from FreeNAS 11.3

P

prophoto

Explorer
Joined
Jul 27, 2015
Messages
61
/var/log/messages from midnight last night until reboot this morning.

Code:
Oct 29 00:00:00 freenas newsyslog[16658]: logfile turned over due to size>200K
Oct 29 00:00:00 freenas syslog-ng[2199]: Configuration reload request received, reloading configuration;
Oct 29 00:00:00 freenas syslog-ng[2199]: Configuration reload finished;
Oct 29 00:03:06 freenas kernel: Limiting closed port RST response from 1292 to 200 packets/sec
Oct 29 00:03:13 freenas kernel[2199]: Last message 'Limiting closed port' repeated 1 times, suppressed by syslog-ng on freenas.local
Oct 29 00:03:13 freenas kernel: Limiting closed port RST response from 1191 to 200 packets/sec
Oct 29 00:04:13 freenas kernel[2199]: Last message 'Limiting closed port' repeated 1 times, suppressed by syslog-ng on freenas.local
Oct 29 00:08:17 freenas kernel: Limiting closed port RST response from 773 to 200 packets/sec
Oct 29 00:08:24 freenas kernel[2199]: Last message 'Limiting closed port' repeated 1 times, suppressed by syslog-ng on freenas.local
Oct 29 00:08:24 freenas kernel: Limiting closed port RST response from 1303 to 200 packets/sec
Oct 29 00:09:23 freenas kernel[2199]: Last message 'Limiting closed port' repeated 1 times, suppressed by syslog-ng on freenas.local
Oct 29 00:14:11 freenas kernel: Limiting closed port RST response from 983 to 200 packets/sec
Oct 29 00:14:23 freenas kernel[2199]: Last message 'Limiting closed port' repeated 1 times, suppressed by syslog-ng on freenas.local
Oct 29 00:14:23 freenas kernel: Limiting closed port RST response from 1111 to 200 packets/sec
Oct 29 00:15:23 freenas kernel[2199]: Last message 'Limiting closed port' repeated 1 times, suppressed by syslog-ng on freenas.local
Oct 29 03:10:27 freenas 1 2020-10-29T03:10:27.987139-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 04:00:27 freenas 1 2020-10-29T04:00:27.973605-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 04:05:27 freenas 1 2020-10-29T04:05:27.984863-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 04:15:27 freenas 1 2020-10-29T04:15:27.973144-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 04:20:27 freenas 1 2020-10-29T04:20:27.972427-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 04:40:27 freenas 1 2020-10-29T04:40:27.973518-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 04:45:27 freenas 1 2020-10-29T04:45:27.972028-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 05:15:27 freenas 1 2020-10-29T05:15:27.973943-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 06:00:27 freenas 1 2020-10-29T06:00:27.973592-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 06:05:27 freenas 1 2020-10-29T06:05:27.978758-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 07:15:27 freenas 1 2020-10-29T07:15:27.971675-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 08:05:27 freenas 1 2020-10-29T08:05:27.971223-04:00 freenas.local collectd 2557 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 223, in connect
    bytes = self.sock.recv(128)
socket.timeout: timed out
Oct 29 08:22:28 freenas syslog-ng[36007]: syslog-ng starting up; version='3.25.1'
Oct 29 08:22:28 freenas kernel: pid 2199 (syslog-ng), jid 0, uid 0: exited on signal 6 (core dumped)
Oct 29 08:25:57 freenas syslog-ng[36007]: syslog-ng shutting down; version='3.25.1'
Oct 29 08:25:57 freenas 1 2020-10-29T08:25:57.237341-04:00 freenas.local ntpd 2444 - - ntpd exiting on signal 15 (Terminated)
Oct 29 08:25:57 freenas 1 2020-10-29T08:25:57.235429-04:00 freenas.local init 1 - - timeout expired for /etc/rc.shutdown: Interrupted system call; going to single user mode
Oct 29 08:29:03 freenas syslog-ng[2187]: syslog-ng starting up; version='3.25.1'
Oct 29 08:29:03 freenas ---<<BOOT>>---
 
HoneyBadger

HoneyBadger

actually does care
Administrator
Moderator
iXsystems
Joined
Feb 6, 2014
Messages
5,112
Looks like disktemp.py issue referenced here:

disktemp.py error

Hi, my log is becoming full with this error. I don't know which disk, or if all disks my be causing it. the only thing of note re my setup - sys disk is pcie m2 - 2x sata6 - 1x sata6 via usb3 (not recognised as HDD in the gui) ep 10 01:58:43 nas collectd[1493]: Traceback (most recent call...
www.truenas.com www.truenas.com

I don't see a definitive bug to roll it all up on Jira but submitting a ticket with debug/dump will no doubt help.

Do you see disk temps in your console? Strange that it works for hours and then falls over.
 
P

prophoto

Explorer
Joined
Jul 27, 2015
Messages
61
Are there instructions somewhere to do a dump? Not sure if these reporting pages are normal or not, never paid much attention to them in 11.3.
 

Attachments

  • Screen Shot 2020-10-29 at 10.25.58 AM.png
    Screen Shot 2020-10-29 at 10.25.58 AM.png
    124.7 KB · Views: 194
  • Screen Shot 2020-10-29 at 10.24.48 AM.png
    Screen Shot 2020-10-29 at 10.24.48 AM.png
    148.9 KB · Views: 229
HoneyBadger

HoneyBadger

actually does care
Administrator
Moderator
iXsystems
Joined
Feb 6, 2014
Messages
5,112
The reporting pages are having issues in TN12, changing your theme in Preferences is sometimes needed to refresh them.

But it looks as if you're getting temp data. Do all of your disks have results if you choose Devices - Select All? I have one device in my test box here that doesn't do SMART (SATA NVRAM card) so it's disabled there, but my boot DOM and SAS drives all report their temperature correctly.
 
P

prophoto

Explorer
Joined
Jul 27, 2015
Messages
61
3/6 show null, the rest have values.
 

Attachments

  • Screen Shot 2020-10-29 at 10.57.35 AM.png
    Screen Shot 2020-10-29 at 10.57.35 AM.png
    171 KB · Views: 206
  • Screen Shot 2020-10-29 at 10.57.26 AM.png
    Screen Shot 2020-10-29 at 10.57.26 AM.png
    164.4 KB · Views: 223
  • Screen Shot 2020-10-29 at 10.57.18 AM.png
    Screen Shot 2020-10-29 at 10.57.18 AM.png
    165.5 KB · Views: 199
AirborneTrooper

AirborneTrooper

Contributor
Joined
Jun 20, 2014
Messages
148
plex, sonarr, radarr, sabnzbd, transmission, tautulli, homebridge. I don't believe it to be anything from the jails though. I can still access my apps when the GUI is stuck on connecting. It's something with python3.8: middlewared and /sbin/systctl -a
 
HoneyBadger

HoneyBadger

actually does care
Administrator
Moderator
iXsystems
Joined
Feb 6, 2014
Messages
5,112
Strange that sysctl -a is what fills top but yet if you run the same command interactively from a shell it doesn't stall out.

I'm afraid I'm not sure what's going on. I don't have this issue, I'm trying to make my test system misbehave in a similar way so that I can try to figure out what's breaking (or at least submit a debug to iX and give them another data point.)
 
M

-Mael-

Dabbler
Joined
Mar 26, 2016
Messages
17
sretalla said:
OK, so ruled out one of the possible causes of those symptoms... SNMP causing high CPU in a python3.8 process.
Click to expand...

Is there a known bug in SNMP? I ask because I do have it enabled to support monitoring. I notice my CPU utilization jumps by about 8% on my Intel Xeon E5-1650 v3 when it's enabled. It not causing me problems, but that seems like a lot of CPU usage for SNMP.
 
M

-Mael-

Dabbler
Joined
Mar 26, 2016
Messages
17
-Mael- said:
Is there a known bug in SNMP? I ask because I do have it enabled to support monitoring. I notice my CPU utilization jumps by about 8% on my Intel Xeon E5-1650 v3 when it's enabled. It not causing me problems, but that seems like a lot of CPU usage for SNMP.
Click to expand...

I just applied the SNMP fix mentioned in this thread and it has lowered my CPU utilization considerably (load average was 1 before and now averages around .3). It also fixed my problem of zabbix not being able to query the ZFS stats. If you're going to try this fix, make sure you stop SNMP before editing the file.
 
Last edited:
AirborneTrooper

AirborneTrooper

Contributor
Joined
Jun 20, 2014
Messages
148
-Mael- said:
I just applied the SNMP fix mentioned in this thread and it has lowered my CPU utilization considerably (load average was 1 before and now averages around .3). It also fixed my problem of zabbix not being able to query the ZFS stats. If you're going to try this fix, make sure you stop SNMP before editing the file.
Click to expand...

What are the steps to
If you change snmp-agent.py line 32 to "kstat.zfs.misc.arcstats" it'll avoid the (presently unneeded) problem dbufs sysctl and work as it did before.
Click to expand...
 
AirborneTrooper

AirborneTrooper

Contributor
Joined
Jun 20, 2014
Messages
148
Found it, I did this
Code:
nano /usr/local/bin/snmp-agent.py


Let's see if GUI is still up tomorrow morning or not.
 
S

scoger

Cadet
Joined
Nov 6, 2020
Messages
4
I have this same sysctl -a issue as well. Quickly after boot of a TrueNAS-12.0-RELEASE system, the system gets bogged down with what appear to be tuck sysctl -a processes. I do not have SNMP turned on. This appears to be gathering stats for reporting, but the calls are either backing up or hanging in some fashion.
Code:
/bin/sh -c /sbin/sysctl -a 2>/dev/null | grep -E "hw.realmem|hw.physmem|vm.stats.vm.v_page_count|vm.stats.vm.v_wire_count|vm.stats.vm.v_active_count|vm.stats.vm.v_inactive_count|vm.stats.vm.v_cache_count|vm.stats.vm.v_free_count|vm.stats.vm.v_page_size"


Can get the system back into shape with a
Code:
killall -9 sysctl
 
You must log in or register to reply here.

Similar threads

S
Highly Unstable after 'upgrade' to TrueNAS 12 RC1
2 3
Replies
49
Views
8K
taney
taney
J
Upgrade from 11.3-U5 to 12 failing
Replies
0
Views
1K
Jestocost
J
wooley-x64
All Drives In Desk Shelf go offline after Upgrade 11.2 -> 11.3 -> 12.0
Replies
17
Views
1K
wooley-x64
wooley-x64
aakelley
High CPU after upgrade from 11.3 to TrueNAS
Replies
3
Views
958
aakelley
aakelley
guillaumesoucy
Can't upgrade any of my servers from 11.3 to 12
Replies
2
Views
1K
guillaumesoucy
guillaumesoucy
Top