Newsletter sign-up
View all newsletters

Sign up for our technology specific newsletters.

Enterprise Java
Email Address:
JavaWorld.com

Diagnose common runtime problems with hprof

Track down the culprits behind your application failures

By Bill Pierce, JavaWorld.com, 12/07/01

  • Digg
  • Reddit
  • SlashDot
  • Stumble
  • del.icio.us
  • Technorati
  • dzone

Page 3 of 6

Let's look at select parts of the profile file. The Sites section's first few lines clearly show what is happening:

SITES BEGIN (ordered by live bytes) Mon Sep  3 19:16:29 2001
          percent         live     alloc'ed       stack class
 rank   self  accum    bytes objs     bytes  objs trace name
    1 97.31% 97.31% 10280000 10000 10280000 10000  1995 [B
    2  0.39% 97.69%    40964     1    81880    10  1996 [L<Unknown>;
    3  0.38% 98.07%    40000 10000    40000 10000  1994 MemoryConsumer
    4  0.16% 98.23%    16388     1    16388     1  1295 [C
    5  0.16% 98.38%    16388     1    16388     1  1304 [C
    ...


There are 10,000 objects of type byte[] ([B in VM-speak) as well as 10,000 MemoryConsumer objects. The byte arrays take up 10,280,000 bytes, so apparently there is overhead just above the raw bytes that each array consumes. Since the number of objects allocated equals the number of live objects, we can conclude that none of these objects could be garbage collected. This is consistent with our expectations.

Another interesting point: the memory reported to be consumed by the MemoryConsumer objects does not include the memory consumed by the byte arrays. This shows that our profiling tool does not expose hierarchical containment relationships, but rather class-by-class statistics. This is important to understand when using hprof to pinpoint a memory leak.

Now, where did those leaky byte arrays come from? Notice that the MemoryConsumer objects and the byte arrays reference traces 1994 and 1995 in the following Trace section. Lo and behold, these traces tell us that the MemoryConsumer objects were created in the MemoryLeak class's main() method and that the byte arrays were created in the constructor (<init>() method in VM-speak). We've found our memory leak, line numbers and all: 

TRACE 1994: (thread=1)
        MemoryLeak.main(MemoryLeak.java:16)
TRACE 1995: (thread=1)
        MemoryConsumer.<init>(MemoryLeak.java:36)
        MemoryLeak.main(MemoryLeak.java:16)


Diagnose a CPU hog

In Listing 2, a BusyWork class has each thread call a method that regulates how much the thread works by varying its sleep time in between bouts of performing CPU-intensive calculations:

Listing 2. CPUHog program

01 /** Main class for control test. */
02 public class CPUHog {
03    public static void main(String[] args) {
04 
05       Thread slouch, workingStiff, workaholic;
06       slouch       = new Slouch();
07       workingStiff = new WorkingStiff();
08       workaholic   = new Workaholic();
09 
10       slouch.start();
11       workingStiff.start();
12       workaholic.start();
13    }
14 }
15 
16 /** Low CPU utilization thread. */
17 class Slouch extends Thread {
18   public Slouch() {
19      super("Slouch");
20   }
21   public void run() {
22      BusyWork.slouch();
23   }
24 }
25 
26 /** Medium CPU utilization thread. */
27 class WorkingStiff extends Thread {
28   public WorkingStiff() {
29       super("WorkingStiff");
30   }
31   public void run() {
32      BusyWork.workNormally();
33   }
34 }
35 
36 /** High CPU utilization thread. */
37 class Workaholic extends Thread {
38   public Workaholic() {
39       super("Workaholic");
40   }
41   public void run() {
42      BusyWork.workTillYouDrop();
43   }
44 }
45 
46 /** Class with static methods to consume varying amounts
47  *  of CPU time. */
48 class BusyWork {
49 
50   public static int callCount = 0;
51 
52   public static void slouch() {
53     int SLEEP_INTERVAL = 1000;
54     computeAndSleepLoop(SLEEP_INTERVAL); 
55   }
56 
57   public static void workNormally() {
58     int SLEEP_INTERVAL = 100;
59     computeAndSleepLoop(SLEEP_INTERVAL); 
60   }
61 
62   public static void workTillYouDrop() {
63     int SLEEP_INTERVAL = 10;
64     computeAndSleepLoop(SLEEP_INTERVAL); 
65   }
66   
67   private static void computeAndSleepLoop(int sleepInterval) {
68      int MAX_CALLS = 10000;
69      while (callCount < MAX_CALLS) {
70         computeAndSleep(sleepInterval);
71      }
72   } 
73 
74   private static void computeAndSleep(int sleepInterval) {
75         int    COMPUTATIONS = 1000;
76         double result;
77         
78         // Compute.
79         callCount++;
80         for (int i = 0; i < COMPUTATIONS; i++) {
81            result = Math.atan(callCount * Math.random());         
82         }
83 
84         // Sleep.
85         try {
86            Thread.currentThread().sleep(sleepInterval);
87         } catch (InterruptedException ie) {
88            // Do nothing.
89         }
90 
91   } // End computeAndSleep.
92 } // End BusyWork.


There are three threads -- Workaholic, WorkingStiff, and Slouch -- whose work ethics vary by orders of magnitude, judging by the work they choose to do. Examine the profile's CPU Samples section shown below. The three highest ranked traces show that the CPU spent most of its time calculating random numbers and arc tangents, as we would expect:

  • Digg
  • Reddit
  • SlashDot
  • Stumble
  • del.icio.us
  • Technorati
  • dzone
Comments (1)
Login
Forgot your account info?

MindblowingBy Anonymous on November 1, 2009, 7:02 amThe article is really helpful and complex information is presented in a very simple way. The information gets very helpful to me to trroubleshoot the performance...

Reply | Read entire comment

View all comments

Add comment
Anonymous comments subject to approval. Register here for member benefits.
Have a JavaWorld account? Log in here. Register now for a free account.
Resources