Programming

Hi all,

I am working on a software, which was developed using C programming on unix environment. I have added certain functionality to the software.

Now, I interested in measuring time taken by new functionality (Mean value of huge amount of tests). Since new function will be part of many threads and will be running simultaneously.

I am looking for a efficient logging mechanism to log time duration for each execution, that will not reduce the performance.

I hope appending to a log file creates bottleneck.

FYI. This software is real time one and will be running for many weeks.

Thanks in advance,

Tamil

First of all I'd like to state that I'm a not an expert in C.
I use in C++ the boost::timer library which is an excellent one to do those calculations.

If you don't want to add dependencies to your project you can do the following:
when the function that you want to calculate time starts start a thread that will count time : see man 3 usleep or man 3 sleep or man 3 nanosleep.
This thread sleeps a number of time which increase every n time unit.
This thread stops counting when the other function finish the procedure and change a boolean value to true.
I think the above solution will not be really efficient but it can work.

Experts in C should have a better answer to this question.

Thanks Venam,

I feel creating a new thread for each thread in focus, would be a bad idea. I am thinking of using time() system call to measure time differences. There should not be any race conditions among the threads, in calling time().

However, once measurement is taken, there is a race condition when multiple threads trying to log. Using semaphore will in turn will create bottleneck.

I am not familiar with syslog(). Can that be useful here?

/Tamil

I didn't get your point about the bottleneck.
In the world of threads there is something called mutex.
paulbridger.com/mutexes
You can also check timer_create() .

Maybe you can start only one thread that count the time and this thread checks for the status of all the other thread and saves in an array/struct the time they are done.

Why do we need a thread to count seconds, when there are systems functions like time() ?

Mutex is also known as semaphore, using which will make threads blocking, which is a bottleneck.

/Tamil

OK, for a real-time app, whatever you do has to be FAST, and if the resources aren't available for your processing thread to do the logging, I'm assuming you'll just have to skip logging that event.

Just as importantly, whatever logging you add, the performance has to be deterministic - it takes the same overhead to do the logging for a processing thread every single time you do the logging. That number should be as small as possible, but it can't be good most every time, with an occasional long-running hang waiting for resources.

So something like Boost is probably the last thing you should be looking into using. Do you know what's going on inside the Boose libraries? And how using it will impact your real-time processing in every single case? No, you don't. If you could get the entire Boost development team and have them answer, "Tell me exactly what happens when I use this Boost functionality in every possible use case.", even the Boost developers themselves almost certainly wouldn't be able to tell you.

Using syslog() might meet your needs, but I'd measure the overhead of doing so.

If I were to roll my own, I'd probably try something like this:

1. Define a binary structure:

Code:

struct timed_event
{
    int event_id;
    time_t event_start;
    time_t event_end;
    time_t current_time;
}

2. Define event ids for all the events you want to collect data from.

3. Create a pipe of some kind - named pipe, SYS V message queue, etc.

4. For each event you time, fill in one of those structures.

5. After filling in the structure, write the binary structure to the pipe. Write using a non-blocking low-level call such as a simple write(). Do NOT use C++ functionality, for a lot of reasons. Again, this needs to be non-blocking so if whatever pipe/queue you're writing to is full, you don't wait. It also needs to be atomic - which is why YOU need to make the write() call (or whatever) directly in YOUR code.

6. Write another process that reads the binary data from the pipe (should be easy since the reader knows the size of the binary structure - read() the proper number of bytes and get a filled-in struct), translates it into a readable log message, and logs it. Or maybe you just log the raw binary data and translate it offline later depending on your space needs.

You might want to add more data to the structure.

One thing to watch out for, especially if you implement something like a simple write() to a Unix pipe: partial write()'s. For example, if your structure comes out to be 32 bytes, maybe the pipe is almost full and write() only puts 24 bytes in the pipe. You might want do so something like start each structure with a magic number int field and put something in there that hopefully can't be duplicated in any other field. Then the reading/logging process can use that magic number field to try to sync up the binary stream of data.

Another issue: make sure your processing code and your logging code use the same size for the binary structure. Compiler optimization flags can change data alignments, which can change structure sizes. So if you aggressively optimize the processing code but not the logging code, the processing code could be using a binary structure that's 48 bytes because of alignment padding while the logging process could be using a non-padded structure that's 32 bytes.

The idea of using a pipe is pretty cool. I never taught about that. Next time I do something I'll take that into consideration. It's going to be way faster But isn't it going to be a little harsh on I/O, I mean it depends on the interval the reader will loop in the pipe.
Anyway, you're answer is cool.