Buffering `printf` outputs between different threads in Linux

Question

Here is my code:

#include <stdlib.h>
#include <unistd.h>
#include <stdio.h>
#include <pthread.h>

pthread_t ntid;void
printids(const char *s) {
  printf("%s \n", s);
}

void *
thr_fn(void *arg)   {
  printids("new thread: ");
  return((void *)0);
}

int
main(void)  {
  pthread_create(&ntid, NULL, thr_fn, NULL);
  printids("main thread:");
}

I'm running it on Red Hat Enterprise Linux Workstation release 6.5 .
Here is my compiling command

gcc -ansi -g -std=c99 -Wall -DLINUX -D_GNU_SOURCE threadid.c -o threadid -pthread -lrt -lbsd

Here is the output:

main thread:
new thread:
new thread:

Why "new thread" has been printed twice? I doubt this may related to buffering mechanism in Linux. But after I added fflush(stdout) and fsync(1) in the end of each function. The output is almost the same.

If you run the program several times. The output differs:

main thread:
new thread:

or

main thread:
new thread:
new thread:

Or

main thread:

Answer 1

Most libc libraries do buffer the output as you mentioned. And at the end of the program (when the main thread exits), they flush all the buffers and exit.

There is a slight possibility that your new thread has flushed the output but before it could update the state of the buffer, the main program exited and the cleanup code flushed the same buffer again. Since these buffers are local to the thread I am sure they won't have concurrency mechanism. But because of this rare case it might get messed up.

You can try

err = pthread_create(&ntid, NULL, thr_fn, NULL);
printids("main thread:");
pthread_join(ntid, NULL);

At the end of the main function and check if the problem is solved.

This will cause your main function to wait till the new thread is finished (including the flushing operation it does).

Answer 2

Double output is possible on glibc-based linux systems due to a nasty bug in glibc: if the FILE lock is already held at the time exit tries to flush, the lock is simply ignored and the buffer access is performed with no synchronization. This would be a great test case to report to glibc to pressure them to fix it, if you can reproduce it reliably.