Server query timeout lead to data loss

[jarrydlee]

Running v1.0.48 (also reproduced on v1.0.49)
5.7.25-28-log Percona Server (GPL)

Problem

After running a migration we saw a significant amount of dataloss which resulted in rolling back to the previous table.

Debugging

When looking through the gh-ost logs to try to determine what exactly had happened, I came across this.

19:45:31.422 - Copy: 17051612/298133316 5.7%; Applied: 57018; Backlog: 1000/1000; Time: 2h29m30s(total), 2h29m30s(copy); streamer: vt-0153850400-bin.013298:1024625; State: migrating; ETA: 41h4m25s
19:45:45.178 - INFO Row copy complete
19:45:45.179 - INFO executing gh-ost-on-before-cut-over hook: <path>
19:45:45.179 - Copy: 17051612/17051612 100.0%; Applied: 57018; Backlog: 997/1000; Time: 2h29m44s(total), 2h29m43s(copy); streamer: vt-0153850400-bin.013298:1037048; State: migrating; ETA: due
19:45:45.855 - [info] binlogsyncer.go:723 rotate to (vt-0153850400-bin.013299, 4)
19:45:45.855 - [info] binlogsyncer.go:723 rotate to (vt-0153850400-bin.013299, 4)
19:45:46.422 - Copy: 17051612/17051612 100.0%; Applied: 57448; Backlog: 1000/1000; Time: 2h29m45s(total), 2h29m43s(copy); streamer: vt-0153850400-bin.013298:2109787; State: postponing cut-over; ETA: due
19:45:46.963 - [error] binlogsyncer.go:631 connection was bad
19:45:47.963 - [info] binlogsyncer.go:573 begin to re-sync from (vt-0153850400-bin.013299, 1102571)
19:45:47.963 - [info] binlogsyncer.go:203 register slave for master server 172.16.172.155:3306
19:45:47.964 - [info] binlogsyncer.go:237 kill last connection id 290712
19:45:47.964 - [error] binlogsyncer.go:231 kill connection 290712 error ERROR 1094 (HY000): Unknown thread id: 290712
19:45:47.968 - [info] binlogsyncer.go:723 rotate to (vt-0153850400-bin.013299, 1102571)

As you can see, we jumped from 5.7% complete, 41hours remaining, and 17_051_612/298_133_316 rows copied, to complete/postponing cutover in just 15seconds. This table has ~300million rows.

Reproducing

After a bit of debugging, I noticed that we had some 300second (our server execution timeout) queries which were timed out by the server milliseconds before the copying "completed". I then set SET GLOBAL MAX_EXECUTION_TIME=1; on a test database so that any select would instantly timeout and reran gh-ost against that test DB. This instantly marked the migration as postponing cutover. This table has 100k rows in it.

Copy: 0/0 100.0%; Applied: 0; Backlog: 0/1000; Time: 2m25s(total), 1s(copy); streamer: vt-0059014500-bin.012257:233423; State: postponing cut-over; ETA: due

---

gh-ost
-assume-rbr
-max-load=Threads_running=100
-critical-load=Threads_running=1000
-verbose
-initially-drop-ghost-table
-initially-drop-old-table
-hooks-path=/usr/local/bin/hooks
-postpone-cut-over-flag-file=/tmp/ghost-cutover-postpone
-throttle-control-replicas="REPLICA_HOSTS"
-serve-socket-file=/tmp/gh-ost.sock
-approve-renamed-columns
-database="KEYSPACE"
-table="TABLE"
-host="HOST"
-conf="MYSQL_CONF_PATH"
-alter="ALTER"
-exact-rowcount
-debug
-execute

---

I looked into this a little further and it looks like the go-sql-driver used by gh-ost just doesn't handle server timeouts and instead treats them as an empty resultset, which signifies there is nothing left to copy since hasFurtherRange remains false if there are no rows [1].

[1]

gh-ost/go/logic/applier.go

Lines 413 to 454 in a8fae98

	func (this *Applier) CalculateNextIterationRangeEndValues() (hasFurtherRange bool, err error) {
	this.migrationContext.MigrationIterationRangeMinValues = this.migrationContext.MigrationIterationRangeMaxValues
	if this.migrationContext.MigrationIterationRangeMinValues == nil {
	this.migrationContext.MigrationIterationRangeMinValues = this.migrationContext.MigrationRangeMinValues
	}
	for i := 0; i < 2; i++ {
	buildFunc := sql.BuildUniqueKeyRangeEndPreparedQueryViaOffset
	if i == 1 {
	buildFunc = sql.BuildUniqueKeyRangeEndPreparedQueryViaTemptable
	}
	query, explodedArgs, err := buildFunc(
	this.migrationContext.DatabaseName,
	this.migrationContext.OriginalTableName,
	&this.migrationContext.UniqueKey.Columns,
	this.migrationContext.MigrationIterationRangeMinValues.AbstractValues(),
	this.migrationContext.MigrationRangeMaxValues.AbstractValues(),
	atomic.LoadInt64(&this.migrationContext.ChunkSize),
	this.migrationContext.GetIteration() == 0,
	fmt.Sprintf("iteration:%d", this.migrationContext.GetIteration()),
	)
	if err != nil {
	return hasFurtherRange, err
	}
	rows, err := this.db.Query(query, explodedArgs...)
	if err != nil {
	return hasFurtherRange, err
	}
	iterationRangeMaxValues := sql.NewColumnValues(this.migrationContext.UniqueKey.Len())
	for rows.Next() {
	if err = rows.Scan(iterationRangeMaxValues.ValuesPointers...); err != nil {
	return hasFurtherRange, err
	}
	hasFurtherRange = true
	}
	if hasFurtherRange {
	this.migrationContext.MigrationIterationRangeMaxValues = iterationRangeMaxValues
	return hasFurtherRange, nil
	}
	}
	log.Debugf("Iteration complete: no further range to iterate")
	return hasFurtherRange, nil
	}

[shlomi-noach]

@jarrydlee thank you for this elaborate analysis. To the best of your understanding, if timeout occurs, the driver does not even return error?

[jarrydlee]

That's correct, and it appears that the result of this line [1] will be an empty rows variable as a result. Additionally I wrote a program that would repro the issue using the go-sql-driver that gh-ost is bundled with [2].

[1]

gh-ost/go/logic/applier.go

Line 436 in a8fae98

rows, err := this.db.Query(query, explodedArgs...)

[2] This table had 100k rows in it. The db has SET GLOBAL MAX_EXECUTION_TIME=1; set

package main

import (
	gosql "database/sql"
	"fmt"
	"time"
	_ "github.com/go-sql-driver/mysql"
)

func main() {
	if db, err := gosql.Open("mysql", "<user>@<ip>/<db>"); err == nil {
		start := time.Now()
		rows, err1 := db.Query("SELECT * FROM table")

		t := time.Now()
		elapsed := t.Sub(start)
		fmt.Println(elapsed)

		if err1 != nil { // This is false
			fmt.Printf("%s", err1.Error())
		}

		fmt.Printf("%+v", rows) // This is empty

	}
}

[shlomi-noach]

Thank you again!

[shlomi-noach]

@jarrydlee I wonder if you're able to test #823

steps would be (assuming you have docker):

cd /tmp
git clone git@github.com:github/gh-ost.git
cd gh-ost/
git checkout update-go-sql-driver-2020-02
script/dock pkg /tmp

then use binary generated in /tmp

without docker (requires go1.12 or above):

cd /tmp
git clone git@github.com:github/gh-ost.git
cd gh-ost/
script/build
bin/gh-ost

[jarrydlee]

I built the binary using the first set of steps and ran against my test db again with the same results

Copy: 0/252515514 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: vt-0816009501-bin.014018:15800; Lag: 0.02s, State: migrating; ETA: N/A
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: vt-0816009501-bin.014018:15800; Lag: 0.02s, State: migrating; ETA: due

[shlomi-noach]

I appreciate it. I don't have an immediate solution.

[shlomi-noach]

I'm unable to reproduce this. If I SET GLOBAL MAX_EXECUTION_TIME=1 before migration begins, I immediately get:

2020-02-16 12:20:29 ERROR Error 3024: Query execution was interrupted, maximum statement execution time exceeded
2020-02-16 12:20:29 FATAL Error 3024: Query execution was interrupted, maximum statement execution time exceeded

If I SET GLOBAL MAX_EXECUTION_TIME=1 while migration is running (testing on a 1M rows table), then gh-ost already reuses existing connections for which the SESSION value is unlimited.

Trying to understand how you were able to reproduce this?

[shlomi-noach]

@jarrydlee since I'm still unable to reproduce, can you please:

• Use Support --mysql-timeout flag #824
• Add --mysql-timeout=<value>

where <value> would be:

• 5
• 10
• 60

and let me know what happens?

[jarrydlee]

@shlomi-noach still seeing the same issues on our end. I'm going to spend today trying out different configurations locally to hopefully be able to see the timeouts. I'll keep you updated when I have more.

[jarrydlee]

I'm still unable to reproduce your results. Here is how I tested locally, so hopefully you can reproduce my results.
This is all run on macOS mojave with docker 2.1.0.5

docker network create groupnet

echo 'Creating nodes'
for N in 1 2 3
do docker run -d --name=node$N --net=groupnet --hostname=node$N \
  -v $PWD/d$N:/var/lib/mysql -e MYSQL_ROOT_PASSWORD=mypass \
  mysql/mysql-server:5.7.29 \
  --server-id=$N \
  --log-bin='mysql-bin-1.log' \
  --enforce-gtid-consistency='ON' \
  --log-slave-updates='ON' \
  --gtid-mode='ON' \
  --transaction-write-set-extraction='XXHASH64' \
  --binlog-checksum='NONE' \
  --master-info-repository='TABLE' \
  --relay-log-info-repository='TABLE' \
  --plugin-load='group_replication.so' \
  --relay-log-recovery='ON' \
  --loose-group-replication-single-primary-mode='ON' \
  --loose-group-replication-enforce-update-everywhere-checks='OFF'
done

then

echo 'Creating replication user and setting global timeout'
docker exec -it node1 mysql -uroot -pmypass \
  -e "CREATE USER 'replication'@'%' IDENTIFIED BY 'replication';" \
  -e "GRANT REPLICATION SLAVE ON *.* TO 'replication'@'%';" \
  -e "SET GLOBAL MAX_EXECUTION_TIME=1;";

echo 'Starting slaves'
for N in 2 3
do docker exec -it node$N mysql -uroot -pmypass \
  -e "CHANGE MASTER TO MASTER_HOST='node1', MASTER_USER='replication', MASTER_PASSWORD='replication', MASTER_LOG_FILE='mysql-bin.000001', MASTER_LOG_POS=1;" \
  -e "START SLAVE;" \
  -e "SHOW SLAVE STATUS;"
done

echo 'Creating database/table with 1 row'
docker exec -it node1 mysql -uroot -pmypass \
  -e "create database testing; use testing; CREATE TABLE t1 (id INT NOT NULL PRIMARY KEY) ENGINE=InnoDB; show tables;INSERT INTO testing.t1 VALUES(1);"

then I created another container in the same network

docker run -dit --name=node4 --net=groupnet --hostname=node4 ubuntu:18.04

and copied the 1.0.48 gh-ost binary into node4 and ran using

/tmp/gh-ost
  -assume-rbr
  -max-load=Threads_running=100
  -critical-load=Threads_running=1000
  -verbose
  -initially-drop-ghost-table
  -initially-drop-old-table
  -postpone-cut-over-flag-file=/tmp/ghost-cutover-postpone
  -serve-socket-file=/tmp/gh-ost.sock
  -approve-renamed-columns
  -database=testing
  -table=t1
  -host=node3
  -conf=/etc/mysql/mysql.conf
  -alter="ADD COLUMN newCol INT NULL;"
  -exact-rowcount
  -debug
  -execute

[jarrydlee]

@shlomi-noach just checking in to see if you've been able to recreate this with the steps above, or if there is any other info you need from me.

[shlomi-noach]

Hi @jarrydlee, I’m sorry. I’m on time off right now and do not expect to be working on this, at least for the next several weeks.

[jarrydlee]

No worries, thanks for the quick response.