CNDB-15260: Add SAI-specific execution info to slow query logger

[adelapena]

What is the issue

The slow query logger is one of the most useful tools when dealing with performance-related incidents. Currently it simply prints the CQL representation of the slow query and its running time. So while it can allow us to identify problematic SAI queries, we have to go to the aggregated metrics where it's difficult to see what matches the problematic query.

I think it would be useful if the slow query logger also printed the SAI query metrics and plan. That way we could examine log records at the time of the incident to see what's going on with individual slow queries, without needing to extract conclusions from aggregated metrics.

What does this PR fix and why was it fixed

This PR adds SAI-specific information to the log messages produced when slow queries are detected. That information consists on the metrics in the QueryContext and the tree view of the query Plan. There is a cassandra.cassandra.sai.slow_query_log.details_enabled property to disable this extended logging.

This is how slow queries are currently logged:

DEBUG [node1_isolatedExecutor:1] node1 2025-10-09 11:14:57,354 MonitoringTask.java:175 - 2 operations were slow in the last 131 msecs:
<SELECT s FROM distributed_test_keyspace.t WHERE (s = s_2 OR s = s_3) AND  ALLOW FILTERING>, time 107 msec - slow timeout 100 msec
<SELECT n FROM distributed_test_keyspace.t WHERE n > 1 AND  ALLOW FILTERING>, was slow 2 times: avg/min/max 104/104/105 msec - slow timeout 100 msec

And this is how they would look like with SAI details:

DEBUG [node1_isolatedExecutor:1] node1 2025-10-09 11:14:57,354 MonitoringTask.java:175 - 2 operations were slow in the last 131 msecs:
<SELECT * FROM distributed_test_keyspace.t WHERE (s = s_2 OR s = s_3) AND  ALLOW FILTERING>, time 111 msec - slow timeout 100 msec
  SAI slow query metrics:
    sstablesHit: 2
    segmentsHit: 2
    partitionsRead: 2
    rowsFiltered: 2
    rowsPreFiltered: 0
    trieSegmentsHit: 2
    bkdPostingListsHit: 0
    bkdSegmentsHit: 0
    bkdPostingsSkips: 0
    bkdPostingsDecodes: 0
    triePostingsSkips: 0
    triePostingsDecodes: 2
    annGraphSearchLatencyNanos: 0
    shadowedPrimaryKeyCount: 0
  SAI slow query plan:
    Limit 2147483647 (rows: 1.8, cost/row: 101.5, cost: 3000.0..3177.6)
     └─ Filter (s = s_2 OR s = s_3) (sel: 1.000000000) (rows: 1.8, cost/row: 101.5, cost: 3000.0..3177.6)
         └─ Fetch (rows: 1.8, cost/row: 101.5, cost: 3000.0..3177.6)
             └─ Union (keys: 1.8, cost/key: 0.1, cost: 3000.0..3000.2)
                 ├─ LiteralIndexScan of t_s_idx (sel: 0.250000000, step: 1.0) (keys: 1.0, cost/key: 0.1, cost: 1500.0..1500.1)
                 │  predicate: Expression{name: s, op: EQ, lower: (s_2, true), upper: (s_2, true), exclusions: []}
                 └─ LiteralIndexScan of t_s_idx (sel: 0.250000000, step: 1.0) (keys: 1.0, cost/key: 0.1, cost: 1500.0..1500.1)
                    predicate: Expression{name: s, op: EQ, lower: (s_3, true), upper: (s_3, true), exclusions: []}
<SELECT * FROM distributed_test_keyspace.t WHERE n > 1 AND  ALLOW FILTERING>, was slow 2 times: avg/min/max 258/103/413 msec - slow timeout 100 msec
  SAI slowest query metrics:
    sstablesHit: 3
    segmentsHit: 3
    partitionsRead: 3
    rowsFiltered: 6
    rowsPreFiltered: 0
    trieSegmentsHit: 0
    bkdPostingListsHit: 3
    bkdSegmentsHit: 3
    bkdPostingsSkips: 0
    bkdPostingsDecodes: 7
    triePostingsSkips: 0
    triePostingsDecodes: 0
    annGraphSearchLatencyNanos: 0
    shadowedPrimaryKeyCount: 0
  SAI slowest query plan:
    Limit 2147483647 (rows: 6.0, cost/row: 101.1, cost: 4500.0..5106.8)
     └─ Filter n > 1 (sel: 1.000000000) (rows: 6.0, cost/row: 101.1, cost: 4500.0..5106.8)
         └─ Fetch (rows: 6.0, cost/row: 101.1, cost: 4500.0..5106.8)
             └─ NumericIndexScan of t_n_idx (sel: 0.857142857, step: 1.0) (keys: 6.0, cost/key: 0.1, cost: 4500.0..4500.6)
                predicate: Expression{name: n, op: RANGE, lower: (1, false), upper: (null, false), exclusions: []}

Note that the queries are printed as invalid CQL and include user data. That is being dealt with in CNDB-15280, which is under review.

[github-actions]

Checklist before you submit for review

• This PR adheres to the Definition of Done
• Make sure there is a PR in the CNDB project updating the Converged Cassandra version
• Use NoSpamLogger for log lines that may appear frequently in the logs
• Verify test results on Butler
• Test coverage for new/modified code is > 80%
• Proper code formatting
• Proper title for each commit staring with the project-issue number, like CNDB-1234
• Each commit has a meaningful description
• Each commit is not very long and contains related changes
• Renames, moves and reformatting are in distinct commits
• All new files should contain the DataStax copyright header instead of the Apache License one

[ekaterinadimitrova2]

I did first round of review and left some questions and suggestions, mostly trivial.
I am wondering how good of an idea is to have to restart a node to disable it if we sense too much noise or performance degradation once enabled?

Sonar didn't run but we can check it with the next CI run, it didn't prevent me from doing initial review.

[ekaterinadimitrova2]

I did not see tests that show that things look ok if we have queries involving non-sai indexes. Can you add some, please?

[adelapena]

Added, and also for regular queries.

[ekaterinadimitrova2]

It seems solar is still complaining on the test coverage for this one and the next check. Can you take a look, please?

[adelapena]

I've added an artificial test for the sake of increasing coverage from the current 96.6%.

[ekaterinadimitrova2]

Why artificial? I see queries and real test case?
for the sake of increasing coverage from the current 96.6%.
This was not about the number at all. There are valid cases as unreachable checks which would exhibit a bug, but this wasn't one of them. Thanks for the added test.

[ekaterinadimitrova2]

Btw by looking into the new test - this was probably just missing queries in the already existing test which would have hit those paths. As this is about testing the slow query logger, they should be checking probably whether we log or not, as expected.

[adelapena]

I am wondering how good of an idea is to have to restart a node to disable it if we sense too much noise or performance degradation once enabled?

We don't need to restart the node with the current approach. The system property that toggles logging SAI execution details is read every time we detect a slow query, and the system property can be changed at any time. Relevant bits here:

cassandra/src/java/org/apache/cassandra/index/sai/plan/StorageAttachedIndexSearcher.java

Lines 205 to 210 in 5c33fd2

	public Monitorable.ExecutionInfo monitorableExecutionInfo()
	{
	return CassandraRelevantProperties.SAI_SLOW_QUERY_LOG_EXECUTION_INFO_ENABLED.getBoolean()
	? new QueryMonitorableExecutionInfo(queryContext, controller.buildPlan())
	: Monitorable.ExecutionInfo.EMPTY;
	}

[ekaterinadimitrova2]

I think we are almost ready.
A few small comments plus complaint on test coverage from the tool. I feel it is worth to check it as even before the tool I mentioned we have to test those if clauses. Thanks
The test failures seem to be known to me flakies not related to what we do here.

About the below comment

I am wondering how good of an idea is to have to restart a node to disable it if we sense too much noise or performance degradation once enabled?

We don't need to restart the node with the current approach. The system property that toggles logging SAI execution details is read every time we detect a slow query, and the system property can be changed at any time. Relevant bits here:

I am clear how we check it to decide whether to log or not, but how do you set that property in runtime? I don't see any setter or anything? What did I miss?

[ekaterinadimitrova2]

It seems solar is still complaining on the test coverage for this one and the next check. Can you take a look, please?

[adelapena]

I am clear how we check it to decide whether to log or not, but how do you set that property in runtime? I don't see any setter or anything? What did I miss?

You didn't miss anything, I did. I have added a new mbean just for SAI and added the new config property there. Hopefully we can incrementally keep adding other similar past and future properties to it.

I have named it StorageAttachedIndexConfig because of a lack of imagination, but any suggestions are welcome.

[adelapena]

After this Slack discussion, I'm removing the SAI mbean since we have other ways to manipulate CassandraRelevantProperties.

[ekaterinadimitrova2]

It seems very neat with the supplier but I do not think volatile is enough now for it. Please check the comment.

I am surprised Sonar complaints about code test coverage for the empty execution info, didn't we have it covered already on the previous run?

About the other issue flagged by Sonar - instance can definitely not be final in MonitoringTask.

[ekaterinadimitrova2]

nit: there is unused import now

[ekaterinadimitrova2]

The supplier is neat, but now volatile is not enough. Also pointed by Sonar. On a quick look, probably just adding AtomicReference should be probably enough? The fields in QueryMonitorableExecutionInfo are final.

[adelapena]

It seems very neat with the supplier but I do not think volatile is enough now for it. Please check the comment.

I have also read that generic warning in Sonar, but wouldn't volatile be enough? There is a single writer thread when the query is executed, and a single read when the monitor picks it.

[ekaterinadimitrova2]

There is a single writer thread when the query is executed, and a single read when the monitor picks it.

Agreed, volatile should be enough actually

[ekaterinadimitrova2]

Let's check the test failures on the other PR and I can approve this one.

[adelapena]

Thanks for the feedback. I have removed that unused import and rebased without conflicts. I don't see related failures in CI in either this PR or the one for CNDB.

[ekaterinadimitrova2]

Note that the queries are printed as invalid CQL and include user data. That is being dealt with in https://github.com/riptano/cndb/issues/15280, which is under review.

Just to confirm - after #15280 slow query logging will always redact user data? I did not see any parameters added in CassandraRelevantProperties (I did not review the full PR - only looked at the description and searched for that class)

[adelapena]

Just to confirm - after #15280 slow query logging will always redact user data? I did not see any parameters added in CassandraRelevantProperties (I did not review the full PR - only looked at the description and searched for that class)

Yes, #15280 will always redact the query user data printed to logs. When either this issue or #15280 get merged, the other will need an update, whichever gets second. I thought #15280 was going to be first, but it is taking longer than initially expected. I understand that while #15280 is not merged, redaction doesn't exist for this ticket. The tests added here will fail when redaction is ready, and I have just modified the one in the CNDB PR so it will also fail with redaction, so we don't miss it.

Note by the way that here we are not printing any additional user data to the logs, since the slow queries were already being logged, the metrics don't contain user data, and the plan contains the same user data as the query (#15280 also redacts the plan).

[adelapena]

@ekaterinadimitrova2 I have added the requested JMH microbenchmark to measure the impact of the extended logging. Here are the results:

Benchmark                                            (enabled)  Mode  Cnt          Score        Error  Units
QueryMonitorableExecutionInfoBench.executionInfo         false  avgt   10         20.180 ±      0.522  ns/op
QueryMonitorableExecutionInfoBench.executionInfo          true  avgt   10       1077.049 ±     19.155  ns/op
QueryMonitorableExecutionInfoBench.logSlowOperation      false  avgt   10      12245.476 ±   1375.457  ns/op
QueryMonitorableExecutionInfoBench.logSlowOperation       true  avgt   10      30474.713 ±  56262.347  ns/op
QueryMonitorableExecutionInfoBench.slowQuery             false  avgt   10  499650847.910 ± 117548.616  ns/op
QueryMonitorableExecutionInfoBench.slowQuery              true  avgt   10  499665972.905 ± 126953.319  ns/op

We can see that the generation of the extended SAI ExecutionInfo takes around one microsecond.

Producing the larger log messages adds some ~20 microseconds to the previous ~10 microseconds per query, making them ~3x slower.

However, the cost of the slow query logging is ~4 orders of magnitude lower than the faster of the slow queries, which take at least 500ms by default. In fact, the impact of the extended logging is lower than the error of the benchmark.

So, as it was expected, the extended logging dilutes into almost nothing when compared to the cost of the reported slow queries themselves.

[ekaterinadimitrova2]

Reviewed the benchmark test, LGTM

[adelapena]

I have rebased this to include the redaction of logged SELECT queries introduced by CNDB-15280, and updated SlowSAIQueryLoggerTest to consider that redaction.

[sonarqubecloud]

Quality Gate passed

Issues
3 New issues
0 Accepted issues

Measures
0 Security Hotspots
97.3% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarQube Cloud

[cassci-bot]

✔️ Build ds-cassandra-pr-gate/PR-2044 approved by Butler

---

Approved by Butler
See build details here

[ekaterinadimitrova2]

Looks great!