mirror of
https://github.com/scylladb/scylladb.git
synced 2026-04-27 03:45:11 +00:00
afe6b0d8c9
Currently we have no visibility into what happens to a read in the reader concurrency semaphore as far as tracing is concerned. This series fixes that, storing a trace state pointer on the reader permit and using it to add trace messages to important semaphore related events:
* admission decision
* execution (execution stage functionality)
* eviction
This allows for seeing if the read suffered any delay in the semaphore.
Example tracing (2 pages):
```
Tracing session: 8cc80d50-c72d-11ed-8427-14e21cc3ed56
activity | timestamp | source | source_elapsed | client
-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2023-03-20 10:43:16.773000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing a statement [shard 0] | 2023-03-20 10:43:16.773754 | 127.0.0.1 | -- | 127.0.0.1
Processing a statement [shard 0] | 2023-03-20 10:43:16.773837 | 127.0.0.1 | 83 | 127.0.0.1
Creating read executor for token -4911109968640856406 with all: {127.0.0.1} targets: {127.0.0.1} repair decision: NONE [shard 0] | 2023-03-20 10:43:16.773874 | 127.0.0.1 | 121 | 127.0.0.1
read_data: querying locally [shard 0] | 2023-03-20 10:43:16.773877 | 127.0.0.1 | 123 | 127.0.0.1
Start querying singular range {{-4911109968640856406, pk{000d73797374656d5f736368656d61}}} [shard 0] | 2023-03-20 10:43:16.773881 | 127.0.0.1 | 128 | 127.0.0.1
[reader concurrency semaphore] admitted immediately [shard 0] | 2023-03-20 10:43:16.773884 | 127.0.0.1 | 130 | 127.0.0.1
[reader concurrency semaphore] executing read [shard 0] | 2023-03-20 10:43:16.773890 | 127.0.0.1 | 137 | 127.0.0.1
Querying cache for range {{-4911109968640856406, pk{000d73797374656d5f736368656d61}}} and slice {(-inf, +inf)} [shard 0] | 2023-03-20 10:43:16.773903 | 127.0.0.1 | 149 | 127.0.0.1
Page stats: 1 partition(s), 0 static row(s) (0 live, 0 dead), 100 clustering row(s) (100 live, 0 dead) and 0 range tombstone(s) [shard 0] | 2023-03-20 10:43:16.774674 | 127.0.0.1 | 920 | 127.0.0.1
Caching querier with key 5eff94d2-e47a-43b2-8e3a-2d80a9cc3b3e [shard 0] | 2023-03-20 10:43:16.774685 | 127.0.0.1 | 931 | 127.0.0.1
Querying is done [shard 0] | 2023-03-20 10:43:16.774688 | 127.0.0.1 | 934 | 127.0.0.1
Done processing - preparing a result [shard 0] | 2023-03-20 10:43:16.774706 | 127.0.0.1 | 953 | 127.0.0.1
Request complete | 2023-03-20 10:43:16.774225 | 127.0.0.1 | 1225 | 127.0.0.1
Tracing session: 8d26f630-c72d-11ed-8427-14e21cc3ed56
activity | timestamp | source | source_elapsed | client
---------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+-----------
Execute CQL3 query | 2023-03-20 10:43:17.395000 | 127.0.0.1 | 0 | 127.0.0.1
Parsing a statement [shard 0] | 2023-03-20 10:43:17.395498 | 127.0.0.1 | -- | 127.0.0.1
Processing a statement [shard 0] | 2023-03-20 10:43:17.395558 | 127.0.0.1 | 60 | 127.0.0.1
Creating read executor for token -4911109968640856406 with all: {127.0.0.1} targets: {127.0.0.1} repair decision: NONE [shard 0] | 2023-03-20 10:43:17.395597 | 127.0.0.1 | 99 | 127.0.0.1
read_data: querying locally [shard 0] | 2023-03-20 10:43:17.395600 | 127.0.0.1 | 102 | 127.0.0.1
Start querying singular range {{-4911109968640856406, pk{000d73797374656d5f736368656d61}}} [shard 0] | 2023-03-20 10:43:17.395604 | 127.0.0.1 | 106 | 127.0.0.1
Found cached querier for key 5eff94d2-e47a-43b2-8e3a-2d80a9cc3b3e and range(s) {{{-4911109968640856406, pk{000d73797374656d5f736368656d61}}}} [shard 0] | 2023-03-20 10:43:17.395610 | 127.0.0.1 | 112 | 127.0.0.1
Reusing querier [shard 0] | 2023-03-20 10:43:17.395614 | 127.0.0.1 | 116 | 127.0.0.1
[reader concurrency semaphore] executing read [shard 0] | 2023-03-20 10:43:17.395622 | 127.0.0.1 | 125 | 127.0.0.1
Page stats: 1 partition(s), 0 static row(s) (0 live, 0 dead), 11 clustering row(s) (11 live, 0 dead) and 0 range tombstone(s) [shard 0] | 2023-03-20 10:43:17.395711 | 127.0.0.1 | 213 | 127.0.0.1
Querying is done [shard 0] | 2023-03-20 10:43:17.395718 | 127.0.0.1 | 221 | 127.0.0.1
Done processing - preparing a result [shard 0] | 2023-03-20 10:43:17.395734 | 127.0.0.1 | 236 | 127.0.0.1
Request complete | 2023-03-20 10:43:17.395276 | 127.0.0.1 | 276 | 127.0.0.1
```
Fixes: https://github.com/scylladb/scylladb/issues/12781
Closes #13255
* github.com:scylladb/scylladb:
reader_concurrency_semaphore: add trace points for important events
reader_permit: refresh trace_state on new pages
reader_permit: keep trace_state pointer on permit
test/perf/perf_collection: give more unique names to key comparators