Playing around with strace

Posted on 17 February 2016 by Paolo Bernardi

From the strace manpage: “strace is a useful diagnostic, instructional, and debugging tool”.

Thanks to strace it’s possible to check what a program is doing by looking at the system calls that it makes. As a simple example, let’s compare what happens when running two “Hello, world!”, respectively with PHP and with Python.

The source codes of the two programs are the following:

ciao.py:

print "Ciao"

ciao.php:

<?php
echo "Ciao\n";

Let’s run them via strace:

$ strace -o py.txt python ciao.py

$ strace -o php.txt php ciao.php

Both programs will write “Ciao” in the console and terminate. As a side effect, strace will record every syscall made by both programs in the respective output files. Let’s peek at the strace logs to compare what happens when running the two toy scripts.

Everything begins from an execve call, that starts the interpreter:

execve("/usr/bin/php", ["php", "ciao.php"], [/* 59 vars */]) = 0

execve("/usr/bin/python", ["python", "ciao.py"], [/* 59 vars */]) = 0

Right after, the flow goes ahead by loading the shared libraries required by each interpreter. For example, php loads a shared library like this:

open("/lib/x86_64-linux-gnu/libz.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\35\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=104824, ...}) = 0
mmap(NULL, 2199880, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9c4e3db000
mprotect(0x7f9c4e3f4000, 2093056, PROT_NONE) = 0
mmap(0x7f9c4e5f3000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18000) = 0x7f9c4e5f3000

As you can see, the shared library file’s content (in ELF format, can you see the header?) the is read and loaded in memory.

Python does more or less the same:

open("/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0>>\0\1\0\0\0\340`\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=142080, ...}) = 0
mmap(NULL, 2217232, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f8a44489000
mprotect(0x7f8a444a1000, 2097152, PROT_NONE) = 0
mmap(0x7f8a446a1000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18000) = 0x7f8a446a1000
mmap(0x7f8a446a3000, 13584, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f8a446a3000

Most of the syscalls are about loading the shared libraries. Both PHP and Python load the shared libraries linked to their executables. After that, other shared libraries are loaded:

  1. For PHP, the PHP extensions configured in the php.ini are loaded, and for each extensions, the shared libraries that it depends upon.
  2. Python scans the PYTHONPATH and loads some shared libraries located in there.

After the shared libraries galore, the script file to be run is loaded in memory:

open("ciao.php", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0664, st_size=21, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9c4e815000
read(4, "<!--?php\necho \"Ciao\\n\";\n", 4096) = 21-->

open("ciao.py", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=13, ...}) = 0
Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR) = 0
fstat(3, {st_mode=S_IFREG|0664, st_size=13, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8a448c7000
read(3, "print \"Ciao\"\n", 4096)

As you can see, apparently both PHP and Python read their scripts by chunks of 4k each.

The interpreter can now execute the program text. Both PHP and Python ultimately, after approximately 1000 syscalls, end up doing exactly the same write operation:

write(1, "Ciao\n", 5)

This can be read as: write to the standard output (file descriptor no. 1) the string “Ciao\n” (the “\n” is explicit in the PHP echo and implicit in python’s print), which is 5 characters long.

And that’s it!

strace’s output can be quite dense (there are a lot of options to filter it – or to make it denser), but it’s incredibly useful to quickly see what happens when running a program (it can also be used to inspect already running programs, just by specifying the desired process-id). It’s surely worth to have it in your toolbelt. 🙂

Get in touch

Thank you for contacting me, I will be in touch with you as soon as possible.
There was an error while trying to send the comment, please try again later.