Discussions

Performance and scalability: my first heap/performance analysis

Bookmark and Share Get thread feed

  1. my first heap/performance analysis (11 messages)

    • Posted by: Mordred QV
    • Posted on: January 26 2005 09:34 EST
    Hello,

    I'm asking for some advise on how to interpretate some memory heap analysis output, this is the first time I do these things and I don't want to be wrong in any of my assumptions.

    The decision to do this analysis was made because we had regular OutOfMemory exceptions in the past, often after some stress tests we did previously. Increasing the memory heap on the related (3rd party) component only seemed to slow down the problem, yet this component has to run 24/7, hence the search for memory leaks.

    I did this by a combination of things:
    - writing a benchmark that can be configured to create x threads that do y requests on the component
    - writing the component's gc output to a file, for later analysis with the tool 'GCViewer'
    - calculating the component's CPU/Heap statistics by using the Eclipse Profiler tool

    These 3 things helped me in accumalting a lot of information, one of them I'm showing below, it's a screenshot from GCViewer, wich shows a graphical representation of gc's in the heap during the run of my batchtest.

    http://myjavaserver.com/~mordred/analysis/mo-gc.gif

    I'm showing it because I'm worried.
    Notice the lower side of the blue line, wich never seems to drop in the vicinity of the previous position.

    I ran the same batchtest 4 times, each with some pause. This test ran 10 threads concurrently, each thread executing a request.

    If someone would ask me what I would think of this graph, I would say that new objects are allocated into memory but they don't get gc'd.

    I don't have to tell how high the lines went when I did a 5th test, using 100 threads, each doing 10 requests.

    Please advise on this.

    M
    Reply to this

    Threaded Messages (11)

  2. some docs / tools[ Go to top ]

    Check out http://java.sun.com/docs/hotspot/gc1.4.2/index.html

    I suggest using JVMStat - its far more detailed, and will let you see the leakage of objects from tenured to old gen.
    Also, use a profiler like http://www.ej-technologies.com/products/jprofiler/overview.html to help you track down the particular objects that are leaking into old gen.

    Fortunately, you can reproduce this issue, so it should be fairly easy with a profiler to find the leaking code.

    Happy hunting!
    Reply to this Reply to original

  3. feedback on docs / tools[ Go to top ]

    Hello Jason,

    I read the document, very usefull information, thank you.

    I used JProfiler and the results were surprising : no memory leak to be spotted, ... but I found one odd difference.
    Only frequent full gc's occured, no minor ones at any time, that's almost the opposite gc behaviour when not using a profiler (freqent minor gc's, with a full gc when the tenured gen became full).
    I find this strange, because sessions with or without this tool used exactly the same VM/program arguments. I looked where this gc behaviour could have been configured in the tool itself, but was unable to find it. Moreover, using the Eclipse Profiler tool, I have the exact same heap behaviour as w/o it.

    So the only possible explanation I can think of is that my test sessions using JProfiler must have been wrongly configured or interpreted.

    This led me to trying out jvmstat, but it seems I need to install jdk 1.5 on the server in question if I want to remotely run jstat (the new name of jvmstat) or visualgc on it from my client pc (cfr. jstad). Previous versions seem to have been discontinued.

    So, for the moment, I'll occupy myself with using Eclipse Profiler for finding any memory leaks. I believe this is possible by looking for suspicious instance count differences after the run of a batchtest.

    If there are other idea's or remarks, please don't hesitate to add them.

    M
    Reply to this Reply to original

  4. feedback on docs / tools[ Go to top ]

    Previous versions seem to have been discontinued.So, for the moment, I'll occupy myself with using Eclipse Profiler for finding any memory leaks. I believe this is possible by looking for suspicious instance count differences after the run of a batchtest.If there are other idea's or remarks, please don't hesitate to add them.M

    There are a lot of options available:

    . Use JProbe or the built-in profiler that comes with WSAD (Eclipse) and try to wath differences between allocated objects and freed objects.
    . If you are using WebSphere, there is an option to ask to the server to generate a file of extension .trcxml where you may find information about created and freed objects.
    . Use a tool such as Introscope.

    You should take a look to all the static variables (Vectors, Hashtables) where you are storing information between user requests: they tend to be the culprits in memory management problems.


    Jose Ramon Huerga

    http://www.terra.es/personal/jrhuerga
    Reply to this Reply to original

  5. feedback on docs / tools[ Go to top ]

    my suggestion is use JProbe. That will help you go down to the source level - where thoes loitering objects are originating from and which thread/method is doing it .

    i had the same problem, took me 10 minutes to found out wihch class-method was doing it

    Shahrukh
    Reply to this Reply to original

  6. reproducability problem[ Go to top ]

    I tried out most of the advise posted here, but the results are disappointing.

    There are 3 profiling methods I used on 1 use case.
    This use case involves :
    1. startup
    pause
    2. sending 100 concurrent requests to the component at 5 req/sec
    pause
    3. repeat step 2
    pause
    4. repeat step 2
    pause
    5. sending 500 concurrent requests to the component at 5 req/sec

    Profiling methods

    1) no profiler, just simple gc analysis

    screenshot :
    - http://www.myjavaserver.com/~mordred/analysis/mo-1.gif
    - http://www.myjavaserver.com/~mordred/analysis/mo-3.gif (extra test, aiming to see if full gc collects all garbage)

    What I see :
    - initial heap size used is between 300K and 800K
    - frequent minor gc's
    - fast processing of requests (a few seconds) because of thread management of the component
    - an obvious memory leak, looking at mo-3.gif, almost at the end you'll see a satisying drop 2 but running 2 batchtests afterwards (containing more requests) increases the heap size tremendously.

    2) JProfiler + simple gc analysis

    screenshot :
    - Heap_telemetry_graph.html

    What I see :
    - inital heap size used is between 1200K and 2000K (difference with profile type 1 probably because of profiler classes)
    - frequent full gc's
    - very slow processing of requests (several minutes, seems there are thread locking situations in the component)
    - can't see a memory leak

    This is confusing, I can't seem to reproduce the behaviour with profile type 1.

    3) Jprofiler + simple gc analysis + custom heap size settings (-Xms128M -Xmx128M)

    screenshot :
    - Heap_telemetry_graph_2.html

    What I see :
    - frequent full gc's
    - very slow processing of requests (several minutes, seems there are thread locking situations in the component)
    - can't see a memory leak
    - the heap size is increasing even w/o running batchtests
    - OutOfMemoryException between the 8th and 9th minute

    Again, no comparable behaviour, so the confusion gets bigger.



    MAIN PROBLEM : reproducing the gc behaviour with a profiler.

    What am I missing ??

    M
    Reply to this Reply to original

  7. adding links to screenshots[ Go to top ]

    Forget to href some screenshots :
    http://www.myjavaserver.com/~mordred/analysis/Heap_telemetry_graph.html
    http://www.myjavaserver.com/~mordred/analysis/Heap_telemetry_graph_2.html
    Reply to this Reply to original

  8. correction[ Go to top ]

    Note : "can't see a memory leak" is of course not true at profile type 3
    Reply to this Reply to original

  9. reproducability problem[ Go to top ]

    Maybe, you can make this test (without any kind of profiler, merely the JVM with -verbosegc):

    . Start the JVM with this configuration:
       -Xms128M -Xmx512M

    . Keep a long running test, with a pacing of 5 request/second, and let it run for two hours.


    At the end of the test, you may take a look at the GC traces, and see what happens. If you have effectively a memory leak, the traces should look this way:

    [Full GC 128000 -> 110000 (3 sec.)]
    ...
    [Full GC 225000 -> 205000 (5 sec.)]
    ...
    [Full GC 346000 -> 291000 (7 sec.)]
    ...
    [Full GC 457000 -> 436000 (8 sec.)]
    ...
    [Full GC 512000 -> 508000 (8 sec.)]
    ...
    java.lang.OutOfMemory
    ...
    [Full GC 513000 -> 512000 (13 sec.)]
    ...
    java.lang.OutOfMemory
    ...


    If you don't see this behaviour, then forget the issue because then probably you don't have a memory leak and your only problem is that you need to start the JVM with more memory.


    Jose Ramon Huerga
    http://www.terra.es/personal/jrhuerga
    Reply to this Reply to original

  10. it seems ok now[ Go to top ]

    Thank you for the suggestion Jose.
    I did the test, just as you said and no memory leak shows up at all, it also seemed to gc well after some heavier tests.
    So I (finally) stopped profiling.

    In any case, I learned a lot from this.

    Thx to all,
    M
    Reply to this Reply to original

  11. reproducability problem[ Go to top ]

    well as i said earlier, use JProbe Memory debugger.
    and stop wasting your time
    Reply to this Reply to original

  12. Jrobe feedback[ Go to top ]

    I forgot to mention I tried that to, the problem of slow processing occurred there to.
    Reply to this Reply to original