Requests locked on parsing database query

[kmasur-icims]

Description

We encountered an issue the other day where all threads on a server got stuck waiting on a new relic agent lock. The thread in question holding the lock had the following stacktrace:

java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$CharPropertyGreedy.match([email protected]/Pattern.java:4300)
at java.util.regex.Pattern$StartS.match([email protected]/Pattern.java:3655)
at java.util.regex.Matcher.search([email protected]/Matcher.java:1729)
at java.util.regex.Matcher.find([email protected]/Matcher.java:746)
at com.newrelic.agent.database.DefaultStatementFactory.parseStatement(DefaultStatementFactory.java:51)
at com.newrelic.agent.database.DefaultDatabaseStatementParser.parseStatement(DefaultDatabaseStatementParser.java:106)
at com.newrelic.agent.database.DefaultDatabaseStatementParser.getParsedDatabaseStatement(DefaultDatabaseStatementParser.java:99)
at com.newrelic.agent.database.CachingDatabaseStatementParser.lambda$getParsedDatabaseStatement$0(CachingDatabaseStatementParser.java:64)
at com.newrelic.agent.database.CachingDatabaseStatementParser$$Lambda$698/0x00007f6e16449960.apply(Unknown Source)
at com.newrelic.agent.deps.com.github.benmanes.caffeine.cache.BoundedLocalCache.lambda$doComputeIfAbsent$14(BoundedLocalCache.java:2406)
at com.newrelic.agent.deps.com.github.benmanes.caffeine.cache.BoundedLocalCache$$Lambda$304/0x00007f6e292fa440.apply(Unknown Source)
at java.util.concurrent.ConcurrentHashMap.compute([email protected]/ConcurrentHashMap.java:1947)
- locked <0x00007f743a9a68b8> (a java.util.concurrent.ConcurrentHashMap$Node)
at com.newrelic.agent.deps.com.github.benmanes.caffeine.cache.BoundedLocalCache.doComputeIfAbsent(BoundedLocalCache.java:2404)
at com.newrelic.agent.deps.com.github.benmanes.caffeine.cache.BoundedLocalCache.computeIfAbsent(BoundedLocalCache.java:2387)
at com.newrelic.agent.deps.com.github.benmanes.caffeine.cache.LocalCache.computeIfAbsent(LocalCache.java:108)
at com.newrelic.agent.deps.com.github.benmanes.caffeine.cache.LocalManualCache.get(LocalManualCache.java:62)
at com.newrelic.agent.database.CachingDatabaseStatementParser.getParsedDatabaseStatement(CachingDatabaseStatementParser.java:62)
at com.newrelic.agent.tracers.DefaultSqlTracer.parseStatement(DefaultSqlTracer.java:380)
at com.newrelic.agent.tracers.DefaultSqlTracer.doFinish(DefaultSqlTracer.java:238)
at com.newrelic.agent.tracers.DefaultTracer.performFinishWork(DefaultTracer.java:260)
at com.newrelic.agent.tracers.DefaultTracer.finish(DefaultTracer.java:236)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.execute(SQLServerStatement.java:745)

This thread held the lock for 20 mintues before the server was rebooted.

When we analyzed the heap dump, we found the thread was stuck on the following pattern matcher for parsing if the database statement is a call: https://github.com/newrelic/newrelic-java-agent/blob/v8.18.0/newrelic-agent/src/main/java/com/newrelic/agent/database/DefaultDatabaseStatementParser.java#L61

The regex for this pattern ".*call\\s+([^\\s(,]*).*" can take a very long time to process large SQL statements. In our case, the SQL query was an execute statement that was over 250,000 characters long. On top of that, while it was trying to process this pattern, all other threads on the server were stuck waiting on the lock in BoundedLocalCache.

Expected Behavior

This seems to have two issues for expected behavior:

1. The above regex can be very slow to process large SQL queries. This can drastically slow down response times.
2. While the above regex was processing, all other requests on the server got blocked by the thread that was processing the long running regex. Ideally, threads shouldn't block other threads from caching their respective data.

Troubleshooting or NR Diag results

Steps to Reproduce

We were able to write a simple unit test to show the slow performance of the regex in question:

	@Test
	public void test() {
		Pattern callPattern = Pattern.compile(".*call\\s+([^\\s(,]*).*", Pattern.CASE_INSENSITIVE | Pattern.DOTALL);

		String execCommand = RandomStringUtils.randomAlphabetic(100000);
		System.out.println("finished building");
		System.out.println("call: " + callPattern.matcher(execCommand).find());

	}

Processing the above regex on my local machine takes about 35 seconds. If the SQL query is very long and is NOT a call query (or the call statement is not near the beginning), processing the regex can take a very long time.

The regex for execute has a similar issue if the SQL query in question is NOT an execute statement: https://github.com/newrelic/newrelic-java-agent/blob/v8.18.0/newrelic-agent/src/main/java/com/newrelic/agent/database/DefaultDatabaseStatementParser.java#L62

The other regexes in the file don't appear to have the same performance issue.

Your Environment

New Relic Agent version: 8.2.0
Java Version 11 (corretto)

Additional context

We worked around the above issue by shortening the SQL query. Specifically, the query was so long as input data was injected directly into the SQL query rather than being parameterized. After moving the input data into parameters, the performance issue went away.

[workato-integration]

https://new-relic.atlassian.net/browse/NR-377188