How to use the Strace+pstack tool to analyze program performance

Introduction

Sometimes we need to optimize the program and reduce the response time of the program. In addition to a paragraph of the time complexity of the code analysis, we have a more convenient way.

If you can directly find the impact of the program running time function calls, and then to the relevant functions of the Code Analysis and optimization, which compared to aimlessly looking at the code, efficiency is much higher.

The Strace and Pstack tools can be used together to achieve these goals. Strace the underlying system call used by the trace program to output the point at which the system call was executed and the time taken by each call, and the process output function call stack for the Pstack tool on the specified PID.

Below we use a simple message to send and receive the procedure, explained uses Strace, the Pstack carries on the procedure analysis the concrete method.

Program Description
The program is a simple socket program, composed of Server/client. The server listens on a port, waits for the client to connect, sends a message to the server when the client connects to the server, and the server sends a response message to the client every time a message is received. The program server interacts with the client as follows:

After the program has been run, it takes a long time for the RESP response to be issued after the server has received the client's submit message. Through the tcpdump grab bag found that time2 and time1 interval of around 1s:

From the preliminary analysis, it is known that the slow message response is a server-side program problem. Let's look at how to use Strace and pstack to analyze why server-side programs respond slowly.

strace View System calls
First we pull up the Server/client program and use Strace to track the server process:

# Ps-elf | grep Server | Grep-v grep
0 S root 16739 22642 0 0-634 1024 14:26 pts/2 00:00:00./server strace-o
- P 16739
Process 16739 attached-interrupt to quit

After some time, we will stop the Strace, 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 Rec Vfrom (4, "Hello", 6, 0, NULL, NULL) = 5 <0.000068>
14:46:40.740241 write (1, "hello\n", 6)  = 6 <0.000066&G t;
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.0 00046>
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>

You can see the server after receiving data (corresponding to the recvfrom call), after 1s or so time to send the message (corresponding to the SendTo call), from the response time, and the results of the bag to coincide. You can also see that the nanosleep system call took 1s of time.

Therefore, it can be concluded that the response delay is caused by a function call corresponding to Nanosleep.

What is the specific function call? In strace output results can not find the answer, because its output is the system call, to display the program in the function call stack information, it is pstack to play.

pstack view function Stack
Pstack is a scripting tool whose core implementation is to use the GDB and thread apply all BT commands, and here 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 MA In ()

As can be seen from the above information, the function call relationship is: main->ha_ha->sleep, so we can find the Ha_ha function to analyze and optimize the modification.

Summary
In this paper, a server/client program is used to illustrate the method of using Strace and Pstack to analyze the response delay.

From the initial server-side slow response, to the use of strace tracking the specific time-consuming system calls, and then using the Pstack to find out the program specific time-consuming functions, step-by-Step to find the impact of the program running time code.

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

The server/client programs and pstack scripts used in this article can be downloaded from here.