Getting Data In

Unable to eliminate line break in gc.log

emiller42
Motivator

I'm attempting to index the gc.log coming from a tomcat installation, and I can't seem to get it to linemerge properly. Here is a snippet from the log:

517045.370: [GC [PSYoungGen: 516944K->3097K(519296K)] 828767K->315076K(1830016K), 0.0065230 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
517076.460: [GC [PSYoungGen: 517337K->2116K(519232K)] 829316K->315460K(1829952K), 0.0184770 secs]
 [Times: user=0.01 sys=0.00, real=0.01 secs] 

and my props.conf for this sourcetype:

DATETIME_CONFIG = CURRENT
LINE_BREAKER = ([\r\n]+)(?=\d+\.\d+:)
SHOULD_LINEMERGE = FALSE

I've also tried:

DATETIME_CONFIG = CURRENT
SHOULD_LINEMERGE = TRUE
BREAK_ONLY_BEFORE = \d+\.\d+:
MUST_NOT_BREAK_BEFORE = \[

Which did not help. I verified that the above props were being applied, and not overridden by any other configurations.

The output is displaying as:

2/10/12 11:41:06.000 AM [Times: user=0.01 sys=0.00, real=0.01 secs] 
2/10/12 11:40:50.000 AM 517076.460: [GC [PSYoungGen: 517337K->2116K(519232K)] 829316K->315460K(1829952K), 0.0184770 secs]

So the second line of each entry is being recorded as a newline despite my props.conf config.

My hunch here is that because the two lines are not being written to the log at the same time (There appears to be some delay between the two according to Splunk) and that I've set DATETIME_CONFIG = CURRENT it's not waiting for the second line to be written before committing the first as an event. This theory is strengthened by the fact that there is the occasional entry that is merged properly.

Is there an appropriate attribute that can control the time Splunk will wait for more lines before considering the event 'done'?

Thanks!

Damien_Dallimor
Ultra Champion

Not a direct answer to your question , but as an alternative to using GC log dumps , have you tried using Splunk4JMX ? I use this app for gathering detailed garbage collection and memory metrics on JVM heap and non-heap memory pools.

hexx
Splunk Employee
Splunk Employee

Your hunch is correct.

I have seen this happen for this type of log (Java garbage collection) and it is caused by the fact that the application writing the logs being tailed by Splunk is pausing mid-event for longer than the default time after which the tailing processor decides that EOF has been reached (by default, 3 seconds). This typically happens if the application is bufferizing its writes.

There are two solutions to this problem :

  1. Ideally, reconfigure the application that is writing the logs to avoid buffering and only write full events at a time to disk.
  2. If the former option is not possible, you can prolong the time that the Splunk tailing processor will keep a file descriptor open while no new data is coming in from the default of 3 seconds to something like 10 seconds. This is configured with the time_before_close parameter in inputs.conf. Note that I would not recommend to push this value too high, and it would be best to scope the change to the affected log only.
Get Updates on the Splunk Community!

What's new in Splunk Cloud Platform 9.1.2312?

Hi Splunky people! We are excited to share the newest updates in Splunk Cloud Platform 9.1.2312! Analysts can ...

What’s New in Splunk Security Essentials 3.8.0?

Splunk Security Essentials (SSE) is an app that can amplify the power of your existing Splunk Cloud Platform, ...

Let’s Get You Certified – Vegas-Style at .conf24

Are you ready to level up your Splunk game? Then, let’s get you certified live at .conf24 – our annual user ...