Shulou(Shulou.com)06/01 Report--

This article will explain in detail how to use the strace command in Linux. The editor thinks it is very practical, so I share it with you as a reference. I hope you can get something after reading this article.

Linux common command strace command is a tool that integrates diagnosis, debugging, statistics and integration. We can use strace to analyze the tracking results of system calls and signal transmission of the application, in order to solve problems or understand the working process of the application.

Strace tracks system calls and signals

Add: of course, strace cannot be compared with professional debugging tools such as gdb, because it is not a professional debugger.

The simplest use of strace is to execute a specified command, which exits after the specified command ends. During the execution of the command, strace records and parses all system calls to the command process and all signal values received by the process.

Syntax strace [- dffhiqrtttTvxx] [- acolumn] [- eexpr]... [- ofile] [- ppid]... [- sstrsize] [- uusername] [- Evar=val]... [- Evar]. [command [arg...]] strace-c [- eexpr]... [- Ooverhead] [- Ssortby] [command [arg...] Option-c counts the execution time, number of times and errors of each system call. -d outputs strace debugging information about standard error. -f tracks the child processes generated by fork calls. -ff if-o filename is provided, the tracking results of all processes are output to the corresponding filename.pid, where pid is the process number of each process. -F attempts to trace vfork calls. At-f, vfork is not tracked. -h outputs brief help information. -I output the entry pointer to the system call. -Q forbids the output of messages about separation. -r prints out the relative time for each system call. -t adds time information before each line in the output. -tt adds time information to each line in the output in microseconds. -ttt microsecond output, which represents the time in seconds. -T shows the time spent on each call. -v outputs all system calls. Some calls about environment variables, status, input and output, etc., are not output by default due to frequent use. -V outputs the version information of strace. -x outputs non-standard strings in hexadecimal form-xx all strings output in hexadecimal form. -a column sets the output location of the return value. The default is 40. -e expr specifies an expression that controls how to trace. Format: [qualifier=] [!] value1 [, value2]... Qualifier can only be one of the trace,abbrev,verbose,raw,signal,read,write. Value is a symbol or number used to qualify. The default qualifier is trace. An exclamation point is a negative symbol. For example:-eopen is equivalent to-e trace=open, which means that only open calls are tracked. And-eTracetracking calls open means to trace calls other than open. There are two special symbols, all and none. Note that some shell is used! To execute the commands in the history, so use\. -e trace=set tracks only specified system calls. For example:-e trace=open,close,rean,write means that only these four system calls are tracked. The default is set=all. -e trace=file only tracks system calls related to file operations. -e trace=process only tracks system calls related to process control. -e trace=network tracks all system calls related to the network. -e strace=signal tracks all system calls related to system signals-e trace=ipc tracks all system calls related to process communication-e abbrev=set sets the result set of system calls output by strace.-v and other abbrev=none. The default is abbrev=all. -e raw=set displays the parameters of the specified system call in hexadecimal. -e signal=set specifies the system signal to be tracked. The default is all. For example, the SIGIO signal is not tracked, for example, Sigo (or Sigio). -e read=set outputs data read from the specified file. For example:-e read=3,5-e write=set outputs data written to the specified file. -o filename writes the output of strace to the file filename-p pid tracking the specified process pid. -s strsize specifies the maximum length of the output string. The default is 32. All the file names are output all the time. -u username uses UID and GID of username to execute tracked command instances to track system calls

Now let's do a very simple program to demonstrate the basic use of strace. The C language code of this program is as follows:

# filename test.c # include int main () {int a; scanf ("% d", & a); printf ("% 09d\ n", a); return 0;} then we compile it with gcc-o test test.c to get an executable file, test. Then use the strace call to execute:

During the execution of strace. / test, you are asked to enter an integer, we enter 99, and the result is as follows:

/ / result of direct execution of test oracle@orainst [orcl]: ~ $. / test / / result 99 000000099 / / result of execution of test via strace oracle@orainst [orcl]: ~ $strace. / test / / strace trace result execve (". / test", [. / test "], [/ * 41 vars * /]) = 0 uname ({sys=" Linux ", node=" orainst.desktop.mycompany.com ") ) = 0 brk (0) = 0x8078000 fstat64 (3, {st_mode=S_IFREG | 0644, st_size=65900,...}) = 0 old_mmap (NULL, 65900, PROT_READ, MAP_PRIVATE, 3,0) = 0xbf5ef000 close (3) = 0 open ("/ lib/tls/libc.so.6", O_RDONLY) = 3 read (3) "\ 177ELF\ 1\ 1\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 3\ 0\ 3\ 0\ 1\ 0\ 0\ 0\ 0\ 0\ 1". 512) = 512 fstat64 (3, {st_mode=S_IFREG | 0755, st_size=1571692,...}) = 0 old_mmap (NULL, 4096, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS,-1, 0) = 0xbf5ee000 old_mmap (NULL, 1275340, PROT_READ | PROT_EXEC, MAP_PRIVATE, 3) 0) = 0xa02000 old_mmap (0xb34000, 12288, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_FIXED, 3, 0x132000) = 0xb34000 old_mmap (0xb37000, 9676, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_FIXED | MAP_ANONYMOUS,-1,0) = 0xb37000 close (3) = 0 set_thread_area ({entry_number:-1-> 6, base_addr:0xbf5ee740, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0 Limit_in_pages:1, seg_not_present:0, useable:1}) = 0 munmap (0xbf5ef000, 65900) = 0 fstat64 (0, {st_mode=S_IFCHR | 0620, st_rdev=makedev (136,0),...}) = 0 mmap2 (NULL, 4096, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS,-1,0) = 0xbf5ff000 read (0,99 "99\ n", 1024) = 3 fstat64 (1, {st_mode=S_IFCHR | 0620) St_rdev=makedev (136,0),...}) = 0 mmap2 (NULL, 4096, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS,-1,0) = 0xbf5fe000 write (1, "000000099\ n", 10000000099) = 10 munmap (0xbf5fe000, 4096) = 0 exit_group (0) =? As can be seen from the trace structure, the system first calls execve to start a new process, then initializes the environment, and finally stops at "read (0,"), that is, it executes to our scanf function and waits for us to input numbers. After entering 99, the system calls the write function to output the formatted value "000000099" to the screen, and finally calls exit_group to exit. Complete the execution process of the whole program.

Tracking signal transmission

Let's still use the test program above to observe how the process receives the signal. Or first strace. / test, wait until waiting for the input screen, do not enter anything, and then open another window, enter the following command

Killall test can see the launch of our program at this time, and the final trace result is as follows:

Oracle@orainst [orcl]: ~ $strace. / test execve (". / test", [. / test "], [/ * 41 vars * /]) = 0 uname ({sys=" Linux ", node=" orainst.desktop.mycompany.com ",...}) = 0 brk (0) = 0x9ae2000 old_mmap (NULL, 65900, PROT_READ, MAP_PRIVATE, 3) 0) = 0xbf5ef000 close (3) = 0 open ("/ lib/tls/libc.so.6", O_RDONLY) = 3 read (3, "\ 177ELF\ 1\ 1\ 1\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 3\ 0\ 0\ 1\ 0\ 0\ 0\ 200X\ 1"... 512) = 512 fstat64 (3, {st_mode=S_IFREG | 0755, st_size=1571692) ) = 0 old_mmap (NULL, 4096, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS,-1,0) = 0xbf5ee000 old_mmap (NULL, 1275340, PROT_READ | PROT_EXEC, MAP_PRIVATE, 3,0) = 0x2e9000 old_mmap (0x41b000, 12288, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_FIXED, 3, 0x132000) = 0x41b000 old_mmap (0x41e000, 9676, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_FIXED | MAP_ANONYMOUS,-1 0) = 0x41e000 close (3) = 0 set_thread_area ({entry_number:-1-> 6, base_addr:0xbf5ee740, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 munmap (0xbf5ef000, 65900) = 0 fstat64 (0, {st_mode=S_IFCHR | 0620, st_rdev=makedev (136,0) ) = 0 mmap2 (NULL, 4096, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS,-1, 0) = 0xbf5ff000 read (0, 0xbf5ff000, 1024) =? ERESTARTSYS (To be restarted)-SIGTERM (Terminated) @ 0 (0)-+ killed by SIGTERM + trace clearly tells you that the test process "+ killed by SIGTERM + +".

System call statistics

Strace can not only track system calls, but also give you a statistical analysis of all system calls in the process by using the parameter-c. Let's take a look at the statistics of strace. This time we execute strace with the-c parameter:

Strace-c. / test

Finally, we can get the following trace result:

Oracle@orainst [orcl]: ~ $strace-c. / test execve (". / test", [. / test "] [/ * 41 vars * /]) = 0% time seconds usecs/call calls errors syscall-45.90 0.000140 5 27 25 open 34.43 0.000105 4 24 21 stat64 7.54 0.000023 5 5 old_mmap 2.62 0.000008 8 1 munmap 1.97 0.000006 6 1 uname 1.97 0.000006 23 fstat64 1.64 0.000005 3 2 1 read 1.31 0.000004 2 2 close 0.98 0.000003 31 brk 0.98 0.000003 31 mmap2 0.66 0.000002 2 1 Set_thread_area-- 100.00 0.000305 68 47 total here clearly tells you which system functions are called Information such as the number of calls, how much time is consumed, and so on, is very useful for us to analyze a program.

Common parameter description in addition to the-c parameter, strace also provides us with other useful parameters, so that we can easily get the information we want, here is an introduction to those commonly used parameters.

Redirect output

The parameter-o is used to output the results of strace to a file. If the-o parameter is not specified, the default output device is STDERR, that is, the results using "- o filename" and "2 > filename" are the same.

# both commands output the strace results to the file test.txt strace-c-o test.txt. / test strace-c. / test 2 > test.txt to time the system call

Strace can use the parameter-T to print out the time spent on each system call, which is now in the angle brackets on the rightmost side of the call line.

Oracle@orainst [orcl]: ~ $strace-T. / test / / only part of the result read (0,1 "1\ n", 1024) = 2 fstat64 (1, {st_mode=S_IFCHR | 0620, st_rdev=makedev (136,0),...}) = 0 mmap2 (NULL, 4096, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS,-1,0) = 0xbf5fe000 write (1, "000000001\ n", 10000000001) = 10 munmap (0xbf5fe000) 4096) = 0 exit_group (0) =? Time of system call

This is a very useful feature, strace will record the occurrence time of each system call, as long as the use of-t/tt/ttt three parameters to see the effect, specific examples can try their own.

Parameter name output style description-t10 ttt1262169244.788478 exit_group 33 exit_group (0) output is accurate to seconds-tt10:33:48.159682 exit_group (0) output is accurate to subtle-ttt1262169244.788478 exit_group (0) is accurate to subtle and time representation is unix timestamp truncated output

The-s parameter is used to specify the length of the string output from each line of the trace result. Let's see how the-s parameter in the test program affects the result. Now specify-s as 20, and then enter a number string of more than 20 characters in read.

Strace-s 20. / test read (0,2222222222222222222222222 / / there are 25 "22222222222222222222"... / 1024) = 26 / / of the results we see, there are only 20 trace and one existing process.

Strace can not only initialize a process for trace, but also track existing processes. The parameter-p is used for this purpose, and the usage is very simple, as follows.

Strace-p pid comprehensive example said so many functions and parameters, now we come to a practical point, that is, to study the Oracle lgwr process, to see if this process is not like the document said that no 3 seconds to write a log file, taking into account the lgwr log trigger conditions are more, we need to find a free Oracle instance to do this experiment.

To get the pid of the lgwr process, run the following command

Ps-ef | grep lgwr oracle 5912 10 Nov12? 00:14:56 ora_lgwr_orcl gets the pid of lgwr is 5912, now start strace, and then output several trace to the lgwr.txt file, execute the following command

Strace-tt-s 10-o lgwr.txt-p 5912 stop strace after a while, and then view the results. Since there are so many output results, it is convenient for us to only look at the call of the pwrite function used when Oracle writes to the log file.

Grep pwrite\ (20 lgwr.txt, etc., why do you use "pwrite (2") when grep? because I know that the handle numbers of the current log files opened by my machine start with 2. The specific search method is to first use the following statement to find out what the currently active log files are:

Select member, v$log.status from v$log, v$logfile where vandalism log.groupdistribution; get

MEMBER STATUS-/ db/databases/orcl/redo-01-a/redo-t01-g03-m1.log INACTIVE / db/databases / orcl/redo-03-a/redo-t01-g03-m2.log INACTIVE / db/databases/orcl/redo-02-a/redo-t01-g02-m1.log CURRENT / db/databases/orcl/redo-04-a/redo-t01-g02-m2.log CURRENT / db/databases/orcl/redo-01-a/redo-t01-g01-m1.log INACTIVE / db/databases/orcl/redo-03-a/redo-t01-g01-m2.log INACTIVE / db/databases / orcl/redo-02-a/redo-t01-g04-m1.log INACTIVE / db/databases/orcl/redo-04-a/redo-t01-g04-m2.log INACTIVE then go to / proc to find the handle to open the file:

Ll / proc/.5912/fd/ get

Lrwx- 1 oracle dba 64 Dec 30 10:55 18-> / db/databases/orcl/redo-01-a/redo-t01-g01-m1.log lrwx- 1 oracle dba 64 Dec 30 10:55 19-> / db/databases/orcl/redo-03-a/redo-t01-g01-m2.log lrwx- 1 oracle dba 64 Dec 30 10 55 20-> / db/databases/orcl/redo-02-a/redo-t01-g02-m1.log lrwx- 1 oracle dba 64 Dec 30 10:55 21-> / db/databases/orcl/redo-04-a/redo-t01-g02-m2.log lrwx- 1 oracle dba 64 Dec 30 10:55 22-> / db/databases/orcl/redo-01-a/redo-t01- G03-m1.log lrwx- 1 oracle dba 64 Dec 30 10:55 23-> / db/databases/orcl/redo-03-a/redo-t01-g03-m2.log lrwx- 1 oracle dba 64 Dec 30 10:55 24-> / db/databases/orcl/redo-02-a/redo-t01-g04-m1.log lrwx- 1 oracle dba 64 Dec 30 10:55 25-> / db/databases/orcl/redo-04-a/redo-t01-g04-m2.log you can now see that the handles to my machine's current log files are 20 and 21, respectively.

Now we have the following results

11 pwrite 13 pwrite (20, "\ 1\"\ 0\ 0J! "..., 1536, 4363264) = 1536 11 pwrite 1315 55.603569 pwrite (21,"\ 1\ "\ 0\ 0J!", 1536, 4363264) = 1536 11 pwrite 55.606888 (20, "\ 1\"\ 0\ 0M! ", 15364800) = 1536 1115 13 pwrite (21,"\ 1\ "\ 0\ 0m!", 1536, 4364800) = 1536 1115 13 pwrite (21, "\ 1\"\ 0\ 0m! " 4364800) = 1536 11 pwrite 1315 55.607934 pwrite (20, "\ 1\"\ 0\ 0P! "..., 1536, 4366336) = 1536 11 pwrite 1315 55.608199 pwrite (21,"\ 1\ "\ 0\ 0P!", 1536,4366336) = 15361115 1355.610260 pwrite (20, "\ 1\"\ 0\ 0S! "..., 15364367872) = 15361115 1315 55.610530 pwrite (21,"\ 1\ "\ 0\ 0S!" 4367872) = 1536 1114 pwrite 00.602446 pwrite (20, "\ 1\"\ 0\ 0V! "..., 1536, 4369408) = 1536 11 pwrite 1415 00.602750 pwrite (21,"\ 1\ "\ 0\ 0V!", 1536,4369408) = 1536111400.606386 pwrite (20, "\ 1\"\ 0\ 0Y! "..., 15364370944) = 15361114 14rel 00.606676 pwrite (21,"\ 1\ "\ 0\ 0Y!" 4370944) = 1536 11 pwrite 14 pwrite 00.607900 pwrite (20, "\ 1\"\ 0\ 0\\ "..., 1024, 4372480) = 1024 11 14 pwrite 00.608161 pwrite (21,"\ 1\ "\ 0\ 0\\", 1024,4372480) = 1024 1114 1400.608816 pwrite (20, "\ 1\"\ 0\ 0 ^! ", 10244373504) = 1024 1114 14 pwrite 00.609071 pwrite (21,"\ 1\ "\ 0\ 0 ^ 0!). 1024, 4373504) = 1024 1111414 pwrite (20, "\ 1\"\ 0\ 0`! ", 1536, 4374528) = 1536 1111454 pwrite (21,"\ 1\ "\ 0\ 0`!", 1536,4374528) = 1536111141414 pwrite (20, "\ 1\"\ 0\ 0c! "..., 10244376064) = 10241114 14 pwrite 05.603119 pwrite (21,"\ 1\ "\ 0\ 0c!). 1024, 4376064) = 1024 11 pwrite 14pwrite 05.607731 pwrite (20, "\ 1\"\ 0\ 0e! "..., 1024, 4377088) = 1024 1111 14 pwrite 05.608020 pwrite (21,"\ 1\ "\ 0\ 0e!", 10244377088) = 1024 111114 pwrite 05.608690 pwrite (20, "\ 1\"\ 0\ 0g! "..., 10244378112) = 1024 1114 14 pwrite (21,"\ 1\ "\ 0\ 0g!) 1024, 4378112) = 1024 11 strace 14 pwrite 05.611022 pwrite (20, "\ 1\"\ 0\ 0i! "..., 1536, 4379136) = 1536 11 14 Linux 05.611283 Linux (21,"\ 1\ "\ 0\ 0i!..., 15364379136) = 1536 this is the end of the article on how to use the command in Linux. Hope that the above content can be helpful to you, so that you can learn more knowledge, if you think the article is good, please share it for more people to see.

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.