[CASSANDRA-14318] Fix query pager DEBUG log leak causing hit in paged reads throughput

• Type: Bug
• Status: Resolved
• Priority: Normal
• Resolution: Fixed
• Fix Version/s: 2.2.13
• Labels: lhf performance
• Severity: Normal
• Since Version: 2.2.1
• Assignee: Alexander Dejanovski
• Reporter: Alexander Dejanovski

Authors

Alexander Dejanovski

Reviewers

Paulo Motta

• Created: 16/Mar/18 14:25
• Updated: 16/Apr/19 09:29
• Resolved: 30/Mar/18 15:18

Description

Debug logging can involve in many cases (especially very low latency ones) a very important overhead on the read path in 2.2 as we've seen when upgrading clusters from 2.0 to 2.2.

The performance impact was especially noticeable on the client side metrics, where p99 could go up to 10 times higher, while ClientRequest metrics recorded by Cassandra didn't show any overhead.

Below shows latencies recorded on the client side with debug logging on first, and then without it :

 

We generated a flame graph before turning off debug logging that shows the read call stack is dominated by debug logging : 

I've attached the original flame graph for exploration.

Once disabled, the new flame graph shows that the read call stack gets extremely thin, which is further confirmed by client recorded metrics : 

The query pager code has been reworked since 3.0 and it looks like log.debug() calls are gone there, but for 2.2 users and to prevent such issues to appear with default settings, I really think debug logging should be disabled by default.

Issue Links

• Blocked: CASSANDRA-14326 Handle verbose logging at a different level than DEBUG