1

I have observed that when running CESM (a weather modeling application), the top command shows a great deal of time is spent on system calls, about 25% to 60%, and only 40% to 75% is used in user code. The application does some I/O and communicates with MPI.

A sample output from the top command is given below:

top - 16:54:32 up 11 days, 13:45,  2 users,  load average: 8.12, 8.25, 8.08
Tasks: 201 total,   9 running, 192 sleeping,   0 stopped,   0 zombie
Cpu(s): 74.3%us, 25.2%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.5%si,  0.0%st
Mem:  24659792k total,  5259280k used, 19400512k free,  1747768k buffers
Swap: 28667984k total,   234408k used, 28433576k free,   169080k cached

  PID USER    PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
20748 user1   25   0  516m 304m  26m R 100.2  1.3  22:31.81 ccsm.exe
20750 user1   25   0  497m 293m  26m R 100.2  1.2  27:12.45 ccsm.exe
20754 user1   25   0  496m 290m  24m R 100.2  1.2  27:18.33 ccsm.exe
20751 user1   25   0  496m 291m  25m R 99.9  1.2  27:21.63 ccsm.exe
20752 user1   25   0  496m 291m  25m R 99.9  1.2  27:18.97 ccsm.exe
20749 user1   25   0  686m 446m  26m R 99.2  1.9  26:36.16 ccsm.exe
20753 user1   25   0  554m 335m  25m R 98.5  1.4  27:19.78 ccsm.exe
20755 user1   25   0  496m 289m  23m R 97.2  1.2  27:12.34 ccsm.exe

Using the strace command to attach to process 20748 shows a lot of

poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=10, events=POLLIN}, {fd=18, events=POLLIN}, {fd=19, events=POLLIN}], 7, 0) = 0 (Timeout)
poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=10, events=POLLIN}, {fd=18, events=POLLIN}, {fd=19, events=POLLIN}], 7, 0) = 0 (Timeout)
poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=10, events=POLLIN}, {fd=18, events=POLLIN}, {fd=19, events=POLLIN}], 7, 0) = 0 (Timeout)

Using strace -c -p 20748 to count time for a while I got:

$ strace -c -p 20748
Process 20748 attached - interrupt to quit
Process 20748 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 85.17    0.068864           0  11713876           poll
  9.74    0.007876           2      4208           write
  4.45    0.003595           1      6463           munmap
  0.37    0.000302           0      6463           mmap
  0.22    0.000179           0      1068           brk
  0.03    0.000025           1        18           open
  0.02    0.000016           1        18           read
  0.00    0.000000           0        18           close
  0.00    0.000000           0         2         1 stat
  0.00    0.000000           0        18           fstat
  0.00    0.000000           0         2           madvise
  0.00    0.000000           0         1           getcwd
------ ----------- ----------- --------- --------- ----------------
100.00    0.080857              11732155         1 total

The file descriptors appeared in the poll are sockets and a pipe.

4 -> socket:[2789396]
5 -> socket:[2789451]
6 -> socket:[2789452]
7 -> socket:[2789456]
10 -> pipe:[2789492]
18 -> socket:[2789517]
19 -> socket:[2789518]

I feel too much time are wasted in poll and wander if anything can be done to decrease this. The first thing I can think of is to find where poll is called. The code of the application doesn't call poll directly. How can I trace back to the source of the call? How to trace back to where the sockets are created?

2

The time in poll is not wasted - it is the time the process waits for input data to "arrive" or for output buffers to be ready for new output data.

You can use lsof to list the open descriptors (including sockets).

How many CPU cores do you have in the system? How many cores can ccsm use?

Your top listing shows around 100% CPU usage for ccsm.exe processes. It seems to me that your bottleneck is not I/O but the CPU.

Anyway, to reduce the "poll time" you would need to speed up I/O - for example by putting the data (database?) on a fast mass memory (system).

  • Each node has 8 cores and ccsm is using multiple full nodes. – user2196452 Apr 1 '14 at 21:55
  • What should I look into from the output of lsof? I think you mean my bottleneck is not the CPU but I/O, right? Are the sockets used for MPI communications or something else? Since there is no disk files involved, can I assume the disk I/O is not an issue? – user2196452 Apr 1 '14 at 22:03
  • I think your bottleneck is the CPU. The strace profile just shows the time spent in system calls. How long did it run until you interrupted it? You need to divide the times from strace output by that time: part of the time spent for IO = 0.0688 s / total s * 100% – Zrin Apr 3 '14 at 16:23

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.