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

stmtdiagnostics: add min exec latency condition #72491

Merged
merged 2 commits into from
Nov 23, 2021

Conversation

yuzefovich
Copy link
Member

@yuzefovich yuzefovich commented Nov 5, 2021

stmtdiagnostics: don't hold the lock when using gossip

Release note: None

stmtdiagnostics: add min exec latency condition

This commit extends the statement diagnostics to support conditional
collection: namely, it introduces minExecutionLatency parameter so
that we could collect bundles on the slow outliers if necessary. Using
the zero value for that parameter will give us the previous behavior
(collecting the bundle on the next query fingerprint execution).

When minExecutionLatency argument is non-zero, then all queries that
match the specified fingerprint are traced until a slow enough query
comes along. This approach was chosen over tracing at most one query at
a time so that we don't miss the slow outlier when fast queries can
"starve" it (imagine that a node is bombarded with many fast queries and
a slow outlier occurs very rarely - it would be unfortunate to not trace
the outlier because when it arrives, a fast query is already being
traced).

In order for some diagnostics requests not to stay "alive" forever, this
commit also adds an expiresAfter interval. It'll be provided by the
user when the conditional collection is desired. The zero value is
treated as "never". Expired and not completed requests are not explicitly
deleted from the system table and are being simply ignored once they
expire.

This commit then adds a migration to the statement_diagnostics_requests
system table to add these two additional columns as well as to update
the secondary index to store these columns as well. All requests created
prior to the migration will never expire and won't have the min execution
latency conditional.

If a diagnostics request already exists for a fingerprint in the system
table, a new one (even with different conditionals / expiration
interval) cannot be created by the API - an error is returned. The
follow-up work will extend an API to make it possible to cancel the
existing request so that a new one could be created.

This API is not hooked up to the DB Console yet, thus there is no release
note.

Supports: #57634.

Release note: None

@cockroach-teamcity
Copy link
Member

This change is Reviewable

@yuzefovich yuzefovich force-pushed the conditional-stmt-diag branch 3 times, most recently from 82cf896 to 8070d90 Compare November 5, 2021 23:47
@yuzefovich yuzefovich marked this pull request as ready for review November 5, 2021 23:50
@yuzefovich yuzefovich requested review from a team as code owners November 5, 2021 23:50
@yuzefovich yuzefovich requested review from a team and RaduBerinde November 5, 2021 23:50
Copy link
Contributor

@postamar postamar left a comment

Choose a reason for hiding this comment

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

I reviewed the changes related to the system table itself and they look good to me. I have a few nits but that's it.

KeyColumnIDs: []descpb.ColumnID{1},
}
}

Copy link
Contributor

Choose a reason for hiding this comment

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

Fine by me, yet this seems like a gratuitous change.

CONSTRAINT "primary" PRIMARY KEY (id),
INDEX completed_idx (completed, id) STORING (statement_fingerprint),
INDEX completed_idx_new (completed, id) STORING (statement_fingerprint, min_execution_latency, expires_at),
Copy link
Contributor

Choose a reason for hiding this comment

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

Would you consider naming this completed_idx_v2 instead? Perhaps I'm thinking too far ahead but what if we need to change this index again do we name it completed_idx_new_new?

If you follow my suggestion then please don't forget to also rename the index created in the migration.

@@ -403,10 +403,12 @@ CREATE TABLE system.statement_diagnostics_requests(
statement_fingerprint STRING NOT NULL,
statement_diagnostics_id INT8,
requested_at TIMESTAMPTZ NOT NULL,
min_execution_latency INTERVAL NOT NULL DEFAULT '0',
expires_at TIMESTAMPTZ NOT NULL DEFAULT now() + '100 years',
Copy link
Contributor

Choose a reason for hiding this comment

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

Just curious but if the default value is meant to be really far into the future, should we consider making it a constant?

If the default is only used for the purpose of backfilling column values in existing rows, and all new rows will have expired_at set, as I suspect is the case, then perhaps don't specify a default value here in systemschema.
This makes the migration more complicated: you have to add the column either nullable or with the default (if you add it nullable you need to run an UPDATE query to backfill) and then subsequently remove the nullability or the default value from the column.

Perhaps it's not worth the trouble, though.

Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @postamar and @RaduBerinde)


pkg/sql/catalog/systemschema/system.go, line 407 at r2 (raw file):
Hm, it sounds like it'd be more complicated for not much benefit. What is the benefit actually?

If the default is only used for the purpose of backfilling column values in existing row ...

The default is also used in another edge case where we insert the row in the table manually (if EXPLAIN ANALYZE (DEBUG) was issued directly, then we will insert a "fake" request into the system table so that the collected bundle was available via the DB Console).


pkg/sql/catalog/systemschema/system.go, line 409 at r2 (raw file):

Previously, postamar (Marius Posta) wrote…

Would you consider naming this completed_idx_v2 instead? Perhaps I'm thinking too far ahead but what if we need to change this index again do we name it completed_idx_new_new?

If you follow my suggestion then please don't forget to also rename the index created in the migration.

Done.


pkg/migration/migrations/retry_jobs_with_exponential_backoff_external_test.go, line 563 at r2 (raw file):

Previously, postamar (Marius Posta) wrote…

Fine by me, yet this seems like a gratuitous change.

Done.

@postamar
Copy link
Contributor

postamar commented Nov 8, 2021

Hm, it sounds like it'd be more complicated for not much benefit.

That's quite possible! In any case the default value actually has a use outside of the migration so I'm glad that my point is moot.

What is the benefit actually?

My rationale was that if the default value is there only to make the migration more convenient, then we're effectively taking on tech debt, in an area (database schema) where the cost of change is high, so I'm typically quite eager to get things right the first time. Hence my probing.

Not only is the cost of change high, in two major versions nobody would remember why this default value was what it is. Comments can be added to explain, but I find such comments burdensome, TODOs particularly so.

Copy link
Member

@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.

Nice, thanks for working on this!!

What are the semantics if we get an instance of query, then while the first instance of the query is running, we get the second instance, and the first instance is fast and the second instance is slow? I believe we won't get the diagnostics in that case, correct? It's not a huge problem, but we should make sure we document this to set the right expectations.

How did you test this? Doing manual insertions in the table? Or the /_status/stmtdiagreports endpoint?

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @postamar, and @yuzefovich)


pkg/server/status.go, line 420 at r3 (raw file):

	// shouldCollectDiagnostics() on the current node will return true for the given
	// fingerprint.
	InsertRequest(ctx context.Context, fprint string, minExecutionLatency time.Duration, expiresAfter time.Duration) error

[nit] long line


pkg/sql/instrumentation.go, line 323 at r3 (raw file):

			)
			bundle.insert(ctx, ih.fingerprint, ast, cfg.StmtDiagnosticsRecorder, ih.diagRequestID)
			ih.stmtDiagnosticsRecorder.RemoveOngoing(ih.diagRequestID)

I think we need to call RemoveOngoing in all cases, no? Btw the comment for theShouldCollectDiagnostics method should be updated (it says "finishFn must always be called" but I think that needs to be "RemoveOngoing must always be called").

Actually, it seems we need some new functionality to put the request back in requestFingerprints? CC @andreimatei

We should have a test that checks that we get a bundle for a query which runs fast a few times then runs slowly (the query can have a CASE nextval(seq) = 3 THEN pg_sleep(..) ELSE true


pkg/sql/catalog/systemschema/system.go, line 407 at r2 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

Hm, it sounds like it'd be more complicated for not much benefit. What is the benefit actually?

If the default is only used for the purpose of backfilling column values in existing row ...

The default is also used in another edge case where we insert the row in the table manually (if EXPLAIN ANALYZE (DEBUG) was issued directly, then we will insert a "fake" request into the system table so that the collected bundle was available via the DB Console).

The first choice would be to use NULL to indicate that there is no expiration. Would that make the code too complicated?


pkg/sql/catalog/systemschema/system.go, line 406 at r3 (raw file):

	statement_diagnostics_id INT8,
	requested_at TIMESTAMPTZ NOT NULL,
	min_execution_latency INTERVAL NOT NULL DEFAULT '0',

Consider just making this a min_execution_latency_ms INT, seems like INTERVAL adds some unnecessary headache.


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 507 at r3 (raw file):

// updates r.mu.requests accordingly.
func (r *Registry) pollRequests(ctx context.Context) error {
	// TODO(yuzefovich): should we delete all expired requests that haven't been

Not a huge problem if we don't clean them up.

Copy link
Member

@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.

Do you think we'll be able to backport this to 21.2.x (given the migration)? We could really use this feature in our escalations.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @postamar, and @yuzefovich)

@yuzefovich
Copy link
Member Author

yuzefovich commented Nov 9, 2021

Do you think we'll be able to backport this to 21.2.x (given the migration)? We could really use this feature in our escalations.

No, I don't think it's possible because of the migration unfortunately. Unless we're willing to stop the train on 21.2.0 in order to fit this PR (as well as yet-to-be-written UI change) in and to break the promise of being able revert to a previous minor release for betas.

@yuzefovich yuzefovich force-pushed the conditional-stmt-diag branch 2 times, most recently from a6f22f1 to 34b13e7 Compare November 9, 2021 03:49
Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

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

What are the semantics if we get an instance of query, then while the first instance of the query is running, we get the second instance, and the first instance is fast and the second instance is slow? I believe we won't get the diagnostics in that case, correct?

If both queries arrive at the same gateway node, then you're right - we'll mark the fast instance as ongoing and will completely ignore the slow instance (because the tracing of this fingerprint is currently in progress). When the latency conditional is not satisfied on the fast instance, then the request is inserted back into the registry, so we'll have to wait for another slow instance.

It's not a huge problem, but we should make sure we document this to set the right expectations.

Do you mean like comments on the protobuf definitions?

How did you test this? Doing manual insertions in the table? Or the /_status/stmtdiagreports endpoint?

The former - I inserted a request manually for pg_sleep fingerprint and confirmed that a couple of fast ones don't get the bundle, and then the slow one does get a bundle.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @postamar, and @RaduBerinde)


pkg/sql/instrumentation.go, line 323 at r3 (raw file):

I think we need to call RemoveOngoing in all cases, no?

Yeah, but I added the logic of RemoveOngoing into CheckExecLatency if that returns false. In that case we put the request back into requestFingerprints too. My understanding is that since we're not updating any system tables when a request becomes ongoing, we simply need to transfer the request from ongoing into requestFingerprints.

Btw the comment for the ShouldCollectDiagnostics method should be updated

Updated.

We should have a test that checks that we get a bundle for a query which runs fast a few times then runs slowly

I did add a test in statement_diagnostics_test.go, do you think it's insufficient? It is very similar to what you're describing (one fast execution followed by a slow execution, and the bundle is captured only for the latter).


pkg/sql/catalog/systemschema/system.go, line 407 at r2 (raw file):

Previously, RaduBerinde wrote…

The first choice would be to use NULL to indicate that there is no expiration. Would that make the code too complicated?

Hm, I started going down this route and the code does become less pretty, so I think it's better to keep this column non-nullable with a default expression.


pkg/sql/catalog/systemschema/system.go, line 406 at r3 (raw file):

Previously, RaduBerinde wrote…

Consider just making this a min_execution_latency_ms INT, seems like INTERVAL adds some unnecessary headache.

Done.


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 261 at r3 (raw file):

		count := int(*row[0].(*tree.DInt))
		if count != 0 {
			// TODO(yuzefovich): think through what to do when the old and the

@RaduBerinde what do you think about this one?


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 507 at r3 (raw file):

Previously, RaduBerinde wrote…

Not a huge problem if we don't clean them up.

Ack, let's not do that then.

Copy link
Contributor

@andreimatei andreimatei left a comment

Choose a reason for hiding this comment

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

What are the semantics if we get an instance of query, then while the first instance of the query is running, we get the second instance, and the first instance is fast and the second instance is slow? I believe we won't get the diagnostics in that case, correct?

If both queries arrive at the same gateway node, then you're right - we'll mark the fast instance as ongoing and will completely ignore the slow instance (because the tracing of this fingerprint is currently in progress). When the latency conditional is not satisfied on the fast instance, then the request is inserted back into the registry, so we'll have to wait for another slow instance.

I can't make up my mind about whether this is a good idea or not. As implemented, a constant stream of fast queries will starve a request to diagnose a slow query. On the other hand, the alternative (tracing all queries of that fingerprint until we hit a slow one) can be a performance hit. We could allow the user to control how much to trace, for example in the form of specifying a cap for a semaphore tracking how many queries are traced concurrenctly per fingerprint, but it might be overkill.
I guess if I were to choose one of the options, I'd go with tracing multiple queries concurrently, as that's guaranteed to satisfy the diagnostics request. But up to you.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @postamar, @RaduBerinde, and @yuzefovich)


pkg/cli/clisqlclient/statement_diag.go, line 82 at r4 (raw file):

	Statement                       string
	RequestedAt                     time.Time
	MinExecutionLatencyMilliseconds int64

why not time.Duration ?


pkg/migration/migrations/alter_statement_diagnostics_requests.go, line 29 at r4 (raw file):

	addColsToStmtDiagReqs = `
ALTER TABLE system.statement_diagnostics_requests
  ADD COLUMN min_execution_latency_ms INT8 NULL,

why not interval ?


pkg/server/serverpb/status.proto, line 1261 at r4 (raw file):

  // diagnostics report is not collected on it, and we will try to get a bundle
  // the next time we see the query fingerprint.
  int64 min_execution_latency = 2;

google.protobuf.Duration ?


pkg/sql/instrumentation.go, line 323 at r3 (raw file):

My understanding is that since we're not updating any system tables when a request becomes ongoing, we simply need to transfer the request from ongoing into requestFingerprints.

Sounds right based on a brief code read.

@RaduBerinde
Copy link
Member

No, I don't think it's possible because of the migration unfortunately. Unless we're willing to stop the train on 21.2.0 in order to fit this PR (as well as yet-to-be-written UI change) in and to break the promise of being able revert to a previous minor release for betas.

I think it's too late for that.. If there was more time, we would add just the updated schema and migration to 21.2.0 and backport the rest later.

Copy link
Member

@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.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @postamar, @RaduBerinde, and @yuzefovich)


pkg/cli/statement_diag_test.go, line 118 at r4 (raw file):

	// statement-diag delete 10
	// statement-diag list
	// Statement diagnostics bundles:

list should show the latency and expiration (if they exist). This is a place where we won't want to show the 100 years in the future thing, so we'll need to check for that somewhere (which seems messy IMO).

Same for the \statement-diag list sql shell command


pkg/cli/clisqlclient/statement_diag.go, line 82 at r4 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

why not time.Duration ?

I agree time.Duration is pretty much always preferable in code


pkg/migration/migrations/alter_statement_diagnostics_requests.go, line 29 at r4 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

why not interval ?

I'm the one I suggested to switch from INTERVAL to INT, interval seems like an unnecessary pain to parse and handle the 0 value.


pkg/sql/instrumentation.go, line 323 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

My understanding is that since we're not updating any system tables when a request becomes ongoing, we simply need to transfer the request from ongoing into requestFingerprints.

Sounds right based on a brief code read.

Ah, sorry, I missed those parts, CheckExecLatency and the tests LGTM


pkg/sql/catalog/systemschema/system.go, line 407 at r2 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

Hm, I started going down this route and the code does become less pretty, so I think it's better to keep this column non-nullable with a default expression.

It's up to you, but I would think we only need to handle it right after reading from the table. We can still use a synthetic timestamp in the code if that makes things easier.


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 261 at r3 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

@RaduBerinde what do you think about this one?

I'd say it's ok to leave like this assuming the user will have a reasonable way of canceling an outstanding request (which I don't think is the case now, outside of using the CLI)


pkg/sql/stmtdiagnostics/statement_diagnostics_test.go, line 118 at r4 (raw file):

	})

	t.Run("conditional", func(t *testing.T) {

[nit] add brief comments like above describing what we're testing

@yuzefovich yuzefovich force-pushed the conditional-stmt-diag branch 2 times, most recently from e38326e to 109a022 Compare November 10, 2021 02:01
Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

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

I like Andrei's suggestion of tracing every instance of a query if it matches a conditional request. I implemented that in a separate commit for ease of the review and will squash later.

I'm also having some issues with the unit test (namely that after one goroutine exists, the second one to execute a query will encounter an error), maybe you'll see where I have a problem. (I verified things manually and everything seemed to work ok.)

PTAL.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @postamar, and @RaduBerinde)


pkg/cli/statement_diag_test.go, line 118 at r4 (raw file):

Previously, RaduBerinde wrote…

list should show the latency and expiration (if they exist). This is a place where we won't want to show the 100 years in the future thing, so we'll need to check for that somewhere (which seems messy IMO).

Same for the \statement-diag list sql shell command

I missed how this interacts with the shell, fixed.


pkg/cli/clisqlclient/statement_diag.go, line 82 at r4 (raw file):

Previously, RaduBerinde wrote…

I agree time.Duration is pretty much always preferable in code

Done - I misunderstood Radu's suggestion.


pkg/server/serverpb/status.proto, line 1261 at r4 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

google.protobuf.Duration ?

Done.


pkg/sql/catalog/systemschema/system.go, line 407 at r2 (raw file):

Previously, RaduBerinde wrote…

It's up to you, but I would think we only need to handle it right after reading from the table. We can still use a synthetic timestamp in the code if that makes things easier.

Yeah, makes sense, done. For some reason I was too fixed on using the same type both for the column in the system table and for the in-memory representation.


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 261 at r3 (raw file):

Previously, RaduBerinde wrote…

I'd say it's ok to leave like this assuming the user will have a reasonable way of canceling an outstanding request (which I don't think is the case now, outside of using the CLI)

I'll introduce the canceling API in a separate PR, left a TODO for this.

@jordanlewis jordanlewis requested a review from a team November 10, 2021 02:44
Copy link
Member

@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.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @postamar, @RaduBerinde, and @yuzefovich)


pkg/cli/statement_diag.go, line 87 at r7 (raw file):

		fmt.Fprint(w, "  ID\tActivation time\tStatement\tMin execution latency\tExpires at\n")
		for _, r := range reqs {
			minExecLatency := "NULL"

[nit] maybe make it "N/A" or "0" instead of "NULL"


pkg/cli/statement_diag.go, line 91 at r7 (raw file):

				minExecLatency = r.MinExecutionLatency.String()
			}
			expiresAt := "NULL"

I'd make it "never"


pkg/cli/statement_diag_test.go, line 99 at r7 (raw file):

	// Outstanding activation requests:
	//   ID  Activation time          Statement     Min execution latency  Expires at
	//   6   2010-01-02 03:04:12 UTC  SELECT _ / _  0s                     NULL

0 and NULL should be printed the same


pkg/cli/clisqlclient/statement_diag.go, line 82 at r7 (raw file):

	Statement           string
	RequestedAt         time.Time
	MinExecutionLatency *time.Duration

[nit] Feels odd to use a pointer, there should be no difference between nil and 0. We can also use the zero value as "never" for ExpiresAt (and test for it with time.IsZero()).

In any case, let's be consistent - there are three different schemes used in this PR (both pointers here, one of them pointers in stmtdiagnostics/, no pointers in server/).


pkg/server/statement_diagnostics_requests.go, line 31 at r7 (raw file):

	RequestedAt            time.Time
	MinExecutionLatency    time.Duration
	ExpiresAt              time.Time

[nit] Worth a comment saying that this is zero for no expiration.


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 68 at r7 (raw file):

		// ongoingConditionalCount tracks how many of the requests in ongoing
		// are conditional.
		ongoingConditionalCount int

I wonder if this whole thing would be simpler if we left the request in requestFingerprints if it's conditional (and remove it once we get a slow instance)


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 95 at r7 (raw file):

		syncutil.Mutex
		// ongoingCount tracks the number of ongoing queries matching the
		// fingerprint that are currently being traced for this request. This is

[int] is


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 435 at r7 (raw file):

	// If no match found yet, check whether it matches an ongoing conditional
	// request.

Check r.mu.ongoingConditionalCount here to avoid the loop in most cases


pkg/sql/stmtdiagnostics/statement_diagnostics_test.go, line 172 at r7 (raw file):

		conns := make([]*gosql.DB, numGoroutines)
		for i := range conns {
			conns[i] = serverutils.OpenDBConn(t, s.ServingSQLAddr(), params.UseDatabase, params.Insecure, s.Stopper())

you can use db.Conn() (see this as an example:

h.conns[i], err = h.godb.Conn(context.Background())
)


pkg/sql/stmtdiagnostics/statement_diagnostics_test.go, line 179 at r7 (raw file):

		for i := range conns {
			go func(i int) {
				wg.Add(1)

Add needs to happen synchronously, or Wait() may run before any of the goroutines; can just do wg.Add(len(conns)) above

Copy link
Contributor

@maryliag maryliag left a comment

Choose a reason for hiding this comment

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

Reviewed 22 of 25 files at r6, 3 of 3 files at r7, all commit messages.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @maryliag, @postamar, @RaduBerinde, and @yuzefovich)


pkg/cli/statement_diag_test.go, line 41 at r7 (raw file):

		        (4, FALSE, 'SELECT _ + _', NULL, '2010-01-02 03:04:10', 100, NULL),
		        (5, FALSE, 'SELECT _ - _', NULL, '2010-01-02 03:04:11', NULL, '2010-01-02 03:04:12'),
		        (6, FALSE, 'SELECT _ / _', NULL, '2010-01-02 03:04:12', 0, NULL)`,

can you also add a test where we set the expires_at in the future?

Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @Azhng, @maryliag, @postamar, and @RaduBerinde)


pkg/migration/migrations/schema_changes.go, line 251 at r9 (raw file):

Previously, Azhng (Archer Zhang) wrote…

why are we ignoring the StoreColumnNames here ?

This extends the logic of ignoring StoreColumnIDs that is already done below (I'm not sure why StoreColumnNames weren't ignored already).


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 342 at r9 (raw file):

Previously, Azhng (Archer Zhang) wrote…

super minor nit: s/CheckExecLatency/IsExecLatencyAboveThreshold/

Hm, switched to IsExecLatencyConditionMet since I think it describes better what this function is about.


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 350 at r9 (raw file):

Previously, Azhng (Archer Zhang) wrote…

Should we check expiration before returning true above ?

I don't think so - CheckExecLatency is called after the tracing of a query has completed, so even if the request has just expired, but we were able to collect a bundle that satisfies the request, I think it makes sense to insert that bundle.

We'll get to this point only for conditional requests for which the query was faster than the latency condition, and deleting the expired conditional request from r.mu.requestFingerprints is an optimization in some sense (i.e. we could leave it in the map, and then it would be deleted the next time pollRequests is executed).

Copy link
Contributor

@Azhng Azhng left a comment

Choose a reason for hiding this comment

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

Mostly looks good, what kind of error was the second goroutine encountering?

Reviewed 1 of 25 files at r9, 1 of 2 files at r10.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @Azhng, @maryliag, @postamar, and @RaduBerinde)


pkg/migration/migrations/schema_changes.go, line 251 at r9 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

This extends the logic of ignoring StoreColumnIDs that is already done below (I'm not sure why StoreColumnNames weren't ignored already).

Oh I missed the column ids ignored. 👍


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 350 at r9 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

I don't think so - CheckExecLatency is called after the tracing of a query has completed, so even if the request has just expired, but we were able to collect a bundle that satisfies the request, I think it makes sense to insert that bundle.

We'll get to this point only for conditional requests for which the query was faster than the latency condition, and deleting the expired conditional request from r.mu.requestFingerprints is an optimization in some sense (i.e. we could leave it in the map, and then it would be deleted the next time pollRequests is executed).

I see, that makes sense. 👍

Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

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

what kind of error was the second goroutine encountering?

Do you mean in the test? I messed up using the wait group (waitGroup.Add was called inside new goroutines whereas it should be called before spawning up those goroutines, and as a result the main test goroutine would exit before the child goroutines get a chance to run and execute a query).

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei, @Azhng, @maryliag, @postamar, and @RaduBerinde)

Copy link
Contributor

@Azhng Azhng left a comment

Choose a reason for hiding this comment

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

Oh that makes sense.

Code :lgtm:, I'll leave the rubber stamp to andrei or radu

Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (waiting on @andreimatei, @Azhng, @maryliag, @postamar, and @RaduBerinde)

@yuzefovich yuzefovich force-pushed the conditional-stmt-diag branch 2 times, most recently from 7b418c2 to 512ad98 Compare November 12, 2021 16:45
@yuzefovich
Copy link
Member Author

Rebased on top of master, PTAL.

@yuzefovich
Copy link
Member Author

Rebased on top of master. Friendly ping @RaduBerinde @andreimatei.

Copy link
Contributor

@andreimatei andreimatei 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 25 files at r13, 3 of 25 files at r14.
Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (and 1 stale) (waiting on @andreimatei, @Azhng, @maryliag, @postamar, @RaduBerinde, and @yuzefovich)


pkg/migration/migrations/alter_statement_diagnostics_requests.go, line 29 at r4 (raw file):

Previously, RaduBerinde wrote…

I'm the one I suggested to switch from INTERVAL to INT, interval seems like an unnecessary pain to parse and handle the 0 value.

I asked Radu why he suggested this and he said there was some dubious code around treating a zero, but also that he doesn't care too much. Then we couldn't quite find the code in question.
I also won't die over this, but I would still prefer an INTERVAL, and use of NULL when it's not set. Cause like even if the ergonomics suck along the way, we wanted a SQL database so now we should enjoy it. So consider this again.


pkg/migration/migrations/alter_statement_diagnostics_requests.go, line 62 at r14 (raw file):

			schemaList: []string{"completed_idx"},
			query:      dropCompletedIdx,
			// DROP INDEX IF EXISTS can be safely execute many times.

nit: execute_d_
But i'd drop the comment altogether :P


pkg/server/status.go, line 422 at r14 (raw file):

		ctx context.Context,
		fprint string,
		minExecutionLatency time.Duration,

consider documenting these args


pkg/server/serverpb/status.proto, line 1263 at r14 (raw file):

  // not collected on it, and we will try to get a bundle the next time we see
  // the query fingerprint.
  google.protobuf.Duration min_execution_latency = 2  [ (gogoproto.nullable) = false, (gogoproto.stdduration) = true ];

consider putting more words about the implementation here, saying that multiple queries might be traced


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 261 at r3 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

I'll introduce the canceling API in a separate PR, left a TODO for this.

Wouldn't it be a good idea for this method to update the existing request? It seems pretty important to me to be able to get rid of a high min_duration that you might have set.
I'll also trust you to come back to this later if you want :).

Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @andreimatei, @Azhng, @maryliag, @postamar, and @RaduBerinde)


pkg/migration/migrations/alter_statement_diagnostics_requests.go, line 29 at r4 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I asked Radu why he suggested this and he said there was some dubious code around treating a zero, but also that he doesn't care too much. Then we couldn't quite find the code in question.
I also won't die over this, but I would still prefer an INTERVAL, and use of NULL when it's not set. Cause like even if the ergonomics suck along the way, we wanted a SQL database so now we should enjoy it. So consider this again.

My original version had INTERVAL NOT NULL DEFAULT now() + '100 years', and I had this code snippet in clisqlclient/statement_diag.go:

		var minExecutionLatency time.Duration
		// 0 value for time.Duration is handled in a special way (see
		// util/duration.encodePostgres).
		if latency := string(vals[3].([]byte)); latency != "00:00:00" {
			minExecutionLatency, err = time.ParseDuration(latency)
			if err != nil {
				return nil, err
			}
		}

I refactored the code to use INTERVAL NULL and updated the logic in clisqlclient/statement_diag.go to use EXTRACT builtin.

Please take a look at that.


pkg/server/status.go, line 422 at r14 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

consider documenting these args

Done.


pkg/server/serverpb/status.proto, line 1263 at r14 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

consider putting more words about the implementation here, saying that multiple queries might be traced

Done.


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 261 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

Wouldn't it be a good idea for this method to update the existing request? It seems pretty important to me to be able to get rid of a high min_duration that you might have set.
I'll also trust you to come back to this later if you want :).

I think the semantics with updating an existing request might not be that clear because there are some cases to consider (which I don't want to get into):

  • do we update the request if new expires_after is sooner? what if it's later than the existing one?
  • do we convert an existing non-conditional request into conditional if a new request is conditional? vice versa?

I imagine that a cleaner UX will be to ask user to somehow get rid of the existing request if they want to submit a new request. The flow would be something like "click on WAITING button" -> "see an option to cancel the existing request" -> this executes an RPC call with diagnostics ID to cancel the request. Then the user can issue a new request since they are starting from scratch.

That said, for power users (for CRDB devs / support) there is always an option to delete the rows from the table or update expires_at column manually.

Copy link
Contributor

@andreimatei andreimatei left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @andreimatei, @Azhng, @maryliag, @postamar, and @RaduBerinde)


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 261 at r3 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

I think the semantics with updating an existing request might not be that clear because there are some cases to consider (which I don't want to get into):

  • do we update the request if new expires_after is sooner? what if it's later than the existing one?
  • do we convert an existing non-conditional request into conditional if a new request is conditional? vice versa?

I imagine that a cleaner UX will be to ask user to somehow get rid of the existing request if they want to submit a new request. The flow would be something like "click on WAITING button" -> "see an option to cancel the existing request" -> this executes an RPC call with diagnostics ID to cancel the request. Then the user can issue a new request since they are starting from scratch.

That said, for power users (for CRDB devs / support) there is always an option to delete the rows from the table or update expires_at column manually.

What I care about is not leaving the code in a state where, if you set a diagnostics request with a min_duration that is never hit, you're essentially no longer able to trace that query. Editing the table manually is better then nothing, but not good enough in my opinion. So if you tell me that we'll figure out some flow soon, then I'll trust you... But I'm not getting the "soon" vibe :)

Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @andreimatei, @Azhng, @maryliag, @postamar, and @RaduBerinde)


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 261 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

What I care about is not leaving the code in a state where, if you set a diagnostics request with a min_duration that is never hit, you're essentially no longer able to trace that query. Editing the table manually is better then nothing, but not good enough in my opinion. So if you tell me that we'll figure out some flow soon, then I'll trust you... But I'm not getting the "soon" vibe :)

I started looking into updating a conditional request in place with the parameters of the new request, and it is quite messy, so I'm again pushing back that it is ok to merge this as is.

You're right that I'm not exposing the "soon" vibe on this - I think it is up to the SQL observability team to think through the right flow on how to handle different requests for the same fingerprint because most of the work will be on the DB Console, and I don't know how to do that. They will tell us what API is needed and will deliver.

My goal with this PR is that the conditional diagnostics feature has been long desired, and it always has been slipping through the cracks, so I decided to make it at least possible to do the conditional statement diagnostics (by manually updating the corresponding system table). Currently, since there is no other way to request a conditional diagnostics, I think it's totally justifiable to ask the user to modify the system table manually if minExecutionLatency is too long.

Copy link
Contributor

@andreimatei andreimatei left a comment

Choose a reason for hiding this comment

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

:lgtm:

Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (and 1 stale) (waiting on @andreimatei, @Azhng, @maryliag, @postamar, @RaduBerinde, and @yuzefovich)


pkg/cli/clisqlclient/statement_diag.go, line 102 at r17 (raw file):

func stmtDiagListOutstandingRequestsInternal(conn Conn) ([]StmtDiagActivationRequest, error) {
	rows, err := conn.Query(
		`SELECT id, statement_fingerprint, requested_at, EXTRACT(millisecond FROM min_execution_latency)::INT8, expires_at

just make sure that this returns the total number of millis. The pg docs are a bit lacking.
FWIW, in this thread I said that I've managed to use the pgx interval type:
https://cockroachlabs.slack.com/archives/C0168LW5THS/p1630610056016200


pkg/sql/stmtdiagnostics/statement_diagnostics.go, line 261 at r3 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

I started looking into updating a conditional request in place with the parameters of the new request, and it is quite messy, so I'm again pushing back that it is ok to merge this as is.

You're right that I'm not exposing the "soon" vibe on this - I think it is up to the SQL observability team to think through the right flow on how to handle different requests for the same fingerprint because most of the work will be on the DB Console, and I don't know how to do that. They will tell us what API is needed and will deliver.

My goal with this PR is that the conditional diagnostics feature has been long desired, and it always has been slipping through the cracks, so I decided to make it at least possible to do the conditional statement diagnostics (by manually updating the corresponding system table). Currently, since there is no other way to request a conditional diagnostics, I think it's totally justifiable to ask the user to modify the system table manually if minExecutionLatency is too long.

OK.

@yuzefovich yuzefovich force-pushed the conditional-stmt-diag branch 2 times, most recently from a3e9839 to 58f3051 Compare November 23, 2021 01:49
This commit extends the statement diagnostics to support conditional
collection: namely, it introduces `minExecutionLatency` parameter so
that we could collect bundles on the slow outliers if necessary. Using
the zero value for that parameter will give us the previous behavior
(collecting the bundle on the next query fingerprint execution).

When `minExecutionLatency` argument is non-zero, then all queries that
match the specified fingerprint are traced until a slow enough query
comes along. This approach was chosen over tracing at most one query at
a time so that we don't miss the slow outlier when fast queries can
"starve" it (imagine that a node is bombarded with many fast queries and
a slow outlier occurs very rarely - it would be unfortunate to not trace
the outlier because when it arrives, a fast query is already being
traced).

In order for some diagnostics requests not to stay "alive" forever, this
commit also adds an `expiresAfter` interval. It'll be provided by the
user when the conditional collection is desired. The zero value is
treated as "never". Expired and not completed requests are not explicitly
deleted from the system table and are being simply ignored once they
expire.

This commit then adds a migration to the `statement_diagnostics_requests`
system table to add these two additional columns as well as to update
the secondary index to store these columns as well. All requests created
prior to the migration will never expire and won't have the min execution
latency conditional.

If a diagnostics request already exists for a fingerprint in the system
table, a new one (even with different conditionals / expiration
interval) cannot be created by the API - an error is returned. The
follow-up work will extend an API to make it possible to cancel the
existing request so that a new one could be created.

This API is not hooked up to the DB Console yet, thus there is no release
note.

Release note: None
Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

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

TFTRs!

bors r+

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @andreimatei, @Azhng, @maryliag, @postamar, and @RaduBerinde)


pkg/cli/clisqlclient/statement_diag.go, line 102 at r17 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

just make sure that this returns the total number of millis. The pg docs are a bit lacking.
FWIW, in this thread I said that I've managed to use the pgx interval type:
https://cockroachlabs.slack.com/archives/C0168LW5THS/p1630610056016200

That's a good point - I had a bug here (everything from "minute" and larger was ignored). Adjusted one test case to be much more interesting and fixed the calculation.

@craig
Copy link
Contributor

craig bot commented Nov 23, 2021

Build succeeded:

@craig craig bot merged commit a5e32e1 into cockroachdb:master Nov 23, 2021
@yuzefovich yuzefovich deleted the conditional-stmt-diag branch November 23, 2021 03:13
@ajwerner
Copy link
Contributor

ajwerner commented Nov 4, 2022

I don't get why StoreColumnNames are ignored. I think I get ignoring the IDs. Don't we want the length of the IDs and the names to be the same?

@yuzefovich
Copy link
Member Author

yuzefovich commented Nov 4, 2022

I don't know why I made that change - probably some tests were failing and ignoring StoreColumnNames seemed reasonable given we're ignoring StoreColumnIDs (which was introduced in #66889). I don't really know what I'm talking about here, so if you say that we shouldn't ignore StoreColumnNames, I believe you.

Can you expand on why you're thinking ignoring the IDs is ok but not names? Is your thinking that we only want to make sure that both slices have the same number of values? It looks like that part didn't happen before this PR.

@ajwerner
Copy link
Contributor

ajwerner commented Nov 4, 2022

There are various reasons why the IDs can shift around, namely due to folks canceling long-running jobs or us failing to properly classify errors. There are no reasons why the names should not exactly match the expectation for the index. Also, the length of the IDs slice should match the expectation. I addressed this in #91304.

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.

8 participants