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.

Sign up for GitHub

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

Jump to bottom

reader_concurrency_semaphore: add trace-points to semaphore events #12781

Closed
denesb opened this issue Feb 8, 2023 · 4 comments · Fixed by #13255
Closed

reader_concurrency_semaphore: add trace-points to semaphore events #12781

denesb opened this issue Feb 8, 2023 · 4 comments · Fixed by #13255
Assignees
@denesb
Milestone
5.3

Comments

@denesb
Copy link
Contributor

denesb commented Feb 8, 2023

Basically, all major permit state changes should get a corresponding trace point.
For this to work, we probably have to store a trace_state_ptr on the permit, which is refreshed on each page.

Requested by @avikivity, based on user feedback. I started looking into how this should be implemented, but I might not get around to do it for a while, so I created this issue so we don't forget.
@denesb denesb self-assigned this Feb 8, 2023
@DoronArazii DoronArazii added this to the 5.x milestone Feb 20, 2023
@denesb denesb mentioned this issue Mar 20, 2023
Merged
denesb added a commit to denesb/scylla that referenced this issue Mar 24, 2023
@denesb
reader_permit: set_trace_state(): emit trace message linking to previ…
3516183 
…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
@denesb denesb mentioned this issue Mar 24, 2023
Closed
denesb added a commit to denesb/scylla that referenced this issue Mar 24, 2023
@denesb
reader_permit: set_trace_state(): emit trace message linking to previ…
ab4052c 
…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
avikivity pushed a commit that referenced this issue Mar 26, 2023
@denesb @avikivity
reader_permit: set_trace_state(): emit trace message linking to previ…
d5488db 
…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
@DoronArazii DoronArazii modified the milestones: 5.x, 5.3 Apr 3, 2023
@avikivity
Copy link
Member

Not a bug, not backporting.

@bhalevy
Copy link
Member

bhalevy commented Jul 31, 2023 •
edited

Not a bug, not backporting.

@avikivity apparently, as @tchaikov found out, the series contains a prerequisite (156e5d3) for backporting #14819 (to provide a new make_tracking_only_permit overload)

@denesb
Copy link
Contributor Author

denesb commented Jul 31, 2023

Not a bug, not backporting.

@avikivity apparently, as @tchaikov found out, the series contains a prerequisite (156e5d3) for backporting #14819 (to provide a new make_tracking_only_permit overload)

This is not a prerequisite to #14819. Interfaces change and backported patches have to be adapted to older versions all the time. #14819 does not depend on the functionality introduced here.

@bhalevy
Copy link
Member

bhalevy commented Jul 31, 2023

okay, so if we can resolve the backporting issue without cherry-picking from this series that's good enough.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@denesb denesb

Labels
None yet
Projects
None yet
Milestone
5.3
Development

Successfully merging a pull request may close this issue.

reader_concurrency_semaphore: add trace points for important events denesb/scylla
5 participants
@avikivity @denesb @bhalevy @scylladb-promoter @DoronArazii