Report from the battlefield #5 - Logging can kill performance

Home

Source: own resources, Authors: Agnieszka and Michał Komorowscy

So far in Report from the battlefield series I wrote about my experiences as an expert in the recruitment company. This time I'll write a bug that I found in the production. It was all about the performance. The problem was that in the new version of an application one operation slowed down about 6 times. Initially, I suspected that amount of data simply increased considerably or some network problems. Fortunately, I easily reproduced the issue on my dev machine. Reproducing a problem is half the battle. Though performance problem are usually difficult to analyse so I was ready for a long investigation.

I started stepping through the code with a debugger just to see what is going on. Everything seemed to be ok until... One of the final operations was to log into a file what was retrieved from a database. What's important the log level was set to Trace so even large amount of data shouldn't matter in the production. Why? Because in the production, precisely because of the performance reasons, the logger should be configured not to log everything to a file. In other words it should ignore messages usually with the log level = Trace or Debug. However, after I had pressed F10 (Step Over), I had to wait a few seconds till the logging ends. BINGO!

My first though was that someone configured the logger in the wrong way in the production. Typical PEBKAC problem. To verify my hypothesis I changed the configuration of the logger and executed the problematic operation. Unfortunately, the problem occurred again. Another look at the code and I know what was wrong. And do you already know?

.
.
.
.
.
.
.
.
.
.
.
.
.
.
.

The problem was that for large amount of data the application required a few seconds just to create/prepare a message for the logger. To make thing worse this message was created, regardless if it was later used by the logger or not. During development it may acceptable but not in the production! There are 2 potential solutions of this problem. Details depends on the logging framework:

• The first approach is to simply check the logging level before creating/preparing a message e.g.:

  if(Logger.LogLevel == LogLevel.Trace) 
  {
      /* Prepare and log a message */
  }
  

• The second approach is to use deferred execution for example lambdas e.g.:

  Logger.Trace(() => /* Prepare a message */).

  If a logger supports this syntax, a lambda will be executed if and only if it is required.

The longest project

Home

Source: own resources, Authors: Agnieszka and Michał Komorowscy

I haven't been blogging for 4 months and it's the longest break I've ever had. Why? Was I sick? Did I have no ideas what to write about? Did I have no time? Did I have too much work? Fortunately, nothing of that. The reason is completely different and probably surprising. So, I finished the longest project in my life.

• The project that I started in 2009.
• The project that for all these years was somewhere in my mind.
• The project that I wanted to abandon over a dozen of times.
• The project that took hundreds or thousands of hours.
• The project that allow me to learn a lot of.
• The project that I would have done in a different way if I had had this chance.
• The project of which I'm extremely proud.
• The project after which I simply had to rest.

What could it be? The answer is PhD in Computer Science. On 12 April 2016 I defended my doctoral dissertation, written under the supervision of Professor Janusz Sosnowski, under the title:

Methods of analysis of information systems based on logs of historical debuggers

Even now I remember how relieved and happy I felt then :)

In my work I focused on the problem of storing and analysing of data collected by historical / reversible debuggers. I performed a detailed analysis what could be and what should be improved when it comes to working with them. In the result I proposed new models of representation of execution traces and I implemented tools that facilitate working with data recorded by historical debuggers. I also performed experiments showing advantages of my ideas. It was a really, really huge job.

Now you may want to ask some questions:

• Was it worth it?
• Why did you do so?
• Did you work professionally at the same time?
• How did you share time between PhD studies with your work? Is it possible at all?
• What did you actually gain?
• How to start PhD studies?
• How much could I earn at the university?
• Would you continue your science career?;
• Why you didn't write about PhD earlier
• And many, many more.

I plan a series of post about doing PhD in the computer science. Many topics will be specific for Poland but many will be general. I want to do that because of two things. Firstly, it'll be a form of therapy for me :) I simply want/need to write about something that was so important to me for such a long time. Secondly, I think that there are not so many blogs/articles about writing PhD so it should be simply useful for others.

If you have any specific questions just let me know.