Showing posts with label jvm. Show all posts
Showing posts with label jvm. Show all posts

Sunday, October 25, 2015

Learning Java Eden Space


If you have been a java developer and you should came across java garbage collection that free the object created by your application from occupied all the java heap. In today article, we will look into java heap and particular into java eden space. First, let's look at the general java heap.

From this StackOverflow

Heap memory

The heap memory is the runtime data area from which the Java VM allocates memory for all class instances and arrays. The heap may be of a fixed or variable size. The garbage collector is an automatic memory management system that reclaims heap memory for objects.

Eden Space: The pool from which memory is initially allocated for most objects.

Survivor Space: The pool containing objects that have survived the garbage collection of the Eden space.

Tenured Generation: The pool containing objects that have existed for some time in the survivor space.

When you created a new object, jvm allocate a part of the heap for your object. Visually, it is something as of following.

                   +-----+  
                   |     |  
   <-minor gc->    v     v   <------------- major gc---------------------->  
   +------------+-----+-----+----------------------------------------------+-------------+  
   |            |     |     |                                              |             |
   | Eden       | S0  | S1  |  Tenure Generation                           | Perm gen    |
   |            |     |     |                                              |             |
   +------------+-----+-----+----------------------------------------------+-------------+  
    <---------------------jvm heap (-Xms -Xmx)----------------------------> -XX:PermSize  
    <-- young gen(-Xmn)---->                                                -XX:MaxPermSize  

When eden space is fill with object and minor gc is performed, survive objects will copy to either survivor spaces; s0 or s1. At a time, one of the survivor space is empty. Because the eden space are relatively small in comparison to the tenure generation, hence, the gc that happened in eden space is quick.  Eden and both survivors spaces are also known as young or new generation.

To understand into how young generation heap get free, this article provided detail explanation.

The Sun/Oracle HotSpot JVM further divides the young generation into three sub-areas: one large area named "Eden" and two smaller "survivor spaces" named "From" and "To". As a rule, new objects are allocated in "Eden" (with the exception that if a new object is too large to fit into "Eden" space, it will be directly allocated in the old generation). During a GC, the live objects in "Eden" first move into the survivor spaces and stay there until they have reached a certain age (in terms of numbers of GCs passed since their creation), and only then they are transferred to the old generation. Thus, the role of the survivor spaces is to keep young objects in the young generation for a little longer than just their first GC, in order to be able to still collect them quickly should they die soon afterwards.
Based on the assumption that most of the young objects may be deleted during a GC, a copying strategy ("copy collection") is being used for young generation GC. At the beginning of a GC, the survivor space "To" is empty and objects can only exist in "Eden" or "From". Then, during the GC, all objects in "Eden" that are still being referenced are moved into "To". Regarding "From", the still referenced objects in this space are handled depending on their age. If they have not reached a certain age ("tenuring threshold"), they are also moved into "To". Otherwise they are moved into the old generation. At the end of this copying procedure, "Eden" and "From" can be considered empty (because they only contain dead objects), and all live objects in the young generation are located in "To". Should "to" fill up at some point during the GC, all remaining objects are moved into the old generation instead (and will never return). As a final step, "From" and "To" swap their roles (or, more precisely, their names) so that "To" is empty again for the next GC and "From" contains all remaining young objects.

As you can observed based on the visual diagram above, you can set the amount of heap for the eden and survivor space using -Xmn in the java parameter. There is also -XX:SurvivorRatio=ratio and you can find further information here for java8. Note that in the diagram above, Perm gen has been removed in java8, hence always refer find out what java run your application and refer to the right version of java documentation.

If you want to monitor the statistics of eden , you can use jstats. Previously I have written an article about jstat and you can read here what is jstat and how to use it. You can also enable gc log statistics and so jvm will write the gc statistics into a file, you can further read more here.

Till then we meet again in the next article. Please consider donate, thank you!

Sunday, June 7, 2015

code path learning on elasticsearch monitoring jvm logging

Today we are going to study the following info logging from elasticsearch 0.90.7.

1:  [2015-03-25 00:45:07,008][INFO ][monitor.jvm       ] [node03] [gc][ParNew][649825][391294] duration [829ms], collections [1]/[1.1s], total [829ms]/[2.8h], memory [8.4gb]->[8.5gb]/[14gb], all_pools {[Code Cache] [14.4mb]->[14.4mb]/[48mb]}{[Par Eden Space] [34.4mb]->[460.1kb]/[133.1mb]}{[Par Survivor Space] [16.6mb]->[16.6mb]/[16.6mb]}{[CMS Old Gen] [8.3gb]->[8.4gb]/[13.8gb]}{[CMS Perm Gen] [43.5mb]->[43.5mb]/[82mb]}  
2:  [2015-03-25 00:45:11,529][INFO ][monitor.jvm       ] [node03] [gc][ParNew][649829][391299] duration [921ms], collections [1]/[1.3s], total [921ms]/[2.8h], memory [8.7gb]->[8.8gb]/[14gb], all_pools {[Code Cache] [14.4mb]->[14.4mb]/[48mb]}{[Par Eden Space] [203.2kb]->[4.1mb]/[133.1mb]}{[Par Survivor Space] [16.6mb]->[16.6mb]/[16.6mb]}{[CMS Old Gen] [8.7gb]->[8.8gb]/[13.8gb]}{[CMS Perm Gen] [43.5mb]->[43.5mb]/[82mb]}  
3:  [2015-03-25 00:45:13,800][INFO ][monitor.jvm       ] [node03] [gc][ParNew][649831][391301] duration [744ms], collections [1]/[1.1s], total [744ms]/[2.8h], memory [8.9gb]->[9gb]/[14gb], all_pools {[Code Cache] [14.4mb]->[14.4mb]/[48mb]}{[Par Eden Space] [5.7mb]->[537.8kb]/[133.1mb]}{[Par Survivor Space] [16.6mb]->[16.6mb]/[16.6mb]}{[CMS Old Gen] [8.9gb]->[9gb]/[13.8gb]}{[CMS Perm Gen] [43.5mb]->[43.5mb]/[82mb]}  
4:  [2015-03-25 00:45:15,088][INFO ][monitor.jvm       ] [node03] [gc][ParNew][649832][391302] duration [891ms], collections [1]/[1.2s], total [891ms]/[2.8h], memory [9gb]->[9.1gb]/[14gb], all_pools {[Code Cache] [14.4mb]->[14.4mb]/[48mb]}{[Par Eden Space] [537.8kb]->[5.4mb]/[133.1mb]}{[Par Survivor Space] [16.6mb]->[16.6mb]/[16.6mb]}{[CMS Old Gen] [9gb]->[9.1gb]/[13.8gb]}{[CMS Perm Gen] [43.5mb]->[43.5mb]/[82mb]}  
5:  [2015-03-25 00:45:17,287][INFO ][monitor.jvm       ] [node03] [gc][ParNew][649834][391304] duration [770ms], collections [1]/[1.1s], total [770ms]/[2.8h], memory [9.2gb]->[9.3gb]/[14gb], all_pools {[Code Cache] [14.4mb]->[14.4mb]/[48mb]}{[Par Eden Space] [359.7kb]->[357.3kb]/[133.1mb]}{[Par Survivor Space] [16.6mb]->[16.6mb]/[16.6mb]}{[CMS Old Gen] [9.2gb]->[9.3gb]/[13.8gb]}{[CMS Perm Gen] [43.5mb]->[43.5mb]/[82mb]}  
6:  [2015-03-25 00:45:18,531][INFO ][monitor.jvm       ] [node03] [gc][ParNew][649835][391305] duration [713ms], collections [1]/[1.2s], total [713ms]/[2.8h], memory [9.3gb]->[9.4gb]/[14gb], all_pools {[Code Cache] [14.4mb]->[14.4mb]/[48mb]}{[Par Eden Space] [357.3kb]->[441.9kb]/[133.1mb]}{[Par Survivor Space] [16.6mb]->[16.6mb]/[16.6mb]}{[CMS Old Gen] [9.3gb]->[9.4gb]/[13.8gb]}{[CMS Perm Gen] [43.5mb]->[43.5mb]/[82mb]}  

Okay, before we go into this codes, let's analyze based on just the output above. We have info logging, nothing very seriously but as a sign we should already pay attention. Happened on one of the node, node03 with class file from package monitor.jvm. Let's take the first line in the log above and format nicely and so we can analyze further. Read below.

 [2015-03-25 00:45:07,008][INFO ][monitor.jvm       ] [node03] [gc]  
   
 [ParNew][649825][391294] duration [829ms],   
 collections [1]/[1.1s],   
 total [829ms]/[2.8h],   
 memory [8.4gb]->[8.5gb]/[14gb],   
 all_pools {[Code Cache]          [14.4mb]->[ 14.4mb ] / [   48mb]}  
           {[Par Eden Space]      [34.4mb]->[460.1kb ] / [133.1mb]}  
           {[Par Survivor Space]  [16.6mb]->[ 16.6mb ] / [ 16.6mb]}  
           {[CMS Old Gen]         [8.3gb] ->[  8.4gb ] / [ 13.8gb]}  
           {[CMS Perm Gen]        [43.5mb]->[ 43.5mb ] / [   82mb]}  

From just the above output, it become even clearer, the gc par new collection duration is 829milliseconds and one collection of 1.1seconds. The heap before was 8.4GB and after collected became 8.5GB with a total heap of 14GB. Then we have all the pools jvm statistics revealed. Pretty obvious, before and after with total memory heap assigned for the pool respectively.

Now, we will read into the code and verify if our assumption are valid. The class that log this is JvmMonitorService.java and we noticed it fall in the if else second evaluation clause.

Again, interpretation based on the code, it is an info logging with gc name is par new. Sequence of this gc is 649825. In this collection, total collection for par new is 391294 and its total collections time is 391294 milliseconds (6 minutes 31 seconds). Note that this collections time is derived with the difference in the last gc and this gc.

Next, the collections total counts between last count and this count. It is follow by the collections time in milliseconds. In this example, we have one collections performed in  1.1seconds.. hmm... Then we have the total time in milliseconds (829 milliseconds) with the gc collections time and in the output, it is showing 2.8 hours!

For the next jvm statistics, we have memory/heap statistics. So it is different than we interpret based on the log before, this statistics shown in the last jvm memory used and then current jvm used. The different is about one GB. The total memory/heap allocated for this jvm is 14GB.

The last statistics is the jvm pool statistics. Notice that the pool statistics is built such that the previous jvm collection run and this jvm collection run were built. The logic of output is such that the previous jvm pool used and then current jvm pool used with current pool max heap allocated. Let's take one from the pool for discussion, {[CMS Old Gen]        [8.3gb] ->[  8.4gb ] / [ 13.8gb]} . So cms old gen pool previous jvm usage was 8.3gb and in this jvm collection, the current usage is 8.4GB. This cms old gen max used is 13.8GB.

That's it and if you think this analysis is not correct, please leave your comment below and make the necessary correction.

Friday, January 16, 2015

operate casandra using jmx in terminal including changing pool size, compacting sstables and key cache

If you operate apache cassandra cluster and if load per node goes huge (like nodetool info show 800GB), compactions become a problem. It's a big problem for apache cassandra 1.0.8 if you have load per node average hover around 600GB to 1TB. The read performance suffers and at times system uptime load goes high. In some instance, I noticed when repair is running, system load goes more than 20. It's not a concern if this is operating well, but the more often you see this, something has gone wrong. Today, I will share my experience on how to operate cassandra when node load is huge and cassandra instance is still running. Often times, there are nice method that is exposed via jmx but to operate remotely, jmx gui client such as jmxconsole is not ideal. Instead, we will using a jmxterm for these operation in apache cassandra 1.0.8. So let's get started.

Changing pool size

So, it is pretty simple, launch it and set to the bean, and then set the CorePoolSize. The steps will be illustrate below.
$ java -jar jmxterm-1.0-alpha-4-uber.jar
$>open localhost:7199
#Connection to localhost:7199 is opened
$>bean org.apache.cassandra.request:type=ReplicateOnWriteStage
#bean is set to org.apache.cassandra.request:type=ReplicateOnWriteStage
$>get CorePoolSize
#mbean = org.apache.cassandra.request:type=ReplicateOnWriteStage:
CorePoolSize = 32;
$>info
#mbean = org.apache.cassandra.request:type=ReplicateOnWriteStage
#class name = org.apache.cassandra.concurrent.JMXConfigurableThreadPoolExecutor
# attributes
%0 - ActiveCount (int, r)
%1 - CompletedTasks (long, r)
%2 - CorePoolSize (int, rw)
%3 - CurrentlyBlockedTasks (int, r)
%4 - PendingTasks (long, r)
%5 - TotalBlockedTasks (int, r)
#there's no operations
#there's no notifications
$>set CorePoolSize 64
$>get CorePoolSize
#mbean = org.apache.cassandra.request:type=ReplicateOnWriteStage:
CorePoolSize = 64;

Alter key cache

Often times, when there is heap pressure in the jvm, the safety valve kicks in.  You can restart the cassandra instance or you can reset the key cache back to the initial value. Assuming your column family name FooBar and keyspace just4fun, then the following are steps to illustrate how is this done.
$>bean org.apache.cassandra.db:cache=FooBarKeyCache,keyspace=just4fun,type=Caches
#bean is set to org.apache.cassandra.db:cache=FooBarKeyCache,keyspace=just4fun,type=Caches
$>info
#mbean = org.apache.cassandra.db:cache=FooBarKeyCache,keyspace=just4fun,type=Caches
#class name = org.apache.cassandra.cache.AutoSavingKeyCache
# attributes
%0 - Capacity (int, rw)
%1 - Hits (long, r)
%2 - RecentHitRate (double, r)
%3 - Requests (long, r)
%4 - Size (int, r)
#there's no operations
#there's no notifications
$>
$>get Size
#mbean = org.apache.cassandra.db:cache=FooBarKeyCache,keyspace=just4fun,type=Caches:
Size = 122307;

$>set Capacity 250000
#Value of attribute Capacity is set to 250000
$>get Capacity;
#mbean = org.apache.cassandra.db:cache=FooBarKeyCache,keyspace=just4fun,type=Caches:
$>get Capacity
#mbean = org.apache.cassandra.db:cache=FooBarKeyCache,keyspace=just4fun,type=Caches:
Capacity = 250000;

Compact sstable

Lastly, to compact sstables. It's amazing we have a sstable that as huge as 84GB! So trigger major compaction is not an option here, often time when load per node goes beyond 600GB, compaction took forever, as GC kick in and cpu keep on recollecting heap, making system load goes high. So here, we will select one sstable that is huge and compact that only. You can also select a few sstable and compact them and separate using comma.
$>bean org.apache.cassandra.db:type=CompactionManager
#bean is set to org.apache.cassandra.db:type=CompactionManager
$>run forceUserDefinedCompaction just4fun FooBar-hc-5-Index.db
#calling operation forceUserDefinedCompaction of mbean org.apache.cassandra.db:type=CompactionManager
#RuntimeMBeanException: java.lang.IllegalArgumentException: FooBar-hc-5-Index.db does not appear to be a data file
$>run forceUserDefinedCompaction just4fun FooBar-hc-401-Data.db
#calling operation forceUserDefinedCompaction of mbean org.apache.cassandra.db:type=CompactionManager
#operation returns:
null

The compaction should be started, you can check in cassandra system log or the nodetool compaction. So that's it, I hope you learned something.

Saturday, November 30, 2013

how does read performance gains when in compression?

Read the following interesting discussion in the cassandra mailing list, and think very good explanation and would like to share out.

how does read performance gains when in compression?
http://www.datastax.com/dev/blog/whats-new-in-cassandra-1-0-compression
http://www.datastax.com/documentation/cassandra/1.2/webhelp/index.html?pagename=docs&version=1.2&file=index#cassandra/dml/dml_about_reads_c.html

Cite from Artur Kronenberg
The way I understand it is that compression gives you the advantage of having to use way less IO and rather use CPU. The bottleneck of reads is usually the IO time you need to read the data from disk. As a figure, we had about 25 reads/s reading from disk, while we get up to 3000 reads/s when we have all of it in cache. So having good compression reduces the amount you have to read from disk. Rather you may spend a little bit more time decompressing data, but this data will be in cache anyways so it won't matter.

Cite from Edward Capriolo
The big * in the explanation: Smaller file size footprint leads to better disk cache, however decompression adds work for the JVM to do and increases the churn of objects in the JVM. Additionally compression block sizes might be 4KB while for some use cases a small row may be 200bytes. This means that internally a large block might be decompressed to get at the row inside of it.

In many use cases compression is a performance win, but not necessarily in all cases. In particular if you are already doing JVM performance tuning issues to stop garbage collection pauses enabling compression could make performance worse.