Monday, August 24, 2020

Palo Alto firewall - Troubleshooting High MP CPU


  • How to Interpret: show system resources

The command show system resources gives a snapshot of Management Plane (MP) resource utilization including memory and CPU. This is similar to the ‘top’ command in Linux.

show system resources provides information about the memory used and available and if the MP is using swap. If the swap usage remains consistently high, it implies that processes are either failing to release memory or they justifiably require more memory to operate.

To verify MP is swapping for a extended period of time, refer to process kswapd highlighted in the sample output below. If this process is running for hours - this could indicate that you have consistent swapping going on and may need to take steps to reduce your memory footprint.

The values of interest are the Swap, Mem, CPU wait time (%wa), Virtual memory usage (VIRT) and CPU usage (%CPU). These values are helpful when determining high MP CPU and/or slow MP response. If the CPU wait time is high, it indicates the MP is waiting for a process to release the CPU.

To view real-time memory and CPU usage, run the command: show system resources follow

Most of the Palo Alto Platforms have multiple core CPUs. Some platforms have dedicated processors for MP and DP, while some use Single Processor for both MP and DP.

For example,

 Platform MP Processors MP Cores
 PA-200 Single Shared Dual Core Processor 1
 PA-220 Single Shared Quad Core Processor 2
 PA-800 Single Shared 8 Cores Processor 3
 PA-3000 Dedicated Dual Core Processor 2
 PA-3200 Dedicated Quad Core Processor 4
 PA-5000 Dedicated Quad Core Processor 4
 PA-5200 Dedicated Multi Core Processor 16-24

This processor can be multiple core processor (some cores can also be used for DP depending on platform), the output lists usage for all cores combined.

You can press "1" after running "show system resources follow" to toggle view to show separate states:

Sample output of the command is provided below:

admin@PA-850 (active)> show system resources

top - 15:15:55 up 15 days,  6:53,  1 user,  load average: 7.50, 6.82, 6.57
Tasks: 177 total,   8 running, 168 sleeping,   0 stopped,   1 zombie
%Cpu(s): 71.1 us,  2.7 sy,  0.3 ni, 25.7 id,  0.3 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  4119516 total,   515792 free,  1325328 used,  2278396 buff/cache
KiB Swap:  6104084 total,  4836884 free,  1267200 used.  1112294 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 4532       20   0   99752   4036   3308 R  94.4  0.1  22001:32 pan_task
 4533       20   0   74712   3808   3252 R  94.4  0.1  22001:56 pan_task
 4537       20   0   74732   3872   3272 R  94.4  0.1  22001:01 pan_task
 4538       20   0   74712   3788   3188 R  94.4  0.1  22002:18 pan_task
 4534       20   0   74712   3724   3132 R  88.9  0.1  22002:01 pan_task
22131       20   0    4012   1620   1244 R  66.7  0.0   0:37.80 genindex.sh
30475       20   0   16912   7020   1904 R   5.6  0.2   0:00.04 top
    1       20   0    2320    252    252 S   0.0  0.0   0:10.94 init
    2       20   0       0      0      0 S   0.0  0.0   0:03.84 kthreadd
    3       20   0       0      0      0 S   0.0  0.0   1:13.88 ksoftirqd/0
    5        0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/0:+
    7       rt   0       0      0      0 S   0.0  0.0   0:59.15 migration/0
    8       20   0       0      0      0 S   0.0  0.0   0:00.00 rcu_bh
    9       20   0       0      0      0 S   0.0  0.0   7:08.67 rcu_sched
   10       20   0       0      0      0 S   0.0  0.0  16:12.77 rcuc/0
   11       20   0       0      0      0 S   0.0  0.0   5:31.92 rcuc/1
   12       rt   0       0      0      0 S   0.0  0.0   0:00.00 migration/1
   13       20   0       0      0      0 S   0.0  0.0   0:00.09 ksoftirqd/1
   14       20   0       0      0      0 S   0.0  0.0   0:00.00 kworker/1:0
   15        0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/1:+
   16       20   0       0      0      0 S   0.0  0.0   6:21.18 rcuc/2
   17       rt   0       0      0      0 S   0.0  0.0   0:00.00 migration/2
   18       20   0       0      0      0 S   0.0  0.0   0:00.10 ksoftirqd/2
   19       20   0       0      0      0 S   0.0  0.0   0:00.00 kworker/2:0
   20        0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/2:+
   21       20   0       0      0      0 S   0.0  0.0   5:46.62 rcuc/3
   22       rt   0       0      0      0 S   0.0  0.0   0:00.00 migration/3
   23       20   0       0      0      0 S   0.0  0.0   0:00.09 ksoftirqd/3
   24       20   0       0      0      0 S   0.0  0.0   0:00.00 kworker/3:0
   25        0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/3:+
   26       20   0       0      0      0 S   0.0  0.0   5:50.48 rcuc/4
   27       rt   0       0      0      0 S   0.0  0.0   0:00.00 migration/4
   28       20   0       0      0      0 S   0.0  0.0   0:00.09 ksoftirqd/4
   29       20   0       0      0      0 S   0.0  0.0   0:00.00 kworker/4:0
   30        0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/4:+
   31       20   0       0      0      0 S   0.0  0.0   5:54.52 rcuc/5
   32       rt   0       0      0      0 S   0.0  0.0   0:00.00 migration/5
   33       20   0       0      0      0 S   0.0  0.0   0:00.08 ksoftirqd/5
   34       20   0       0      0      0 S   0.0  0.0   0:00.00 kworker/5:0
   35        0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/5:+
   36       20   0       0      0      0 R   0.0  0.0  17:11.93 rcuc/6
   37       rt   0       0      0      0 S   0.0  0.0   1:06.43 migration/6
   38       20   0       0      0      0 S   0.0  0.0   0:33.33 ksoftirqd/6
   39       20   0       0      0      0 S   0.0  0.0   0:00.02 kworker/6:0
   40        0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/6:+
   41       20   0       0      0      0 S   0.0  0.0  17:17.72 rcuc/7
   42       rt   0       0      0      0 S   0.0  0.0   0:56.47 migration/7
   43       20   0       0      0      0 S   0.0  0.0   2:09.25 ksoftirqd/7
   45        0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/7:+
   46        0 -20       0      0      0 S   0.0  0.0   0:00.00 khelper
   47        0 -20       0      0      0 S   0.0  0.0   0:00.00 netns
  235        0 -20       0      0      0 S   0.0  0.0   0:00.00 writeback
  238        0 -20       0      0      0 S   0.0  0.0   0:00.00 bioset
  239        0 -20       0      0      0 S   0.0  0.0   0:00.00 kblockd
  245        0 -20       0      0      0 S   0.0  0.0   0:00.00 ata_sff
  255       20   0       0      0      0 S   0.0  0.0   0:00.00 khubd
  262        0 -20       0      0      0 S   0.0  0.0   0:00.00 edac-poller
  280        0 -20       0      0      0 S   0.0  0.0   0:00.00 rpciod
  327       20   0       0      0      0 S   0.0  0.0  40:24.01 kswapd0
  328       20   0       0      0      0 S   0.0  0.0   0:00.00 fsnotify_m+
  329        1 -19       0      0      0 S   0.0  0.0   0:00.00 nfsiod
  335        0 -20       0      0      0 S   0.0  0.0   0:00.00 kthrotld
  904       20   0       0      0      0 S   0.0  0.0   0:00.00 scsi_eh_0
  907       20   0       0      0      0 S   0.0  0.0   0:00.00 scsi_eh_1
  921       20   0       0      0      0 S   0.0  0.0   0:00.00 spi32766
  968       20   0       0      0      0 S   0.0  0.0   0:43.90 kworker/5:1
  989       20   0       0      0      0 S   0.0  0.0   0:45.87 kworker/4:1
  990       20   0       0      0      0 S   0.0  0.0   0:45.66 kworker/3:1
  991       20   0       0      0      0 S   0.0  0.0   0:45.45 kworker/2:1
  992       20   0       0      0      0 S   0.0  0.0   0:44.38 kworker/1:1
 1105        0 -20       0      0      0 S   0.0  0.0   0:00.00 deferwq
 1107        0 -20       0      0      0 S   0.0  0.0   1:18.71 kworker/0:+
 1108       20   0       0      0      0 S   0.0  0.0   1:15.74 kjournald
 1109        0 -20       0      0      0 S   0.0  0.0   0:00.01 kworker/5:+
 1111        0 -20       0      0      0 S   0.0  0.0   0:00.01 kworker/1:+
 1113        0 -20       0      0      0 S   0.0  0.0   0:00.01 kworker/2:+
 1116        0 -20       0      0      0 S   0.0  0.0   0:00.01 kworker/3:+
 1118        0 -20       0      0      0 S   0.0  0.0   0:00.01 kworker/4:+
 1121        0 -20       0      0      0 S   0.0  0.0   0:50.12 kworker/7:+
 1124        0 -20       0      0      0 S   0.0  0.0   0:48.54 kworker/6:+
 1170       16  -4    2672    212    208 S   0.0  0.0   0:00.50 udevd
 2281       20   0       0      0      0 S   0.0  0.0   0:20.17 kjournald
 2282       20   0       0      0      0 S   0.0  0.0   0:00.00 kjournald
 2552       20   0 2014520 398796   9356 S   0.0  9.7 373:58.74 mgmtsrvr
 2805       20   0    2516    372    320 S   0.0  0.0   0:20.46 syslogd
 2808       20   0    2376    192    192 S   0.0  0.0   0:00.02 klogd
 2823 rpc       20   0    5444    208    208 S   0.0  0.0   0:01.71 rpcbind
 2884       20   0    6752    252    248 S   0.0  0.0   0:00.00 xinetd
 2929       20   0    7752    132    128 S   0.0  0.0   0:00.00 rpc.mountd
 2934       20   0       0      0      0 S   0.0  0.0   0:00.00 lockd
 2935        1 -19       0      0      0 S   0.0  0.0   0:00.00 nfsd
 2936        1 -19       0      0      0 S   0.0  0.0   0:00.00 nfsd
 2937        1 -19       0      0      0 S   0.0  0.0   0:00.00 nfsd
 2938        1 -19       0      0      0 S   0.0  0.0   0:00.00 nfsd
 2939        1 -19       0      0      0 S   0.0  0.0   0:00.00 nfsd
 2940        1 -19       0      0      0 S   0.0  0.0   0:00.00 nfsd
 2941        1 -19       0      0      0 S   0.0  0.0   0:00.00 nfsd
 2942        1 -19       0      0      0 S   0.0  0.0   0:00.00 nfsd
 3104        0 -20  206236  20200   2384 S   0.0  0.5  98:29.43 masterd_ap+
 3108       20   0    3976    292    288 S   0.0  0.0   0:00.00 agetty
 3124       15  -5  133252  11736   1244 S   0.0  0.3 202:15.59 sysd
 3145       20   0   13604   3912   3152 S   0.0  0.1   0:00.06 sshd
 3292       20   0  383860   9900   1980 S   0.0  0.2   4:16.82 dagger
 3293       20   0  289988   2384   1760 S   0.0  0.1 179:24.66 contentd
 3294       20   0 1026880   2864   1564 S   0.0  0.1  10:00.61 sysdagent
 3307       30  10  202592   7564   1944 S   0.0  0.2  85:38.70 python
 3311       20   0  672404    440    440 S   0.0  0.0   2:44.18 plugin_api+
 3329       20   0  343288   1712    920 S   0.0  0.0  78:52.63 brdagent
 3330       20   0   51196   2296   1072 S   0.0  0.1  94:38.64 ehmon
 3331       20   0  507268    992    992 S   0.0  0.0   3:38.77 chasd
 3600       20   0  584184   3240   1548 S   0.0  0.1   5:02.83 cryptod
 3609 nobody    20   0   41684   1048    752 S   0.0  0.0  36:32.76 redis-serv+
 3614 nobody    20   0   47316   1488    920 S   0.0  0.0  37:19.04 redis-serv+
 3625       20   0    9864    416    412 S   0.0  0.0   0:00.02 sshd
 3636 admin     20   0   13604   1928   1168 S   0.0  0.0   0:00.01 sshd
 3650       20   0    9864    556    468 S   0.0  0.0   0:00.03 sshd
 3657       20   0       0      0      0 S   0.0  0.0   0:37.87 kjournald
 3662 admin     20   0  190100  60072  24760 S   0.0  1.5   0:02.47 cli
 4482       20   0  414084   4644   1800 S   0.0  0.1  33:50.34 iotd
 4483       20   0 1632408 227332 114448 S   0.0  5.5  67:11.41 devsrvr
 4488       20   0  639500 132724 114592 S   0.0  3.2  67:56.22 useridd
 4490       20   0  364060   2016    612 S   0.0  0.0 135:46.63 distributo+
 4519       20   0   66992   1380   1132 S   0.0  0.0   9:06.94 sdwand
 4520       20   0   67176   2152   1364 S   0.0  0.1  54:00.98 pan_dha
 4521       20   0   59396   2068   1420 S   0.0  0.1  12:40.03 mprelay
 4522       20   0  952640   8564   2500 S   0.0  0.2  65:26.83 pan_comm
 4523       20   0   58676   1412   1140 S   0.0  0.0  29:00.07 tund
 4539       20   0  149856  12572   1620 S   0.0  0.3  63:43.24 wifclient
 4546 nobody    20   0   41684   1364    808 S   0.0  0.0 144:22.35 redis-serv+
 4556 nobody    20   0   41684   1576    932 S   0.0  0.0  45:09.37 redis-serv+
 4558 nobody    20   0  292344   1568    992 S   0.0  0.0   0:01.02 nginx
 4594       30  10   54612   5176   1816 S   0.0  0.1  15:15.53 python
 4656 loguser   20   0   11048    184    120 S   0.0  0.0   0:00.00 syslog-ng
 4657 loguser   20   0  381304   2716   1108 S   0.0  0.1   0:58.39 syslog-ng
 4719 nobody    20   0  293792   3480   1980 S   0.0  0.1   2:43.42 nginx
 4760 nobody    20   0  325784   1304   1248 S   0.0  0.0   3:10.90 httpd
 4761       20   0  131032  13804   2384 S   0.0  0.3 102:56.88 identitycl+
 4783 nobody    20   0  288456   2924   1560 S   0.0  0.1   6:35.29 appweb3
 4784       20   0  523048   1532   1016 S   0.0  0.0   4:40.33 ikemgr
 4785       20   0 1656580 195780   3460 S   0.0  4.8 102:48.95 logrcvr
 4788       20   0  738788   1556    960 S   0.0  0.0   4:13.00 rasmgr
 4789       20   0  528692    936    792 S   0.0  0.0   4:07.47 keymgr
 4790       20   0  155496   1364    984 S   0.0  0.0   2:37.30 pan_ifmgr
 4791       20   0 1367156   4076   2416 S   0.0  0.1   7:39.28 varrcvr
 4792       17  -3  437708   1548   1076 S   0.0  0.0  25:34.02 l2ctrld
 4793       17  -3  157512   2468   1460 S   0.0  0.1   8:50.61 ha_agent
 4794       20   0  480604   1164    900 S   0.0  0.0   7:23.45 satd
 4795       20   0 1101604   1512   1512 S   0.0  0.0   9:30.24 sslmgr
 4796       20   0  433980   1468    976 S   0.0  0.0   4:13.93 pan_dhcpd
 4797       20   0  340948  12776   3704 S   0.0  0.3 106:49.37 dnsproxyd
 4799       20   0  365096    920    792 S   0.0  0.0   3:43.70 pppoed
 4800       17  -3  922376   2680   1816 S   0.0  0.1  11:06.36 routed
 4804       20   0 1204484   3980   2088 S   0.0  0.1  18:26.40 authd
 4814       20   0  210296  13684   1792 S   0.0  0.3   7:37.65 snmpd
 4827 nobody    20   0  302848   1012    916 S   0.0  0.0   0:01.03 nginx
 5045 nobody    20   0  303776   1144   1136 S   0.0  0.0   3:00.01 nginx
 5046 nobody    20   0  303776   1180   1136 S   0.0  0.0   3:10.08 nginx
 5047 nobody    20   0  303308    812    812 S   0.0  0.0   2:55.11 nginx
 6721       20   0       0      0      0 S   0.0  0.0   0:08.55 kworker/0:1
 7510       20   0       0      0      0 S   0.0  0.0   0:00.06 kworker/7:0
 7675       20   0       0      0      0 S   0.0  0.0   0:04.68 kworker/0:2
 7835       20   0       0      0      0 Z   0.0  0.0   0:00.05 mgmtsrvr
 9387       20   0       0      0      0 S   0.0  0.0   0:17.25 kworker/6:1
13144       20   0       0      0      0 S   0.0  0.0   0:11.19 kworker/7:1
13248       20   0       0      0      0 S   0.0  0.0   0:01.13 kworker/u1+
14847       20   0   75820   2192   1960 S   0.0  0.1   0:04.90 ntpd
21417 nobody    20   0 1670296  92316   7276 S   0.0  2.2   2:02.60 httpd
22116       20   0    3420    488    368 S   0.0  0.0   0:00.00 crond
22120       20   0    3816   1372   1180 S   0.0  0.0   0:00.00 genindex_b+
22303       20   0    3356    396    304 S   0.0  0.0   0:07.24 crond
22915 nobody    20   0  291644   1616   1520 S   0.0  0.0   0:01.13 nginx
23005 nobody    20   0  295552   1300   1184 S   0.0  0.0   0:58.50 nginx
23006 nobody    20   0  295552   1196   1188 S   0.0  0.0   0:49.62 nginx
25914       20   0       0      0      0 S   0.0  0.0   0:00.32 kworker/u1+
30466 admin     20   0    2728    704    580 S   0.0  0.0   0:00.01 less
30471       20   0   17248   7100   2204 S   0.0  0.2   0:00.02 sh
30476       20   0   16724   6204   1560 S   0.0  0.2   0:00.02 sed


You can press "1" after running "show system resources follow" to toggle view to show separate states:
Example from a PA-850 firewall:

admin@PA-850 (active)> show system resources

top - 14:21:05 up 11 days, 5:58, 1 user, load average: 6.45, 6.44, 6.45
Tasks: 173 total, 8 running, 165 sleeping, 0 stopped, 0 zombie
%Cpu0 : 35.0 us, 7.3 sy, 0.0 ni, 57.8 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu2 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu3 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu4 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu5 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu6 : 20.5 us, 3.0 sy, 0.0 ni, 76.6 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu7 : 28.1 us, 7.3 sy, 0.0 ni, 64.4 id, 0.3 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 4119516 total, 456576 free, 1381004 used, 2281936 buff/cache
KiB Swap: 6104084 total, 5046640 free, 1057444 used. 1434722 avail Mem


PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4532 root 20 0 99752 5796 4784 R 100.0 0.1 16189:00 pan_task
4533 root 20 0 74712 5540 4920 R 100.0 0.1 16189:29 pan_task
4534 root 20 0 74712 5460 4860 R 100.0 0.1 16189:29 pan_task
4537 root 20 0 74732 5360 4756 R 100.0 0.1 16188:40 pan_task
4538 root 20 0 74712 5564 4932 R 100.0 0.1 16189:40 pan_task
21848 root 20 0 4012 1664 1256 R 96.0 0.0 5:27.98 genindex.sh
3330 root 20 0 48976 4520 2560 S 1.0 0.1 69:47.02 ehmon
4488 root 20 0 639500 139056 117412 S 0.3 3.4 48:58.79 useridd
4490 root 20 0 364060 5096 3720 S 0.3 0.1 98:37.45 distributord
4523 root 20 0 58676 2892 2576 S 0.3 0.1 21:11.89 tund
4761 root 20 0 131032 14696 3064 S 0.3 0.4 75:23.93 identityclient
4783 nobody 20 0 288456 8620 3936 S 0.3 0.2 4:48.71 appweb3
4785 root 20 0 1656580 195980 7320 S 0.3 4.8 32:45.77 logrcvr
25172 nobody 20 0 2186392 159940 7900 S 0.3 3.9 2:41.97 httpd
1 root 20 0 2320 508 504 S 0.0 0.0 0:08.10 init



To Toggle IRIX Mode off press Shift+I:

- You can see above this box has 8 CPUs, 5 of which (1-5) are for DP. The DP process is pan_task which is supposed to be running at all times hence it has no idle CPU cycles.
- In above you will notice individually each pan_task (process for DP) are showing 100% CPU. This is design behavior of TOP Command in IRIX Mode where It is possible for the % CPU column to display values that total greater than 100%.
- Solaris mode divides the % CPU for each process by the number of CPUs in the system so that the total will be 100%.


top - 15:37:56 up 15 days, 7:15, 1 user, load average: 6.59, 6.65, 6.66
Tasks: 176 total, 7 running, 167 sleeping, 0 stopped, 2 zombie
%Cpu0 : 28.0 us, 6.4 sy, 0.5 ni, 64.2 id, 0.0 wa, 0.0 hi, 0.9 si, 0.0 st
%Cpu1 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu2 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu3 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu4 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu5 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu6 : 17.9 us, 6.0 sy, 0.0 ni, 75.7 id, 0.5 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu7 : 43.6 us, 7.3 sy, 0.0 ni, 48.6 id, 0.0 wa, 0.0 hi, 0.5 si, 0.0 st
KiB Mem : 4119516 total, 292220 free, 1224748 used, 2602548 buff/cache
KiB Swap: 6104084 total, 4752288 free, 1351796 used. 848512 avail Mem
Iris mode On
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4532 root 20 0 99752 3508 2832 R 100.0 0.1 22023:31 pan_task
4534 root 20 0 74712 3460 2868 R 100.0 0.1 22024:01 pan_task
4537 root 20 0 74732 3560 2956 R 100.0 0.1 22023:01 pan_task
4538 root 20 0 74712 3372 2776 R 100.0 0.1 22024:18 pan_task
4533 root 20 0 74712 3320 2776 R 99.5 0.1 22023:55 pan_task
23368 root 20 0 4012 1620 1212 R 95.4 0.0 7:05.25 genindex.sh
3104 root 0 -20 206236 19628 2372 S 5.5 0.5 98:36.40 masterd_apps
4488 root 20 0 639500 131072 114584 S 4.6 3.2 68:00.68 useridd
3124 root 15 -5 133252 8904 1240 S 1.8 0.2 202:33.41 sysd
3307 root 30 10 202592 7432 1928 S 1.4 0.2 85:45.42 python
41 root 20 0 0 0 0 S 0.5 0.0 17:19.33 rcuc/7
3686 admin 20 0 4208 1616 1128 R 0.5 0.0 0:00.23 top
4761 root 20 0 131032 13484 2124 S 0.5 0.3 103:03.36 identityclient
4804 root 20 0 1204484 3332 1440 S 0.5 0.1 18:27.52 authd
7675 root 20 0 0 0 0 S 0.5 0.0 0:04.91 kworker/0:2


Additionally note that average CPU usage for this box will also consider DP Cores so your monitoring tools will show higher MP Usage.

Example from a PA-5060 device:
show system resources follow

 top - 21:23:26 up 4 days,  1:57,  1 user,  load average: 0.00, 0.00, 0.00
Tasks: 131 total,   1 running, 130 sleeping,   0 stopped,   0 zombie
Cpu0  :  0.3%us,  0.0%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  0.3%us,  0.0%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu3  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   4053832k total,  2953796k used,  1100036k free,   163596k buffers
Swap:  2007992k total,     1080k used,  2006912k free,  1298156k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2402 root 0 -20 52960 16m 4440 S 0.3 0.4 5:31.90 masterd_apps
2421 root 15 -5 21680 4408 2508 S 0.3 0.1 18:59.06 sysd
3106 nobody 20 0 156m 47m 10m S 0.3 1.2 21:01.78 appweb3
1 root 20 0 2084 696 576 S 0.0 0.0 0:01.88 init


In this platform all cores are dedicated for MP, so you do not see any pan_task. Rest of the logic remains same.

  • Genindex.sh causing high MP CPU

show system resources follow
top - 14:17:29 up 11 days,  5:55,  1 user,  load average: 6.84, 6.46, 6.45
Tasks: 176 total,   8 running, 168 sleeping,   0 stopped,   0 zombie
%Cpu(s): 73.0 us,  2.6 sy,  0.1 ni, 24.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  4119516 total,   319332 free,  1415160 used,  2385024 buff/cache
KiB Swap:  6104084 total,  5050440 free,  1053644 used.  1295050 avail Mem

 PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4532 root 20 0 99752 5800 4788 R 100.0 0.1 16185:23 pan_task
4533 root 20 0 74712 5544 4924 R 100.0 0.1 16185:53 pan_task
4534 root 20 0 74712 5460 4860 R 100.0 0.1 16185:52 pan_task
4538 root 20 0 74712 5568 4936 R 100.0 0.1 16186:04 pan_task
4537 root 20 0 74732 5364 4760 R 99.7 0.1 16185:04 pan_task
21848 root 20 0 4012 1664 1256 R 97.0 0.0 2:03.25 genindex.sh
3124 root 15 -5 133232 12636 2568 S 1.0 0.3 140:10.34 sysd
3104 root 0 -20 206236 22044 4280 S 0.7 0.5 70:13.62 masterd_apps
3307 root 30 10 202592 10124 4512 S 0.7 0.2 62:48.48 python

4785 root 20 0 1656580 195988 7104 S 0.3 4.8 32:45.55 logrcvrSymptom
Genindex.sh process utilizing a large amount of CPU.

Environment
All firewall platforms can be affected by this post PANOS - +8.1

Cause
Genindex.sh runs after a PAN-OS upgrade to re-index the logs with any new fields that have been added.  It runs every 15 minutes and is known to cause spikes in the CPU on the management plane.  After it completes indexing all the logs, it will then stop running.

This should not cause any issues or be detrimental to the firewall and will only last until it has indexed all of your logs.  However, depending on the amount of logs you have based off your platform and what you have log retention set to, it can take up to weeks.

One way to reduce the amount of time genindex.sh has to run is to make sure you are making use of log retention as the last logs there are to index, the less time it will take for the process to finish.

Resolution
There is no resolution, this is working as expected.  Once it has finished indexing all the logs it will stop running and you should see your CPU utilization drop.  Also it's worth keeping in mind that this process only uses one core so your devices with multiple cores will not be affected, however it will show up in the logs and GUI that the management CPU is high.

On many occasions, this could be resolved by reducing the amount of logging.


  • PA-500 High Management CPU and poor performance with high logging

Symptom
PA 500 runs very slow and it was possible to  notice that Management CPU is between 98-100% almost all the time.

MP CPU Spikes up very frequently and "logrcvr", "mgmtsrvr" and "genindex.sh" appears to be the offending processes:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 
3265 20 0 1095m 282m 4780 S 35.4 14.2 93995:05 logrcvr 
14961 20 0 5260 1560 1232 R 16.9 0.1 0:51.34 genindex.sh 

3265 20 0 1095m 205m 3264 S 76.7 10.4 94000:37 logrcvr 
3217 20 0 1198m 315m 7280 S 14.7 15.9 38133:24 mgmtsrvr

High IOWait process was seen as well, however disk space utilization was fine:

PU USAGE DISTRIBUTION Avg Max Max Date
---------------------------------------------
User 54% 54.3% 01-08-06:15
System 13% 13.9% 01-05-12:11
Nice 2% 2.6% 01-09-02:36
Idle 25% 26.6% 01-04-11:29
IOWait 1% 1.1% 01-04-11:29

Due to poor management plane performance commits and other tasks may be affected and get stuck, and using commit force should help in order to go through.

Environment
Palo Alto PA-500 Firewall.
PAN-OS 8.0 and 8.1,
High rate of logging configured.

Cause
When average IOWait is greater than 1%, it is likely causing processes to run slower than normal and it is important to reduce the amount of logging.

Resolution
1. Set the Max days for Logs, In this case the max days was configured to value '90' using this article, which automatically purged all the logs older than 90 days.
2. In this case device was also upgraded to latest stable release. These both actions improved the performance remarkably.


* Reference URLs:

No comments: