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

TiFlash cannot read from normal table after insert and being available on arm64 / mac m1 #6659

Closed
mjonss opened this issue Jan 19, 2023 · 13 comments
Labels
severity/minor type/bug The issue is confirmed as a bug.

Comments

@mjonss
Copy link
Contributor

mjonss commented Jan 19, 2023

Bug Report

Please answer these questions before submitting your issue. Thanks!

I cannot do select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t on my macbook air m1 (on Linux x86_64 it works)

1. Minimal reproduce step (Required)

Start a playground cluster:

tiup playground nightly --db 2 --kv 3 --pd 3 --tiflash 2

Run these sql statements:

drop table if exists t;
create table t (a int primary key, b varchar(255), c int, key (b), key (c,b));
alter table t set tiflash replica 1;
select sleep(3);
select * from information_schema.tiflash_replica where table_schema = 'test';
insert into t values (1,"1",-1);
set @t := 1;
insert into t select a+@t,a+@t,-(a+@t) from t;
set @t := 2 * @t; 
insert into t select a+@t,a+@t,-(a+@t) from t;
set @t := 500000;
insert into t select a+@t,a+@t,-(a+@t) from t;
set @t := 1000000;
insert into t select a+@t,a+@t,-(a+@t) from t;
select sleep(3);
select * from information_schema.tiflash_replica where table_schema = 'test';
select /*+ READ_FROM_STORAGE(TIKV[t]) */ count(*) from t;
select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t;

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

Answer from TiFlash

3. What did you see instead (Required)

error:

tidb> drop table if exists t;
Query OK, 0 rows affected (0.30 sec)

tidb> create table t (a int primary key, b varchar(255), c int, key (b), key (c,b));
Query OK, 0 rows affected (0.10 sec)

tidb> alter table t set tiflash replica 1;
Query OK, 0 rows affected (0.17 sec)

tidb> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.00 sec)

tidb> select * from information_schema.tiflash_replica where table_schema = 'test';
+--------------+------------+----------+---------------+-----------------+-----------+----------+
| TABLE_SCHEMA | TABLE_NAME | TABLE_ID | REPLICA_COUNT | LOCATION_LABELS | AVAILABLE | PROGRESS |
+--------------+------------+----------+---------------+-----------------+-----------+----------+
| test         | t          |       92 |             1 |                 |         1 |        1 |
+--------------+------------+----------+---------------+-----------------+-----------+----------+
1 row in set (0.00 sec)

tidb> insert into t values (1,"1",-1);
Query OK, 1 row affected (0.01 sec)

tidb> set @t := 1;
Query OK, 0 rows affected (0.00 sec)

tidb> insert into t select a+@t,a+@t,-(a+@t) from t;
Query OK, 1 row affected (0.00 sec)
Records: 1  Duplicates: 0  Warnings: 0

tidb> set @t := 2 * @t; 
Query OK, 0 rows affected (0.00 sec)

tidb> insert into t select a+@t,a+@t,-(a+@t) from t;
Query OK, 2 rows affected (0.00 sec)
Records: 2  Duplicates: 0  Warnings: 0

tidb> set @t := 500000;
Query OK, 0 rows affected (0.00 sec)

tidb> insert into t select a+@t,a+@t,-(a+@t) from t;
Query OK, 4 rows affected (0.00 sec)
Records: 4  Duplicates: 0  Warnings: 0

tidb> set @t := 1000000;
Query OK, 0 rows affected (0.00 sec)

tidb> insert into t select a+@t,a+@t,-(a+@t) from t;
Query OK, 8 rows affected (0.00 sec)
Records: 8  Duplicates: 0  Warnings: 0

tidb> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.00 sec)

tidb> select * from information_schema.tiflash_replica where table_schema = 'test';
+--------------+------------+----------+---------------+-----------------+-----------+----------+
| TABLE_SCHEMA | TABLE_NAME | TABLE_ID | REPLICA_COUNT | LOCATION_LABELS | AVAILABLE | PROGRESS |
+--------------+------------+----------+---------------+-----------------+-----------+----------+
| test         | t          |       92 |             1 |                 |         1 |        1 |
+--------------+------------+----------+---------------+-----------------+-----------+----------+
1 row in set (0.00 sec)

tidb> select /*+ READ_FROM_STORAGE(TIKV[t]) */ count(*) from t;
+----------+
| count(*) |
+----------+
|       16 |
+----------+
1 row in set (0.00 sec)

tidb> select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t;
ERROR 1105 (HY000): [FLASH:Coprocessor:RegionError] Region 121 is unavailable at 17: (while doing learner read for table, logical table_id: 87)

4. What is your TiFlash version? (Required)

From tiup:

Start pd instance:v6.6.0-alpha-nightly-20230119
Start pd instance:v6.6.0-alpha-nightly-20230119
Start pd instance:v6.6.0-alpha-nightly-20230119
Start tikv instance:v6.6.0-alpha-nightly-20230119
Start tikv instance:v6.6.0-alpha-nightly-20230119
Start tikv instance:v6.6.0-alpha-nightly-20230119
Start tidb instance:v6.6.0-alpha-nightly-20230119
Start tidb instance:v6.6.0-alpha-nightly-20230119
Start tiflash instance:v6.6.0-alpha-nightly-20230119
Start tiflash instance:v6.6.0-alpha-nightly-20230119

From information_schema.cluster_info:

+---------+-----------------+-----------------+-------------------+------------------------------------------+----------------------+--------------+-----------+
| TYPE    | INSTANCE        | STATUS_ADDRESS  | VERSION           | GIT_HASH                                 | START_TIME           | UPTIME       | SERVER_ID |
+---------+-----------------+-----------------+-------------------+------------------------------------------+----------------------+--------------+-----------+
| tidb    | 127.0.0.1:4000  | 127.0.0.1:10080 | 6.6.0-alpha       | 8ec2612ba2315592d25d55d54f93a7ecd6bb1e6b | 2023-01-19T00:31:24Z | 2m11.383929s |    469897 |
| tidb    | 127.0.0.1:4001  | 127.0.0.1:10081 | 6.6.0-alpha       | 8ec2612ba2315592d25d55d54f93a7ecd6bb1e6b | 2023-01-19T00:31:24Z | 2m11.383931s |    815569 |
| pd      | 127.0.0.1:2382  | 127.0.0.1:2382  | 6.6.0-alpha       | 082fc6a9bc2e61787f4ecf8e0cbf103bccb13039 | 2023-01-19T00:31:15Z | 2m20.383939s |         0 |
| pd      | 127.0.0.1:2379  | 127.0.0.1:2379  | 6.6.0-alpha       | 082fc6a9bc2e61787f4ecf8e0cbf103bccb13039 | 2023-01-19T00:31:15Z | 2m20.38394s  |         0 |
| pd      | 127.0.0.1:2384  | 127.0.0.1:2384  | 6.6.0-alpha       | 082fc6a9bc2e61787f4ecf8e0cbf103bccb13039 | 2023-01-19T00:31:15Z | 2m20.383941s |         0 |
| tikv    | 127.0.0.1:20162 | 127.0.0.1:20182 | 6.6.0-alpha       | b35d4fb33a18c5be9136c790e01ca449075e6acb | 2023-01-19T00:31:17Z | 2m18.383942s |         0 |
| tikv    | 127.0.0.1:20160 | 127.0.0.1:20180 | 6.6.0-alpha       | b35d4fb33a18c5be9136c790e01ca449075e6acb | 2023-01-19T00:31:17Z | 2m18.383943s |         0 |
| tikv    | 127.0.0.1:20161 | 127.0.0.1:20181 | 6.6.0-alpha       | b35d4fb33a18c5be9136c790e01ca449075e6acb | 2023-01-19T00:31:17Z | 2m18.383943s |         0 |
| tiflash | 127.0.0.1:3930  | 127.0.0.1:20292 | 6.6.0-alpha-dirty | 2dd8483b7ce9656554cd2ba3901f448c2ec0a042 | 2023-01-19T00:31:28Z | 2m7.383944s  |         0 |
| tiflash | 127.0.0.1:3931  | 127.0.0.1:20293 | 6.6.0-alpha-dirty | 2dd8483b7ce9656554cd2ba3901f448c2ec0a042 | 2023-01-19T00:31:28Z | 2m7.383944s  |         0 |
+---------+-----------------+-----------------+-------------------+------------------------------------------+----------------------+--------------+-----------+
@mjonss mjonss added the type/bug The issue is confirmed as a bug. label Jan 19, 2023
@Lloyd-Pottiger
Copy link
Contributor

I fail to reproduce on my mac m1. Can you always get the error?

@Lloyd-Pottiger
Copy link
Contributor

mysql> use test
Database changed
mysql> create table t (a int primary key, b varchar(255), c int, key (b), key (c,b));
Query OK, 0 rows affected (0.16 sec)

mysql> alter table t set tiflash replica 1;
Query OK, 0 rows affected (0.37 sec)

mysql> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.00 sec)

mysql> select * from information_schema.tiflash_replica where table_schema = 'test';
+--------------+------------+----------+---------------+-----------------+-----------+----------+
| TABLE_SCHEMA | TABLE_NAME | TABLE_ID | REPLICA_COUNT | LOCATION_LABELS | AVAILABLE | PROGRESS |
+--------------+------------+----------+---------------+-----------------+-----------+----------+
| test         | t          |       82 |             1 |                 |         1 |        1 |
+--------------+------------+----------+---------------+-----------------+-----------+----------+
1 row in set (0.01 sec)

mysql> insert into t values (1,"1",-1);
Query OK, 1 row affected (0.01 sec)

mysql> set @t := 1;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into t select a+@t,a+@t,-(a+@t) from t;
Query OK, 1 row affected (0.01 sec)
Records: 1  Duplicates: 0  Warnings: 0

mysql> set @t := 2 * @t; 
Query OK, 0 rows affected (0.00 sec)

mysql> insert into t select a+@t,a+@t,-(a+@t) from t;
Query OK, 2 rows affected (0.00 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> set @t := 500000;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into t select a+@t,a+@t,-(a+@t) from t;
Query OK, 4 rows affected (0.00 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql> set @t := 1000000;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into t select a+@t,a+@t,-(a+@t) from t;
Query OK, 8 rows affected (0.00 sec)
Records: 8  Duplicates: 0  Warnings: 0

mysql> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.00 sec)

mysql> select /*+ READ_FROM_STORAGE(TIKV[t]) */ count(*) from t;
+----------+
| count(*) |
+----------+
|       16 |
+----------+
1 row in set (0.00 sec)

mysql> select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t;
+----------+
| count(*) |
+----------+
|       16 |
+----------+
1 row in set (0.01 sec)

@mjonss
Copy link
Contributor Author

mjonss commented Jan 19, 2023

I fail to reproduce on my mac m1. Can you always get the error?

No, not every time, but more than 50%

@Lloyd-Pottiger
Copy link
Contributor

When you get the error, wait for a second, and then rerun select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t;, will you get the error again?

@mjonss
Copy link
Contributor Author

mjonss commented Jan 19, 2023

Yes, I can get the error again.
It seems like it is easier to reproduce if the cluster is newly started.
From the mysql client:

tidb> select * from information_schema.tiflash_replica where table_schema = 'test';
+--------------+------------+----------+---------------+-----------------+-----------+----------+
| TABLE_SCHEMA | TABLE_NAME | TABLE_ID | REPLICA_COUNT | LOCATION_LABELS | AVAILABLE | PROGRESS |
+--------------+------------+----------+---------------+-----------------+-----------+----------+
| test         | t          |       82 |             1 |                 |         1 |        1 |
+--------------+------------+----------+---------------+-----------------+-----------+----------+
1 row in set (0.00 sec)

tidb> select /*+ READ_FROM_STORAGE(TIKV[t]) */ count(*) from t;
+----------+
| count(*) |
+----------+
|       16 |
+----------+
1 row in set (0.00 sec)

tidb> select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t;
ERROR 1105 (HY000): [FLASH:Coprocessor:RegionError] Region 124 is unavailable at 17: (while doing learner read for table, logical table_id: 82)
tidb> select sleep(1);
+----------+
| sleep(1) |
+----------+
|        0 |
+----------+
1 row in set (1.00 sec)

tidb> select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t;
ERROR 1105 (HY000): [FLASH:Coprocessor:RegionError] Region 124 is unavailable at 31: (while doing learner read for table, logical table_id: 82)
tidb> select sleep(60);
+-----------+
| sleep(60) |
+-----------+
|         0 |
+-----------+
1 row in set (1 min 0.02 sec)

tidb> select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t;
ERROR 1105 (HY000): [FLASH:Coprocessor:RegionError] Region 124 is unavailable at 48: (while doing learner read for table, logical table_id: 82)
tidb> 
tidb> select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t;
ERROR 1105 (HY000): [FLASH:Coprocessor:RegionError] Region 124 is unavailable at 75: (while doing learner read for table, logical table_id: 82)

Here are some logs snippets:
tidb.log:

[2023/01/19 10:09:07.076 +00:00] [INFO] [session.go:3815] ["CRUCIAL OPERATION"] [conn=6940770504429011351] [schemaVersion=40] [cur_db=test] [sql="drop table if exists t"] [user=root@%]
[2023/01/19 10:09:07.076 +00:00] [INFO] [session.go:3815] ["CRUCIAL OPERATION"] [conn=6940770504429011351] [schemaVersion=40] [cur_db=test] [sql="create table t (a int primary key, b varchar(255), c int, key (b), key (c,b))"] [user=root@%]
[2023/01/19 10:09:07.081 +00:00] [INFO] [ddl_worker.go:227] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:83, Type:create table, State:queueing, SchemaState:none, SchemaID:2, TableID:82, RowCount:0, ArgLen:2, start time: 2023-01-19 10:09:07.067 +0000 WET, Err:<nil>, ErrCount:0, SnapshotVersion:0; "] [table=true]
[2023/01/19 10:09:07.089 +00:00] [INFO] [ddl.go:973] ["[ddl] start DDL job"] [job="ID:83, Type:create table, State:queueing, SchemaState:none, SchemaID:2, TableID:82, RowCount:0, ArgLen:2, start time: 2023-01-19 10:09:07.067 +0000 WET, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="create table t (a int primary key, b varchar(255), c int, key (b), key (c,b))"]
[2023/01/19 10:09:07.107 +00:00] [INFO] [domain.go:200] ["diff load InfoSchema success"] [currentSchemaVersion=40] [neededSchemaVersion=41] ["start time"=451.916µs] [phyTblIDs="[82]"] [actionTypes="[3]"]
[2023/01/19 10:09:07.150 +00:00] [INFO] [domain.go:744] ["mdl gets lock, update to owner"] [jobID=83] [version=41]
[2023/01/19 10:09:07.590 +00:00] [INFO] [ddl.go:1071] ["[ddl] DDL job is finished"] [jobID=83]
[2023/01/19 10:09:07.593 +00:00] [INFO] [callback.go:121] ["performing DDL change, must reload"]
[2023/01/19 10:09:07.593 +00:00] [INFO] [split_region.go:85] ["split batch regions request"] ["split key count"=1] ["batch count"=1] ["first batch, region ID"=24] ["first split key"=748000000000000052]
[2023/01/19 10:09:07.598 +00:00] [INFO] [session.go:3815] ["CRUCIAL OPERATION"] [conn=6940770504429011351] [schemaVersion=41] [cur_db=test] [sql="alter table t set tiflash replica 1"] [user=root@%]
[2023/01/19 10:09:07.606 +00:00] [INFO] [split_region.go:187] ["batch split regions complete"] ["batch region ID"=24] ["first at"=748000000000000052] ["first new region left"="{Id:120 StartKey:7480000000000000ff5000000000000000f8 EndKey:7480000000000000ff5200000000000000f8 RegionEpoch:{ConfVer:1 Version:46} Peers:[id:121 store_id:1 ] EncryptionMeta:<nil> IsInFlashback:false}"] ["new region count"=1]
[2023/01/19 10:09:07.606 +00:00] [INFO] [split_region.go:236] ["split regions complete"] ["region count"=1] ["region IDs"="[120]"]
[2023/01/19 10:09:07.607 +00:00] [INFO] [ddl_worker.go:227] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:84, Type:set tiflash replica, State:queueing, SchemaState:none, SchemaID:2, TableID:82, RowCount:0, ArgLen:1, start time: 2023-01-19 10:09:07.567 +0000 WET, Err:<nil>, ErrCount:0, SnapshotVersion:0; "] [table=true]
[2023/01/19 10:09:07.619 +00:00] [INFO] [ddl.go:973] ["[ddl] start DDL job"] [job="ID:84, Type:set tiflash replica, State:queueing, SchemaState:none, SchemaID:2, TableID:82, RowCount:0, ArgLen:1, start time: 2023-01-19 10:09:07.567 +0000 WET, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="alter table t set tiflash replica 1"]
[2023/01/19 10:09:07.655 +00:00] [INFO] [domain.go:200] ["diff load InfoSchema success"] [currentSchemaVersion=41] [neededSchemaVersion=42] ["start time"=454.083µs] [phyTblIDs="[]"] [actionTypes="[]"]
[2023/01/19 10:09:07.700 +00:00] [INFO] [domain.go:744] ["mdl gets lock, update to owner"] [jobID=84] [version=42]
[2023/01/19 10:09:08.120 +00:00] [INFO] [ddl.go:1071] ["[ddl] DDL job is finished"] [jobID=84]
[2023/01/19 10:09:08.122 +00:00] [INFO] [callback.go:121] ["performing DDL change, must reload"]
[2023/01/19 10:09:08.805 +00:00] [INFO] [domain.go:200] ["diff load InfoSchema success"] [currentSchemaVersion=42] [neededSchemaVersion=43] ["start time"=382.083µs] [phyTblIDs="[]"] [actionTypes="[]"]
[2023/01/19 10:09:08.850 +00:00] [INFO] [domain.go:744] ["mdl gets lock, update to owner"] [jobID=85] [version=43]
[2023/01/19 10:10:14.221 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=60.073712833s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861287684046851] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:10:52.676 +00:00] [INFO] [domain.go:2403] ["refreshServerIDTTL succeed"] [serverID=3156297] ["lease id"=6f1885c974a990b0]
[2023/01/19 10:11:14.221 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.074099625s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861287684046851] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:12:14.321 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.173765083s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861287684046851] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:13:14.422 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.273835333s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861287684046851] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:14:14.521 +00:00] [INFO] [conn.go:1152] ["command dispatched failed"] [conn=6940770504429011351] [connInfo="id:6940770504429011351, addr:127.0.0.1:55019 status:10, collation:latin1_swedish_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"] [txn_mode=PESSIMISTIC] [timestamp=438861287684046851] [err="[tikv:13][FLASH:Coprocessor:RegionError] Region 124 is unavailable at 17: (while doing learner read for table, logical table_id: 82)"]
[2023/01/19 10:15:15.622 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=60.095738584s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861366694510593] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:15:52.680 +00:00] [INFO] [domain.go:2403] ["refreshServerIDTTL succeed"] [serverID=3156297] ["lease id"=6f1885c974a990b0]
[2023/01/19 10:16:15.722 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.195954167s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861366694510593] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:17:15.822 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.295705709s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861366694510593] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:17:16.598 +00:00] [WARN] [collate.go:221] ["The collation latin1_swedish_ci specified on connection is not supported when new collation is enabled, switch to the default collation: utf8mb4_bin"]
[2023/01/19 10:18:15.923 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.396003417s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861366694510593] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:19:15.534 +00:00] [INFO] [conn.go:1152] ["command dispatched failed"] [conn=6940770504429011351] [connInfo="id:6940770504429011351, addr:127.0.0.1:55019 status:10, collation:latin1_swedish_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"] [txn_mode=PESSIMISTIC] [timestamp=438861366694510593] [err="[tikv:13][FLASH:Coprocessor:RegionError] Region 124 is unavailable at 31: (while doing learner read for table, logical table_id: 82)"]
[2023/01/19 10:20:52.702 +00:00] [INFO] [domain.go:2403] ["refreshServerIDTTL succeed"] [serverID=3156297] ["lease id"=6f1885c974a990b0]
[2023/01/19 10:21:15.645 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=60.0871225s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861461072117761] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:22:15.745 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.187063333s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861461072117761] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:23:15.846 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.287535875s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861461072117761] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:24:15.947 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.387584916s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861461072117761] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:25:15.564 +00:00] [INFO] [conn.go:1152] ["command dispatched failed"] [conn=6940770504429011351] [connInfo="id:6940770504429011351, addr:127.0.0.1:55019 status:10, collation:latin1_swedish_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"] [txn_mode=PESSIMISTIC] [timestamp=438861461072117761] [err="[tikv:13][FLASH:Coprocessor:RegionError] Region 124 is unavailable at 48: (while doing learner read for table, logical table_id: 82)"]
[2023/01/19 10:25:52.705 +00:00] [INFO] [domain.go:2403] ["refreshServerIDTTL succeed"] [serverID=3156297] ["lease id"=6f1885c974a990b0]
[2023/01/19 10:30:40.750 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=60.075207625s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861609211002882] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]
[2023/01/19 10:30:52.708 +00:00] [INFO] [domain.go:2403] ["refreshServerIDTTL succeed"] [serverID=3156297] ["lease id"=6f1885c974a990b0]
[2023/01/19 10:31:40.850 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.174932125s] [stats=t:pseudo] [conn_id=6940770504429011351] [user=root] [database=test] [table_ids="[82]"] [txn_start_ts=438861609211002882] [mem_max="388 Bytes (388 Bytes)"] [sql="select /*+ READ_FROM_STORAGE(TIFLASH[t]) */ count(*) from t"]

tiflash.log (instance 0):

[2023/01/19 10:14:02.772 +00:00] [WARN] [PathCapacityMetrics.cpp:196] ["Available space is only 3.09% of capacity size. Avail size: 14.24 GiB, used size: 396.00 B, capacity size: 460.43 GiB"] [source=PathCapacityMetrics] [thread_id=8]
[2023/01/19 10:14:03.127 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:04.161 +00:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=7]
[2023/01/19 10:14:05.130 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:07.132 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:09.133 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info=lag_region_id=124, leader_safe_ts=438861364859502593, self_safe_ts=438861286818971651; "] [source=operator()] [thread_id=26]
[2023/01/19 10:14:09.180 +00:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=7]
[2023/01/19 10:14:11.135 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:12.778 +00:00] [WARN] [PathCapacityMetrics.cpp:196] ["Available space is only 3.09% of capacity size. Avail size: 14.24 GiB, used size: 396.00 B, capacity size: 460.43 GiB"] [source=PathCapacityMetrics] [thread_id=8]
[2023/01/19 10:14:13.136 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:14.177 +00:00] [WARN] [Region.cpp:559] ["[region 124] wait learner index 17 timeout"] [thread_id=24]
[2023/01/19 10:14:14.210 +00:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=7]
[2023/01/19 10:14:14.520 +00:00] [ERROR] [DAGDriver.cpp:199] ["[FLASH:Coprocessor:RegionError] Region 124 is unavailable at 17: (while doing learner read for table, logical table_id: 82)\n\n     0x100805c10\tStackTrace::StackTrace() [tiflash+4295285776]\n     0x105942148\tDB::doLearnerRead(long long, DB::MvccQueryInfo&, bool, DB::Context&, std::__1::shared_ptr<DB::Logger> const&)::$_1::operator()(unsigned long) const::'lambda'(unsigned long long, unsigned long long)::operator()(unsigned long long, unsigned long long) const [tiflash+4380467528]\n     0x1059403ec\tDB::doLearnerRead(long long, DB::MvccQueryInfo&, bool, DB::Context&, std::__1::shared_ptr<DB::Logger> const&)::$_1::operator()(unsigned long) const [tiflash+4380460012]\n     0x10593edc0\tDB::doLearnerRead(long long, DB::MvccQueryInfo&, bool, DB::Context&, std::__1::shared_ptr<DB::Logger> const&) [tiflash+4380454336]\n     0x105b9615c\tDB::DAGStorageInterpreter::doBatchCopLearnerRead() [tiflash+4382908764]\n     0x105b92a68\tDB::DAGStorageInterpreter::prepare() [tiflash+4382894696]\n     0x105b92a10\tDB::DAGStorageInterpreter::execute(DB::DAGPipeline&) [tiflash+4382894608]\n     0x105c913c4\tDB::PhysicalTableScan::transformImpl(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383937476]\n     0x105c6477c\tDB::PhysicalPlanNode::transform(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383754108]\n     0x105c71168\tDB::PhysicalAggregation::transformImpl(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383805800]\n     0x105c6477c\tDB::PhysicalPlanNode::transform(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383754108]\n     0x105c8e7b8\tDB::PhysicalProjection::transformImpl(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383926200]\n     0x105c6477c\tDB::PhysicalPlanNode::transform(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383754108]\n     0x105c6bcd8\tDB::Planner::executeImpl(DB::DAGPipeline&) [tiflash+4383784152]\n     0x105c6bb38\tDB::Planner::execute() [tiflash+4383783736]\n     0x105b295b4\tDB::(anonymous namespace)::executeDAG(DB::IQuerySource&, DB::Context&, bool) [tiflash+4382463412]\n     0x105b29328\tDB::executeQuery(DB::Context&, bool) [tiflash+4382462760]\n     0x105b4ea90\tDB::DAGDriver<true>::execute() [tiflash+4382616208]\n     0x105b0655c\tDB::BatchCoprocessorHandler::execute() [tiflash+4382319964]\n     0x105b227e4\tstd::__1::__function::__func<DB::FlashService::BatchCoprocessor(grpc::ServerContext*, coprocessor::BatchRequest const*, grpc::ServerWriter<coprocessor::BatchResponse>*)::$_20, std::__1::allocator<DB::FlashService::BatchCoprocessor(grpc::ServerContext*, coprocessor::BatchRequest const*, grpc::ServerWriter<coprocessor::BatchResponse>*)::$_20>, grpc::Status ()>::operator()() [tiflash+4382435300]\n     0x105b21ec4\tstd::__1::packaged_task<grpc::Status ()>::operator()() [tiflash+4382432964]\n     0x105d39d18\tThreadPool::worker() [tiflash+4384627992]\n     0x105d3a2ac\tvoid* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, ThreadPool::ThreadPool(unsigned long, std::__1::function<void ()>)::$_0> >(void*) [tiflash+4384629420]\n     0x1a075d06c\t__pthread_deallocate [libsystem_pthread.dylib+6446436460]\n     0x1a0757e2c\t_pthread_key_init_np [libsystem_pthread.dylib+6446415404]"] [source=DAGDriver] [thread_id=24]
[2023/01/19 10:14:14.520 +00:00] [DEBUG] [BatchCoprocessorHandler.cpp:83] ["Handle DAG request done"] [source=BatchCoprocessorHandler] [thread_id=24]
[2023/01/19 10:14:14.520 +00:00] [DEBUG] [MemoryTracker.cpp:69] ["Peak memory usage (total): 0.00 B."] [source=MemoryTracker] [thread_id=24]
[2023/01/19 10:14:14.520 +00:00] [DEBUG] [FlashService.cpp:215] ["Handle coprocessor request done: 0, "] [source=FlashService] [thread_id=23]
[2023/01/19 10:14:15.138 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:15.527 +00:00] [DEBUG] [FlashService.cpp:189] ["Handling coprocessor request: context {\n  region_id: 124\n  region_epoch {\n    conf_ver: 2\n    version: 48\n  }\n  peer {\n    id: 126\n    store_id: 119\n    role: Learner\n  }\n  record_time_stat: true\n  record_scan_stat: true\n  task_id: 2192\n  resource_group_tag: \"\\n \\216-\\336\\235\\364E\\271C\\240N>qp\\226\\272\\252\\374O \\344c\\300k\\013}\\026\\340?R\\235b\\326\\022 b\\250\\256\\301\\352$\\023E\\026\\305i.\\204\\201d\\276\\005X\\371\\037\\245J\\2673\\300\\0146\\022\\204A]\\334\\030\\001\"\n}\ntp: 103\ndata: \"\\030\\000 \\342\\001(\\0000\\000@\\001Z\\017Atlantic/Canary`\\001r\\002\\010\\000\\212\\001\\270\\001\\010\\006*\\237\\001\\022X\\010\\271\\027\\032/\\010\\311\\001\\022\\010\\200\\000\\000\\000\\000\\000\\000\\000 \\000*\\034\\010\\003\\020\\203 \\030\\013 \\000(\\301\\377\\377\\377\\377\\377\\377\\377\\377\\0012\\006binary8\\000 \\000*\\034\\010\\010\\020\\201\\001\\030\\025 \\000(\\301\\377\\377\\377\\377\\377\\377\\377\\377\\0012\\006binary8\\000H\\002\\030\\0002A\\010\\000\\022%\\010R\\022\\031\\010\\001\\020\\003\\030\\301\\377\\377\\377\\377\\377\\377\\377\\377\\001 \\013(\\0000\\203 \\250\\001\\001\\030\\000(\\000@\\000H\\000R\\020TableFullScan_21\\210\\001\\000\\220\\001\\000R\\014StreamAgg_10\\210\\001\\000\\220\\001\\000\"\nregions {\n  region_id: 124\n  region_epoch {\n    conf_ver: 2\n    version: 48\n  }\n  ranges {\n    start: \"t\\200\\000\\000\\000\\000\\000\\000R_r\\000\\000\\000\\000\\000\\000\\000\\000\"\n    end: \"t\\200\\000\\000\\000\\000\\000\\000R_r\\377\\377\\377\\377\\377\\377\\377\\377\\000\"\n  }\n}\nstart_ts: 438861366694510593\nschema_ver: 43\n"] [source=FlashService] [thread_id=29]
[2023/01/19 10:14:15.527 +00:00] [DEBUG] [BatchCoprocessorHandler.cpp:70] ["Handling 1 regions from 1 physical tables in DAG request: time_zone_offset: 0\nflags: 226\noutput_offsets: 0\ncollect_range_counts: false\nencode_type: TypeChunk\ntime_zone_name: \"Atlantic/Canary\"\ncollect_execution_summaries: true\nchunk_memory_layout {\n  endian: LittleEndian\n}\nroot_executor {\n  tp: TypeStreamAgg\n  aggregation {\n    agg_func {\n      tp: Count\n      children {\n        tp: ColumnRef\n        val: \"\\200\\000\\000\\000\\000\\000\\000\\000\"\n        sig: Unspecified\n        field_type {\n          tp: 3\n          flag: 4099\n          flen: 11\n          decimal: 0\n          collate: -63\n          charset: \"binary\"\n        }\n        has_distinct: false\n      }\n      sig: Unspecified\n      field_type {\n        tp: 8\n        flag: 129\n        flen: 21\n        decimal: 0\n        collate: -63\n        charset: \"binary\"\n      }\n      has_distinct: false\n      aggFuncMode: Partial1Mode\n    }\n    streamed: false\n    child {\n      tp: TypeTableScan\n      tbl_scan {\n        table_id: 82\n        columns {\n          column_id: 1\n          tp: 3\n          collation: -63\n          columnLen: 11\n          decimal: 0\n          flag: 4099\n          pk_handle: true\n        }\n        desc: false\n        next_read_engine: Local\n        keep_order: false\n        is_fast_scan: false\n      }\n      executor_id: \"TableFullScan_21\"\n      fine_grained_shuffle_stream_count: 0\n      fine_grained_shuffle_batch_size: 0\n    }\n  }\n  executor_id: \"StreamAgg_10\"\n  fine_grained_shuffle_stream_count: 0\n  fine_grained_shuffle_batch_size: 0\n}\n"] [source=BatchCoprocessorHandler] [thread_id=30]
[2023/01/19 10:14:15.527 +00:00] [DEBUG] [executeQuery.cpp:386] ["(from 127.0.0.1:55053, query_id: 9a74fc63-d0a3-41cb-8483-424a519f8666) time_zone_offset: 0 flags: 226 output_offsets: 0 collect_range_counts: false encode_type: TypeChunk time_zone_name: \"Atlantic/Canary\" collect_execution_summaries: true chunk_memory_layout {   endian: LittleEndian } root_executor {   tp: TypeStreamAgg   aggregation {     agg_func {       tp: Count       children {         tp: ColumnRef         val: \"\\200\\000\\000\\000\\000\\000\\000\\000\"         sig: Unspecified         field_type {           tp: 3           flag: 4099           flen: 11           decimal: 0           collate: -63           charset: \"binary\"         }         has_distinct: false       }       sig: Unspecified       field_type {         tp: 8         flag: 129         flen: 21         decimal: 0         collate: -63         charset: \"binary\"       }       has_distinct: false       aggFuncMode: Partial1Mode     }     streamed: false     child {       tp: TypeTableScan       tbl_scan {         table_id: 82         columns {           column_id: 1           tp: 3           collation: -63           columnLen: 11           decimal: 0           flag: 4099           pk_handle: true         }         desc: false         next_read_engine: Local         keep_order: false         is_fast_scan: false       }       executor_id: \"TableFullScan_21\"       fine_grained_shuffle_stream_count: 0       fine_grained_shuffle_batch_size: 0     }   }   executor_id: \"StreamAgg_10\"   fine_grained_shuffle_stream_count: 0   fine_grained_shuffle_batch_size: 0 } "] [source=BatchCoprocessorHandler] [thread_id=30]
[2023/01/19 10:14:15.527 +00:00] [DEBUG] [PhysicalPlan.cpp:265] ["build unoptimized physical plan: \n<Projection, StreamAgg_10> | is_tidb_operator: false, schema: <StreamAgg_10_CAST(count()_collator , Int64_String)_collator_0 , Int64>\n <Aggregation, StreamAgg_10> | is_tidb_operator: true, schema: <CAST(count()_collator , Int64_String)_collator_0 , Int64>\n  <TableScan, TableFullScan_21> | is_tidb_operator: true, schema: <table_scan_0, Int32>\n"] [source=BatchCoprocessorHandler] [thread_id=30]
[2023/01/19 10:14:15.527 +00:00] [DEBUG] [PhysicalPlan.cpp:271] ["build optimized physical plan: \n<Projection, StreamAgg_10> | is_tidb_operator: false, schema: <StreamAgg_10_CAST(count()_collator , Int64_String)_collator_0 , Int64>\n <Aggregation, StreamAgg_10> | is_tidb_operator: true, schema: <CAST(count()_collator , Int64_String)_collator_0 , Int64>\n  <TableScan, TableFullScan_21> | is_tidb_operator: true, schema: <table_scan_0, Int32>\n"] [source=BatchCoprocessorHandler] [thread_id=30]
[2023/01/19 10:14:15.527 +00:00] [DEBUG] [LearnerRead.cpp:298] ["Batch read index, original size 1, send & get 1 message, cost 0ms"] [source=BatchCoprocessorHandler] [thread_id=30]
[2023/01/19 10:14:15.527 +00:00] [DEBUG] [Region.cpp:539] ["[region 124, applied: term 6 index 7] need to wait learner index 31"] [thread_id=30]
[2023/01/19 10:14:17.041 +00:00] [DEBUG] [GCManager.cpp:46] ["Start GC with table id: 4"] [source=GCManager] [thread_id=17]
[2023/01/19 10:14:17.042 +00:00] [DEBUG] [GCManager.cpp:101] ["End GC and next gc will start with table id: 4"] [source=GCManager] [thread_id=17]
[2023/01/19 10:14:17.139 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:19.140 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:19.239 +00:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=7]
[2023/01/19 10:14:21.141 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:22.780 +00:00] [WARN] [PathCapacityMetrics.cpp:196] ["Available space is only 3.09% of capacity size. Avail size: 14.24 GiB, used size: 396.00 B, capacity size: 460.43 GiB"] [source=PathCapacityMetrics] [thread_id=8]
[2023/01/19 10:14:23.143 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:24.250 +00:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=7]
[2023/01/19 10:14:25.144 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:27.146 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:29.146 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:29.273 +00:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=7]
[2023/01/19 10:14:31.148 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:31.598 +00:00] [INFO] [PageDirectory.cpp:1620] ["After MVCC gc in memory [lowest_seq=5] clean [invalid_snapshot_nums=0] [invalid_page_nums=0] [total_deref_counter=0] [all_del_entries=0]. Still exist [snapshot_nums=0], [page_nums=3]. Longest alive snapshot: [longest_alive_snapshot_time=0] [longest_alive_snapshot_seq=0] [stale_snapshot_nums=0]"] [source=__global__.meta] [thread_id=9]
[2023/01/19 10:14:31.600 +00:00] [INFO] [BlobStore.cpp:1009] ["BlobStore gc get status done. gc info: Read-Only Blob: [null]. No GC Blob: [1/0.73]. Full GC Blob: [null]. Truncated Blob: [null]."] [source=__global__.meta] [thread_id=9]
[2023/01/19 10:14:31.604 +00:00] [DEBUG] [PageStorageImpl.cpp:330] ["GC finished without full gc. [total time=6ms] [compact wal=0ms] [compact directory=1ms] [compact spacemap=0ms] [gc status=4ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=__global__.meta] [thread_id=9]
[2023/01/19 10:14:31.608 +00:00] [INFO] [PageDirectory.cpp:1620] ["After MVCC gc in memory [lowest_seq=1] clean [invalid_snapshot_nums=0] [invalid_page_nums=0] [total_deref_counter=0] [all_del_entries=0]. Still exist [snapshot_nums=0], [page_nums=1]. Longest alive snapshot: [longest_alive_snapshot_time=0] [longest_alive_snapshot_seq=0] [stale_snapshot_nums=0]"] [source=__global__.data] [thread_id=9]
[2023/01/19 10:14:31.612 +00:00] [INFO] [BlobStore.cpp:1009] ["BlobStore gc get status done. gc info: Read-Only Blob: [null]. No GC Blob: [null]. Full GC Blob: [null]. Truncated Blob: [null]."] [source=__global__.data] [thread_id=9]
[2023/01/19 10:14:31.612 +00:00] [DEBUG] [PageStorageImpl.cpp:330] ["GC finished without full gc. [total time=4ms] [compact wal=0ms] [compact directory=3ms] [compact spacemap=0ms] [gc status=0ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=__global__.data] [thread_id=9]
[2023/01/19 10:14:31.612 +00:00] [INFO] [BlobStore.cpp:1009] ["BlobStore gc get status done. gc info: Read-Only Blob: [null]. No GC Blob: [null]. Full GC Blob: [null]. Truncated Blob: [null]."] [source=__global__.log] [thread_id=9]
[2023/01/19 10:14:31.616 +00:00] [DEBUG] [PageStorageImpl.cpp:330] ["GC finished without full gc. [total time=3ms] [compact wal=0ms] [compact directory=0ms] [compact spacemap=0ms] [gc status=3ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=__global__.log] [thread_id=9]
[2023/01/19 10:14:32.785 +00:00] [WARN] [PathCapacityMetrics.cpp:196] ["Available space is only 3.09% of capacity size. Avail size: 14.24 GiB, used size: 396.00 B, capacity size: 460.43 GiB"] [source=PathCapacityMetrics] [thread_id=8]
[2023/01/19 10:14:33.148 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:14:34.281 +00:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=7]
...
[2023/01/19 10:19:12.863 +00:00] [WARN] [PathCapacityMetrics.cpp:196] ["Available space is only 3.09% of capacity size. Avail size: 14.21 GiB, used size: 396.00 B, capacity size: 460.43 GiB"] [source=PathCapacityMetrics] [thread_id=8]
[2023/01/19 10:19:13.382 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:19:15.282 +00:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=7]
[2023/01/19 10:19:15.384 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:19:15.533 +00:00] [WARN] [Region.cpp:559] ["[region 124] wait learner index 31 timeout"] [thread_id=30]
[2023/01/19 10:19:15.533 +00:00] [ERROR] [DAGDriver.cpp:199] ["[FLASH:Coprocessor:RegionError] Region 124 is unavailable at 31: (while doing learner read for table, logical table_id: 82)\n\n     0x100805c10\tStackTrace::StackTrace() [tiflash+4295285776]\n     0x105942148\tDB::doLearnerRead(long long, DB::MvccQueryInfo&, bool, DB::Context&, std::__1::shared_ptr<DB::Logger> const&)::$_1::operator()(unsigned long) const::'lambda'(unsigned long long, unsigned long long)::operator()(unsigned long long, unsigned long long) const [tiflash+4380467528]\n     0x1059403ec\tDB::doLearnerRead(long long, DB::MvccQueryInfo&, bool, DB::Context&, std::__1::shared_ptr<DB::Logger> const&)::$_1::operator()(unsigned long) const [tiflash+4380460012]\n     0x10593edc0\tDB::doLearnerRead(long long, DB::MvccQueryInfo&, bool, DB::Context&, std::__1::shared_ptr<DB::Logger> const&) [tiflash+4380454336]\n     0x105b9615c\tDB::DAGStorageInterpreter::doBatchCopLearnerRead() [tiflash+4382908764]\n     0x105b92a68\tDB::DAGStorageInterpreter::prepare() [tiflash+4382894696]\n     0x105b92a10\tDB::DAGStorageInterpreter::execute(DB::DAGPipeline&) [tiflash+4382894608]\n     0x105c913c4\tDB::PhysicalTableScan::transformImpl(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383937476]\n     0x105c6477c\tDB::PhysicalPlanNode::transform(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383754108]\n     0x105c71168\tDB::PhysicalAggregation::transformImpl(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383805800]\n     0x105c6477c\tDB::PhysicalPlanNode::transform(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383754108]\n     0x105c8e7b8\tDB::PhysicalProjection::transformImpl(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383926200]\n     0x105c6477c\tDB::PhysicalPlanNode::transform(DB::DAGPipeline&, DB::Context&, unsigned long) [tiflash+4383754108]\n     0x105c6bcd8\tDB::Planner::executeImpl(DB::DAGPipeline&) [tiflash+4383784152]\n     0x105c6bb38\tDB::Planner::execute() [tiflash+4383783736]\n     0x105b295b4\tDB::(anonymous namespace)::executeDAG(DB::IQuerySource&, DB::Context&, bool) [tiflash+4382463412]\n     0x105b29328\tDB::executeQuery(DB::Context&, bool) [tiflash+4382462760]\n     0x105b4ea90\tDB::DAGDriver<true>::execute() [tiflash+4382616208]\n     0x105b0655c\tDB::BatchCoprocessorHandler::execute() [tiflash+4382319964]\n     0x105b227e4\tstd::__1::__function::__func<DB::FlashService::BatchCoprocessor(grpc::ServerContext*, coprocessor::BatchRequest const*, grpc::ServerWriter<coprocessor::BatchResponse>*)::$_20, std::__1::allocator<DB::FlashService::BatchCoprocessor(grpc::ServerContext*, coprocessor::BatchRequest const*, grpc::ServerWriter<coprocessor::BatchResponse>*)::$_20>, grpc::Status ()>::operator()() [tiflash+4382435300]\n     0x105b21ec4\tstd::__1::packaged_task<grpc::Status ()>::operator()() [tiflash+4382432964]\n     0x105d39d18\tThreadPool::worker() [tiflash+4384627992]\n     0x105d3a2ac\tvoid* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, ThreadPool::ThreadPool(unsigned long, std::__1::function<void ()>)::$_0> >(void*) [tiflash+4384629420]\n     0x1a075d06c\t__pthread_deallocate [libsystem_pthread.dylib+6446436460]\n     0x1a0757e2c\t_pthread_key_init_np [libsystem_pthread.dylib+6446415404]"] [source=DAGDriver] [thread_id=30]
[2023/01/19 10:19:15.533 +00:00] [DEBUG] [BatchCoprocessorHandler.cpp:83] ["Handle DAG request done"] [source=BatchCoprocessorHandler] [thread_id=30]
[2023/01/19 10:19:15.533 +00:00] [DEBUG] [MemoryTracker.cpp:69] ["Peak memory usage (total): 0.00 B."] [source=MemoryTracker] [thread_id=30]
[2023/01/19 10:19:15.533 +00:00] [DEBUG] [FlashService.cpp:215] ["Handle coprocessor request done: 0, "] [source=FlashService] [thread_id=29]
[2023/01/19 10:19:17.388 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:19:19.389 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:19:20.290 +00:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=7]
[2023/01/19 10:19:21.392 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info="] [source=operator()] [thread_id=26]
[2023/01/19 10:19:21.874 +00:00] [DEBUG] [GCManager.cpp:46] ["Start GC with table id: 4"] [source=GCManager] [thread_id=12]
[2023/01/19 10:19:21.875 +00:00] [DEBUG] [GCManager.cpp:101] ["End GC and next gc will start with table id: 4"] [source=GCManager] [thread_id=12]
[2023/01/19 10:19:22.866 +00:00] [WARN] [PathCapacityMetrics.cpp:196] ["Available space is only 3.09% of capacity size. Avail size: 14.21 GiB, used size: 396.00 B, capacity size: 460.43 GiB"] [source=PathCapacityMetrics] [thread_id=8]

tiflash_tikv.log (instance 0):

[2023/01/19 10:08:52.606 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:09:02.607 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:09:07.662 +00:00] [INFO] [kv.rs:635] ["batch_raft RPC is called, new gRPC stream established"]
[2023/01/19 10:09:07.669 +00:00] [INFO] [peer.rs:312] ["replicate peer"] [peer_id=126] [region_id=124]
[2023/01/19 10:09:07.670 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }"] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.674 +00:00] [INFO] [raft.rs:1120] ["became follower at term 0"] [term=0] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.674 +00:00] [INFO] [raft.rs:384] [newRaft] [peers="Configuration { incoming: Configuration { voters: {} }, outgoing: Configuration { voters: {} } }"] ["last term"=0] ["last index"=0] [applied=0] [commit=0] [term=0] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.674 +00:00] [INFO] [raw_node.rs:315] ["RawNode created with id 126."] [id=126] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.674 +00:00] [INFO] [raft.rs:1364] ["received a message with higher term from 125"] ["msg type"=MsgHeartbeat] [message_term=6] [term=0] [from=125] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.674 +00:00] [INFO] [raft.rs:1120] ["became follower at term 6"] [term=6] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.674 +00:00] [INFO] [raft_client.rs:790] ["resolve store address ok"] [addr=127.0.0.1:20162] [store_id=1]
[2023/01/19 10:09:07.674 +00:00] [INFO] [raft_client.rs:675] ["server: new connection with tikv endpoint"] [store_id=1] [addr=127.0.0.1:20162]
[2023/01/19 10:09:07.683 +00:00] [INFO] [snap.rs:670] ["set_snapshot_meta total cf files count: 3"]
[2023/01/19 10:09:07.683 +00:00] [INFO] [snap.rs:263] ["saving snapshot file"] [file=/Users/mattias/.tiup/data/TTNVtBU/tiflash-0/flash/snap/rev_124_6_7_(default|lock|write).sst] [snap_key=124_6_7]
[2023/01/19 10:09:07.722 +00:00] [INFO] [snap.rs:271] ["saving all snapshot files"] [takes=38.117875ms] [snap_key=124_6_7]
[2023/01/19 10:09:07.725 +00:00] [INFO] [snap.rs:670] ["set_snapshot_meta total cf files count: 3"]
[2023/01/19 10:09:07.725 +00:00] [INFO] [raft_log.rs:627] ["log [committed=0, persisted=0, applied=0, unstable.offset=1, unstable.entries.len()=0] starts to restore snapshot [index: 7, term: 6]"] [snapshot_term=6] [snapshot_index=7] [log="committed=0, persisted=0, applied=0, unstable.offset=1, unstable.entries.len()=0"] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.725 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {125} }, outgoing: Configuration { voters: {} } }, learners: {126}, learners_next: {}, auto_leave: false }"] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.725 +00:00] [INFO] [raft.rs:2630] ["restored snapshot"] [snapshot_term=6] [snapshot_index=7] [last_term=6] [last_index=7] [commit=7] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.725 +00:00] [INFO] [raft.rs:2511] ["[commit: 7, term: 6] restored snapshot [index: 7, term: 6]"] [snapshot_term=6] [snapshot_index=7] [commit=7] [term=6] [raft_id=126] [region_id=124]
[2023/01/19 10:09:07.725 +00:00] [INFO] [peer_storage.rs:580] ["begin to apply snapshot"] [peer_id=126] [region_id=124]
[2023/01/19 10:09:07.725 +00:00] [INFO] [peer_storage.rs:663] ["apply snapshot with state ok"] [state="applied_index: 7 truncated_state { index: 7 term: 6 }"] [region="id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 2 version: 48 } peers { id: 125 store_id: 1 } peers { id: 126 store_id: 119 role: Learner }"] [peer_id=126] [region_id=124]
[2023/01/19 10:09:07.739 +00:00] [INFO] [snap.rs:670] ["set_snapshot_meta total cf files count: 3"]
[2023/01/19 10:09:07.740 +00:00] [INFO] [peer.rs:4736] ["snapshot is persisted"] [region="id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 2 version: 48 } peers { id: 125 store_id: 1 } peers { id: 126 store_id: 119 role: Learner }"] [peer_id=126] [region_id=124]
[2023/01/19 10:09:07.750 +00:00] [INFO] [observer.rs:738] ["pre apply snapshot"] [pending=0] [snap_key="SnapKey { region_id: 124, term: 6, idx: 7 }"] [region_id=124] [peer_id=126]
[2023/01/19 10:09:07.905 +00:00] [INFO] [region.rs:441] ["begin apply snap data"] [peer_id=126] [region_id=124]
[2023/01/19 10:09:07.910 +00:00] [INFO] [snap.rs:670] ["set_snapshot_meta total cf files count: 3"]
[2023/01/19 10:09:07.910 +00:00] [INFO] [observer.rs:814] ["post apply snapshot"] [region="id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 2 version: 48 } peers { id: 125 store_id: 1 } peers { id: 126 store_id: 119 role: Learner }"] [snap_key="SnapKey { region_id: 124, term: 6, idx: 7 }"] [peer_id=126]
[2023/01/19 10:09:07.910 +00:00] [INFO] [observer.rs:832] ["get prehandled snapshot success"] [pending=1] [region_id=124] [snap_key="SnapKey { region_id: 124, term: 6, idx: 7 }"] [peer_id=126]
[2023/01/19 10:09:07.911 +00:00] [INFO] [observer.rs:855] ["apply snapshot finished"] [pending=0] [region="id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 2 version: 48 } peers { id: 125 store_id: 1 } peers { id: 126 store_id: 119 role: Learner }"] [snap_key="SnapKey { region_id: 124, term: 6, idx: 7 }"] [peer_id=126]
[2023/01/19 10:09:07.911 +00:00] [INFO] [region.rs:488] ["apply new data"] [time_takes=1.153208ms] [region_id=124]
[2023/01/19 10:09:12.608 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:09:22.610 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:09:32.612 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:09:42.613 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:09:52.614 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:10:02.521 +00:00] [INFO] [peer.rs:1297] ["deleting applied snap file"] [snap_file=124_6_7] [peer_id=126] [region_id=124]
[2023/01/19 10:10:02.522 +00:00] [INFO] [snap.rs:670] ["set_snapshot_meta total cf files count: 3"]
[2023/01/19 10:10:02.616 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]

tikv.log (instance 2, nothing in 0 or 1):

[2023/01/19 10:08:46.054 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:08:56.056 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:09:06.057 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:09:07.593 +00:00] [INFO] [peer.rs:5642] ["on split"] [source=ipv4:127.0.0.1:52270] [split_keys="key 7480000000000000FF5200000000000000F8"] [peer_id=25] [region_id=24]
[2023/01/19 10:09:07.593 +00:00] [INFO] [pd.rs:1082] ["try to batch split region"] [task=batch_split] [region="id: 24 start_key: 7480000000000000FF5000000000000000F8 end_key: 748000FFFFFFFFFFFFF900000000000000F8 region_epoch { conf_ver: 1 version: 45 } peers { id: 25 store_id: 1 }"] [new_region_ids="[new_region_id: 120 new_peer_ids: 121]"] [region_id=24]
[2023/01/19 10:09:07.597 +00:00] [INFO] [apply.rs:1647] ["execute admin command"] [command="cmd_type: BatchSplit splits { requests { split_key: 7480000000000000FF5200000000000000F8 new_region_id: 120 new_peer_ids: 121 } right_derive: true }"] [index=82] [term=6] [peer_id=25] [region_id=24]
[2023/01/19 10:09:07.597 +00:00] [INFO] [apply.rs:2505] ["split region"] [keys="key 7480000000000000FF5200000000000000F8"] [region="id: 24 start_key: 7480000000000000FF5000000000000000F8 end_key: 748000FFFFFFFFFFFFF900000000000000F8 region_epoch { conf_ver: 1 version: 45 } peers { id: 25 store_id: 1 }"] [peer_id=25] [region_id=24]
[2023/01/19 10:09:07.605 +00:00] [INFO] [endpoint.rs:170] ["region met split/merge command, stop tracking since key range changed, wait for re-register"] [req_type=BatchSplit]
[2023/01/19 10:09:07.606 +00:00] [INFO] [peer.rs:3949] ["moving 0 locks to new regions"] [region_id=24]
[2023/01/19 10:09:07.606 +00:00] [INFO] [peer.rs:3979] ["notify pd with split"] [split_count=2] [peer_id=25] [region_id=24]
[2023/01/19 10:09:07.606 +00:00] [INFO] [peer.rs:4044] ["insert new region"] [region="id: 120 start_key: 7480000000000000FF5000000000000000F8 end_key: 7480000000000000FF5200000000000000F8 region_epoch { conf_ver: 1 version: 46 } peers { id: 121 store_id: 1 }"] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [peer.rs:262] ["create peer"] [peer_id=121] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [endpoint.rs:404] ["deregister observe region"] [observe_id=ObserveId(95)] [region_id=24] [store_id=Some(1)]
[2023/01/19 10:09:07.606 +00:00] [INFO] [endpoint.rs:330] ["register observe region"] [region="id: 24 start_key: 7480000000000000FF5200000000000000F8 end_key: 748000FFFFFFFFFFFFF900000000000000F8 region_epoch { conf_ver: 1 version: 46 } peers { id: 25 store_id: 1 }"]
[2023/01/19 10:09:07.606 +00:00] [INFO] [subscription_manager.rs:395] ["backup stream: on_modify_observe"] [op="RefreshResolver { region: Region { id: 24, ver: 46, conf_ver: 1, range: [7480000000000000FF5200000000000000F8,748000FFFFFFFFFFFFF900000000000000F8), peers: 1 } }"]
[2023/01/19 10:09:07.606 +00:00] [WARN] [subscription_track.rs:217] ["backup stream observer refreshing void subscription."] [r.id=24] [r.ver=46] [r.conf_ver=1] [r.range="[7480000000000000FF5200000000000000F8,748000FFFFFFFFFFFFF900000000000000F8)"] [r.peers=1]
[2023/01/19 10:09:07.606 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {121} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }"] [raft_id=121] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [raft.rs:1120] ["became follower at term 5"] [term=5] [raft_id=121] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [raft.rs:384] [newRaft] [peers="Configuration { incoming: Configuration { voters: {121} }, outgoing: Configuration { voters: {} } }"] ["last term"=5] ["last index"=5] [applied=5] [commit=5] [term=5] [raft_id=121] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [raw_node.rs:315] ["RawNode created with id 121."] [id=121] [raft_id=121] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [raft.rs:1550] ["starting a new election"] [term=5] [raft_id=121] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [raft.rs:1170] ["became pre-candidate at term 5"] [term=5] [raft_id=121] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [raft.rs:1144] ["became candidate at term 6"] [term=6] [raft_id=121] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [raft.rs:1228] ["became leader at term 6"] [term=6] [raft_id=121] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [peer.rs:5403] ["require updating max ts"] [initial_status=25769803868] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [endpoint.rs:330] ["register observe region"] [region="id: 120 start_key: 7480000000000000FF5000000000000000F8 end_key: 7480000000000000FF5200000000000000F8 region_epoch { conf_ver: 1 version: 46 } peers { id: 121 store_id: 1 }"]
[2023/01/19 10:09:07.606 +00:00] [INFO] [pd.rs:1701] ["succeed to update max timestamp"] [region_id=120]
[2023/01/19 10:09:07.606 +00:00] [INFO] [endpoint.rs:251] ["Resolver initialized"] [pending_data_index=0] [snapshot_index=82] [observe_id=ObserveId(97)] [region=24]
[2023/01/19 10:09:07.606 +00:00] [INFO] [endpoint.rs:251] ["Resolver initialized"] [pending_data_index=0] [snapshot_index=6] [observe_id=ObserveId(98)] [region=120]
[2023/01/19 10:09:07.639 +00:00] [INFO] [pd.rs:1536] ["try to split"] [region_epoch="conf_ver: 1 version: 46"] [region_id=24]
[2023/01/19 10:09:07.639 +00:00] [INFO] [peer.rs:5642] ["on split"] [source=pd] [split_keys="2 keys range from 7480000000000000FF525F720000000000FA to 7480000000000000FF5300000000000000F8"] [peer_id=25] [region_id=24]
[2023/01/19 10:09:07.639 +00:00] [INFO] [pd.rs:1082] ["try to batch split region"] [task=batch_split] [region="id: 24 start_key: 7480000000000000FF5200000000000000F8 end_key: 748000FFFFFFFFFFFFF900000000000000F8 region_epoch { conf_ver: 1 version: 46 } peers { id: 25 store_id: 1 }"] [new_region_ids="[new_region_id: 122 new_peer_ids: 123, new_region_id: 124 new_peer_ids: 125]"] [region_id=24]
[2023/01/19 10:09:07.639 +00:00] [INFO] [apply.rs:1647] ["execute admin command"] [command="cmd_type: BatchSplit splits { requests { split_key: 7480000000000000FF525F720000000000FA new_region_id: 122 new_peer_ids: 123 } requests { split_key: 7480000000000000FF5300000000000000F8 new_region_id: 124 new_peer_ids: 125 } right_derive: true }"] [index=83] [term=6] [peer_id=25] [region_id=24]
[2023/01/19 10:09:07.639 +00:00] [INFO] [apply.rs:2505] ["split region"] [keys="2 keys range from 7480000000000000FF525F720000000000FA to 7480000000000000FF5300000000000000F8"] [region="id: 24 start_key: 7480000000000000FF5200000000000000F8 end_key: 748000FFFFFFFFFFFFF900000000000000F8 region_epoch { conf_ver: 1 version: 46 } peers { id: 25 store_id: 1 }"] [peer_id=25] [region_id=24]
[2023/01/19 10:09:07.643 +00:00] [INFO] [peer.rs:3949] ["moving 0 locks to new regions"] [region_id=24]
[2023/01/19 10:09:07.644 +00:00] [INFO] [endpoint.rs:170] ["region met split/merge command, stop tracking since key range changed, wait for re-register"] [req_type=BatchSplit]
[2023/01/19 10:09:07.644 +00:00] [INFO] [peer.rs:3979] ["notify pd with split"] [split_count=3] [peer_id=25] [region_id=24]
[2023/01/19 10:09:07.644 +00:00] [INFO] [peer.rs:4044] ["insert new region"] [region="id: 122 start_key: 7480000000000000FF5200000000000000F8 end_key: 7480000000000000FF525F720000000000FA region_epoch { conf_ver: 1 version: 48 } peers { id: 123 store_id: 1 }"] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [peer.rs:262] ["create peer"] [peer_id=123] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [endpoint.rs:404] ["deregister observe region"] [observe_id=ObserveId(97)] [region_id=24] [store_id=Some(1)]
[2023/01/19 10:09:07.644 +00:00] [INFO] [endpoint.rs:330] ["register observe region"] [region="id: 24 start_key: 7480000000000000FF5300000000000000F8 end_key: 748000FFFFFFFFFFFFF900000000000000F8 region_epoch { conf_ver: 1 version: 48 } peers { id: 25 store_id: 1 }"]
[2023/01/19 10:09:07.644 +00:00] [INFO] [subscription_manager.rs:395] ["backup stream: on_modify_observe"] [op="RefreshResolver { region: Region { id: 24, ver: 48, conf_ver: 1, range: [7480000000000000FF5300000000000000F8,748000FFFFFFFFFFFFF900000000000000F8), peers: 1 } }"]
[2023/01/19 10:09:07.644 +00:00] [WARN] [subscription_track.rs:217] ["backup stream observer refreshing void subscription."] [r.id=24] [r.ver=48] [r.conf_ver=1] [r.range="[7480000000000000FF5300000000000000F8,748000FFFFFFFFFFFFF900000000000000F8)"] [r.peers=1]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {123} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }"] [raft_id=123] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1120] ["became follower at term 5"] [term=5] [raft_id=123] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:384] [newRaft] [peers="Configuration { incoming: Configuration { voters: {123} }, outgoing: Configuration { voters: {} } }"] ["last term"=5] ["last index"=5] [applied=5] [commit=5] [term=5] [raft_id=123] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raw_node.rs:315] ["RawNode created with id 123."] [id=123] [raft_id=123] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1550] ["starting a new election"] [term=5] [raft_id=123] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1170] ["became pre-candidate at term 5"] [term=5] [raft_id=123] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1144] ["became candidate at term 6"] [term=6] [raft_id=123] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1228] ["became leader at term 6"] [term=6] [raft_id=123] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [peer.rs:4044] ["insert new region"] [region="id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 1 version: 48 } peers { id: 125 store_id: 1 }"] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [peer.rs:262] ["create peer"] [peer_id=125] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {125} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }"] [raft_id=125] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1120] ["became follower at term 5"] [term=5] [raft_id=125] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:384] [newRaft] [peers="Configuration { incoming: Configuration { voters: {125} }, outgoing: Configuration { voters: {} } }"] ["last term"=5] ["last index"=5] [applied=5] [commit=5] [term=5] [raft_id=125] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raw_node.rs:315] ["RawNode created with id 125."] [id=125] [raft_id=125] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1550] ["starting a new election"] [term=5] [raft_id=125] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1170] ["became pre-candidate at term 5"] [term=5] [raft_id=125] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1144] ["became candidate at term 6"] [term=6] [raft_id=125] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [raft.rs:1228] ["became leader at term 6"] [term=6] [raft_id=125] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [peer.rs:5403] ["require updating max ts"] [initial_status=25769803872] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [peer.rs:5403] ["require updating max ts"] [initial_status=25769803872] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [endpoint.rs:330] ["register observe region"] [region="id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 1 version: 48 } peers { id: 125 store_id: 1 }"]
[2023/01/19 10:09:07.644 +00:00] [INFO] [endpoint.rs:330] ["register observe region"] [region="id: 122 start_key: 7480000000000000FF5200000000000000F8 end_key: 7480000000000000FF525F720000000000FA region_epoch { conf_ver: 1 version: 48 } peers { id: 123 store_id: 1 }"]
[2023/01/19 10:09:07.644 +00:00] [INFO] [endpoint.rs:251] ["Resolver initialized"] [pending_data_index=0] [snapshot_index=83] [observe_id=ObserveId(99)] [region=24]
[2023/01/19 10:09:07.644 +00:00] [INFO] [pd.rs:1701] ["succeed to update max timestamp"] [region_id=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [pd.rs:1701] ["succeed to update max timestamp"] [region_id=122]
[2023/01/19 10:09:07.644 +00:00] [INFO] [endpoint.rs:251] ["Resolver initialized"] [pending_data_index=0] [snapshot_index=6] [observe_id=ObserveId(100)] [region=124]
[2023/01/19 10:09:07.644 +00:00] [INFO] [endpoint.rs:251] ["Resolver initialized"] [pending_data_index=0] [snapshot_index=6] [observe_id=ObserveId(101)] [region=122]
[2023/01/19 10:09:07.651 +00:00] [INFO] [pd.rs:1508] ["try to change peer"] [changes="[peer { id: 126 store_id: 119 role: Learner } change_type: AddLearnerNode]"] [region_id=124]
[2023/01/19 10:09:07.651 +00:00] [INFO] [peer.rs:4703] ["propose conf change peer"] [kind=Simple] [changes="[change_type: AddLearnerNode peer { id: 126 store_id: 119 role: Learner }]"] [peer_id=125] [region_id=124]
[2023/01/19 10:09:07.654 +00:00] [INFO] [apply.rs:1647] ["execute admin command"] [command="cmd_type: ChangePeerV2 change_peer_v2 { changes { change_type: AddLearnerNode peer { id: 126 store_id: 119 role: Learner } } }"] [index=7] [term=6] [peer_id=125] [region_id=124]
[2023/01/19 10:09:07.654 +00:00] [INFO] [apply.rs:2239] ["exec ConfChangeV2"] [epoch="conf_ver: 1 version: 48"] [kind=Simple] [peer_id=125] [region_id=124]
[2023/01/19 10:09:07.654 +00:00] [INFO] [apply.rs:2420] ["conf change successfully"] ["current region"="id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 2 version: 48 } peers { id: 125 store_id: 1 } peers { id: 126 store_id: 119 role: Learner }"] ["original region"="id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 1 version: 48 } peers { id: 125 store_id: 1 }"] [changes="[change_type: AddLearnerNode peer { id: 126 store_id: 119 role: Learner }]"] [peer_id=125] [region_id=124]
[2023/01/19 10:09:07.659 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {125} }, outgoing: Configuration { voters: {} } }, learners: {126}, learners_next: {}, auto_leave: false }"] [raft_id=125] [region_id=124]
[2023/01/19 10:09:07.659 +00:00] [INFO] [subscription_manager.rs:395] ["backup stream: on_modify_observe"] [op="RefreshResolver { region: Region { id: 124, ver: 48, conf_ver: 2, range: [7480000000000000FF525F720000000000FA,7480000000000000FF5300000000000000F8), peers: 1,119 } }"]
[2023/01/19 10:09:07.659 +00:00] [WARN] [subscription_track.rs:217] ["backup stream observer refreshing void subscription."] [r.id=124] [r.ver=48] [r.conf_ver=2] [r.range="[7480000000000000FF525F720000000000FA,7480000000000000FF5300000000000000F8)"] [r.peers=1,119]
[2023/01/19 10:09:07.662 +00:00] [INFO] [peer.rs:3843] ["notify pd with change peer region"] [region="id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 2 version: 48 } peers { id: 125 store_id: 1 } peers { id: 126 store_id: 119 role: Learner }"] [peer_id=125] [region_id=124]
[2023/01/19 10:09:07.666 +00:00] [INFO] [replication_mode.rs:40] ["backup store labels"] [labels="[key: \"engine\" value: \"tiflash\"]"] [store_id=119]
[2023/01/19 10:09:07.670 +00:00] [INFO] [raft_client.rs:790] ["resolve store address ok"] [addr=127.0.0.1:20170] [store_id=119]
[2023/01/19 10:09:07.674 +00:00] [INFO] [raft_client.rs:675] ["server: new connection with tikv endpoint"] [store_id=119] [addr=127.0.0.1:20170]
[2023/01/19 10:09:07.674 +00:00] [INFO] [kv.rs:639] ["batch_raft RPC is called, new gRPC stream established"]
[2023/01/19 10:09:07.674 +00:00] [INFO] [peer.rs:2407] ["reported disk usage changes None -> AlmostFull"] [peer_id=126] [region_id=124]
[2023/01/19 10:09:07.674 +00:00] [INFO] [peer_storage.rs:522] ["requesting snapshot"] [request_peer=126] [request_index=0] [peer_id=125] [region_id=124]
[2023/01/19 10:09:07.677 +00:00] [INFO] [snap.rs:916] ["scan snapshot of one cf"] [size=0] [key_count=0] [cf=default] [snapshot=/Users/mattias/.tiup/data/TTNVtBU/tikv-2/data/snap/gen_124_6_7_(default|lock|write).sst] [region_id=124]
[2023/01/19 10:09:07.677 +00:00] [INFO] [snap.rs:916] ["scan snapshot of one cf"] [size=0] [key_count=0] [cf=lock] [snapshot=/Users/mattias/.tiup/data/TTNVtBU/tikv-2/data/snap/gen_124_6_7_(default|lock|write).sst] [region_id=124]
[2023/01/19 10:09:07.677 +00:00] [INFO] [snap.rs:916] ["scan snapshot of one cf"] [size=0] [key_count=0] [cf=write] [snapshot=/Users/mattias/.tiup/data/TTNVtBU/tikv-2/data/snap/gen_124_6_7_(default|lock|write).sst] [region_id=124]
[2023/01/19 10:09:07.682 +00:00] [INFO] [snap.rs:1055] ["scan snapshot"] [takes=7.485083ms] [size=0] [key_count=0] [snapshot=/Users/mattias/.tiup/data/TTNVtBU/tikv-2/data/snap/gen_124_6_7_(default|lock|write).sst] [region_id=124]
[2023/01/19 10:09:07.682 +00:00] [INFO] [snap.rs:670] ["set_snapshot_meta total cf files count: 3"]
[2023/01/19 10:09:07.725 +00:00] [INFO] [snap.rs:452] ["sent snapshot"] [duration=43.153708ms] [size=0] [snap_key=124_6_7] [region_id=124]
[2023/01/19 10:09:07.725 +00:00] [INFO] [peer.rs:1924] ["report snapshot status"] [status=Finish] [to="id: 126 store_id: 119 role: Learner"] [peer_id=125] [region_id=124]
[2023/01/19 10:09:11.136 +00:00] [INFO] [scheduler.rs:720] ["get snapshot failed"] [err="Error(Request(message: \"EpochNotMatch current epoch of region 24 is conf_ver: 1 version: 48, but you sent conf_ver: 1 version: 45\" epoch_not_match { current_regions { id: 24 start_key: 7480000000000000FF5300000000000000F8 end_key: 748000FFFFFFFFFFFFF900000000000000F8 region_epoch { conf_ver: 1 version: 48 } peers { id: 25 store_id: 1 } } current_regions { id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 2 version: 48 } peers { id: 125 store_id: 1 } peers { id: 126 store_id: 119 role: Learner } } current_regions { id: 122 start_key: 7480000000000000FF5200000000000000F8 end_key: 7480000000000000FF525F720000000000FA region_epoch { conf_ver: 1 version: 48 } peers { id: 123 store_id: 1 } } current_regions { id: 120 start_key: 7480000000000000FF5000000000000000F8 end_key: 7480000000000000FF5200000000000000F8 region_epoch { conf_ver: 1 version: 46 } peers { id: 121 store_id: 1 } } }))"] [cid=1183]
[2023/01/19 10:09:12.701 +00:00] [WARN] [endpoint.rs:808] [error-response] [err="Region error (will back off and retry) message: \"EpochNotMatch current epoch of region 24 is conf_ver: 1 version: 48, but you sent conf_ver: 1 version: 45\" epoch_not_match { current_regions { id: 24 start_key: 7480000000000000FF5300000000000000F8 end_key: 748000FFFFFFFFFFFFF900000000000000F8 region_epoch { conf_ver: 1 version: 48 } peers { id: 25 store_id: 1 } } current_regions { id: 124 start_key: 7480000000000000FF525F720000000000FA end_key: 7480000000000000FF5300000000000000F8 region_epoch { conf_ver: 2 version: 48 } peers { id: 125 store_id: 1 } peers { id: 126 store_id: 119 role: Learner } } current_regions { id: 122 start_key: 7480000000000000FF5200000000000000F8 end_key: 7480000000000000FF525F720000000000FA region_epoch { conf_ver: 1 version: 48 } peers { id: 123 store_id: 1 } } current_regions { id: 120 start_key: 7480000000000000FF5000000000000000F8 end_key: 7480000000000000FF5200000000000000F8 region_epoch { conf_ver: 1 version: 46 } peers { id: 121 store_id: 1 } } }"]
[2023/01/19 10:09:16.058 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:09:26.059 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
...
[2023/01/19 10:19:46.172 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:19:56.177 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:19:56.794 +00:00] [INFO] [pd.rs:1508] ["try to change peer"] [changes="[peer { id: 127 store_id: 2 role: Learner } change_type: AddLearnerNode]"] [region_id=54]
[2023/01/19 10:19:56.795 +00:00] [INFO] [peer.rs:4703] ["propose conf change peer"] [kind=Simple] [changes="[change_type: AddLearnerNode peer { id: 127 store_id: 2 role: Learner }]"] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.795 +00:00] [INFO] [apply.rs:1647] ["execute admin command"] [command="cmd_type: ChangePeerV2 change_peer_v2 { changes { change_type: AddLearnerNode peer { id: 127 store_id: 2 role: Learner } } }"] [index=266] [term=6] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.795 +00:00] [INFO] [apply.rs:2239] ["exec ConfChangeV2"] [epoch="conf_ver: 1 version: 4"] [kind=Simple] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.795 +00:00] [INFO] [apply.rs:2420] ["conf change successfully"] ["current region"="id: 54 start_key: 748000FFFFFFFFFFFFFE00000000000000F8 end_key: 7800000000000000FB region_epoch { conf_ver: 2 version: 4 } peers { id: 55 store_id: 1 } peers { id: 127 store_id: 2 role: Learner }"] ["original region"="id: 54 start_key: 748000FFFFFFFFFFFFFE00000000000000F8 end_key: 7800000000000000FB region_epoch { conf_ver: 1 version: 4 } peers { id: 55 store_id: 1 }"] [changes="[change_type: AddLearnerNode peer { id: 127 store_id: 2 role: Learner }]"] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.799 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {55} }, outgoing: Configuration { voters: {} } }, learners: {127}, learners_next: {}, auto_leave: false }"] [raft_id=55] [region_id=54]
[2023/01/19 10:19:56.799 +00:00] [INFO] [peer.rs:3843] ["notify pd with change peer region"] [region="id: 54 start_key: 748000FFFFFFFFFFFFFE00000000000000F8 end_key: 7800000000000000FB region_epoch { conf_ver: 2 version: 4 } peers { id: 55 store_id: 1 } peers { id: 127 store_id: 2 role: Learner }"] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.799 +00:00] [INFO] [subscription_manager.rs:395] ["backup stream: on_modify_observe"] [op="RefreshResolver { region: Region { id: 54, ver: 4, conf_ver: 2, range: [748000FFFFFFFFFFFFFE00000000000000F8,7800000000000000FB), peers: 1,2 } }"]
[2023/01/19 10:19:56.799 +00:00] [WARN] [subscription_track.rs:217] ["backup stream observer refreshing void subscription."] [r.id=54] [r.ver=4] [r.conf_ver=2] [r.range="[748000FFFFFFFFFFFFFE00000000000000F8,7800000000000000FB)"] [r.peers=1,2]
[2023/01/19 10:19:56.799 +00:00] [INFO] [replication_mode.rs:40] ["backup store labels"] [labels="[]"] [store_id=2]
[2023/01/19 10:19:56.799 +00:00] [INFO] [raft_client.rs:790] ["resolve store address ok"] [addr=127.0.0.1:20160] [store_id=2]
[2023/01/19 10:19:56.799 +00:00] [INFO] [raft_client.rs:675] ["server: new connection with tikv endpoint"] [store_id=2] [addr=127.0.0.1:20160]
[2023/01/19 10:19:56.801 +00:00] [INFO] [kv.rs:639] ["batch_raft RPC is called, new gRPC stream established"]
[2023/01/19 10:19:56.801 +00:00] [INFO] [peer_storage.rs:522] ["requesting snapshot"] [request_peer=127] [request_index=0] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.808 +00:00] [INFO] [io.rs:184] ["build_sst_cf_file_list builds 1 files in cf default. Total keys 129, total size 846649. raw_size_per_file 104857600, total takes 6.76ms"]
[2023/01/19 10:19:56.809 +00:00] [INFO] [snap.rs:916] ["scan snapshot of one cf"] [size=846649] [key_count=129] [cf=default] [snapshot=/Users/mattias/.tiup/data/TTNVtBU/tikv-2/data/snap/gen_54_6_266_(default|lock|write).sst] [region_id=54]
[2023/01/19 10:19:56.809 +00:00] [INFO] [snap.rs:916] ["scan snapshot of one cf"] [size=0] [key_count=0] [cf=lock] [snapshot=/Users/mattias/.tiup/data/TTNVtBU/tikv-2/data/snap/gen_54_6_266_(default|lock|write).sst] [region_id=54]
[2023/01/19 10:19:56.813 +00:00] [INFO] [io.rs:184] ["build_sst_cf_file_list builds 1 files in cf write. Total keys 172, total size 7912. raw_size_per_file 104857600, total takes 3.664334ms"]
[2023/01/19 10:19:56.813 +00:00] [INFO] [snap.rs:916] ["scan snapshot of one cf"] [size=7912] [key_count=172] [cf=write] [snapshot=/Users/mattias/.tiup/data/TTNVtBU/tikv-2/data/snap/gen_54_6_266_(default|lock|write).sst] [region_id=54]
[2023/01/19 10:19:56.817 +00:00] [INFO] [snap.rs:1055] ["scan snapshot"] [takes=14.957917ms] [size=41912] [key_count=301] [snapshot=/Users/mattias/.tiup/data/TTNVtBU/tikv-2/data/snap/gen_54_6_266_(default|lock|write).sst] [region_id=54]
[2023/01/19 10:19:56.817 +00:00] [INFO] [snap.rs:670] ["set_snapshot_meta total cf files count: 3"]
[2023/01/19 10:19:56.839 +00:00] [INFO] [snap.rs:452] ["sent snapshot"] [duration=22.127167ms] [size=41912] [snap_key=54_6_266] [region_id=54]
[2023/01/19 10:19:56.839 +00:00] [INFO] [peer.rs:1924] ["report snapshot status"] [status=Finish] [to="id: 127 store_id: 2 role: Learner"] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.888 +00:00] [INFO] [pd.rs:1508] ["try to change peer"] [changes="[peer { id: 127 store_id: 2 }, peer { id: 55 store_id: 1 role: Learner } change_type: AddLearnerNode]"] [region_id=54]
[2023/01/19 10:19:56.888 +00:00] [INFO] [peer.rs:4703] ["propose conf change peer"] [kind=EnterJoint] [changes="[peer { id: 127 store_id: 2 }, change_type: AddLearnerNode peer { id: 55 store_id: 1 role: Learner }]"] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.888 +00:00] [INFO] [apply.rs:1647] ["execute admin command"] [command="cmd_type: ChangePeerV2 change_peer_v2 { changes { peer { id: 127 store_id: 2 } } changes { change_type: AddLearnerNode peer { id: 55 store_id: 1 role: Learner } } }"] [index=267] [term=6] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.888 +00:00] [INFO] [apply.rs:2239] ["exec ConfChangeV2"] [epoch="conf_ver: 2 version: 4"] [kind=EnterJoint] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.888 +00:00] [INFO] [apply.rs:2420] ["conf change successfully"] ["current region"="id: 54 start_key: 748000FFFFFFFFFFFFFE00000000000000F8 end_key: 7800000000000000FB region_epoch { conf_ver: 4 version: 4 } peers { id: 55 store_id: 1 role: DemotingVoter } peers { id: 127 store_id: 2 role: IncomingVoter }"] ["original region"="id: 54 start_key: 748000FFFFFFFFFFFFFE00000000000000F8 end_key: 7800000000000000FB region_epoch { conf_ver: 2 version: 4 } peers { id: 55 store_id: 1 } peers { id: 127 store_id: 2 role: Learner }"] [changes="[peer { id: 127 store_id: 2 }, change_type: AddLearnerNode peer { id: 55 store_id: 1 role: Learner }]"] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.892 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {127} }, outgoing: Configuration { voters: {55} } }, learners: {}, learners_next: {55}, auto_leave: false }"] [raft_id=55] [region_id=54]
[2023/01/19 10:19:56.892 +00:00] [INFO] [peer.rs:3843] ["notify pd with change peer region"] [region="id: 54 start_key: 748000FFFFFFFFFFFFFE00000000000000F8 end_key: 7800000000000000FB region_epoch { conf_ver: 4 version: 4 } peers { id: 55 store_id: 1 role: DemotingVoter } peers { id: 127 store_id: 2 role: IncomingVoter }"] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.892 +00:00] [INFO] [subscription_manager.rs:395] ["backup stream: on_modify_observe"] [op="RefreshResolver { region: Region { id: 54, ver: 4, conf_ver: 4, range: [748000FFFFFFFFFFFFFE00000000000000F8,7800000000000000FB), peers: 1,2 } }"]
[2023/01/19 10:19:56.892 +00:00] [WARN] [subscription_track.rs:217] ["backup stream observer refreshing void subscription."] [r.id=54] [r.ver=4] [r.conf_ver=4] [r.range="[748000FFFFFFFFFFFFFE00000000000000F8,7800000000000000FB)"] [r.peers=1,2]
[2023/01/19 10:19:56.892 +00:00] [INFO] [pd.rs:1521] ["try to transfer leader"] [to_peers="[]"] [to_peer="id: 127 store_id: 2 role: IncomingVoter"] [from_peer="id: 55 store_id: 1 role: DemotingVoter"] [region_id=54]
[2023/01/19 10:19:56.892 +00:00] [INFO] [pd.rs:1521] ["try to transfer leader"] [to_peers="[]"] [to_peer="id: 127 store_id: 2 role: IncomingVoter"] [from_peer="id: 55 store_id: 1 role: DemotingVoter"] [region_id=54]
[2023/01/19 10:19:56.895 +00:00] [INFO] [peer.rs:3319] ["reject to transfer leader"] [last_index=267] [index=266] [reason="pending conf change"] [to="id: 127 store_id: 2 role: Learner"] [peer_id=55] [region_id=54]
[2023/01/19 10:19:56.895 +00:00] [INFO] [peer.rs:3319] ["reject to transfer leader"] [last_index=267] [index=266] [reason="pending conf change"] [to="id: 127 store_id: 2 role: Learner"] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.051 +00:00] [INFO] [pd.rs:1521] ["try to transfer leader"] [to_peers="[]"] [to_peer="id: 127 store_id: 2 role: IncomingVoter"] [from_peer="id: 55 store_id: 1 role: DemotingVoter"] [region_id=54]
[2023/01/19 10:20:02.052 +00:00] [INFO] [peer.rs:3738] ["transfer leader"] [peer="id: 127 store_id: 2 role: IncomingVoter"] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.052 +00:00] [INFO] [raft.rs:1904] ["[term 6] starts to transfer leadership to 127"] [lead_transferee=127] [term=6] [raft_id=55] [region_id=54]
[2023/01/19 10:20:02.052 +00:00] [INFO] [raft.rs:1917] ["sends MsgTimeoutNow to 127 immediately as 127 already has up-to-date log"] [lead_transferee=127] [raft_id=55] [region_id=54]
[2023/01/19 10:20:02.052 +00:00] [INFO] [raft.rs:1364] ["received a message with higher term from 127"] ["msg type"=MsgRequestVote] [message_term=7] [term=6] [from=127] [raft_id=55] [region_id=54]
[2023/01/19 10:20:02.052 +00:00] [INFO] [raft.rs:1120] ["became follower at term 7"] [term=7] [raft_id=55] [region_id=54]
[2023/01/19 10:20:02.052 +00:00] [INFO] [raft.rs:1565] ["[logterm: 6, index: 267, vote: 0] cast vote for 127 [logterm: 6, index: 267] at term 7"] ["msg type"=MsgRequestVote] [term=7] [msg_index=267] [msg_term=6] [from=127] [vote=0] [log_index=267] [log_term=6] [raft_id=55] [region_id=54]
[2023/01/19 10:20:02.052 +00:00] [INFO] [endpoint.rs:404] ["deregister observe region"] [observe_id=ObserveId(35)] [region_id=54] [store_id=Some(1)]
[2023/01/19 10:20:02.052 +00:00] [INFO] [subscription_manager.rs:395] ["backup stream: on_modify_observe"] [op="Stop { region: Region { id: 54, ver: 4, conf_ver: 4, range: [748000FFFFFFFFFFFFFE00000000000000F8,7800000000000000FB), peers: 1,2 } }"]
[2023/01/19 10:20:02.052 +00:00] [INFO] [subscription_manager.rs:395] ["backup stream: on_modify_observe"] [op="Stop { region: Region { id: 54, ver: 4, conf_ver: 4, range: [748000FFFFFFFFFFFFFE00000000000000F8,7800000000000000FB), peers: 1,2 } }"]
[2023/01/19 10:20:02.053 +00:00] [INFO] [apply.rs:1647] ["execute admin command"] [command="cmd_type: ChangePeerV2 change_peer_v2 {}"] [index=269] [term=7] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.053 +00:00] [INFO] [apply.rs:2239] ["exec ConfChangeV2"] [epoch="conf_ver: 4 version: 4"] [kind=LeaveJoint] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.053 +00:00] [INFO] [apply.rs:2450] ["leave joint state successfully"] [region="id: 54 start_key: 748000FFFFFFFFFFFFFE00000000000000F8 end_key: 7800000000000000FB region_epoch { conf_ver: 6 version: 4 } peers { id: 55 store_id: 1 role: Learner } peers { id: 127 store_id: 2 }"] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.062 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {127} }, outgoing: Configuration { voters: {} } }, learners: {55}, learners_next: {}, auto_leave: false }"] [raft_id=55] [region_id=54]
[2023/01/19 10:20:02.062 +00:00] [INFO] [apply.rs:1647] ["execute admin command"] [command="cmd_type: ChangePeerV2 change_peer_v2 { changes { change_type: RemoveNode peer { id: 55 store_id: 1 role: Learner } } }"] [index=270] [term=7] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.062 +00:00] [INFO] [apply.rs:2239] ["exec ConfChangeV2"] [epoch="conf_ver: 6 version: 4"] [kind=Simple] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.062 +00:00] [INFO] [apply.rs:2420] ["conf change successfully"] ["current region"="id: 54 start_key: 748000FFFFFFFFFFFFFE00000000000000F8 end_key: 7800000000000000FB region_epoch { conf_ver: 7 version: 4 } peers { id: 127 store_id: 2 }"] ["original region"="id: 54 start_key: 748000FFFFFFFFFFFFFE00000000000000F8 end_key: 7800000000000000FB region_epoch { conf_ver: 6 version: 4 } peers { id: 55 store_id: 1 role: Learner } peers { id: 127 store_id: 2 }"] [changes="[change_type: RemoveNode peer { id: 55 store_id: 1 role: Learner }]"] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.062 +00:00] [INFO] [router.rs:345] ["[region 54] shutdown mailbox"]
[2023/01/19 10:20:02.069 +00:00] [INFO] [raft.rs:2646] ["switched to configuration"] [config="Configuration { voters: Configuration { incoming: Configuration { voters: {127} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }"] [raft_id=55] [region_id=54]
[2023/01/19 10:20:02.069 +00:00] [INFO] [peer.rs:3580] ["delays destroy"] [reason=UnFlushLogGc] [merged_by_target=false] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.073 +00:00] [INFO] [peer.rs:3590] ["starts destroy"] [merged_by_target=false] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.073 +00:00] [INFO] [peer.rs:1420] ["begin to destroy"] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.073 +00:00] [INFO] [pd.rs:1631] ["remove peer statistic record in pd"] [region_id=54]
[2023/01/19 10:20:02.073 +00:00] [INFO] [peer_storage.rs:1020] ["finish clear peer meta"] [takes=3.709µs] [raft_key=1] [apply_key=1] [meta_key=1] [region_id=54]
[2023/01/19 10:20:02.078 +00:00] [INFO] [peer.rs:1524] ["peer destroy itself"] [keep_data=false] [clean=true] [takes=4.125ms] [peer_id=55] [region_id=54]
[2023/01/19 10:20:02.078 +00:00] [INFO] [router.rs:345] ["[region 54] shutdown mailbox"]
[2023/01/19 10:20:02.078 +00:00] [INFO] [region.rs:602] ["register deleting data in range"] [end_key=7A7800000000000000FB] [start_key=7A748000FFFFFFFFFFFFFE00000000000000F8] [region_id=54]
[2023/01/19 10:20:02.078 +00:00] [INFO] [region.rs:636] ["delete data in range because of stale"] [end_key=7A7800000000000000FB] [start_key=7A748000FFFFFFFFFFFFFE00000000000000F8] [region_id=54]
[2023/01/19 10:20:02.570 +00:00] [WARN] [endpoint.rs:808] [error-response] [err="Region error (will back off and retry) message: \"region 54 is missing\" region_not_found { region_id: 54 }"]
[2023/01/19 10:20:02.571 +00:00] [WARN] [endpoint.rs:808] [error-response] [err="Region error (will back off and retry) message: \"region 54 is missing\" region_not_found { region_id: 54 }"]
[2023/01/19 10:20:06.180 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]
[2023/01/19 10:20:16.182 +00:00] [INFO] [sst_importer.rs:442] ["shrink cache by tick"] ["retain size"=0] ["shrink size"=0]

@mjonss
Copy link
Contributor Author

mjonss commented Jan 19, 2023

Not sure if the pd.log from the leader is needed, but here it comes as well:

372 [2023/01/19 09:56:02.350 +00:00] [INFO] [util.go:83] ["load cluster version"] [cluster-version=6.6.0-alpha]
373 [2023/01/19 09:56:05.841 +00:00] [INFO] [cluster.go:1500] ["store has changed to serving"] [store-id=118] [store-address=127.0.0.1:3931]
374 [2023/01/19 09:56:05.863 +00:00] [INFO] [cluster.go:1500] ["store has changed to serving"] [store-id=119] [store-address=127.0.0.1:3930]
375 [2023/01/19 09:56:45.842 +00:00] [INFO] [store_config.go:200] ["sync the store config successful"] [store-address=127.0.0.1:20182] [store-config="{\n  \"coprocessor\": {\n    \"region-max-size\": \"144MiB\",\n    \"region-split-size\": \"96MiB\",\n    \"region-max-keys\": 1440000,\n    \"region-split-keys\": 960000,\n    \"enable-region-bucket\": false,\n    \"region-bucket-size\": \"96MiB\"\n  }\n}"]
376 [2023/01/19 10:04:54.062 +00:00] [INFO] [trace.go:152] ["trace[1785065534] linearizableReadLoop"] [detail="{readStateIndex:3993; appliedIndex:3993; }"] [duration=101.177792ms] [start=2023/01/19 10:04:53.961 +00:00] [end=2023/01/19 10:04:54.062 +00:00] [steps="[\"trace[1785065534] 'read index received'  (duration: 101.175417ms)\",\"trace[1785065534] 'applied index is now lower than readState.Index'  (duration: 2µs)\"]"]
377 [2023/01/19 10:04:54.062 +00:00] [WARN] [util.go:163] ["apply request took too long"] [took=101.262125ms] [expected-duration=100ms] [prefix="read-only range "] [request="key:\"/topology/tidb/\" range_end:\"/topology/tidb0\" "] [response="range_response_count:4 size:737"] []
378 [2023/01/19 10:04:54.062 +00:00] [INFO] [trace.go:152] ["trace[372756090] range"] [detail="{range_begin:/topology/tidb/; range_end:/topology/tidb0; response_count:4; response_revision:3896; }"] [duration=101.593041ms] [start=2023/01/19 10:04:53.961 +00:00] [end=2023/01/19 10:04:54.062 +00:00] [steps="[\"trace[372756090] 'agreement among raft nodes before linearized reading'  (duration: 101.236375ms)\"]"]
379 [2023/01/19 10:04:54.075 +00:00] [WARN] [util.go:163] ["apply request took too long"] [took=108.864542ms] [expected-duration=100ms] [prefix="read-only range "] [request="key:\"/pd/7190299863336064691/gc/safe_point\" "] [response="range_response_count:0 size:5"] []
380 [2023/01/19 10:04:54.075 +00:00] [INFO] [trace.go:152] ["trace[2142358601] range"] [detail="{range_begin:/pd/7190299863336064691/gc/safe_point; range_end:; response_count:0; response_revision:3898; }"] [duration=109.161958ms] [start=2023/01/19 10:04:53.966 +00:00] [end=2023/01/19 10:04:54.075 +00:00] [steps="[\"trace[2142358601] 'agreement among raft nodes before linearized reading'  (duration: 108.845625ms)\"]"]
381 [2023/01/19 10:05:52.912 +00:00] [INFO] [grpc_service.go:1453] ["update service GC safe point"] [service-id=gc_worker] [expire-at=-9223372035180653057] [safepoint=438861077640904704]
382 [2023/01/19 10:07:32.951 +00:00] [INFO] [grpc_service.go:1405] ["updated gc safe point"] [safe-point=438861077640904704]
383 [2023/01/19 10:09:07.593 +00:00] [INFO] [cluster_worker.go:145] ["alloc ids for region split"] [region-id=120] [peer-ids="[121]"]
384 [2023/01/19 10:09:07.606 +00:00] [INFO] [region.go:679] ["region Version changed"] [region-id=24] [detail="StartKey Changed:{7480000000000000FF5000000000000000F8} -> {7480000000000000FF5200000000000000F8}, EndKey:{748000FFFFFFFFFFFFF900000000000000F8}"] [old-version=45] [new-version=46]
385 [2023/01/19 10:09:07.606 +00:00] [INFO] [cluster_worker.go:237] ["region batch split, generate new regions"] [region-id=24] [origin="id:120 start_key:\"7480000000000000FF5000000000000000F8\" end_key:\"7480000000000000FF5200000000000000F8\" region_epoch:<conf_ver:1 version:46 > peers:<id:121 store_id:1 >"] [total=1]
386 [2023/01/19 10:09:07.630 +00:00] [INFO] [audit.go:126] ["Audit Log"] [service-info="{ServiceLabel:SetRule, Method:HTTP/1.1/POST:/pd/api/v1/config/rule, Component:anonymous, IP:127.0.0.1, StartTime:2023-01-19 10:09:07 +0000 WET, URLParam:{}, BodyParam:{\"group_id\":\"tiflash\",\"id\":\"table-82-r\",\"index\":120,\"start_key\":\"7480000000000000ff525f720000000000fa\",\"end_key\":\"7480000000000000ff5300000000000000f8\",\"r    ole\":\"learner\",\"count\":1,\"label_constraints\":[{\"key\":\"engine\",\"op\":\"in\",\"values\":[\"tiflash\"]}]}}"]
387 [2023/01/19 10:09:07.639 +00:00] [INFO] [rule_manager.go:252] ["placement rule updated"] [rule="{\"group_id\":\"tiflash\",\"id\":\"table-82-r\",\"index\":120,\"start_key\":\"7480000000000000ff525f720000000000fa\",\"end_key\":\"7480000000000000ff5300000000000000f8\",\"role\":\"learner\",\"is_witness\":false,\"count\":1,\"label_constraints\":[{\"key\":\"engine\",\"op\":\"in\",\"values\":[\"tiflash\"]}],\"create_timestamp\"    :1674122947}"]
388 [2023/01/19 10:09:07.639 +00:00] [INFO] [operator_controller.go:452] ["add operator"] [region-id=24] [operator="\"rule-split-region {split: region 24 use policy USEKEY and keys [7480000000000000FF525F720000000000FA 7480000000000000FF5300000000000000F8]} (kind:split, region:24(46, 1), createAt:2023-01-19 10:09:07.639258 +0000 WET m=+805.687592251, startAt:0001-01-01 00:00:00 +0000 UTC, currentStep:0, size:1, steps:[split     region with policy USEKEY],timeout:[1m0s])\""] [additional-info="{\"region-end-key\":\"748000FFFFFFFFFFFFF900000000000000F8\",\"region-start-key\":\"7480000000000000FF5200000000000000F8\"}"]
389 [2023/01/19 10:09:07.639 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=24] [step="split region with policy USEKEY"] [source=create]
390 [2023/01/19 10:09:07.639 +00:00] [INFO] [cluster_worker.go:145] ["alloc ids for region split"] [region-id=122] [peer-ids="[123]"]
391 [2023/01/19 10:09:07.639 +00:00] [INFO] [cluster_worker.go:145] ["alloc ids for region split"] [region-id=124] [peer-ids="[125]"]
392 [2023/01/19 10:09:07.644 +00:00] [INFO] [cluster_worker.go:237] ["region batch split, generate new regions"] [region-id=24] [origin="id:122 start_key:\"7480000000000000FF5200000000000000F8\" end_key:\"7480000000000000FF525F720000000000FA\" region_epoch:<conf_ver:1 version:48 > peers:<id:123 store_id:1 > id:124 start_key:\"7480000000000000FF525F720000000000FA\" end_key:\"7480000000000000FF5300000000000000F8\" region_epoch    :<conf_ver:1 version:48 > peers:<id:125 store_id:1 >"] [total=2]
393 [2023/01/19 10:09:07.644 +00:00] [INFO] [region.go:679] ["region Version changed"] [region-id=24] [detail="StartKey Changed:{7480000000000000FF5200000000000000F8} -> {7480000000000000FF5300000000000000F8}, EndKey:{748000FFFFFFFFFFFFF900000000000000F8}"] [old-version=46] [new-version=48]
394 [2023/01/19 10:09:07.644 +00:00] [INFO] [operator_controller.go:565] ["operator finish"] [region-id=24] [takes=4.853958ms] [operator="\"rule-split-region {split: region 24 use policy USEKEY and keys [7480000000000000FF525F720000000000FA 7480000000000000FF5300000000000000F8]} (kind:split, region:24(46, 1), createAt:2023-01-19 10:09:07.639258 +0000 WET m=+805.687592251, startAt:2023-01-19 10:09:07.639393 +0000 WET m=+805.6    87726501, currentStep:1, size:1, steps:[split region with policy USEKEY],timeout:[1m0s]) finished\""] [additional-info="{\"region-end-key\":\"748000FFFFFFFFFFFFF900000000000000F8\",\"region-start-key\":\"7480000000000000FF5200000000000000F8\"}"]
395 [2023/01/19 10:09:07.648 +00:00] [INFO] [operator_controller.go:452] ["add operator"] [region-id=124] [operator="\"add-rule-peer {add peer: store [119]} (kind:replica,region, region:124(48, 1), createAt:2023-01-19 10:09:07.64892 +0000 WET m=+805.697253417, startAt:0001-01-01 00:00:00 +0000 UTC, currentStep:0, size:1, steps:[add learner peer 126 on store 119],timeout:[10m0s])\""] [additional-info=]
396 [2023/01/19 10:09:07.651 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=124] [step="add learner peer 126 on store 119"] [source=create]
397 [2023/01/19 10:09:07.659 +00:00] [INFO] [region.go:690] ["region ConfVer changed"] [region-id=124] [detail="Add peer:{id:126 store_id:119 role:Learner }"] [old-confver=1] [new-confver=2]
398 [2023/01/19 10:09:07.662 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=124] [step="add learner peer 126 on store 119"] [source=heartbeat]
399 [2023/01/19 10:09:07.911 +00:00] [INFO] [operator_controller.go:565] ["operator finish"] [region-id=124] [takes=260.301958ms] [operator="\"add-rule-peer {add peer: store [119]} (kind:replica,region, region:124(48, 1), createAt:2023-01-19 10:09:07.64892 +0000 WET m=+805.697253417, startAt:2023-01-19 10:09:07.651293 +0000 WET m=+805.699627001, currentStep:1, size:1, steps:[add learner peer 126 on store 119],timeout:[10m0s    ]) finished\""] [additional-info=]
400 [2023/01/19 10:15:52.896 +00:00] [INFO] [grpc_service.go:1453] ["update service GC safe point"] [service-id=gc_worker] [expire-at=-9223372035180652457] [safepoint=438861234928091136]
401 [2023/01/19 10:17:32.920 +00:00] [INFO] [grpc_service.go:1405] ["updated gc safe point"] [safe-point=438861234928091136]
402 [2023/01/19 10:19:56.793 +00:00] [INFO] [operator_controller.go:452] ["add operator"] [region-id=54] [operator="\"move-hot-read-leader {mv peer: store [1] to [2]} (kind:hot-region,region,leader, region:54(4, 1), createAt:2023-01-19 10:19:56.793794 +0000 WET m=+1454.821922167, startAt:0001-01-01 00:00:00 +0000 UTC, currentStep:0, size:1, steps:[add learner peer 127 on store 2, use joint consensus, promote learner peer 127     on store 2 to voter, demote voter peer 55 on store 1 to learner, transfer leader from store 1 to store 2, leave joint state, promote learner peer 127 on store 2 to voter, demote voter peer 55 on store 1 to learner, remove peer on store 1],timeout:[18m0s])\""] [additional-info=]
403 [2023/01/19 10:19:56.794 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=54] [step="add learner peer 127 on store 2"] [source=create]
404 [2023/01/19 10:19:56.799 +00:00] [INFO] [region.go:690] ["region ConfVer changed"] [region-id=54] [detail="Add peer:{id:127 store_id:2 role:Learner }"] [old-confver=1] [new-confver=2]
405 [2023/01/19 10:19:56.799 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=54] [step="add learner peer 127 on store 2"] [source=heartbeat]
406 [2023/01/19 10:19:56.888 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=54] [step="use joint consensus, promote learner peer 127 on store 2 to voter, demote voter peer 55 on store 1 to learner"] [source=heartbeat]
407 [2023/01/19 10:19:56.892 +00:00] [INFO] [region.go:690] ["region ConfVer changed"] [region-id=54] [detail="Remove peer:{id:55 store_id:1 },Remove peer:{id:127 store_id:2 role:Learner },Add peer:{id:55 store_id:1 role:DemotingVoter },Add peer:{id:127 store_id:2 role:IncomingVoter }"] [old-confver=2] [new-confver=4]
408 [2023/01/19 10:19:56.892 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=54] [step="transfer leader from store 1 to store 2"] [source=heartbeat]
409 [2023/01/19 10:19:56.892 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=54] [step="transfer leader from store 1 to store 2"] [source=heartbeat]
410 [2023/01/19 10:20:02.051 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=54] [step="transfer leader from store 1 to store 2"] [source="active push"]
411 [2023/01/19 10:20:02.052 +00:00] [INFO] [region.go:703] ["leader changed"] [region-id=54] [from=1] [to=2]
412 [2023/01/19 10:20:02.052 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=54] [step="leave joint state, promote learner peer 127 on store 2 to voter, demote voter peer 55 on store 1 to learner"] [source=heartbeat]
413 [2023/01/19 10:20:02.053 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=54] [step="leave joint state, promote learner peer 127 on store 2 to voter, demote voter peer 55 on store 1 to learner"] [source=heartbeat]
414 [2023/01/19 10:20:02.058 +00:00] [INFO] [region.go:690] ["region ConfVer changed"] [region-id=54] [detail="Remove peer:{id:55 store_id:1 role:DemotingVoter },Remove peer:{id:127 store_id:2 role:IncomingVoter },Add peer:{id:55 store_id:1 role:Learner },Add peer:{id:127 store_id:2 }"] [old-confver=4] [new-confver=6]
415 [2023/01/19 10:20:02.058 +00:00] [INFO] [operator_controller.go:651] ["send schedule command"] [region-id=54] [step="remove peer on store 1"] [source=heartbeat]
416 [2023/01/19 10:20:02.065 +00:00] [INFO] [region.go:690] ["region ConfVer changed"] [region-id=54] [detail="Remove peer:{id:55 store_id:1 role:Learner }"] [old-confver=6] [new-confver=7]
417 [2023/01/19 10:20:02.066 +00:00] [INFO] [operator_controller.go:565] ["operator finish"] [region-id=54] [takes=5.270362708s] [operator="\"move-hot-read-leader {mv peer: store [1] to [2]} (kind:hot-region,region,leader, region:54(4, 1), createAt:2023-01-19 10:19:56.793794 +0000 WET m=+1454.821922167, startAt:2023-01-19 10:19:56.794811 +0000 WET m=+1454.822938751, currentStep:5, size:1, steps:[add learner peer 127 on store     2, use joint consensus, promote learner peer 127 on store 2 to voter, demote voter peer 55 on store 1 to learner, transfer leader from store 1 to store 2, leave joint state, promote learner peer 127 on store 2 to voter, demote voter peer 55 on store 1 to learner, remove peer on store 1],timeout:[18m0s]) finished\""] [additional-info=]
418 [2023/01/19 10:25:52.924 +00:00] [INFO] [grpc_service.go:1453] ["update service GC safe point"] [service-id=gc_worker] [expire-at=-9223372035180651857] [safepoint=438861392220782592]
419 [2023/01/19 10:27:32.966 +00:00] [INFO] [grpc_service.go:1405] ["updated gc safe point"] [safe-point=438861392220782592]

@JaySon-Huang
Copy link
Contributor

JaySon-Huang commented Jan 20, 2023

[2023/01/19 10:14:02.772 +00:00] [WARN] [PathCapacityMetrics.cpp:196] ["Available space is only 3.09% of capacity size. Avail size: 14.24 GiB, used size: 396.00 B, capacity size: 460.43 GiB"] [source=PathCapacityMetrics] [thread_id=8]
...
[2023/01/19 10:14:09.133 +00:00] [DEBUG] [ProxyFFIStatusService.cpp:86] ["table_id=82, total_region_count=1, ready_region_count=0, lag_region_info=lag_region_id=124, leader_safe_ts=438861364859502593, self_safe_ts=438861286818971651; "] [source=operator()] [thread_id=26]

Seems the available size of tiflash deploy disk is very limited, and the raft log sync is lagged. @mjonss You can try adding a config to workaround this issue: storage.main.capacity: [1073741824] to limit the capacity size (by default it is the total size of the deploy disk).

## The maximum storage capacity of each directory in storage.main.dir.
## If it is not set, or is set to multiple 0, the actual disk (the disk where the directory is located) capacity is used.
## Note that human-readable numbers such as "10GB" are not supported yet.
## Numbers are specified in bytes.
## The size of the capacity list should be the same with the dir size.
## For example:
# capacity = [ 10737418240, 10737418240 ]

Or deploy tiflash into a disk that has enough available space.

@JaySon-Huang
Copy link
Contributor

JaySon-Huang commented Jan 20, 2023

When the raft log sync is lagged, the progress shown in information_schema.tiflash_replica should be less than 1. But it is shown as "1.0" in the previous comment.

@mjonss Can you wait for a minute after the tiflash query raise region error and check the progress field shown in information_schema.tiflash_replica again?
/cc @hehechen

@mjonss
Copy link
Contributor Author

mjonss commented Jan 31, 2023

So I assume this bug is related to free disk available on the TiFlash nodes. Having enough free space does not trigger this issue.

@hehechen
Copy link
Contributor

hehechen commented Feb 3, 2023

So I assume this bug is related to free disk available on the TiFlash nodes. Having enough free space does not trigger this issue.

PD has low-space-ratio configuration, if disk usage of TiFlash store reaches this threshold, PD will not add learner peer in this store.

@Lloyd-Pottiger
Copy link
Contributor

The progress shown in information_schema.tiflash_replica seems not accurate. It should be less than 1.0, but it shown as 1.0 🤔 @hehechen

@hehechen
Copy link
Contributor

hehechen commented Feb 3, 2023

The progress shown in information_schema.tiflash_replica seems not accurate. It should be less than 1.0, but it shown as 1.0 🤔 @hehechen

It should be less than 1.0 after several minutes. @mjonss Did you wait for several minutes after the tiflash query raise region error and check the progress field shown ?

@mjonss
Copy link
Contributor Author

mjonss commented May 11, 2023

Can no longer reproduce, probably issue with disk space.

@mjonss mjonss closed this as completed May 11, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
severity/minor type/bug The issue is confirmed as a bug.
Projects
None yet
Development

No branches or pull requests

6 participants