Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
wants to merge 1 commit into from

Conversation

denesb
Copy link
Contributor

@denesb denesb commented Mar 24, 2023

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

…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
@denesb
Copy link
Contributor Author

denesb commented Mar 24, 2023

To have a reliably printed trace message we have to store the trace session id in the paging state, then we could move this message to the pager (coordinator). As-is this message will be printed on each replica (that has a cached read).

@denesb denesb self-assigned this Mar 24, 2023
@scylladb-promoter
Copy link
Contributor

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants