stale-read query latency 10x spike cause by information schema cache miss

[crazycs520]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

High schema cache miss.

Related metrics:

Analyze

The reason for a large number of load snapshot schema operations must be InfoSchema cache miss, but what causes cache miss?

Almost all TiDB generate a large number of load snapshot schema operations at the same time. It's weird, I picked a TiDB (tidb-11) with a large amount of operations for log analysis.

grep 'load InfoSchema' tidb-11.log

"[2024/05/09 15:00:46.337 +00:00] [INFO] [domain.go:224] [\"diff load InfoSchema success\"] [currentSchemaVersion=585441] [neededSchemaVersion=585442] [\"start time\"=1.734944ms] [phyTblIDs=\"[]\"] [actionTypes=\"[]\"]",

"[2024/05/09 15:00:46.521 +00:00] [INFO] [domain.go:224] [\"diff load InfoSchema success\"] [currentSchemaVersion=585442] [neededSchemaVersion=585443] [\"start time\"=503.56µs] [phyTblIDs=\"[]\"] [actionTypes=\"[]\"]",

"[2024/05/09 15:01:34.130 +00:00] [INFO] [domain.go:224] [\"diff load InfoSchema success\"] [currentSchemaVersion=585443] [neededSchemaVersion=585445] [\"start time\"=4.158976ms] [phyTblIDs=\"[454637]\"] [actionTypes=\"[8]\"]",

The schema version has 585442, 585443, and 585445, but 585444 does not exist, and there's a hole that causes schema cache misses, so TiDB needs to load snapshot schema from TiKV. Related codes are following:

tidb/infoschema/cache.go

Line 118 in 868456d

if h.cache[i-1].infoschema.SchemaMetaVersion() == is.infoschema.SchemaMetaVersion()+1 && uint64(h.cache[i-1].timestamp) > ts {

Well, Why does the schema version 585444 not exist? From the current code implementation, since GenSchemaVersion uses a separate transaction to generate schema version, but SetSchemaDiff use another transaction, so if GenSchemaVersion transaction succeed, but SetSchemaDiff transaction fails, then will have schema version gap in this issue.

Why use two separate transactions? this change is introduced by PR: support concurrent ddl

tidb/pkg/ddl/ddl.go

Lines 448 to 453 in 5d990c6

	err = kv.RunInNewTxn(kv.WithInternalSourceType(context.Background(), kv.InternalTxnDDL), store, true, func(_ context.Context, txn kv.Transaction) error {
	var err error
	m := meta.NewMeta(txn)
	schemaVersion, err = m.GenSchemaVersion()
	return err
	})

tidb/pkg/ddl/schema_version.go

Line 358 in 851e22d

err = t.SetSchemaDiff(diff)

tidb/domain/domain.go

Lines 423 to 424 in 2abf83d

	// Empty diff means the txn of generating schema version is committed, but the txn of `runDDLJob` is not or fail.
	// It is safe to skip the empty diff because the infoschema is new enough and consistent.

2. What did you expect to see? (Required)

No information schema cache miss.

3. What did you see instead (Required)

information schema cache miss then cause many operation which is load snapshot schema for stale-read query.

4. What is your TiDB version? (Required)

nightly: e1a6b1d

[crazycs520]

@lcwangchao PTAL

[D3Hunter]

run admin show ddl jobs to checkout which ddl is cancelled or failed

[crazycs520]

run admin show ddl jobs to checkout which ddl is cancelled or failed

It doesn't matter what DDL cancels or fails, the important thing is that there is a schema version gap that causes the schema cache miss, then cause stale-read query latency 10x spike.

[crazycs520]

Another possible cause of this problem is when tryLoadSchemaDiffs loads multiple versions of schema in one time, such as following log:

[2024/05/24 09:00:09.638 +00:00] [INFO] [domain.go:287] ["diff load InfoSchema success"] [currentSchemaVersion=14899] [neededSchemaVersion=14901] [gap=2] ["start time"=3.152629ms] [gotSchemaVersion=14901] [phyTblIDs="[17245,17184]"] [actionTypes="[3,7]"] [diffTypes="[\"create table\",\"add index\"]"]

This is because create table DDL job and add index DDL job can can be executed concurrently.

[tiancaiamao]

I'd like to point out that in the new design of fast create table, the schema diff for create table could be missing.
And we will not have all the schema history eventually.

[D3Hunter]

I'd like to point out that in the new design of fast create table, the schema diff for create table could be missing. And we will not have all the schema history eventually.

you mean tidb_enable_fast_create_table?, it will set diff too, but don't wait it apply

[crazycs520]

Another possible cause of this problem is when tryLoadSchemaDiffs loads multiple versions of schema in one time, such as following log:

[2024/05/24 09:00:09.638 +00:00] [INFO] [domain.go:287] ["diff load InfoSchema success"] [currentSchemaVersion=14899] [neededSchemaVersion=14901] [gap=2] ["start time"=3.152629ms] [gotSchemaVersion=14901] [phyTblIDs="[17245,17184]"] [actionTypes="[3,7]"] [diffTypes="[\"create table\",\"add index\"]"]

This is because create table DDL job and add index DDL job can can be executed concurrently.

#53620 should fix this.

[mittalrishabh]

I have few questions about this issue

1. when does set schema transaction failed. Is it because of conflict ?
2. Why it generated large qps on a tikv node to read metadata. Should there be rate limit from tidb ? We have seen it generating 60k qps on a tikv node.
3. How it repopulates the schema cache after tidb is rebooted ?