Tidb auto analyze returns error [parser:1064]

Eugen_Korentsov · April 13, 2023, 11:11am

Application environment:

production

TiDB version: 6.5.1

Problem:

If I check SHOW ANALYZE STATUS; I see a lot of failed queries with exception:
[parser:1064]You have an error in your SQL syntax; check the manual that corresponds to your TiDB version for the right syntax to use run multiple statements internally is not supported"

I stopped auto analyze, and tried to run analyze manually with query:
analyze table test_table; and got same error in my MySQL client:
SQL Error [1064] [42000]: You have an error in your SQL syntax; check the manual that corresponds to your TiDB version for the right syntax to use run multiple statements internally is not supported

What I’ve noticed that all failed tables are present in TiFlash.

dveeden · April 13, 2023, 12:30pm

Could you share the output of SHOW ANALYZE STATUS?

Did you upgrade from a earlier version or is this a new installation that started with v6.5.1?

The syntax you posted is fine:

sql> CREATE TABLE test_table (id SERIAL PRIMARY KEY);
Query OK, 0 rows affected (0.1628 sec)

sql> analyze table test_table;
Query OK, 0 rows affected, 1 warning (0.1118 sec)
Note (code 1105): Analyze use auto adjusted sample rate 1.000000 for table test.test_table

Is there something in the logs of tidb-server that might give more details on what happened?

Eugen_Korentsov · April 13, 2023, 12:38pm

No upgrades, started from v6.5.1. Deployed in k8s, using tidb operator. Attaching analyze status output.
_SHOW_ANALYZE_STATUS__202304131332.csv (1.2 KB)

Eugen_Korentsov · April 13, 2023, 12:42pm

And If I create new table, analyze works fine on it. I have same result as you above.

dveeden · April 13, 2023, 1:04pm

The error message seems to be related to this setting: tidb_multi_statement_mode.

However I would not expect this to give issues for running ANALYZE.

There should be a similar message in the logs of tidb-server. Could you share that?

Eugen_Korentsov · April 13, 2023, 1:17pm

Tidb log:
2023-04-13 12:51:08 [2023/04/13 11:51:08.861 +00:00] [ERROR] [analyze.go:318] [“save table stats to storage failed”] [conn=7866431751669379465] [error=“[parser:1064]You have an error in your SQL syntax; check the manual that corresponds to your TiDB version for the right syntax to use run multiple statements internally is not supported”] [tableID=1251]

Eugen_Korentsov · April 13, 2023, 1:17pm

Also, I found a table that is not in tiflash, also the same error.

dveeden · April 13, 2023, 2:33pm

This is where it seems to go wrong:

github.com

pingcap/tidb/blob/4084b077d615f9dc0a41cf2e30bc6e1a02332df2/statistics/handle/handle.go#L1647


      
          		if err == nil && statsVer != 0 {
          			err = h.recordHistoricalStatsMeta(tableID, statsVer)
          		}
          	}()
          	h.mu.Lock()
          	defer h.mu.Unlock()
          	return SaveTableStatsToStorage(h.mu.ctx, results, analyzeSnapshot)
          }
          
          
// SaveTableStatsToStorage saves the stats of a table to storage.
          func SaveTableStatsToStorage(sctx sessionctx.Context, results *statistics.AnalyzeResults, analyzeSnapshot bool) (err error) {
          	needDumpFMS := results.TableID.IsPartitionTable()
          	tableID := results.TableID.GetStatisticsID()
          	statsVer := uint64(0)
          	defer func() {
          		if err == nil && statsVer != 0 {
          			err = recordHistoricalStatsMeta(sctx, tableID, statsVer)
          		}
          	}()
          	ctx := kv.WithInternalSourceType(context.Background(), kv.InternalTxnStats)
          	exec := sctx.(sqlexec.SQLExecutor)

Based on the logging I can’t tell where in this function the error is coming from.

Are there any log messages from around the same time that might be related?

Is tidb_analyze_version set to 2?

Eugen_Korentsov · April 13, 2023, 3:28pm

yes tidb_analyze_version = 2

dveeden · April 13, 2023, 3:42pm

To troubleshoot this further one option is to see if SET GLOBAL tidb_multi_statement_mode=ON and a restart of TiDB allows the analyze process to run without issues.

Eugen_Korentsov · April 13, 2023, 4:17pm

So I’ve enabled tidb_multi_statement_mode=ON, with SET GLOBAL tidb_multi_statement_mode=ON

Restarted all tidb replicas, and still the same issue. Which services need to be restarted only tidb? No need to restart pd/tikv/tiflash?

Eugen_Korentsov · April 13, 2023, 8:11pm

For tidb we have WARN log level, messages around:


[2023/04/13 18:45:46.637 +00:00] [WARN] [pd.go:152] ["get timestamp too slow"] ["cost time"=118.628969ms]
[2023/04/13 18:45:46.764 +00:00] [WARN] [pd.go:152] ["get timestamp too slow"] ["cost time"=35.760627ms]
[2023/04/13 18:45:46.765 +00:00] [WARN] [pd.go:152] ["get timestamp too slow"] ["cost time"=31.645138ms]
[2023/04/13 18:45:47.415 +00:00] [ERROR] [analyze.go:318] ["save table stats to storage failed"] [conn=5369196753406920077] [error="[parser:1064]You have an error in your SQL syntax; check the manual that corresponds to your TiDB version for the right syntax to use run multiple statements internally is not supported"] [tableID=1267]
[2023/04/13 18:45:47.429 +00:00] [WARN] [session.go:2220] ["run statement failed"] [conn=5369196753406920077] [schemaVersion=1265] [error="[parser:1064]You have an error in your SQL syntax; check the manual that corresponds to your TiDB version for the right syntax to use run multiple statements internally is not supported"] [session="{\n  \"currDBName\": \"masked-name\",\n  \"id\": 5369196753406920077,\n  \"status\": 514,\n  \"strictMode\": true,\n  \"user\": {\n    \"Username\": \"root\",\n    \"Hostname\": \"10.100.0.13\",\n    \"CurrentUser\": false,\n    \"AuthUsername\": \"root\",\n    \"AuthHostname\": \"%\"\n  }\n}"]
[2023/04/13 18:48:35.985 +00:00] [WARN] [pd.go:152] ["get timestamp too slow"] ["cost time"=30.858497ms]
[2023/04/13 18:57:35.911 +00:00] [WARN] [pd.go:152] ["get timestamp too slow"] ["cost time"=103.274251ms]

dveeden · April 13, 2023, 9:23pm

Only restarting TiDB is enough. No need to restart anything else.

I assume there are no messages with “parse SQL failed” in them?

Eugen_Korentsov · April 14, 2023, 7:46am

@dveeden

Found some WARN messages from yesterday:

"[parser:1064]You have an error in your SQL syntax; check the manual that corresponds to your TiDB version for the right syntax to use line 1 column 67 near \"yze table active\" "

But I tried to run analyze table active; today also, no such messages from today.

Eugen_Korentsov · April 14, 2023, 4:37pm

@dveeden
maybe we should try to switch to tidb_analyze_version 1 ?

Nope, it didn’t help. tidb_enable_fast_analyze 1 also didn’t help.

Eugen_Korentsov · April 15, 2023, 10:51am

More logs:

2023-04-15 11:15:21	
[2023/04/15 10:15:21.522 +00:00] [ERROR] [update.go:1290] ["[stats] auto analyze failed"] [sql="analyze table `masked-name`.`source_table`"] [cost_time=4h52m22.130447809s] [error="runtime error: slice bounds out of range [-1:]"]Show context
2023-04-15 11:15:21	
[2023/04/15 10:15:21.511 +00:00] [ERROR] [analyze.go:308] ["analyze failed"] [error="runtime error: slice bounds out of range [-1:]"]

and this one new:
2023-04-15 11:35:03	
[2023/04/15 10:35:03.180 +00:00] [ERROR] [handle.go:623] ["[stats] error occurred when read table stats"] [table=logs] [error="proto: CMSketch: wiretype end group for non-group"]

dveeden · April 17, 2023, 6:49am

For the message about the logs table, could you check what’s in the stats tables?

-- Find the TableID for the logs table:
SELECT TIDB_TABLE_ID FROM information_schema.TABLES WHERE TABLE_NAME='logs';

SELECT * FROM mysql.stats_meta WHERE table_id=...;
SELECT * FROM mysql.stats_histograms WHERE table_id=...;
SELECT * FROM mysql.stats_extended WHERE table_id=...;

Uploading a full dump of these tables would also work.

If there is anything special it is probably in the cm_sketch column of the mysql.stats_histograms table.

For the other message: The “Show context”, is that in the log file or is that something from the log viewer that can reveal more details? If so, could you post the details/context?

Eugen_Korentsov · April 17, 2023, 11:21am

SELECT * FROM mysql.stats_extended WHERE table_id=...;

Empty result.

for stats_meta and stats_histograms, Yes, there is something weird in cm_sketch column where stats_ver=1

But I see no more cm_sketch errors now, seems it is related to my attempt to switch to 1 version of tidb_analyze_version

Eugen_Korentsov · April 17, 2023, 11:26am

Here is all context around this ERROR:

[2023/04/15 10:15:43.843 +00:00] [INFO] [2pc.go:672] ["[BIG_TXN]"] [session=2944193072021373767] ["key sample"=7480000000000003f85f72800000000000375d] [size=5059588] [keys=1] [puts=1] [dels=0] [locks=0] [checks=0] [txnStartTS=440809224541569035]
[2023/04/15 10:15:39.086 +00:00] [INFO] [advancer.go:189] ["[log backup advancer hint] sample range."] [sample="([7480000000000004305F698000000000000004040000000000001EA80419AE82000000000003800000003A80D6BE, 7480000000000004305F698000000000000004040000000000001EAB0419A814000000000003800000000600645B), 440809149174906915)"] [total-len=1]
[2023/04/15 10:15:27.086 +00:00] [INFO] [advancer.go:189] ["[log backup advancer hint] sample range."] [sample="([7480000000000004305F698000000000000004040000000000001EA80419AE82000000000003800000003A80D6BE, 7480000000000004305F698000000000000004040000000000001EAB0419A814000000000003800000000600645B), 440809149174906915)"] [total-len=1]
[2023/04/15 10:15:21.522 +00:00] [WARN] [session.go:2220] ["run statement failed"] [schemaVersion=1453] [error="runtime error: slice bounds out of range [-1:]"] [session="{\n  \"currDBName\": \"\",\n  \"id\": 2944193072021372931,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": null\n}"]
[2023/04/15 10:15:21.522 +00:00] [INFO] [tidb.go:270] ["rollbackTxn called due to ddl/autocommit failure"]
[2023/04/15 10:15:21.521 +00:00] [INFO] [analyze.go:575] ["analyze table `masked-name`.`source_table` has failed"] [partition=] ["job info"="auto analyze table all columns with 256 buckets, 500 topn, 0.0003319489643193822 samplerate"] ["start time"=2023/04/15 05:22:59.418 +00:00] ["end time"=2023/04/15 10:15:21.511 +00:00] [cost=4h52m22.092857036s]
[2023/04/15 10:15:21.511 +00:00] [ERROR] [analyze.go:308] ["analyze failed"] [error="runtime error: slice bounds out of range [-1:]"]
[2023/04/15 10:15:21.511 +00:00] [ERROR] [analyze_col_v2.go:644] ["analyze worker panicked"] [recover="runtime error: slice bounds out of range [-1:]"] [stack="github.com/pingcap/tidb/executor.(*AnalyzeColumnsExecV2).subBuildWorker.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/analyze_col_v2.go:644\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:884\nruntime.goPanicSliceB\n\t/usr/local/go/src/runtime/panic.go:153\ngithub.com/pingcap/tidb/statistics.BuildHistAndTopN\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/statistics/builder.go:378\ngithub.com/pingcap/tidb/executor.(*AnalyzeColumnsExecV2).subBuildWorker\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/analyze_col_v2.go:778\ngithub.com/pingcap/tidb/executor.(*AnalyzeColumnsExecV2).buildSamplingStats.func3\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/analyze_col_v2.go:347\ngithub.com/pingcap/tidb/executor.(*notifyErrorWaitGroupWrapper).Run.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/executor/analyze_utils.go:127"]
[2023/04/15 10:15:19.081 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=17539.689596235s] [conn_id=2944193072021372931] [txn_start_ts=0] [mem_max="1187689735 Bytes (1.11 GB)"] [sql="analyze table `masked-name`.`source_table`"]```

Eugen_Korentsov · April 18, 2023, 1:29pm

@dveeden any idea?