You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Michał Łowicki <ml...@gmail.com> on 2015/06/01 11:46:31 UTC
How to interpret some GC logs
Hi,
Normally I get logs like:
2015-06-01T09:19:50.610+0000: 4736.314: [GC 6505591K->4895804K(8178944K),
0.0494560 secs]
which is fine and understandable but occasionalIy I see something like:
2015-06-01T09:19:50.661+0000: 4736.365: [GC 4901600K(8178944K), 0.0049600
secs]
How to interpret it? Does it miss only part before "->" so memory occupied
before GC cycle?
--
BR,
Michał Łowicki
Re: How to interpret some GC logs
Posted by Brice Dutheil <br...@gmail.com>.
Looking at GC logs is certainly interesting and possible.
But it is difficult to get the big picture in a single file, and especially
on a multi-node datacenter.
If there's one tool I'd consider it is Censum, from jClarity. This tool is
not free, yet it is the only tool that can allows one to make sense of
hundreds of GC logs.
GC logs format were tweaked between major and minor versions of the JDK,
Censum manages it flawlessly. There's regular updates. The team behind it
are known experts in this field.
Other free tool just don't even come close to Censum.
Allocation rate :
[image: Inline image 1]
Time spent GCing
[image: Inline image 2]
GC Pause times
[image: Inline image 3]
There's many more, and other information that describe the possible problem
and possible solution to fix it.
We are quite happy that we spent some money on it, it saved us many hours
or days (I remember the old days) trying to figure out GC on java
applications (and of course cassandra).
-- Brice
On Wed, Jun 3, 2015 at 3:44 PM, Carlos Rolo <ro...@pythian.com> wrote:
> GC Logs are a weird science. I use a couple of resources to get through
> them. Regarding your question my 1.8.0_40 always have the first the "->". I
> "greped" through 2h of logs, and on a test environment.
>
> I use the following set of options:
>
> -XX:+PrintGCDetails"
> -XX:+PrintGCDateStamps"
> -XX:+PrintHeapAtGC"
> -XX:+PrintTenuringDistribution"
> -XX:+PrintGCApplicationStoppedTime"
> -XX:+PrintPromotionFailure"
> -XX:PrintFLSStatistics=1"
>
> I don't know if the following could help but I use this tool to visualize
> my GC behaviour: https://github.com/chewiebug/GCViewer
> If I need insight into the GC as it goes I use Java VisualVM.
>
> Regards,
>
> Carlos Juzarte Rolo
> Cassandra Consultant
>
> Pythian - Love your data
>
> rolo@pythian | Twitter: cjrolo | Linkedin: *linkedin.com/in/carlosjuzarterolo
> <http://linkedin.com/in/carlosjuzarterolo>*
> Mobile: +31 6 159 61 814 | Tel: +1 613 565 8696 x1649
> www.pythian.com
>
> On Tue, Jun 2, 2015 at 9:17 AM, Michał Łowicki <ml...@gmail.com> wrote:
>
>>
>>
>> On Tue, Jun 2, 2015 at 9:06 AM, Sebastian Martinka <
>> sebastian.martinka@mercateo.com> wrote:
>>
>>> this should help you:
>>>
>>> https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs
>>>
>>
>> I don't see there such format. Passed options related to GC are:
>>
>> -XX:+PrintGCDateStamps -Xloggc:/var/log/cassandra/gc.log
>>
>>
>>>
>>>
>>> Best Regards,
>>> Sebastian Martinka
>>>
>>>
>>>
>>> *Von:* Michał Łowicki [mailto:mlowicki@gmail.com]
>>> *Gesendet:* Montag, 1. Juni 2015 11:47
>>> *An:* user@cassandra.apache.org
>>> *Betreff:* How to interpret some GC logs
>>>
>>>
>>>
>>> Hi,
>>>
>>>
>>>
>>> Normally I get logs like:
>>>
>>>
>>>
>>> 2015-06-01T09:19:50.610+0000: 4736.314: [GC
>>> 6505591K->4895804K(8178944K), 0.0494560 secs]
>>>
>>>
>>>
>>> which is fine and understandable but occasionalIy I see something like:
>>>
>>> 2015-06-01T09:19:50.661+0000: 4736.365: [GC 4901600K(8178944K),
>>> 0.0049600 secs]
>>>
>>> How to interpret it? Does it miss only part before "->" so memory
>>> occupied before GC cycle?
>>>
>>> --
>>>
>>> BR,
>>> Michał Łowicki
>>>
>>
>>
>>
>> --
>> BR,
>> Michał Łowicki
>>
>
>
> --
>
>
>
>
Re: How to interpret some GC logs
Posted by Carlos Rolo <ro...@pythian.com>.
GC Logs are a weird science. I use a couple of resources to get through
them. Regarding your question my 1.8.0_40 always have the first the "->". I
"greped" through 2h of logs, and on a test environment.
I use the following set of options:
-XX:+PrintGCDetails"
-XX:+PrintGCDateStamps"
-XX:+PrintHeapAtGC"
-XX:+PrintTenuringDistribution"
-XX:+PrintGCApplicationStoppedTime"
-XX:+PrintPromotionFailure"
-XX:PrintFLSStatistics=1"
I don't know if the following could help but I use this tool to visualize
my GC behaviour: https://github.com/chewiebug/GCViewer
If I need insight into the GC as it goes I use Java VisualVM.
Regards,
Carlos Juzarte Rolo
Cassandra Consultant
Pythian - Love your data
rolo@pythian | Twitter: cjrolo | Linkedin: *linkedin.com/in/carlosjuzarterolo
<http://linkedin.com/in/carlosjuzarterolo>*
Mobile: +31 6 159 61 814 | Tel: +1 613 565 8696 x1649
www.pythian.com
On Tue, Jun 2, 2015 at 9:17 AM, Michał Łowicki <ml...@gmail.com> wrote:
>
>
> On Tue, Jun 2, 2015 at 9:06 AM, Sebastian Martinka <
> sebastian.martinka@mercateo.com> wrote:
>
>> this should help you:
>>
>> https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs
>>
>
> I don't see there such format. Passed options related to GC are:
>
> -XX:+PrintGCDateStamps -Xloggc:/var/log/cassandra/gc.log
>
>
>>
>>
>> Best Regards,
>> Sebastian Martinka
>>
>>
>>
>> *Von:* Michał Łowicki [mailto:mlowicki@gmail.com]
>> *Gesendet:* Montag, 1. Juni 2015 11:47
>> *An:* user@cassandra.apache.org
>> *Betreff:* How to interpret some GC logs
>>
>>
>>
>> Hi,
>>
>>
>>
>> Normally I get logs like:
>>
>>
>>
>> 2015-06-01T09:19:50.610+0000: 4736.314: [GC 6505591K->4895804K(8178944K),
>> 0.0494560 secs]
>>
>>
>>
>> which is fine and understandable but occasionalIy I see something like:
>>
>> 2015-06-01T09:19:50.661+0000: 4736.365: [GC 4901600K(8178944K), 0.0049600
>> secs]
>>
>> How to interpret it? Does it miss only part before "->" so memory
>> occupied before GC cycle?
>>
>> --
>>
>> BR,
>> Michał Łowicki
>>
>
>
>
> --
> BR,
> Michał Łowicki
>
--
--
Re: How to interpret some GC logs
Posted by Michał Łowicki <ml...@gmail.com>.
On Tue, Jun 2, 2015 at 9:06 AM, Sebastian Martinka <
sebastian.martinka@mercateo.com> wrote:
> this should help you:
>
> https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs
>
I don't see there such format. Passed options related to GC are:
-XX:+PrintGCDateStamps -Xloggc:/var/log/cassandra/gc.log
>
>
> Best Regards,
> Sebastian Martinka
>
>
>
> *Von:* Michał Łowicki [mailto:mlowicki@gmail.com]
> *Gesendet:* Montag, 1. Juni 2015 11:47
> *An:* user@cassandra.apache.org
> *Betreff:* How to interpret some GC logs
>
>
>
> Hi,
>
>
>
> Normally I get logs like:
>
>
>
> 2015-06-01T09:19:50.610+0000: 4736.314: [GC 6505591K->4895804K(8178944K),
> 0.0494560 secs]
>
>
>
> which is fine and understandable but occasionalIy I see something like:
>
> 2015-06-01T09:19:50.661+0000: 4736.365: [GC 4901600K(8178944K), 0.0049600
> secs]
>
> How to interpret it? Does it miss only part before "->" so memory occupied
> before GC cycle?
>
> --
>
> BR,
> Michał Łowicki
>
--
BR,
Michał Łowicki
AW: How to interpret some GC logs
Posted by Sebastian Martinka <se...@mercateo.com>.
this should help you:
https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs
Best Regards,
Sebastian Martinka
Von: Michał Łowicki [mailto:mlowicki@gmail.com]
Gesendet: Montag, 1. Juni 2015 11:47
An: user@cassandra.apache.org
Betreff: How to interpret some GC logs
Hi,
Normally I get logs like:
2015-06-01T09:19:50.610+0000: 4736.314: [GC 6505591K->4895804K(8178944K), 0.0494560 secs]
which is fine and understandable but occasionalIy I see something like:
2015-06-01T09:19:50.661+0000: 4736.365: [GC 4901600K(8178944K), 0.0049600 secs]
How to interpret it? Does it miss only part before "->" so memory occupied before GC cycle?
--
BR,
Michał Łowicki
Re: How to interpret some GC logs
Posted by Michał Łowicki <ml...@gmail.com>.
On Mon, Jun 1, 2015 at 7:25 PM, Jason Wee <pe...@gmail.com> wrote:
> can you tell what jvm is that?
>
root@db2:~# java -version
java version "1.7.0_80"
Java(TM) SE Runtime Environment (build 1.7.0_80-b15)
Java HotSpot(TM) 64-Bit Server VM (build 24.80-b11, mixed mode)
>
> jason
>
> On Mon, Jun 1, 2015 at 5:46 PM, Michał Łowicki <ml...@gmail.com> wrote:
>
>> Hi,
>>
>> Normally I get logs like:
>>
>> 2015-06-01T09:19:50.610+0000: 4736.314: [GC 6505591K->4895804K(8178944K),
>> 0.0494560 secs]
>>
>> which is fine and understandable but occasionalIy I see something like:
>>
>> 2015-06-01T09:19:50.661+0000: 4736.365: [GC 4901600K(8178944K), 0.0049600
>> secs]
>>
>> How to interpret it? Does it miss only part before "->" so memory
>> occupied before GC cycle?
>> --
>> BR,
>> Michał Łowicki
>>
>
>
--
BR,
Michał Łowicki
Re: How to interpret some GC logs
Posted by Jason Wee <pe...@gmail.com>.
can you tell what jvm is that?
jason
On Mon, Jun 1, 2015 at 5:46 PM, Michał Łowicki <ml...@gmail.com> wrote:
> Hi,
>
> Normally I get logs like:
>
> 2015-06-01T09:19:50.610+0000: 4736.314: [GC 6505591K->4895804K(8178944K),
> 0.0494560 secs]
>
> which is fine and understandable but occasionalIy I see something like:
>
> 2015-06-01T09:19:50.661+0000: 4736.365: [GC 4901600K(8178944K), 0.0049600
> secs]
>
> How to interpret it? Does it miss only part before "->" so memory occupied
> before GC cycle?
> --
> BR,
> Michał Łowicki
>