[Bug]: eks bvt regression： the same sql and statement_id log records in statement_info are greater than 1

[heni02]

Is there an existing issue for the same bug?

• I have checked the existing issues.

Environment

- Version or commit-id (e.g. v0.1.0 or 8b23a93):nightly-3ca7054
- Hardware parameters:
- OS type:
- Others:

Actual Behavior

job: https://github.com/matrixorigin/mo-nightly-regression/actions/runs/5189483136/jobs/9354645167

Expected Behavior

No response

Steps to Reproduce

No response

Additional information

No response

[volgariver6]

@xzxiong please check this issue.

[xzxiong]

log status:

1. cn0.log and cn1.log missed log before 2023-06-06 14:13:08
2. mo data on eks already deleted
3. at 2023/06/06 14:15:13.064264 do run ETLMerge task.

[xzxiong]

root cause

this is client-timeout while do txn commit:
do commit in open txn and meet timeout before commit exec, BUT the txn will commit successed.
==> then DB in pending status

op trace:

	mo	time
t0		// connect mo with timeout: 2 seconds
t1		begin
t2		insert into user_info(name, create_time) values ("jacksonxie", "2023-06-07 17:26:21")
t3	insert with id: 20002	// got LastInsertId: 20002
t4		commit
t5	// manually wait 3 second	-- got timeout in 2 seconds

query test_txn.user_info found out that: id: 20002already in table.

mysql> select * from user_info order by id;
+-------+------------+---------------------+
| id    | name       | create_time         |
+-------+------------+---------------------+
|     1 | jacksonxie | 2023-06-07 15:10:41 |
|     2 | jacksonxie | 2023-06-07 15:10:44 |
|     3 | jacksonxie | 2023-06-07 15:10:46 |
|     4 | jacksonxie | 2023-06-07 15:11:02 |
|     5 | jacksonxie | 2023-06-07 15:13:36 |
| 10001 | jacksonxie | 2023-06-07 17:12:37 |
| 20001 | jacksonxie | 2023-06-07 17:24:30 |
| 20002 | jacksonxie | 2023-06-07 17:26:21 |
+-------+------------+---------------------+
8 rows in set (0.01 sec)

repro step

• mo debug code
  https://github.com/xzxiong/matrixone/tree/debug_double_stm

	case *tree.CommitTransaction:
+		if ses.GetDatabaseName() == "test_txn" {
+			time.Sleep(3 * time.Second)
+		}
		err = ses.TxnCommit()
		if err != nil {
			return err
		}

• test code
  code.tgz
  run out with error, run: tar zxfv code.tgz && cd code && make run

2023/06/07 17:26:20.663970 +0800 INFO init log
2023/06/07 17:26:20.664166 +0800 INFO conn dsn: dump:111@tcp(127.0.0.1:6001)/test_txn?parseTime=true&loc=Local&readTimeout=1s&writeTimeout=1s&timeout=1s&maxAllowedPacket=16777216
2023/06/07 17:26:20.764385 +0800 INFO success insert id: 20002, affect: 1
2023/06/07 17:26:21.764635 +0800 ERROR mysql read tcp 127.0.0.1:65430->127.0.0.1:6001: i/o timeout
main.(*MysqlLogger).Print
        /Users/jacksonxie/go/src/github.com/jacksonxie/db/mysql.go:21
github.com/go-sql-driver/mysql.(*mysqlConn).readPacket
        /Users/jacksonxie/go/pkg/mod/github.com/go-sql-driver/[email protected]/packets.go:37
github.com/go-sql-driver/mysql.(*mysqlConn).readResultSetHeaderPacket
        /Users/jacksonxie/go/pkg/mod/github.com/go-sql-driver/[email protected]/packets.go:538
github.com/go-sql-driver/mysql.(*mysqlConn).exec
        /Users/jacksonxie/go/pkg/mod/github.com/go-sql-driver/[email protected]/connection.go:334
github.com/go-sql-driver/mysql.(*mysqlTx).Commit
        /Users/jacksonxie/go/pkg/mod/github.com/go-sql-driver/[email protected]/transaction.go:19
database/sql.(*Tx).Commit.func1
        /usr/local/go/src/database/sql/sql.go:2268
database/sql.withLock
        /usr/local/go/src/database/sql/sql.go:3405
database/sql.(*Tx).Commit
        /usr/local/go/src/database/sql/sql.go:2267
main.accessDBTxnTimeout
        /Users/jacksonxie/go/src/github.com/jacksonxie/db/main.go:367
main.main
        /Users/jacksonxie/go/src/github.com/jacksonxie/db/main.go:412
runtime.main
        /usr/local/go/src/runtime/proc.go:250
2023/06/07 17:26:21.764914 +0800 ERROR commit failed: invalid connection
main.accessDBTxnTimeout
        /Users/jacksonxie/go/src/github.com/jacksonxie/db/main.go:369
main.main
        /Users/jacksonxie/go/src/github.com/jacksonxie/db/main.go:412
runtime.main
        /usr/local/go/src/runtime/proc.go:250
2023/06/07 17:26:21.764961 +0800 INFO Done ON 127.0.0.1:6001
20230607.172621.764963

[xzxiong]

not sure how to fix
proposal:

1. mo should sense the connection status
2. mo commit op should sucess in 3 sec.
3. etl sql write should mark those files which is meet commit timeout.

[xzxiong]

still try to repro.

[xzxiong]

important one CI result https://github.com/xzxiong/matrixone/actions/runs/5218093671

• show there is NO op commit failed.

[xzxiong]

important CI job: https://github.com/xzxiong/matrixone/actions/runs/5239279033/jobs/9462419306
collect great infos.

[xzxiong]

@gavinyue ptal

[gavinyue]

Will fix this along with new insert change.

[gavinyue]

pending on #9834

[gavinyue]

#10090 一起处理

[gavinyue]

Looking into this today

[gavinyue]

pending on the stmt_aggr merge

[gavinyue]

Pending for the stmt_aggr pr merge. Stuck on dn oom

[gavinyue]

Merged the PR for stmt_aggr. Close this issue.

[xzxiong]

important CI job: https://github.com/xzxiong/matrixone/actions/runs/5239279033/jobs/9462419306 collect great infos.

@gavinyue ptal
in db_holder.go, there still has problem between calling bulkInsert and context.Done()

matrixone/pkg/util/export/etl/db/db_holder.go

Line 187 in dacfe86

go bulkInsert(ctx, done, dbConn, records, tbl, MaxInsertLen, MiddleInsertLen)

[gavinyue]

Start coding this. ETA 27th

[gavinyue]

Pr draft is ready

[gavinyue]

PR is ready for review

[gavinyue]

Should be resolved after the #10302 merged

[heni02]

The problem is not easy to reproduce in the case. After reviewing the eks regression results for the past 3 days, no issues were found. Please close it first
he past 3 days eks bvt regression：
https://github.com/matrixorigin/matrixone/actions/runs/5434137867/jobs/9882428023
https://github.com/matrixorigin/matrixone/actions/runs/5439585269/jobs/9891842672
https://github.com/matrixorigin/matrixone/actions/runs/5430403710/jobs/9876190235