legacy-wiki
Sys versus user
Recovered from the older tannerjc.net wiki snapshot dated January 23, 2016.
Problem
- User applications are listed in top as using a high amount of CPU, but top or vmstat is only showing that sys cpu is high.
Solution
- Translating and explaining the sys versus usr cpu usage can be difficult, but with a little bit of sample code it becomes a lot more obvious.
Examples
- sys-loop.c: Sample application which makes many system calls
#include stdio.h
#include sys/statfs.h
#include errno.h
//compiler options gcc -o sys-loop sys-loop.c
int main()
{
//build a struct to hold the return code of statfs
struct statfs statfs_buf;
int i;
// check repeatedly to see if /boot is mounted
for(i= 0; i 100000000; i++) statfs(/boot/, statfs_buf);
return 0;
}
- usr-loop.c: Sample application which executes only in user space
#include math.h
// compiler options gcc -o usr-loop usr-loop.c
// code modified from John Wallis's examples:
// http://www.programmersheaven.com/download/16163/download.aspx
#define MAX 5000
main()
{
int i;
int numerator[MAX+1], denominator[MAX+1];
register int k;
double Pi = 2.0; /*really!*/
for (i=1; i 100000; i++)
{
for (k = 0; k = MAX; k+=2) /*initialize arrays*/
{
numerator[k] = k + 2;
denominator[k] = k + 1;
}
for (k = 1; k = MAX; k+=2)
{
numerator[k] = k + 1;
denominator[k] = k + 2;
}
for (k = 0; k = MAX; k++)
{
Pi *= (double)numerator[k]/(double)denominator[k];
//printf(Term #%5d ---------- ã ÷ %f \n,k,Pi);
}
}
}
- vmstat when executing sys-loop x 2
[root@rhel5box Documentation]# vmstat 5
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 1 60 3664 125644 41736 0 0 8 66 5 8 0 1 91 9 0
1 1 60 4172 125660 40984 0 0 2 514 1106 364 3 43 0 54 0
1 1 60 4180 125676 40996 0 0 0 691 1136 459 7 93 0 0 0
3 1 60 4052 125688 41020 0 0 0 541 1114 373 7 93 0 0 0
2 1 60 4052 125692 41028 0 0 0 683 1135 463 9 91 0 0 0
2 1 60 4060 125708 41048 0 0 0 693 1140 473 8 92 0 0 0
0 1 60 4016 126448 40572 0 0 1 690 1140 469 2 35 0 63 0
- strace sys-loop
statfs(/boot/, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=2380632, f_bfree=1097488, f_bavail=974608, f_files=2457600, f_ffree=2361369, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
statfs(/boot/, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=2380632, f_bfree=1097488, f_bavail=974608, f_files=2457600, f_ffree=2361369, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
statfs(/boot/, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=2380632, f_bfree=1097488, f_bavail=974608, f_files=2457600, f_ffree=2361369, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
statfs(/boot/, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=2380632, f_bfree=1097488, f_bavail=974608, f_files=2457600, f_ffree=2361369, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
statfs(/boot/, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=2380632, f_bfree=1097488, f_bavail=974608, f_files=2457600, f_ffree=2361369, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
statfs(/boot/, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=2380632, f_bfree=1097488, f_bavail=974608, f_files=2457600, f_ffree=2361369, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
statfs(/boot/, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=2380632, f_bfree=1097488, f_bavail=974608, f_files=2457600, f_ffree=2361369, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
statfs(/boot/, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=2380632, f_bfree=1097488, f_bavail=974608, f_files=2457600, f_ffree=2361369, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
statfs(/boot/, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=2380632, f_bfree=1097488, f_bavail=974608, f_files=2457600, f_ffree=2361369, f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
--- SIGINT (Interrupt) @ 0 (0) ---
- vmstat when executing usr-loop x 2
[root@rhel5box Documentation]# vmstat 5
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 1 60 3696 129284 37944 0 0 8 66 5 8 0 1 91 9 0
0 1 60 3696 129292 37968 0 0 0 693 1144 466 0 6 0 94 0
2 1 60 3568 129296 37988 0 0 2 556 1116 399 29 5 0 66 0
4 0 60 4372 128984 37432 0 0 0 541 1109 380 95 5 0 0 0
2 1 60 4312 129000 37436 0 0 0 660 1133 450 95 5 0 0 0
2 1 60 4260 129036 37460 0 0 0 686 1136 464 95 5 0 0 0
- strace usr-loop
[root@rhel5box ~]# strace ./usr-loop
execve(./usr-loop, [./usr-loop], [/* 22 vars */]) = 0
brk(0) = 0x862b000
access(/etc/ld.so.preload, R_OK) = -1 ENOENT (No such file or directory)
open(/etc/ld.so.cache, O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=36750, ...}) = 0
mmap2(NULL, 36750, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f23000
close(3) = 0
open(/lib/libc.so.6, O_RDONLY) = 3
read(3, \177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\377M\0004\0\0\0..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1606808, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f22000
mmap2(0x4ca000, 1324452, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x4ca000
mmap2(0x608000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13e) = 0x608000
mmap2(0x60b000, 9636, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x60b000
close(3) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f21000
set_thread_area({entry_number:-1 - 6, base_addr:0xb7f216c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0x608000, 8192, PROT_READ) = 0
mprotect(0x4c6000, 4096, PROT_READ) = 0
munmap(0xb7f23000, 36750) = 0
Observations and conclusion
In the case of sys-loop, the r value (runq size) increases linearly with the number of processes making system calls. The cpu’s sy value goes up to 93 indicating that a lot of system calls are being made. The us value does increase to 9, but that is probably due to processing the for loop. The strace shows the system call is repeatedly running over and over until I break out of the process. Notice that it’s only stat’ing the mountpoint, so it’s not actually reading or writing blocks (bi/bo).
The usr-loop application appears to increase the runq size a little bit more than sys-loop intially, but eventually decreases to a proportional value. The cpu’s us value increases to 95% while the sy value slightly increases to 5. The strace reveals that not many system calls are made so it’s less useful for examining the application.
User applications can actually consume a lot of system cpu time without affecting the user percentage.