Return-Path: X-Original-To: apmail-cassandra-commits-archive@www.apache.org Delivered-To: apmail-cassandra-commits-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 0DE1FF0F6 for ; Wed, 1 May 2013 08:38:24 +0000 (UTC) Received: (qmail 79515 invoked by uid 500); 1 May 2013 08:38:23 -0000 Delivered-To: apmail-cassandra-commits-archive@cassandra.apache.org Received: (qmail 79355 invoked by uid 500); 1 May 2013 08:38:21 -0000 Mailing-List: contact commits-help@cassandra.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cassandra.apache.org Delivered-To: mailing list commits@cassandra.apache.org Received: (qmail 79250 invoked by uid 99); 1 May 2013 08:38:20 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 01 May 2013 08:38:20 +0000 Date: Wed, 1 May 2013 08:38:20 +0000 (UTC) From: "Sylvain Lebresne (JIRA)" To: commits@cassandra.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (CASSANDRA-5520) Query tracing session info inconsistent with events info MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CASSANDRA-5520?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13646456#comment-13646456 ] Sylvain Lebresne commented on CASSANDRA-5520: --------------------------------------------- To be fair to Ilya, maybe we could add a line in the trace log saying that we've timeouted, how many response we were waiting for, and which node answered. Could also be useful to record with the session info the result of the operation (i.e. success or exception), so it's easy to filter out the one that have thrown (without having to compare the total duration to the rpc timeout, which can be painful if you've change the rpc timeout a few time, and besides it's not like our timeout are very precise so I think it's possible (though very unlikely) for a query to have a total duration slightly greater than the rpc timeout without having timeouted). I'ts improvement, not bugs, but still likely nice to have. > 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