Matthias Vallentin wrote:

On Mon, Jun 09, 2008 at 01:46:51PM +0200, Mojmir Svoboda wrote:

...

there is a dark side of my approach: the user may not pay at the runtime, but certainly he'll suffer at compile-time. what you gain is control of the types passed to logging framework (how many times we all messed a printf's format and arguments? :)

<0.02> I would not consider this a dark side. Enduring long compile cycles seems tenable when optimizing for runtime-performance. Your design sounds appealing to me. I am exactly looking for a small and efficient logging library that provides basic functionality (levels, filters, facilities, filters and alike) and has been designed from scratch to be used in multi-threaded programs.

At this time, my library already does this - you can certainly specify whether you want thread-safety or not, and the lib is certainly efficient. Best, John -- http://John.Torjo.com -- C++ expert http://blog.torjo.com ... call me only if you want things done right

Mojmir Svoboda wrote:

hello, John :)

...

At this time, my library already does this - you can certainly specify

going quickly through your code i definitly must admit you are farer than i am. there's no apparent reason start new thingy. for example i'd probably never mess with internationalization ;)

It's your call ;) I think I've done about 6 other versions until I got to this one - which I will change as well ;)

...

whether you want thread-safety or not, and the lib is certainly efficient.

can you give me some hints in the right direction, please? i mean some general advices "use this if you want be small, this if you want be fast, avoid that at all costs etc". i'd like both, of course.

Well, this is quite hard: - the locking strategy - make it a policy, which you can change later; this will also make it easy for you to test, using a single threaded app - why do you apply filters to the logged text? A filter should be something able to say "yes" or "no" without looking at the text. First of all, if the filter says "no", you shouldn't need to do any processing of the text. - I believe having a compile time vector for formatting the output is a mistake: typedef vector, sep, fn, sep, msg>::type pipe_mania; The user should be able to specify that at runtime - what if he wants to configure the log at runtime? Other than that, I need to see more docs about what you're going to implement.

i started with your sample and got it down to 12kB (assume 5k is C helloworld). that's not quite bad, i suppose, but still twice as it should be ;-P

Oh well, I don't care that much about size nowadays.

there are still 9 allocation - there is some vector at initialization time, but i'd have to read the sources more carefully. perhaps you could point out these places where expensive and other interesting things pop up.

minor issues i found: - logger.hpp:248 when cache is off, source cannot be compiled (missing ifdef probably)

Ouch. My bad - anyway, the caching will be gone in v3 of the lib ;)

- pthreads are detected incorrecty. even in singlethr model mutex is required.

What do you mean?

- it would be nice if it can compile with -fno-rtti -fno-exceptions (op_equal and shared_ptr) see *)

*) note that it would be nice that all boost code that does not really need rtti could switch it off

Yes I agree - I want to add this in the future ;) Best, John -- http://John.Torjo.com -- C++ expert http://blog.torjo.com ... call me only if you want things done right

Mojmir Svoboda wrote:

...

The user should be able to specify that at runtime - what if he wants to configure the log at runtime?

no he will _NOT_, that is the beauty ;)) if he still do, let him use log4jpp. according to my (i admit that short perhaps) experiences, this is very rarely needed. you can either modify source and recompile or use log4j++ like i said.

My experience is with large products with many subsystems, worked on by many developers over the course of years. The most effective logging machinery: - Allows you to turn on logging at runtime, so your support person in e-mail dialog with an irritated user can say, "Okay, please set this configuration switch and try that again." Some bugs can only be reproduced on a user's machine. On the other hand, you don't want to generate large log files for every user, every run. - Allows you to be selective about what logging output is produced, because if you turn on EVERYTHING, your user has trouble even storing and mailing you the resulting file -- never mind your problems trying to discover what might be relevant. (This is the result of accumulating helpful logging output in many interacting subsystems over the course of years.) - Has trivial runtime cost for a suppressed log message. In particular, no string allocation or formatting is performed. Ideally, the amortized runtime cost is nothing more than examining a static bool and a jump. There are probably people for whom compile-time controls suffice. But such a library wouldn't be useful to our developers.

* Patrick Loney [2008-06-12 15:48:42 +0100]:

Nat Goodspeed Wrote:

...

- Allows you to turn on logging at runtime

...

- Allows you to be selective about what logging output is produced

...

- Has trivial runtime cost for a suppressed log message.

Just to back this up Mojmir, these are pretty much essential for a useful logging system really. As a developer I can step through my code to find out what's happening. Logging can be useful while developing but the only reason I include all the extra code in my apps is to allow my company to provide support once the system has gone live. If it didn't do that I'd stick to the debugger and if the live system is running correctly then you don't want the overhead...

see my response for Nat. i admit log is a saviour frequently. saved my ass so many times! and even if it does not pinpoint the problem accurately, it provides at least probable direction of the problem. and knowing your log means knowing your system. this always helps. there are drawbacks although: - it takes resources. okay that's the price you pay but i do not want pay more that it deserves. - serializes multithreaded code there are sometimes faults that occur only with logging off, because of the serialization by logging library. theser are very nasty :) on the other hand it may be solved by removing all shared rsrcs, perhaps by saving each thread's log to separate sink? regards, mojmir

... be connected to a "sink" specific for that thread.

This approach was chosen after making some observations: 1) Synchronization has a performance penalty. and not a trivial one :/

2) Synchronization might affect the behaviour of the program when increasing the amount of logged data, potentially leading to heisenbugs. heisenbugs ;)) 3) Sometimes you actually never need to merge the streams of events. 4) Since the logged data is used for "external" diagnostics only, the library should allow the application generating the logs to do as little as necessary before storing them away. Storing primary measurement data, in a sense.

i agree there. i'd like to minimize the interference of the debugging mode from the normal flow as much as possible. maybe with exception of the runtime filtering facilities. i thought about it and these runtime values are read only most of the time. it depends - use either spinlocks if they are likely to be modified at runtime or marked simply as volatile and restrict write only to initialization phase.

The idea was to separate the generation of a log event from the synchronization, transformation and storage of log events.

exactly.

In this way, the cost of synchronization of multiple log streams is moved to a later stage. It can either be done in a designated "merger" thread inside the application, reading from lock-free queues connected to the "thread loggers", or each stream can be sent to a different file or network socket and merged off-line by a diagnostics tool (if needed).

aaaaah, the agony of re-discovering the already discovered ;-) don't you have sources available? best regards, mojmir

Mojmir Svoboda schrieb:

i know, logs can be really huge.

but i never meant to not provide what you call runtime filtering. i perhaps said something badly. i thought you wanted add another filter at runtime.

what i am saying is: User is not allowed to change format of the logged text at runtime, by changing the formatting chain. i know it can be done, but i don't want to as i consider it unnecessary.

the reason why is that as you have large codebase with lot of outputs, your people probably have tools helping them analyse the logs: regexps, indents, scripts, filters to gnuplot etc etc. if you change order of the logged columns, your tools are confused.

my approach is simply: think before picking format and then let it be the same forever (or at least for some long period). as a library user you can change it during development of course, but to take place, you have to recompile.

I think also that it is not so important to change the format during runtime. It is a nice to have feature but at least for me not a must. If you can configure the output format it has one big advantage: you can change the format of older products without recompiling the program. The most important thing for me that it does not cost a lot of time to format the message.

i hope that is clear, now and sorry for confusion i made.

best regards Hansjörg

good morning,

Did anybody of you look at how Solaris TNF framework or DTrace framework are implemented? A lot can be accomplished by tricks at link stage, and DTrace with UDT provider offers even more (selective filtering and data aggregation at run-time) than I could ask of any logging library. And that at a negligible cost for disabled log points.

just finished the usenix doc so that i got the picture. wow, i am quite astonished, i must say. this seems like every developper's dream... i worked with 5.8 and then quite lost a track. i used truss, strace, valgrind, purify, etc for achieve part of that goal, but apparently dtrace is lot more.

[No, I'm not proposing to reimplement all of DTrace. But what you're it would be perhaps easier to port it than rewrite, anyway

describing already exists, so it might be worth looking into how these things are implemented. Or, if nothing else, write a logging back-end for DTrace and/or TNF.

i'll certainly have a look at it, thanks! best regards, mojmir

Hi Mojmir,

...

- why do you apply filters to the logged text? A filter should be something able to say "yes" or "no" without looking at the text. First of all, if the filter says "no", you shouldn't need to do any processing of the text.

if you are talking about my approach of filters, i mixed three concepts according what the user has to do: 1. nothing at all (filter simply appends text, for example timestamp) 2. supply an argument - for filters like file, line taking __FILE__ etc 3. 2. + supply comparation logic and run-time value. this is case of levelling logged text and filtering out messages > certain level.

I'm still not sure why you need to text for that ;)

...

- I believe having a compile time vector for formatting the output is a mistake: typedef vector, sep, fn, sep, msg>::type pipe_mania; The user should be able to specify that at runtime - what if he wants to configure the log at runtime?

no he will _NOT_, that is the beauty ;)) if he still do, let him use log4jpp. according to my (i admit that short perhaps) experiences, this is very rarely needed.

Nat and Patrick already said it - run-time configuration is a must.

...

...

- pthreads are detected incorrecty. even in singlethr model mutex is required.

What do you mean?

i did not use bjam for the build as i really think this tool surely comes from hell.

I second that :) But it's good, every now and then ;) Best, John -- http://John.Torjo.com -- C++ expert http://blog.torjo.com ... call me only if you want things done right

Mojmir Svoboda wrote:

run-time configuration like setting desired level is ok and already integrated in the first version of the library.

Going further out on a limb, and again speaking only for myself, I've always found that logging "level" doesn't map well to my needs. I typically need to see full detail for some two or three interacting subsystems, without any of the log output from any other subsystems. In homebrew logging systems, I usually associate a string tag with each log statement. The string tag is looked up on first reaching the statement, and every subsequent visit tests a cached bool. When the logging system initializes, it reads config info (from a file or registry data) to enable/disable particular string tags. I usually include the ability to express the configuration data as "only these tags" or "all but these tags." You can get fancier still by defining relationships between string tags, expressing them as hierarchies... but I don't consider that essential. The essence of the idea is the ability to control particular groups of related log messages. In my experience, the traditional "level" approach can be restated as: - hardly any useful information - not enough useful information - too much information - WAY too much information

Mojmir Svoboda wrote:

...

When the logging system initializes, it reads config info (from a file or registry data) to enable/disable particular string tags. I usually

could you show me perhaps some of your config files? just for inspiration...

In a product using a separate config file specifically for logging, the file contents might look like this: ---8<--- error warn assets config --->8--- The code splits on whitespace, adding the string tags to a map. Again, map lookup occurs only the /first/ time control reaches a particular log message. When I'm reading a more generic config file (or registry subtree), the above can go into a string-valued config variable instead. For a developer debugging session, it might look like this: ---8<--- * events memory (long list of other tags I explicitly want to suppress) --->8--- where the tag '*' means: enable all log messages except those explicitly named. This sets a flag inverting the sense of map lookup success/failure.

how do you force reload of config? on unix i'd use a signal, but to be honest, have no big clue about windows...

Heh -- since I've mostly used this with consumer products, I haven't had to confront that. You exit the program, edit the config file and start it up again. Of course that's inadequate for a general-purpose logging library. I think I'd investigate the Windows functionality that allows a program to register interest in a change to a particular file.

i planned to add another run-time filtering facility; for example you could define your facilities like that:

namespace flog {

unsigned const bit_all = bin<11111111>::value; unsigned const bit_trace = bin<00000001>::value; unsigned const bit_hedumps = bin<00000010>::value; unsigned const bit_dataflow = bin<00000100>::value; ... unsigned const bit_synchro = bin<10000000>::value;

/**@class default_filters * @brief sequence of default filters used for text formatting */ typedef runtime_flt rt_context; typedef runtime_flt rt_level; typedef mpl::vector,line, I, msg>::type default_filters;

} // namespace flog

.. and then somthing like:

LOG(l, bit_debug, 7, "will enable trace..."); runtime_set(l, identity(), bit_hexdump | bit_trace); { ENTRY(l, 7, "void foo(T) [with T = long int]"); }

i'd really like to know your opinion on that.

I once worked on a very large product whose error codes were #defined in a central header file, e.g. #define ERROR_FILENOTFOUND 1001 ...many, many others... Every .cpp file in the system #included that file. Any change to that file forced a lengthy full rebuild on every developer. What happened was that developers quietly rebelled, hard-coding new decimal values into error-message-emitting function calls. Naturally, since those decimal values were no longer centrally registered, duplicates cropped up in different subsystems. Moreover, a typo in a hard-coded number (e.g. transposing two digits) could and did get released to the world before anyone noticed. In C++ source code, having a single, central source of truth for such things can actually be counterproductive. I much prefer a decentralized approach. An early incarnation of the log mechanism I've been describing used single-character tags: easy to code, more recognizable than decimal constants, cheap to store and compare. Scales /very/ poorly. I've come to prefer string tags, and have used that approach in several different products now. While theoretically possible, collisions are rare. Typos are readily spotted.

On Tue, Jun 10, 2008 at 07:17:00AM +0300, John Torjo wrote:

At this time, my library already does this - you can certainly specify whether you want thread-safety or not, and the lib is certainly efficient.

Great. I am looking forward to the next release, but already the current version addresses my needs. Matthias -- Matthias Vallentin vallentin@icsi.berkeley.edu pgp/gpg: 0x37F34C16