Dear boosters, Worked some more on the logging library, and here's what's new: - added ***documentation*** - added samples - made static library (improved compilation times) - added efficient thread-safe logger, which does the logging on a dedicated thread (in order to be as fast as possible, it caches multiple log messages - which could be coming from multiple threads, and has a dedicated thread, which once at X milliseconds, writes them) Get it from: http://groups.yahoo.com/group/boost/files/logging.zip or http://www.torjo.com/code/logging.zip Looking forward to your feedback. Best, John -- John Torjo Freelancer -- john@torjo.com -- http://www.torjo.com/logview/ - viewing/filtering logs is just too easy!
John Torjo wrote:
Dear boosters,
Worked some more on the logging library, and here's what's new:
- added ***documentation*** - added samples - made static library (improved compilation times) - added efficient thread-safe logger, which does the logging on a dedicated thread
why do you route the log to a different thread instead of writing it directly ? On the one hand you provide macros to be able to optimize the logger code away if it is not desired, on the other hand you accept a full context switch (and mutex lock and...) for each single message ! May be, if you want to be fancy and fashionable, you could put this kind of 'strategy' into a trait... Regards, Stefan
Stefan Seefeld wrote:
John Torjo wrote:
Dear boosters,
Worked some more on the logging library, and here's what's new:
- added ***documentation*** - added samples - made static library (improved compilation times) - added efficient thread-safe logger, which does the logging on a dedicated thread
why do you route the log to a different thread instead of writing it directly ? On the one hand you provide macros to be able to optimize the logger code away if it is not desired, on the other hand you accept a full context switch (and mutex lock and...) for each single message !
Note that this (the efficient thread-safe logger) is just one of the possible loggers that come with the library - see the documentation. Note: when allowing to optimize away logs (note: not loggers!), it's a whole different story. A log can end up (if enabled) to call multiple functions - loggers and/or modifier functions. One of the loggers is the thread-safe logger/ on a dedicated thread. Take a look at multiple_threads sample and maybe you'll understand better. Please let me know if there are any more issues. Thanks.
May be, if you want to be fancy and fashionable, you could put this kind of 'strategy' into a trait...
Actually, it is a 'strategy' ;) see above. Best, John -- John Torjo Freelancer -- john@torjo.com -- http://www.torjo.com/logview/ - viewing/filtering logs is just too easy!
Stefan Seefeld wrote:
John Torjo wrote:
Dear boosters,
Worked some more on the logging library, and here's what's new:
- added ***documentation*** - added samples - made static library (improved compilation times) - added efficient thread-safe logger, which does the logging on a dedicated thread
why do you route the log to a different thread instead of writing it directly ? On the one hand you provide macros to be able to optimize the logger code away if it is not desired, on the other hand you accept a full context switch (and mutex lock and...) for each single message !
p.s. the 'logger' is the equivalent of log4j's Appender concept. Best, John -- John Torjo Freelancer -- john@torjo.com -- http://www.torjo.com/logview/ - viewing/filtering logs is just too easy!
John Torjo <john.lists <at> torjo.com> writes:
Dear boosters,
Worked some more on the logging library
Hi John, I really like your idea of simplifying the actual logging by not directly modeling the hierarchy. The if/else macro to only conditionally evaluate the arguments is also an essential feature that your design includes. However, I think one significant feature is missing, and some aspects of the design and implementation don't seem to suit at least one use (mine of course :-). However, logging seems to be one of those things that everyone at least thinks they have special requirements for, and maybe I'm missing how to apply the library effectively. I think a *small* library is desirable, and any usage dependant issues should be dealt with by making the library extensible/configurable, not larger. The specific features I'm concerned about... Support for dynamic log creation: Some form of dynamic log creation would be very useful. Consider a networked system of some kind in which the application instantiates an object with a runtime determined name/identifier (such as the address/name of the peer/client/server/node/service/entity). So to turn on detailed logging of information from just one such entity, named "bob" one would (via an appropriate runtime UI) enable_logs("app.trace.client.bob"). The object that represents a connection with bob needs to hold some scoped_log object. The actual writing to the log would need to be different for a dynamic vs static log - a macro taking the scoped_log rather than the log_name. Possible bug in handling of early logging: Isn't the effectiveness of the facility to buffer data written prior to defining the log dependent on the order of instantiation of the static objects that log vs the instantiation of the logid's themselves? If any logging is attempted after the logid name is registered but before any log_funcs have been added the messages will be lost. Or am I missing something here? Log enable/disable/add/remove performance/scalability: The separation of logging and the implied hierarchy has made for a relatively expensive update process when the logging settings are changed. As you point out in the docs, this shouldn't be a big issue, as they don't change often. However, I am somewhat disturbed by what looks like an O(n^2) cost for log enable/disable. Maybe this is just an implementation detail that can be optimised relatively easily (couldn't the raw enabled array be implemented as a map keyed by prefix?). One could also imagine building a more elaborate, data structure to represent the hierarchy if this level of optimisation was really needed (I'm not suggesting that you should do this). Multi-threading performance: The caching of the loglib_info on a per thread basis seems to have the potential to produce some large latencies in the operation of a heavily-multi- threaded application whenever logging settings are changed. The loglib_info is certainly not a lightweight object and is copied between threads (while holding a lock on the master/global instance). In addition to the copying, just the storage used per thread due to the duplication of data may be significant for an application with a lot of lightweight threads. I'm also not convinced that your lock-free counter is strictly portable, but in practice I don't know of a system it wouldn't work well enough on. Regardless, I think it is solving the wrong problem (at least for systems with any form of real-time constraints) in that the whole design seems to offer low average latency, but with a worst-case latency that depends on and scales poorly with the size of the system (measured by number of logs and number of threads). Finer-grained locking would seem preferable. A version that explicitly forgoes thread safety would also seem useful - and not just for single threaded apps. It seems like a lot of the implementation is tied up in the thread support area - it would be nice to separate the threading issues more cleanly. Efficient long/complex log entries:
From the docs: // to avoid this: // (which could be very time-consuming - acquiring the log one million times) for (int idx = 0; idx < 1000000; ++idx) BOOST_LOG(app) << "message at idx " << idx << std::endl;
Not only time consuming - potentially, only some lines of output would be generated (if log settings changed) and other log output could be interleaved between lines of this message. // you will want to do this: // (very efficient) if (BOOST_IS_LOG_ENABLED(app)) { std::ostringstream out; for (int idx = 0; idx < 1000000; ++idx) out << "message at idx " << idx << std::endl; BOOST_LOG(app) << out.str(); } Much better - but then why can't I do this: if (MAKE_LOG(log, app)) { for (int idx = 0; idx < 1000000; ++idx) log << "message at idx " << idx << std::endl; } Which should be more efficient again? Regards Darryl.
Hi Daryl,
Hi John, I really like your idea of simplifying the actual logging by not directly
Thanks.
Support for dynamic log creation:
Some form of dynamic log creation would be very useful. Consider a networked system of some kind in which the application instantiates an object with a runtime determined name/identifier (such as the address/name of the peer/client/server/node/service/entity). So to turn on detailed logging of information from just one such entity, named "bob" one would (via an appropriate runtime UI) enable_logs("app.trace.client.bob"). The object that represents a connection with bob needs to hold some scoped_log object. The actual writing to the log would need to be different for a dynamic vs static log - a macro taking the scoped_log rather than the log_name.
I'm sorry - I know you gave an example, but did not understand it too well. Could you please explain further - eventually in a private email?
Possible bug in handling of early logging:
Isn't the effectiveness of the facility to buffer data written prior to defining the log dependent on the order of instantiation of the static objects that log vs the instantiation of the logid's themselves? If any logging is attempted after the logid name is registered but before any log_funcs have been added the messages will be lost. Or am I missing something here?
You're right about this. I have to think of a way to fix it - do you have any idea?
Log enable/disable/add/remove performance/scalability:
The separation of logging and the implied hierarchy has made for a relatively expensive update process when the logging settings are changed. As you point out in the docs, this shouldn't be a big issue, as they don't change often. However, I am somewhat disturbed by what looks like an O(n^2) cost for log
yes, but n will be very small - 10-20 at the most IMO. Anyway (see below), I'll allow you to disallow latency.
enable/disable. Maybe this is just an implementation detail that can be optimised relatively easily (couldn't the raw enabled array be implemented as a map keyed by prefix?). One could also imagine building a more elaborate, data structure to represent the hierarchy if this level of optimisation was really needed (I'm not suggesting that you should do this).
I would really need to think abou this. The thing is that I assume a regular app won't have more than 10-20 logs (note: not loggers = Appenders, a la log4j). Even for about 100 logs, this should be extremely fast.
Multi-threading performance:
The caching of the loglib_info on a per thread basis seems to have the potential to produce some large latencies in the operation of a heavily-multi- threaded application whenever logging settings are changed. The loglib_info is certainly not a lightweight object and is copied between threads (while holding a lock on the master/global instance). In addition to the copying, just the storage used per thread due to the duplication of data may be significant for an application with a lot of lightweight threads.
I understand what you mean - do you have an example of an application, where you would actually have a lot short periods, in which log settings would get changed often? (because I fail to see such a scenario - and only in this scenario the problems you outlined happen).
I'm also not convinced that your lock-free counter is strictly portable, but in practice I don't know of a system it wouldn't work well enough on. Regardless, I think it is solving the wrong problem (at least for systems with any form of real-time constraints) in that the whole design seems to offer low average latency, but with a worst-case latency that depends on and scales poorly with the size of the system (measured by number of logs and number of threads). Finer-grained locking would seem preferable. A version that explicitly forgoes thread safety would also seem useful - and not just for single threaded apps. It seems like a lot of the implementation is tied up in the thread support area - it would be nice to separate the threading issues more cleanly.
You're totally right. I think I'll provide for the following options: - no thread-safety - thread safety with latency - thread-safety (with the additional note that I know this will me very time-consuming compared to the above). And I will create a test - to see the overhead of each (I really have a hunch that the third option will be about 5-10 times slower).
// you will want to do this: // (very efficient) if (BOOST_IS_LOG_ENABLED(app)) { std::ostringstream out; for (int idx = 0; idx < 1000000; ++idx) out << "message at idx " << idx << std::endl; BOOST_LOG(app) << out.str(); }
Much better - but then why can't I do this:
if (MAKE_LOG(log, app)) { for (int idx = 0; idx < 1000000; ++idx) log << "message at idx " << idx << std::endl; }
Which should be more efficient again?
I guess both would be about the same. It does sound interesting - anyone wants to second this? If so, I'll do it - it's easy. That said, busy times have struck again :( For the next couple of months I'll be very busy - just started work on a new project. So, I'll probably have time to incorporate some more changes in 2-4 weeks. Best, John -- John Torjo Freelancer -- john@torjo.com -- http://www.torjo.com/logview/ - viewing/filtering logs is just too easy!
participants (3)
-
Darryl Green -
John Torjo -
Stefan Seefeld