GC Log - Duplicate GCTimeStamps

[mattmonkey83]

Hi,

We have any issue with duplicate GCTimeStamps appearing in GC logs, e.g. -

1.027: Total time for which application threads were stopped: 0.0000230 seconds
1.686: [GC1.687: [DefNew
Desired survivor size 4358144 bytes, new threshold 1 (max 6)
- age   1:    8716288 bytes,    8716288 total
: 68160K->8512K(76672K), 0.0284560 secs] 68160K->13947K(253632K), 0.0287330 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]
1.715: Total time for which application threads were stopped: 0.0288730 seconds
2.731: Total time for which application threads were stopped: 0.0001220 seconds
3.045: Total time for which application threads were stopped: 0.0000670 seconds
3.736: [GC3.736: [DefNew
Desired survivor size 4358144 bytes, new threshold 1 (max 6)
- age   1:    8716288 bytes,    8716288 total
: 76672K->8512K(76672K), 0.0445610 secs] 82107K->20595K(253632K), 0.0446170 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

Notice the repeated timestamp after [GC.

We're seeing this behaviour on Ubuntu 14.04.2 LTS using ES 1.5.2 and 1.6.0 with both the OpenJDK JRE 7 and Oracle JRE 7. I'm not seeing it on OS X 10.10 however.

I've tested other Java apps with the same setup and they don't have duplicate timestamps so this appears to be Elasticsearch specific.

GCDateStamps also get duplicated if we enable them via ES_JAVA_OPTS e.g. -

2015-07-03T13:29:43.859+0000: 594133.063: [GC2015-07-03T13:29:43.859+0000: 594133.063: [ParNew: 281570K->11211K(306688K), 0.0516960 secs] 2889367K->2619012K(15673088K), 0.0517990 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
2015-07-03T13:30:24.341+0000: 594173.544: [GC2015-07-03T13:30:24.341+0000: 594173.544: [ParNew: 283851K->10915K(306688K), 0.0490020 secs] 2891652K->2618718K(15673088K), 0.0491160 secs] [Times: user=0.19 sys=0.01, real=0.05 secs]
2015-07-03T13:31:16.119+0000: 594225.322: [GC2015-07-03T13:31:16.119+0000: 594225.322: [ParNew: 283555K->10013K(306688K), 0.0528850 secs] 2891358K->2618616K(15673088K), 0.0529900 secs] [Times: user=0.21 sys=0.00, real=0.05 secs]
2015-07-03T13:31:56.255+0000: 594265.458: [GC2015-07-03T13:31:56.255+0000: 594265.458: [ParNew: 282653K->11148K(306688K), 0.0504550 secs] 2891256K->2619756K(15673088K), 0.0505590 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
2015-07-03T13:32:46.685+0000: 594315.888: [GC2015-07-03T13:32:46.685+0000: 594315.888: [ParNew: 283788K->12110K(306688K), 0.0531040 secs] 2892396K->2620723K(15673088K), 0.0532130 secs] [Times: user=0.21 sys=0.00, real=0.06 secs]

This is causing problems when trying to parse the logs in our logging system.

Any suggestions would be appreciated.

Thanks,

Matt.

[mattmonkey83]

Sorry - I've since noticed this behaviour on the same setup for a different Java app.

Only seems to occur when the '-XX:+UseConcMarkSweepGC' option is used.

And it actually does appear to be present on OS X too when using Oracle Java 1.7.0_79-b15. Not sure how I missed it previously.

I've since tried using Oracle JRE 8 on Ubuntu 14.04.2 LTS and the issue does not occur. So am assuming this is a Java 7 issue. Will try to raise an issue via OpenJDK project.