[jira] [Commented] (CASSANDRA-5520) Query tracing session info inconsistent with events info
[ https://issues.apache.org/jira/browse/CASSANDRA-5520?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13645945#comment-13645945 ] Ilya Kirnos commented on CASSANDRA-5520: just to clarify: how can i tell which part of the request caused the timeout? or are you saying that all the parts, when added up, exceed 10 seconds? looking at the trace above, that's not the 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 | 1230 | 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
[jira] [Updated] (CASSANDRA-5520) Query tracing session info inconsistent with events info
[ https://issues.apache.org/jira/browse/CASSANDRA-5520?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Ilya Kirnos updated CASSANDRA-5520: --- Description: 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 | 1230 | 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
[jira] [Commented] (CASSANDRA-5520) Query tracing session info inconsistent with events info
[ https://issues.apache.org/jira/browse/CASSANDRA-5520?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13646135#comment-13646135 ] Ilya Kirnos commented on CASSANDRA-5520: Sorry to be dense, but: what does it mean for a session to end late with no events seemingly in flight? isn't a session just a container for events? 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 | 1230 | 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 |
[jira] [Created] (CASSANDRA-5520) Query tracing session info inconsistent with events info
Ilya Kirnos created CASSANDRA-5520: -- Summary: 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 | 1230 | 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 |
