|
| 1 | +--- |
| 2 | +title: Example Application |
| 3 | +weight: 4 |
| 4 | + |
| 5 | +### FIXED, DO NOT MODIFY |
| 6 | +layout: learningpathall |
| 7 | +--- |
| 8 | + |
| 9 | +## Example Application. |
| 10 | + |
| 11 | +Copy and paste the following Java snippet into a file called `HeapUsageExample.java`. This code example allocates 1 million string objects to fill up the heap. We can use this example to easily observe the effects of different GC tuning parameters. |
| 12 | + |
| 13 | +```java |
| 14 | +public class HeapUsageExample { |
| 15 | + public static void main(String[] args) { |
| 16 | + System.out.println("Starting the application..."); |
| 17 | + |
| 18 | + try { |
| 19 | + // Create a large number of objects to quickly use up the heap |
| 20 | + for (int i = 0; i < 1000000; i++) { |
| 21 | + String[] array = new String[1000]; |
| 22 | + for (int j = 0; j < array.length; j++) { |
| 23 | + array[j] = "Object " + j; |
| 24 | + } |
| 25 | + } |
| 26 | + } catch (OutOfMemoryError e) { |
| 27 | + System.err.println("OutOfMemoryError caught: " + e.getMessage()); |
| 28 | + } |
| 29 | + |
| 30 | + System.out.println("Application finished."); |
| 31 | + } |
| 32 | +} |
| 33 | +``` |
| 34 | + |
| 35 | +### Enable GC logging |
| 36 | + |
| 37 | +To observe the what the GC is doing, one option is to enabling logging whilst the JVM is running. To enable this, we need to pass in some command-line arguments. The `gc` option logs the GC information we are interested. The `filecount` option creates a rolling log to prevent uncontrolled growth of logs with the drawback that historical logs may be rewritten and lost. Run the following command from the terminal to enable logging on JDK 11 onwards. |
| 38 | + |
| 39 | +```bash |
| 40 | +java -Xms512m -Xmx1024m -XX:+UseSerialGC -Xlog:gc:file=gc.log:tags,uptime,time,level:filecount=10,filesize=16m HeapUsageExample.java |
| 41 | +``` |
| 42 | + |
| 43 | +Use the following command if you are using JDK8. |
| 44 | + |
| 45 | +```bash |
| 46 | +java -Xms512m -Xmx1024m -XX:+UseSerialGC -Xloggc:gc.log -XX:+PrintGCTimeStamps -XX:+UseGCLogFileRotation HeapUsageExample.java |
| 47 | +``` |
| 48 | + |
| 49 | +The `-Xms512m` and `-Xmx1024` options create a minimum and maximum heap size of 512 MiB and 1GiB respectively. This is simply so we do not have to wait for too long to see activity within the GC. Additionally, we force the JVM to use the serial garbage collector with the `-XX:+UseSerialGC` flag. |
| 50 | + |
| 51 | +You will now see logs, named `gc.log.*` within the same directory. Viewing the contents you will see the following. |
| 52 | + |
| 53 | +```output |
| 54 | +[2024-11-08T15:04:54.304+0000][0.713s][info][gc ] GC(2) Pause Young (Allocation Failure) 139M->3M(494M) 3.627ms |
| 55 | +... |
| 56 | +[2024-11-08T15:04:54.350+0000][0.759s][info][gc ] GC(3) Pause Young (Allocation Failure) 139M->3M(494M) 3.699ms |
| 57 | +``` |
| 58 | + |
| 59 | +These logs provide insights into the frequency, duration, and impact of Young garbage collection events. The results may vary depending on your system. |
| 60 | + |
| 61 | + - Frequency: ~ every 46 ms |
| 62 | + - Pause duration: ~ 3.6 ms |
| 63 | + - Reduction size: ~ 139 MB (or 3M objects) |
| 64 | + |
| 65 | +This logging method has the benefit of being verbose but at the tradeoff of clarity. Furthermore, this method clearly isn't suitable for a running process which makes debugging a live environment slightly more challenging. |
| 66 | + |
| 67 | +### Use jstat to observe real-time GC statistics |
| 68 | + |
| 69 | +The following java code snippet is a long-running example that prints out a random integer and double precision floating point number 4 times a second. Copy the example below and paste into a file called `WhileLoopExample.java`. |
| 70 | + |
| 71 | +```java |
| 72 | +import java.util.Random; |
| 73 | + |
| 74 | +public class GenerateRandom { |
| 75 | + |
| 76 | + public static void main(String[] args) { |
| 77 | + Random rand = new Random(); |
| 78 | + |
| 79 | + while (true) { |
| 80 | + // Generate random integer in range 0 to 999 |
| 81 | + int rand_int1 = rand.nextInt(1000); |
| 82 | + |
| 83 | + // Print random integer |
| 84 | + System.out.println("Random Integers: " + rand_int1); |
| 85 | + |
| 86 | + // Generate random double |
| 87 | + double rand_dub1 = rand.nextDouble(); |
| 88 | + |
| 89 | + // Print random double |
| 90 | + System.out.println("Random Doubles: " + rand_dub1); |
| 91 | + |
| 92 | + // Sleep for 1 second (1000 milliseconds) |
| 93 | + try { |
| 94 | + Thread.sleep(250); |
| 95 | + } catch (InterruptedException e) { |
| 96 | + System.err.println("Thread interrupted: " + e.getMessage()); |
| 97 | + } |
| 98 | + } |
| 99 | + } |
| 100 | +} |
| 101 | +``` |
| 102 | + |
| 103 | +Run the following command and open up a separate terminal session. Start the Java program with the command below. This will use the default parameters for the garbage collection. |
| 104 | + |
| 105 | +```bash |
| 106 | +java WhileLoopExample.java |
| 107 | +``` |
| 108 | +On the other terminal session, we use the `jstat` command to print out the JVM statistics specifically related to the GC using the `-gcutil` flag. |
| 109 | + |
| 110 | +```bash |
| 111 | +jstat -gcutil $(pgrep java) 1000 |
| 112 | +``` |
| 113 | + |
| 114 | + |
| 115 | +You will obserse an output like the following until `ctl+c` is pressed. |
| 116 | + |
| 117 | +```output |
| 118 | + S0 S1 E O M CCS YGC YGCT FGC FGCT CGC CGCT GCT |
| 119 | + 0.00 100.00 6.11 1.81 71.05 73.21 1 0.010 0 0.000 0 0.000 0.010 |
| 120 | + 0.00 100.00 6.11 1.81 71.05 73.21 1 0.010 0 0.000 0 0.000 0.010 |
| 121 | + 0.00 100.00 6.11 1.81 71.05 73.21 1 0.010 0 0.000 0 0.000 0.010 |
| 122 | +... |
| 123 | + 0.00 100.00 6.11 1.81 71.05 73.21 1 0.010 0 0.000 0 0.000 0.010 |
| 124 | +``` |
| 125 | + |
| 126 | +The columns of interest are: |
| 127 | +- **E (Eden Space Utilization)**: The percentage of the Eden space that is currently used. High utilization indicates frequent allocations and can trigger minor GCs. |
| 128 | +- **O (Old Generation Utilization)**: The percentage of the Old (Tenured) generation that is currently used. High utilization can lead to Full GCs, which are more expensive. |
| 129 | +- **YGCT (Young Generation GC Time)**: The total time (in seconds) spent in Young Generation (minor) GC events. High values indicate frequent minor GCs, which can impact performance. |
| 130 | +- **FGCT (Full GC Time)**: The total time (in seconds) spent in Full GC events. High values indicate frequent Full GCs, which can significantly impact performance. |
| 131 | +- **GCT (Total GC Time)**: The total time (in seconds) spent in all GC events (Young, Full, and Concurrent). This provides an overall view of the time spent in GC, helping to assess the impact on application performance. |
| 132 | + |
| 133 | + |
0 commit comments