none
High Speed Lightweight Microsecond Message Logging RRS feed

  • Question

  • Hello,

    I am trying to implement C/C++ message logging in my real-time application. I need to be able to log a message in under a microsecond. I have seen this done with third-party (expensive) software that I use but I was unable to replicate it myself. Currently, what I have done was implement a logger that is capable of INFO, WARNING and ERROR messages. I basically copy the message to a buffer which I then use a background thread to handle and print to a log file. In total a message takes about 20 microseconds between function calls and strcpy which is way too long. I need a way to perform this in a microsecond or less. Does anyone have any ideas how this may be possible?

    Thanks!

    Sunday, November 3, 2013 10:17 PM

Answers

  • It sounds like the main requirement is to create some logging that does not affect your main processing routine much when you enable various logging levels.  You don't actually care that the message is logged to a file within 10 us but more that it does not block the logging routine for very long.

    If your logging levels are not fast enough to overload the secondary logging routines over a period of time, you can always just log the pointers to the strings into a ring buffer and have your secondary thread process the data out of the ring buffers.  You can use the InterlockedExchangePointer/InterlockedCompareExchangePointer routines for synchronization and can also report the number of dropped messages via InterlockedExchange and InterlockedIncrement routines.

    You also need to ensure that your log processing thread runs below the priority of the code you do not want it to interrupt / delay, otherwise it could still impact the operation of the main processing threads.

    This does make a few assumptions:

    1. You can allocate a ring buffer large enough for all the messages you require.
    2. It is allowable to drop messages as long as it is detectable that one was dropped.
    3. There is enough free processor time below your main execution threads to get through the messages created by the system.

    If you are using sprintf or other routines this will start to add additional impact to the logging depending on what is happening.  I would avoid the use of those functions in the main processing thread or use pointers to structures so that strings can be processed / generated at a later date.

    As per your later question about putting function calls on a queue, you can always do that.  You could actually have a pointer to a structure that defines how you want your messages formatted and place them on a queue to be dealt with later.  It all depends on how much spare processing power you have and how much you can delay your calling routine for.  Using synchronization objects such as Mutexes or Critical Sections could block your main processing thread for a longer period than an InterlockedExchange etc... it all really depends on what your requirements and goals are for your system.

    Simple solution is to have a queue protected by a lock that is accessed by both your main processing code and the log processing code.  One acquires the lock and queues the message and releases the lock while the other acquires the lock, dequeues the message and releases the lock.

    If the simple solution works then I would just do that.  It does however leave the main processing thread locked for a longer period of time but does not require as much work to implement.  Since you cannot use UINT32 code values you can always use static strings and just pass the pointers to those around as well.

    You also need to handle the case where the main processing thread overloads the logging thread to ensure that the queue doesn't grow until you run out of memory and ensure the thread priority is low enough not to affect the main processing thread.

    Good Luck,

    Brad

    • Marked as answer by elk84 Tuesday, November 5, 2013 4:58 PM
    Monday, November 4, 2013 11:01 PM

All replies

  • 20 us is pretty fast already ....

    I'm thinking the strycpy is your bottleneck here, i would suggest you log an error number instead of an error message and have your secondary thread decode & allocate room for the  error message.

    So try to avoid the strcpy function :)
    • Edited by Kevin Deckx Monday, November 4, 2013 9:35 AM
    Monday, November 4, 2013 9:32 AM
  • I think the answer is no unless you've got a pretty hot processor and fast I/O (although you don't say how often you log messages).

    Have you tried writing just a 32-bit word for each message rather than actual text? That would give you 2 billion possible "messages" and should be pretty fast to copy (maybe as little as 1 instruction). You haven't said what you plan to do with this data or justified why a string is necessary. I think you want to be outside the box in your thinking...

    Paul T.

    Monday, November 4, 2013 3:16 PM
  • Thanks. I am trying to log all types of messages. So it has to be any given string that I enter whether it is just info, debug messages or errors. You did get me thinking though with the whole decoding messages this to avoid strcpy. I will see if I can come up with anything :)
    Monday, November 4, 2013 4:43 PM
  • I plan on taking this data and having a background thread print it to a log file that I can use for debugging or anything else I need. I guess that is why I need a string. I want to be able to put any random message. The message does not have to appear in real-time in the file, matter of fact my goal is to have the main instruction sequence not block on the logging call that I make from my code. The messages can appear much later (that is why I have the buffer and a secondary worker thread to output the messages to a file). My processor is below 1 GHz  and that is kind of what I am limited to now. I have to see if there is a way to get rid of the stcpy as Kevin suggested. Would it be faster if I used inline functions as opposed to function calls?

    Sorry to ramble, but I can't find this anywhere. Is there any way to assign certain function calls to a separate low priority thread so that when the main thread is executing instructions it can save certain instructions on a queue (the logging call) (which would be assigned to a low priority thread) and continue execution? When there is available clock left the low priority thread can execute the function calls placed in the queue. I think what I'm trying to say is can I place specific function calls in a queue/linked list that can be executed by a lower priority thread instead of being executed by the high priority thread that first encounters it?

    Thanks


    • Edited by elk84 Monday, November 4, 2013 5:03 PM
    Monday, November 4, 2013 4:46 PM
  • It sounds like the main requirement is to create some logging that does not affect your main processing routine much when you enable various logging levels.  You don't actually care that the message is logged to a file within 10 us but more that it does not block the logging routine for very long.

    If your logging levels are not fast enough to overload the secondary logging routines over a period of time, you can always just log the pointers to the strings into a ring buffer and have your secondary thread process the data out of the ring buffers.  You can use the InterlockedExchangePointer/InterlockedCompareExchangePointer routines for synchronization and can also report the number of dropped messages via InterlockedExchange and InterlockedIncrement routines.

    You also need to ensure that your log processing thread runs below the priority of the code you do not want it to interrupt / delay, otherwise it could still impact the operation of the main processing threads.

    This does make a few assumptions:

    1. You can allocate a ring buffer large enough for all the messages you require.
    2. It is allowable to drop messages as long as it is detectable that one was dropped.
    3. There is enough free processor time below your main execution threads to get through the messages created by the system.

    If you are using sprintf or other routines this will start to add additional impact to the logging depending on what is happening.  I would avoid the use of those functions in the main processing thread or use pointers to structures so that strings can be processed / generated at a later date.

    As per your later question about putting function calls on a queue, you can always do that.  You could actually have a pointer to a structure that defines how you want your messages formatted and place them on a queue to be dealt with later.  It all depends on how much spare processing power you have and how much you can delay your calling routine for.  Using synchronization objects such as Mutexes or Critical Sections could block your main processing thread for a longer period than an InterlockedExchange etc... it all really depends on what your requirements and goals are for your system.

    Simple solution is to have a queue protected by a lock that is accessed by both your main processing code and the log processing code.  One acquires the lock and queues the message and releases the lock while the other acquires the lock, dequeues the message and releases the lock.

    If the simple solution works then I would just do that.  It does however leave the main processing thread locked for a longer period of time but does not require as much work to implement.  Since you cannot use UINT32 code values you can always use static strings and just pass the pointers to those around as well.

    You also need to handle the case where the main processing thread overloads the logging thread to ensure that the queue doesn't grow until you run out of memory and ensure the thread priority is low enough not to affect the main processing thread.

    Good Luck,

    Brad

    • Marked as answer by elk84 Tuesday, November 5, 2013 4:58 PM
    Monday, November 4, 2013 11:01 PM
  • Bradley, 

    I think you have pointed me in the right direction. I will try out your suggestions and see how that works out for me.

    Thanks!

    Tuesday, November 5, 2013 4:59 PM
  • Brad,

    In your post you said "you can always just log the pointers to the strings into a ring buffer and have your secondary thread process the data out of the ring buffers" . I am a little confused. And excuse my ignorance because I am a bit new to this. When I log a message as follows: MYLOG("This is a message"), the first thing that must be done in order to save that message is perform a strcpy or memcpy of that string into a buffer, correct? From what you say it seems that you are saying to log the pointer to the string in a buffer. I do not understand how this is done. If you dont initially copy the actually string to a buffer what pointer can you store? Also, how will the message persist to later work on it with the background thread. It is mainly that stcpy that is consuming all my time. I do not believe that the actual sting ("This is a message") has a pointer unless I first store it in a buffer, unless I am wrong??... Can you please clarify this for me?

    Thank you!

    Wednesday, November 6, 2013 5:35 PM
  • So, in the case of MYLOG("This is a message") you are actually passing a pointer to a string into MYLOG.  Since the string is a constant, it will just work.

    But, if you allocate a string buffer and then create a dynamic message, then somewhere you will need to manage those allocations.   It might make sense to request that the logger allocate and manage the buffer.  That is when the logger finishes outputting, it can free the buffer.   I would have the logger allocate a big enough chunk of memory when it starts and then had out slices as needed.


    Bruce Eitman (eMVP)
    Senior Engineer
    Bruce.Eitman AT Eurotech DOT com
    My BLOG http://geekswithblogs.net/bruceeitman

    Eurotech Inc.
    www.Eurotech.com

    Wednesday, November 6, 2013 6:34 PM
    Moderator