sql: index recommendation code can cause log spam and errors

[ajwerner]

Describe the problem

I ran an unrelated test and see:

W220810 04:22:35.670649 5728 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1482  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.683731 8487 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1483  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.697454 8489 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1484  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.709887 8456 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1485  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.722901 8516 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1486  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.736447 8518 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1487  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.748243 8520 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1488  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.759527 8493 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1489  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.772222 8463 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1490  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.783008 8526 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1491  unable to build memo: cannot use CheckPrivilege without a txn
W220810 04:22:35.793800 8528 sql/instrumentation.go:711  [n1,intExec=expire-sessions] 1492  unable to build memo: cannot use CheckPrivilege without a txn

I think there's a few things going on here:

1. I think the internal executor is in some way not set up for the index recommendation code.
2. I think we need to have the cache update the last generation time when we're deciding to return true as opposed to when we add the new recommendation -- otherwise if the index recommendation code starts failing, we'll run it every time the query is hit. Already I think there's a problem that if you run a query at a high frequency then once you hit the threshold, we'll generate the recommendations in parallel.

To Reproduce

Run a test that sets short job intervals.

Jira issue: CRDB-18470

[RichardJCai]

cc @rafiss

I think this might be related to the case where we get an error but only log it instead of returning it, thus the txn becomes invalid?

[rafiss]

I think this might be related to the case where we get an error but only log it instead of returning it, thus the txn becomes invalid?

+1 was going to point that out too. Here's an example where that happened before: #85454

Is there any part of this code that uses a transaction/internalExecutor to do something, but then ignores/logs the error without returning it to the txn runner?

[maryliag]

This is the part of the code that is causing the error

cockroach/pkg/sql/instrumentation.go

Lines 699 to 726 in 4655f97

	evalCtx := opc.p.EvalContext()
	oldCtx := evalCtx.Context
	evalCtx.Context = ctx
	defer func() {
	evalCtx.Context = oldCtx
	}()
	f.Init(evalCtx, &opc.catalog)
	f.FoldingControl().AllowStableFolds()
	bld := optbuilder.New(ctx, &opc.p.semaCtx, evalCtx, &opc.catalog, f, opc.p.stmt.AST)
	err := bld.Build()
	if err != nil {
	log.Warningf(ctx, "unable to build memo: %s", err)
	} else {
	err = opc.makeQueryIndexRecommendation(ctx)
	if err != nil {
	log.Warningf(ctx, "unable to generate index recommendations: %s", err)
	} else {
	idxRec.UpdateIndexRecommendations(
	ih.fingerprint,
	ih.planGist.Hash(),
	planner.SessionData().Database,
	stmtType,
	ih.indexRecommendations,
	true,
	)
	}
	}

that is the first time using the executor (on this new function) and we add the log. That functions is called here

cockroach/pkg/sql/conn_executor_exec.go

Line 1201 in 4655f97

planner.instrumentation.SetIndexRecommendations(ctx, ex.server.idxRecommendationsCache, planner)

[rafiss]

Is it intentional that a nil txn is passed into ExecEx? I'd guess not, since otherwise why are we using the IE inside of a db.Txn?

		if err := r.db.Txn(ctx, func(ctx context.Context, txn *kv.Txn) error {
			// Run the expiration transaction at low priority to ensure that it does
			// not contend with foreground reads. Note that the adoption and cancellation
			// queries also use low priority so they will interact nicely.
			if err := txn.SetUserPriority(roachpb.MinUserPriority); err != nil {
				return errors.WithAssertionFailure(err)
			}
			_, err := r.ex.ExecEx(
				ctx, "expire-sessions", nil,
				sessiondata.InternalExecutorOverride{User: username.RootUserName()},
				removeClaimsForDeadSessionsQuery,
				s.ID().UnsafeBytes(),
				cancellationsUpdateLimitSetting.Get(&r.settings.SV),
			)
			return err
		})

[rafiss]

OK I have a better idea now, my previous comment definitely seems like it's a bug (i.e. the change in aed014f doesn't seem like it fully did what we want cc @ajwerner), but I don't think that's the problem here.

The problem is that that SetIndexRecommendations is called here:

cockroach/pkg/sql/conn_executor_exec.go

Line 1201 in 65fe1a5

planner.instrumentation.SetIndexRecommendations(ctx, ex.server.idxRecommendationsCache, planner)

But at this point the transaction may already have committed, probably due to the 1PC fast path optimization.

[ajwerner]

But at this point the transaction may already have committed, probably due to the 1PC fast path optimization.

It also could be aborted due to a serializability or deadlock error.