Poor Performance of Decorator extraction when file does not contain Tags

[jlittle-ptc]

Describe the bug
When running GCToolkit against a larger G1GC log file it appears that the regex used to parse out the decorator tags is causing a performance hit.

Using the sample with a 58MB log file, the timing of the maven run returns:

[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  01:06 min

After running some profiling, the poorly performing lines in question are (com.microsoft.gctoolkit.parser.jvm.Decorators):

        Matcher tagMatcher = UnifiedLoggingTokens.TAGS.matcher(line);
        if (tagMatcher.find()) {
            numberOfDecorators++;
            tags = String.join(",", Arrays.asList(tagMatcher.group(1).trim().split(",")));
        }

If these lines are commented out and the sample is re-run against the same file, the result is significantly (10x) better:

[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  7.869 s

To Reproduce
Steps to reproduce the behavior:

• Using sample application, run it against attached file.

largegc.zip

[jlittle-ptc]

A few initial observations:

• In this specific case, the TAGS regex never matches as this particular log file does not include them.
• Comparing similarly sized files (20MB), one with tags, one without, results in 6s for the file with tags, and 30 seconds for the file without.
• The Regex in question contains a positive lookaround which may be the root of the problem.

[kcpeppe]

Can you post an example log file?

[jlittle-ptc]

I attached the log file to the original post (link at bottom), but I'm also including the 2x 20MB files I used to confirm the problem was due to the missing tags. (The tagged sample came from your test data)

sampleLogs-20mb.zip

[jlittle-ptc]

Attempt with more specific regex on 20 mb files: 11s without tags, 5 seconds with.

Regex used: .*\[((?:gc|safepoint)(?:[, ][a-z0-9, ]+)?)\]\s

Not the safest way of doing things, as I'm not confident that tags only ever start with either gc or safepoint (and have no evidence of the latter in sample files, just comments) It does exclude the safepoint hex thread address mentioned in the comments though.

Next thought is to set a diary flag, though Decorators doesn't currently reference the diary...

[jlittle-ptc]

OK, much better performance (6s both cases) with the following regex, and I think its safer:

^.*?\[([a-z\d.,\s]+)\]\s

We use a start-of-string anchor and a lazy match that ends at the space that always follows the last decorator. Excludes the safepoint condition in the comments and all current tests are passing.

@kcpeppe Do you see any problems with this regex?

[jlittle-ptc]

Looks like this was already addressed by #458. (I'm working off a base of 3.7.0 right now)

I'll make sure everything works as expected and if so, close off this request.

[jlittle-ptc]

Yep, the changes in #458 perform similarly; processing both 20 MB files in 5-6 seconds.

Sorry for the duplicate!

[kcpeppe]

If the test pass and it's faster... I'm happy. I'll take a look to ensure that the test is comprehensive enough to ensure confidence that it's working.