Tracing Python with strace or truss

@brandon_rhodes

PyOhio 2014

What is a system call?

Hundreds of times a second,
your operating system turns over
control of the CPU to a process

Each process is sandboxed

Can read and write from memory
Must ask the OS for everything else

“Python, Linkers, and Virtual Memory”

— PyCon 2012

strace — Linux, thus Ubuntu

truss — BSD, thus Mac OS X

stderr is awesome

$ cat a.html b.html c.html | wc

cat: c.html: No such file or directory
   111     250    5787

       ┌───┐     ┌──┐
TTY → 0│cat│1 → 0│wc│1→ TTY
       └───┘     └──┘
         2         2
         ↓         ↓

        TTY       TTY

$ cat a.html b.html c.html 2>err | wc >out
$ cat err

cat: c.html: No such file or directory

$ cat out

   111     250    5787

       ┌───┐     ┌──┐
TTY → 0│cat│1 → 0│wc│1→ “./out”
       └───┘     └──┘
         2         2
         ↓         ↓

      “./err”     TTY

Why “2>”?

0< — stdin
1> — stdout
2> — stderr

where 1 is the

default for >

So we could:

$ ... | strace python script.py 2>trace.txt | ...

But this would interleave
the trace output with whatever
script.py itself prints to stderr

Instead we will:

$ ... | strace -o trace.txt python script.py | ...

to isolate trace output

in its own separate file

Let’s trace the simplest

possible command

/bin/true

Purpose:

Exit with status 0

process exit status

— success
— run-time error
— bad command line
≥3 — see bash(1) and wait(2)

$?

Status of most recent command

$ grep root /etc/passwd

root:x:0:0:root:/root:/bin/bash

$ echo $?

0

$ grep hamlet /etc/passwd
$ echo $?

1

if

$ if grep -q root /etc/passwd; \
  then echo found; else echo nope; fi

found

$ if grep -q hamlet /etc/passwd; \
  then echo found; else echo nope; fi

nope

Error status

Nonzero status fine in if / while
Otherwise shell script will exit
Use command || true to survive
Or set -e before command

/bin/true

Originally an empty file:

shell script → exit status 0

As AT&T commercialized UNIX,

John Chambers noticed something

/bin/true

#     Copyright (c) 1984 AT&T
#       All Rights Reserved

#     THIS IS UNPUBLISHED PROPRIETARY SOURCE CODE OF AT&T
#     The copyright notice above does not evidence any
#     actual or intended publication of such source code.

#ident        "@(#)cmd/true.sh        50.1"

/bin/true

Has AT&T copyrighted

their own copyright message?

#     Copyright (c) 1984 AT&T
#       All Rights Reserved

#     THIS IS UNPUBLISHED PROPRIETARY SOURCE CODE OF AT&T
#     The copyright notice above does not evidence any
#     actual or intended publication of such source code.

#ident        "@(#)cmd/true.sh        50.1"

#     Copyright (c) 1984 AT&T
#       All Rights Reserved

#     THIS IS UNPUBLISHED PROPRIETARY SOURCE CODE OF AT&T
#     The copyright notice above does not evidence any
#     actual or intended publication of such source code.

#ident        "@(#)cmd/true.sh        50.1"

Or are we violating AT&T copyright

every time we create an empty file?

On my Linux laptop:

$ file /bin/true

/bin/true: ELF 32-bit LSB executable...

$ strace -o trace.txt /bin/true

execve("/bin/true", ["true"], [/* 71 vars */]) = 0
brk(0)                                  = 0x8385000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb777d000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=95435, ...}) = 0
mmap2(NULL, 95435, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7765000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1758972, ...}) = 0
mmap2(NULL, 1763964, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb75b6000
mmap2(0xb775f000, 12288, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a9000) = 0xb775f000
mmap2(0xb7762000, 10876, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7762000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75b5000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb75b5940,
                 limit:1048575, seg_32bit:1, contents:0, read_exec_only:0,
                 limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb775f000, 8192, PROT_READ)   = 0
mprotect(0x804d000, 4096, PROT_READ)    = 0
mprotect(0xb77a0000, 4096, PROT_READ)   = 0
munmap(0xb7765000, 95435)               = 0
exit_group(0)                           = ?
+++ exited with 0 +++

System calls

0 often means success
-1 often means failure
errno global is set

Documentation:

man 2 write

execve("/bin/true", ["true"], [/* 71 vars */]) = 0

brk(0)                                  = 0x8385000

access("/etc/ld.so.nohwcap", F_OK)
  = -1 ENOENT (No such file or directory)

mmap2(NULL, 8192, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb777d000

access("/etc/ld.so.preload", R_OK)
  = -1 ENOENT (No such file or directory)

open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

fstat64(3, {..., st_size=95435, ...}) = 0

mmap2(NULL, 95435, PROT_READ, MAP_PRIVATE, 3, 0)
  = 0xb7765000

close(3) = 0

The life and death of

file descriptor number 3

“Perl Meets Cobol”

“I didn’t have to explain
filehandles; they already knew
about filehandles. But they used
jargon to talk about them that wasn’t
the jargon I was familiar with.

“Oh, you're establishing
addressibility on the file,”
someone said.

—They seemed pleased
at how easy it was … to establish
addressibility on a file.”

open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

lsof

Run lsof -p PID to see a process’s

file descriptors and memory maps

access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT

open("/lib/i386-linux-gnu/libc.so.6",
     O_RDONLY|O_CLOEXEC) = 3

read(3, "\177ELF\1\1\1\0\0\0\0\0"..., 512) = 512

fstat64(3, {..., st_size=1758972, ...}) = 0

mmap2(NULL, 1763964, PROT_READ|PROT_EXEC,
      MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb75b6000
mmap2(0xb775f000, 12288, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|..., 3, 0x1a9000) = 0xb775f000
mmap2(0xb7762000, 10876, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|..., -1, 0) = 0xb7762000

close(3) = 0

mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_ANONYMOUS, -1,
      0) = 0xb75b5000

set_thread_area({entry_number:-1 -> 6,
  base_addr:0xb75b5940, limit:1048575,
  seg_32bit:1, contents:0, read_exec_only:0,
  limit_in_pages:1, seg_not_present:0,
  useable:1}) = 0

mprotect(0xb775f000, 8192, PROT_READ)   = 0
mprotect(0x804d000, 4096, PROT_READ)    = 0
mprotect(0xb77a0000, 4096, PROT_READ)   = 0

munmap(0xb7765000, 95435)               = 0
exit_group(0)                           = ?
+++ exited with 0 +++

noise

execve("/bin/true", ["true"], [/* 71 vars */]) = 0
brk(0)                                  = 0x8385000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb777d000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=95435, ...}) = 0
mmap2(NULL, 95435, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7765000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1758972, ...}) = 0
mmap2(NULL, 1763964, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb75b6000
mmap2(0xb775f000, 12288, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a9000) = 0xb775f000
mmap2(0xb7762000, 10876, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7762000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75b5000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb75b5940,
                 limit:1048575, seg_32bit:1, contents:0, read_exec_only:0,
                 limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb775f000, 8192, PROT_READ)   = 0
mprotect(0x804d000, 4096, PROT_READ)    = 0
mprotect(0xb77a0000, 4096, PROT_READ)   = 0
munmap(0xb7765000, 95435)               = 0
exit_group(0)                           = ?
+++ exited with 0 +++

“It is a pity that so much tracing
clutter is produced by systems
employing shared libraries.”

— strace(2)

$ strace -o trace.txt python3.4 -c ''

↓

507 lines

execve("/usr/bin/python3.4",
       ["python3.4", "-c", ""], [/* 71 vars */])
brk(0)
access("/etc/ld.so.nohwcap", F_OK)
mmap2(NULL, 8192, …)
access("/etc/ld.so.preload", R_OK)
open("/etc/ld.so.cache", …) = 3
fstat64(3, {…, st_size=95435, …})
mmap2(NULL, 95435, …)
close(3)
                        ⋮

7 times:

                        ⋮
access("/etc/ld.so.nohwcap", F_OK)
open("/lib/i386-linux-gnu/libpthread.so.0", …)
read(3, "\177ELF\1\1\1\0"…, 512)
fstat64(3, {…, st_size=130518, …})
mmap2(NULL, 111276, …)
mmap2(0xb776e000, 8192, …)
mmap2(0xb7770000, 4780, …)
close(3)
                        ⋮

$ which python3.4
/usr/bin/python3.4

$ ldd /usr/bin/python3.4
        linux-gate.so.1 => ...
        libpthread.so.0 => ...
        libc.so.6 => ...
        libdl.so.2 => ...
        libutil.so.1 => ...
        libexpat.so.1 => ...
        libz.so.1 => ...
        libm.so.6 => ...
        /lib/ld-linux.so.2 (0xb77da000)

After further memory-map shenanigans:

open("/dev/urandom",
     O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fcntl64(3, F_GETFD) = 0x1 (flags FD_CLOEXEC)
read(3, "…", 24) = 24
close(3)

Then the Python runtime gets serious:

stat64("/home/brandon/bin/python3.4", …) = -1
stat64("/home/brandon/usr/bin/python3.4", …) = -1
stat64("/usr/local/sbin/python3.4", …) = -1
stat64("/usr/local/bin/python3.4", …) = -1
stat64("/usr/sbin/python3.4", …) = -1
stat64("/usr/bin/python3.4",
       {…, st_size=3802224, …}) = 0
readlink("/usr/bin/python3.4", …, 4096) = -1

the result is stored as sys.executable

Python checks for a few config files

open("/usr/bin/pyvenv.cfg", …) = -1 ENOENT
open("/usr/pyvenv.cfg", …) = -1 ENOENT
stat64("/usr/bin/Modules/Setup", …) = -1 ENOENT

The standard library is discovered

through a search for nearby lib directories

stat64("/usr/bin/lib/python3.4/os.py", …) = -1
stat64("/usr/bin/lib/python3.4/os.pyc", …) = -1
stat64("/usr/lib/python3.4/os.py",
       {…, st_size=33618, …}) = 0

(That is why virtualenv copies os.py)

Finally, import can start its work

stat64("/usr/lib/python3.4/encodings"
        "/__init__.cpython-34m-i386-linux-gnu.so",
       …) = -1
stat64(…"/__init__.cpython-34m.so", …) = -1
stat64(…"/__init__.abi3.so", …) = -1
stat64(…"/__init__.so", …) = -1
stat64(…"/__init__.py", …) = 0
stat64(…"/__init__.py", …) = 0
open(…"/__pycache__/__init__.cpython-34.pyc", …) = 3

How many filenames does Python try?

m directories × n extensions

System Python:

$ python3.4 -c 'import sys, pprint;\
                pprint.pprint(sys.path)'
['',
 '/usr/lib/python3.4',
 '/usr/lib/python3.4/plat-i386-linux-gnu',
 '/usr/lib/python3.4/lib-dynload',
 '/usr/local/lib/python3.4/dist-packages',
 '/usr/lib/python3/dist-packages']

Python in a virtualenv:

$ bin/python3.4 -c 'import sys,pprint;\
                    pprint.pprint(sys.path)'
['',
 '…venv/lib/python3.4',
 '…venv/lib/python3.4/plat-i386-linux-gnu',
 '…venv/lib/python3.4/lib-dynload',
 '/usr/lib/python3.4',
 '/usr/lib/python3.4/plat-i386-linux-gnu',
 '/home/brandon/p/lib/python3.4/site-packages',
 '/usr/lib/python3/dist-packages',
 '/usr/local/lib/python3.4/dist-packages']

After easy_install of some eggs:

$ easy_install zc.recipe.egg
⋮
$ bin/python3.4 -c 'import sys,pprint;\
                    pprint.pprint(sys.path)'
['',
 '…venv/…/site-packages/zc.recipe.egg-2.0.1-py3.4.egg',
 '…venv/…/site-packages/zc.buildout-2.2.1-py3.4.egg',
 '…venv/lib/python3.4',
 '…venv/lib/python3.4/plat-i386-linux-gnu',
 '…venv/lib/python3.4/lib-dynload',
 '/usr/lib/python3.4',
 '/usr/lib/python3.4/plat-i386-linux-gnu',
 '/home/brandon/v/lib/python3.4/site-packages',
 '/usr/lib/python3/dist-packages',
 '/usr/local/lib/python3.4/dist-packages']

The combination of Zope plus

easy_install was a perfect storm

$ grokenv/bin/easy_install grok

⋮

$ grokenv/bin/python2.7 -c \
  'import sys; print(len(sys.path))'

183

Longer sys.path generates more

system calls for each import

strace -c ...

Counts system calls

strace -e open,stat64 ...

Filter system calls

$ strace -c -e open,stat64 \
  /usr/bin/python2.7 -c 'import popen2'

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 70.11    0.000258           1       276       206 open
 29.89    0.000110           1       102        66 stat64
------ ----------- ----------- --------- --------- -------
100.00    0.000368                   378       272 total

$ strace -c -e open,stat64 \
  venv/bin/python2.7 -c 'import popen2'

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 72.73    0.000947           3       292       237 open
 27.27    0.000355           2       222       117 stat64
------ ----------- ----------- --------- --------- -------
100.00    0.001302                   514       354 total

$ strace -c -e open,stat64 \
  grokenv/bin/python2.7 -c 'import popen2'

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 72.42    0.013402           3      4290      4232 open
 27.58    0.005104           4      1417       879 stat64
------ ----------- ----------- --------- --------- -------
100.00    0.018506                  5707      5111 total

How long do those

5,707 system calls take?

$ time -p /usr/bin/python2.7 -c 'import popen2'

real 0.03
user 0.03
sys 0.00

$ time -p grokenv/bin/python2.7 -c 'import popen2'

real 0.13
user 0.05
sys 0.07

Note

That was from merely

having Grok installed

import popen2

What if we actually

imported Grok?

O(n²)

$ strace -c -e open,stat64 \
  grokenv/bin/python2.7 -c 'import grok'

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 79.56    0.163195           3     59704     58917 open
 20.44    0.041926           3     13773     11972 stat64
------ ----------- ----------- --------- --------- -------
100.00    0.205121                 73477     70889 total

Always use

pip and virtualenv

Two approaches

easy_install

Everything in system site-packages,

then mix-and-match with sys.path

…/site-packages/Django-1.3-py2.7.egg/django/…
…/site-packages/Django-1.5-py2.7.egg/django/…
…/site-packages/Django-1.6-py2.7.egg/django/…

virtualenv and pip

Separate environments, each with

a single django directly installed

…/venv/python2.7/site-packages/django/…

Always use

pip

Always use

virtualenv

Faster search

Python 3.3+ runs os.listdir()
on each entry in sys.path instead
of repeated stat64() and open()

$ strace -c -e open,stat64 \
  /usr/bin/python2.7 -c 'import email'

% time     seconds  usecs/call     calls    errors syscall
⋮
100.00    0.000000                   384       275 total

$ strace -c -e open,stat64 \
  /usr/bin/python3.4 -c 'import email'

% time     seconds  usecs/call     calls    errors syscall
⋮
100.00    0.000000                   148        24 total

Debugging

These stacks of stat() and

open() calls give great info

import example

Is the directory that contains

example.py getting searched?

No?

Check sys.path

import example

Is Python able to open file

example.py without error?

No?

Check file, directory permissions

import example

Is another file named example.*

getting found and loaded first?

Yes?

Something has shadowed the

module; it might need renaming,

or removal of an old *.pyc

Note that a Python import can

trigger dynamic library loading!

import ssl

ssl.py
↓
_ssl.so
↓
libssl.so.1.0.0
libcrypto.so.1.0.0

PEP 302

PEP 328

Once your application
is imported and running,
what calls will you see?

1 : 1

Many os and socket routines

map directly to system calls

import os
os.mkdir("d")

       ⋮
mkdir("d", 0777)
       ⋮

import socket
s = socket.socket()

                    ⋮
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
                    ⋮

import os
os.write(1, "hello\n")

           ⋮
write(1, "hello\n", 6) = 6
           ⋮

1 : many

Other Python operations

generate several calls

import os
os.listdir("/")

               ⋮
openat(AT_FDCWD, "/", ...) = 3
getdents64(3, /* 27 entries */, 32768)  = 720
getdents64(3, /* 0 entries */, 32768)   = 0
close(3)                                = 0
               ⋮

import socket
socket.getaddrinfo("google.com", "www")

open("/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 3
                       ⋮
             (20 more system calls)
                       ⋮
open("/etc/gai.conf", O_RDONLY|O_CLOEXEC)    = 3
                       ⋮
             (18 more system calls)
                       ⋮
socket(PF_INET, SOCK_DGRAM|…, IPPROTO_IP)    = 3
connect(3, {sa_family=AF_INET, sin_port=htons(53),
        sin_addr=inet_addr("127.0.1.1")}, 16) = 0
                       ⋮
             (35 more system calls)

Manual section 2 vs 3

$ man mkdir

Whoops! Section 1 is shell commands:

MKDIR(1)     User Commands    MKDIR(1)

NAME
       mkdir - make directories

SYNOPSIS
       mkdir [OPTION]... DIRECTORY...

DESCRIPTION
       Create  the  DIRECTORY(ies), if
       they do not already exist.

$ man -s 2,3 mkdir

or, if you already have a guess:

$ man 2 mkdir         # system call: simple
$ man 3 getaddrinfo   # libc function: compound

1 : nothing!

Sometimes an action
can seem to have no
immediate result!

import sys, time
print "Hello",
sys.stdout.write("world.")
time.sleep(100)

Process makes no

attempt to output!

Buffering

Not an OS feature,

but a behavior of:

(originally) FILE* objects in libc
(nowadays) Python io module

Buffering makes I/O more efficient

print
stdout.write()
stderr.write()
another_file.write()

compared to raw I/O

os.write()

print "a",
print "b",
print "c"

          ⋮
write(1, "a b c\n", 6)
          ⋮

Buffering

More efficient
Can delay output
Can be confusing

flushing

import sys
print "a",
sys.stdout.flush()
print "b"

       ⋮
write(1, "a", 1)
write(1, " b\n", 3)
       ⋮

turn off buffering

$ python -u ...

$ export PYTHONUNBUFFERED=True

or even

sys.stdout = os.fdopen(sys.stdout.fileno(), 'w', 0)

When does buffered output

flush() on its own?

After newline, when writing to terminal:

for i in range(10000):
    print 'Number',
    print i

          ⋮
write(1, "Number 0\n", 9)
write(1, "Number 1\n", 9)
write(1, "Number 2\n", 9)
          ⋮
write(1, "Number 9999\n", 12)
          ⋮

Every block, when writing to file:

for i in range(10000):
    print 'Number',
    print i

          ⋮
write(1, "Number 0\nNumber 1\nNumber 2\n"..., 4096)
write(1, "er 382\nNumber 383\nNumber 384"..., 4096)
write(1, "54\nNumber 755\nNumber 756\nNu"..., 4096)
          ⋮
write(1, "mber 9991\nNumber 9992\nNumber"..., 106)
          ⋮

How does Python tell?

import sys
sys.stdout.isatty()

import os
os.isatty(1)

ioctl(1,
      SNDCTL_TMR_TIMEBASE
      or SNDRV_TIMER_IOCTL_NEXT_DEVICE
      or TCGETS,
      {B38400 opost isig icanon echo...}) = 0

sys.exit() flushes buffers
os._exit() does not

Threads

Like a new process,
but lives in the same
memory sandbox

import threading
threading.Thread().start()

⋮
clone(child_stack=0xb70f6424,
      flags=CLONE_VM|CLONE_FS|CLONE_FILES
           |CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM
           |CLONE_SETTLS|CLONE_PARENT_SETTID
           |CLONE_CHILD_CLEARTID, ...) = 13496
⋮

Process

Run a different executable

inside a new memory sandbox

import os
os.spawnvp(os.P_WAIT, "ls", ["ls"])

⋮
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID
      |CLONE_CHILD_SETTID|SIGCHLD, ...) = 13703
⋮

And then what?

Use strace -f to follow each

child thread created by clone()

import os
os.spawnvp(os.P_WAIT, "ls", ["ls"])

⋮
13742 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID
            |CLONE_CHILD_SETTID|SIGCHLD, ...) = 13743
⋮
13743 execve("/bin/ls", ["ls"], [/* 70 vars */]) = 0
13743 brk(0)                             = 0x90b4000
13743 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT
⋮

import os
os.system("ls")

⋮
1915 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID
           |CLONE_CHILD_SETTID|SIGCHLD, ...) = 1916
1915 wait4(-1,  <unfinished ...>
1916 execve("/bin/ls", ["ls"], [/* 79 vars */]) = 0
1916 brk(0)                            = 0x90b4000
1916 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT
⋮
1916  +++ exited with 0 +++
1915  <... waitpid resumed>
      [{WIFEXITED(s)… == 0}], 0, NULL) = 1916
⋮

subprocess operations are

even more complicated

call()
check_call()
check_output()
Popen()

Advice

Always compare your trace

to a working example

Common debugging

Running out of memory

malloc used brk() in the old days
Python calls mmap2(…,fd=-1,…) today
ENOMEM (Cannot allocate memory)

Running out of file descriptors

FD’s for open files
Also used for sockets
Watch for monotonic increase
ulimit -n to check bound
Check for reference loops
Use with or close()

More options

strace -p PID against running process
-P for calls targeting a specific path
-T elapsed time of each system call
-t timestamp each system call
-s can print larger string excerpts
-e can turn on other extended data
Take a look at the sysdig project

ltrace

Even slower:

traces library calls

Useful for SSL, when

strace can only show:

                      ⋮
write(3, "\27\3\3\0`\342\243\357\314\ndk"..., 101)
read(3, "\27\3\3\4\343", 5)
read(3, "\0\0\0\0\0\0\0\1\262/\264\254\0"..., 1251)
                      ⋮

ssl_test.py

import urllib
urllib.urlopen('https://www.google.com/').read()

ltrace.conf

int SSL_write(void, string, uint)

$ ltrace -F ltrace.conf -s 9999 \
    -l 'libssl*' -o ltrace.txt \
    python2.7 -c ssl_test.py

_ssl.i386-linux-gnu.so->SSL_write(
  "GET / HTTP/1.0\r\nHost: www.google.com\r\n"
  "User-Agent: Python-urllib/1.17\r\n\r\n",
  72) = 72

strace

ltrace

truss

@brandon_rhodes