Home | Contact Us | FAQ | Search & Site Map | Link to Us
Sign In | Join | Other 45 Sites in Network
HomeAnnouncementsWhite Papers
Discussion GroupsFirst AidDatabasesJavaBeansGUIJava 3DVirtual MachineCORBASecurityToolsGeneral
Java DirectoryOpen Source ProjectsSample Book ChaptersUser GroupsWeb Resources
Related Topics
Databases.NETMore Topics ...

Java Forum / General / July 2007

Tip: Looking for answers? Try searching our database.

Tuning suggestions, please?

Thread view: 
Bret Schuhmacher - 04 Jul 2007 06:47 GMT
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
Twisted - 04 Jul 2007 07:08 GMT
> 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.

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

It's probably just when the BufferedReader has to fetch more data from
the disk. If one row is about 256 bytes and the buffer in the
BufferedReader is 1K, it will indeed grab more data from the disk
about every fourth call.

It may be possible to tweak BufferedReader to a larger buffer size, or
use NIO to get double-buffering where it will fill up one buffer while
your code reads from another then switch.
Bret Schuhmacher - 04 Jul 2007 07:29 GMT
Thanks for the quick reply!  Unfortunately I don't think it's the
BufferedReader.  I first noticed the problem when the method in question was
called from Informix as a User Defined Routine and there was no
BufferedReader.  I added a main() and some code to open a flat file today to
see if Informix was the issue and the problem persisted exactly as it had
under Informix - 15ms delays.

Thanks very much for the response, though.

Rgds,

Bret
Twisted - 04 Jul 2007 07:48 GMT
> Thanks for the quick reply!  Unfortunately I don't think it's the
> BufferedReader.  I first noticed the problem when the method in question was
> called from Informix as a User Defined Routine and there was no
> BufferedReader.  I added a main() and some code to open a flat file today to
> see if Informix was the issue and the problem persisted exactly as it had
> under Informix - 15ms delays.

Well there's a few other things it could be:
* Another Java thread is doing stuff -- anything from incremental
 GCs to the random things I see in Eclipse's debugger from time to
 time like "JVM termination thread", "Finalization thread", and "AWT
 image fetcher thread". These manage a bunch of stuff under the hood.
 Some only for graphical apps; others for any app, to finalize dead
 objects with nontrivial finalize() methods, handle reference queues,
 and etc.
* JIT compiling (but that should stop after a few iterations when
 it's fully optimized)
* The JVM is simply doing something weird
* Something else on the host system is hogging the CPU and yielding
 timeslices every 15 ms that are just long enough for the Java task
 to get a few iterations in
* The OS you're running it on is doing something weird (Windoze
 by any chance?)
* The very hardware you're running it on is doing something weird

> Thanks very much for the response, though.

YW.
pascal.lecointe@euriware.fr - 04 Jul 2007 08:38 GMT
> Hello all,
>
[quoted text clipped - 84 lines]
>
> Bret

If I remember coreectly, the frequency of the user clock timer on
windows is between 15 and 16 ms, so you can't have a better resolution
within Java 1.4.

Since Java5 (or Java6, don't remember), there is the new method
System.nanoTime(), which has a much better resolution (use another
clock timer of the OS)
Juha Laiho - 04 Jul 2007 08:57 GMT
"Bret Schuhmacher" <bret@thelastmilellc.com> said:
>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...

Could it be OS context switches; is there something else in the machine
doing something, and thus stealing the CPU every now and then?
Signature

Wolf  a.k.a.  Juha Laiho     Espoo, Finland
(GC 3.0) GIT d- s+: a C++ ULSH++++$ P++@ L+++ E- W+$@ N++ !K w !O !M V
        PS(+) PE Y+ PGP(+) t- 5 !X R !tv b+ !DI D G e+ h---- r+++ y++++
"...cancel my subscription to the resurrection!" (Jim Morrison)

David Gourley - 04 Jul 2007 22:10 GMT
> "Bret Schuhmacher" <bret@thelastmilellc.com> said:
>
[quoted text clipped - 7 lines]
> Could it be OS context switches; is there something else in the machine
> doing something, and thus stealing the CPU every now and then?

There is a virtual machine thread which wakes up and does some stuff
every 20 ms..  (This might show up as introducing pauses on single
CPUs). (you can see this effect if you look at a JVM running with a
kernel profiler e.g. prospect on hpux).  Also on single CPU boxes, some
kernel threads will periodically steal cycles (e.g. to flush file cache).

Another thing to look out for (as your thread looks like it might be CPU
bound) is what's happening to it priority wise.  The default scheduler
behaviour on many OSs reduces the priority of long running threads if
they run without yielding the CPU... this behaviour can often be
modified (e.g. using rtsched command on hp-ux, but solaris and windows
have equivalents as well, so I'm guessing AIX does).  Setting thread
priority from Java affects base priority but may not stop the priority
from getting adjusted dynamically if that's the default OS scheduling
policy.

You need to do UNIX profiling to see this last effect (shows up as the
priority getting reduced for your application thread, and a large number
of involuntary context switches).

If you're looking to benchmark with the nanosecond routines, you
probably need to double check what system call they map onto.. on some
hardware platforms, the high accuracy time routines can get mapped onto
  a fixed CPU (essentially to avoid clock drift between processors) and
this can become a bottleneck.

Cheers

Dave
Nigel Wade - 04 Jul 2007 11:53 GMT
> Hello all,
>
[quoted text clipped - 43 lines]
> 2007-07-03 19:40:21,865  INFO
> 2007-07-03 19:40:21,881  INFO

> Any idea what might cause this 15ms delay?  A

I don't think it's a 15ms delay, rather it's the resolution of the clock. On my
Windows XP laptop the resolution is exactly 10ms. On my Linux desktop the
resolution is 1ms.

Try this simple piece of code to see what your resolution is. It outputs the
difference in mS of the clock every time the clock generates a new value, along
with the number of times that it was able to create a new Date() (with the same
value) during that interval.

import java.util.Date;
public class TestClock {
   
   public static void main(String[] args) {
       int count = 0;
       Date olddate = new  Date();
       while(true) {
           Date date = new  Date();
           if ( date.after(olddate)) {
               long step = date.getTime() - olddate.getTime();
               System.out.println(step+" "+count);
               olddate = date;
               count = 0;
           }
           else {
               count++;
           }

       }
   }
   
}

Signature

Nigel Wade, System Administrator, Space Plasma Physics Group,
           University of Leicester, Leicester, LE1 7RH, UK
E-mail :    nmw@ion.le.ac.uk
Phone :     +44 (0)116 2523548, Fax : +44 (0)116 2523555

Bret Schuhmacher - 04 Jul 2007 14:53 GMT
Thanks for the code, Nigel.  Here's the output:
15 193573
16 186582
16 190201
15 183223
16 116424
16 123012
15 100954
16 183436
15 170407
16 180246
16 195359
15 186473
16 190119
16 148391
.
.
.

Looks like the timer resolution on my laptop running Windows XP is 15-16ms -
consistent with the 15-16 ms I was trying to track down.

I originally saw the issue at a customer's site on an AIX v5.2 box and
replicated it on my Windows laptop.  Is it possible an AIX box has the same
timer resolution a Windows box does?  I see the same issues inside and
outside of Eclipse, as well as under different JVM versions (for those of
you who were asking).

Is there *anything* I can do about this?  Sounds like it's hardwired into
the CPU.  I tried adding this:
        Thread thisThread = Thread.currentThread();
        thisThread.setPriority(Thread.MAX_PRIORITY);
But it didn't help.

Are there other ways of dedicating a CPU or increasing the timeslice or
priority to a thread in Java?  Would it help?

Thanks again, Nigel!

Rgds,

Bret
Nigel Wade - 04 Jul 2007 15:47 GMT
> Thanks for the code, Nigel.  Here's the output:
> 15 193573
[quoted text clipped - 38 lines]
>
> Bret

You don't need to do anything. Your CPU is getting 100% (or pretty much). The
only issue is the time resolution - you can't resolve the time to better than
15ms.

In the above test output you can see that during the 15ms resolution of your
clock the code is actually running round the loop between 100,000 and 200,000
times.

Signature

Nigel Wade, System Administrator, Space Plasma Physics Group,
           University of Leicester, Leicester, LE1 7RH, UK
E-mail :    nmw@ion.le.ac.uk
Phone :     +44 (0)116 2523548, Fax : +44 (0)116 2523555

Patricia Shanahan - 04 Jul 2007 16:32 GMT
> Thanks for the code, Nigel.  Here's the output:
> 15 193573
[quoted text clipped - 32 lines]
> Are there other ways of dedicating a CPU or increasing the timeslice or
> priority to a thread in Java?  Would it help?

You still seem to be looking for something like context switches that
would cause intermittent delays. However, the message from the timer
resolution measurement is that all you know is the average time for a
series of calls. Maybe there are intermittent delays. Maybe every single
call takes between 8.5 and 8.7 milliseconds. Both are consistent with
the data.

The next step should be to redo the measurement, using
System.nanoTime(). That will tell you what type of problem you are
looking for.

Patricia
Bjorn Borud - 04 Jul 2007 17:43 GMT
["Bret Schuhmacher" <bret@thelastmilellc.com>]

| Looks like the timer resolution on my laptop running Windows XP is 15-16ms -
| consistent with the 15-16 ms I was trying to track down.

if it is a timer-resolution problem then why not increase the number
of times the calculation is run between sampling of the clock?  if you
run it 10, 100 and 1000 times you should be less and less dependent on
the resolution of the timer.  

(other factors may come into play, like GC, but I don't think this
should be an issue here.  anyway, make sure that the heap is large
enough so that the young generation comfortably can cope with all the
(transient) objects allocated during the calculation.  not that I
suspect this to be a problem here (I'd have to take a look at the
code), but if all your objects are really short-lived, you will
actually lessen the GC burden).

(oh, and you should check if there are any differences in running the
code in -server or -client mode).

-Bjørn
Roedy Green - 04 Jul 2007 14:49 GMT
On Wed, 4 Jul 2007 05:47:19 GMT, "Bret Schuhmacher"
<bret@thelastmilellc.com> wrote, quoted or indirectly quoted someone
who said :

>Notice the 15ms delay every so often?

see http://mindprod.com/jgloss/garbagecollection.html
--
Roedy Green Canadian Mind Products
The Java Glossary
http://mindprod.com
Roedy Green - 04 Jul 2007 14:57 GMT
On Wed, 4 Jul 2007 05:47:19 GMT, "Bret Schuhmacher"
<bret@thelastmilellc.com> wrote, quoted or indirectly quoted someone
who said :

> And
>GC wouldn't run so frequently, would it?

I wish I could remember what the tool was I used, (might have just
been IntelliJ) but it let me know every time GC ran. I was amazed at
how frequent it was.  It seemed to do big gcs and little gcs.

One type of optimisation I have not seen much attention paid to is
reducing the frequency of garbage collection by avoiding creating new
objects uncessarily, particularly large objects like a buffer to read
on entire file into RAM.

Other possible culprits:

1. some other task on your machine, e.g. indexing, mail check, cache
flushing.  You might run the resource monity with and without your
code to see what other tasks are up to.

2. you should see a couple of pauses for HotSpot to do some
optimisation.

As a practical matter, consider Jet to ultra optimise this code. See
http://mindprod.com/jgloss/jet.html
'
--
Roedy Green Canadian Mind Products
The Java Glossary
http://mindprod.com
Bjorn Borud - 04 Jul 2007 17:57 GMT
[Roedy Green <see_website@mindprod.com.invalid>]

| I wish I could remember what the tool was I used, (might have just
| been IntelliJ) but it let me know every time GC ran. I was amazed at
| how frequent it was.  It seemed to do big gcs and little gcs.

probably VisualGC?  if you run Java 1.5 or later it should be very
simple to just attach it to a running VM and inspect what the GC
system is doing.  

check here:

 http://java.sun.com/performance/jvmstat/#Tools

If you see several minor-collections per second then you might have
heap that is too small.  also have a look at how the tenured
generation grows.

the hardest thing to optimize is code that keeps filling up the
tenured generation, triggering major collections. (a few years ago I
had an application that strained the GC a lot.  turned out that by
getting rid of some caches in the application¹, I got much smoother
overall performance since the system wasn't doing major collections as
often)

¹) the assumption of the programmer who put them there was possibly
  that these would make the system faster since he was used to the
  expense of frequent object creation and destruction in C++. it
  turned out that in this case the cache just slowed things down
  and that instantiation of the classes in question was pretty
  quick anyway.

| One type of optimisation I have not seen much attention paid to is
| reducing the frequency of garbage collection by avoiding creating new
| objects uncessarily, particularly large objects like a buffer to read
| on entire file into RAM.

well, and then hanging on to them for so long that they go into the
tenured generation.  remember, if you get rid of the object *quickly*
it won't have to be copied during a number of minor collections and it
won't end up in the tenured generation -- which is significantly
slower to garbage collect.

-Bjørn
Bret Schuhmacher - 04 Jul 2007 22:34 GMT
Thanks for the tips everyone!  I do appreciate your input :-).

I've run visualgc and the GC time shows 94 collections, 59.81ms and unknown
GC reason.  The Eden space graph is up and down like a yo-yo very regularly.
Is that normal?  I don't know where the tenured GC is, though.  I have an
image of the tool running, but probably can't post it to this non binary
newsgroup.  I'll try to extend my heap as you suggested Bjorn - I do see a
lot of GC in the Eden space - it's wild.

Thanks,

Bret
Wojtek - 05 Jul 2007 00:28 GMT
Bret Schuhmacher wrote :
> Thanks for the tips everyone!  I do appreciate your input :-).
>
> The Eden space graph is up and down like a yo-yo very regularly.
>  Is that normal?

I have a Web app where I capture the used memory every ten minutes. The
result is displayed as a bar graph. Even when the app is idle, the used
memory looks like a saw tooth:

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

Signature

Wojtek :-)

Twisted - 05 Jul 2007 00:53 GMT
> I have a Web app where I capture the used memory every ten minutes. The
> result is displayed as a bar graph. Even when the app is idle, the used
[quoted text clipped - 4 lines]
>  *** *** ***
> *************

Is it really idle? If it's got a GUI all kinds of short-lived FooEvent
objects are buzzing around, and every so often the GC will clear up
the accumulated cruft. If it's doing networking stuff in the
background, that activity also probably involves some rate of object
turnover. You'll see a sawtooth graph like this whenever the rate of
object turnover isn't basically zero.
Wojtek - 05 Jul 2007 01:15 GMT
Twisted wrote :
>> I have a Web app where I capture the used memory every ten minutes. The
>> result is displayed as a bar graph. Even when the app is idle, the used
[quoted text clipped - 11 lines]
> turnover. You'll see a sawtooth graph like this whenever the rate of
> object turnover isn't basically zero.

It is a Web application. When no hits are happening, it should be doing
nothing. And my code does no networking.

Mind you I do have several timers running, but then the memory use goes
from 30M to 74M over a 2 hour period, then drops back to 30M, which
seems kind of excessive for timers.

Signature

Wojtek :-)

Twisted - 05 Jul 2007 01:55 GMT
> Twisted wrote :
>
[quoted text clipped - 20 lines]
> from 30M to 74M over a 2 hour period, then drops back to 30M, which
> seems kind of excessive for timers.

5 or 6 bytes per millisecond on average. One new object created each
millisecond on average is more than enough to cause what you observe.
If the timers have resolutions of a few ms, there are a few of them,
and they generate new Dates each time they update ... there you go.
Wojtek - 05 Jul 2007 16:27 GMT
Twisted wrote :
>> Twisted wrote :
>>
[quoted text clipped - 25 lines]
> If the timers have resolutions of a few ms, there are a few of them,
> and they generate new Dates each time they update ... there you go.

The memory stat timer triggers every ten mnutes. The others are set for
24 hours.

Signature

Wojtek :-)

Bjorn Borud - 05 Jul 2007 10:06 GMT
[Wojtek <nowhere@a.com>]

| It is a Web application. When no hits are happening, it should be
| doing nothing. And my code does no networking.
|
| Mind you I do have several timers running, but then the memory use
| goes from 30M to 74M over a 2 hour period, then drops back to 30M,
| which seems kind of excessive for timers.

you're talking about the Eden space, right? 44Mb allocated in a 2 hour
period isn't really dramatic enough to warrant frenetic "optimization"
efforts for an idle app, in my opinion.  if Eden is collected only
every 2 hours there is next to no cost associated with those objects.
if you really want to reduce memory footprint, make sure that you keep
eden large enough to cope comfortably during high load.

44Mb is a trivial amount of memory if you compare to memory hogs like
Firefox :-).

-Bjørn
Tom Hawtin - 05 Jul 2007 12:42 GMT
>> I have a Web app where I capture the used memory every ten minutes. The
>> result is displayed as a bar graph. Even when the app is idle, the used
[quoted text clipped - 6 lines]
>
> Is it really idle? If it's got a GUI all kinds of short-lived FooEvent

Well, no it's not. It presumably has instrumentation attached to it. The
effect is quite normal if you are using something like jconsole.

Tom Hawtin
Bret Schuhmacher - 05 Jul 2007 03:45 GMT
Thanks Wojtek, that's exactly what I saw.  Maybe it's normal.

Rgds,

Bret
Bjorn Borud - 05 Jul 2007 09:46 GMT
[Wojtek <nowhere@a.com>]

| I have a Web app where I capture the used memory every ten
| minutes. The result is displayed as a bar graph. Even when the app is
[quoted text clipped - 4 lines]
|  *** *** ***
| *************

provided that you have an adequate sampling frequency, which in this
case would be at least two samples or more in the time between minor
collections, a distinct sawtooth shape is usually what you want for
programs like web apps.  the period of the sawtooth should be some
multiple of the request time for the great majority of requests.
(which should be simple unless you have obscene variance).

-Bjørn
Wojtek - 05 Jul 2007 16:25 GMT
Bjorn Borud wrote :
> [Wojtek <nowhere@a.com>]
>>
[quoted text clipped - 13 lines]
> multiple of the request time for the great majority of requests.
> (which should be simple unless you have obscene variance).

No, this is a totaly idle effect. This is observed on the test server
where no one is using it over-night. Logs prove that no hits were made.

With activity the pattern is much more random, with spikes as graphics
are processed. It takes a LOT of memory to rotate a 3Mbyte image.

Signature

Wojtek :-)

Bjorn Borud - 05 Jul 2007 21:13 GMT
[Wojtek <nowhere@a.com>]

| No, this is a totaly idle effect. This is observed on the test server
| where no one is using it over-night. Logs prove that no hits were
| made.

well, there is obviously some periodic activity and the sampling of
values itself probably causes objects to be created and dropped.

| With activity the pattern is much more random, with spikes as graphics
| are processed. It takes a LOT of memory to rotate a 3Mbyte image.

if you get a high rate of minor collections you may need more memory
allocated to the heap?

-Bjørn
Wojtek - 05 Jul 2007 21:48 GMT
Bjorn Borud wrote :
> [Wojtek <nowhere@a.com>]
>>
[quoted text clipped - 10 lines]
> if you get a high rate of minor collections you may need more memory
> allocated to the heap?

It is set to 2GBytes on the test machine, 1GBytes on my dev machine.

Spikes is relative. If I see use go from 8% to 20%, then back to 2%,
that 20% is a spike.

The highest I ever saw it was 80%, after several image manipulations in
a short time. The next image process caused GC to run, and the usage
dropped to 2%, then up again as more images were processed. On my dev
machine, done by myself during testing.

The usual idle is from 2% to 9%, back to 2%.

I am not worried at all about the actual memory used, just curios about
the use pattern. It may very well be that my app is not causing it at
all, but rather Tomcat doing something periodically, then GC runs.

Signature

Wojtek :-)

Twisted - 06 Jul 2007 03:27 GMT
> I am not worried at all about the actual memory used, just curios about
> the use pattern. It may very well be that my app is not causing it at
> all, but rather Tomcat doing something periodically, then GC runs.

If the app is running on the same JVM as some additional code, it's
very likely that code isn't completely idle when it's "idle". To get
the observed behavior you would not need a very high rate of object
creation, depending on the sizes of the objects. Even small objects at
the glacial pace of one every few million clock cycles is sufficient
to rack up 44MB of garbage in two hours.

As long as the sawtooth is level rather than trending upward I
wouldn't worry. If it's trending upward it's accumulating cruft
somewhere and is doomed to eventually die of OOME, probably because a
permanently-reachable collection is growing without bound. But it
doesn't look like that's happening in your case. (If it ever does,
identify the culprit collection. If it's a Map consider using
WeakHashMap. If it's anything else consider changing it from Set<Foo>
or List<Foo> or whatever to <WeakReference<Foo>> and holding a direct
reference to each Foo somewhere else that is discarded once that Foo
is no longer useful. Each WeakReference must be created on a
ReferenceQueue which must be occasionally polled to remove references
from the queue, and remove any that are found also from the
collection. A thread can sleep(1000) then lock and poll the reference
queue until empty, then lock the collection and remove all the polled
reference objects, then sleep again. In fact, there really should be
Soft and WeakFoo collection wrapper classes that do this for you --
hold an internal ReferenceQueue, wrap added items in a reference
object on that queue, are synchronized, and collectively use a worker
thread pool to periodically clean out their queues and dead reference
objects, while also handling dereferencing objects and releasing
resources. Heck maybe I should write and publish WeakList and WeakSet
wrappers ... I may need some myself some day anyway. Soft versions
would make good caches; Weak versions where you want to store
references to objects live elsewhere in a system for whatever reason
but not to otherwise-dead objects, and the collection isn't a map's
keys. A map with weak values might be useful too, for that matter...
Bjorn Borud - 06 Jul 2007 10:58 GMT
[Wojtek <nowhere@a.com>]

| The highest I ever saw it was 80%, after several image manipulations
| in a short time. The next image process caused GC to run, and the
| usage dropped to 2%, then up again as more images were processed. On
| my dev machine, done by myself during testing.

how often do minor and major GCs, respectively, run during this?  does
it run minor GCs several times per second?

-Bjørn
Bjorn Borud - 05 Jul 2007 10:00 GMT
["Bret Schuhmacher" <bret@thelastmilellc.com>]

| I've run visualgc and the GC time shows 94 collections, 59.81ms and unknown
| GC reason.  The Eden space graph is up and down like a yo-yo very regularly.
|  Is that normal?  I don't know where the tenured GC is, though.  I have an
| image of the tool running, but probably can't post it to this non binary
| newsgroup.  I'll try to extend my heap as you suggested Bjorn - I do see a
| lot of GC in the Eden space - it's wild.

it looks like your Eden space may be a bit small (I don't know what
your application does, so I can't really give you very precise
advice).  I did however remember that you had some parameters to
choose the parallell GC and that some other memory tuning options.

the general advice is to start with the "coarse grained" tuning
parameters -- start by just enlarging the heap size.  RAM is cheap and
the JVM is a lot happier when it has a bit of room.  the next thing to
do may be to tune the ratio of eden space (young generation) to the
rest of the heap etc.

switching GC algorithms is not something I have a lot of experience
doing since I usually am able to get the behavior I want just by doing
really simple tweaks and looking at visual GC.

in any case, having visual GC you can now get a better idea of what
the system is doing, so it should be possible to figure out when you
are making changes that have a positive effect :-).

-Bjørn
Joshua Cranmer - 04 Jul 2007 22:29 GMT
> 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.

From the Javadocs:

public static long currentTimeMillis()

   Returns the current time in milliseconds. Note that while the unit of
time of the return value is a millisecond, the granularity of the value
depends on the underlying operating system and may be larger. For
example, many operating systems measure time in units of tens of
milliseconds.

I notice the same thing to: when timing, I noticed that all of my times
were nicely divisible by 15 ms (e.g, 4095ms, etc.).

In short: it's the fact that Window's doesn't like telling you that 1ms
has passed.


Free Magazines

Get these publications absolutely FREE for up to 12 months. There are no hidden fees and no obligation. Simply choose a title, complete the application form and submit it. Read more ...

Oracle MagazineNetwork ComputingComputer WorldBio-IT WorldeWeekInformation WeekInfosecurity
 
Sign In
Join
My Latest Posts
My Monitored Threads
My Blog
My Photo Gallery
My Profile
My Homepage

Start New Thread
Enable EMail Alerts
Rate this Thread



©2008 Advenet LLC   Privacy Policy - Terms of Use
This website includes both content owned or controlled by Advenet as well as content owned or controlled by third parties.