show session variables is very slow on first run

[morgo]

Bug Report

This is reported here:

https://asktug.com/t/topic/69586
https://asktug.com/t/topic/69767
https://asktug.com/t/topic/69699

1. Minimal reproduce step (Required)

SHOW VARIABLES in a new session

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

It should always be fast.

3. What did you see instead (Required)

The first execution is slow.

4. What is your TiDB version? (Required)

Verified against master:

mysql> select tidb_version()\G
*************************** 1. row ***************************
tidb_version(): Release Version: v4.0.0-beta.2-2748-g8b0305aa2-dirty
Edition: Community
Git Commit Hash: 8b0305aa2af38f201c893fe9ce8c9af4201ebbc8
Git Branch: master
UTC Build Time: 2021-04-27 14:20:08
GoVersion: go1.13.15
Race Enabled: false
TiKV Min Version: v3.0.0-60965b006877ca7234adaced7890d7b029ed1306
Check Table Before Drop: false
1 row in set (0.00 sec)

[morgo]

The problem is more complicated to fix than I first thought. SHOW VARIABLES actually shows both session and global variables, for which the global-only variables will load the value from mysql.global_variables one row at a time.

The easy fix is to change loadCommonGlobalVariablesIfNeeded() to load all variables at once, whether or not they are required. But this may require a lot of additional memory, since each session will cache the global variables even though they don't change. This may actually be the outcome in user deployments, since on the first SHOW SESSION VARIABLES call, the global variables will be cached in systems[], but it seems like an unfortunate regression for users who don't call SHOW SESSION VARIABLES.

The more complex fix is to improve the caching layer for sysVars to separate global scoped variables and session scoped variables. When a new session is created, it should copy the session-scoped cache immediately (this is MySQL behavior; currently TiDB does not follow this exactly because it lazy-loads the session vars.)

Improving the caching layer also means that read-after-write consistency can be ensured. This is not provided by the current global value cache, and the testsuite does non-MySQL compatible things to ensure it:

tidb/session/session_test.go

Lines 2573 to 2580 in dbecb9e

	tk.MustExec("set global time_zone = '+00:00'")
	tk.MustQuery("show variables like 'time_zone'").Check(testkit.Rows("time_zone +08:00"))
	// Disable global variable cache, so load global session variable take effect immediate.
	s.dom.GetGlobalVarsCache().Disable()
	tk1 := testkit.NewTestKitWithInit(c, s.store)
	tk1.MustQuery("show variables like 'time_zone'").Check(testkit.Rows("time_zone +00:00"))

(There are other occurences of this, and this issue is not just affecting the testsuite. I've also noticed it when scripting against TiDB, since global changes even on a local server are not immediate.)

The global variable cache uses a 2 second TTL, and doesn't actually notify other TiDB servers that the cache is out of date and needs to be reloaded. A more friendly design would be to use the same as the privilege system which uses a 5 minute TTL and subscribes to updates via etcd notifications. This makes both the cache more useful, and also the updates on other TiDB servers can be reduced to less than 2 seconds in most cases.

[ngaut]

Good catch, here is another report https://asktug.com/t/topic/69936

[morgo]

This relates to #24368 - the subsequent "fast" runs of show variables are actually incorrect anyway, since the first run is caching global values when it is not supposed to. But removing this cache should occur after the sysvar cache is improved.

[ti-srebot]

Please edit this comment or add a new comment to complete the following information

Bug

Note: Make Sure that 'component', and 'severity' labels are added
Example for how to fill out the template: #20100

1. Root Cause Analysis (RCA) (optional)

Global variables are expected to show in SHOW VARIABLES output, but the values are read row-at-a-time from TiKV (an N+1 problem) and then cached. The cache itself is incorrect (a separate issue).

2. Symptom (optional)

Any latency betweeen tidb and the tikv region which stores the config information increases the impact of this issue, resulting in some users reporting close to 1 second delay.

3. All Trigger Conditions (optional)

4. Workaround (optional)

Use a connection pool, and pre-run SHOW VARIABLES. Short lived connections or short lived pools exhibit the slow cache issue the worst.

5. Affected versions

[v4.0.1:v4.0.12], [v5.0.0:v5.0.1]

6. Fixed versions

master

[ti-srebot]

( AffectedVersions ) fields are empty.
The values in ( AffectedVersions ) fields are incorrect.

[tisonkun]

@morgo do you refer to all by "all versions before and include 5.0.1?

[morgo]

@morgo do you refer to all by "all versions before and include 5.0.1?

Yes.

[shenli]

may I know why this issue is closed?

[morgo]

may I know why this issue is closed?

This has been fixed with the introduction of sysvar cache in master. The sysvar cache functions differently to the previous global variables cache in that it invalidates the cache when changes are made. Regeneration is also handled in the background.