Difference between revisions of "Strace: what a process does"

From Linuxintro
imported>ThorstenStaerk
m
 
(38 intermediate revisions by 2 users not shown)
Line 1: Line 1:
 
<metadesc>How to strace a process. How to understand strace's output. How to follow sub-processes, how to format the string length so you get a sensible meaning, how to find the file descriptors and how to see where the process spends most of its time.</metadesc>
 
<metadesc>How to strace a process. How to understand strace's output. How to follow sub-processes, how to format the string length so you get a sensible meaning, how to find the file descriptors and how to see where the process spends most of its time.</metadesc>
So you have a process that is crashing or misbehaving and you found the tool strace to tell you what the process does. However you don't understand its output? Then this article is for you.
 
  
<pic src="http://www.linuxintro.org/strace-mindmap.jpg" width=50% align=right caption="strace mindmap" />
+
strace is a [[command]] that shows a process' calls to the kernel (aka syscalls). This helps you to do excellent troubleshooting and gain good performance tuning insights.
  
= starting strace =
+
<pic border=1 src="http://www.linuxintro.org/strace-mindmap.jpg" width=50% align=right caption="strace cheat sheet" link="http://www.linuxintro.org/strace-mindmap.jpg" />
You can start a new process with strace or you can attach strace to an already running process. To start a new process just put strace in front of its command:
+
 
strace <abbr title="print the first 99 characters of every output string">-s 99</abbr> <abbr title="follow child processes">-ff</abbr> <abbr title="command that you want to execute and trace">ls</abbr>
+
= Understand strace's output =
To attach strace to an already running process, in this example firefox, find out the process' id:
+
Let's start with a real-world example: You want to [[troubleShoot sound]] on your computer. You know that speaker-test does some test noise. To find out what exactly happens, issue:
  # ps -A | grep firefox
+
  # strace -s 99 -ff speaker-test
2728 pts/1    00:00:02 firefox
+
You will find a lot of lines like
Then call strace with the id as parameter:
+
 
strace <abbr title="print the first 99 characters of every output string">-s 99</abbr> <abbr title="follow child processes">-ff</abbr><abbr title="process id">p</abbr> 2728
+
<pre>
 +
[pid 15287] write(6, "W", 1)            = 1
 +
[pid 15287] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"L\0\0\0\2L\0\0\2+U\0\0\0\0\0\31vqU\0\0\0\0\0\0\0\0001TU \240\326\0\4\252\354TU \240\326\0\4\262%r\0\0\0\0\0\20\0\0r\0\0\0\0\0\2\260\220R\0\0\0\0\0\0\0\0R\0\0\0\0\0\2\260\220", 83}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 83
 +
[pid 15287] write(6, "W", 1)            = 1
 +
</pre>
  
= Understanding strace's output =
+
'''Looks complicated, right?''' But fear not, every line follows the same pattern:
The bad news is that strace's output looks tedious like this:
+
;[pid ''process id''] syscall(parameters) = return code
clock_gettime(CLOCK_MONOTONIC, {4433, 764347636}) = 0
 
poll([{fd=12, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=12, revents=POLLIN|POLLRDNORM}])
 
<abbr title="Syscall. Find out more with the command man 2 recv.">recv</abbr>(<abbr title="As we can tell from man 2 recv, the following is a file descriptor. Find out more with the command cat /prov/''PID''/fd/12">12</abbr>, "\37\36&\364T<\264\6Og\20\2\30%-\31C\3757\350{\260\0203\351\23&O\365(y\212"..., 16384, 0) = 1448
 
The good news is that every line follows the same scheme:
 
syscall(parameters) = return value
 
Whatever you see for syscall you can get help on using the man(2) pages. So for the above example
 
man 2 clock_gettime
 
man 2 poll
 
man 2 recv
 
Will give you the information what is going on. For example, clock_gettime retrieves the current time.
 
  
 +
You will only find the first column with the '''process id''' if you use the -ff option (follow sub-processes). For the '''syscall''' (write or recvmsg in the above example) it is easy to obtain information - just type
 +
man 2 ''syscall''
 +
in the above example
 +
man 2 write
 +
and
 +
man 2 recvmsg
 +
And you will find abundant information what the syscall does. If you understand 50% you are doing well :)
 +
The '''return code''' will also be documented in the syscall's man page.
  
Wow, that was easy. Now to the next line, poll. According to [http://linux.die.net/man/2/poll man 2 poll] it waits for an event on a file descriptor, like "data to be read". The file descriptor is the first argument, 12. Fortunately you can look up the file descriptor's meaning if you know the process id. In this case the process id was 7179:
+
'''So what happens here?''' Obviously speaker-test calls the kernel's ''recvmsg'' method. The interesting thing we get from <tt>man 2 recvmsg</tt> is that the first parameter is sockfd, the file descriptor of a socket. So it hands over a socket as a parameter. Let's look at process' file descriptors:
  /proc/7179/fd # ll
+
<pre>
 +
  cd /proc/15287/fd
 +
ls -l
 
  total 0
 
  total 0
  lr-x------ 1 root root 64 Apr 19 08:02 0 -> /dev/null
+
  lrwx------ 1 root root 64 Apr 4 22:55 0 -> /dev/pts/4
  lrwx------ 1 root root 64 Apr 19 08:02 1 -> socket:[156171]
+
  lrwx------ 1 root root 64 Apr 4 22:55 1 -> /dev/pts/4
  l-wx------ 1 root root 64 Apr 19 08:02 2 -> /var/log/apache2/error_log
+
  lrwx------ 1 root root 64 Apr 4 22:55 2 -> /dev/pts/4
  lr-x------ 1 root root 64 Apr 19 08:02 4 -> pipe:[156208]
+
  lr-x------ 1 root root 64 Apr 4 22:55 3 -> pipe:[297487]
  l-wx------ 1 root root 64 Apr 19 08:02 5 -> pipe:[156208]
+
  l-wx------ 1 root root 64 Apr 4 22:55 4 -> pipe:[297487]
  l-wx------ 1 root root 64 Apr 19 08:02 6 -> /var/log/apache2/access_log
+
  lr-x------ 1 root root 64 Apr 4 22:55 5 -> pipe:[297488]
  lrwx------ 1 root root 64 Apr 19 08:02 7 -> anon_inode:[eventpoll]
+
  l-wx------ 1 root root 64 Apr 4 22:55 6 -> pipe:[297488]  
  lrwx------ 1 root root 64 Apr 19 08:02 12 -> socket:[155097]
+
  lrwx------ 1 root root 64 Apr 4 22:55 7 -> socket:[297495]
 +
</pre>
  
Ok, to find out what socket:[155097] is we use the command
+
aha! file descriptor 7 is the unix socket 297495. Let's look what this is connected to:
# lsof | grep 155097
 
httpd2-pr 7158            root    3u    IPv4    155097      0t0        TCP *:http (LISTEN)
 
httpd2-pr 7179          wwwrun    3u    IPv4    155097      0t0        TCP *:http (LISTEN)
 
  
So this is a socket listening to the http port.
+
<pre>
 +
ss -p | grep 297495
 +
u_str  ESTAB      0      0      /run/user/0/pulse/native 297496                * 297495  users:(("pulseaudio",2289,28))
 +
u_str  ESTAB      0      0                    * 297495                * 297496  users:(("speaker-test",15286,7))
 +
</pre>
 +
 
 +
We see - the socket 297495 is connected to the socket 297496. What is written into 297495 will be readable from 297496 and the other way round. This couple of sockets connects the speaker-test process with the pulseaudio process. 2289 is pulseaudio's process id, and 15286 is the root process id of speaker-test. This system is using pulseaudio for sound which is an important information for troubleshooting sound. In my example I had been messing around with pulseaudio's configuration and I could fix the problem quickly once I understood I was using it.
 +
 
 +
= strace start options =
 +
You can start a new process with strace or you can attach strace to an already running process. To start a new process just put strace in front of its command:
 +
strace -s 99 -ff ls
 +
 
 +
To attach strace to an already running process, in this example firefox, find out the process' id:
 +
ps -A | grep firefox
 +
2728 pts/1    00:00:02 firefox
 +
 
 +
Then call strace with the id as parameter:
 +
strace -s 99 -ff -p 2728
  
 
= limitations =
 
= limitations =
 
strace will show you all syscalls from a process, and that's it. This also mean that if your process hangs in an endless loop that does not do any syscall, strace will not show anything.
 
strace will show you all syscalls from a process, and that's it. This also mean that if your process hangs in an endless loop that does not do any syscall, strace will not show anything.
 +
 +
= Examples =
 +
* [http://scn.sap.com/community/linux/blog/2014/04/11/dispwork-running-but-not-connected-to-message-server# find out why SAP does not start]
 +
* find out why [[shellinabox]] shows [[forkpty failed]]
 +
* you can find out [[is my ulimit exceeded]]
 +
* I only got [[guacAmole]] to run because I strace'd it.
  
 
= interprocess communication =
 
= interprocess communication =
Line 57: Line 81:
 
* by writing into files
 
* by writing into files
  
 +
== via sockets ==
 
For example when using strace to [[troubleshoot sound]] you may see that speaker-test receives messages from file descriptor 7:
 
For example when using strace to [[troubleshoot sound]] you may see that speaker-test receives messages from file descriptor 7:
  # strace -s 99 -ffp 32681
+
<pre>
 +
  strace -s 99 -ffp 32681
 
  [pid 32682] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"L\0\0\0\2L\0\0\0}U\0\0\0\0\0\22\10\277U\0\0\0\0\0\0\0\0001TU b|\0\17(\347TU b|\0\0175\342r\0\0\0\0\0\20\0\0r\0\0\0\0\0\2\260\220R\0\0\0\0\0\0\0\0R\0\0\0\0\0\2\260\220", 83}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 83
 
  [pid 32682] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"L\0\0\0\2L\0\0\0}U\0\0\0\0\0\22\10\277U\0\0\0\0\0\0\0\0001TU b|\0\17(\347TU b|\0\0175\342r\0\0\0\0\0\20\0\0r\0\0\0\0\0\2\260\220R\0\0\0\0\0\0\0\0R\0\0\0\0\0\2\260\220", 83}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 83
 +
</pre>
 
Now let's find out what file descriptor 7 of process 32681 is:
 
Now let's find out what file descriptor 7 of process 32681 is:
  # ll /proc/32681/fd/7
+
<pre>
 +
  ll /proc/32681/fd/7
 
  lrwx------ 1 root root 64 Apr  4 18:17 /proc/32681/fd/7 -> socket:[198064]
 
  lrwx------ 1 root root 64 Apr  4 18:17 /proc/32681/fd/7 -> socket:[198064]
 +
</pre>
 
So it is unix socket 198064. Let's find out what process it is:
 
So it is unix socket 198064. Let's find out what process it is:
 +
<pre>
 
  # ss -p | grep 198064
 
  # ss -p | grep 198064
 
  u_str  ESTAB      0      0                    * 198064                * 198065  users:(("speaker-test",32681,7))
 
  u_str  ESTAB      0      0                    * 198064                * 198065  users:(("speaker-test",32681,7))
 
  u_str  ESTAB      0      0      /run/user/0/pulse/native 198065                * 198064  users:(("pulseaudio",2289,28))
 
  u_str  ESTAB      0      0      /run/user/0/pulse/native 198065                * 198064  users:(("pulseaudio",2289,28))
 +
</pre>
 +
 +
== via pipes ==
 +
Let's construct a situation where processes communicate via [[pipe]]s. The following [[command]] will create two processes, cat writing random data to a pipe and grep reading it:
 +
cat /dev/urandom | grep "To be or not to be, that is the question"
 +
 +
Let's find the process IDs:
 +
<pre>
 +
ps -A | grep -E "cat|grep"
 +
  8654 pts/1    00:10:30 cat
 +
  8655 pts/1    00:00:04 grep
 +
10949 pts/2    00:00:00 grep
 +
</pre>
 +
Let's look at cat's file descriptors:
 +
<pre>
 +
cd /proc/8654/fd
 +
ll
 +
total 0
 +
lrwx------ 1 root root 64 Apr  6 11:40 0 -> /dev/pts/1
 +
l-wx------ 1 root root 64 Apr  6 11:40 1 -> pipe:[70679]
 +
lrwx------ 1 root root 64 Apr  6 11:39 2 -> /dev/pts/1
 +
lr-x------ 1 root root 64 Apr  6 11:40 3 -> /dev/urandom
 +
</pre>
 +
So cat is communicating with a pipe numbered 70679. Let's see if we can find the other process that is reading from it:
 +
<pre>
 +
lsof | grep 70679
 +
cat        8654            root    1w    FIFO        0,8      0t0      70679 pipe
 +
grep      8655            root    0r    FIFO        0,8      0t0      70679 pipe
 +
</pre>
 +
Works. We can use the command [[lsof]] to find the processes involved into pipe communication.
  
 
= Search for a syscall =
 
= Search for a syscall =
 
With strace, you can search for a special syscall. For example,
 
With strace, you can search for a special syscall. For example,
 
  strace -e open ''command''
 
  strace -e open ''command''
 +
 
will show you all files that have been touched (opened) by ''command''. This can be used e.g. to [[find out where configuration changes are stored]].
 
will show you all files that have been touched (opened) by ''command''. This can be used e.g. to [[find out where configuration changes are stored]].
  
 
= Performance analysis =
 
= Performance analysis =
 
With strace, you can find out the biggest time-consuming syscalls during a program run:
 
With strace, you can find out the biggest time-consuming syscalls during a program run:
 +
<pre>
 
  strace -c ls -R
 
  strace -c ls -R
 
  Entries  Repository  Root
 
  Entries  Repository  Root
Line 106: Line 168:
 
  ------ ----------- ----------- --------- --------- ----------------
 
  ------ ----------- ----------- --------- --------- ----------------
 
  100.00    0.614296                198036        19 total
 
  100.00    0.614296                198036        19 total
 
+
</pre>
 
Now you go
 
Now you go
 
  [http://linux.die.net/man/2/getdents64 man 2 getdents64]
 
  [http://linux.die.net/man/2/getdents64 man 2 getdents64]
Line 119: Line 181:
  
 
[[Category:low-level]]
 
[[Category:low-level]]
 +
[[Category:TroubleShooting]]
 
[[Category:command]]
 
[[Category:command]]
 +
[[Category:mindmap]]

Latest revision as of 08:20, 22 July 2023


strace is a command that shows a process' calls to the kernel (aka syscalls). This helps you to do excellent troubleshooting and gain good performance tuning insights.

strace cheat sheet

Understand strace's output

Let's start with a real-world example: You want to troubleShoot sound on your computer. You know that speaker-test does some test noise. To find out what exactly happens, issue:

# strace -s 99 -ff speaker-test

You will find a lot of lines like

[pid 15287] write(6, "W", 1)            = 1
[pid 15287] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"L\0\0\0\2L\0\0\2+U\0\0\0\0\0\31vqU\0\0\0\0\0\0\0\0001TU \240\326\0\4\252\354TU \240\326\0\4\262%r\0\0\0\0\0\20\0\0r\0\0\0\0\0\2\260\220R\0\0\0\0\0\0\0\0R\0\0\0\0\0\2\260\220", 83}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 83
[pid 15287] write(6, "W", 1)            = 1

Looks complicated, right? But fear not, every line follows the same pattern:

[pid process id] syscall(parameters) = return code

You will only find the first column with the process id if you use the -ff option (follow sub-processes). For the syscall (write or recvmsg in the above example) it is easy to obtain information - just type

man 2 syscall

in the above example

man 2 write 

and

man 2 recvmsg

And you will find abundant information what the syscall does. If you understand 50% you are doing well :) The return code will also be documented in the syscall's man page.

So what happens here? Obviously speaker-test calls the kernel's recvmsg method. The interesting thing we get from man 2 recvmsg is that the first parameter is sockfd, the file descriptor of a socket. So it hands over a socket as a parameter. Let's look at process' file descriptors:

 cd /proc/15287/fd
 ls -l
 total 0
 lrwx------ 1 root root 64 Apr  4 22:55 0 -> /dev/pts/4
 lrwx------ 1 root root 64 Apr  4 22:55 1 -> /dev/pts/4
 lrwx------ 1 root root 64 Apr  4 22:55 2 -> /dev/pts/4
 lr-x------ 1 root root 64 Apr  4 22:55 3 -> pipe:[297487]
 l-wx------ 1 root root 64 Apr  4 22:55 4 -> pipe:[297487]
 lr-x------ 1 root root 64 Apr  4 22:55 5 -> pipe:[297488]
 l-wx------ 1 root root 64 Apr  4 22:55 6 -> pipe:[297488] 
 lrwx------ 1 root root 64 Apr  4 22:55 7 -> socket:[297495]

aha! file descriptor 7 is the unix socket 297495. Let's look what this is connected to:

 ss -p | grep 297495
 u_str  ESTAB      0      0      /run/user/0/pulse/native 297496                * 297495  users:(("pulseaudio",2289,28))
 u_str  ESTAB      0      0                    * 297495                * 297496  users:(("speaker-test",15286,7))

We see - the socket 297495 is connected to the socket 297496. What is written into 297495 will be readable from 297496 and the other way round. This couple of sockets connects the speaker-test process with the pulseaudio process. 2289 is pulseaudio's process id, and 15286 is the root process id of speaker-test. This system is using pulseaudio for sound which is an important information for troubleshooting sound. In my example I had been messing around with pulseaudio's configuration and I could fix the problem quickly once I understood I was using it.

strace start options

You can start a new process with strace or you can attach strace to an already running process. To start a new process just put strace in front of its command:

strace -s 99 -ff ls

To attach strace to an already running process, in this example firefox, find out the process' id:

ps -A | grep firefox
2728 pts/1    00:00:02 firefox

Then call strace with the id as parameter:

strace -s 99 -ff -p 2728

limitations

strace will show you all syscalls from a process, and that's it. This also mean that if your process hangs in an endless loop that does not do any syscall, strace will not show anything.

Examples

interprocess communication

Processes will typically communicate:

  • via network
  • via sockets
  • via pipes
  • via shared memory
  • by writing into files

via sockets

For example when using strace to troubleshoot sound you may see that speaker-test receives messages from file descriptor 7:

 strace -s 99 -ffp 32681
 [pid 32682] recvmsg(7, {msg_name(0)=NULL, msg_iov(1)=[{"L\0\0\0\2L\0\0\0}U\0\0\0\0\0\22\10\277U\0\0\0\0\0\0\0\0001TU b|\0\17(\347TU b|\0\0175\342r\0\0\0\0\0\20\0\0r\0\0\0\0\0\2\260\220R\0\0\0\0\0\0\0\0R\0\0\0\0\0\2\260\220", 83}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=2289, uid=0, gid=0}}, msg_flags=0}, 0) = 83

Now let's find out what file descriptor 7 of process 32681 is:

 ll /proc/32681/fd/7
 lrwx------ 1 root root 64 Apr  4 18:17 /proc/32681/fd/7 -> socket:[198064]

So it is unix socket 198064. Let's find out what process it is:

 # ss -p | grep 198064
 u_str  ESTAB      0      0                    * 198064                * 198065  users:(("speaker-test",32681,7))
 u_str  ESTAB      0      0      /run/user/0/pulse/native 198065                * 198064  users:(("pulseaudio",2289,28))

via pipes

Let's construct a situation where processes communicate via pipes. The following command will create two processes, cat writing random data to a pipe and grep reading it:

cat /dev/urandom | grep "To be or not to be, that is the question"

Let's find the process IDs:

 ps -A | grep -E "cat|grep"
  8654 pts/1    00:10:30 cat
  8655 pts/1    00:00:04 grep
 10949 pts/2    00:00:00 grep

Let's look at cat's file descriptors:

cd /proc/8654/fd
ll
total 0
lrwx------ 1 root root 64 Apr  6 11:40 0 -> /dev/pts/1
l-wx------ 1 root root 64 Apr  6 11:40 1 -> pipe:[70679]
lrwx------ 1 root root 64 Apr  6 11:39 2 -> /dev/pts/1
lr-x------ 1 root root 64 Apr  6 11:40 3 -> /dev/urandom

So cat is communicating with a pipe numbered 70679. Let's see if we can find the other process that is reading from it:

 lsof | grep 70679
 cat        8654            root    1w     FIFO        0,8      0t0      70679 pipe
 grep       8655            root    0r     FIFO        0,8      0t0      70679 pipe

Works. We can use the command lsof to find the processes involved into pipe communication.

Search for a syscall

With strace, you can search for a special syscall. For example,

strace -e open command

will show you all files that have been touched (opened) by command. This can be used e.g. to find out where configuration changes are stored.

Performance analysis

With strace, you can find out the biggest time-consuming syscalls during a program run:

 strace -c ls -R
 Entries  Repository  Root
 % time     seconds  usecs/call     calls    errors syscall
 ------ ----------- ----------- --------- --------- ----------------
  67.09    0.412153          14     29664           getdents64
  27.70    0.170168          11     14849        14 open
   4.24    0.026043           0    123740           write
   0.72    0.004443           0     14837           close
   0.20    0.001204           0     14836           fstat
   0.05    0.000285         285         1           execve
   0.00    0.000000           0        12           read
   0.00    0.000000           0         4         3 stat
   0.00    0.000000           0        33           mmap
   0.00    0.000000           0        18           mprotect
   0.00    0.000000           0         4           munmap
   0.00    0.000000           0        12           brk
   0.00    0.000000           0         2           rt_sigaction
   0.00    0.000000           0         1           rt_sigprocmask
   0.00    0.000000           0         2           ioctl
   0.00    0.000000           0         1         1 access
   0.00    0.000000           0         3           mremap
   0.00    0.000000           0         1           fcntl
   0.00    0.000000           0         1           getrlimit
   0.00    0.000000           0         1           statfs
   0.00    0.000000           0         1           arch_prctl
   0.00    0.000000           0         3         1 futex
   0.00    0.000000           0         1           set_tid_address
   0.00    0.000000           0         8           fadvise64
   0.00    0.000000           0         1           set_robust_list
 ------ ----------- ----------- --------- --------- ----------------
 100.00    0.614296                198036        19 total

Now you go

man 2 getdents64

to find out what that syscall is about.

See also