[CASSANDRA-13677] Make SASI timeouts easier to debug

• Type: Improvement
• Status: Resolved
• Priority: Low
• Resolution: Fixed
• Fix Version/s: 4.0-alpha1, 4.0
• Component/s: Feature/SASI
• Assignee: Corentin Chary
• Reporter: Corentin Chary

Authors

Corentin Chary

Reviewers

Sam Tunnicliffe

• Created: 06/Jul/17 13:14
• Updated: 06/May/21 21:12
• Resolved: 14/Sep/17 15:59

Description

This would now give something like:

    WARN  [ReadStage-15] 2017-06-08 12:47:57,799 AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread Thread[ReadStage-15,5,main]: {}
    java.lang.RuntimeException: org.apache.cassandra.index.sasi.exceptions.TimeQuotaExceededException: Command 'Read(biggraphite_metadata.directories columns=* rowfilter=component_0 = criteo limits=LIMIT 5000 range=(min(-9223372036854775808), min(-9223372036854775808)] pfilter=names(EMPTY))' took too long (100 > 100ms).
            at org.apache.cassandra.service.StorageProxy$DroppableRunnable.run(StorageProxy.java:2591) ~[main/:na]
            at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_131]
            at org.apache.cassandra.concurrent.AbstractLocalAwareExecutorService$FutureTask.run(AbstractLocalAwareExecutorService.java:162) ~[main/:na]
            at org.apache.cassandra.concurrent.AbstractLocalAwareExecutorService$LocalSessionFutureTask.run(AbstractLocalAwareExecutorService.java:134) [main/:na]
            at org.apache.cassandra.concurrent.SEPWorker.run(SEPWorker.java:109) [main/:na]
            at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
    Caused by: org.apache.cassandra.index.sasi.exceptions.TimeQuotaExceededException: Command 'Read(biggraphite_metadata.directories columns=* rowfilter=component_0 = criteo limits=LIMIT 5000 range=(min(-9223372036854775808), min(-9223372036854775808)] pfilter=names(EMPTY))' took too long (100 > 100ms).
            at org.apache.cassandra.index.sasi.plan.QueryController.checkpoint(QueryController.java:163) ~[main/:na]
            at org.apache.cassandra.index.sasi.plan.QueryController.getPartition(QueryController.java:117) ~[main/:na]
            at org.apache.cassandra.index.sasi.plan.QueryPlan$ResultIterator.computeNext(QueryPlan.java:116) ~[main/:na]
            at org.apache.cassandra.index.sasi.plan.QueryPlan$ResultIterator.computeNext(QueryPlan.java:71) ~[main/:na]
            at org.apache.cassandra.utils.AbstractIterator.hasNext(AbstractIterator.java:47) ~[main/:na]
            at org.apache.cassandra.db.transform.BasePartitions.hasNext(BasePartitions.java:92) ~[main/:na]
            at org.apache.cassandra.db.partitions.UnfilteredPartitionIterators$Serializer.serialize(UnfilteredPartitionIterators.java:310) ~[main/:na]
            at org.apache.cassandra.db.ReadResponse$LocalDataResponse.build(ReadResponse.java:145) ~[main/:na]
            at org.apache.cassandra.db.ReadResponse$LocalDataResponse.<init>(ReadResponse.java:138) ~[main/:na]
            at org.apache.cassandra.db.ReadResponse$LocalDataResponse.<init>(ReadResponse.java:134) ~[main/:na]
            at org.apache.cassandra.db.ReadResponse.createDataResponse(ReadResponse.java:76) ~[main/:na]
            at org.apache.cassandra.db.ReadCommand.createResponse(ReadCommand.java:333) ~[main/:na]
            at org.apache.cassandra.service.StorageProxy$LocalReadRunnable.runMayThrow(StorageProxy.java:1884) ~[main/:na]
            at org.apache.cassandra.service.StorageProxy$DroppableRunnable.run(StorageProxy.java:2587) ~[main/:na]
            ... 5 common frames omitted

Not having the query makes it super hard to debug. Even worse, because it stops potentially before the slow_query threshold, it won't appear as one.