Java application speed goes up after adding log output

Question

We stumbled upon a rather strange problem IMO. Our clients have been complaining about the speed at which our application imports and processes data from files [ filesize 1kB cca, time required to import the file under normal conditions is 4-10 seconds, depending on the overall workload. Yes, it is a lot ]...

So we started looking into it, but something quite unexpected happened: after inserting debug log outputs into certain parts of the code [ not affecting the logic otherwise ] the import sped up quite a lot : 300ms-2200ms /file depending on the overall workload.

Language used: Java

JDK 6_34 on my station [ don't know what versions my colleagues use ]

I've went through the code... many times. Nothing unusual. Even though it's all executed in a thread, this thread doesn't have a competitor doing the same job OR accessing the same files.

Is this situation familiar to anyone?

P.S.: I do hope that this question does belong here. If not, I apologize sincerely.

edit:

as for logging, we use log4j.

OS: Windows XP / my machine. One colleague has the same, the other uses Win7 /

CPU: E7500 @ 2.93 GHz

RAM: 2 GB DDR2

One other machine is basically the same. The configuration of the third is unknown to me as it's new and not my workstation.

Files are all loaded/stored from/to a local HDD in my situation.

What concerns me most is that we use a platform for which we have no source, because, well we've paid for a license, but not source >.<

Answer 1

My theory is that adding logging is changing something in your application's thread scheduling patterns.

Normally, this shouldn't matter. But if the underlying problem in your application is something related to thread scheduling, then it is not surprising that the logging changes the observed behaviour.

I recommend that you audit the relevant parts of your codebase looking for Thread.sleep(...) calls, Thread.yield() calls, places where your code is polling, and so on. Also consider that this might be happening in 3rd-party library code.

@OldCurmudgeon's answer includes two simple versions of what you should be looking for. Even using sleep(0) is wasteful, though it is better than sleep(N) where N is significantly greater than zero.