Tuning JVM parameters:
jstat - to monitor the memory usage and garbage collector stats
./jstat -gcutil 8556 1 1
Please add the following parameters to the JVM in the weblogic startup script.
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/home/user/gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/user
StackOverflow will occur:
http://download.oracle.com/javase/6/docs/api/java/util/Properties.html
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4906193
1) Create a Properties object based on another (the Defaults parameter object). By example, Properties props1 = new Properties(System.getProperties()).
2) the newly created object is used again as Default to create others. By example, Properties props2 = new Properties(props1);
3) repeat 1) and 2) too many times
4) if you try to get a parameter which is not in the newest properties object, it will try to recursively get the parameter from its Defaults parameter object, which in turn has its own Defaults parameter object, and so on. If the chain of Properties objects is too long, searching for an unexistent value may lead to a StackOverflow exception.
Parellel GC:
When we are doing a lot of processing it makes sense to choose the parallel collector. Note that when using Coherence we need to obtain data as fast as possible with a minimal amount of pause time. In this case, we can tune the parallel collector for a certain service level, i.e., a goal for the maximum introduced pause time while maintaining a certain throughput. By using the parallel collector we can specify the following service parameters:
maximum garbage collection pause time (-XX:MaxGCPauseMillis=N – if this parameter is specified the collector attempts to reach this service level.
throughput (-XX:GCTimeRatio=N) – the throughput goal 1 / (1+N) is measured as the time spent garbage collecting versus time spent running the application.
The parameters for the parallel collector can be set as follows:
1
-server -Xms1024m -Xmx1024m -XX:NewRatio=2 -XX:+UseParallelGC -XX:ParallelGCThreads=2 -XX:MaxGCPauseMillis=200 -XX:GCTimeRatio=19 -XX:+UseParallelOldGC -XX:+UseTLAB -XX:LargePageSizeInBytes=2048k -XX:+UseLargePages
-server – select the JIT compiler.
-Xms – initial heap size.
-Xmx – maximum heap size.
-XX:NewRatio=N – sets the young generation to heap size / (1 + N).
-XX:-UseParallelGC – select the parallel collector for minor collections.
-XX:ParallelGCThreads – sets the number of garbage collector threads, i.e., the number of CPUs to be used.
-XX:MaxGCPauseMillis – sets the maximum pause time goal.
-XX:GCTimeRatio=N – sets the throughput goal that is measured in terms of the time spent doing garbage collection versus the time spent outside of garbage collection. In the case above with N=19, the garbage collection time to application time is set to 1 / (1+N) = 1 / 20, i.e., 5% of the total time is spent in garbage collection.
-XX:-UseParallelOldGC – selects the parallel collector for major collections.
-XX:+UseTLAB – enables thread-local object allocation. More information on thread local allocation can be found in the ‘Compaction and Thread Local Area’ section of the Tune the JVM that runs Coherence post.
-XX:LargePageSizeInBytes – sets the large page size used for the Java heap. We set this equal to the operating system parameter: Hugepagesize, which in our case is 2048kB
-XX:+UseLargePages – use large page memory. The steps involved on how to configure large pages in the operating system can be found in the ‘Call profiling and large pages’ section of the Tune the JVM that runs Coherence post.
MEM_ARGS="-server -Xms1024m -Xmx1024m -XX:NewRatio=2 -XX:+UseParallelGC -XX:ParallelGCThreads=2 -XX:MaxGCPauseMillis=200 -XX:GCTimeRatio=19 -XX:+UseParallelOldGC -XX:+UseTLAB -XX:LargePageSizeInBytes=2048k -XX:+UseLargePages"
============================================
# output for the -XX:+PrintGCApplicationStoppedTime option
02
Total time for which application threads were stopped: 0.0001760 seconds
03
# output for the -XX:+PrintGCApplicationConcurrentTime option
04
Application time: 0.5882530 seconds
05
...
06
# output for the -verbosegc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps options
07
1787.096: [GC [PSYoungGen: 331731K->6970K(337472K)] 1027141K->703972K(1037888K), 0.0225070 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
08
Total time for which application threads were stopped: 0.0227760 seconds
09
Application time: 0.0250060 seconds
10
...
11
1793.293: [GC [PSYoungGen: 331706K->3635K(337984K)] 1028708K->702533K(1038400K), 0.0164910 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
12
1793.325: [Full GC [PSYoungGen: 3635K->0K(337984K)] [ParOldGen: 698897K->19384K(700416K)] 702533K->19384K(1038400K) [PSPermGen: 40255K->39956K(81920K)], 0.3813170 secs] [Times: user=0.29 sys=0.02, real=0.39 secs]
13
Total time for which application threads were stopped: 0.4218670 seconds
14
Application time: 0.0016200 seconds
15
...
16
1798.766: [GC [PSYoungGen: 325504K->11112K(336640K)] 344888K->30496K(1037056K), 0.0154580 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
17
Total time for which application threads were stopped: 0.0159380 seconds
18
Application time: 0.1704330 seconds
19
...
20
3470.295: [GC-- [PSYoungGen: 337920K->337920K(342144K)] 1035431K->1038331K(1042560K), 0.1103830 secs] [Times: user=0.13 sys=0.00, real=0.11 secs]
21
3470.405: [Full GC [PSYoungGen: 337920K->0K(342144K)] [ParOldGen: 700411K->25867K(700416K)] 1038331K->25867K(1042560K) [PSPermGen: 40003K->39987K(83968K)], 0.2131430 secs] [Times: user=0.29 sys=0.00, real=0.22 secs]
22
Total time for which application threads were stopped: 0.3239480 seconds
23
Application time: 0.0004270 seconds
24
...
25
5075.141: [GC [PSYoungGen: 329440K->3008K(338816K)] 1025250K->701386K(1039232K), 0.0133860 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
26
5075.154: [Full GC [PSYoungGen: 3008K->0K(338816K)] [ParOldGen: 698378K->16712K(700416K)] 701386K->16712K(1039232K) [PSPermGen: 40040K->40023K(83968K)], 0.4227600 secs] [Times: user=0.36 sys=0.01, real=0.42 secs]
27
Total time for which application threads were stopped: 0.4365580 seconds
28
Application time: 0.0004490 seconds
Analysis:
The garbage collection log has the following structure: collector type: occupancy before the collection -> occupancy after the collection, pause time in seconds. When we look at the collection occurring at 1793.293, we have a minor collection in which the parallel collector is used. Here 331706 – 3335 = 328371kB were collected in 16 milliseconds. Subsequently, a major collection occurred at 1793.325, in which the total heap usage dropped from 702533kB to 19384kB. The message afterward shows that the application was stopped for 421 milliseconds. As can be seen from the logging above minor collections do not typically introduce long pause times. However, major collections, though infrequent, introduce a much larger pause time. If pause times introduced by the major collections can be controlled not to run into the seconds range this is something we can live with. One remark is in order though, when the heap is increased it is very likely the major collection pause time to increase as well. Note that this is dependent on the number of live objects on the heap. When using an in-memory cache we should strive to an object occupancy of no more than one-third of the heap (with the heap size being around 2048MB). This usually means that, we have to run more JVM instances if we want to store more data or resort to storing data off-heap or use the elastic data feature that automatically fails-over to disk when the configured RAM part is full. More information about Coherence storage can be found in the post Data Storage Structures in Coherence.
Some handy command-line tools that ship with the HotSpot JVM are:
jstat – to monitor the memory usage and garbage collection statistics.
jmap – to print shared object memory maps or heap memory details.
jhat – parses a java heap dump file (generated, for example, by jmap) and launches a web server that can be reached at:http://hostname:7000.
jconsole – a graphical monitoring tool that also provides an MBean browser.
An example jstat output is the following:
1
[oracle@edu-wls-rh bin]$ ./jstat -gcutil 8556 1 1
2
S0 S1 E O P YGC YGCT FGC FGCT GCT
3
0.00 22.05 43.99 33.90 50.15 1652 31.886 5 1.341 33.228
This tells us that we have had 1652 minor collections (YGC) that took 31.886 seconds and 5 major collections (FGC) that took 1.341 seconds.
To obtain a heap summary, the garbage collection algorithm used, the heap configuration and generation wise heap usage, we can use jmap as
jstat - to monitor the memory usage and garbage collector stats
./jstat -gcutil 8556 1 1
Please add the following parameters to the JVM in the weblogic startup script.
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/home/user/gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/user
StackOverflow will occur:
http://download.oracle.com/javase/6/docs/api/java/util/Properties.html
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4906193
1) Create a Properties object based on another (the Defaults parameter object). By example, Properties props1 = new Properties(System.getProperties()).
2) the newly created object is used again as Default to create others. By example, Properties props2 = new Properties(props1);
3) repeat 1) and 2) too many times
4) if you try to get a parameter which is not in the newest properties object, it will try to recursively get the parameter from its Defaults parameter object, which in turn has its own Defaults parameter object, and so on. If the chain of Properties objects is too long, searching for an unexistent value may lead to a StackOverflow exception.
Parellel GC:
When we are doing a lot of processing it makes sense to choose the parallel collector. Note that when using Coherence we need to obtain data as fast as possible with a minimal amount of pause time. In this case, we can tune the parallel collector for a certain service level, i.e., a goal for the maximum introduced pause time while maintaining a certain throughput. By using the parallel collector we can specify the following service parameters:
maximum garbage collection pause time (-XX:MaxGCPauseMillis=N – if this parameter is specified the collector attempts to reach this service level.
throughput (-XX:GCTimeRatio=N) – the throughput goal 1 / (1+N) is measured as the time spent garbage collecting versus time spent running the application.
The parameters for the parallel collector can be set as follows:
1
-server -Xms1024m -Xmx1024m -XX:NewRatio=2 -XX:+UseParallelGC -XX:ParallelGCThreads=2 -XX:MaxGCPauseMillis=200 -XX:GCTimeRatio=19 -XX:+UseParallelOldGC -XX:+UseTLAB -XX:LargePageSizeInBytes=2048k -XX:+UseLargePages
-server – select the JIT compiler.
-Xms – initial heap size.
-Xmx – maximum heap size.
-XX:NewRatio=N – sets the young generation to heap size / (1 + N).
-XX:-UseParallelGC – select the parallel collector for minor collections.
-XX:ParallelGCThreads – sets the number of garbage collector threads, i.e., the number of CPUs to be used.
-XX:MaxGCPauseMillis – sets the maximum pause time goal.
-XX:GCTimeRatio=N – sets the throughput goal that is measured in terms of the time spent doing garbage collection versus the time spent outside of garbage collection. In the case above with N=19, the garbage collection time to application time is set to 1 / (1+N) = 1 / 20, i.e., 5% of the total time is spent in garbage collection.
-XX:-UseParallelOldGC – selects the parallel collector for major collections.
-XX:+UseTLAB – enables thread-local object allocation. More information on thread local allocation can be found in the ‘Compaction and Thread Local Area’ section of the Tune the JVM that runs Coherence post.
-XX:LargePageSizeInBytes – sets the large page size used for the Java heap. We set this equal to the operating system parameter: Hugepagesize, which in our case is 2048kB
-XX:+UseLargePages – use large page memory. The steps involved on how to configure large pages in the operating system can be found in the ‘Call profiling and large pages’ section of the Tune the JVM that runs Coherence post.
MEM_ARGS="-server -Xms1024m -Xmx1024m -XX:NewRatio=2 -XX:+UseParallelGC -XX:ParallelGCThreads=2 -XX:MaxGCPauseMillis=200 -XX:GCTimeRatio=19 -XX:+UseParallelOldGC -XX:+UseTLAB -XX:LargePageSizeInBytes=2048k -XX:+UseLargePages"
============================================
# output for the -XX:+PrintGCApplicationStoppedTime option
02
Total time for which application threads were stopped: 0.0001760 seconds
03
# output for the -XX:+PrintGCApplicationConcurrentTime option
04
Application time: 0.5882530 seconds
05
...
06
# output for the -verbosegc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps options
07
1787.096: [GC [PSYoungGen: 331731K->6970K(337472K)] 1027141K->703972K(1037888K), 0.0225070 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
08
Total time for which application threads were stopped: 0.0227760 seconds
09
Application time: 0.0250060 seconds
10
...
11
1793.293: [GC [PSYoungGen: 331706K->3635K(337984K)] 1028708K->702533K(1038400K), 0.0164910 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
12
1793.325: [Full GC [PSYoungGen: 3635K->0K(337984K)] [ParOldGen: 698897K->19384K(700416K)] 702533K->19384K(1038400K) [PSPermGen: 40255K->39956K(81920K)], 0.3813170 secs] [Times: user=0.29 sys=0.02, real=0.39 secs]
13
Total time for which application threads were stopped: 0.4218670 seconds
14
Application time: 0.0016200 seconds
15
...
16
1798.766: [GC [PSYoungGen: 325504K->11112K(336640K)] 344888K->30496K(1037056K), 0.0154580 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
17
Total time for which application threads were stopped: 0.0159380 seconds
18
Application time: 0.1704330 seconds
19
...
20
3470.295: [GC-- [PSYoungGen: 337920K->337920K(342144K)] 1035431K->1038331K(1042560K), 0.1103830 secs] [Times: user=0.13 sys=0.00, real=0.11 secs]
21
3470.405: [Full GC [PSYoungGen: 337920K->0K(342144K)] [ParOldGen: 700411K->25867K(700416K)] 1038331K->25867K(1042560K) [PSPermGen: 40003K->39987K(83968K)], 0.2131430 secs] [Times: user=0.29 sys=0.00, real=0.22 secs]
22
Total time for which application threads were stopped: 0.3239480 seconds
23
Application time: 0.0004270 seconds
24
...
25
5075.141: [GC [PSYoungGen: 329440K->3008K(338816K)] 1025250K->701386K(1039232K), 0.0133860 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
26
5075.154: [Full GC [PSYoungGen: 3008K->0K(338816K)] [ParOldGen: 698378K->16712K(700416K)] 701386K->16712K(1039232K) [PSPermGen: 40040K->40023K(83968K)], 0.4227600 secs] [Times: user=0.36 sys=0.01, real=0.42 secs]
27
Total time for which application threads were stopped: 0.4365580 seconds
28
Application time: 0.0004490 seconds
Analysis:
The garbage collection log has the following structure: collector type: occupancy before the collection -> occupancy after the collection, pause time in seconds. When we look at the collection occurring at 1793.293, we have a minor collection in which the parallel collector is used. Here 331706 – 3335 = 328371kB were collected in 16 milliseconds. Subsequently, a major collection occurred at 1793.325, in which the total heap usage dropped from 702533kB to 19384kB. The message afterward shows that the application was stopped for 421 milliseconds. As can be seen from the logging above minor collections do not typically introduce long pause times. However, major collections, though infrequent, introduce a much larger pause time. If pause times introduced by the major collections can be controlled not to run into the seconds range this is something we can live with. One remark is in order though, when the heap is increased it is very likely the major collection pause time to increase as well. Note that this is dependent on the number of live objects on the heap. When using an in-memory cache we should strive to an object occupancy of no more than one-third of the heap (with the heap size being around 2048MB). This usually means that, we have to run more JVM instances if we want to store more data or resort to storing data off-heap or use the elastic data feature that automatically fails-over to disk when the configured RAM part is full. More information about Coherence storage can be found in the post Data Storage Structures in Coherence.
Some handy command-line tools that ship with the HotSpot JVM are:
jstat – to monitor the memory usage and garbage collection statistics.
jmap – to print shared object memory maps or heap memory details.
jhat – parses a java heap dump file (generated, for example, by jmap) and launches a web server that can be reached at:http://hostname:7000.
jconsole – a graphical monitoring tool that also provides an MBean browser.
An example jstat output is the following:
1
[oracle@edu-wls-rh bin]$ ./jstat -gcutil 8556 1 1
2
S0 S1 E O P YGC YGCT FGC FGCT GCT
3
0.00 22.05 43.99 33.90 50.15 1652 31.886 5 1.341 33.228
This tells us that we have had 1652 minor collections (YGC) that took 31.886 seconds and 5 major collections (FGC) that took 1.341 seconds.
To obtain a heap summary, the garbage collection algorithm used, the heap configuration and generation wise heap usage, we can use jmap as
No comments:
Post a Comment