Troubleshooting Tip: FortiGate CPU Profiling

[Renante_Era]

Description	This article describes how to perform CPU profiling.
Scope	FortiGate v7.0 and above,
Solution	The idea of CPU profiling is to single out a singular CPU core and see what processes this core is calling. This can give insight into what the core is busy with. Check the CPU usage with the command 'get sys performance status'.  Softirq are interrupt requests that stem from the device processing packets. High softirq often points towards offloading issues. Down below is an example of high system usage: CPU states: 0% user 99% system 0% nice 1% idle 0% iowait 0% irq 0% softirq CPU0 states: 0% user 99% system 0% nice 1% idle 0% iowait 0% irq 0% softirq CPU1 states: 0% user 98% system 0% nice 2% idle 0% iowait 0% irq 0% softirq In three separate windows run: get sys stat get sys perf stat diagnose sys top 5 20 99999 <----- This shows us what processes are most active and can give a lead on processes that might be responsible. get sys stat get sys perf stat diagnose sys mpstat 5 99999 <----- This shows the usage similar to what 'get sys performance status' shows just over time. Especially on larger machines with more CPU cores, this lets check if only one or more CPU cores are affected and if the issue is moving from one core to another, or if the issue is static to one or more cores. Note that the commands 'get sys stat' and 'get sys perf stat' are essential here to be included. They contain the current time (for example 'System time: Tue Sep 24 10:28:33 2024') and the current uptime (for example 'Uptime: 77 days, 15 hours, 2 minutes'). This is required to correlate the 'top' and the 'mpstat' commands as the top commands only contain the uptime but no absolute time. Otherwise, it is not possible to match a high CPU spike in user space as seen in the top command with the output of mpstat or other debugs. The CPU profiling. For that find the CPU core with the highest load in the system or softirq. If there are multiple CPU cores with unusually high load please repeat this procedure for multiple cores. Select the core: get sys status get sys perf status diag sys profile cpumask _NUMBER_OF_CPU_WITH_LOAD_<----- Where the busy core CPU0 is 'diag sys profile cpumask 0', busy core CPU1 is 'diag sys profile cpumask 1', etc. Print time and start the profiling: fnsysctl date diagnose sys profile start Wait for 30 seconds. Stop the profiling and dump the information: fnsysctl date diagnose sys profile stop diagnose sys profile show order diagnose sys profile show detail diagnose sys profile report Example of a 'diagnose sys profile show order' output. This can be difficult to read and often refers to Linux processes [1], but in this example, it is possible to see the rijndaelDecrypt process being called which refers to AES encryption, which is commonly used with IPSEC: 0xffffffc000487130: 51 rijndaelDecrypt+0x5f0/0xc70 0xffffffc000084260: 28 default_idle+0x10/0x20 0xffffffc0001292f8: 6 __kmalloc+0x98/0x100 0xffffffc0003b4830: 4 l2ips_outbound_cb+0xf0/0x640 0xffffffc0003c98c0: 4 nf_hook_slow+0xa0/0x130 While it is possible to select multiple cores with this command (for example, by typing 'diagnose sys profile cpumask 2 3 4 5', which would profile cores 2 to 5), this is generally not advised. Separate CPUs may be busy with separate tasks, meaning that selecting multiple cores will add all functions called by the selected cores into one table. This would give the impression that all cores are busy with the same things, while this may be not the case in reality. There are cases where the CPU usage is spiky. In these instances, collecting logs by manually selecting a CPU core is simply too slow. Here, the command diagnose sys profile report can be used. It will profile all of the CPU cores for a very short period. The disadvantage when compared to the manual selection is that the functions will be added together into a singular table. diagnose sys profile report CPU Kernel Percentages:   0: 52% (52 of 100). Will profile.   1: 51% (51 of 100). Will profile. Kernel=0xffffffff80200190-0xffffffff80625dbd, module-gap=0x1f9da243 Profile buffer: profile step=4, sz=13046916-3261729, last-addr=0xffffffffa084b857 warning: functions cannot be profiled properly, early_idt_handlers-_einittext 0xffffffff80208408:                     50   mwait_idle+0x58/0x80 0xffffffffa004ec37:                     28   __ipsec_tunnel_flush_sa+0x5a7/0x6f0 0xffffffff802650b8:                     22   local_bh_enable+0x28/0xa0 Related document: Linux source code