How to use Strace+pstack tool to analyze program performance

Introduction

Sometimes we need to optimize the program and reduce the program response time. Do we have a more convenient way of analyzing the time complexity of the code in addition to a segment?

If we can directly find the function call that affects the program running time, and then the Code Analysis and optimization for the related function, it is much more efficient than aimlessly looking at the code.

The Strace and Pstack tools can be used together to achieve these goals. The underlying system calls used by the Strace tracker can output the point in time at which the system call was executed and the duration of each call, and the Pstack tool's process output function call stack for the specified PID.

Below we use a simple messaging program that illustrates the specific method of using Strace, Pstack for program analysis.

Program Description
The program is a simple socket program made up of Server/client. The server listens on a port, waits for a client connection, sends a message to the server periodically after the client connects to the server, and the server sends a response message to the client after each message is received. The program server interacts with the client as shown:

After the program has run, it takes a long time for the RESP response to be issued after the server receives a submit message from the client. The time interval between time2 and time1 was found to be around 1s with the tcpdump clutch:

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 the server-side program responds slowly.

Strace viewing system calls
First we pull up the Server/client program and use Strace to track the server process:

# Ps-elf | grep Server | Grep-v grep0 S root 16739 22642 0 0-634, 14:26 pts/2 00:00:00./server# strace-o server.strace-ttt-p 16739Pro Cess 16739 Attached-interrupt to quit

After a while, we'll stop strace, and 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& Gt

You can see that after the server receives the data (corresponding to the recvfrom call), the message is emitted (corresponding to the SendTo call) at about 1s, and the response time is consistent with the result of the packet capture. You can also see that nanosleep system calls took 1s of time.

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

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

Pstack Viewing the function stack
Pstack is a scripting tool whose core implementation is to use GDB and the thread apply all BT command, 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 ()

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

Summary
In this paper, a server/client program case is presented to illustrate the method of analyzing response delay using strace and pstack.

From the initial server side response slow phenomenon, to use strace to trace the specific time-consuming system calls, and to use Pstack to find the program in the specific time-consuming function, step by step to locate the program code that affects the program run time.

More understanding of the underlying, 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.

How to use Strace+pstack tool to analyze program performance