Use strace + pstack to analyze Program Performance

Introduction

Sometimes we need to optimize the program and reduce the program response time. In addition to analyzing the time complexity of code in segments, do we have more convenient methods?

If you can directly find the function calls that affect the running time of the program, and analyze and optimize the code of the relevant functions, it is much more efficient than looking at the code without any aim.

Use strace and pstack together to achieve the above purpose. The underlying system call used by the strace tracing program can output the time points when the system call is executed and the time consumed by each call. The pstack tool outputs the function call stack to the process of the specified PID.

The following describes how to use strace and pstack for program analysis through a simple message sending and receiving program.

Program description
This program is a simple socket program consisting of server/client. The server listens to a port and waits for the connection from the client. After the client connects to the server, it regularly sends messages to the server. Each time the server receives a message, it sends a Response Message to the client. The interaction between the program server and the client is shown as follows:

After the program runs, it takes a long time for the server to send a resp response after it finds that the server receives the submit message from the client. Through tcpdump packet capture, it is found that the interval between time2 and time1 is about 1 s:

According to the preliminary analysis above, the slow message response is a program problem on the server side. Next we will look at how to use strace and pstack to analyze the reasons for slow response of the server program.

 

View system calls in strace
First, we pull the server/client program and use strace to track the server process:

# ps -elf | grep server | grep -v grep0 S root 16739 22642 0 76 0 - 634 1024 14:26 pts/2 00:00:00 ./server# strace -o server.strace -Ttt -p 16739Process 16739 attached - interrupt to quit

 

After a while, we will stop strace. The server. strace file has the following output:

14:46:39.741366 select(8, [3 4], NULL, NULL, {1, 0}) = 1 (in [4], left {0, 1648}) <0.998415>14:46:40.739965 recvfrom(4, "hello", 6, 0, NULL, NULL) = 5 <0.000068>14:46:40.740241 write(1, "hello\n", 6)  = 6 <0.000066>14:46:40.740414 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000046>14:46:40.740565 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0 <0.000048>14:46:40.740715 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000046>14:46:40.740853 nanosleep({1, 0}, {1, 0}) = 0 <1.000276>14:46:41.741284 sendto(4, "hello\0", 6, 0, NULL, 0) = 6 <0.000111>

After the server receives the data (corresponding to the recvfrom call), the message is sent (corresponding to sendto call) in about one second. The response time is consistent with the packet capture result. It can be seen that the nanosleep system calls took 1 s.

Therefore, it can be determined that the response delay is caused by the function call corresponding to nanosleep.

Which function is called? The answer cannot be found in the strace output result, because the output shows that all of them are system calls. to display the function call stack information in the program, it is pstack's turn.

 

Pstack view function Stack
Pstack is a script tool. Its core implementation is to use the GDB and thread apply all BT commands. Below we use pstack to view the server process function Stack:

# sh pstack.sh 16739#0 0x00002ba1f8152650 in __nanosleep_nocancel () from /lib64/libc.so.6#1 0x00002ba1f8152489 in sleep () from /lib64/libc.so.6#2 0x00000000004007bb in ha_ha ()#3 0x0000000000400a53 in main ()

From the above information, we can see that the function call relationship is main-> ha_ha-> sleep, so we can find the ha_ha function for analysis and optimization and modification.

Summary
This article uses a server/client program example to illustrate how to analyze the response latency using strace and pstack.

From the initial server-side slow response, to the use of strace to trace specific time-consuming system calls, and then to the use of pstack to find specific time-consuming functions in the program, find the program code that affects the running time step by step.

More understanding of the underlying layer, starting from the operating system level, is more conducive to program performance analysis and optimization.