User-ID causing high CPU

[inzamam.shahid]

Hello People, 

My client has receently upgraded to 7.1.3 and now the management plane is constantly running 100% on all firewalls. 

This is the following message displayed and filling up the userid.log

2016-07-22 16:43:38.660 +0100 Error: pan_user_id_agent_msgs_queue_msg(pan_user_id_agent_msgs.c:58): failed to insert msg into sending msg list

We have restarted the user-id process, but that has not made a difference. Here is the output of show system resource follow:

Khipu@VH-PA-3020> show system resources follow
top - 16:57:59 up 4 days, 19:27, 1 user, load average: 0.59, 0.34, 0.39
Tasks: 109 total, 1 running, 108 sleeping, 0 stopped, 0 zombie
Cpu0 : 71.3%us, 23.0%sy, 0.0%ni, 2.0%id, 0.0%wa, 0.0%hi, 3.7%si, 0.0%st
Cpu1 : 58.8%us, 24.9%sy, 1.3%ni, 2.3%id, 0.0%wa, 0.0%hi, 12.6%si, 0.0%st
Mem: 3850716k total, 3535912k used, 314804k free, 39776k buffers
Swap: 2008084k total, 706888k used, 1301196k free, 1192424k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
13691 root 20 0 1990m 1.8g 117m S 171.6 48.4 29:16.95 useridd
3980 root 20 0 784m 46m 2756 S 14.6 1.2 682:57.29 logrcvr
10158 root 20 0 699m 55m 5428 S 1.3 1.5 14:23.74 mgmtsrvr
2338 root 30 10 18360 4864 2440 S 0.7 0.1 4:43.39 python
2278 root 0 -20 52896 9.8m 2788 S 0.3 0.3 8:25.44 masterd_apps
2296 root 15 -5 21664 3016 1660 S 0.3 0.1 18:26.08 sysd
3970 nobody 20 0 139m 3120 2260 S 0.3 0.1 36:37.83 appweb3
3979 root 20 0 69472 2432 2184 S 0.3 0.1 9:50.96 ikemgr
26387 Khipu 20 0 2532 1116 836 R 0.3 0.0 0:00.05 top
1 root 20 0 2084 600 572 S 0.0 0.0 0:02.87 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
3 root RT 0 0 0 0 S 0.0 0.0 0:01.36 migration/0
4 root 20 0 0 0 0 S 0.0 0.0 0:05.94 ksoftirqd/0
5 root RT 0 0 0 0 S 0.0 0.0 0:01.26 migration/1
6 root 20 0 0 0 0 S 0.0 0.0 0:07.95 ksoftirqd/1
7 root 20 0 0 0 0 S 0.0 0.0 0:15.46 events/0
8 root 20 0 0 0 0 S 0.0 0.0 1:00.75 events/1
9 root 20 0 0 0 0 S 0.0 0.0 0:00.01 khelper

Khipu@VH-PA-3020> show system resources follow
top - 16:58:58 up 4 days, 19:28, 1 user, load average: 0.58, 0.36, 0.39
Tasks: 110 total, 1 running, 109 sleeping, 0 stopped, 0 zombie
Cpu0 : 71.1%us, 20.9%sy, 0.0%ni, 3.3%id, 0.0%wa, 0.0%hi, 4.7%si, 0.0%st
Cpu1 : 56.1%us, 25.6%sy, 0.3%ni, 3.0%id, 0.0%wa, 0.0%hi, 15.0%si, 0.0%st
Mem: 3850716k total, 3462776k used, 387940k free, 39976k buffers
Swap: 2008084k total, 706840k used, 1301244k free, 1056956k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
13691 root 20 0 2063m 1.8g 117m S 171.2 50.0 30:58.85 useridd
3980 root 20 0 784m 47m 2756 S 14.6 1.2 683:06.00 logrcvr
10158 root 20 0 699m 55m 5428 S 1.3 1.5 14:24.19 mgmtsrvr
2296 root 15 -5 21664 3016 1660 S 0.7 0.1 18:26.21 sysd
2338 root 30 10 18360 4864 2440 S 0.7 0.1 4:43.46 python
26577 root 20 0 2164 720 592 S 0.7 0.0 0:00.02 ping
2278 root 0 -20 52896 9.8m 2788 S 0.3 0.3 8:25.52 masterd_apps
3960 root 20 0 760m 4316 2180 S 0.3 0.1 15:40.80 mongod
3970 nobody 20 0 139m 3120 2260 S 0.3 0.1 36:38.15 appweb3
3979 root 20 0 69472 2432 2184 S 0.3 0.1 9:51.05 ikemgr
3984 root 20 0 71716 1872 1544 S 0.3 0.0 2:18.80 l2ctrld
3993 root 17 -3 144m 4484 3200 S 0.3 0.1 1:58.73 routed
11443 root 20 0 13740 2592 1884 S 0.3 0.1 8:00.72 packet_path_pin
1 root 20 0 2084 600 572 S 0.0 0.0 0:02.87 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
3 root RT 0 0 0 0 S 0.0 0.0 0:01.36 migration/0
4 root 20 0 0 0 0 S 0.0 0.0 0:05.94 ksoftirqd/0
5 root RT 0 0 0 0 S 0.0 0.0 0:01.26 migration/1
6 root 20 0 0 0 0 S 0.0 0.0 0:07.95 ksoftirqd/1

Khipu@VH-PA-3020> show system resources follow
top - 16:59:12 up 4 days, 19:29, 1 user, load average: 0.45, 0.34, 0.38
Tasks: 110 total, 1 running, 109 sleeping, 0 stopped, 0 zombie
Cpu(s): 52.1%us, 15.8%sy, 0.1%ni, 25.4%id, 0.4%wa, 0.0%hi, 6.2%si, 0.0%st
Mem: 3850716k total, 3530968k used, 319748k free, 40032k buffers
Swap: 2008084k total, 706804k used, 1301280k free, 1106224k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
13691 root 20 0 2072m 1.9g 117m S 165.5 50.5 31:23.48 useridd
3980 root 20 0 784m 47m 2756 S 13.3 1.3 683:08.13 logrcvr
8804 root 20 0 43960 8552 2288 S 1.9 0.2 9:01.24 snmpd
1 root 20 0 2084 600 572 S 0.0 0.0 0:02.87 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
3 root RT 0 0 0 0 S 0.0 0.0 0:01.36 migration/0
4 root 20 0 0 0 0 S 0.0 0.0 0:05.94 ksoftirqd/0
5 root RT 0 0 0 0 S 0.0 0.0 0:01.26 migration/1
6 root 20 0 0 0 0 S 0.0 0.0 0:07.95 ksoftirqd/1
7 root 20 0 0 0 0 S 0.0 0.0 0:15.47 events/0
8 root 20 0 0 0 0 S 0.0 0.0 1:00.76 events/1
9 root 20 0 0 0 0 S 0.0 0.0 0:00.01 khelper
14 root 20 0 0 0 0 S 0.0 0.0 0:00.00 async/mgr

If you could let me know how to reduce the CPU that would be great. 

Thanks, 

[BPry]

The 3020's were having some issue with this exact issue on 7.1.2 that had people downgrading earlier, however 7.1.3 was supposed to stop that from being an issue. I would contact your SE or open up a support case with it if you can but this was the same issue that was affecting earlier builds of 7.1.*.

Please keep us up to-date on this though, as our company has been talking about upgrading to 7.1.3 with the newest security vulnerabilities that came out this/last week or continuing on to 7.0.8. 

[inzamam.shahid]

Thanks I will let you know when I recieve an update. 

[inzamam.shahid]

Hi Guys, 

Just thought I should give you an update with regards to this issue, so I logged this with TAC and after the troubleshooting it has been concluded as a bug. I believe this bug is specific to us as we had three firewalls acting as User-ID agents for themselves and other firewalls. As we were not using this feature anymore we disbaled this and it bought the management CPU down. This is being tracked in bug 100988. 

If you would like anymore info please let me know.