Synchronization

Problem

A POSIX example:

Output (program is called sem) The numbers in parentheses in the second column are the number of threads in the critical section.

sem 4 1sem 8 3sem 12 4sem 12 8
ThreadId 0: acquired semaphore
ThreadId 0: working...
ThreadId 0: released semaphore
ThreadId 1: acquired semaphore
ThreadId 1: working...
ThreadId 1: released semaphore
ThreadId 2: acquired semaphore
ThreadId 2: working...
ThreadId 2: released semaphore
ThreadId 3: acquired semaphore
ThreadId 3: working...
ThreadId 3: released semaphore
ThreadId 0: acquired semaphore (1)
ThreadId 0: working...
ThreadId 2: acquired semaphore (2)
ThreadId 2: working...
ThreadId 1: acquired semaphore (3)
ThreadId 1: working...
ThreadId 0: released semaphore (2)
ThreadId 3: acquired semaphore (3)
ThreadId 3: working...
ThreadId 4: acquired semaphore (4)
ThreadId 4: working...
ThreadId 1: released semaphore (3)
ThreadId 2: released semaphore (2)
ThreadId 5: acquired semaphore (3)
ThreadId 5: working...
ThreadId 3: released semaphore (2)
ThreadId 6: acquired semaphore (3)
ThreadId 6: working...
ThreadId 7: acquired semaphore (4)
ThreadId 7: working...
ThreadId 5: released semaphore (3)
ThreadId 4: released semaphore (2)
ThreadId 6: released semaphore (1)
ThreadId 7: released semaphore (0)
ThreadId 1: acquired semaphore
ThreadId 1: working...
ThreadId 3: acquired semaphore
ThreadId 2: acquired semaphore
ThreadId 2: working...
ThreadId 3: working...
ThreadId 0: acquired semaphore
ThreadId 0: working...
ThreadId 1: released semaphore
ThreadId 2: released semaphore
ThreadId 5: acquired semaphore
ThreadId 5: working...
ThreadId 4: acquired semaphore
ThreadId 4: working...
ThreadId 3: released semaphore
ThreadId 6: acquired semaphore
ThreadId 6: working...
ThreadId 0: released semaphore
ThreadId 7: acquired semaphore
ThreadId 7: working...
ThreadId 6: released semaphore
ThreadId 8: acquired semaphore
ThreadId 8: working...
ThreadId 5: released semaphore
ThreadId 9: acquired semaphore
ThreadId 9: working...
ThreadId 4: released semaphore
ThreadId 10: acquired semaphore
ThreadId 10: working...
ThreadId 7: released semaphore
ThreadId 11: acquired semaphore
ThreadId 11: working...
ThreadId 8: released semaphore
ThreadId 9: released semaphore
ThreadId 10: released semaphore
ThreadId 11: released semaphore
ThreadId 0: acquired semaphore
ThreadId 0: working...
ThreadId 2: acquired semaphore
ThreadId 2: working...
ThreadId 3: acquired semaphore
ThreadId 5: acquired semaphore
ThreadId 5: working...
ThreadId 4: acquired semaphore
ThreadId 4: working...
ThreadId 3: working...
ThreadId 7: acquired semaphore
ThreadId 7: working...
ThreadId 6: acquired semaphore
ThreadId 1: acquired semaphore
ThreadId 1: working...
ThreadId 6: working...
ThreadId 0: released semaphore
ThreadId 3: released semaphore
ThreadId 5: released semaphore
ThreadId 4: released semaphore
ThreadId 7: released semaphore
ThreadId 8: acquired semaphore
ThreadId 8: working...
ThreadId 11: acquired semaphore
ThreadId 11: working...
ThreadId 2: released semaphore
ThreadId 10: acquired semaphore
ThreadId 10: working...
ThreadId 6: released semaphore
ThreadId 9: acquired semaphore
ThreadId 9: working...
ThreadId 1: released semaphore
ThreadId 8: released semaphore
ThreadId 11: released semaphore
ThreadId 10: released semaphore
ThreadId 9: released semaphore
The problem is in the thread function. The 3rd printf statement is not in the critical section:
/* sem.c                                             */
void *ThreadFn(void *p)
{
  struct ThreadParams *params = (struct ThreadParams *)p;
  sem_t *semaphore = params->semaphore;
  int tid = params->tid;
  
    /* Acquire semaphore */
  sem_wait(semaphore); 
  printf("ThreadId %i: acquired semaphore\n", tid);

    /* Pretend to do some work */
  printf("ThreadId %i: working...\n", tid);
  sleep(1);
  
    /* Release semaphore */
  sem_post(semaphore); 
  printf("ThreadId %i: released semaphore\n", tid);    This is not protected!
  
  return 0;
}
The simple and obvious solution is to just put the print statement in the critical section:
/* sem.c                                             */
void *ThreadFn(void *p)
{
  struct ThreadParams *params = (struct ThreadParams *)p;
  sem_t *semaphore = params->semaphore;
  int tid = params->tid;
    
  sem_wait(semaphore); /* Acquire semaphore */

    printf("ThreadId %i: acquired semaphore\n", tid);

      /* Pretend to do some work */
    printf("ThreadId %i: working...\n", tid);
    sleep(1);
  
    printf("ThreadId %i: released semaphore\n", tid);    Now this is protected.
    
  sem_post(semaphore); /* Release semaphore */
  
  return 0;
}
Why did the other runs succeed?