unexpected delay in main thread-CodePudding

Here is a small c code to test cyclic call using thread. But it gets failed because of unexpected delay sometimes. The for-loop should be called every 10ms. The runtime of for-loop is just 1ms usually. But sometimes the execution time is longer than 200ms. It looks like other process interrupts this for-loop and return back after 200ms. This is unbelievable, 200ms, so long time is taken. The program runs under GNU Linux 5.10.41 ARM aarch64. How can I do, so that the main thread can not be preemptive by other process or threads ? Thanks a lot!

while(1)
{
    auto start_time = std::chrono::high_resolution_clock::now();
    LOG_F(INFO, "cyclic start time");
    for(int j = 0; j < 150000; j  ); //
    auto end_time  = std::chrono::high_resolution_clock::now();
    auto exec_time = std::chrono::duration_cast<std::chrono::milliseconds>(end_time - start_time);
    LOG_F(INFO, "execution time: %dms", exec_time.count());
    if (exec_time.count() < 10)
    {
        LOG_F(INFO, "i = %d", i);
        std::this_thread::sleep_for(std::chrono::milliseconds(10 - exec_time.count()));
    }
    else
    {
        LOG_F(ERROR, "execution time was higher than 10ms (%dms)", exec_time.count());
        break;
    }
}

CodePudding user response：

It is working after remove logging statements. Logging is really a mutex hog like @Frebreeze mentioned. Actually the logging statements can be kept in code, just call program with -v ERROR. Thank you very much for the Help !

It looks that the logging is the reason. But why does the logging statements take so long time, but not always, just like a heartbeat ?

CodePudding user response：

Correct answer written in original answer in comments:

Shot in the dark. Logging mutex hog. There likely is a mutex/lock within your logging system. Another thread may be a resource hog acquiring the lock and not releasing it quickly. This would cause THIS thread to wait much longer than expected. Check this behaviour by disabling all other threads and see if behaviour continues.

Follow up help below:

@Jung Glad you figured it out!

If logging is taking variable amounts of time, look into the data you are passing to the logging system. General things to lookout for would be large data structs passed by value. Yes I know compilers are smart now, but just something to keep an eye out for.

One of the methods I sometimes use to reduce log hogs is to use a dedicated thread for writing log statements to file. This thread uses a std::vector or queue. When vector.size() > 8, then dump it to the file(s). If you have a method of setting priority, you can then also then assign prio. This gets us into RTOS ideas. Can look into that if you need strict timings.

Workflow

Suppose sensor1 thread writes log statement.
- Sensor1 thread adds data to std::vec
Suppose sensor2 thread writes log statement
- Sensor2 thread adds data to std::vec

....

Once std::vec > 8 fire event to wake up thread
Thread wakes up, and once given CPU time, begins writing to file

This will help minimize the time spent locking mutexs as well as minimize time spent opening files. However, it is at the cost of memory. Play with the queue size to reach your desired goals.