Difference between revisions of "Debugging notes"

From Noah.org
Jump to navigationJump to search
 
(3 intermediate revisions by the same user not shown)
Line 30: Line 30:
  
 
The '''ptrace(1)''' system call is used to attach a trace to a process. See the following article,  [[ptrace notes]], for information on using '''ptrace''' for debugging down to the CPU instruction level.
 
The '''ptrace(1)''' system call is used to attach a trace to a process. See the following article,  [[ptrace notes]], for information on using '''ptrace''' for debugging down to the CPU instruction level.
 +
 +
== Debugging with `perf trace` ==
 +
 +
'''perf trace''' is similar to '''strace''' but it is newer and uses a different subsystem in the kernel to gather its trace information. You may need to install the '''linux-tools''' package in Ubuntu.
 +
 +
<pre>
 +
perf trace echo "hello world"
 +
</pre>
  
 
== Debugging with `strace` ==
 
== Debugging with `strace` ==
  
For these examples, I usually open two xterm windows for experimentation. In one shell I use `strace` to attach to the PID of the other shell. You can get the PID of a shell by running `echo $$` in the shell you want to watch.  
+
See also '''perf trace'''.
 +
 
 +
For these examples, I used two terminal shells windows. In one shell I use '''strace''' to attach to the PID of the other shell.
 +
You can get the PID of a shell by running '''echo $$''' in the shell you want to trace
 +
 
 +
The first thing you may notice is that '''strace''' truncates strings and argument lists to function calls. The truncation of function call arguments is the most annoying, but it can be disabled (of ren. Beware, adding these arguments greatly increases the size of the trace output. The two following arguments work for most all argument lists I've wanted to see,
 +
<pre>
 +
strace -s 1024 -v
 +
# For example:
 +
strace -s 1024 -v -e trace=lstat,stat mountpoint /mnt
 +
<pre>
 +
 
 +
Keep track of children by following them as they are created. The '-f' option tells `strace` to follow children that are forked and exec'ed. Note that this is a '''best effort''' and that strace can miss a few system calls by the child while it starts up. This can be significant in the real world.
  
 
This will show all file related activity by the process, $PID. Note that '''-e trace=file''' is synonymous with '''-e file'''. The man page for `strace` explains the expression syntax for the '''-e''' option.
 
This will show all file related activity by the process, $PID. Note that '''-e trace=file''' is synonymous with '''-e file'''. The man page for `strace` explains the expression syntax for the '''-e''' option.
 +
<pre>
 +
strace -p $PID -f -e trace=file
 +
</pre>
  
 +
The following will show network activity by the process, $PID:
 
<pre>
 
<pre>
strace -p $PID -f -e trace=file
+
strace -p $PID -f -e trace=network
 
</pre>
 
</pre>
  
 
You can use the '''-c''' option to get a count of each system call made by the process. The count is made after filtering by the '''-e''' expression. The count is printed when `strace` exits. The following will show a count of each file related system call.
 
You can use the '''-c''' option to get a count of each system call made by the process. The count is made after filtering by the '''-e''' expression. The count is printed when `strace` exits. The following will show a count of each file related system call.
 
 
<pre>
 
<pre>
 
strace -p $PID -c -f -e trace=file
 
strace -p $PID -c -f -e trace=file
 
</pre>
 
</pre>
  
This will show a count of ''all'' system calls.
+
This will show a count of all system calls.
 
 
 
<pre>
 
<pre>
 
strace -p $PID -c -f
 
strace -p $PID -c -f
 
</pre>
 
</pre>
  
This will show what data is ''written'' by the process, $PID.
+
This will show what data is written by the process, $PID.
 
 
 
<pre>
 
<pre>
 
strace -p $PID -f -e write
 
strace -p $PID -f -e write
 
</pre>
 
</pre>
 
The '-f' option tells `strace` to follow children that are forked and execed. Note that this is a '''best effort''' and that strace can miss a few system calls of the child while it starts up. This can be significant in the real world.
 
  
 
The following will trace data that is read and written by the process, $PID:
 
The following will trace data that is read and written by the process, $PID:
 
 
<pre>
 
<pre>
 
strace -f -e write,read -p $PID
 
strace -f -e write,read -p $PID
 
</pre>
 
</pre>
  
The following will trace data that is written by the process, $PID. This is useful for tracing stdout of shells and the like. I don't know why I need both '''-e''' options. I think I should need only '''-e write=2''', but if I do that then I see every other system call. Nor can I do '''-e write,write=2'''. This syntax gives me a headache... At any rate, this mostly does what I want, but not quite -- it does not actually print re response back from the shell in the hex dump:
+
The following will trace data that is written by the process, $PID. This is useful for tracing stdout of shells and the like. I don't know why I need both '''-e''' options. I think I should need only '''-e write=2''', but if I do that then I see every other system call. Nor can I do '''-e write,write=2'''. This syntax gives me a headache... At any rate, this mostly does what I want, but not quite -- it does not actually print theresponse back from the shell:
 
 
 
<pre>
 
<pre>
 
strace -f -s 1024 -e write -e write=2 -p $PID
 
strace -f -s 1024 -e write -e write=2 -p $PID
Line 74: Line 91:
  
 
This will show files created by a process. Note that files can be created and opened for writing using 'creat' as well as 'open'. Here I filter a lot of the open calls. The "-o /proc/self/fd/1" forces output to stdout.
 
This will show files created by a process. Note that files can be created and opened for writing using 'creat' as well as 'open'. Here I filter a lot of the open calls. The "-o /proc/self/fd/1" forces output to stdout.
 
 
<pre>
 
<pre>
 
strace -o /proc/self/fd/1 -p $PID -f -e creat,open | grep -v O_RDONLY
 
strace -o /proc/self/fd/1 -p $PID -f -e creat,open | grep -v O_RDONLY
Line 80: Line 96:
  
 
In theory, you could also force output to stdout with '-o \|cat', but piping through cat seems to take more time, so `strace` misses more child calls when it tried to follow them. It is also '''slower''' to use `strace's` own built-in filter option '-e'. It is faster to pipe through grep for later filtering. For example, this will often miss 'open' calls to open files for writing:
 
In theory, you could also force output to stdout with '-o \|cat', but piping through cat seems to take more time, so `strace` misses more child calls when it tried to follow them. It is also '''slower''' to use `strace's` own built-in filter option '-e'. It is faster to pipe through grep for later filtering. For example, this will often miss 'open' calls to open files for writing:
 
 
<pre>
 
<pre>
 
strace -o \|cat -p $PID -f -e creat -e open | grep -v O_RDONLY
 
strace -o \|cat -p $PID -f -e creat -e open | grep -v O_RDONLY
Line 86: Line 101:
  
 
But will work a little better:
 
But will work a little better:
 
 
<pre>
 
<pre>
 
strace -o \|cat -p $PID -f | grep -v O_RDONLY | grep open
 
strace -o \|cat -p $PID -f | grep -v O_RDONLY | grep open
 
</pre>
 
</pre>
  
You might miss a file open or creat when using redirects from the parent shell. If you use this in a command-line pipe stream that the process you trace has the file opened for it already as file descriptor 1. This should be no surprise...
+
You might miss a file open or create when using redirects from the parent shell. If you use this in a command-line pipe stream that the process you trace has the file opened for it already as file descriptor 1. This should be no surprise...
 
 
 
<pre>
 
<pre>
 
strace -f -e write echo foo > foo.txt
 
strace -f -e write echo foo > foo.txt
 
</pre>
 
</pre>

Latest revision as of 23:47, 9 March 2015


Summary of memory used by a program

This will give the max memory used by a program while it was running. It is unclear if this includes child processes and shared libraries. I use `command` here to start `time` because `time` is a Bash built-in as well as an external command. In this case I want the command, not the built-in. UPDATE WARNING: The `command` tool does not seem to work as I had expected in Bash. There is an alternative that seems to work and that is to put a \ back-slash in from the command you want to be loaded as a program instead of a shell built-in.

This shows the resident set size.

command time --format "%MK" [COMMAND]
# OR
\time --format "%MK" [COMMAND]

The following is a more concrete example. This compares the effect of using read modifiers in ImageMagic conversion.

# With read modifier:
command time --format "%MK" find ~/Pictures -type f -exec convert {}'[480x272]' -format jpg -quality 80 -resize '480x272>' -gravity center -extent 480x272 -background white -flatten {}.preview.jpg \;
# Without read modifier:
command time --format "%MK" find ~/Pictures -type f -exec convert {} -format jpg -quality 80 -resize '480x272>' -gravity center -extent 480x272 -background white -flatten {}.preview.jpg \;

Debugging with LD_PRELOAD hooks

See http://michael.toren.net/slides/lkm-alternatives/slide006.html

See also LD_PRELOAD_notes.

Debugging with ptrace(1)

The ptrace(1) system call is used to attach a trace to a process. See the following article, ptrace notes, for information on using ptrace for debugging down to the CPU instruction level.

Debugging with `perf trace`

perf trace is similar to strace but it is newer and uses a different subsystem in the kernel to gather its trace information. You may need to install the linux-tools package in Ubuntu.

perf trace echo "hello world"

Debugging with `strace`

See also perf trace.

For these examples, I used two terminal shells windows. In one shell I use strace to attach to the PID of the other shell. You can get the PID of a shell by running echo $$ in the shell you want to trace

The first thing you may notice is that strace truncates strings and argument lists to function calls. The truncation of function call arguments is the most annoying, but it can be disabled (of ren. Beware, adding these arguments greatly increases the size of the trace output. The two following arguments work for most all argument lists I've wanted to see,

strace -s 1024 -v
# For example:
strace -s 1024 -v -e trace=lstat,stat mountpoint /mnt
<pre>

Keep track of children by following them as they are created. The '-f' option tells `strace` to follow children that are forked and exec'ed. Note that this is a '''best effort''' and that strace can miss a few system calls by the child while it starts up. This can be significant in the real world.

This will show all file related activity by the process, $PID. Note that '''-e trace=file''' is synonymous with '''-e file'''. The man page for `strace` explains the expression syntax for the '''-e''' option.
<pre>
strace -p $PID -f -e trace=file

The following will show network activity by the process, $PID:

strace -p $PID -f -e trace=network

You can use the -c option to get a count of each system call made by the process. The count is made after filtering by the -e expression. The count is printed when `strace` exits. The following will show a count of each file related system call.

strace -p $PID -c -f -e trace=file

This will show a count of all system calls.

strace -p $PID -c -f

This will show what data is written by the process, $PID.

strace -p $PID -f -e write

The following will trace data that is read and written by the process, $PID:

strace -f -e write,read -p $PID

The following will trace data that is written by the process, $PID. This is useful for tracing stdout of shells and the like. I don't know why I need both -e options. I think I should need only -e write=2, but if I do that then I see every other system call. Nor can I do -e write,write=2. This syntax gives me a headache... At any rate, this mostly does what I want, but not quite -- it does not actually print theresponse back from the shell:

strace -f -s 1024 -e write -e write=2 -p $PID

This will show files created by a process. Note that files can be created and opened for writing using 'creat' as well as 'open'. Here I filter a lot of the open calls. The "-o /proc/self/fd/1" forces output to stdout.

strace -o /proc/self/fd/1 -p $PID -f -e creat,open | grep -v O_RDONLY

In theory, you could also force output to stdout with '-o \|cat', but piping through cat seems to take more time, so `strace` misses more child calls when it tried to follow them. It is also slower to use `strace's` own built-in filter option '-e'. It is faster to pipe through grep for later filtering. For example, this will often miss 'open' calls to open files for writing:

strace -o \|cat -p $PID -f -e creat -e open | grep -v O_RDONLY

But will work a little better:

strace -o \|cat -p $PID -f | grep -v O_RDONLY | grep open

You might miss a file open or create when using redirects from the parent shell. If you use this in a command-line pipe stream that the process you trace has the file opened for it already as file descriptor 1. This should be no surprise...

strace -f -e write echo foo > foo.txt