16

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 >.<

4

5 回答 5

5

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.

于 2012-09-07T23:08:55.763 回答
4

Were you able to reproduce the customer's original problem (i.e. Were you able to pull files and have them take 4-10 seconds as you mentioned) on a machine that you are using?

If not, then there are too many factors involved to specifically give log4j the credit. I'm with Wilf on this one. There's no way that adding logs could reliably increase the speed of a piece of code...at least there's no way that I can think of.

If you were able to reproduce the issue, then added logs, and then, using the same hardware, same logic, and same files got that much of a speed increase, then you have officially blown my mind.

于 2012-09-07T23:03:02.883 回答
4

In this sort of situation, what I did was place trace timings at key parts of the application (say 5 - 10 stages) and see what part was taking the most time. In your case you could see what stage speeds up. I suspect there is just one stage which will be faster in which case you can places more timing in that and narrow down to the code where you see the most difference.

In the past where you see strange increase in delay this has been down to network calls such a DNS lookups. When you process the file, are you accessing an external application/network service?

于 2012-09-08T06:57:10.420 回答
3

Adding logging adds synchronisation points to your logic. Perhaps what you are seeing is a (odd) side effect of this.

于 2012-09-07T23:01:50.427 回答
2

You're looking for a spin loop.

Somewhere in your code (or the underlying framework) you have code that looks something like:

while (!ready()) {
  // Do next to nothing.
}

or something that boils down to that.

Essentially the loop is spinning so fast the resource it is waiting for does not get enough time to become available. You will usually also see strangely high CPU usage.

The logging alleviates the condition because it slows down the loop, thus allowing the resource to become ready.

You need to change it to something like:

while (!ready()) {
  Thread.currentThread().sleep(0);
}

or, ideally, use a proper blocking mechanism.

于 2012-09-07T23:47:19.497 回答