Transcription
Here is a cheat sheet reference guide when initially troubleshooting Linux performance problems. Let's get right to it.
In this first demo, a client comes up to you and says that the latency of their application has increased. What could be going on? Let's start out by running the tenth option, `top`. `top` gives a general overview of the system. If we look here, we can see how the system is using the CPU. In this case, we can see that 0.4% of compute is going to the user space, while 38.5 percent of compute is going to system space. Also note that 39.2 percent of the time is spent idle. High amounts of idle CPU means that we are not getting saturation on CPU utilization. This softly says that the issue may not be CPU bound. We'll have to make more checks to make sure.
Now, let's run `vmstat 1`. We ran this with an argument of 1, which means that it prints 1-second summaries. This is another command that gives a summary of key server statistics. The output for the first row is different because it only shows a partial summary of the averages since boot, so we can generally ignore that first row. Let's go through each of the important columns. The `r` column gives the number of processors that are either currently running on the CPU or waiting for a turn. If the `r` value is greater than the number of CPUs, then the CPU is saturated. In a nutshell, large `r` values would be a cause for concern. In this case, the values look like they are generally in a small range, so there is nothing out of place here.
`vmstat` can also be used to get an overview of memory. Here, each of the `free`, `buff`, and `cache` values are comfortably above zero. Also, note that the swap values are zero. The swap values refer to swap memory, which is when some memory is moved to the hard drive. Swap memory is generally very slow, so it is normally used as a last resort. If the swap values are ever non-zero, then we know that we have run out of memory. Overall, these output suggests that we probably have enough memory in our system.
Now let's look at the CPU columns. The columns stand for user time, system time, idle time, wait i/o time, and stolen time. The results here mirror the output from `top`. Our system time utilization is high, while our user time is low, so it's unlikely that our CPU utilization is saturated. However, note the `wait i/o` value. It stays relatively constant at around 17%. A constant degree of wait i/o points to a disk bottleneck. This means that CPUs are idle because tasks are blocked while waiting for the disk.
But first, let's make sure our CPU values are valid. `mpstat` is another command that checks CPUs. This command is convenient as it prints time breakdowns per CPU, which can be used to check for an imbalance. A single hot CPU can be evidence of a single-threaded application causing issues. In this case, all of our processes are running on a single core anyways, so the point is moot.
Let's check the disk utilization next. `iostat` is a great tool for understanding how the disks are running. The most important statistic here is the percent utilization. Looking at this column here, we can see that there is a 78% disk utilization. For interpreting this percentage, understand that values greater than 60% typically lead to poor performance. As a note, systems can still generally run well with max CPUs, this is as the kernel understands priority and can rip threads off of the CPU very quickly if it needs to and run other threads. This is not as true for disks; it is harder to send i/o with higher priority dispatch if it's already doing something else. This is not as relevant for SSDs, however. Great, this was the value that we were looking for. The high utilization means that the disks are the most likely culprit for why our application has more latency.
However, for the sake of completion, let's check the network i/o as well. This command checks the network i/o. Of course, there is not much being utilized here, so there is nothing to report.
In summary, we can point to the disks as the most likely factor for causing performance issues for this demo. So, we found that the problem in our application was tied to the disk i/o; that was the bottleneck. We got there by seeing that our CPUs were mostly concerned with system time, that let us narrow down the possibilities. High disk usage can be checked with `iostat`. Low amounts of available RAM means that the system will be using swap space, which can be checked with `vmstat`. High network i/o can be checked with `sar`, and it could also have been due to system calls from the application itself. This could have been checked with `strace`. Trying to figure out the root cause of performance issues means drilling down from what the metrics are telling you.
Let's move on. In this second demo, the client tells us that their application is taking forever. Let's have a look at this one. For this one, let's start with `vmstat` to get a general overview of the system. The `r` column looks good; our values are very low, no processes are having to wait for an open CPU. Memory seems fine as well; there is plenty of free buffer and cache to go around. Also, both of the swap columns are zero, as they should be.
However, when we look at the CPU statistics, something becomes apparent. There is no idle time, and there is a high amount of user time and system time. Specifically, around 55% is user time and around 45% is system time. Let's run a different command to verify this. When we run `mpstat`, we can see pretty much the same information: lots of user time and system time is being utilized by this computer.
Let's now make sure that it is our process that is utilizing these CPU resources. In this case, our process is called `lab003`. After running `pidstat`, we can see that it is our application that is using up all of the CPU utilization. What might be causing this? Let's first narrow down what is causing so much system time to be utilized. First, let's check the disk i/o. After running `iostat`, we can see that the disk utilization is within acceptable bounds. Two to three percent utilization is perfectly fine, and the wait period is also in the milliseconds.
Let's check the network i/o next. The network i/o is also basically warmint, nothing to report here either. What could be the cause? We know from the earlier `pidstat` that there is a significant amount of system time being utilized. We have already checked for swap, disk, and network causes. There is, however, a different avenue we can check for the system calls used by our application. Let's check that with `strace`. We ran `strace` with specific parameters. `strace` is a bit resource-intensive, so we went for the top 100 responses. We also used the `-t` flag to add timestamps. We can see from the output that a system call of `read` is being called on file descriptor 3, however, it is only requesting 0 bytes of memory each time.
We have now found the problem. The application is running in a never-ending loop while trying to read a file. So, we found that the application was trying to read a file zero bytes at a time in a never-ending loop. We managed to drill down to the solution after recognizing that there was a high amount of system time utilization, then after eliminating the other possibilities of swap, disk, and network, we found that there was an excessive amount of system calls being run by the application.
Let's now move on. In this next demo, something mysterious is consuming the CPU. It's our job to figure out what's wrong. We start with the basic `top` command to get an overview of the system. Right off the bat, we can see that the CPUs are very busy, around 90% user time and 9.6% system time. Note that there is also basically no idle time. Oddly enough, `top` is not showing us what is causing our CPU to be so consumed. Normally, it would appear in the CPU column below. Perhaps it will come up if we use a different command.
After running `mpstat`, we see the same behavior: lots of user time and some system time, but this command gave us no additional information for what the problem may be. Perhaps we can track down where the system time is coming from. Disks are basically dormant. The system time is coming from a different source. Let's check the network next. The network i/o is also basically warmint, nothing to report here either. What could be the cause? Let's check memory next. There is also plenty of memory. The swap columns are also both 0, indicating that there is no paging or swapping going on.
Okay, so we know that we're busy on CPUs. Let's try profiling with `perf` to see what is going on. So here we are running `perf record -F 99 -a -- core` for 10 seconds only. We ran it on 99 Hertz instead of 100 because we don't want to accidentally sample in lockstep. This is to avoid not recording activity that is running at specific intervals. Now we can look at the results. Finally, we have found our culprit. We can see here that around 82% of our CPU time is spent in the `checksum` command.
So why could we not see it in our `top` command from earlier? It is because these are short-lived processors. This is the weakness of `top`. The above highlighted `checksum` process only exists for a couple of milliseconds. To get around this, use alternative commands like `htop` or `perf` tools like `execsnoop`.
So originally, we knew that something mysterious was consuming the CPU. We went through all of the potential system time offenders, but the actual issue was much harder to catch. Our favorite tool, `top`, was unable to immediately show the problem because `top` is not great for short-lived processors. We were only able to narrow down to our solution after using profiling with `perf`. Make sure to be vigilant about all the tools at your disposal. For one, `htop` can be used to get around some of `top`'s weaknesses.
And that's it! Thanks for watching. I hope you found this helpful. If you want more resources for this kind of thing, I have included some reference materials in the description below. This video was made using Video Puppet. Make sure to check them out!