reader_concurrency_semaphore: add trace points for important events #13255

denesb · 2023-03-20T14:46:37Z

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: #12781

denesb · 2023-03-20T14:47:22Z

Depends on #13173.

Only the last 4 commits belong to this PR, the rest belongs to the dependency.

avikivity · 2023-03-20T14:58:15Z

Using this as a platform:

We need a way to prune the trace tree, right now a trace can easily generate huge amounts of work.

I think we'll need to assign a level to every tracepoint and a way to indicate what level (<= input) we're interested in. They'll also need a name.

/cc @vladzcloudius (you may want to review the series)

avikivity · 2023-03-20T15:02:44Z

multishard_mutation_query.cc

@@ -325,6 +325,7 @@ flat_mutation_reader_v2 read_context::create_reader(
            if (reader_opt->permit() != permit) {
                on_internal_error(mmq_log, "read_context::create_reader(): passed-in permit is different than saved reader's permit");
            }
+            permit.set_trace_state(trace_state);


"refreshkeep" in $subject?

I think I must have changed my mind half-way on how to phrase it and borked it. Will fix.

avikivity · 2023-03-20T15:04:53Z

reader_permit.hh

+    const tracing::trace_state_ptr& trace_state() const noexcept;
+
+    void set_trace_state(tracing::trace_state_ptr trace_ptr) noexcept;
+


What happens if a read starts with one trace, generates a page, then transfers into another page? We'll get mixed traces no?

avikivity · 2023-03-20T15:06:08Z

reader_concurrency_semaphore.cc

+    }
+
+    void set_trace_state(tracing::trace_state_ptr trace_ptr) noexcept {
+        _trace_ptr = std::move(trace_ptr);


(continuing from below). What if _trace_ptr is set?

Perhaps we should create a stitching record that says that old_session continues in new_session.

Note that files etc will all have the old session in them, if they captured it.

I'll respond to the page-bridging question here: if I set the trace pointer on the first page and leave it as-is, all reader concurrency semaphore messages will be in the first session. In the example from the cover letter, all messages would be in the tracing session "8cc80d50-c72d-11ed-8427-14e21cc3ed56".
If I refresh the trace pointer on each page, then each message goes into the session of the relevant page. We seems to have one session per page.

Yes, but let's have an event "resuming read from session {}" or something, to create a link between pages (and to note the fact that we have an 1865 hit).

@avikivity each trace_state is defined by a corresponding session_id value, which in line corresponds to a single CQL query.
A single CQL (read) query is always limited to a single page.
Hence each new page has to have a new trace_state object if traced.

And now the most interesting question is when that "if traced" holds.

When tracing is enabled from the application (will eventually come down to Scylla using a Trace bit) then things are rather straight forward exactly as @denesb shown in the commit message example - every new page will show up as new session object. And I agree with you, it would definitely make sense to create some way to "connect" different pages. And hence what you suggested (create a trace point that would have "old session id -> new session id" info) makes a lot of sense.

However when Tracing is enabled via probabilistic tracing we may trace some pages out of multi-page read sequence and not the others.

In such a case, on the one hand, it would be interesting to trace the whole multi-page sequence. But on the other hand, implementing this would require us to change the current semantics and the implementation of the probabilistic tracing (quite) a bit.

I don't have a strong opinion but from the debugging perspective having the whole multi-page sequence traced if the first page was picked would make a lot of sense.

Doesn't have to be part of this series however - just a thought.

and to note the fact that we have an 1865 hit

We already have a trace point for this:

Reusing querier [shard 0] | 2023-03-20 10:43:17.395614 | 127.0.0.1 | 116 | 127.0.0.1

Ok, let's add a link to the previous session then.

I was about to say that this requires intrusive changes like saving the session id in the paging state and whatnot... then remembered that in set_trace_state() I have the old trace state and the new one and I can just use the new one to create a trace point with the session id extracted from the old one. I hope it will be as simple as it sounds written down.

Guess I'll fix this in a follow-up.

Follow-up here: #13318.

scylladb-promoter · 2023-03-20T19:13:34Z

CI state SUCCESS - https://jenkins.scylladb.com/job/scylla-master/job/scylla-ci/164/

vladzcloudius · 2023-03-21T01:07:23Z

Using this as a platform:

We need a way to prune the trace tree, right now a trace can easily generate huge amounts of work.

I think we'll need to assign a level to every tracepoint and a way to indicate what level (<= input) we're interested in. They'll also need a name.

/cc @vladzcloudius (you may want to review the series)

The series makes sense (didn't look too deep but you seem to have reviewed it alright).

Your idea above definitely makes sense in general, @avikivity.
This specific PR doesn't add that many more trace points however... ;)

perf.cc has two key comparators: key_compare and key_tri_compare. These are very generic name, in fact key_compare directly clashes with a comparator with the same name in types.hh. Avoid the clash by renaming both of these to a more unique name.

And propagate it down to where it is created. This will be used to add trace points for semaphore related events, but this will come in the next patches.

To make sure all tracing done on a certain page will make its way into the appropriate trace session. This is a contination of the previous patch (which added trace pointer to the permit).

Notably, to admission execution and eviction. Registering/unregistering the permit as inactive is not traced, as this happens on every buffer-fill for range scans. Semaphore trace messages have a "[reader_concurrency_semaphore]" prefix to allow them to be clearly associated with the semaphore.

denesb · 2023-03-22T08:59:18Z

v2:

Rebased on now merged dependency.
Fixed borked commit message.

scylladb-promoter · 2023-03-22T11:19:11Z

CI state FAILURE - https://jenkins.scylladb.com/job/scylla-master/job/scylla-ci/213/

denesb · 2023-03-22T11:44:14Z

CI state FAILURE - https://jenkins.scylladb.com/job/scylla-master/job/scylla-ci/213/

#13283

denesb · 2023-03-22T11:44:50Z

CI is completely broken, will re-kick it later.

scylladb-promoter · 2023-03-23T11:02:32Z

CI state SUCCESS - https://jenkins.scylladb.com/job/scylla-master/job/scylla-ci/251/

…ous page This method is called on the start of each page, updating the trace state stored on the permit to that of the current page. When doing so, emit a trace message, containing the session id of the previous page, so the per-page sessions can be stiched together later. Note that this message is only emitted if the cached read Example: Tracing session: dcfc1570-ca3c-11ed-88d0-24443f03a8bb activity | timestamp | source | source_elapsed | client ---------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+----------- Execute CQL3 query | 2023-03-24 08:10:27.271000 | 127.0.0.1 | 0 | 127.0.0.1 Parsing a statement [shard 0] | 2023-03-24 08:10:27.271864 | 127.0.0.1 | -- | 127.0.0.1 Processing a statement [shard 0] | 2023-03-24 08:10:27.271958 | 127.0.0.1 | 94 | 127.0.0.1 Creating read executor for token 3274692326281147944 with all: {127.0.0.1} targets: {127.0.0.1} repair decision: NONE [shard 0] | 2023-03-24 08:10:27.271995 | 127.0.0.1 | 132 | 127.0.0.1 read_data: querying locally [shard 0] | 2023-03-24 08:10:27.271998 | 127.0.0.1 | 135 | 127.0.0.1 Start querying singular range {{3274692326281147944, pk{00026b73}}} [shard 0] | 2023-03-24 08:10:27.272003 | 127.0.0.1 | 140 | 127.0.0.1 [reader concurrency semaphore] admitted immediately [shard 0] | 2023-03-24 08:10:27.272006 | 127.0.0.1 | 143 | 127.0.0.1 [reader concurrency semaphore] executing read [shard 0] | 2023-03-24 08:10:27.272014 | 127.0.0.1 | 150 | 127.0.0.1 Querying cache for range {{3274692326281147944, pk{00026b73}}} and slice {(-inf, +inf)} [shard 0] | 2023-03-24 08:10:27.272022 | 127.0.0.1 | 159 | 127.0.0.1 Page stats: 1 partition(s), 0 static row(s) (0 live, 0 dead), 3 clustering row(s) (3 live, 0 dead) and 0 range tombstone(s) [shard 0] | 2023-03-24 08:10:27.272076 | 127.0.0.1 | 212 | 127.0.0.1 Caching querier with key ab928e0d-b815-46b7-9a02-1fa2d9549477 [shard 0] | 2023-03-24 08:10:27.272084 | 127.0.0.1 | 221 | 127.0.0.1 Querying is done [shard 0] | 2023-03-24 08:10:27.272087 | 127.0.0.1 | 224 | 127.0.0.1 Done processing - preparing a result [shard 0] | 2023-03-24 08:10:27.272106 | 127.0.0.1 | 242 | 127.0.0.1 Request complete | 2023-03-24 08:10:27.271259 | 127.0.0.1 | 259 | 127.0.0.1 Tracing session: dd3092f0-ca3c-11ed-88d0-24443f03a8bb activity | timestamp | source | source_elapsed | client ---------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+----------- Execute CQL3 query | 2023-03-24 08:10:27.615000 | 127.0.0.1 | 0 | 127.0.0.1 Parsing a statement [shard 0] | 2023-03-24 08:10:27.615223 | 127.0.0.1 | -- | 127.0.0.1 Processing a statement [shard 0] | 2023-03-24 08:10:27.615310 | 127.0.0.1 | 87 | 127.0.0.1 Creating read executor for token 3274692326281147944 with all: {127.0.0.1} targets: {127.0.0.1} repair decision: NONE [shard 0] | 2023-03-24 08:10:27.615346 | 127.0.0.1 | 124 | 127.0.0.1 read_data: querying locally [shard 0] | 2023-03-24 08:10:27.615349 | 127.0.0.1 | 126 | 127.0.0.1 Start querying singular range {{3274692326281147944, pk{00026b73}}} [shard 0] | 2023-03-24 08:10:27.615352 | 127.0.0.1 | 130 | 127.0.0.1 Found cached querier for key ab928e0d-b815-46b7-9a02-1fa2d9549477 and range(s) {{{3274692326281147944, pk{00026b73}}}} [shard 0] | 2023-03-24 08:10:27.615358 | 127.0.0.1 | 135 | 127.0.0.1 Reusing querier [shard 0] | 2023-03-24 08:10:27.615362 | 127.0.0.1 | 139 | 127.0.0.1 Continuing paged query, previous page's trace session is dcfc1570-ca3c-11ed-88d0-24443f03a8bb [shard 0] | 2023-03-24 08:10:27.615364 | 127.0.0.1 | 141 | 127.0.0.1 [reader concurrency semaphore] executing read [shard 0] | 2023-03-24 08:10:27.615371 | 127.0.0.1 | 148 | 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] | 2023-03-24 08:10:27.615385 | 127.0.0.1 | 163 | 127.0.0.1 Querying is done [shard 0] | 2023-03-24 08:10:27.615583 | 127.0.0.1 | 360 | 127.0.0.1 Done processing - preparing a result [shard 0] | 2023-03-24 08:10:27.615730 | 127.0.0.1 | 507 | 127.0.0.1 Request complete | 2023-03-24 08:10:27.615518 | 127.0.0.1 | 518 | 127.0.0.1 See the message: Continuing paged query, previous page's trace session is dcfc1570-ca3c-11ed-88d0-24443f03a8bb [shard 0] | 2023-03-24 08:10:27.615364 | 127.0.0.1 | 141 | 127.0.0.1 This is a folow-up to scylladb#13255 Refs: scylladb#12781

…ous page This method is called on the start of each page, updating the trace state stored on the permit to that of the current page. When doing so, emit a trace message, containing the session id of the previous page, so the per-page sessions can be stiched together later. Note that this message is only emitted if the cached read survived between the pages. Example: Tracing session: dcfc1570-ca3c-11ed-88d0-24443f03a8bb activity | timestamp | source | source_elapsed | client ---------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+----------- Execute CQL3 query | 2023-03-24 08:10:27.271000 | 127.0.0.1 | 0 | 127.0.0.1 Parsing a statement [shard 0] | 2023-03-24 08:10:27.271864 | 127.0.0.1 | -- | 127.0.0.1 Processing a statement [shard 0] | 2023-03-24 08:10:27.271958 | 127.0.0.1 | 94 | 127.0.0.1 Creating read executor for token 3274692326281147944 with all: {127.0.0.1} targets: {127.0.0.1} repair decision: NONE [shard 0] | 2023-03-24 08:10:27.271995 | 127.0.0.1 | 132 | 127.0.0.1 read_data: querying locally [shard 0] | 2023-03-24 08:10:27.271998 | 127.0.0.1 | 135 | 127.0.0.1 Start querying singular range {{3274692326281147944, pk{00026b73}}} [shard 0] | 2023-03-24 08:10:27.272003 | 127.0.0.1 | 140 | 127.0.0.1 [reader concurrency semaphore] admitted immediately [shard 0] | 2023-03-24 08:10:27.272006 | 127.0.0.1 | 143 | 127.0.0.1 [reader concurrency semaphore] executing read [shard 0] | 2023-03-24 08:10:27.272014 | 127.0.0.1 | 150 | 127.0.0.1 Querying cache for range {{3274692326281147944, pk{00026b73}}} and slice {(-inf, +inf)} [shard 0] | 2023-03-24 08:10:27.272022 | 127.0.0.1 | 159 | 127.0.0.1 Page stats: 1 partition(s), 0 static row(s) (0 live, 0 dead), 3 clustering row(s) (3 live, 0 dead) and 0 range tombstone(s) [shard 0] | 2023-03-24 08:10:27.272076 | 127.0.0.1 | 212 | 127.0.0.1 Caching querier with key ab928e0d-b815-46b7-9a02-1fa2d9549477 [shard 0] | 2023-03-24 08:10:27.272084 | 127.0.0.1 | 221 | 127.0.0.1 Querying is done [shard 0] | 2023-03-24 08:10:27.272087 | 127.0.0.1 | 224 | 127.0.0.1 Done processing - preparing a result [shard 0] | 2023-03-24 08:10:27.272106 | 127.0.0.1 | 242 | 127.0.0.1 Request complete | 2023-03-24 08:10:27.271259 | 127.0.0.1 | 259 | 127.0.0.1 Tracing session: dd3092f0-ca3c-11ed-88d0-24443f03a8bb activity | timestamp | source | source_elapsed | client ---------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+----------- Execute CQL3 query | 2023-03-24 08:10:27.615000 | 127.0.0.1 | 0 | 127.0.0.1 Parsing a statement [shard 0] | 2023-03-24 08:10:27.615223 | 127.0.0.1 | -- | 127.0.0.1 Processing a statement [shard 0] | 2023-03-24 08:10:27.615310 | 127.0.0.1 | 87 | 127.0.0.1 Creating read executor for token 3274692326281147944 with all: {127.0.0.1} targets: {127.0.0.1} repair decision: NONE [shard 0] | 2023-03-24 08:10:27.615346 | 127.0.0.1 | 124 | 127.0.0.1 read_data: querying locally [shard 0] | 2023-03-24 08:10:27.615349 | 127.0.0.1 | 126 | 127.0.0.1 Start querying singular range {{3274692326281147944, pk{00026b73}}} [shard 0] | 2023-03-24 08:10:27.615352 | 127.0.0.1 | 130 | 127.0.0.1 Found cached querier for key ab928e0d-b815-46b7-9a02-1fa2d9549477 and range(s) {{{3274692326281147944, pk{00026b73}}}} [shard 0] | 2023-03-24 08:10:27.615358 | 127.0.0.1 | 135 | 127.0.0.1 Reusing querier [shard 0] | 2023-03-24 08:10:27.615362 | 127.0.0.1 | 139 | 127.0.0.1 Continuing paged query, previous page's trace session is dcfc1570-ca3c-11ed-88d0-24443f03a8bb [shard 0] | 2023-03-24 08:10:27.615364 | 127.0.0.1 | 141 | 127.0.0.1 [reader concurrency semaphore] executing read [shard 0] | 2023-03-24 08:10:27.615371 | 127.0.0.1 | 148 | 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] | 2023-03-24 08:10:27.615385 | 127.0.0.1 | 163 | 127.0.0.1 Querying is done [shard 0] | 2023-03-24 08:10:27.615583 | 127.0.0.1 | 360 | 127.0.0.1 Done processing - preparing a result [shard 0] | 2023-03-24 08:10:27.615730 | 127.0.0.1 | 507 | 127.0.0.1 Request complete | 2023-03-24 08:10:27.615518 | 127.0.0.1 | 518 | 127.0.0.1 See the message: Continuing paged query, previous page's trace session is dcfc1570-ca3c-11ed-88d0-24443f03a8bb [shard 0] | 2023-03-24 08:10:27.615364 | 127.0.0.1 | 141 | 127.0.0.1 This is a folow-up to scylladb#13255 Refs: scylladb#12781

…ous page This method is called on the start of each page, updating the trace state stored on the permit to that of the current page. When doing so, emit a trace message, containing the session id of the previous page, so the per-page sessions can be stiched together later. Note that this message is only emitted if the cached read survived between the pages. Example: Tracing session: dcfc1570-ca3c-11ed-88d0-24443f03a8bb activity | timestamp | source | source_elapsed | client ---------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+----------- Execute CQL3 query | 2023-03-24 08:10:27.271000 | 127.0.0.1 | 0 | 127.0.0.1 Parsing a statement [shard 0] | 2023-03-24 08:10:27.271864 | 127.0.0.1 | -- | 127.0.0.1 Processing a statement [shard 0] | 2023-03-24 08:10:27.271958 | 127.0.0.1 | 94 | 127.0.0.1 Creating read executor for token 3274692326281147944 with all: {127.0.0.1} targets: {127.0.0.1} repair decision: NONE [shard 0] | 2023-03-24 08:10:27.271995 | 127.0.0.1 | 132 | 127.0.0.1 read_data: querying locally [shard 0] | 2023-03-24 08:10:27.271998 | 127.0.0.1 | 135 | 127.0.0.1 Start querying singular range {{3274692326281147944, pk{00026b73}}} [shard 0] | 2023-03-24 08:10:27.272003 | 127.0.0.1 | 140 | 127.0.0.1 [reader concurrency semaphore] admitted immediately [shard 0] | 2023-03-24 08:10:27.272006 | 127.0.0.1 | 143 | 127.0.0.1 [reader concurrency semaphore] executing read [shard 0] | 2023-03-24 08:10:27.272014 | 127.0.0.1 | 150 | 127.0.0.1 Querying cache for range {{3274692326281147944, pk{00026b73}}} and slice {(-inf, +inf)} [shard 0] | 2023-03-24 08:10:27.272022 | 127.0.0.1 | 159 | 127.0.0.1 Page stats: 1 partition(s), 0 static row(s) (0 live, 0 dead), 3 clustering row(s) (3 live, 0 dead) and 0 range tombstone(s) [shard 0] | 2023-03-24 08:10:27.272076 | 127.0.0.1 | 212 | 127.0.0.1 Caching querier with key ab928e0d-b815-46b7-9a02-1fa2d9549477 [shard 0] | 2023-03-24 08:10:27.272084 | 127.0.0.1 | 221 | 127.0.0.1 Querying is done [shard 0] | 2023-03-24 08:10:27.272087 | 127.0.0.1 | 224 | 127.0.0.1 Done processing - preparing a result [shard 0] | 2023-03-24 08:10:27.272106 | 127.0.0.1 | 242 | 127.0.0.1 Request complete | 2023-03-24 08:10:27.271259 | 127.0.0.1 | 259 | 127.0.0.1 Tracing session: dd3092f0-ca3c-11ed-88d0-24443f03a8bb activity | timestamp | source | source_elapsed | client ---------------------------------------------------------------------------------------------------------------------------------------+----------------------------+-----------+----------------+----------- Execute CQL3 query | 2023-03-24 08:10:27.615000 | 127.0.0.1 | 0 | 127.0.0.1 Parsing a statement [shard 0] | 2023-03-24 08:10:27.615223 | 127.0.0.1 | -- | 127.0.0.1 Processing a statement [shard 0] | 2023-03-24 08:10:27.615310 | 127.0.0.1 | 87 | 127.0.0.1 Creating read executor for token 3274692326281147944 with all: {127.0.0.1} targets: {127.0.0.1} repair decision: NONE [shard 0] | 2023-03-24 08:10:27.615346 | 127.0.0.1 | 124 | 127.0.0.1 read_data: querying locally [shard 0] | 2023-03-24 08:10:27.615349 | 127.0.0.1 | 126 | 127.0.0.1 Start querying singular range {{3274692326281147944, pk{00026b73}}} [shard 0] | 2023-03-24 08:10:27.615352 | 127.0.0.1 | 130 | 127.0.0.1 Found cached querier for key ab928e0d-b815-46b7-9a02-1fa2d9549477 and range(s) {{{3274692326281147944, pk{00026b73}}}} [shard 0] | 2023-03-24 08:10:27.615358 | 127.0.0.1 | 135 | 127.0.0.1 Reusing querier [shard 0] | 2023-03-24 08:10:27.615362 | 127.0.0.1 | 139 | 127.0.0.1 Continuing paged query, previous page's trace session is dcfc1570-ca3c-11ed-88d0-24443f03a8bb [shard 0] | 2023-03-24 08:10:27.615364 | 127.0.0.1 | 141 | 127.0.0.1 [reader concurrency semaphore] executing read [shard 0] | 2023-03-24 08:10:27.615371 | 127.0.0.1 | 148 | 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] | 2023-03-24 08:10:27.615385 | 127.0.0.1 | 163 | 127.0.0.1 Querying is done [shard 0] | 2023-03-24 08:10:27.615583 | 127.0.0.1 | 360 | 127.0.0.1 Done processing - preparing a result [shard 0] | 2023-03-24 08:10:27.615730 | 127.0.0.1 | 507 | 127.0.0.1 Request complete | 2023-03-24 08:10:27.615518 | 127.0.0.1 | 518 | 127.0.0.1 See the message: Continuing paged query, previous page's trace session is dcfc1570-ca3c-11ed-88d0-24443f03a8bb [shard 0] | 2023-03-24 08:10:27.615364 | 127.0.0.1 | 141 | 127.0.0.1 This is a folow-up to #13255 Refs: #12781 Closes #13318

…eaders needlessly" to branch-5.2' from Botond Dénes The patch doesn't apply cleanly, so a targeted backport PR was necessary. I also needed to cherry-pick two patches from #13255 that the backported patch depends on. Decided against backporting the entire #13255 as it is quite an intrusive change. Fixes: #11803 Closes #13515 * github.com:scylladb/scylladb: reader_concurrency_semaphore: don't evict inactive readers needlessly reader_concurrency_semaphore: add stats to record reason for queueing permits reader_concurrency_semaphore: can_admit_read(): also return reason for rejection

…eaders needlessly" to branch-5.1' from Botond Dénes The patch doesn't apply cleanly, so a targeted backport PR was necessary. I also needed to cherry-pick two patches from #13255 that the backported patch depends on. Decided against backporting the entire #13255 as it is quite an intrusive change. Fixes: #11803 Closes #13516 * github.com:scylladb/scylladb: reader_concurrency_semaphore: don't evict inactive readers needlessly reader_concurrency_semaphore: add stats to record reason for queueing permits reader_concurrency_semaphore: can_admit_read(): also return reason for rejection reader_concurrency_semaphore: add set_resources()

…eaders needlessly" to branch-5.0' from Botond Dénes The patch doesn't apply cleanly, so a targeted backport PR was necessary. I also needed to cherry-pick two patches from #13255 that the backported patch depends on. Decided against backporting the entire #13255 as it is quite an intrusive change. Fixes: #11803 Closes #13517 * github.com:scylladb/scylladb: reader_concurrency_semaphore: don't evict inactive readers needlessly reader_concurrency_semaphore: add stats to record reason for queueing permits reader_concurrency_semaphore: can_admit_read(): also return reason for rejection reader_concurrency_semaphore: add set_resources()

denesb requested review from tgrabiec and nyh as code owners March 20, 2023 14:46

denesb requested a review from avikivity March 20, 2023 14:46

avikivity reviewed Mar 20, 2023

View reviewed changes

denesb added 4 commits March 22, 2023 04:58

reader_permit: keep trace_state pointer on permit

156e5d3

And propagate it down to where it is created. This will be used to add trace points for semaphore related events, but this will come in the next patches.

reader_permit: refresh trace_state on new pages

1f51f75

To make sure all tracing done on a certain page will make its way into the appropriate trace session. This is a contination of the previous patch (which added trace pointer to the permit).

denesb force-pushed the rcs-tracing branch from 3419353 to ff87f95 Compare March 22, 2023 08:58

scylladb-promoter merged commit afe6b0d into scylladb:master Mar 24, 2023

denesb mentioned this pull request Mar 24, 2023

reader_permit: set_trace_state(): emit trace message linking to previous page #13318

Closed

tchaikov mentioned this pull request Mar 30, 2023

reader_concurrency_semaphore: don't evict inactive readers needlessly #13286

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

reader_concurrency_semaphore: add trace points for important events #13255

reader_concurrency_semaphore: add trace points for important events #13255

denesb commented Mar 20, 2023

denesb commented Mar 20, 2023 •

edited

avikivity commented Mar 20, 2023

avikivity Mar 20, 2023

denesb Mar 20, 2023

avikivity Mar 20, 2023

avikivity Mar 20, 2023

avikivity Mar 20, 2023

denesb Mar 20, 2023

avikivity Mar 20, 2023

vladzcloudius Mar 21, 2023 •

edited

denesb Mar 21, 2023 •

edited

avikivity Mar 23, 2023

denesb Mar 23, 2023

denesb Mar 24, 2023

denesb Mar 24, 2023

scylladb-promoter commented Mar 20, 2023

vladzcloudius commented Mar 21, 2023

denesb commented Mar 22, 2023

scylladb-promoter commented Mar 22, 2023

denesb commented Mar 22, 2023

denesb commented Mar 22, 2023

scylladb-promoter commented Mar 23, 2023

		const tracing::trace_state_ptr& trace_state() const noexcept;

		void set_trace_state(tracing::trace_state_ptr trace_ptr) noexcept;

reader_concurrency_semaphore: add trace points for important events #13255

reader_concurrency_semaphore: add trace points for important events #13255

Conversation

denesb commented Mar 20, 2023

denesb commented Mar 20, 2023 • edited

avikivity commented Mar 20, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vladzcloudius Mar 21, 2023 • edited

Choose a reason for hiding this comment

denesb Mar 21, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

scylladb-promoter commented Mar 20, 2023

vladzcloudius commented Mar 21, 2023

denesb commented Mar 22, 2023

scylladb-promoter commented Mar 22, 2023

denesb commented Mar 22, 2023

denesb commented Mar 22, 2023

scylladb-promoter commented Mar 23, 2023

denesb commented Mar 20, 2023 •

edited

vladzcloudius Mar 21, 2023 •

edited

denesb Mar 21, 2023 •

edited