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 A7A04F464 for ; Sun, 28 Apr 2013 06:50:16 +0000 (UTC) Received: (qmail 28479 invoked by uid 500); 28 Apr 2013 06:50:16 -0000 Delivered-To: apmail-cassandra-commits-archive@cassandra.apache.org Received: (qmail 28411 invoked by uid 500); 28 Apr 2013 06:50:16 -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 28393 invoked by uid 99); 28 Apr 2013 06:50:16 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 28 Apr 2013 06:50:16 +0000 Date: Sun, 28 Apr 2013 06:50:15 +0000 (UTC) From: "Ilya Kirnos (JIRA)" To: commits@cassandra.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (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 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 | 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 /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 | 50.112.213.136 | 202 | ReadStage:41 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39146-af3a-11e2-9480-e9d811e0fc18 | Enqueuing response to /50.112.90.147 | 50.112.4.16 | 572 | ReadStage:5329 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39146-af3a-11e2-9ec9-772ec39805fe | Sending message to /10.252.153.16 | 50.112.90.147 | 489 | WRITE-/50.112.4.16 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39146-af3a-11e2-b8dc-a7032a583115 | Acquiring sstable references | 50.112.213.136 | 215 | ReadStage:41 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39147-af3a-11e2-9480-e9d811e0fc18 | Executing single-partition query on CardHash | 50.112.4.16 | 610 | ReadStage:5330 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39147-af3a-11e2-b8dc-a7032a583115 | Merging data from memtables and 0 sstables | 50.112.213.136 | 239 | ReadStage:11 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39148-af3a-11e2-9480-e9d811e0fc18 | Acquiring sstable references | 50.112.4.16 | 625 | ReadStage:5330 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39148-af3a-11e2-b8dc-a7032a583115 | Merging memtable contents | 50.112.213.136 | 242 | ReadStage:41 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39149-af3a-11e2-9480-e9d811e0fc18 | Sending message to /10.252.152.81 | 50.112.4.16 | 627 | WRITE-/50.112.90.147 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e39149-af3a-11e2-b8dc-a7032a583115 | Read 0 live cells and 0 tombstoned | 50.112.213.136 | 258 | ReadStage:11 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914a-af3a-11e2-9480-e9d811e0fc18 | Merging memtable contents | 50.112.4.16 | 646 | ReadStage:5330 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914a-af3a-11e2-b8dc-a7032a583115 | Merging data from memtables and 0 sstables | 50.112.213.136 | 287 | ReadStage:41 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914b-af3a-11e2-9480-e9d811e0fc18 | Merging data from memtables and 0 sstables | 50.112.4.16 | 679 | ReadStage:5330 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914b-af3a-11e2-b8dc-a7032a583115 | Enqueuing response to /50.112.90.147 | 50.112.213.136 | 301 | ReadStage:11 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914c-af3a-11e2-9480-e9d811e0fc18 | Read 0 live cells and 0 tombstoned | 50.112.4.16 | 704 | ReadStage:5330 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914c-af3a-11e2-b8dc-a7032a583115 | Read 0 live cells and 0 tombstoned | 50.112.213.136 | 311 | ReadStage:41 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914d-af3a-11e2-9480-e9d811e0fc18 | Enqueuing response to /50.112.90.147 | 50.112.4.16 | 763 | ReadStage:5330 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914d-af3a-11e2-b8dc-a7032a583115 | Enqueuing response to /50.112.90.147 | 50.112.213.136 | 354 | ReadStage:41 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3914e-af3a-11e2-b8dc-a7032a583115 | Sending message to /10.252.152.81 | 50.112.213.136 | 374 | WRITE-/50.112.90.147 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b850-af3a-11e2-9ec9-772ec39805fe | Message received from /50.112.213.136 | 50.112.90.147 | 1289 | Thread-80 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b850-af3a-11e2-9f00-0b1bd79b59b0 | Message received from /50.112.90.147 | 50.112.79.52 | 28 | Thread-71 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b851-af3a-11e2-9ec9-772ec39805fe | Processing response from /50.112.213.136 | 50.112.90.147 | 1370 | RequestResponseStage:8 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b852-af3a-11e2-9ec9-772ec39805fe | Message received from /50.112.4.16 | 50.112.90.147 | 1533 | Thread-1435 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3b853-af3a-11e2-9ec9-772ec39805fe | Processing response from /50.112.4.16 | 50.112.90.147 | 1598 | RequestResponseStage:7 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df60-af3a-11e2-9ec9-772ec39805fe | Message received from /50.112.79.52 | 50.112.90.147 | 2527 | Thread-143 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df60-af3a-11e2-9f00-0b1bd79b59b0 | Message received from /50.112.90.147 | 50.112.79.52 | 280 | Thread-71 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df61-af3a-11e2-9ec9-772ec39805fe | Processing response from /50.112.79.52 | 50.112.90.147 | 2604 | RequestResponseStage:6 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df61-af3a-11e2-9f00-0b1bd79b59b0 | Executing single-partition query on CardHash | 50.112.79.52 | 424 | ReadStage:6435 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df62-af3a-11e2-9f00-0b1bd79b59b0 | Acquiring sstable references | 50.112.79.52 | 445 | ReadStage:6435 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df63-af3a-11e2-9f00-0b1bd79b59b0 | Merging memtable contents | 50.112.79.52 | 474 | ReadStage:6435 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df64-af3a-11e2-9f00-0b1bd79b59b0 | Merging data from memtables and 0 sstables | 50.112.79.52 | 525 | ReadStage:6435 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df65-af3a-11e2-9f00-0b1bd79b59b0 | Read 0 live cells and 0 tombstoned | 50.112.79.52 | 545 | ReadStage:6435 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df66-af3a-11e2-9f00-0b1bd79b59b0 | Enqueuing response to /50.112.90.147 | 50.112.79.52 | 603 | ReadStage:6435 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df67-af3a-11e2-9f00-0b1bd79b59b0 | Executing single-partition query on CardHash | 50.112.79.52 | 617 | ReadStage:6436 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df68-af3a-11e2-9f00-0b1bd79b59b0 | Acquiring sstable references | 50.112.79.52 | 632 | ReadStage:6436 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df69-af3a-11e2-9f00-0b1bd79b59b0 | Merging memtable contents | 50.112.79.52 | 656 | ReadStage:6436 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6a-af3a-11e2-9f00-0b1bd79b59b0 | Sending message to /10.252.152.81 | 50.112.79.52 | 657 | WRITE-/50.112.90.147 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6b-af3a-11e2-9f00-0b1bd79b59b0 | Merging data from memtables and 0 sstables | 50.112.79.52 | 697 | ReadStage:6436 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6c-af3a-11e2-9f00-0b1bd79b59b0 | Read 0 live cells and 0 tombstoned | 50.112.79.52 | 718 | ReadStage:6436 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e3df6d-af3a-11e2-9f00-0b1bd79b59b0 | Enqueuing response to /50.112.90.147 | 50.112.79.52 | 766 | ReadStage:6436 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40670-af3a-11e2-b266-75b700b21012 | Message received from /50.112.90.147 | 50.112.201.218 | 23 | Thread-47 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40671-af3a-11e2-b266-75b700b21012 | Message received from /50.112.90.147 | 50.112.201.218 | 81 | Thread-47 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40672-af3a-11e2-b266-75b700b21012 | Executing single-partition query on CardHash | 50.112.201.218 | 150 | ReadStage:58 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40673-af3a-11e2-b266-75b700b21012 | Executing single-partition query on CardHash | 50.112.201.218 | 158 | ReadStage:60 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40674-af3a-11e2-b266-75b700b21012 | Acquiring sstable references | 50.112.201.218 | 175 | ReadStage:58 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40675-af3a-11e2-b266-75b700b21012 | Acquiring sstable references | 50.112.201.218 | 176 | ReadStage:60 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40676-af3a-11e2-b266-75b700b21012 | Merging memtable contents | 50.112.201.218 | 201 | ReadStage:58 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40677-af3a-11e2-b266-75b700b21012 | Merging memtable contents | 50.112.201.218 | 201 | ReadStage:60 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40678-af3a-11e2-b266-75b700b21012 | Merging data from memtables and 0 sstables | 50.112.201.218 | 240 | ReadStage:58 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e40679-af3a-11e2-b266-75b700b21012 | Merging data from memtables and 0 sstables | 50.112.201.218 | 243 | ReadStage:60 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067a-af3a-11e2-b266-75b700b21012 | Read 0 live cells and 0 tombstoned | 50.112.201.218 | 264 | ReadStage:58 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067b-af3a-11e2-b266-75b700b21012 | Read 0 live cells and 0 tombstoned | 50.112.201.218 | 264 | ReadStage:60 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067c-af3a-11e2-b266-75b700b21012 | Enqueuing response to /50.112.90.147 | 50.112.201.218 | 310 | ReadStage:60 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067d-af3a-11e2-b266-75b700b21012 | Enqueuing response to /50.112.90.147 | 50.112.201.218 | 310 | ReadStage:58 c7e36a30-af3a-11e2-9ec9-772ec39805fe | c7e4067e-af3a-11e2-b266-75b700b21012 | Sending message to /10.252.152.81 | 50.112.201.218 | 369 | WRITE-/50.112.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