Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Don't allow reading a snapshot with the timestamp greater than the current max timestamp #25680

Closed
youjiali1995 opened this issue Jun 22, 2021 · 4 comments · Fixed by #25732
Closed
Assignees
Labels
severity/major sig/transaction SIG:Transaction type/bug This issue is a bug.

Comments

@youjiali1995
Copy link
Contributor

youjiali1995 commented Jun 22, 2021

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

TiDB can read data with a user-defined timestamp(using tidb_snapshot or stale-read) which may be greater than the current max timestamp in PD. It can update the max_ts in TiKV and the async-commit transaction may commit data with the version which is greater than the next timestamp in PD, so the following transactions can't read it which means the transaction isolation is broken.

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

TiDB doesn't allow setting snapshot with the version which is greater than the current max version.

3. What did you see instead (Required)

mysql root@127.0.0.1:test> set @@tidb_snapshot = '2022-06-24 16:59:02';
Query OK, 0 rows affected
Time: 0.022s

4. What is your TiDB version? (Required)

v5.0.0-v5.0.2

@youjiali1995 youjiali1995 added type/bug This issue is a bug. sig/transaction SIG:Transaction labels Jun 22, 2021
@youjiali1995 youjiali1995 self-assigned this Jun 23, 2021
@NingLin-P
Copy link
Contributor

NingLin-P commented Jun 23, 2021

For stale read, which required read_ts >= resolved_ts, using a timestamp greater than the current max timestamp as the read_ts of a stale read transaction will result in TiKV keep report DataIsNotReady error and TiDB backoff retry until the resolved_ts is catch up with read_ts. The resolved_ts is allocated from PD, it shouldn't greater than the current max timestamp.

There is a pitfall that if TiDB forgets to set the stale_read flag in a stale read request, TiKV will treat the request like tidb_snapshot request.

@nolouch
Copy link
Member

nolouch commented Jun 23, 2021

may tikv/tikv#10443

@sticnarf sticnarf assigned sticnarf and unassigned youjiali1995 Jun 24, 2021
@zyguan
Copy link
Contributor

zyguan commented Jun 24, 2021

@NingLin-P @nolouch @sticnarf It seems stale_read flag is not set properly when using prepared statement, here is the case.

package main

import (
	"bytes"
	"context"
	"database/sql"
	"log"
	"net/http"
	"time"

	_ "github.com/go-sql-driver/mysql"
)

const (
	dsn = "root:@tcp(172.16.4.180:31126)/test"
	api = "http://172.16.4.180:30906/fail/"
)

func panicOnErr(err error) {
	if err != nil {
		panic(err)
	}
}

func enablePauseBeforeCommit() {
	req, err := http.NewRequest(http.MethodPut, api+"github.com/pingcap/tidb/store/tikv/beforeCommit", bytes.NewBufferString("pause"))
	panicOnErr(err)
	_, err = http.DefaultClient.Do(req)
	panicOnErr(err)
}

func disablePauseBeforeCommit() {
	req, err := http.NewRequest(http.MethodDelete, api+"github.com/pingcap/tidb/store/tikv/beforeCommit", nil)
	panicOnErr(err)
	_, err = http.DefaultClient.Do(req)
	panicOnErr(err)
}

func main() {
	disablePauseBeforeCommit()

	ctx := context.Background()

	log.Printf("init %s", dsn)
	db, err := sql.Open("mysql", dsn)
	panicOnErr(err)
	_, err = db.Exec("drop table if exists t")
	panicOnErr(err)
	_, err = db.Exec("create table t (a int, b int, primary key (a))")
	panicOnErr(err)
	_, err = db.Exec("insert into t values (1, 10), (2, 20), (3, 30)")
	panicOnErr(err)

	c1, err := db.Conn(ctx)
	panicOnErr(err)
	c2, err := db.Conn(ctx)
	panicOnErr(err)

	_, err = c1.ExecContext(ctx, "set @@tidb_enable_async_commit = 0, @@tidb_enable_1pc = 0")
	panicOnErr(err)

	log.Printf("start tx1")
	_, err = c1.ExecContext(ctx, "begin")
	panicOnErr(err)
	_, err = c1.ExecContext(ctx, "delete from t where a = 1")
	panicOnErr(err)
	_, err = c1.ExecContext(ctx, "insert into t values (1, 11)")
	panicOnErr(err)

	log.Printf("enable failpoint")
	enablePauseBeforeCommit()

	commitDone := make(chan struct{})
	go func() {
		defer close(commitDone)
		log.Printf("commit tx1")
		_, err = c1.ExecContext(ctx, "commit")
		panicOnErr(err)
		log.Printf("tx1 committed")
	}()

	time.Sleep(time.Second)
	log.Printf("start tx2")
	_, err = c2.ExecContext(ctx, "start transaction read only as of timestamp date_add(now(), interval 5 second)")
	panicOnErr(err)
	stmt, err := c2.PrepareContext(ctx, "select sum(a) from t where a < ?")
	panicOnErr(err)
	_, err = stmt.Exec(3)
	panicOnErr(err)

	log.Printf("disable failpoint")
	disablePauseBeforeCommit()

	log.Printf("rollback tx2")
	_, err = c2.ExecContext(ctx, "rollback")
	panicOnErr(err)
	log.Printf("tx2 rollbacked")

	<-commitDone
	log.Printf("done")
}

and here is the log.

2021/06/24 04:17:33 init root:@tcp(172.16.4.180:31126)/test
2021/06/24 04:17:33 start tx1
2021/06/24 04:17:33 enable failpoint
2021/06/24 04:17:33 commit tx1
2021/06/24 04:17:34 start tx2
2021/06/24 04:17:34 disable failpoint
2021/06/24 04:17:34 rollback tx2
2021/06/24 04:17:34 tx2 rollbacked
2021/06/24 04:17:38 tx1 committed
2021/06/24 04:17:38 done
[2021/06/24 04:16:38.862 +00:00] [INFO] [session.go:2817] [GENERAL_LOG] [conn=365] [user=root@172.18.219.0] [schemaVersion=467] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=] [txn_mode=PESSIMISTIC] [sql="use `test`"]
[2021/06/24 04:16:38.863 +00:00] [INFO] [session.go:2817] [GENERAL_LOG] [conn=363] [user=root@172.18.219.0] [schemaVersion=467] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=test] [txn_mode=PESSIMISTIC] [sql="set @@tidb_enable_async_commit = 0, @@tidb_enable_1pc = 0"]
[2021/06/24 04:16:38.864 +00:00] [INFO] [session.go:2817] [GENERAL_LOG] [conn=363] [user=root@172.18.219.0] [schemaVersion=467] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=test] [txn_mode=PESSIMISTIC] [sql=begin]
[2021/06/24 04:16:38.864 +00:00] [INFO] [session.go:2817] [GENERAL_LOG] [conn=363] [user=root@172.18.219.0] [schemaVersion=467] [txnStartTS=425855077269897226] [forUpdateTS=425855077269897226] [isReadConsistency=false] [current_db=test] [txn_mode=PESSIMISTIC] [sql="delete from t where a = 1"]
[2021/06/24 04:16:38.866 +00:00] [INFO] [session.go:2817] [GENERAL_LOG] [conn=363] [user=root@172.18.219.0] [schemaVersion=467] [txnStartTS=425855077269897226] [forUpdateTS=425855077269897226] [isReadConsistency=false] [current_db=test] [txn_mode=PESSIMISTIC] [sql="insert into t values (1, 11)"]
[2021/06/24 04:16:38.869 +00:00] [INFO] [session.go:2817] [GENERAL_LOG] [conn=363] [user=root@172.18.219.0] [schemaVersion=467] [txnStartTS=425855077269897226] [forUpdateTS=425855077269897226] [isReadConsistency=false] [current_db=test] [txn_mode=PESSIMISTIC] [sql=commit]
[2021/06/24 04:16:39.870 +00:00] [INFO] [session.go:2817] [GENERAL_LOG] [conn=365] [user=root@172.18.219.0] [schemaVersion=467] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=test] [txn_mode=PESSIMISTIC] [sql="start transaction read only as of timestamp date_add(now(), interval 5 second)"]
[2021/06/24 04:16:39.872 +00:00] [INFO] [session.go:2817] [GENERAL_LOG] [conn=365] [user=root@172.18.219.0] [schemaVersion=467] [txnStartTS=425855078629376000] [forUpdateTS=425855078629376000] [isReadConsistency=false] [current_db=test] [txn_mode=PESSIMISTIC] [sql="select sum(a) from t where a < ? [arguments: 3]"]
[2021/06/24 04:16:39.872 +00:00] [INFO] [distsql.go:81] [">>> send cop req"] [conn=365] [start-ts=425855078629376000] [stale=false] [stack="github.com/pingcap/tidb/distsql.Select\n\t/home/zyguan/pingcap/tidb/distsql/distsql.go:81\ngithub.com/pingcap/tidb/distsql.SelectWithRuntimeStats\n\t/home/zyguan/pingcap/tidb/distsql/distsql.go:132\ngithub.com/pingcap/tidb/executor.selectResultHook.SelectResult\n\t/home/zyguan/pingcap/tidb/executor/table_reader.go:51\ngithub.com/pingcap/tidb/executor.(*TableReaderExecutor).buildResp\n\t/home/zyguan/pingcap/tidb/executor/table_reader.go:303\ngithub.com/pingcap/tidb/executor.(*TableReaderExecutor).Open\n\t/home/zyguan/pingcap/tidb/executor/table_reader.go:197\ngithub.com/pingcap/tidb/executor.(*baseExecutor).Open\n\t/home/zyguan/pingcap/tidb/executor/executor.go:169\ngithub.com/pingcap/tidb/executor.(*StreamAggExec).Open\n\t/home/zyguan/pingcap/tidb/executor/aggregate.go:1104\ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/home/zyguan/pingcap/tidb/executor/adapter.go:387\ngithub.com/pingcap/tidb/session.runStmt\n\t/home/zyguan/pingcap/tidb/session/session.go:1653\ngithub.com/pingcap/tidb/session.(*session).preparedStmtExec\n\t/home/zyguan/pingcap/tidb/session/session.go:1790\ngithub.com/pingcap/tidb/session.(*session).ExecutePreparedStmt\n\t/home/zyguan/pingcap/tidb/session/session.go:1951\ngithub.com/pingcap/tidb/server.(*TiDBStatement).Execute\n\t/home/zyguan/pingcap/tidb/server/driver_tidb.go:73\ngithub.com/pingcap/tidb/server.(*clientConn).executePreparedStmtAndWriteResult\n\t/home/zyguan/pingcap/tidb/server/conn_stmt.go:228\ngithub.com/pingcap/tidb/server.(*clientConn).handleStmtExecute\n\t/home/zyguan/pingcap/tidb/server/conn_stmt.go:208\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/zyguan/pingcap/tidb/server/conn.go:1120\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/zyguan/pingcap/tidb/server/conn.go:860\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/zyguan/pingcap/tidb/server/server.go:482"]
[2021/06/24 04:16:39.874 +00:00] [INFO] [lock_resolver.go:574] [">>> txn-id: 425855077269897226, caller-start-ts: 425855078629376000, current-ts: 425855077453398018"]
[2021/06/24 04:16:39.878 +00:00] [INFO] [session.go:2817] [GENERAL_LOG] [conn=365] [user=root@172.18.219.0] [schemaVersion=467] [txnStartTS=425855078629376000] [forUpdateTS=425855078629376000] [isReadConsistency=false] [current_db=test] [txn_mode=PESSIMISTIC] [sql=rollback]
[2021/06/24 04:16:39.878 +00:00] [INFO] [commit.go:115] ["2PC commitTS rejected by TiKV, retry with a newer commitTS"] [txnStartTS=425855077269897226] [info="{StartTs:425855077269897226 AttemptedCommitTs:425855077283004417 Key:74800000000000017f5f728000000000000001 MinCommitTs:425855078629376001}"]
[2021/06/24 04:16:39.879 +00:00] [INFO] [commit.go:115] ["2PC commitTS rejected by TiKV, retry with a newer commitTS"] [txnStartTS=425855077269897226] [info="{StartTs:425855077269897226 AttemptedCommitTs:425855077545410562 Key:74800000000000017f5f728000000000000001 MinCommitTs:425855078629376001}"]
[2021/06/24 04:16:39.879 +00:00] [INFO] [commit.go:115] ["2PC commitTS rejected by TiKV, retry with a newer commitTS"] [txnStartTS=425855077269897226] [info="{StartTs:425855077269897226 AttemptedCommitTs:425855077545410563 Key:74800000000000017f5f728000000000000001 MinCommitTs:425855078629376001}"]
[2021/06/24 04:16:39.880 +00:00] [INFO] [commit.go:115] ["2PC commitTS rejected by TiKV, retry with a newer commitTS"] [txnStartTS=425855077269897226] [info="{StartTs:425855077269897226 AttemptedCommitTs:425855077545410564 Key:74800000000000017f5f728000000000000001 MinCommitTs:425855078629376001}"]
[2021/06/24 04:16:39.881 +00:00] [INFO] [commit.go:115] ["2PC commitTS rejected by TiKV, retry with a newer commitTS"] [txnStartTS=425855077269897226] [info="{StartTs:425855077269897226 AttemptedCommitTs:425855077545410565 Key:74800000000000017f5f728000000000000001 MinCommitTs:425855078629376001}"]
[2021/06/24 04:16:39.882 +00:00] [INFO] [commit.go:115] ["2PC commitTS rejected by TiKV, retry with a newer commitTS"] [txnStartTS=425855077269897226] [info="{StartTs:425855077269897226 AttemptedCommitTs:425855077545410566 Key:74800000000000017f5f728000000000000001 MinCommitTs:425855078629376001}"]
[2021/06/24 04:16:39.883 +00:00] [INFO] [commit.go:115] ["2PC commitTS rejected by TiKV, retry with a newer commitTS"] [txnStartTS=425855077269897226] [info="{StartTs:425855077269897226 AttemptedCommitTs:425855077545410567 Key:74800000000000017f5f728000000000000001 MinCommitTs:425855078629376001}"]
[2021/06/24 04:16:39.884 +00:00] [INFO] [commit.go:115] ["2PC commitTS rejected by TiKV, retry with a newer commitTS"] [txnStartTS=425855077269897226] [info="{StartTs:425855077269897226 AttemptedCommitTs:425855077545410568 Key:74800000000000017f5f728000000000000001 MinCommitTs:425855078629376001}"]
[2021/06/24 04:16:39.884 +00:00] [INFO] [commit.go:115] ["2PC commitTS rejected by TiKV, retry with a newer commitTS"] [txnStartTS=425855077269897226] [info="{StartTs:425855077269897226 AttemptedCommitTs:425855077545410569 Key:74800000000000017f5f728000000000000001 MinCommitTs:425855078629376001}"]

@ti-srebot
Copy link
Contributor

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

Not a bug

  1. Remove the 'type/bug' label
  2. Add notes to indicate why it is not a bug

Duplicate bug

  1. Add the 'type/duplicate' label
  2. Add the link to the original bug

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)

2. Symptom (optional)

3. All Trigger Conditions (optional)

4. Workaround (optional)

5. Affected versions

6. Fixed versions

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
severity/major sig/transaction SIG:Transaction type/bug This issue is a bug.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants