Monitor system CPU / system calls in Linux

Question

I have a couple processes that are eating up a lot of system CPU time (as determined by looking at vmstat). Is there an easy way to find out what kind of system calls are being made?

I know there is strace, but is there a quicker and easier way? Does there exist something like a "top" for system calls?

Solution 1

I think strace with the -c flag is probably the closest I know of. If you haven't used the -c flag, try this:

$  sudo strace -c -p 12345

Where 12345 is the Process ID (PID) of the process in question. Note that stracing a process does add additional overhead, so while you're tracing it, the process will run slower.

After running that for however long you want to collect data, press Ctrl-C to stop your data collection and output the results. It'll produce something like this:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 31.88    0.001738         145        12           futex
 16.79    0.000915          11        80           tgkill
 12.36    0.000674          34        20           read
  9.76    0.000532         266         2           statfs
  8.42    0.000459          13        35           time
  4.38    0.000239           6        40           gettimeofday
  3.65    0.000199           4        48           sigprocmask
  2.94    0.000160          18         9           open
  2.88    0.000157          12        13           stat64
  1.32    0.000072           9         8           munmap
  0.90    0.000049           6         8           mmap2
  0.88    0.000048           3        14         7 sigreturn
  0.79    0.000043           5         9           close
  0.77    0.000042           4        10           rt_sigprocmask
  0.64    0.000035           3        12           setitimer
  0.55    0.000030           5         6         6 rt_sigsuspend
  0.53    0.000029           4         8           fstat64
  0.29    0.000016           8         2           setresuid32
  0.13    0.000007           4         2           _llseek
  0.09    0.000005           3         2           prctl
  0.04    0.000002           2         1           geteuid32
------ ----------- ----------- --------- --------- ----------------
100.00    0.005451                   341        13 total

As you can see, this is a breakdown of all system calls made by the application, sorted by total time, and including the average time per call and number of calls for each syscall. If you want to sort them differently, see the man page for strace, as there's a couple of options.

Solution 2

The type of strace switches that I tend to use is this.

strace -ffttT -p pid -o /tmp/strace.out

An example of this would look like,

19:35:57.485493 mprotect(0x7f35e7472000, 16384, PROT_READ) = 0 <0.000037>
19:35:57.485599 mprotect(0x7f35e7692000, 4096, PROT_READ) = 0 <0.000030>
19:35:57.485697 mprotect(0x7f35e78b7000, 4096, PROT_READ) = 0 <0.000030>
19:35:57.485782 munmap(0x7f35e7896000, 129588) = 0 <0.000037>
19:35:57.485875 set_tid_address(0x7f35e78949d0) = 10730 <0.000029>
19:35:57.485960 set_robust_list(0x7f35e78949e0, 0x18) = 0 <0.000024>
19:35:57.486048 futex(0x7fff8f58628c, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000025>
19:35:57.486131 futex(0x7fff8f58628c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1,       NULL, 7f35e7894700) = -1 EAGAIN (Resource temporarily unavailable) <0.000024>

You see the time difference at the right hand side of the system call showing how much time it has taken to go from one system call to another.

It will catch you the time difference between the system calls. So, when you see that a system call has quite a few seconds gap with the next system call, then there it is making some noise.

Another method is to coredump it with gcore. However, that requires a little experience navigating through gdb.

But, if the thread is a kernel thread, then you can't strace or coredump it. In that case, we have to use something more complex. In RHEL5 kernel, we use oprofile. In RHEL6, we use perf. I prefer perf over oprofile. Perf data can be collected with graph like format showing the system call where maximum percentage of CPU is being used.

With a test perf, I see this.

38.06%  swapper  [kernel.kallsyms]  [k] mwait_idle_with_hints                                                                                                               ↑

29.45%  swapper  [kernel.kallsyms]  [k] read_hpet 
4.90%  swapper  [kernel.kallsyms]  [k] acpi_os_read_port                                                                                                                   ▒
4.74%  swapper  [kernel.kallsyms]  [k] hpet_next_event   

It shows the kernel function where 38% CPU time is being spent. Now, we can check the function and see what it is doing and what it is supposed to do.

With a few examples, it is not that much hard.

Solution 3

Maybe try out one of the sampling profilers, such as oprofile, or for newer kernels, perf. If you're lucky, "perf top" might tell you precisely what you want. See here for some examples

Comments

[Warner]

strace is the solution.

[Gaius]

Damn you, futile mutex! shakes fist