[jira] [Comment Edited] (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=13646587#comment-13646587
]
Jonathan Ellis edited comment on CASSANDRA-5520 at 5/1/13 1:54 PM:
---
As I said on IRC, I think the fix is as simple as changing {{logger.debug(...
timed out)}} to trace calls in CassandraServer. (More precisely, we should
trace it if tracing is enabled, otherwise logger.debug it, for symmetry with
our open-trace-session code.)
If we're going to gold-plate it, including the result in the trace (but not the
debug call, we only want to construct it if requested, because creating Strings
is expensive) is a good idea too. :)
was (Author: jbellis):
As I said on IRC, I think the fix is as simple as changing
{{logger.debug(... timed out)}} to trace calls. (More precisely, we should
trace it if tracing is enabled, otherwise logger.debug it, for symmetry with
our open-trace-session code.)
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
Assignee: Aleksey Yeschenko
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
[jira] [Comment Edited] (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=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 | 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 |
