C program hanging when executing thread in producer-consumer problem

Question

I'm reproducing the producer-consumer in C using semaphores from semaphore.h and threads and mutexes from pthread.h with a very simple implementation. However, when I compile and run my program I won't see any output and the process is just hanging. I couldn't even get the program to print a string as the first instruction in main().

#include <stdio.h>
#include <pthread.h>
#include <semaphore.h>

#define N 100
#define MAX 10000

int buffer[N], cont = 0, lo = 0, hi = 0;
sem_t empty, full;
pthread_mutex_t mutex;

void *producer(void *ptr){
    for(int i = 1; i < MAX; i ++){
        pthread_mutex_lock(&mutex);
        sem_wait(&empty);
        
        buffer[hi] = i;
        hi = (hi + 1) % N;
        cont ++;
        
        sem_post(&full);
        pthread_mutex_unlock(&mutex);
    }

    pthread_exit(0);
}

void *consumer(void *ptr){
    for(int i = 1; i < MAX; i ++){
        pthread_mutex_lock(&mutex);
        sem_wait(&full);
        
        printf("%d\n", buffer[lo]);
        lo = (lo + 1) % N;
        cont --;
        
        sem_post(&empty);
        pthread_mutex_unlock(&mutex);
    }

    pthread_exit(0);
}

int main(void){
    pthread_t prod, cons;

    sem_init(&empty, 0, N);
    sem_init(&full, 0, 0);
    pthread_mutex_init(&mutex, 0);

    pthread_create(&prod, 0, producer, 0);
    pthread_create(&cons, 0, consumer, 0);

    pthread_join(prod, 0);
    pthread_join(cons, 0);

    pthread_mutex_destroy(&mutex);
    sem_destroy(&empty);
    sem_destroy(&full);

    return 0;
}

However, when I add this simple printer() function containing a single print statement and pass it to be executed in the threads, replacing producer() and consumer(), the program will print correctly.

void *printer(void *ptr){
    printf("I printed");
    pthread_exit(0);
}

I believe there must be a deadlock or race condition anywhere in this code but I couldn't find it. Does anyone have any clue?

Answer 1

You do have a deadlock [eventually].

To fix, reverse the order of the sem* and mutex calls.

Here is the refactored code with debug:

#include <stdio.h>
#include <pthread.h>
#include <semaphore.h>
#include <time.h>
#include <stdarg.h>

#define N 100
#define MAX 10000

int buffer[N], cont = 0, lo = 0, hi = 0;
sem_t empty, full;
pthread_mutex_t mutex;

#define LOCKWAIT(_sem) \
    lockwait(&_sem,#_sem)

#define POSTUNLOCK(_sem) \
    postunlock(&_sem,#_sem)

// debug control
double tsczero;                         // absolute start time
__thread const char *tid;               // thread name
FILE *xfdbg;                            // debug log stream
int opt_r;                              // 1=reverse order of calls (i.e. fix)

#if DEBUG
#define dbgprt(_fmt...) \
    xdbgprt(__FUNCTION__,_fmt)
#else
#define dbgprt(_fmt...) \
    do { } while (0)
#endif

// tscgetf -- get hires timestamp
double
tscgetf(void)
{
    struct timespec ts;
    double sec;

    clock_gettime(CLOCK_MONOTONIC,&ts);

    sec = ts.tv_nsec;
    sec /= 1e9;
    sec += ts.tv_sec;

    sec -= tsczero;

    return sec;
}

// xdbgprt -- output debug message
void
xdbgprt(const char *fnc,const char *fmt,...)
{
    char buf[1000];
    char *bp = buf;
    va_list ap;

    bp += sprintf(bp,"[%.9f %s] %s: ",tscgetf(),tid,fnc);

    va_start(ap,fmt);
    bp += vsprintf(bp,fmt,ap);
    va_end(ap);

    fputs(buf,xfdbg);
}

// lockwait -- perform mutex lock and semaphore wait
void
lockwait(sem_t *sem,const char *sym)
{

    // original
    if (! opt_r) {
        dbgprt("LOCK\n");
        pthread_mutex_lock(&mutex);

        dbgprt("WAIT %s\n",sym);
        sem_wait(sem);
    }

    // fixed
    else {
        dbgprt("WAIT %s\n",sym);
        sem_wait(sem);

        dbgprt("LOCK\n");
        pthread_mutex_lock(&mutex);
    }
}

// postunlock -- perform mutex unlock and semaphore post
void
postunlock(sem_t *sem,const char *sym)
{

    // original
    if (! opt_r) {
        dbgprt("POST %s\n",sym);
        sem_post(sem);

        dbgprt("UNLOCK\n");
        pthread_mutex_unlock(&mutex);
    }

    // fixed
    else {
        dbgprt("UNLOCK\n");
        pthread_mutex_unlock(&mutex);

        dbgprt("POST %s\n",sym);
        sem_post(sem);
    }
}

void *
producer(void *ptr)
{

    tid = "prod";

    dbgprt("ENTER\n");

    for (int i = 1; i < MAX; i++) {
        dbgprt("LOOP i=%d\n",i);

        LOCKWAIT(empty);

        dbgprt("MODIFY hi=%d\n",hi);
        buffer[hi] = i;
        hi = (hi + 1) % N;
        cont++;

        POSTUNLOCK(full);
    }

    dbgprt("EXIT\n");
    pthread_exit(0);
}

void *
consumer(void *ptr)
{

    tid = "cons";

    dbgprt("ENTER\n");

    for (int i = 1; i < MAX; i++) {
        dbgprt("LOOP i=%d\n",i);

        LOCKWAIT(full);

        dbgprt("MODIFY lo=%d cont=%d\n",lo,cont);
        printf("%d\n", buffer[lo]);
        lo = (lo + 1) % N;
        cont--;

        POSTUNLOCK(empty);
    }

    dbgprt("EXIT\n");
    pthread_exit(0);
}

int
main(int argc,char **argv)
{
    pthread_t prod, cons;

    tid = "main";

    --argc;
    ++argv;

    for (;  argc > 0;  --argc, ++argv) {
        char *cp = *argv;
        if (*cp != '-')
            break;

        cp += 2;
        switch (cp[-1]) {
        case 'r':
            opt_r = ! opt_r;
            break;
        }
    }

#if DEBUG
    tsczero = tscgetf();
    xfdbg = fopen("debug.txt","w");
    setlinebuf(xfdbg);
#endif

    dbgprt("REVERSE opt_r=%d\n",opt_r);

    sem_init(&empty, 0, N);
    sem_init(&full, 0, 0);
    pthread_mutex_init(&mutex, 0);

    dbgprt("CREATE producer\n");
    pthread_create(&prod, 0, producer, 0);
    dbgprt("CREATE consumer\n");
    pthread_create(&cons, 0, consumer, 0);

    dbgprt("JOIN\n");
    pthread_join(prod, 0);
    pthread_join(cons, 0);

    dbgprt("DESTROY\n");
    pthread_mutex_destroy(&mutex);
    sem_destroy(&empty);
    sem_destroy(&full);

#if DEBUG
    fclose(xfdbg);
#endif

    return 0;
}

---

Here is the debug output using your original order:

[0.000517853 main] main: REVERSE opt_r=0
[0.000633840 main] main: CREATE producer
[0.000693570 main] main: CREATE consumer
[0.000729565 main] main: JOIN
[0.000743532 prod] producer: ENTER
[0.000758227 prod] producer: LOOP i=1
[0.000763465 prod] lockwait: LOCK
[0.000768604 prod] lockwait: WAIT empty
[0.000773880 prod] producer: MODIFY hi=0
[0.000778208 prod] postunlock: POST full
[0.000782575 prod] postunlock: UNLOCK
[0.000787080 prod] producer: LOOP i=2
[0.000790260 prod] lockwait: LOCK
[0.000796188 prod] lockwait: WAIT empty
[0.000785370 cons] consumer: ENTER
[0.000800456 prod] producer: MODIFY hi=1
[0.000830415 prod] postunlock: POST full
[0.000815459 cons] consumer: LOOP i=1
[0.000842767 cons] lockwait: LOCK
[0.000834296 prod] postunlock: UNLOCK
[0.000863640 prod] producer: LOOP i=3
[0.000870208 prod] lockwait: LOCK
[0.000875329 cons] lockwait: WAIT full
[0.000886424 cons] consumer: MODIFY lo=0 cont=2
[0.000942927 cons] postunlock: POST empty
[0.000951050 cons] postunlock: UNLOCK
[0.000959818 cons] consumer: LOOP i=2
[0.000965404 cons] lockwait: LOCK
[0.000969747 cons] lockwait: WAIT full
[0.000973936 cons] consumer: MODIFY lo=1 cont=1
[0.000990639 cons] postunlock: POST empty
[0.000999437 cons] postunlock: UNLOCK
[0.001005915 cons] consumer: LOOP i=3
[0.001013370 cons] lockwait: LOCK
[0.001020467 cons] lockwait: WAIT full

---

Here is the debug log using -r (that reverses the order) [redacted]:

[0.000055199 main] main: REVERSE opt_r=1
[0.000085554 main] main: CREATE producer
[0.000117494 main] main: CREATE consumer
[0.000145610 main] main: JOIN
[0.000182603 prod] producer: ENTER
[0.000198292 prod] producer: LOOP i=1
[0.000203529 prod] lockwait: WAIT empty
[0.000209265 prod] lockwait: LOCK
[0.000214722 prod] producer: MODIFY hi=0
[0.000219398 prod] postunlock: UNLOCK
[0.000224284 prod] postunlock: POST full
[0.000228802 prod] producer: LOOP i=2
[0.000239351 prod] lockwait: WAIT empty
[0.000242521 prod] lockwait: LOCK
[0.000244922 prod] producer: MODIFY hi=1
[0.000247484 prod] postunlock: UNLOCK
[0.000249832 prod] postunlock: POST full
[0.000252303 prod] producer: LOOP i=3
[0.000244887 cons] consumer: ENTER
[0.000254683 prod] lockwait: WAIT empty
[0.000275230 prod] lockwait: LOCK
[0.000265113 cons] consumer: LOOP i=1
[0.000286063 cons] lockwait: WAIT full
[0.000295160 cons] lockwait: LOCK
[0.000278717 prod] producer: MODIFY hi=2
[0.000304316 prod] postunlock: UNLOCK
[0.000309933 prod] postunlock: POST full
[0.000312835 prod] producer: LOOP i=4
[0.000315391 prod] lockwait: WAIT empty
[0.000317821 prod] lockwait: LOCK
[0.000320131 prod] producer: MODIFY hi=3
[0.000322593 prod] postunlock: UNLOCK
[0.000326965 prod] postunlock: POST full
[0.000329833 prod] producer: LOOP i=5
[0.000332340 prod] lockwait: WAIT empty
[0.000338385 prod] lockwait: LOCK
[0.000329810 cons] consumer: MODIFY lo=0 cont=4
[0.000378317 cons] postunlock: UNLOCK
[0.000386295 cons] postunlock: POST empty
[0.000390299 cons] consumer: LOOP i=2
[0.000394642 cons] lockwait: WAIT full
[0.000398724 cons] lockwait: LOCK
[0.000402682 cons] consumer: MODIFY lo=1 cont=3
[0.000412222 cons] postunlock: UNLOCK
[0.000416774 cons] postunlock: POST empty
[0.000421020 cons] consumer: LOOP i=3
[0.000424895 cons] lockwait: WAIT full
[0.000428433 cons] lockwait: LOCK
[0.000432381 cons] consumer: MODIFY lo=2 cont=2
[0.000441909 cons] postunlock: UNLOCK
[0.000446592 cons] postunlock: POST empty
[0.000450642 cons] consumer: LOOP i=4
[0.000454705 cons] lockwait: WAIT full
[0.000458676 cons] lockwait: LOCK
[0.000462377 cons] consumer: MODIFY lo=3 cont=1
[0.000471476 cons] postunlock: UNLOCK
[0.000479299 cons] postunlock: POST empty
[0.000484029 cons] consumer: LOOP i=5
[0.000488070 cons] lockwait: WAIT full
[0.000487936 prod] producer: MODIFY hi=4
[0.000497353 prod] postunlock: UNLOCK
[0.000502948 prod] postunlock: POST full
[0.000511573 prod] producer: LOOP i=6
[0.000517299 prod] lockwait: WAIT empty
[0.000525397 prod] lockwait: LOCK
[0.000533415 prod] producer: MODIFY hi=5
[0.000540494 prod] postunlock: UNLOCK
[0.000517517 cons] lockwait: LOCK
[0.000543576 prod] postunlock: POST full
[0.000550409 cons] consumer: MODIFY lo=4 cont=2
[0.000556990 prod] producer: LOOP i=7
[0.000566307 prod] lockwait: WAIT empty
[0.000566850 cons] postunlock: UNLOCK
[0.000578519 cons] postunlock: POST empty
[0.000572297 prod] lockwait: LOCK
[0.000586760 cons] consumer: LOOP i=6
[0.000590214 prod] producer: MODIFY hi=6
[0.000602937 prod] postunlock: UNLOCK
[0.000608912 prod] postunlock: POST full
[0.000614508 prod] producer: LOOP i=8
[0.000596016 cons] lockwait: WAIT full
[0.000619884 prod] lockwait: WAIT empty
[0.000626648 cons] lockwait: LOCK
[0.000632447 prod] lockwait: LOCK
[0.000637344 cons] consumer: MODIFY lo=5 cont=2
[0.000649678 cons] postunlock: UNLOCK
[0.000654972 cons] postunlock: POST empty
[0.000656237 prod] producer: MODIFY hi=7
[0.000659138 cons] consumer: LOOP i=7
[0.000660696 prod] postunlock: UNLOCK
[0.000666434 cons] lockwait: WAIT full
[0.000670165 prod] postunlock: POST full
[0.000672836 cons] lockwait: LOCK
[0.000674145 prod] producer: LOOP i=9
[0.000679944 cons] consumer: MODIFY lo=6 cont=2
[0.000682624 prod] lockwait: WAIT empty
[0.000690880 prod] lockwait: LOCK
[0.000693454 cons] postunlock: UNLOCK
[0.000701987 cons] postunlock: POST empty
[0.000702740 prod] producer: MODIFY hi=8
[0.000709721 cons] consumer: LOOP i=8
[0.000712282 prod] postunlock: UNLOCK
[0.000717730 cons] lockwait: WAIT full
[0.000720967 prod] postunlock: POST full
[0.000722632 cons] lockwait: LOCK
[0.000723947 prod] producer: LOOP i=10
[0.000729548 cons] consumer: MODIFY lo=7 cont=2
[0.000738906 prod] lockwait: WAIT empty
[0.000748707 prod] lockwait: LOCK
[0.000749263 cons] postunlock: UNLOCK
[0.000757085 cons] postunlock: POST empty
[0.000757911 prod] producer: MODIFY hi=9
[0.000764814 cons] consumer: LOOP i=9
[0.000767559 prod] postunlock: UNLOCK
[0.000772937 cons] lockwait: WAIT full
[0.000776378 prod] postunlock: POST full
[0.000781869 cons] lockwait: LOCK
[0.000784639 prod] producer: LOOP i=11
[0.000787374 cons] consumer: MODIFY lo=8 cont=2
[0.000788658 prod] lockwait: WAIT empty
[0.000798022 prod] lockwait: LOCK
[0.000799115 cons] postunlock: UNLOCK
[0.000805397 cons] postunlock: POST empty
[0.000806244 prod] producer: MODIFY hi=10
[0.000812837 cons] consumer: LOOP i=10
[0.000815531 prod] postunlock: UNLOCK
[0.000820807 cons] lockwait: WAIT full
[0.000824184 prod] postunlock: POST full
[0.000829613 cons] lockwait: LOCK
[0.000832394 prod] producer: LOOP i=12
[0.000838115 cons] consumer: MODIFY lo=9 cont=2
[0.000840744 prod] lockwait: WAIT empty
[0.000848593 prod] lockwait: LOCK
[0.000849557 cons] postunlock: UNLOCK
[0.000856992 cons] postunlock: POST empty
[0.000857734 prod] producer: MODIFY hi=11
[0.000864306 cons] consumer: LOOP i=11
[0.000866948 prod] postunlock: UNLOCK
[0.000872336 cons] lockwait: WAIT full
[0.000875577 prod] postunlock: POST full
[0.000878181 cons] lockwait: LOCK
[0.000879523 prod] producer: LOOP i=13
[0.000885419 cons] consumer: MODIFY lo=10 cont=2
[0.000888128 prod] lockwait: WAIT empty
[0.000896147 prod] lockwait: LOCK
[0.000897118 cons] postunlock: UNLOCK
[0.000903262 cons] postunlock: POST empty
[0.000904183 prod] producer: MODIFY hi=12
[0.000910608 cons] consumer: LOOP i=12
[0.000913332 prod] postunlock: UNLOCK
[0.000918640 cons] lockwait: WAIT full
[0.000922011 prod] postunlock: POST full
[0.000927424 cons] lockwait: LOCK
[0.000930297 prod] producer: LOOP i=14
[0.000935952 cons] consumer: MODIFY lo=11 cont=2
[0.000938622 prod] lockwait: WAIT empty
[0.000946452 prod] lockwait: LOCK
[0.000947247 cons] postunlock: UNLOCK
[0.000954348 cons] postunlock: POST empty
[0.000955167 prod] producer: MODIFY hi=13
[0.000962026 cons] consumer: LOOP i=13
[0.000964769 prod] postunlock: UNLOCK
[0.000970171 cons] lockwait: WAIT full
[0.000973468 prod] postunlock: POST full
[0.000975867 cons] lockwait: LOCK
[0.000977445 prod] producer: LOOP i=15
[0.000983074 cons] consumer: MODIFY lo=12 cont=2
[0.000985739 prod] lockwait: WAIT empty
[0.000994076 prod] lockwait: LOCK
[0.000995090 cons] postunlock: UNLOCK
[0.001003230 cons] postunlock: POST empty
[0.001004058 prod] producer: MODIFY hi=14
[0.001010934 cons] consumer: LOOP i=14
[0.001013610 prod] postunlock: UNLOCK
[0.001019208 cons] lockwait: WAIT full
[0.001022371 prod] postunlock: POST full
[0.001023962 cons] lockwait: LOCK
[0.001025403 prod] producer: LOOP i=16
[0.001031008 cons] consumer: MODIFY lo=13 cont=2
[0.001033629 prod] lockwait: WAIT empty
[0.001041470 prod] lockwait: LOCK
[0.001042576 cons] postunlock: UNLOCK
[0.001049282 cons] postunlock: POST empty
[0.001050084 prod] producer: MODIFY hi=15
[0.001056666 cons] consumer: LOOP i=15
[0.001059315 prod] postunlock: UNLOCK
[0.001064660 cons] lockwait: WAIT full
[0.001067903 prod] postunlock: POST full
[0.001069633 cons] lockwait: LOCK
[0.001070928 prod] producer: LOOP i=17
[0.001076780 cons] consumer: MODIFY lo=14 cont=2
[0.001079487 prod] lockwait: WAIT empty
[0.001087688 prod] lockwait: LOCK
[0.001088742 cons] postunlock: UNLOCK
[0.001095560 cons] postunlock: POST empty
[0.001096297 prod] producer: MODIFY hi=16
[0.001102918 cons] consumer: LOOP i=16
[0.001105597 prod] postunlock: UNLOCK
[0.001108103 cons] lockwait: WAIT full
[0.001109992 prod] postunlock: POST full
[0.001115527 cons] lockwait: LOCK
[0.001118404 prod] producer: LOOP i=18
[0.001124102 cons] consumer: MODIFY lo=15 cont=2
[0.001126811 prod] lockwait: WAIT empty
[0.001134586 prod] lockwait: LOCK
[0.001135513 cons] postunlock: UNLOCK
[0.001143617 cons] postunlock: POST empty
[0.001144402 prod] producer: MODIFY hi=17
[0.001151004 cons] consumer: LOOP i=17
[0.001153610 prod] postunlock: UNLOCK
[0.001162964 cons] lockwait: WAIT full
[0.001166257 prod] postunlock: POST full
[0.001171991 cons] lockwait: LOCK
[0.001174672 prod] producer: LOOP i=19
[0.001185815 prod] lockwait: WAIT empty
[0.001179892 cons] consumer: MODIFY lo=16 cont=2
[0.001190836 prod] lockwait: LOCK
[0.001199597 cons] postunlock: UNLOCK
[0.001206362 cons] postunlock: POST empty
[0.001207080 prod] producer: MODIFY hi=18
[0.001213919 cons] consumer: LOOP i=18
[0.001216471 prod] postunlock: UNLOCK
[0.001221884 cons] lockwait: WAIT full
[0.001225169 prod] postunlock: POST full
[0.001227765 cons] lockwait: LOCK
[0.001229165 prod] producer: LOOP i=20
[0.001240508 cons] consumer: MODIFY lo=17 cont=2
[0.001243515 prod] lockwait: WAIT empty
[0.001252271 prod] lockwait: LOCK
[0.001254139 cons] postunlock: UNLOCK
[0.001260196 cons] postunlock: POST empty
[0.001261043 prod] producer: MODIFY hi=19
[0.001267592 cons] consumer: LOOP i=19
[0.001270228 prod] postunlock: UNLOCK
[0.001275580 cons] lockwait: WAIT full
[0.001279138 prod] postunlock: POST full
[0.001285059 cons] lockwait: LOCK
[0.001288061 prod] producer: LOOP i=21
[0.001293964 cons] consumer: MODIFY lo=18 cont=2
[0.001296763 prod] lockwait: WAIT empty
[0.001304793 prod] lockwait: LOCK
[0.001305873 cons] postunlock: UNLOCK
[0.001313871 prod] producer: MODIFY hi=20
[0.001321520 prod] postunlock: UNLOCK
[0.001313056 cons] postunlock: POST empty
[0.001327716 prod] postunlock: POST full
[0.001334982 cons] consumer: LOOP i=20
[0.001337633 prod] producer: LOOP i=22
[0.001343371 cons] lockwait: WAIT full
[0.001346087 prod] lockwait: WAIT empty
[0.001351580 cons] lockwait: LOCK
[0.001357004 prod] lockwait: LOCK
[0.001362167 cons] consumer: MODIFY lo=19 cont=2
[0.001374832 cons] postunlock: UNLOCK
[0.001380170 cons] postunlock: POST empty
[0.001381046 prod] producer: MODIFY hi=21
[0.001387405 cons] consumer: LOOP i=21
[0.001390142 prod] postunlock: UNLOCK
[0.001395580 cons] lockwait: WAIT full
[0.001399002 prod] postunlock: POST full
[0.001404692 cons] lockwait: LOCK
[0.001407393 prod] producer: LOOP i=23
[0.001413243 cons] consumer: MODIFY lo=20 cont=2
[0.001415825 prod] lockwait: WAIT empty
[0.001423992 prod] lockwait: LOCK
[0.001424969 cons] postunlock: UNLOCK
[0.001432759 cons] postunlock: POST empty
[0.001433523 prod] producer: MODIFY hi=22
[0.001440312 cons] consumer: LOOP i=22
[0.001442943 prod] postunlock: UNLOCK
[0.001448309 cons] lockwait: WAIT full
[0.001451555 prod] postunlock: POST full
[0.001453167 cons] lockwait: LOCK
[0.001454552 prod] producer: LOOP i=24
[0.001460281 cons] consumer: MODIFY lo=21 cont=2
[0.001462926 prod] lockwait: WAIT empty
[0.001471089 prod] lockwait: LOCK
[0.001471990 cons] postunlock: UNLOCK
[0.001479872 cons] postunlock: POST empty
[0.001480716 prod] producer: MODIFY hi=23
[0.001487546 cons] consumer: LOOP i=23
[0.001490207 prod] postunlock: UNLOCK
[0.001495606 cons] lockwait: WAIT full
[0.001498918 prod] postunlock: POST full
[0.001500629 cons] lockwait: LOCK
[0.001501968 prod] producer: LOOP i=25
[0.001507611 cons] consumer: MODIFY lo=22 cont=2
[0.001510353 prod] lockwait: WAIT empty
[0.001518173 prod] lockwait: LOCK
[0.001519013 cons] postunlock: UNLOCK
[0.001526678 cons] postunlock: POST empty
[0.001527420 prod] producer: MODIFY hi=24
[0.001534062 cons] consumer: LOOP i=24
[0.001536713 prod] postunlock: UNLOCK
[0.001542081 cons] lockwait: WAIT full
[0.001545518 prod] postunlock: POST full
[0.001551054 cons] lockwait: LOCK
[0.001553736 prod] producer: LOOP i=26
[0.001556361 cons] consumer: MODIFY lo=23 cont=2
[0.001557741 prod] lockwait: WAIT empty

...

[0.558383183 prod] producer: LOOP i=9990
[0.558386139 cons] consumer: MODIFY lo=59 cont=30
[0.558390972 prod] lockwait: WAIT empty
[0.558398995 cons] postunlock: UNLOCK
[0.558399288 prod] lockwait: LOCK
[0.558404762 cons] postunlock: POST empty
[0.558411672 prod] producer: MODIFY hi=89
[0.558414659 cons] consumer: LOOP i=9961
[0.558417208 prod] postunlock: UNLOCK
[0.558418741 cons] lockwait: WAIT full
[0.558424253 prod] postunlock: POST full
[0.558427173 cons] lockwait: LOCK
[0.558433086 prod] producer: LOOP i=9991
[0.558435818 cons] consumer: MODIFY lo=60 cont=30
[0.558440916 prod] lockwait: WAIT empty
[0.558449111 cons] postunlock: UNLOCK
[0.558449522 prod] lockwait: LOCK
[0.558455179 cons] postunlock: POST empty
[0.558461799 prod] producer: MODIFY hi=90
[0.558464766 cons] consumer: LOOP i=9962
[0.558470320 prod] postunlock: UNLOCK
[0.558473265 cons] lockwait: WAIT full
[0.558478548 prod] postunlock: POST full
[0.558481497 cons] lockwait: LOCK
[0.558486884 prod] producer: LOOP i=9992
[0.558489655 cons] consumer: MODIFY lo=61 cont=30
[0.558492034 prod] lockwait: WAIT empty
[0.558494834 prod] lockwait: LOCK
[0.558496967 cons] postunlock: UNLOCK
[0.558501881 cons] postunlock: POST empty
[0.558503788 prod] producer: MODIFY hi=91
[0.558504793 cons] consumer: LOOP i=9963
[0.558511990 prod] postunlock: UNLOCK
[0.558514987 cons] lockwait: WAIT full
[0.558521390 prod] postunlock: POST full
[0.558523301 cons] lockwait: LOCK
[0.558528778 prod] producer: LOOP i=9993
[0.558531411 cons] consumer: MODIFY lo=62 cont=30
[0.558536830 prod] lockwait: WAIT empty
[0.558545322 cons] postunlock: UNLOCK
[0.558545705 prod] lockwait: LOCK
[0.558551370 cons] postunlock: POST empty
[0.558558301 prod] producer: MODIFY hi=92
[0.558561263 cons] consumer: LOOP i=9964
[0.558563917 prod] postunlock: UNLOCK
[0.558565366 cons] lockwait: WAIT full
[0.558570957 prod] postunlock: POST full
[0.558573989 cons] lockwait: LOCK
[0.558579432 prod] producer: LOOP i=9994
[0.558582227 cons] consumer: MODIFY lo=63 cont=30
[0.558587326 prod] lockwait: WAIT empty
[0.558595522 cons] postunlock: UNLOCK
[0.558595754 prod] lockwait: LOCK
[0.558601249 cons] postunlock: POST empty
[0.558607928 prod] producer: MODIFY hi=93
[0.558610935 cons] consumer: LOOP i=9965
[0.558616399 prod] postunlock: UNLOCK
[0.558619342 cons] lockwait: WAIT full
[0.558624717 prod] postunlock: POST full
[0.558627627 cons] lockwait: LOCK
[0.558633079 prod] producer: LOOP i=9995
[0.558635806 cons] consumer: MODIFY lo=64 cont=30
[0.558638037 prod] lockwait: WAIT empty
[0.558648130 cons] postunlock: UNLOCK
[0.558654211 cons] postunlock: POST empty
[0.558659958 cons] consumer: LOOP i=9966
[0.558665108 cons] lockwait: WAIT full
[0.558670352 cons] lockwait: LOCK
[0.558675412 cons] consumer: MODIFY lo=65 cont=29
[0.558648406 prod] lockwait: LOCK
[0.558683807 cons] postunlock: UNLOCK
[0.558694670 cons] postunlock: POST empty
[0.558697900 cons] consumer: LOOP i=9967
[0.558703819 cons] lockwait: WAIT full
[0.558709449 cons] lockwait: LOCK
[0.558696469 prod] producer: MODIFY hi=94
[0.558720788 prod] postunlock: UNLOCK
[0.558727081 prod] postunlock: POST full
[0.558728030 cons] consumer: MODIFY lo=66 cont=29
[0.558730626 prod] producer: LOOP i=9996
[0.558734592 prod] lockwait: WAIT empty
[0.558735989 cons] postunlock: UNLOCK
[0.558737292 prod] lockwait: LOCK
[0.558739538 cons] postunlock: POST empty
[0.558741900 prod] producer: MODIFY hi=95
[0.558743313 cons] consumer: LOOP i=9968
[0.558749321 prod] postunlock: UNLOCK
[0.558752308 cons] lockwait: WAIT full
[0.558757942 prod] postunlock: POST full
[0.558760643 cons] lockwait: LOCK
[0.558766144 prod] producer: LOOP i=9997
[0.558768935 cons] consumer: MODIFY lo=67 cont=29
[0.558774423 prod] lockwait: WAIT empty
[0.558779325 prod] lockwait: LOCK
[0.558780367 cons] postunlock: UNLOCK
[0.558786221 cons] postunlock: POST empty
[0.558789056 cons] consumer: LOOP i=9969
[0.558788191 prod] producer: MODIFY hi=96
[0.558794958 cons] lockwait: WAIT full
[0.558802250 prod] postunlock: UNLOCK
[0.558805084 cons] lockwait: LOCK
[0.558811280 prod] postunlock: POST full
[0.558813116 cons] consumer: MODIFY lo=68 cont=29
[0.558818940 prod] producer: LOOP i=9998
[0.558824331 prod] lockwait: WAIT empty
[0.558825114 cons] postunlock: UNLOCK
[0.558830697 prod] lockwait: LOCK
[0.558833698 cons] postunlock: POST empty
[0.558838995 prod] producer: MODIFY hi=97
[0.558841785 cons] consumer: LOOP i=9970
[0.558844455 prod] postunlock: UNLOCK
[0.558845814 cons] lockwait: WAIT full
[0.558851569 prod] postunlock: POST full
[0.558854476 cons] lockwait: LOCK
[0.558860092 prod] producer: LOOP i=9999
[0.558862777 cons] consumer: MODIFY lo=69 cont=29
[0.558867731 prod] lockwait: WAIT empty
[0.558875815 cons] postunlock: UNLOCK
[0.558882101 cons] postunlock: POST empty
[0.558887810 cons] consumer: LOOP i=9971
[0.558893069 cons] lockwait: WAIT full
[0.558898397 cons] lockwait: LOCK
[0.558903499 cons] consumer: MODIFY lo=70 cont=28
[0.558876313 prod] lockwait: LOCK
[0.558911811 cons] postunlock: UNLOCK
[0.558922552 cons] postunlock: POST empty
[0.558925663 cons] consumer: LOOP i=9972
[0.558931414 cons] lockwait: WAIT full
[0.558936676 cons] lockwait: LOCK
[0.558924230 prod] producer: MODIFY hi=98
[0.558947441 prod] postunlock: UNLOCK
[0.558954397 prod] postunlock: POST full
[0.558955333 cons] consumer: MODIFY lo=71 cont=28
[0.558957879 prod] producer: EXIT
[0.558963141 cons] postunlock: UNLOCK
[0.558966733 cons] postunlock: POST empty
[0.558969386 cons] consumer: LOOP i=9973
[0.558971936 cons] lockwait: WAIT full
[0.558974379 cons] lockwait: LOCK
[0.558976723 cons] consumer: MODIFY lo=72 cont=27
[0.558982212 cons] postunlock: UNLOCK
[0.558984940 cons] postunlock: POST empty
[0.558987417 cons] consumer: LOOP i=9974
[0.558989919 cons] lockwait: WAIT full
[0.558992386 cons] lockwait: LOCK
[0.558994699 cons] consumer: MODIFY lo=73 cont=26
[0.559000029 cons] postunlock: UNLOCK
[0.559002700 cons] postunlock: POST empty
[0.559005123 cons] consumer: LOOP i=9975
[0.559007597 cons] lockwait: WAIT full
[0.559009982 cons] lockwait: LOCK
[0.559012364 cons] consumer: MODIFY lo=74 cont=25
[0.559017716 cons] postunlock: UNLOCK
[0.559020409 cons] postunlock: POST empty
[0.559022865 cons] consumer: LOOP i=9976
[0.559025313 cons] lockwait: WAIT full
[0.559027769 cons] lockwait: LOCK
[0.559030064 cons] consumer: MODIFY lo=75 cont=24
[0.559035493 cons] postunlock: UNLOCK
[0.559038186 cons] postunlock: POST empty
[0.559040657 cons] consumer: LOOP i=9977
[0.559043183 cons] lockwait: WAIT full
[0.559045628 cons] lockwait: LOCK
[0.559047971 cons] consumer: MODIFY lo=76 cont=23
[0.559059623 cons] postunlock: UNLOCK
[0.559062699 cons] postunlock: POST empty
[0.559065212 cons] consumer: LOOP i=9978
[0.559067756 cons] lockwait: WAIT full
[0.559070219 cons] lockwait: LOCK
[0.559072523 cons] consumer: MODIFY lo=77 cont=22
[0.559077935 cons] postunlock: UNLOCK
[0.559080680 cons] postunlock: POST empty
[0.559083113 cons] consumer: LOOP i=9979
[0.559085608 cons] lockwait: WAIT full
[0.559088035 cons] lockwait: LOCK
[0.559090395 cons] consumer: MODIFY lo=78 cont=21
[0.559095835 cons] postunlock: UNLOCK
[0.559098543 cons] postunlock: POST empty
[0.559101002 cons] consumer: LOOP i=9980
[0.559103517 cons] lockwait: WAIT full
[0.559105993 cons] lockwait: LOCK
[0.559108297 cons] consumer: MODIFY lo=79 cont=20
[0.559113792 cons] postunlock: UNLOCK
[0.559116510 cons] postunlock: POST empty
[0.559118955 cons] consumer: LOOP i=9981
[0.559121505 cons] lockwait: WAIT full
[0.559123927 cons] lockwait: LOCK
[0.559126265 cons] consumer: MODIFY lo=80 cont=19
[0.559131757 cons] postunlock: UNLOCK
[0.559134479 cons] postunlock: POST empty
[0.559136987 cons] consumer: LOOP i=9982
[0.559141081 cons] lockwait: WAIT full
[0.559143637 cons] lockwait: LOCK
[0.559146953 cons] consumer: MODIFY lo=81 cont=18
[0.559152451 cons] postunlock: UNLOCK
[0.559155063 cons] postunlock: POST empty
[0.559157452 cons] consumer: LOOP i=9983
[0.559159920 cons] lockwait: WAIT full
[0.559162297 cons] lockwait: LOCK
[0.559164607 cons] consumer: MODIFY lo=82 cont=17
[0.559170381 cons] postunlock: UNLOCK
[0.559173079 cons] postunlock: POST empty
[0.559175508 cons] consumer: LOOP i=9984
[0.559177944 cons] lockwait: WAIT full
[0.559180400 cons] lockwait: LOCK
[0.559182698 cons] consumer: MODIFY lo=83 cont=16
[0.559189406 cons] postunlock: UNLOCK
[0.559192088 cons] postunlock: POST empty
[0.559194528 cons] consumer: LOOP i=9985
[0.559196973 cons] lockwait: WAIT full
[0.559199338 cons] lockwait: LOCK
[0.559201650 cons] consumer: MODIFY lo=84 cont=15
[0.559207029 cons] postunlock: UNLOCK
[0.559210487 cons] postunlock: POST empty
[0.559212957 cons] consumer: LOOP i=9986
[0.559215426 cons] lockwait: WAIT full
[0.559217878 cons] lockwait: LOCK
[0.559220173 cons] consumer: MODIFY lo=85 cont=14
[0.559225617 cons] postunlock: UNLOCK
[0.559228245 cons] postunlock: POST empty
[0.559237473 cons] consumer: LOOP i=9987
[0.559241608 cons] lockwait: WAIT full
[0.559244170 cons] lockwait: LOCK
[0.559246597 cons] consumer: MODIFY lo=86 cont=13
[0.559252946 cons] postunlock: UNLOCK
[0.559255750 cons] postunlock: POST empty
[0.559258181 cons] consumer: LOOP i=9988
[0.559260649 cons] lockwait: WAIT full
[0.559263091 cons] lockwait: LOCK
[0.559265387 cons] consumer: MODIFY lo=87 cont=12
[0.559273881 cons] postunlock: UNLOCK
[0.559276523 cons] postunlock: POST empty
[0.559278951 cons] consumer: LOOP i=9989
[0.559281395 cons] lockwait: WAIT full
[0.559283768 cons] lockwait: LOCK
[0.559286103 cons] consumer: MODIFY lo=88 cont=11
[0.559291439 cons] postunlock: UNLOCK
[0.559294085 cons] postunlock: POST empty
[0.559296496 cons] consumer: LOOP i=9990
[0.559298890 cons] lockwait: WAIT full
[0.559301290 cons] lockwait: LOCK
[0.559303552 cons] consumer: MODIFY lo=89 cont=10
[0.559309016 cons] postunlock: UNLOCK
[0.559311695 cons] postunlock: POST empty
[0.559314087 cons] consumer: LOOP i=9991
[0.559316558 cons] lockwait: WAIT full
[0.559318974 cons] lockwait: LOCK
[0.559321267 cons] consumer: MODIFY lo=90 cont=9
[0.559326594 cons] postunlock: UNLOCK
[0.559329252 cons] postunlock: POST empty
[0.559331631 cons] consumer: LOOP i=9992
[0.559334096 cons] lockwait: WAIT full
[0.559336461 cons] lockwait: LOCK
[0.559338706 cons] consumer: MODIFY lo=91 cont=8
[0.559344049 cons] postunlock: UNLOCK
[0.559346744 cons] postunlock: POST empty
[0.559349145 cons] consumer: LOOP i=9993
[0.559351566 cons] lockwait: WAIT full
[0.559353938 cons] lockwait: LOCK
[0.559356191 cons] consumer: MODIFY lo=92 cont=7
[0.559361530 cons] postunlock: UNLOCK
[0.559364151 cons] postunlock: POST empty
[0.559366578 cons] consumer: LOOP i=9994
[0.559369007 cons] lockwait: WAIT full
[0.559371397 cons] lockwait: LOCK
[0.559376251 cons] consumer: MODIFY lo=93 cont=6
[0.559382274 cons] postunlock: UNLOCK
[0.559385015 cons] postunlock: POST empty
[0.559387427 cons] consumer: LOOP i=9995
[0.559389873 cons] lockwait: WAIT full
[0.559392314 cons] lockwait: LOCK
[0.559394601 cons] consumer: MODIFY lo=94 cont=5
[0.559399868 cons] postunlock: UNLOCK
[0.559402503 cons] postunlock: POST empty
[0.559404896 cons] consumer: LOOP i=9996
[0.559407322 cons] lockwait: WAIT full
[0.559409734 cons] lockwait: LOCK
[0.559412036 cons] consumer: MODIFY lo=95 cont=4
[0.559417438 cons] postunlock: UNLOCK
[0.559420124 cons] postunlock: POST empty
[0.559422540 cons] consumer: LOOP i=9997
[0.559425055 cons] lockwait: WAIT full
[0.559427470 cons] lockwait: LOCK
[0.559429770 cons] consumer: MODIFY lo=96 cont=3
[0.559435077 cons] postunlock: UNLOCK
[0.559437728 cons] postunlock: POST empty
[0.559440110 cons] consumer: LOOP i=9998
[0.559442545 cons] lockwait: WAIT full
[0.559444930 cons] lockwait: LOCK
[0.559447219 cons] consumer: MODIFY lo=97 cont=2
[0.559452568 cons] postunlock: UNLOCK
[0.559455205 cons] postunlock: POST empty
[0.559457602 cons] consumer: LOOP i=9999
[0.559460061 cons] lockwait: WAIT full
[0.559462502 cons] lockwait: LOCK
[0.559464804 cons] consumer: MODIFY lo=98 cont=1
[0.559470138 cons] postunlock: UNLOCK
[0.559472870 cons] postunlock: POST empty
[0.559475288 cons] consumer: EXIT
[0.559494919 main] main: DESTROY