Zarar Siddiqi's Blog: November 2005 Archive

So I found myself wanting to know if I could print the enclosing method of the current line of code being executed. A quick look at the reflection API didn't yield much. A little reflective thinking later, I came to the conclusion that it's impossible for the reflection API to tell me this since it explores binary files at the class level.

Thats when it struck me that Log4J does exactly what I want to do. It can print out the method and line number of the code for each log.debug(..) call. So of I went digging into Log4J code looking for an answer. I found it.

What Log4J ends up doing is that for each debug(..) call, it creates an instance of Throwable which takes a snapshot of the runtime stack. It then proceeds to parse the stack to yield the current line of code being executed along with class and method information.

Keep in mind that constructing stack traces is a fairly expensive operation. When an Exception is created, the JVM needs to literally pause the processing and so it can get a good glimpse of the entire runtime stack - this includes classes, methods, line numbers etc - starting from Thread.run() all the way till the creation of Throwable. From the runtime's point of view, this is acceptable since it's not designed for great Exception handling but to run as fast as possible.

However, in the logging scenario, the culprit is the call to the Throwable.fillInStackTrace() method in the Throwable constructor which gets invoked on each debug(..), info(..) and other logging calls. This is the only way to retrieve the logging information requested via the PatternLayout class. Give Log4J credit since they only create the Throwable instance when the specific PatternLayout is specified; plus they have the decency to warn you about using the l, L and other expensive options.

Although descriptive logging can provide good roll-back mechanisms in production code, the cost incurred by specifying method and line numbers when logging is simply too high. It seems like the pain of typing out the method name when logging is unavoidable.

To some, this might come as old news but to many it'll make them change their log4j.properties.

Developer thinks he'll make a better PM

Posted by zarar on November 08, 2005 at 12:03 PM | Permalink | Comments (7)

Although I've been a core developer for a significant part of my career, I do often come in contact with the business-types who drone on about requirements while the eager-to-please IT shop keeps saying yes to even the most unfathomable requests. After all the yes's have been nodded and all the necessary hands shaken, the Project Manager brings a steep pile of 8.5 x 11's to the developers along with a pat on the back and a confidence inspiring wink. Boo Yeah! The project has started.

A meeting is held by all parties involved only to be cut short by 12:00 PM and the ensuing two hour lunch break. The developers are left figuring what this stack of paper is trying to say. The front page is pretty clear, "Inventory Management System" it says. On the second page there's something about Java being a requirement. There's also a due date. They start working.

Fast forward to five months later. The stack of paper has a lot of writing on it. Lines have been scribbled and crossed out. Along with bits and pieces of scribble, you'll also find pepperoni stains and some fluids which can best be ascribed to coke spills. Lots of code has been written, some of it has even been tested. The programmers are feeling fairly confident, the PM has his ass covered, anything goes wrong, and he’s ready to play the blame game.

Guess what? Something does go wrong. Seriously wrong. Turns out something works the way it's not supposed to work. "No Problem" says the PM and says he can have it fixed by end-of-day. The developer is told of the "problem" and the expected fix date. The look on his face is priceless: "That's not a problem, I've made it that way just like you said", he pleads pointing at the greasy stack of paper. They both consult the stack, sure enough, he's right. He's done what he was asked to do.

The PM frowns, goes away, comes back half an hour later and says, "You've misunderstood the document, this is what it really means". The developer listens, frowns, frowns some more, consults the other developers who all frown. An hour later, they reach the agreement that the wording can mean more than one thing depending on the time of day and the salary you're making.

The PM has found somebody to blame.

********************

It's incidents like these that motivated me to go back to class and take a couple Project Management courses via pmi.org. I'm almost through with the courses and have so far learnt that Project Management is simply common sense wrapped around acronyms, document formats and jargon. It really does sound very simple and sometimes quite bloated. Hey, did you know if you have 10 people on your project you have 45 communication channels? How did I arrive at that number? Why I simply applied the formula n(n-1)/2. That’s 45 different conversations between two people and thus a lot of room for miscommunication.

See what I mean? Someone wise once said, "common sense is not common". I agree.