pthread_cond_timedwait() not waiting under 1 second? (Linux)

Question

I wrote that nice capability to listen to UDP messages and these are added to a FIFO whenever a new message arrives and that is signaled to a listener.

The listener waits for messages if it has nothing else to do. However, it knows, in some cases, that it should wake up in a very short amount of time. So I wrote code to use the pthread_cond_timedwait() and there I put the time which in my current test 1.5 seconds, roughly.

It does wait 1 second, then the wait function does not block anymore. Does that mean the current implementation does not support sub-seconds (milli/micro second waits)?

There is a little bit of my output. I start with 1417 milli-seconds, and it seems to wait for 1001 milli-seconds on the first attempt. Then 0 or 1 millisecond on each following attempt, non-blocking at all.

image transform ending with [1416272]
wait for 1417 till 1401354361 now = 1401354360
image transform ending with [415259]
wait for 416 till 1401354361 now = 1401354361
image transform ending with [414759]
wait for 415 till 1401354361 now = 1401354361
image transform ending with [414196]
wait for 415 till 1401354361 now = 1401354361
image transform ending with [413646]
wait for 414 till 1401354361 now = 1401354361
image transform ending with [413013]
wait for 414 till 1401354361 now = 1401354361
image transform ending with [412385]
wait for 413 till 1401354361 now = 1401354361
image transform ending with [411801]
wait for 412 till 1401354361 now = 1401354361
image transform ending with [411237]
wait for 412 till 1401354361 now = 1401354361
image transform ending with [410690]
wait for 411 till 1401354361 now = 1401354361
image transform ending with [410204]
wait for 411 till 1401354361 now = 1401354361
image transform ending with [409728]
wait for 410 till 1401354361 now = 1401354361
image transform ending with [409150]
wait for 410 till 1401354361 now = 1401354361
image transform ending with [408566]
wait for 409 till 1401354361 now = 1401354361
image transform ending with [408004]
...snip...
wait for 3 till 1401354361 now = 1401354361
image transform ending with [2188]
wait for 3 till 1401354361 now = 1401354361
image transform ending with [1628]
wait for 2 till 1401354361 now = 1401354361
image transform ending with [1077]
wait for 2 till 1401354361 now = 1401354361
image transform ending with [221]
wait for 1 till 1401354361 now = 1401354361

The wait function:

    void wait(int msecs)
    {
        if(msecs == -1)
        {
            pthread_cond_wait(&f_condition, &f_mutex.f_mutex);
        }
        else if(msecs > 0)
        {
            struct timeval tod;
            gettimeofday(&tod, nullptr);
            struct timespec ts;
            ts.tv_sec = tod.tv_sec + msecs / 1000;
            ts.tv_nsec = tod.tv_usec * 1000 + msecs % 1000;
            ts.tv_sec += ts.tv_nsec / 1000000000L;
            ts.tv_nsec = ts.tv_nsec % 1000000000L;

std::cerr << "wait for " << msecs << " till " << ts.tv_sec << " now = " << time(NULL) << "\n";

            pthread_cond_timedwait(&f_condition, &f_mutex.f_mutex, &ts);
        }
    }

And what return code are you seeing from `pthread_cond_timedwait()` when that happens? — 6EQUJ5, May 29 '14 at 22:37
Okay, I added the code of the wait() function itself. It is called with the mutex locked. The code returned by the call is 110 which represents `#define ETIMEDOUT 110 /* Connection timed out */`. So it thinks that `current time >= ts`... — Alexis Wilke, May 30 '14 at 07:09
Just in case, I also tested errno. It stays at zero the whole time. — Alexis Wilke, May 30 '14 at 07:27
Should it not be `ts.tv_nsec = tod.tv_usec * 1000 + msecs * 1000 * 1000` ? You appear to be modulo dividing msecs by 1000 (ie calculating units of seconds) then adding it to units of nsec.. — 6EQUJ5, May 30 '14 at 08:11
@6EQUJ5: I think you've hit on the problem, but I think the actual expression should be: `ts.tv_nsec = tod.tv_usec * 1000 + (msecs % 1000) * 1000 * 1000` — Michael Burr, May 30 '14 at 09:13
Ha! Ha! Yes... Darn... Missed the ms to µs... Also Michael is correct, the module 1000 is very important. In my case, the `msecs` parameter is around 1500. — Alexis Wilke, May 30 '14 at 21:47

score 0 · Answer 1 · answered May 30 '14 at 08:55

I wrote that nice capability to listen to UDP messages and these are added to a FIFO whenever a new message arrives and that is signaled to a listener.

Well, the socket buffer is already a FIFO. So you take a UDP datagram from FIFO and put it into a FIFO again. Is that right?

The listener waits for messages if it has nothing else to do. However, it knows, in some cases, that it should wake up in a very short amount of time. So I wrote code to use the pthread_cond_timedwait() and there I put the time which in my current test 1.5 seconds, roughly.

Why don't you just use select/epoll or something like libevent with 1.5 second timeout?

It does wait 1 second, then the wait function does not block anymore. Does that mean the current implementation does not support sub-seconds (milli/micro second waits)?

Your output is hard to read and is not helpful in determining what is going on. You need to print how long you wanted to wait, what happened (timeout or received a signal) and, in case of timeout, how long it actually waited.

(Point 1) Indeed, a UDP message queue is a FIFO. I have 2 threads because I may receive 100 messages in the UDP FIFO while the working thread goes on and on and would not check the UDP FIFO. At some point, that FIFO may be full and if that happens, I may miss some of the events (some of which could be important such as the STOP message which I use to end the working process ASAP.) (Point 2) Since I have two threads, it seems logical to me to use thread related functions.... (Point 3) The main number to look at is that 416 which goes down, about 1 ms at a time, up to 1 in the last message. — Alexis Wilke, May 30 '14 at 21:42

pthread_cond_timedwait() not waiting under 1 second? (Linux)

1 Answers1