Watching System Calls Happen

Get access to whole semester resourcesSemester Pass

Chapter Ten

Syllabus topic Module 1, "Fundamentals of Operating systems - System Calls"

Pages 39 to 42 of 452

In one line

strace asks the kernel to report every system call a program makes, with its arguments and its answer, in order.

Why this is worth a chapter

Everything in this paper is invisible. You cannot see a process being scheduled, a page being replaced or a lock being taken. The system call interface is the one place where the whole of the operating system's work becomes a list of lines you can read.

It is also the best debugging tool a student will meet. A program that reports it cannot find a file becomes a trace showing the exact name it asked for and the exact answer it got.

How it works, in one paragraph

The kernel offers a facility by which one process may watch another: it stops the watched process at every entry to and exit from a system call and lets the watcher inspect it. strace uses that facility. The consequence worth knowing is that a program under strace runs far more slowly, because every call now stops it twice, so timings taken under it mean nothing.

The whole life of the simplest program

/bin/true returns success and does nothing else. Here is everything it asks the kernel for.

$ strace -o t.txt /bin/true
$ wc -l < t.txt
29
$ head -4 t.txt | sed 's/0x[0-9a-f]*/ADDRESS/g'
execve("/bin/true", ["/bin/true"], ADDRESS /* 14 vars */) = 0
brk(NULL)                               = ADDRESS
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = ADDRESS
faccessat(AT_FDCWD, "/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
$ grep -c mmap t.txt
6
$ tail -2 t.txt
exit_group(0)                           = ?
+++ exited with 0 +++

Read it as a story. The program was started with execve. A cache of library locations was looked for and opened. The C library was found, opened and mapped into memory six times over, once for each part of it that needs different permissions. Then the program exited.

Twenty nine lines and twenty seven calls: the last two lines are the exit and the note that the program finished, so they are not calls. Not one of those calls is the program's own work. It is the cost of being a program at all.

Two lines in that list are worth naming because they come back later in the book.

execve is the system call of Chapter twenty, the one that replaces a process's program.
mmap is the call of Chapter eighty, the one that maps something into a process's address

space. The C library arrives in memory by being mapped, not by being read.

A program that actually does something

Now a program that reads a file, so that the interesting calls are not buried.

#include <fcntl.h>
#include <unistd.h>
#include <stdio.h>

int main(void)
{
    char buf[32];
    int fd = open("greeting.txt", O_RDONLY);

    if (fd < 0) {
        perror("open");
        return 1;
    }
    ssize_t n = read(fd, buf, sizeof buf);
    write(STDOUT_FILENO, buf, (size_t)n);
    close(fd);
    return 0;
}

Watching System Calls Happen

hello from a file

$ gcc -std=c17 -Wall -Wextra -o readone readone.c
$ strace -e trace=openat,read,write,close -o r.txt ./readone
hello from a file
$ tail -5 r.txt
openat(AT_FDCWD, "greeting.txt", O_RDONLY) = 3
read(3, "hello from a file\n", 32)      = 18
write(1, "hello from a file\n", 18)     = 18
close(3)                                = 0
+++ exited with 0 +++

Those are the last five lines: the ones above them are the C library being loaded, exactly as in the trace before. Four calls are the program's own, and every one of them is readable.

openat returned 3. That is the file descriptor, a small integer the kernel gives the

program to refer to the open file. Descriptors 0, 1 and 2 are already taken: standard input, standard output and standard error. So the first file a program opens is almost always 3.

read(3, ..., 32) asked for up to 32 bytes and got 18.

The return value is what was actually read, and a program that assumes it got everything it asked for is a broken program.

write(1, ..., 18) wrote to descriptor 1, standard output, which is why the text appeared on

the screen.

close(3) gave the descriptor back.

open appears in the trace as openat. The library calls the newer system call, which takes a directory to be relative to, and AT_FDCWD means the current directory. This is a real and common surprise: the name in your program need not be the name of the system call underneath.

Counting, rather than listing

For a large program the list is too long to read. Counting is more useful.

$ strace -c -o c.txt ./readone
hello from a file
$ awk 'NR<3 || $NF ~ /^(openat|read|close|mmap)$/ {print $(NF-1), $NF}' c.txt | sort
--------- ----------------
2 read
3 close
3 openat
6 mmap
errors syscall

The columns are the share of time, the total time, the average per call, the number of calls, the number that returned an error, and the name. The errors column is the one to look at first when a program misbehaves, because a call that failed and was ignored is the commonest cause of mysterious behaviour.

Worked example: why did it not find the file?

This is the use a student will get most value from. A program is given a name that does not exist.

$ rm -f greeting.txt
$ strace -e trace=openat -o miss.txt ./readone
open: No such file or directory
$ grep greeting miss.txt
openat(AT_FDCWD, "greeting.txt", O_RDONLY) = -1 ENOENT (No such file or directory)

Watching System Calls Happen

The answer is -1 and the reason is ENOENT. A system call reports failure by returning -1 and setting an error number, and perror is the library function that turns that number into the sentence the program printed. Every system call in this book follows that rule, and Chapter twenty one shows the one famous exception, fork, which has three possible answers rather than two.

Distinctions that carry marks

	`strace`	A debugger
Shows	the boundary between program and kernel	the inside of the program
Needs the source?	no	usually
Slows the program	greatly	greatly
Answers	what did it ask the system for	what is it doing and why

	Return value of a system call	Error number
On success	the useful answer: a descriptor, a count	not set meaningfully
On failure	-1	says which failure
Read with	the value itself	`errno`, printed by `perror`

What it does not mean

A trace is not the program's source code. It shows only what crossed the boundary. Everything the program computed between two calls is invisible here, and that is the point.

Timings under strace are not real timings. Every call stops the program twice.

Not every function in your program appears. strlen, malloc and most of printf are library code and make no system call at all, so they leave no trace.

Quick revision

strace lists every system call a program makes, with arguments and return value. -e trace=

selects calls, -o writes to a file, -c counts instead of listing.

A program under strace is much slower, so timings taken under it are worthless.
The first file a program opens usually gets descriptor 3: 0, 1 and 2 are standard input,

output and error.

read returns how much it actually read, which may be less than was asked for.
open in a program appears as openat in the trace, with AT_FDCWD for the current

directory.

A system call reports failure as -1 plus an error number, such as ENOENT. perror prints

it.

Even /bin/true makes about twenty seven calls: that is the cost of starting any program.

Test yourself

What does strace show, and what does it not show? Every system call a program makes,

with arguments and results. It shows nothing that happens inside the program between calls.

Why is descriptor 3 the first one a program usually gets? Because 0, 1 and 2 are already

open as standard input, standard output and standard error, and the kernel gives out the lowest free number.

read(3, buf, 32) returns 18. What happened, and what must the program do? Eighteen bytes

were available and were read. The program must use the return value rather than assume it got 32, and must call read again if it needs more.

Watching System Calls Happen

A program says it cannot find a file. How would you find out which name it looked for?

Trace it and look at the openat line: the trace shows the exact string and the error, for example -1 ENOENT.

How does a system call report failure? It returns -1 and sets an error number, which

perror or strerror turns into a message.

Why does strlen never appear in a trace? It is library code that computes in user mode

and makes no request of the kernel.

The rest of this subject

These notes are cut from the University's printed syllabus. Open the syllabus itself, or the past papers, for the same subject.

Issue