Why does printf() in the parent almost always win the race condition after fork()?

Question

There is a somewhat famous Unix brain-teaser: Write an if expression to make the following program print Hello, world! on the screen. The expr in if must be a legal C expression and should not contain other program structures.

if (expr)
    printf("Hello, ");
else
    printf("world!\n");

The answer is fork().

When I was younger, I just had a laugh and forgot about it. But rethinking it, I find I couldn't understand why this program is surprisingly reliable than it should be. The order of execution after fork() is not guaranteed and a race condition exists, but in practice, you almost always see Hello, world!\n, never world!\nHello,.

To demonstrate it, I ran the program for 100,000 rounds.

for i in {0..100000}; do
    ./fork >> log
done

On Linux 5.9 (Fedora 32, gcc 10.2.1, -O2), after 100001 executions, the child only won 146 times, the parent has a winning probability of 99.9985%.

$ uname -a
Linux openwork 5.9.14-1.qubes.x86_64 #1 SMP Tue Dec 15 17:29:47 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

$ wc -l log
100001 log

$ grep ^world log | wc -l
146

The result is similar on FreeBSD 12.2 (clang 10.0.1, -O2). The child only won 68 times, or 0.00067% of the time, meanwhile the parent won 99.993% of all executions.

An interesting side-note is that ktrace ./fork instantly changes the dominant result to world\nHello, (because only the parent is traced), demonstrating the Heisenbug nature of the problem. Nevertheless, tracing both processes via ktrace -i ./fork reverts the behavior back, because both processes are traced and equally slow.

$ uname -a
FreeBSD freebsd 12.2-RELEASE-p1 FreeBSD 12.2-RELEASE-p1 GENERIC  amd64

$ wc -l log 
100001 log

$ grep ^world log | wc -l
68

Independence from Buffering?

An answer suggests that buffering can influence the behavior of this race condition. But the behavior still presents after removing \n from printf().

if (expr)
    printf("Hello");
else
    printf("World");

And turning off stdout's buffering via stdbuf on FreeBSD.

for i in {0..10000}; do
    stdbuf -i0 -o0 -e0 ./fork >> log
    echo > log
done

$ wc -l log 
10001 log

$ grep -v "^HelloWorld" log | wc -l
30

Why does printf() in the parent almost always win the race condition after fork() in practice? Is it related to the internal implementation details of printf() in the C standard library? The write() system call? Or process scheduling in the Unix kernels?

Answer 1

When you execute printf(3) to output a string to the terminal (to any tty device, this is checked inside the stdio package, by means of a isatty(3) call), the stdio package works in line mode buffering, which means that the internal buffer that accumulates output before writing it to the terminal flushes the buffer:

• if the buffer fills up completely (this is not going to happen, as the string is too short, while the buffer is typically a best performance size or around 16kb ---this is the value for ufs2 filesystems in BSD unix), or...
• if the output contains a \n line separator (this is only happening in the parent code, see below) the flush occurs at the position of the \n.

As your parent code (the one that received the pid_t process id of the child) is the one that executes the printf(3) with the included \n character, it's buffer is flushed at the time of the execution of the printf() call, while the buffer of the child will be flushed at the time of the exit(3) system call, as part of the atexit(3) processing. You can test this by calling _exit(2) (the exit(3) version that doesn't call the at-exit handlers) in both, the parent and the child, and you will see that only the parent output is seen on the screen.

There is, as you tell, a race condition, so in case the child is executed to its end, before the parent has had time to execute its printf(3) then you can get the parent's output at the end (just put a sleep(3) call in the parent code, before the printf(3), and you will see the correct order. The most important thing is that the first process that starts it's write(2) system call will be the winner (because the inode is locked during the execution of the write(2) syscal, and the output is sequenced). But the parent process only executes it's code without any system call in between, while the sequence for the child process is to store the string in the buffer and to flush it when the list of atexit(3) functions is called after returning from main(). This can involve several system calls in the mean time, that can even block the process for a while.

You can also put a \n in the child code and it is probable that you can see the child process being scheduled and starting the write() before the parent, although it is still probable that the parent will continue winning because it is very possible that it gets scheduled before the child is allowed to start (this is because the parent starting the fork(2) executes only the first part of it, e.g. checking for permissions to create a child and create the new process table entry that gives it the child's pid number needed to return from the fork, allowing the parent's fork(2) to return as soon as the child process id is known, while the allocation of memory segments to the new process and prepare it to execute is done in the child's fork() second half. This means that most probably the child will return from the fork() call when the parent is already running at top speed to the printf() call. But you cannot control this.

Answer 2

When fork is executed, the process executing it (the new parent) is executing (of course), and the newly created child is not. For the child to run, either the parent must be stopped and the child given the processor, or the child must be started on another processor, which takes time. Meanwhile, the parent continues execution.

Unless some unrelated event occurs, such as the parent exhausting the time slice it was given for sharing the processor, it wins the race.