mirror of
https://github.com/scylladb/scylladb.git
synced 2026-06-03 05:26:58 +00:00
581d619572
A speculative retry can appear out of the blue[1] and confuse people, as
it looks like the consistency level was elevated. Fix by adding such
a tracepoint.
Sample output:
```
activity | timestamp | source | source_elapsed | client
---------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2024-06-27 14:25:58.947000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing a statement [shard 0] | 2024-06-27 14:25:58.947918 | 127.0.0.1 | 2 | 127.0.0.1
Processing a statement for authenticated user: anonymous [shard 0] | 2024-06-27 14:25:58.948025 | 127.0.0.1 | 108 | 127.0.0.1
Creating read executor for token -4069959284402364209 with all: [127.0.0.1, 127.0.0.2] targets: [127.0.0.2] repair decision: NONE [shard 0] | 2024-06-27 14:25:58.948125 | 127.0.0.1 | 209 | 127.0.0.1
Added extra target 127.0.0.1 for speculative read [shard 0] | 2024-06-27 14:25:58.948128 | 127.0.0.1 | 212 | 127.0.0.1
Creating speculating_read_executor [shard 0] | 2024-06-27 14:25:58.948129 | 127.0.0.1 | 213 | 127.0.0.1
read_data: sending a message to /127.0.0.2 [shard 0] | 2024-06-27 14:25:58.948138 | 127.0.0.1 | 222 | 127.0.0.1
Launching speculative retry for data [shard 0] | 2024-06-27 14:25:58.948234 | 127.0.0.1 | 318 | 127.0.0.1
read_data: querying locally [shard 0] | 2024-06-27 14:25:58.948235 | 127.0.0.1 | 319 | 127.0.0.1
Start querying singular range {{-4069959284402364209, pk{000400000001}}} [shard 0] | 2024-06-27 14:25:58.948246 | 127.0.0.1 | 330 | 127.0.0.1
[reader concurrency semaphore user] admitted immediately [shard 0] | 2024-06-27 14:25:58.948250 | 127.0.0.1 | 334 | 127.0.0.1
[reader concurrency semaphore user] executing read [shard 0] | 2024-06-27 14:25:58.948258 | 127.0.0.1 | 342 | 127.0.0.1
Querying cache for range {{-4069959284402364209, pk{000400000001}}} and slice [(-inf, +inf)] [shard 0] | 2024-06-27 14:25:58.948281 | 127.0.0.1 | 365 | 127.0.0.1
Page stats: 1 partition(s), 0 static row(s) (0 live, 0 dead), 1 clustering row(s) (1 live, 0 dead) and 0 range tombstone(s) [shard 0] | 2024-06-27 14:25:58.948311 | 127.0.0.1 | 395 | 127.0.0.1
Querying is done [shard 0] | 2024-06-27 14:25:58.948320 | 127.0.0.1 | 404 | 127.0.0.1
read_data: message received from /127.0.0.1 [shard 0] | 2024-06-27 14:25:58.948351 | 127.0.0.2 | 12 | 127.0.0.1
Done processing - preparing a result [shard 0] | 2024-06-27 14:25:58.948354 | 127.0.0.1 | 438 | 127.0.0.1
Start querying singular range {{-4069959284402364209, pk{000400000001}}} [shard 0] | 2024-06-27 14:25:58.948370 | 127.0.0.2 | 31 | 127.0.0.1
[reader concurrency semaphore user] admitted immediately [shard 0] | 2024-06-27 14:25:58.948374 | 127.0.0.2 | 35 | 127.0.0.1
[reader concurrency semaphore user] executing read [shard 0] | 2024-06-27 14:25:58.948388 | 127.0.0.2 | 49 | 127.0.0.1
Querying cache for range {{-4069959284402364209, pk{000400000001}}} and slice [(-inf, +inf)] [shard 0] | 2024-06-27 14:25:58.948405 | 127.0.0.2 | 66 | 127.0.0.1
Page stats: 1 partition(s), 0 static row(s) (0 live, 0 dead), 1 clustering row(s) (1 live, 0 dead) and 0 range tombstone(s) [shard 0] | 2024-06-27 14:25:58.948424 | 127.0.0.2 | 85 | 127.0.0.1
Querying is done [shard 0] | 2024-06-27 14:25:58.948430 | 127.0.0.2 | 91 | 127.0.0.1
read_data handling is done, sending a response to /127.0.0.1 [shard 0] | 2024-06-27 14:25:58.948436 | 127.0.0.2 | 97 | 127.0.0.1
read_data: got response from /127.0.0.2 [shard 0] | 2024-06-27 14:25:58.949140 | 127.0.0.1 | 1224 | 127.0.0.1
Request complete | 2024-06-27 14:25:58.947449 | 127.0.0.1 | 449 | 127.0.0.1
```
Ref #18988
[1] not completely out of the blue, ff29f430 indicates that a speculative read
*can* happen.
Closes scylladb/scylladb#19520