B
Bret Schuhmacher
Hello all,
I have a program that runs very quickly with one small exception. I'm
trying to tune the performance and I can't track down a 15ms delay. Maybe
you can help. 15ms may not sound like much, but this is supposed to be a
VERY high performing app, and 15ms adds up...
I've got log4j spitting out log statements at the entrance and exit of the
method in question. All the program does is open a file and read the
contents into a bufferedreader, then enter a loop and call the method until
there are no more rows to read. Here are the timings from the log4j log:
2007-07-03 19:40:21,678 INFO
2007-07-03 19:40:21,678 INFO
2007-07-03 19:40:21,678 INFO
2007-07-03 19:40:21,693 INFO
2007-07-03 19:40:21,693 INFO
2007-07-03 19:40:21,709 INFO
2007-07-03 19:40:21,709 INFO
2007-07-03 19:40:21,709 INFO
2007-07-03 19:40:21,725 INFO
2007-07-03 19:40:21,725 INFO
2007-07-03 19:40:21,740 INFO
2007-07-03 19:40:21,740 INFO
2007-07-03 19:40:21,740 INFO
2007-07-03 19:40:21,756 INFO
2007-07-03 19:40:21,756 INFO
2007-07-03 19:40:21,771 INFO
2007-07-03 19:40:21,771 INFO
2007-07-03 19:40:21,771 INFO
2007-07-03 19:40:21,787 INFO
2007-07-03 19:40:21,787 INFO
2007-07-03 19:40:21,787 INFO
2007-07-03 19:40:21,803 INFO
2007-07-03 19:40:21,803 INFO
2007-07-03 19:40:21,803 INFO
2007-07-03 19:40:21,818 INFO
2007-07-03 19:40:21,818 INFO
2007-07-03 19:40:21,818 INFO
2007-07-03 19:40:21,834 INFO
2007-07-03 19:40:21,834 INFO
2007-07-03 19:40:21,850 INFO
2007-07-03 19:40:21,850 INFO
2007-07-03 19:40:21,850 INFO
2007-07-03 19:40:21,865 INFO
2007-07-03 19:40:21,865 INFO
2007-07-03 19:40:21,865 INFO
2007-07-03 19:40:21,881 INFO
Notice the 15ms delay every so often? I'll get about 3 calls to the method
in the same millisecond, then it'll delay about 15-16ms, and continue. I
thought it was garbage collection, but if it is, I can't find the 15ms. And
GC wouldn't run so frequently, would it? I'm running inside the Informix
JRE (it's an IBM recompiled 1.4.2) and Sun 1.5.0_6. In the Sun JRE I use
the following tuning: -Xms128m -Xmx768m -XX:MaxPermSize=128m
-XX:+UseParallelGC -verbosegc -XX:MaxNewSize=32M -XX:NewSize=32M. That
shows me this info:
[GC 24576K->1121K(126976K), 0.0162035 secs]
[GC 25697K->1120K(126976K), 0.0185842 secs]
[GC 25696K->1121K(126976K), 0.0144689 secs]
[GC 25697K->1121K(126976K), 0.0177961 secs]
[GC 25697K->1109K(126976K), 0.0154531 secs]
[GC 25685K->1113K(129920K), 0.0149296 secs]
[GC 31577K->1137K(128512K), 0.0141060 secs]
[GC 31281K->1137K(129408K), 0.0029744 secs]
[GC 30833K->1137K(128064K), 0.0011108 secs]
[GC 30833K->1137K(129344K), 0.0010085 secs]
[GC 30577K->1121K(129408K), 0.0044000 secs]
[GC 30561K->1121K(129408K), 0.0015647 secs]
[GC 30561K->1121K(129408K), 0.0035977 secs]
[GC 30561K->1121K(129472K), 0.0015692 secs]
[GC 30625K->1121K(129408K), 0.0011789 secs]
[GC 30625K->1121K(129536K), 0.0029607 secs]
[GC 30753K->1121K(129472K), 0.0025517 secs]
[GC 30753K->1137K(129664K), 0.0014398 secs]
[GC 31025K->1121K(129600K), 0.0014365 secs]
[GC 31009K->1121K(129792K), 0.0009292 secs]
Any idea what might cause this 15ms delay? Any other avenues I should be
looking into? FWIW, I got the 15ms delay before I added any JVM arguments
(i.e. they didn't cause the problem). I only added the JVM args to try to
figure out the issue.
Thanks in advance for your thoughts and suggestions!
Rgds,
Bret
I have a program that runs very quickly with one small exception. I'm
trying to tune the performance and I can't track down a 15ms delay. Maybe
you can help. 15ms may not sound like much, but this is supposed to be a
VERY high performing app, and 15ms adds up...
I've got log4j spitting out log statements at the entrance and exit of the
method in question. All the program does is open a file and read the
contents into a bufferedreader, then enter a loop and call the method until
there are no more rows to read. Here are the timings from the log4j log:
2007-07-03 19:40:21,678 INFO
2007-07-03 19:40:21,678 INFO
2007-07-03 19:40:21,678 INFO
2007-07-03 19:40:21,693 INFO
2007-07-03 19:40:21,693 INFO
2007-07-03 19:40:21,709 INFO
2007-07-03 19:40:21,709 INFO
2007-07-03 19:40:21,709 INFO
2007-07-03 19:40:21,725 INFO
2007-07-03 19:40:21,725 INFO
2007-07-03 19:40:21,740 INFO
2007-07-03 19:40:21,740 INFO
2007-07-03 19:40:21,740 INFO
2007-07-03 19:40:21,756 INFO
2007-07-03 19:40:21,756 INFO
2007-07-03 19:40:21,771 INFO
2007-07-03 19:40:21,771 INFO
2007-07-03 19:40:21,771 INFO
2007-07-03 19:40:21,787 INFO
2007-07-03 19:40:21,787 INFO
2007-07-03 19:40:21,787 INFO
2007-07-03 19:40:21,803 INFO
2007-07-03 19:40:21,803 INFO
2007-07-03 19:40:21,803 INFO
2007-07-03 19:40:21,818 INFO
2007-07-03 19:40:21,818 INFO
2007-07-03 19:40:21,818 INFO
2007-07-03 19:40:21,834 INFO
2007-07-03 19:40:21,834 INFO
2007-07-03 19:40:21,850 INFO
2007-07-03 19:40:21,850 INFO
2007-07-03 19:40:21,850 INFO
2007-07-03 19:40:21,865 INFO
2007-07-03 19:40:21,865 INFO
2007-07-03 19:40:21,865 INFO
2007-07-03 19:40:21,881 INFO
Notice the 15ms delay every so often? I'll get about 3 calls to the method
in the same millisecond, then it'll delay about 15-16ms, and continue. I
thought it was garbage collection, but if it is, I can't find the 15ms. And
GC wouldn't run so frequently, would it? I'm running inside the Informix
JRE (it's an IBM recompiled 1.4.2) and Sun 1.5.0_6. In the Sun JRE I use
the following tuning: -Xms128m -Xmx768m -XX:MaxPermSize=128m
-XX:+UseParallelGC -verbosegc -XX:MaxNewSize=32M -XX:NewSize=32M. That
shows me this info:
[GC 24576K->1121K(126976K), 0.0162035 secs]
[GC 25697K->1120K(126976K), 0.0185842 secs]
[GC 25696K->1121K(126976K), 0.0144689 secs]
[GC 25697K->1121K(126976K), 0.0177961 secs]
[GC 25697K->1109K(126976K), 0.0154531 secs]
[GC 25685K->1113K(129920K), 0.0149296 secs]
[GC 31577K->1137K(128512K), 0.0141060 secs]
[GC 31281K->1137K(129408K), 0.0029744 secs]
[GC 30833K->1137K(128064K), 0.0011108 secs]
[GC 30833K->1137K(129344K), 0.0010085 secs]
[GC 30577K->1121K(129408K), 0.0044000 secs]
[GC 30561K->1121K(129408K), 0.0015647 secs]
[GC 30561K->1121K(129408K), 0.0035977 secs]
[GC 30561K->1121K(129472K), 0.0015692 secs]
[GC 30625K->1121K(129408K), 0.0011789 secs]
[GC 30625K->1121K(129536K), 0.0029607 secs]
[GC 30753K->1121K(129472K), 0.0025517 secs]
[GC 30753K->1137K(129664K), 0.0014398 secs]
[GC 31025K->1121K(129600K), 0.0014365 secs]
[GC 31009K->1121K(129792K), 0.0009292 secs]
Any idea what might cause this 15ms delay? Any other avenues I should be
looking into? FWIW, I got the 15ms delay before I added any JVM arguments
(i.e. they didn't cause the problem). I only added the JVM args to try to
figure out the issue.
Thanks in advance for your thoughts and suggestions!
Rgds,
Bret