Slashdot Mirror
Software Logging Schemes?
MySkippy writes "I've been a software engineer for just over 10 years, and I've seen a lot of different styles of logging in the applications I've worked on. Some were extremely verbose — about 1 logging line for every 2 lines of code. Others were very lacking, with maybe 1 line in 200 devoted to logging. I personally find that writing debug and informational messages about every 2 to 5 lines works well for debugging an issue, but can become cumbersome when reading through a log for analysis. I like to write warning messages when thresholds or limits are being approached — these tend to be infrequent. I log errors whenever I catch one (but I've never put a 'fatal' message in my code, because if it's truly a fatal error I probably didn't catch it). Recently I came across log4j and log4net and have begun using them both. That brings me to my question: how do the coders on Slashdot handle logging in their code?"
I find I usually end up with 3 levels of logging:
Normal operation, often with some notion of "Yes, I'm still running even though I haven't done anything else lately".
Details. Usually corresponding to processing steps.
Algorithm tracing. This includes things like logging SQL queries. This is usually only of interest to me.
...laura
I will add lots of logging to debug a specific problem and then rip it out when the problem is fixed. Permanent logging includes run time problems like serial communication errors, file not found, etc. I like to make various logging functions switchable, so user input can be logged for example, but only when needed. Once a program is running well, it should only log data for dire exceptions, unless regular accounting logs are needed.
If you're using log4j, don't use multiple hosts to write to the same nfs filesystem file. You'll run into blocking issues and log4j doesn't handle them correctly. The nirvana of clustered app logging is an async JMS queue. You fire off the message and forget it. You don't wait for file handles.
It depends on the app you're writing -- is it a web app, a database app, a userspace program written in C, a Perl/Ruby script, or.. At work we created our own logging library in C to emit log events for different levels, e.g. informational, debugging, warnings, errors, fatal messages. We then have wrappers around that library so that languages like Ruby can access that logging library. But on hindsight I think I would've just used syslog if I had to start over. :)
IMO database logging has good points and bad points: On the good side, its easy to manipulate (query, purge, transform, summarise) the log entries. Also you can access the log entries remotely using the database tools you already know. On the bad side, its undoubtedly slower and more resource-intensive. Also, unless you have multiple DB connections (which itself raises complexity and overhead), then committing a log entry to the database will also commit your unit of work. It seems to work well for "user logging", i.e. where the end user of your application (rather than just the dev team) would want to read the messages.
[x] auto-moderate all posts by this user as insightful
1 line of logging per 200 lines of code is way too much. 2 in 5 lines is absolutely insane. I've seen way too many systems where the logging made it totally unusable. People just don't realize the costs of logging everything.
There's absolutely no way to document anything this verbose. Without documentation, the logging is useless.
Agreed, logging every 2 to 5 lines gives you the kind of information that you should really be getting with a debugger. Of course, when you're trying to diagnose a specific problem, sometimes it can be easier to put log messages every line or two than to repeatedly step through the code with a debugger, but that's sort of the same thing, just a temporary debugging aid - most of that logging output should be removed once you've figured out what's going on. For general use, I think about one log call per function might be reasonable - more if it's a long function, or none if it's a short function that does something really simple. And even most of those should probably be disabled once you release the software.
Comment removed based on user account deletion
My logging is setup so I can quickly filter down to the type of data I want. It's more than just "information", "warning", and "error" - but by (cpp)file, module, etc. That way, if an issue arises, I can eliminate the cruft and see just what I need. Just takes planning.
Why can't all fpga/microcontroller manufacturers just release free optimizing compilers???
First - let me give you my own perspective. I recommend having each subsystem log in such a fashion that you can easily grep to include or ignore that subsystem. For example for one package the following LVLx messages were the first four characters as follows:
LVL1 - basic startup and shutdown info ( a few lines per run)
LVL2 - Interactions with the database
LVL3 - Interactions with the file system
LVL4 - Detailed database interactions including each sql statement
LVL5 - amazingly verbose debug information including memory and variable allocations
In almost all cases, I recommend being able to set each level on or off. Your sysadmin (maybe yourself) will appreciate that ability.
If appropriate, I recommend an 'audit' record after each completed or aborted transaction. EG - after every order or every user change or whatever is important for accountability / business activity monitoring purposes.
This is the original question .
There is no code in the world that I can think of that needs a log line after every two steps in a procedure.
Any code in which timeouts can affect the result would require this kind of logging, which includes networking code or code that handshakes between multiple threads/processors. Example: debugging something like a new x/y/zmodem implementation is nigh impossible within a debugger because your side must respond within 10 seconds or the other side will start acting differently.
Companies with virtualized machines are often also using storage area networking and related high-availability technologies. The traditional bottleneck associated with disk I/O does not happen nearly as badly.
My blog
I'd be careful about using multi-core as a crutch: if the logging code isn't written properly, it can still be a bottleneck. Last year at my office we had to excise our old logging library because it turned out that each function call to the log acquired a global critical section even if the log level threshold wasn't met. Multi core wouldn't help because it was highly likely that any given call to the log would block the calling thread.
I'm going to the casino. Don't gamble.
It might come back to haunt you later.
The society for a thought-free internet welcomes you.
And let's hope it never does disappear or we can kiss new software goodbye.
That being said, you can add what ever logging you want as long as you do it outside the application code, such as through AOP (if you don't know what that is then google is your new best friend).
Logging through external means has a number of benefits. First you application code is relieved from unnecessary clutter. Second the logging can be added or removed as fit for the environment with no need for any runtime checking, which is perfect for turning of all logging in production environments. And lastly it enforces good coding practices as it makes sure people break up code in a way that makes external logging possible, which is how code should be written anyway.
The majority of all logging, dare I say all useful logging, is easy to summarize.
This is perfect for function/method interception since it comes down to something more specific.
So simply add the first logging to an interceptor that operates before the functions you want to log, and the second after the function.
If you find yourself needing detail inside the function then you need to break the function up into sub routines, so you can use this generic logging on the sub routines instead, or as well as.
One solution I have found for this is to write my own logging application. I write mainly web-based software and AGI stuff, and all my software makes use of the same logging application. Basically what happens is that when I want to write to the log (which is stored in a MySQL database so analysis and viewing the logs is enhanced), the software simply tells the OS to execute the logging utility which can be niced or deprioritised on the system. This way, the software doesn't have to worry about I/O to the log, it doesn't have to wait for MySQL and it can carry on without the hassles involved in rewritting bits of logging code for each project. I have found this works really well for me, and having all the logs for all my code in a central database makes it easy for me to write some nice little AJAX/PHP app to apply filters to the logs or to analyse the logs, whatever I want basically. However, I know this method is not practical for many situations.
I wonder why, given the huge increase in the performance of computers over the last ten years and more, why it sill takes some games one to five minutes to load.
The goal of almost any commercial product isn't to be 100% awesome in every possible way. It's to be adequate on most measures and awesome in the few that buyers care most about.
Game buyers care about volume and quality of content a lot more than load time. So even if some engineer figured out a way to cut load time in half, somebody would just add more content and bump up bit rates and quality levels until it was back to a tolerable load time.
I just had occasion to try and optimize an old C++ app that was having performance issues in certain sections. This app had its own custom logging system using Unix message queues, and was always a little suspect. I noticed as I tried to instrument the code that whenever I seemed to get close to the bottleneck, the problem seemed to move to a different part of the code. Finally, it dawned on me that the log system itself was part of the problem. In fact, the log object constructor was taking significant time, including (in some places) within critical (as in lock/unlock) sections. Most critical classes had been defined with an instance of the logger as a member, which was overkill. Doing nothing more than changing the definitions of the log objects to static dropped critical section performance by an entire order of magnitude.
Moral: Do logging, but do it judiciously. Know what you're doing - and know what the log system is doing too.