Isn't dispatch_semaphore_wait FIFO?

The documentation for dispatch_semaphore_wait says that it "waits in FIFO order for a signal". But it doesn't seem to in this example-- can someone please explain?

Example:

#include <dispatch/dispatch.h>
#include <stdio.h>

dispatch_queue_t q1, q2;
dispatch_semaphore_t sem;
int g_call;

void do_work(void)
{
    int s = 0;
    int i;
    for (i = 0; i < 100000000; ++i)
        ++s;
}

void f1(int call)
{
__block int waited = 0;
    dispatch_async(q1, ^{
        while (dispatch_semaphore_wait(sem, dispatch_time(DISPATCH_TIME_NOW, NSEC_PER_SEC/1000)))
            waited = 1;
        printf("1:%d %s\n", call, waited ? "waited" : "");
        do_work();
        dispatch_semaphore_signal(sem);
    });
}

void f2(int call)
{
    __block int waited = 0;
    dispatch_async(q2, ^{
        while (dispatch_semaphore_wait(sem, dispatch_time(DISPATCH_TIME_NOW, NSEC_PER_SEC/1000)))
            waited = 1;
        printf("\t\t2:%d %s\n", call, waited ? "waited" : "");
        do_work();
        dispatch_semaphore_signal(sem);
    });
}

int main(int argc, char **argv)
{
    q1 = dispatch_queue_create(NULL, NULL);
    q2 = dispatch_queue_create(NULL, NULL);
    sem = dispatch_semaphore_create(1);
    g_call = 0;

    dispatch_queue_t q_global = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0);
    dispatch_source_t timer = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER, 0, 0, q_global);
    const uint64_t DELAY = 10;
    dispatch_source_set_event_handler(timer, ^{
        f1(g_call);
        f2(g_call);
        ++g_call;
        dispatch_source_set_timer(timer, dispatch_time(DISPATCH_TIME_NOW, DELAY), 0, 0);
    });
    dispatch_source_set_timer(timer, dispatch_time(DISPATCH_TIME_NOW, DELAY), 0, 0);
    dispatch_resume(timer);

    sleep(3);
}

Expected output:

Actual output (one example):

1:0
1:1
...
1:14
        2:0 waited
        2:1
        ...

Edit: Actual output if, instead of being serial queues, q1 and q2 are set to the global queue:

1:0 
        2:8 waited
1:3 waited
1:4 waited
        2:3 waited
1:6 waited
1:9 waited
        2:9 waited
        2:21 
1:28 waited

(Sometimes it works perfectly, but sometimes it's weird like this.)

Solution

dispatch_queue_create creates a serial queue, and then the serial queue creates a pthread thread (I'm not so sure...).

And dispatch_semaphore_wait uses spin locks for acquiring a semaphore for performance. It means that it is not a context switching point as pthread_mutex_lock. It doesn't switch context so frequently.

If you use the global queue, your code would output as your expected (however it is not exactly same). Because the global queue uses pthread workqueue. The behavior of switching context is different from a pthread thread's one.

q1 = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0);
q2 = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0);

EDITED:

The global queue executes the given tasks sequentially, but these tasks are executing concurrently, the output order may vary by context switching. Moreover, the timer of your code fires every 10 nanoseconds, too many tasks are executing concurrently.

Another simple example,

dispatch_queue_t queue =
    dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0);
dispatch_apply(10, queue, ^(size_t index) {
    printf("%zu\n", index);
});

On my 8core MacBook Pro: