athos athos - 29 days ago 4
C++ Question

What's the good practice of logging in multithreading?

I'm working on a multithreading C++ code, where it could be run either as an exe or an XLL Add-on for Excel, in either case, it will be run in multiple threads.

What's the good practice of doing logging?

There's a similiar thread on C# programs Logging in multithreading environment and testing , suggesting:


Wrap your logging instance in a thread-safe singleton. Don't use
double check locking! Also, it probably makes sense to use a logging
library like log4net or Enterprise Library 5.


I wonder if this still applies, to C++ programs?

Some says Singleton is evil, but seems loggins is a valid case for this pattern?

What are the good libraries of logging that will take care of the stream buffer issue, so by log files it's enough to reconstruct the scenarios trustfully?

Using a Singleton to do logging from multiple threads, would that bring down the performance? Would mutex/lock has to be used?

I'm working on Windows environments.

Answer

how do you do logging from multithread without using Singleton?

I find this question curious.

The key parts of accessing my ram-based-log (round-robin style) are:


  • I often create the log in a constructor of some class instance that is central to what is going on. Once created, any thread has access to the log through the name. In the following case, "M_dtbLog".

    if (0 == M_dtbLog) { M_dtbLog = new DTB::Log(1*60*1000, 1024*256*2); dtbAssert(0 != M_dtbLog); }

update 10/06 10:45 - forgot to mention this dtblog was created prior to 2011, so no std::thread. The threads were Posix threads.

  • In any code where you wish to access the log:

1) pull in the code

#include "../../bag/src/dtb_log.hh"

2) back then, I added a macro for convenience (if you must). for illustration:

//     several years ago (in a much more c-style approach),
#define  DBG  if(M_dtbLog)  (void)M_dtbLog->enq

2b) back then I also added:

// the compiler checks many more things for printf does
// use this simple #define temporarily to test your DBG's
#if (0)
#undef  DBG
#define DBG if(M_dtbLog) (void)::printf
#endif

3) "DBG" as a code injector is now available, and each invocation confirms that the que is available. Example:

void LMBM::Node:init(void)
{
    if(m_next)
       m_next->init(); 
    //...

    DBG("m_semIn %2d = %p\n", m_nodeId, m_semIn);  // <<<<<<<<

update 10/06 10:45 - forgot to mention these Node's each have their own thread and input semaphore, thus the static M_dtbLog. The default settings create 10 Nodes (and 10 threads and semaphores). Each of these Node's have direct access to the static M_dtbLog.

4) More recently, I use what I consider a simpler C++ approach ... for discussion some other time.

5) Some times simpler is better, especially for unit test. Here I sometimes use std::stringstream (which is not thread safe). Just have to remember to limit how much gets in to the code by the end of the task.

6) For production, when Log not needed, I simply do not instantiate the log if not needed (and usually is not). But I leave the DBG statements in the code for when debug is needed.


In any file / class in which you want to use this log, regardless of which thread, simply add the #include, and the #define and however many DBG's you want.

There is currently no support to measure performance issues. It is writing to ram, and for my purposes was fast enough.


The exclusive access control (for multiple thread access) is in the dtb_log implementation.

In my Linux version of this code, I use a Posix Process Semaphore in local mode (i.e. not process shared, not a mutex nor std::mutex).

The general work of building a string and pre-pending the time and thread id, etc, is done in automatic memory (commonly called stack) so that the threads (which each have there own stack) can not interfere with each other.

The string in automatic memory is then enqueued into the round robin memory buffer. (using the private method DTB::Log::enqRrq()) The dtb_log can be used by any thread. The critical section is used in the typical way. 'enqRrq' is about 12 lines of code, and simply shuffles characters from one buff to the round robin buff.

update 10/6 - code snippet -


Following the code to inject time stamp, thread id, and message etc

// buff 1 now ready to install
enqRrq(buff1, retVal); // install text into round-robin queue

Next, transfer the new log entry into round-robin-buffer

void DTB::Log::enqRrq(const char* buff, size_t sz)
{
   DTB::ProcessSemCritSect critSect(m_mutex);

   dtbAssert(0 == m_rrBuff[m_nextIn]); // code broken

   // move char from buff into m_rrBuff
   {
      {
         bmpNextIn(); // leave one null between records

         for (size_t i = 0; i < sz; i += 1) // insert sz chars of buff
         {
            m_rrBuff[m_nextIn] = buff[i];
            bmpNextIn();                     // m_rrBuff is round-robin
         }
         m_rrBuff[m_nextIn] = 0; // insert null char at end of m_rrBuff
      }
   }

   uint32_t lni = m_nextIn + 1; // lni starts after null we just inserted
   if (lni >= m_rrBuffSize) lni = 0; // round-robin

   // stomp 0's to end of oldest message
   {
      while (0 != m_rrBuff[lni]) // while in middle of oldest message
      {
         m_rrBuff[lni++] = 0; // stomp on oldest message (to its end)
         if (lni >= m_rrBuffSize) lni = 0; // round-robin
      }
   }
}

I happened to find several examples of this kind of log output. Sorry about the line length, the biggest is 160 some chars.

Note that this is the last 5 seconds of the log I found.

  • retrieve_shelf_inventory() is apparently once per second. (usually repetitive log entries are suppressed, after they wrap around and stomp on what you wanted to see, by the user, not by the log)

  • the last second show an update to a number of leds and office alarms.

  • pem_cm, a different code layer, [a block of threads], is sending the commands which triggered these log entries.

  • This system has around 1000 threads running.
    And a 100 or so developers herding the code.

    05:27:41 0x010117 262.816 mcu_t::retrieve_shelf_inventory() size=91 05:27:41 0x010117 262.816 --mcu:sdd_io2(ant=210 (SDD_GET_SHELF_PHY_INV) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 519, (1109792 us)

    05:27:42 0x010117 263.928 mcu_t::retrieve_shelf_inventory() size=91 05:27:42 0x010117 263.928 --mcu:sdd_io2(ant=210 (SDD_GET_SHELF_PHY_INV) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 520, (1111872 us)

    05:27:43 0x010117 265.040 mcu_t::retrieve_shelf_inventory() size=91 05:27:43 0x010117 265.040 --mcu:sdd_io2(ant=210 (SDD_GET_SHELF_PHY_INV) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 521, (1111873 us)

    05:27:44 0x010117 266.152 mcu_t::retrieve_shelf_inventory() size=91 05:27:44 0x010117 266.152 --mcu:sdd_io2(ant=210 (SDD_GET_SHELF_PHY_INV) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 522, (1111883 us)

    05:27:44 0x010117 266.152 mcu_t::sdd_control_led(indx=13, color=1, action=1) = 0 05:27:44 0x010117 266.152 --mcu:sdd_io2(ant=20 (SDD_LED_CONTROL) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 523, (48 us)

    05:27:44 0x010117 266.152 mcu_t::sdd_control_led(indx=14, color=1, action=1) = 0 05:27:44 0x010117 266.152 --mcu:sdd_io2(ant=20 (SDD_LED_CONTROL) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 524, (19 us)

    05:27:44 0x010117 266.152 mcu_t::sdd_control_led(indx=15, color=2, action=1) = 0 05:27:44 0x010117 266.152 --mcu:sdd_io2(ant=20 (SDD_LED_CONTROL) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 525, (19 us)

    05:27:44 0x010117 266.152 mcu_t::sdd_control_led(indx=12, color=0, action=0) = 0 05:27:44 0x010117 266.152 --mcu:sdd_io2(ant=20 (SDD_LED_CONTROL) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 526, (21 us)

    05:27:44 0x010117 266.152 pci2:blsr:office_alarms:change() aud_CR.vis_CR.aud_MJ.vis_MJ.aud_MN.vis_MN 0000003f 05:27:44 0x010117 266.152 --mcu:sdd_io2(ant=35 (SDD_SET_ALARM) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 527, (26 us)

    05:27:44 0x010117 266.200 mcu_t::sdd_control_led(indx=13, color=1, action=1) = 0 05:27:44 0x010117 266.200 --mcu:sdd_io2(ant=20 (SDD_LED_CONTROL) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 528, (49 us)

    05:27:44 0x010117 266.200 mcu_t::sdd_control_led(indx=14, color=1, action=1) = 0 05:27:44 0x010117 266.200 --mcu:sdd_io2(ant=20 (SDD_LED_CONTROL) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 529, (20 us)

    05:27:44 0x010117 266.200 mcu_t::sdd_control_led(indx=15, color=2, action=0) = 0 05:27:44 0x010117 266.200 --mcu:sdd_io2(ant=20 (SDD_LED_CONTROL) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 530, (19 us)

    05:27:44 0x010117 266.200 mcu_t::sdd_control_led(indx=12, color=0, action=0) = 0 05:27:44 0x010117 266.200 --mcu:sdd_io2(ant=20 (SDD_LED_CONTROL) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 531, (20 us)

    05:27:44 0x010117 266.200 pci2:blsr:office_alarms:change() aud_CR.vis_CR.aud_MJ.vis_MJ.aud_mn.vis_mn 0000001b 05:27:44 0x010117 266.200 --mcu:sdd_io2(ant=35 (SDD_SET_ALARM) sender=0001020e (pem_cm), sec_id=4088C04080000000) eqType=35 major=1, 532, (25 us)

    513 lines, 55287 bytes (m_size=65536) show, 55287


update 11/04

Some says Singleton is evil, but seems loggins is a valid case for this pattern?

I have used several singleton's, but ultimately found singleton's to add no value. It does has a memorable name, so it is easier to remember, so perhaps is more readable to others, and so you see more about it than the other patterns (I think). But even when I use the ideas for the access and control of a hw of which there is only one ... imho the singleton did not simplify or speed up anything.

I have not seen code where the singleton 'provides' thread safety. I believe the pattern book (which published the pattern) has a statement saying, essentially, none of the patterns are thread safe. (But it has been a while since I looked.) Perhaps a C# singleton is something different.

When the author you quoted said, "Wrap your logging instance in a thread-safe singleton.", I believe he was suggesting no more than a) to use a singleton, and b) add thread safety to the singleton. The singleton does not provide thread safety, and thread safety does not provide singleton features.


update 11/04

Using a Singleton to do logging from multiple threads, would that bring down the performance? Would mutex/lock has to be used?

As I said above, I have not seen the idea that a singleton provides thread safety. imho it does not.

Performance always takes a hit with synchronization of multiple threads accessing a shared resource. The code above creates a critical section using a POSIX semaphore. That implementation looks something like:

DTB::ProcessSemCritSect::ProcessSemCritSect(ProcessSemaphore*  a_processSem) :
   m_processSem (a_processSem)
{
   assert(nullptr != m_processSem);
   int wait_status = m_processSem->wait();  // block if already locked
   assert(DTB::ProcessSemaphore::SUCCESS == wait_status);
}


DTB::ProcessSemCritSect::~ProcessSemCritSect(void)
{
   assert(nullptr != m_processSem);
   int post_status = m_processSem->post(); // un-block any waiting thread
   assert(DTB::ProcessSemaphore::SUCCESS == post_status);
   m_processSem = 0;
}

My benchmarks show that the two step wait() and post() is very quick, on my system < 25 ns.

If your threads attempting to use the log have minimal collisions, that would be the lower bound of semaphore overhead (on my system).

Threads (in different cores, perhaps) that collide in this style of critical section can take as much as 12,000 ns for a context switch on my system. Your performance will vary.

Comments