Logging restructure

[lucasvickers]

Related to #1107

Tasks completed in this rewrite

• LogManager's enable/disable routines were removed
• LogManager's interface was standardized with addLogger and removeLogger, etc
• LoggerMulti was removed and replaced with an internal vector of Loggers
• DebugTest was rewritten to be an easier to use test case
• Logger example updated
• Restructured locking so that there is no risk of crash, and wrote test case to confirm this

Performance

The good news is we now prevent a crash when adding and removing loggers from threads. I confirmed the crash exists in the main branch, and confirmed the crash is fixed in this PR.

The bad news is that, in order to stop this crash, we had to move the lock mutex to the lowest level write() routine. This really starts to show when you are logging from multiple threads.

For tests below, each thread logged 1 million times to a single log file.

Main branch (localized locks, not thread safe)

|debug  | void DebugTestApp::testPerformance()[244] Single logging took 0.01393 ms / log.
|debug  | void DebugTestApp::testPerformance()[248] 2 threads logging took 0.02628 ms / log.
|debug  | void DebugTestApp::testPerformance()[252] 3 threads logging took 0.06138 ms / log.

This branch (lock in write(), thread safe)

|debug  | void DebugTestApp::testPerformance()[280] Single logging took 0.01441 ms / log.
|debug  | void DebugTestApp::testPerformance()[284] 2 threads logging took 0.06125 ms / log.
|debug  | void DebugTestApp::testPerformance()[288] 3 threads logging took 0.10274 ms / log.

This is, of course, probably worse case since my test case has multiple threads logging from within loops. I think we'll be able to improve this considerably when we can introduce shared_locks into the code base.

[lucasvickers]

The logic I was using to tally time / log was incorrect. I was doing:

time_per_log = ( run1.duration + run2.duration ) / ( run1.num_logs + run2.num_logs )

Which is incorrect because the timers were running in a concurrent manner. If I switch to using the max time any of the loggers took, things are a bit more reasonable:

time_per_log = std::max( run1.duration, run2.duration ) / ( run1.num_logs + run2.num_logs )

Produces these results:

Main branch (localized locks, not thread safe)

Single logging took 0.01446 ms / log.
2 threads logging took 0.01303 ms / log.
3 threads logging took 0.02161 ms / log.

This branch (lock in write(), thread safe)

Single logging took 0.01497 ms / log.
2 threads logging took 0.03369 ms / log.
3 threads logging took 0.03494 ms / log.

[richardeakin]

Since we're switching to LoggerRef's before, might as well return a std::vector<LoggerRef> here too (can be done with std::dynamic_pointer_cast<LoggerT>() in impl).

[lucasvickers]

I struggled with that a little bit. I really wanted to return a std::vector<shared_ptr<LoggerT>>, but returning a shared_ptr of a different template is problematic.

Part of me thought it was strange to return std::vector<LoggerRef> since you requested LoggerT, but I think it's more consistent than the raw pointers, and makes more sense given the rest of the interface.

I'll make that change.

Thanks for the review!

[richardeakin]

Despite my suggestion above to return vector (wasn't thinking to deeply), what if we did it like this? That way if the type of logger you're requesting has special parameters you have the right type in the vector and can act on them directly, without needing to type cast again.

If this is agreeable, then I'll go ahead and merge the PR along with that change.

[lucasvickers]

Got it, I didn't fully understand the workings of std::dynamic_pointer_cast<LoggerT>() when you first mentioned it. This is definitely the ideal solution.

[richardeakin]

Other than above comment, looks good to me. Thanks for getting through all of this!