flaky test TestAnalyzeMVIndex

hawkingrei commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

/severity minor

hawkingrei commented 1 year ago

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

wuhuizuo commented 2 weeks ago

/component test

pingcap / tidb