[
https://issues.apache.org/jira/browse/CASSANDRA-5520?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13646116#comment-13646116
]
Brandon Williams edited comment on CASSANDRA-5520 at 4/30/13 11:08 PM:
-----------------------------------------------------------------------
The events may not always add up to the total. There are at least two ways
sessions and events can be inconsistent with each other: first, there are
events happening after the session has ended, and second, there are too few
events to explain why the session ended so late. You seem to have the latter
case.
was (Author: brandon.williams):
The events may not always add up to the total. There are at least two ways
sessions and events can be inconsistent with each other: first, there are
events happening after the session has ended, and second, there are too few
events to explain why the session ended so late. You see to have the latter
case.
> 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 /xxx.xxx.90.147 | xxx.xxx.4.16 | 19 | Thread-57
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e36a31-af3a-11e2-9ec9-772ec39805fe |
> Sending message to /xxx.xxx.153.16 | xxx.xxx.90.147 | 246 |
> WRITE-/xxx.xxx.4.16
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39140-af3a-11e2-9480-e9d811e0fc18 |
> Message received from /xxx.xxx.90.147 | xxx.xxx.4.16 | 259 | Thread-57
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39140-af3a-11e2-9ec9-772ec39805fe |
> Sending message to /10.248.106.37 | xxx.xxx.90.147 | 253 |
> WRITE-/xxx.xxx.79.52
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39140-af3a-11e2-b8dc-a7032a583115 |
> Message received from /xxx.xxx.90.147 | xxx.xxx.213.136 | 25 | Thread-94
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39141-af3a-11e2-9480-e9d811e0fc18 |
> Executing single-partition query on CardHash | xxx.xxx.4.16 | 421 |
> ReadStage:5329
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39141-af3a-11e2-9ec9-772ec39805fe |
> Sending message to /xxx.xxx.151.214 | xxx.xxx.90.147 | 310 |
> WRITE-/xxx.xxx.213.136
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39141-af3a-11e2-b8dc-a7032a583115 |
> Message received from /xxx.xxx.90.147 | xxx.xxx.213.136 | 106 | Thread-94
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39142-af3a-11e2-9480-e9d811e0fc18 |
> Acquiring sstable references | xxx.xxx.4.16 | 444 | ReadStage:5329
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39142-af3a-11e2-9ec9-772ec39805fe |
> Sending message to /10.248.106.37 | xxx.xxx.90.147 | 352 |
> WRITE-/xxx.xxx.79.52
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39142-af3a-11e2-b8dc-a7032a583115 |
> Executing single-partition query on CardHash | xxx.xxx.213.136 | 144 |
> ReadStage:11
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39143-af3a-11e2-9480-e9d811e0fc18 |
> Merging memtable contents | xxx.xxx.4.16 | 472 | ReadStage:5329
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39143-af3a-11e2-9ec9-772ec39805fe |
> Sending message to /10.248.95.237 | xxx.xxx.90.147 | 362 |
> WRITE-/xxx.xxx.201.218
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39143-af3a-11e2-b8dc-a7032a583115 |
> Acquiring sstable references | xxx.xxx.213.136 | 164 | ReadStage:11
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39144-af3a-11e2-9480-e9d811e0fc18 |
> Merging data from memtables and 0 sstables | xxx.xxx.4.16 | 510 |
> ReadStage:5329
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39144-af3a-11e2-9ec9-772ec39805fe |
> Sending message to /xxx.xxx.151.214 | xxx.xxx.90.147 | 376 |
> WRITE-/xxx.xxx.213.136
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39144-af3a-11e2-b8dc-a7032a583115 |
> Merging memtable contents | xxx.xxx.213.136 | 195 | ReadStage:11
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39145-af3a-11e2-9480-e9d811e0fc18 |
> Read 0 live cells and 0 tombstoned | xxx.xxx.4.16 | 530 | ReadStage:5329
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39145-af3a-11e2-9ec9-772ec39805fe |
> Sending message to /10.248.95.237 | xxx.xxx.90.147 | 401 |
> WRITE-/xxx.xxx.201.218
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39145-af3a-11e2-b8dc-a7032a583115 |
> Executing single-partition query on CardHash | xxx.xxx.213.136 | 202 |
> ReadStage:41
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39146-af3a-11e2-9480-e9d811e0fc18 |
> Enqueuing response to /xxx.xxx.90.147 | xxx.xxx.4.16 | 572 | ReadStage:5329
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39146-af3a-11e2-9ec9-772ec39805fe |
> Sending message to /xxx.xxx.153.16 | xxx.xxx.90.147 | 489 |
> WRITE-/xxx.xxx.4.16
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39146-af3a-11e2-b8dc-a7032a583115 |
> Acquiring sstable references | xxx.xxx.213.136 | 215 | ReadStage:41
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39147-af3a-11e2-9480-e9d811e0fc18 |
> Executing single-partition query on CardHash | xxx.xxx.4.16 | 610 |
> ReadStage:5330
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39147-af3a-11e2-b8dc-a7032a583115 |
> Merging data from memtables and 0 sstables | xxx.xxx.213.136 | 239 |
> ReadStage:11
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39148-af3a-11e2-9480-e9d811e0fc18 |
> Acquiring sstable references | xxx.xxx.4.16 | 625 | ReadStage:5330
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39148-af3a-11e2-b8dc-a7032a583115 |
> Merging memtable contents | xxx.xxx.213.136 | 242 | ReadStage:41
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39149-af3a-11e2-9480-e9d811e0fc18 |
> Sending message to /xxx.xxx.152.81 | xxx.xxx.4.16 | 627 |
> WRITE-/xxx.xxx.90.147
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39149-af3a-11e2-b8dc-a7032a583115 |
> Read 0 live cells and 0 tombstoned | xxx.xxx.213.136 | 258 | ReadStage:11
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914a-af3a-11e2-9480-e9d811e0fc18 |
> Merging memtable contents | xxx.xxx.4.16 | 646 | ReadStage:5330
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914a-af3a-11e2-b8dc-a7032a583115 |
> Merging data from memtables and 0 sstables | xxx.xxx.213.136 | 287 |
> ReadStage:41
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914b-af3a-11e2-9480-e9d811e0fc18 |
> Merging data from memtables and 0 sstables | xxx.xxx.4.16 | 679 |
> ReadStage:5330
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914b-af3a-11e2-b8dc-a7032a583115 |
> Enqueuing response to /xxx.xxx.90.147 | xxx.xxx.213.136 | 301 | ReadStage:11
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914c-af3a-11e2-9480-e9d811e0fc18 |
> Read 0 live cells and 0 tombstoned | xxx.xxx.4.16 | 704 | ReadStage:5330
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914c-af3a-11e2-b8dc-a7032a583115 |
> Read 0 live cells and 0 tombstoned | xxx.xxx.213.136 | 311 | ReadStage:41
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914d-af3a-11e2-9480-e9d811e0fc18 |
> Enqueuing response to /xxx.xxx.90.147 | xxx.xxx.4.16 | 763 | ReadStage:5330
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914d-af3a-11e2-b8dc-a7032a583115 |
> Enqueuing response to /xxx.xxx.90.147 | xxx.xxx.213.136 | 354 | ReadStage:41
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914e-af3a-11e2-b8dc-a7032a583115 |
> Sending message to /xxx.xxx.152.81 | xxx.xxx.213.136 | 374 |
> WRITE-/xxx.xxx.90.147
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b850-af3a-11e2-9ec9-772ec39805fe |
> Message received from /xxx.xxx.213.136 | xxx.xxx.90.147 | 1289 | Thread-80
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b850-af3a-11e2-9f00-0b1bd79b59b0 |
> Message received from /xxx.xxx.90.147 | xxx.xxx.79.52 | 28 | Thread-71
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b851-af3a-11e2-9ec9-772ec39805fe |
> Processing response from /xxx.xxx.213.136 | xxx.xxx.90.147 | 1370 |
> RequestResponseStage:8
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b852-af3a-11e2-9ec9-772ec39805fe |
> Message received from /xxx.xxx.4.16 | xxx.xxx.90.147 | 1533 | Thread-1435
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b853-af3a-11e2-9ec9-772ec39805fe |
> Processing response from /xxx.xxx.4.16 | xxx.xxx.90.147 | 1598 |
> RequestResponseStage:7
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df60-af3a-11e2-9ec9-772ec39805fe |
> Message received from /xxx.xxx.79.52 | xxx.xxx.90.147 | 2527 | Thread-143
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df60-af3a-11e2-9f00-0b1bd79b59b0 |
> Message received from /xxx.xxx.90.147 | xxx.xxx.79.52 | 280 | Thread-71
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df61-af3a-11e2-9ec9-772ec39805fe |
> Processing response from /xxx.xxx.79.52 | xxx.xxx.90.147 | 2604 |
> RequestResponseStage:6
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df61-af3a-11e2-9f00-0b1bd79b59b0 |
> Executing single-partition query on CardHash | xxx.xxx.79.52 | 424 |
> ReadStage:6435
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df62-af3a-11e2-9f00-0b1bd79b59b0 |
> Acquiring sstable references | xxx.xxx.79.52 | 445 | ReadStage:6435
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df63-af3a-11e2-9f00-0b1bd79b59b0 |
> Merging memtable contents | xxx.xxx.79.52 | 474 | ReadStage:6435
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df64-af3a-11e2-9f00-0b1bd79b59b0 |
> Merging data from memtables and 0 sstables | xxx.xxx.79.52 | 525 |
> ReadStage:6435
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df65-af3a-11e2-9f00-0b1bd79b59b0 |
> Read 0 live cells and 0 tombstoned | xxx.xxx.79.52 | 545 | ReadStage:6435
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df66-af3a-11e2-9f00-0b1bd79b59b0 |
> Enqueuing response to /xxx.xxx.90.147 | xxx.xxx.79.52 | 603 | ReadStage:6435
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df67-af3a-11e2-9f00-0b1bd79b59b0 |
> Executing single-partition query on CardHash | xxx.xxx.79.52 | 617 |
> ReadStage:6436
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df68-af3a-11e2-9f00-0b1bd79b59b0 |
> Acquiring sstable references | xxx.xxx.79.52 | 632 | ReadStage:6436
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df69-af3a-11e2-9f00-0b1bd79b59b0 |
> Merging memtable contents | xxx.xxx.79.52 | 656 | ReadStage:6436
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6a-af3a-11e2-9f00-0b1bd79b59b0 |
> Sending message to /xxx.xxx.152.81 | xxx.xxx.79.52 | 657 |
> WRITE-/xxx.xxx.90.147
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6b-af3a-11e2-9f00-0b1bd79b59b0 |
> Merging data from memtables and 0 sstables | xxx.xxx.79.52 | 697 |
> ReadStage:6436
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6c-af3a-11e2-9f00-0b1bd79b59b0 |
> Read 0 live cells and 0 tombstoned | xxx.xxx.79.52 | 718 | ReadStage:6436
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6d-af3a-11e2-9f00-0b1bd79b59b0 |
> Enqueuing response to /xxx.xxx.90.147 | xxx.xxx.79.52 | 766 | ReadStage:6436
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40670-af3a-11e2-b266-75b700b21012 |
> Message received from /xxx.xxx.90.147 | xxx.xxx.201.218 | 23 | Thread-47
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40671-af3a-11e2-b266-75b700b21012 |
> Message received from /xxx.xxx.90.147 | xxx.xxx.201.218 | 81 | Thread-47
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40672-af3a-11e2-b266-75b700b21012 |
> Executing single-partition query on CardHash | xxx.xxx.201.218 | 150 |
> ReadStage:58
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40673-af3a-11e2-b266-75b700b21012 |
> Executing single-partition query on CardHash | xxx.xxx.201.218 | 158 |
> ReadStage:60
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40674-af3a-11e2-b266-75b700b21012 |
> Acquiring sstable references | xxx.xxx.201.218 | 175 | ReadStage:58
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40675-af3a-11e2-b266-75b700b21012 |
> Acquiring sstable references | xxx.xxx.201.218 | 176 | ReadStage:60
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40676-af3a-11e2-b266-75b700b21012 |
> Merging memtable contents | xxx.xxx.201.218 | 201 | ReadStage:58
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40677-af3a-11e2-b266-75b700b21012 |
> Merging memtable contents | xxx.xxx.201.218 | 201 | ReadStage:60
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40678-af3a-11e2-b266-75b700b21012 |
> Merging data from memtables and 0 sstables | xxx.xxx.201.218 | 240 |
> ReadStage:58
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40679-af3a-11e2-b266-75b700b21012 |
> Merging data from memtables and 0 sstables | xxx.xxx.201.218 | 243 |
> ReadStage:60
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067a-af3a-11e2-b266-75b700b21012 |
> Read 0 live cells and 0 tombstoned | xxx.xxx.201.218 | 264 | ReadStage:58
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067b-af3a-11e2-b266-75b700b21012 |
> Read 0 live cells and 0 tombstoned | xxx.xxx.201.218 | 264 | ReadStage:60
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067c-af3a-11e2-b266-75b700b21012 |
> Enqueuing response to /xxx.xxx.90.147 | xxx.xxx.201.218 | 310 | ReadStage:60
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067d-af3a-11e2-b266-75b700b21012 |
> Enqueuing response to /xxx.xxx.90.147 | xxx.xxx.201.218 | 310 | ReadStage:58
> c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067e-af3a-11e2-b266-75b700b21012 |
> Sending message to /xxx.xxx.152.81 | xxx.xxx.201.218 | 369 |
> WRITE-/xxx.xxx.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
