flaky test TestAnalyzeMVIndex

[hawkingrei]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

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

3. What did you see instead (Required)

         	Error Trace:	testkit/result.go:49
        	            				executor/test/analyzetest/analyze_test.go:3234
        	Error:      	Not equal: 
        	            	expected: "[1 test t  analyze table columns a with 256 buckets, 3 topn, 1 samplerate 27 finished]\n[2 test t  analyze index ij_signed 190 finished]\n[3 test t  analyze index ij_unsigned 135 finished]\n[4 test t  analyze index ij_double 154 finished]\n[5 test t  analyze index ij_binary 259 finished]\n[6 test t  analyze index ij_char 189 finished]\n"
        	            	actual  : "[1 test t  analyze table columns a with 256 buckets, 3 topn, 1 samplerate 54 finished]\n[2 test t  analyze index ij_signed 190 finished]\n[3 test t  analyze index ij_unsigned 135 finished]\n[4 test t  analyze index ij_double 154 finished]\n[5 test t  analyze index ij_binary 259 finished]\n[6 test t  analyze index ij_char 189 finished]\n"
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,2 +1,2 @@
        	            	-[1 test t  analyze table columns a with 256 buckets, 3 topn, 1 samplerate 27 finished]
        	            	+[1 test t  analyze table columns a with 256 buckets, 3 topn, 1 samplerate 54 finished]
        	            	 [2 test t  analyze index ij_signed 190 finished]
        	Test:       	TestAnalyzeMVIndex
        	Messages:   	sql:select id, table_schema, table_name, partition_name, job_info, processed_rows, state from mysql.analyze_jobs order by id, args:[] 

4. What is your TiDB version? (Required)

[time-and-fate]

https://tiprow.hawkingrei.com/view/gs/pingcapprow/pr-logs/pull/pingcap_tidb/46987/tiprow_fast_test/1702271672482009088#1:build-log.txt%3A3700

Very strange phenomenon in the log:

[2023/09/14 18:51:23.069 +08:00] [INFO] [analyze.go:625] ["analyze table `test`.`t` has finished"] [partition=] ["job info"="analyze table columns a with 256 buckets, 3 topn, 1 samplerate"] ["start time"=2023/09/14 18:51:23.065 +08:00] ["end time"=2023/09/14 18:51:23.067 +08:00] [cost=2.350202ms] ["sample rate reason"=]
[2023/09/14 18:51:23.085 +08:00] [INFO] [analyze.go:625] ["analyze table `test`.`t` has finished"] [partition=] ["job info"="analyze index ij_double"] ["start time"=2023/09/14 18:51:23.065 +08:00] ["end time"=2023/09/14 18:51:23.083 +08:00] [cost=18.459459ms] ["sample rate reason"=]
[2023/09/14 18:51:23.096 +08:00] [INFO] [analyze.go:625] ["analyze table `test`.`t` has finished"] [partition=] ["job info"="analyze index ij_signed"] ["start time"=2023/09/14 18:51:23.065 +08:00] ["end time"=2023/09/14 18:51:23.095 +08:00] [cost=30.014888ms] ["sample rate reason"=]
[2023/09/14 18:51:23.105 +08:00] [INFO] [analyze.go:625] ["analyze table `test`.`t` has finished"] [partition=] ["job info"="analyze index ij_unsigned"] ["start time"=2023/09/14 18:51:23.065 +08:00] ["end time"=2023/09/14 18:51:23.104 +08:00] [cost=39.095206ms] ["sample rate reason"=]
[2023/09/14 18:51:23.106 +08:00] [INFO] [handle.go:1155] ["incrementally update modifyCount"] [category=stats] [tableID=100] [curModifyCnt=27] [results.BaseModifyCnt=27] [modifyCount=0]
[2023/09/14 18:51:23.106 +08:00] [INFO] [handle.go:1177] ["directly update count"] [category=stats] [tableID=100] [results.Count=27] [count=27]
[2023/09/14 18:51:23.126 +08:00] [INFO] [analyze.go:625] ["analyze table `test`.`t` has finished"] [partition=] ["job info"="analyze table columns a with 256 buckets, 3 topn, 1 samplerate"] ["start time"=2023/09/14 18:51:23.065 +08:00] ["end time"=2023/09/14 18:51:23.125 +08:00] [cost=59.578683ms] ["sample rate reason"=]
[2023/09/14 18:51:23.138 +08:00] [INFO] [analyze.go:625] ["analyze table `test`.`t` has finished"] [partition=] ["job info"="analyze index ij_binary"] ["start time"=2023/09/14 18:51:23.068 +08:00] ["end time"=2023/09/14 18:51:23.137 +08:00] [cost=68.789353ms] ["sample rate reason"=]
[2023/09/14 18:51:23.151 +08:00] [INFO] [analyze.go:625] ["analyze table `test`.`t` has finished"] [partition=] ["job info"="analyze index ij_char"] ["start time"=2023/09/14 18:51:23.069 +08:00] ["end time"=2023/09/14 18:51:23.149 +08:00] [cost=80.203902ms] ["sample rate reason"=] 

Notice L1 and L7. Looks like the same analyze job is "finished" twice.
On my machine, I can't reproduce this failure.
I'll add some logs to analyze job-related operations for the test case.

[time-and-fate]

/severity minor

[hawkingrei]

If we cannot see this problem in the next month. we will close it.

[wuhuizuo]

/component test