Self-help Linux problem diagnosis tool strace

Introduction

"Oops, the system crashes ..."

"Oops, the program crashes ..."

"Oops, command execution error ..."

 

For maintenance personnel, such tragedies are happening every day. Ideally, the system or application error log provides enough comprehensive information. By viewing the relevant logs, the maintenance staff can quickly locate the cause of the problem. However, in reality, many error logs are printed to simulate the occurrence of errors (for example, "cocould not open file", "connect to XXX time out "), rather than the cause of the error.

 

Error logs cannot meet the problem locating requirements. Can we start to analyze them in a deeper layer? The execution of programs or commands requires interaction with the operating system through system call. In fact, we can define the error range by observing these system calls, their parameters, and return values, even find out the root cause of the problem.

 

In Linux, strace is such a tool. Through it, we can track system calls generated during program execution and receive signals to help us analyze exceptions encountered during program or command execution.

 

A simple example

How to Use strace to track programs and view corresponding output? The following is an example.

1. Examples of Tracked programs

//main.c
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
int main( )
{
　　int fd ;
　　int i = 0 ;
　　fd = open( “/tmp/foo”, O_RDONLY ) ;
　　if ( fd < 0 )
　　　　i=5;
　　else
　　　　i=2;
　　return i;
}

The above program tries to open the/tmp/foo file in read-only mode, and then exits. Only the open system calls the function. Then we compile the program to generate an executable file:

lx@LX:~$ gcc main.c -o main

 

2. strace Trace Output

Run the following command to track the above programs and redirect the results to the main. strace file:

lx@LX:~$ strace -o main.strace ./main

Next let's take a look at the content of the main. strace file:

Lx @ LX :~ $ Cat main. strace
1 execve ("./main", ["./main"], [/* 43 vars */]) = 0
2 brk (0) = 0x9ac4000
3 access ("/etc/ld. so. nohwcap", F_ OK) =-1 ENOENT (No such file or directory)
4 mmap2 (NULL, 8192, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS,-1, 0) = 0xb7739000
5 access ("/etc/ld. so. preload", R_ OK) =-1 ENOENT (No such file or directory)
6 open ("/etc/ld. so. cache", O_RDONLY) = 3
7 fstat64 (3, {st_mode = S_IFREG | 0644, st_size = 80682,...}) = 0
8 mmap2 (NULL, 80682, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7725000
9 close (3) = 0
10 access ("/etc/ld. so. nohwcap", F_ OK) =-1 ENOENT (No such file or directory)
11 open ("/lib/i386-linux-gnu/libc. so.6", O_RDONLY) = 3
12 read (3, "\ 177ELF \ 1 \ 1 \ 0 \ 0 \ 0 \ 0 \ 0 \ 0 \ 0 \ 0 \ 0 \ 0 \ 3 \ 0 \ 3 \ 0 \ 1 \ 0 \ 0 \ 0 \ 0 \ 0 \ 220o \ 1 \ 0004 \ 0 \ 0 \ 0 "..., 512) = 512
13 fstat64 (3, {st_mode = S_IFREG | 0755, st_size = 1434180,...}) = 0
14 mmap2 (NULL, 1444360, PROT_READ | PROT_EXEC, MAP_PRIVATE | MAP_DENYWRITE, 3, 0) = 0x56d000
15 mprotect (0x6c7000, 4096, PROT_NONE) = 0
16 (0x6c8000, 12288, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_FIXED | MAP_DENYWRITE, 3, 0x15a) = 0x6c8000
17 mmap2 (0x6cb000, 10760, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_FIXED | MAP_ANONYMOUS,-1, 0) = 0x6cb000
18 close (3) = 0
19 mmap2 (NULL, 4096, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS,-1, 0) = 0xb7724000
20 set_thread_area ({entry_number:-1-> 6, base_addr: limit, limit: 1048575, seg_32bit: 1, contents: 0, read_exec _ only: 0, limit_in_pages: 1, seg_not_present: 0, useable: 1}) = 0
21 mprotect (0x6c8000, 8192, PROT_READ) = 0
22 mprotect (0x8049000,409 6, PROT_READ) = 0
23 mprotect (0x4b0000, 4096, PROT_READ) = 0
24 munmap (0xb7725000, 80682) = 0
25 open ("/tmp/foo", O_RDONLY) =-1 ENOENT (No such file or directory)
26 exit_group (5) =?
// The highlighted red line number is added for convenience instructions, and the output is not executed by strace.

Are you worried about the output? Don't worry. Next we will analyze the output one by one.

 

The system call generated when the strace tracing program interacts with the system. Each line above corresponds to a system call. The format is:

Name of the System Call (parameter...) = return value error flag and description

 

Line 1: For programs executed under the command line, execve (or one of the exec series calls) is the first in the strace Output System Call. Strace first calls the fork or clone function to create a sub-process, and then calls exec in the sub-process to load the program to be executed (here is./main)

Line 2: Uses 0 as the parameter to call brk. The returned value is the starting address of Memory Management (if malloc is called in a sub-process, space is allocated from the 0x9ac4000 address)

Line 3: Call the access function to check whether/etc/ld. so. nohwcap exists.

Line 4: Use the mmap2 function for anonymous memory ing to obtain the 8192bytes memory space. The starting address of this space is 0xb7739000. For anonymous memory ing, see here.

Line 6: Call the open function to open the/etc/ld. so. cache file. The returned file descriptor is 3.

Line 7: Fstat64 function to get/etc/ld. so. cache file information

Line 8: Call the mmap2 function to map the/etc/ld. so. cache file to the memory. For details about how to use the mmap ing file to the memory, see here

Line 9: Close the/etc/ld. so. cache file pointed to by the file descriptor 3.

Line12: Call read to read 512 bytes from the/lib/i386-linux-gnu/libc. so.6 libc library file, that is, read ELF header information

Line15: Use the mprotect function to protect the 4096bytes space starting with 0x6c7000 (PROT_NONE indicates that access is not allowed, and PROT_READ indicates that access is allowed)

Line24: Call the munmap function to map the/etc/ld. so. cache file from the memory, which corresponds to mmap2 of Line 8.

Line25: Corresponds to the unique system call-open function used in the source code to open the/tmp/foo file.

Line26: The sub-process ends. The exit code is 5 (why is the exit value 5? Return to the previous sample code to check the source code :)

 

3. Output Analysis

Call! After reading this multi-system call function, isn't it easy to find it? Let's get back to the topic strace.

From the above output, we can find that only the open System Call (Line25) can correspond to the source code, and almost all other system calls are used for process initialization: load the program to be executed, load the libc function library, and set the memory ing.

 

The if statements or other code in the source code are not reflected in the corresponding strace output, because they do not invoke the system call. Strace only cares about the interaction between the program and the system. Therefore, strace is not applicable to troubleshooting and Analysis of Program Logic code.

 

For hundreds of system calls in Linux, the number of strace output above is only the tip of the iceberg. If you want to learn more about Linux system calls, just man!

Man 2 system call name
Man ld. so // Linux dynamic link manpage

 

Common strace options

This section describes several strace command options that are frequently used and when to use these options.

1. Track sub-Processes

By default, strace only tracks the specified process, rather than the newly created sub-process in the specified process. Use the-f option to track newly created sub-processes in the process and print the corresponding process PID in the output result:

mprotect(0x5b1000, 4096, PROT_READ)     = 0
munmap(0xb77fc000, 80682)               = 0
clone(Process 13600 attached
child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb77fb938) = 13600
[pid 13599] fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
[pid 13600] fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
[pid 13599] mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 13600] mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb780f000
……

When you use strace to trace multi-process programs, commands, and scripts, the-f option is generally enabled.

 

2. Record the system call time

Strace can also record the time information of each system call when the program interacts with the system. There are several options, such as r, t, tt, ttt, and T, which record the time:

-T: records the time spent by each system call, accurate to microseconds.

-R: timing the first system call (usually execve), accurate to microseconds

-T: hour: minute: Second

-Tt: hour: minute: Second. microsecond

-Ttt: the number of seconds since the computer epoch. microseconds

The T option is commonly used because it provides the time required for each system call. The time records of other options include both the system call time and the user-level code execution time, which makes little reference. We can combine some time options, for example:

strace -Tr ./main
0.000000 execve(“./main”, [“main”], [/* 64 vars */]) = 0
0.000931 fcntl64(0, F_GETFD)= 0 <0.000012>
0.000090 fcntl64(1, F_GETFD)= 0 <0.000022>
0.000060 fcntl64(2, F_GETFD)= 0 <0.000012>
0.000054 uname({sys=”Linux”, node=”ion”, ...}) = 0 <0.000014>
0.000307 geteuid32()= 7903 <0.000011>
0.000040 getuid32()= 7903 <0.000012>
0.000039 getegid32()= 200 <0.000011>
0.000039 getgid32()= 200 <0.000011>
……

The leftmost column is the time output corresponding to the-r option, and the rightmost column is the output corresponding to the-T option.

 

3. Track Running Processes

Use strace to trace the running program and run the "strace-p PID" command. After the command is executed, the tracked process will be executed as usual, other strace options also apply to running process tracing.

 

Use the strace handler to kill

Finally, we use a program example to learn how to use the strace analysis program to die.

1. Dead program source code

// Hang. c
# Include <stdio. h>
# Include <sys/types. h>
# Include <unistd. h>
# Include <string. h>

Int main (int argc, char ** argv)
{
Getpid (); // identifies a system call.
If (argc <2)
{
Printf ("hang (user | system) \ n ");
Return 1;
}
If (! Strcmp (argv [1], "user "))
While (1 );
Else if (! Strcmp (argv [1], "system "))
Sleep (500 );
Return 0;
}

The user and system parameters can be transmitted to the program. The above Code uses an endless loop to simulate user State death, and CALLS sleep to simulate kernel state program death.

2. strace Trace Output

Output of dead trace in user mode:

lx@LX:~$ gcc hang.c -o hang
lx@LX:~$ strace ./hang user
……
mprotect(0x8049000, 4096, PROT_READ)    = 0
mprotect(0xb59000, 4096, PROT_READ)     = 0
munmap(0xb77bf000, 80682)               = 0
getpid()                                = 14539

Output of kernel state dead tracing:

lx@LX:~$ strace ./hang system
……
mprotect(0x8049000, 4096, PROT_READ)    = 0
mprotect(0xddf000, 4096, PROT_READ)     = 0
munmap(0xb7855000, 80682)               = 0
getpid()                                = 14543
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({500, 0}, 

 

3. Output Analysis

When the user State fails, strace does not have other system call output after the getpid () line is output. If the process crashes in the kernel state, the system call nanosleep in the last line cannot be completely displayed, no returned value of nanosleep indicates that the call has not been completed.

 

Therefore, we can draw the following conclusion: Use strace to trace dead programs. If the system call in the last line is complete, the program will be suspended in the logic code. If the system call in the last line is incomplete, the program crashes at the system call.

 

When the program crashes in the system call, we can view the man manual of the corresponding system call to find out under what circumstances the system call will crash. In addition, system call parameters also provide us with some information, such as hanging to the following system call:

read(16,

Then we can know that the read function is reading the file or socket with the file descriptor 16. Further, we can use the lsof tool, obtains information about the file name corresponding to file descriptor 16 and the processes that occupy the file.

 

Summary

This article introduces strace, a common problem diagnosis tool in Linux, and introduces how to use strace, the output format, and how to use strace to analyze program crashes, in addition, several common options of the strace tool are described, and the applicable scenarios of these options are described.

Next time, if the program crashes and the command execution reports an error, if you do not see the cause of the problem from the program log and System Log, do not rush to google or ask experts for help, don't forget that a powerful tool is there, so it will never be abandoned. Just take a look at strace!

 

Reference: Self-Service Linux