[CASSANDRA-7657] tracing doesn't finalize under load when it should

• Type: Bug
• Status: Resolved
• Priority: Normal
• Resolution: Fixed
• Severity: Normal
• Since Version: 2.1 rc4
• Assignee: Unassigned
• Reporter: Brandon Williams
• Created: 31/Jul/14 15:40
• Updated: 16/Apr/19 09:31
• Resolved: 31/Jul/14 15:49

Description

If I run stress against a cluster and trace queries in cqlsh, queries that complete well within time don't finalize:

session_id                           | event_id                             | activity                                                          | source        | source_elapsed | thread
--------------------------------------+--------------------------------------+-------------------------------------------------------------------+---------------+----------------+-------------------------
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1130e3a1-18c8-11e4-95bf-4b4842ed69b9 | Parsing insert into "Standard1" (key, "C0") VALUES ( 0xff, 0xff); |  10.208.8.123 |            105 |    SharedPool-Worker-12
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1130e3a2-18c8-11e4-95bf-4b4842ed69b9 |                                               Preparing statement |  10.208.8.123 |            450 |    SharedPool-Worker-12
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1130e3a3-18c8-11e4-95bf-4b4842ed69b9 |                                 Determining replicas for mutation |  10.208.8.123 |            533 |    SharedPool-Worker-12
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 11310ab0-18c8-11e4-95bf-4b4842ed69b9 |                                   Sending message to /10.208.8.63 |  10.208.8.123 |           1511 |      WRITE-/10.208.8.63
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 113131c0-18c8-11e4-95bf-4b4842ed69b9 |                                 Sending message to /10.208.35.225 |  10.208.8.123 |           2010 |    WRITE-/10.208.35.225
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 113158d0-18c8-11e4-95bf-4b4842ed69b9 |                                Message received from /10.208.8.63 |  10.208.8.123 |           3544 |                Thread-6
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 11317fe0-18c8-11e4-95bf-4b4842ed69b9 |                             Processing response from /10.208.8.63 |  10.208.8.123 |           3718 |    SharedPool-Worker-16
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131a6f0-18c8-11e4-95bf-4b4842ed69b9 |                              Message received from /10.208.35.225 |  10.208.8.123 |           4762 |                Thread-3
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131a6f0-18c8-11e4-b290-3b546d897db7 |                               Message received from /10.208.8.123 |   10.208.8.63 |             46 |              Thread-346
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131a6f1-18c8-11e4-95bf-4b4842ed69b9 |                           Processing response from /10.208.35.225 |  10.208.8.123 |           4938 |    SharedPool-Worker-34
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131a6f1-18c8-11e4-b290-3b546d897db7 |                                            Appending to commitlog |   10.208.8.63 |            198 |     SharedPool-Worker-7
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131a6f2-18c8-11e4-b290-3b546d897db7 |                                      Adding to Standard1 memtable |   10.208.8.63 |            235 |     SharedPool-Worker-7
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131ce00-18c8-11e4-9b6e-517bcdb23258 |                               Message received from /10.208.8.123 | 10.208.35.225 |             83 |                Thread-4
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131ce00-18c8-11e4-b290-3b546d897db7 |                               Enqueuing response to /10.208.8.123 |   10.208.8.63 |            283 |     SharedPool-Worker-7
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131ce01-18c8-11e4-9b6e-517bcdb23258 |                                            Appending to commitlog | 10.208.35.225 |            367 |     SharedPool-Worker-4
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131ce01-18c8-11e4-b290-3b546d897db7 |                              Sending message to bw-1/10.208.8.123 |   10.208.8.63 |            447 | WRITE-bw-1/10.208.8.123
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131ce02-18c8-11e4-9b6e-517bcdb23258 |                                      Adding to Standard1 memtable | 10.208.35.225 |            434 |     SharedPool-Worker-4
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131ce03-18c8-11e4-9b6e-517bcdb23258 |                               Enqueuing response to /10.208.8.123 | 10.208.35.225 |            494 |     SharedPool-Worker-4
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 1131f510-18c8-11e4-9b6e-517bcdb23258 |                              Sending message to bw-1/10.208.8.123 | 10.208.35.225 |            840 | WRITE-bw-1/10.208.8.123

Leaving the duration null:

 session_id                           | coordinator  | duration | parameters                                                                                  | request            | started_at
--------------------------------------+--------------+----------+---------------------------------------------------------------------------------------------+--------------------+--------------------------
 1130e3a0-18c8-11e4-95bf-4b4842ed69b9 | 10.208.8.123 |     null | {'page_size': '5000', 'query': 'insert into "Standard1" (key, "C0") VALUES ( 0xff, 0xff);'} | Execute CQL3 query | 2014-07-31 15:33:48+0000

This doesn't happen on 2.0.

Issue Links

• duplicates: CASSANDRA-7644 tracing does not log commitlog/memtable ops when the coordinator is a replica