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

sql: emit more tracing events from the stats cache #54035

Merged
merged 2 commits into from
Sep 10, 2020

Conversation

RaduBerinde
Copy link
Member

The stats cache has various "slow" paths (where we need to query the
system table). These are currently only logged if verbosity is high.

This change switches to VEvent in most cases, so that these are
visible during tracing (including in statement diagnostics bundles).
This will allow us to diagnose slow planning times, e.g. due to the
stats cache getting full.

Release justification: low-risk change to existing functionality, high
potential benefit for debugging issues.

Release note: None

@RaduBerinde RaduBerinde requested a review from a team as a code owner September 8, 2020 16:49
@cockroach-teamcity
Copy link
Member

This change is Reviewable

Copy link
Collaborator

@rytaft rytaft left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:lgtm:

Reviewed 1 of 1 files at r1.
Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (waiting on @RaduBerinde)


pkg/sql/stats/stats_cache.go, line 192 at r1 (raw file):

		// We are in the process of grabbing stats for this table. Wait until
		// that is complete, at which point e.stats will be populated.
		log.VEventf(ctx, 1, "waiting for statistics for table %d", tableID)

So the difference here is that we're always logging somewhere, but the location depends on the verbosity?


pkg/sql/stats/stats_cache.go, line 309 at r1 (raw file):

	log.VEventf(ctx, 1, "refreshing statistics for table %d", tableID)
	ctx, span := tracing.ForkCtxSpan(ctx, "refresh-table-stats")
	defer tracing.FinishSpan(span)

Will this wait to finish until the goroutine below finishes?

The stats cache has various "slow" paths (where we need to query the
system table). These are currently only logged if verbosity is high.

This change switches to `VEvent` in most cases, so that these are
visible during tracing (including in statement diagnostics bundles).
This will allow us to diagnose slow planning times, e.g. due to the
stats cache getting full.

Release justification: low-risk change to existing functionality, high
potential benefit for debugging issues.

Release note: None
Add a few more tracing events around the use of the optimizer.

Release note: None
Copy link
Member Author

@RaduBerinde RaduBerinde left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

TFTR! Updated and added a small commit that adds a couple of more events in the planning code.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @rytaft)


pkg/sql/stats/stats_cache.go, line 192 at r1 (raw file):

Previously, rytaft (Rebecca Taft) wrote…

So the difference here is that we're always logging somewhere, but the location depends on the verbosity?

VEvent generates a trace event if we are tracing, and also logs it if the verbosity is high. The previous code did not generate a trace event if verbosity was not set.


pkg/sql/stats/stats_cache.go, line 309 at r1 (raw file):

Previously, rytaft (Rebecca Taft) wrote…

Will this wait to finish until the goroutine below finishes?

Silly me, fixed. Nice catch! This didn't cause any failures because I don't think we ever have a span in the context currently, but I put it in just in case.

Copy link
Collaborator

@rytaft rytaft left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:lgtm:

Reviewed 1 of 1 files at r2, 1 of 1 files at r3.
Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained

@RaduBerinde
Copy link
Member Author

bors r+

@craig
Copy link
Contributor

craig bot commented Sep 10, 2020

Build succeeded:

@craig craig bot merged commit 6227db0 into cockroachdb:master Sep 10, 2020
@RaduBerinde RaduBerinde deleted the more-events-stats-cache branch September 17, 2020 20:16
@rafiss rafiss added this to the 20.2 milestone Apr 22, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants