[
https://issues.apache.org/jira/browse/CASSANDRA-5520?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13704673#comment-13704673
]
Tyler Hobbs commented on CASSANDRA-5520:
----------------------------------------
bq. I was going to commit this but then I realized we still have a bunch of
logger.debug for the timeouts in CassandraServer. Inclined to say we should
just rip out logger.debug on this path after all, it's too noisy to use in a
live system and tracing is just better all around. WDYT?
I rarely use debug logging (especially while looking into timeouts), so I can't
say how useful it is, but I feel like some mention of the timeout happening at
debug level would be good, especially considering it's a somewhat rare event.
bq. Meant to comment on this earlier – it does seem useful to denormalize this
into sessions, maybe even index it so you can easily query it for failures when
you have the "trace N% of my requests" turned on. (Should we enable that by
default in 2.0?) ... However if we are going to standardize tracing events soon
(CASSANDRA-5672) then we could index the event type directly which would be
almost as user-friendly, so it might not warrant its own sessions column.
Adding a session column seems a little more human-user friendly to me, so
perhaps having both would be good.
Regarding enabling tracing by default, I'm -1 on that. Given that it incurs
extra overhead, I say we follow the principle of least surprise and only enable
it when requested.
bq. Either way I think it's worth pulling into a separate ticket.
Thanks, I agree.
> Query tracing session info inconsistent with events info
> --------------------------------------------------------
>
> Key: CASSANDRA-5520
> URL: https://issues.apache.org/jira/browse/CASSANDRA-5520
> Project: Cassandra
> Issue Type: Improvement
> Affects Versions: 1.2.4
> Environment: Linux
> Reporter: Ilya Kirnos
> Assignee: Tyler Hobbs
> Priority: Minor
> Attachments: 5520-v1.txt, 5520-v2.txt, 5520-v3.txt
>
>
> Session info for a trace is showing that a query took > 10 seconds (it timed
> out).
> {noformat}
> 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
> {noformat}
--
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
