[ https://issues.apache.org/jira/browse/CASSANDRA-5520?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Brandon Williams resolved CASSANDRA-5520. ----------------------------------------- Resolution: Invalid bq. However, the event-level breakdown shows no such large duration It doesn't need to, the entire request time just needs to exceed the rpc timeout. > Query tracing session info inconsistent with events info > -------------------------------------------------------- > > Key: CASSANDRA-5520 > URL: https://issues.apache.org/jira/browse/CASSANDRA-5520 > Project: Cassandra > Issue Type: Bug > Affects Versions: 1.2.4 > Environment: Linux > Reporter: Ilya Kirnos > > Session info for a trace is showing that a query took > 10 seconds (it timed > out). > cqlsh:system_traces> select session_id, duration, request from sessions where > session_id = c7e36a30-af3a-11e2-9ec9-772ec39805fe; > session_id | duration | request > --------------------------------------+----------+---------------- > c7e36a30-af3a-11e2-9ec9-772ec39805fe | 10000230 | multiget_slice > However, the event-level breakdown shows no such large duration: > cqlsh:system_traces> select * from events where session_id = > c7e36a30-af3a-11e2-9ec9-772ec39805fe; > session_id | event_id > | activity | source | > source_elapsed | thread > --------------------------------------+--------------------------------------+----------------------------------------------+----------------+----------------+------------------------ > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e36a30-af3a-11e2-9480-e9d811e0fc18 > | Message received from /50.112.90.147 | 50.112.4.16 | > 19 | Thread-57 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e36a31-af3a-11e2-9ec9-772ec39805fe > | Sending message to /10.252.153.16 | 50.112.90.147 | > 246 | WRITE-/50.112.4.16 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39140-af3a-11e2-9480-e9d811e0fc18 > | Message received from /50.112.90.147 | 50.112.4.16 | > 259 | Thread-57 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39140-af3a-11e2-9ec9-772ec39805fe > | Sending message to /10.248.106.37 | 50.112.90.147 | > 253 | WRITE-/50.112.79.52 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39140-af3a-11e2-b8dc-a7032a583115 > | Message received from /50.112.90.147 | 50.112.213.136 | > 25 | Thread-94 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39141-af3a-11e2-9480-e9d811e0fc18 > | Executing single-partition query on CardHash | 50.112.4.16 | > 421 | ReadStage:5329 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39141-af3a-11e2-9ec9-772ec39805fe > | Sending message to /10.252.151.214 | 50.112.90.147 | > 310 | WRITE-/50.112.213.136 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39141-af3a-11e2-b8dc-a7032a583115 > | Message received from /50.112.90.147 | 50.112.213.136 | > 106 | Thread-94 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39142-af3a-11e2-9480-e9d811e0fc18 > | Acquiring sstable references | 50.112.4.16 | > 444 | ReadStage:5329 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39142-af3a-11e2-9ec9-772ec39805fe > | Sending message to /10.248.106.37 | 50.112.90.147 | > 352 | WRITE-/50.112.79.52 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39142-af3a-11e2-b8dc-a7032a583115 > | Executing single-partition query on CardHash | 50.112.213.136 | > 144 | ReadStage:11 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39143-af3a-11e2-9480-e9d811e0fc18 > | Merging memtable contents | 50.112.4.16 | > 472 | ReadStage:5329 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39143-af3a-11e2-9ec9-772ec39805fe > | Sending message to /10.248.95.237 | 50.112.90.147 | > 362 | WRITE-/50.112.201.218 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39143-af3a-11e2-b8dc-a7032a583115 > | Acquiring sstable references | 50.112.213.136 | > 164 | ReadStage:11 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39144-af3a-11e2-9480-e9d811e0fc18 > | Merging data from memtables and 0 sstables | 50.112.4.16 | > 510 | ReadStage:5329 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39144-af3a-11e2-9ec9-772ec39805fe > | Sending message to /10.252.151.214 | 50.112.90.147 | > 376 | WRITE-/50.112.213.136 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39144-af3a-11e2-b8dc-a7032a583115 > | Merging memtable contents | 50.112.213.136 | > 195 | ReadStage:11 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39145-af3a-11e2-9480-e9d811e0fc18 > | Read 0 live cells and 0 tombstoned | 50.112.4.16 | > 530 | ReadStage:5329 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39145-af3a-11e2-9ec9-772ec39805fe > | Sending message to /10.248.95.237 | 50.112.90.147 | > 401 | WRITE-/50.112.201.218 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39145-af3a-11e2-b8dc-a7032a583115 > | Executing single-partition query on CardHash | 50.112.213.136 | > 202 | ReadStage:41 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39146-af3a-11e2-9480-e9d811e0fc18 > | Enqueuing response to /50.112.90.147 | 50.112.4.16 | > 572 | ReadStage:5329 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39146-af3a-11e2-9ec9-772ec39805fe > | Sending message to /10.252.153.16 | 50.112.90.147 | > 489 | WRITE-/50.112.4.16 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39146-af3a-11e2-b8dc-a7032a583115 > | Acquiring sstable references | 50.112.213.136 | > 215 | ReadStage:41 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39147-af3a-11e2-9480-e9d811e0fc18 > | Executing single-partition query on CardHash | 50.112.4.16 | > 610 | ReadStage:5330 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39147-af3a-11e2-b8dc-a7032a583115 > | Merging data from memtables and 0 sstables | 50.112.213.136 | > 239 | ReadStage:11 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39148-af3a-11e2-9480-e9d811e0fc18 > | Acquiring sstable references | 50.112.4.16 | > 625 | ReadStage:5330 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39148-af3a-11e2-b8dc-a7032a583115 > | Merging memtable contents | 50.112.213.136 | > 242 | ReadStage:41 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39149-af3a-11e2-9480-e9d811e0fc18 > | Sending message to /10.252.152.81 | 50.112.4.16 | > 627 | WRITE-/50.112.90.147 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39149-af3a-11e2-b8dc-a7032a583115 > | Read 0 live cells and 0 tombstoned | 50.112.213.136 | > 258 | ReadStage:11 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914a-af3a-11e2-9480-e9d811e0fc18 > | Merging memtable contents | 50.112.4.16 | > 646 | ReadStage:5330 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914a-af3a-11e2-b8dc-a7032a583115 > | Merging data from memtables and 0 sstables | 50.112.213.136 | > 287 | ReadStage:41 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914b-af3a-11e2-9480-e9d811e0fc18 > | Merging data from memtables and 0 sstables | 50.112.4.16 | > 679 | ReadStage:5330 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914b-af3a-11e2-b8dc-a7032a583115 > | Enqueuing response to /50.112.90.147 | 50.112.213.136 | > 301 | ReadStage:11 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914c-af3a-11e2-9480-e9d811e0fc18 > | Read 0 live cells and 0 tombstoned | 50.112.4.16 | > 704 | ReadStage:5330 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914c-af3a-11e2-b8dc-a7032a583115 > | Read 0 live cells and 0 tombstoned | 50.112.213.136 | > 311 | ReadStage:41 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914d-af3a-11e2-9480-e9d811e0fc18 > | Enqueuing response to /50.112.90.147 | 50.112.4.16 | > 763 | ReadStage:5330 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914d-af3a-11e2-b8dc-a7032a583115 > | Enqueuing response to /50.112.90.147 | 50.112.213.136 | > 354 | ReadStage:41 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914e-af3a-11e2-b8dc-a7032a583115 > | Sending message to /10.252.152.81 | 50.112.213.136 | > 374 | WRITE-/50.112.90.147 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b850-af3a-11e2-9ec9-772ec39805fe > | Message received from /50.112.213.136 | 50.112.90.147 | > 1289 | Thread-80 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b850-af3a-11e2-9f00-0b1bd79b59b0 > | Message received from /50.112.90.147 | 50.112.79.52 | > 28 | Thread-71 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b851-af3a-11e2-9ec9-772ec39805fe > | Processing response from /50.112.213.136 | 50.112.90.147 | > 1370 | RequestResponseStage:8 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b852-af3a-11e2-9ec9-772ec39805fe > | Message received from /50.112.4.16 | 50.112.90.147 | > 1533 | Thread-1435 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b853-af3a-11e2-9ec9-772ec39805fe > | Processing response from /50.112.4.16 | 50.112.90.147 | > 1598 | RequestResponseStage:7 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df60-af3a-11e2-9ec9-772ec39805fe > | Message received from /50.112.79.52 | 50.112.90.147 | > 2527 | Thread-143 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df60-af3a-11e2-9f00-0b1bd79b59b0 > | Message received from /50.112.90.147 | 50.112.79.52 | > 280 | Thread-71 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df61-af3a-11e2-9ec9-772ec39805fe > | Processing response from /50.112.79.52 | 50.112.90.147 | > 2604 | RequestResponseStage:6 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df61-af3a-11e2-9f00-0b1bd79b59b0 > | Executing single-partition query on CardHash | 50.112.79.52 | > 424 | ReadStage:6435 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df62-af3a-11e2-9f00-0b1bd79b59b0 > | Acquiring sstable references | 50.112.79.52 | > 445 | ReadStage:6435 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df63-af3a-11e2-9f00-0b1bd79b59b0 > | Merging memtable contents | 50.112.79.52 | > 474 | ReadStage:6435 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df64-af3a-11e2-9f00-0b1bd79b59b0 > | Merging data from memtables and 0 sstables | 50.112.79.52 | > 525 | ReadStage:6435 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df65-af3a-11e2-9f00-0b1bd79b59b0 > | Read 0 live cells and 0 tombstoned | 50.112.79.52 | > 545 | ReadStage:6435 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df66-af3a-11e2-9f00-0b1bd79b59b0 > | Enqueuing response to /50.112.90.147 | 50.112.79.52 | > 603 | ReadStage:6435 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df67-af3a-11e2-9f00-0b1bd79b59b0 > | Executing single-partition query on CardHash | 50.112.79.52 | > 617 | ReadStage:6436 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df68-af3a-11e2-9f00-0b1bd79b59b0 > | Acquiring sstable references | 50.112.79.52 | > 632 | ReadStage:6436 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df69-af3a-11e2-9f00-0b1bd79b59b0 > | Merging memtable contents | 50.112.79.52 | > 656 | ReadStage:6436 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6a-af3a-11e2-9f00-0b1bd79b59b0 > | Sending message to /10.252.152.81 | 50.112.79.52 | > 657 | WRITE-/50.112.90.147 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6b-af3a-11e2-9f00-0b1bd79b59b0 > | Merging data from memtables and 0 sstables | 50.112.79.52 | > 697 | ReadStage:6436 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6c-af3a-11e2-9f00-0b1bd79b59b0 > | Read 0 live cells and 0 tombstoned | 50.112.79.52 | > 718 | ReadStage:6436 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6d-af3a-11e2-9f00-0b1bd79b59b0 > | Enqueuing response to /50.112.90.147 | 50.112.79.52 | > 766 | ReadStage:6436 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40670-af3a-11e2-b266-75b700b21012 > | Message received from /50.112.90.147 | 50.112.201.218 | > 23 | Thread-47 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40671-af3a-11e2-b266-75b700b21012 > | Message received from /50.112.90.147 | 50.112.201.218 | > 81 | Thread-47 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40672-af3a-11e2-b266-75b700b21012 > | Executing single-partition query on CardHash | 50.112.201.218 | > 150 | ReadStage:58 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40673-af3a-11e2-b266-75b700b21012 > | Executing single-partition query on CardHash | 50.112.201.218 | > 158 | ReadStage:60 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40674-af3a-11e2-b266-75b700b21012 > | Acquiring sstable references | 50.112.201.218 | > 175 | ReadStage:58 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40675-af3a-11e2-b266-75b700b21012 > | Acquiring sstable references | 50.112.201.218 | > 176 | ReadStage:60 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40676-af3a-11e2-b266-75b700b21012 > | Merging memtable contents | 50.112.201.218 | > 201 | ReadStage:58 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40677-af3a-11e2-b266-75b700b21012 > | Merging memtable contents | 50.112.201.218 | > 201 | ReadStage:60 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40678-af3a-11e2-b266-75b700b21012 > | Merging data from memtables and 0 sstables | 50.112.201.218 | > 240 | ReadStage:58 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40679-af3a-11e2-b266-75b700b21012 > | Merging data from memtables and 0 sstables | 50.112.201.218 | > 243 | ReadStage:60 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067a-af3a-11e2-b266-75b700b21012 > | Read 0 live cells and 0 tombstoned | 50.112.201.218 | > 264 | ReadStage:58 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067b-af3a-11e2-b266-75b700b21012 > | Read 0 live cells and 0 tombstoned | 50.112.201.218 | > 264 | ReadStage:60 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067c-af3a-11e2-b266-75b700b21012 > | Enqueuing response to /50.112.90.147 | 50.112.201.218 | > 310 | ReadStage:60 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067d-af3a-11e2-b266-75b700b21012 > | Enqueuing response to /50.112.90.147 | 50.112.201.218 | > 310 | ReadStage:58 > c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067e-af3a-11e2-b266-75b700b21012 > | Sending message to /10.252.152.81 | 50.112.201.218 | > 369 | WRITE-/50.112.90.147 -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators For more information on JIRA, see: http://www.atlassian.com/software/jira