PD GC Safe Point Calculation Bug: Negative expire-at Value Causes RPC Failures and PD/TSO Disruption
- Dominant language
- Go
- Stars
- 40.5k
- Forks
- 6.2k
- PR merge metrics
- PR metrics pending
Description
## Bug Report
Please answer these questions before submitting your issue. Thanks!
### 1. Minimal reproduce step (Required)
1. **Cluster Deployment:**
Deploy a TiDB cluster with the following components:
- **PD Node (node0):**
- Endpoint: `http://166.18.0.11:2379`
- *Note: The cluster uses only one PD node.*
- **TiKV Nodes:** At least two nodes (e.g., node1 and node2).
- **TiDB Server:** Running on node1, configured to use TiKV with PD path `166.18.0.11:2379`.
2. **Cluster Settings:**
The current cluster store configuration (as returned by `pd-ctl -u http://166.18.0.11:2379 store`) is:
```json
{
"count": 4,
"stores": [
{
"store": {
"id": 1,
"address": "166.18.0.21:20160",
"version": "8.5.0-alpha",
"peer_address": "166.18.0.21:20160",
"status_address": "127.0.0.1:20180",
"git_hash": "Unknown git hash",
"start_timestamp": 1738456813,
"deploy_path": "/usr/local/bin",
"last_heartbeat": 1740397833572457060,
"state_name": "Up"
},
"status": {
"capacity": "1.441TiB",
"available": "233.1GiB",
"used_size": "480.1MiB",
"leader_count": 0,
"leader_weight": 1,
"leader_score": 0,
"leader_size": 0,
"region_count": 2,
"region_weight": 1,
"region_score": 2100005669.7473407,
"region_size": 241,
"slow_score": 1,
"slow_trend": {
"cause_value": 250048.56655290103,
"cause_rate": 0,
"result_value": 0,
"result_rate": 0
},
"start_ts": "2025-02-02T08:40:13+08:00",
"last_heartbeat_ts": "2025-02-24T19:50:33.57245706+08:00",
"uptime": "539h10m20.57245706s"
}
},
{
"store": {
"id": 130,
"address": "166.18.0.22:20160",
"version": "8.5.0-alpha",
"peer_address": "166.18.0.22:20160",
"status_address": "127.0.0.1:20180",
"git_hash": "Unknown git hash",
"start_timestamp": 1738456858,
"deploy_path": "/usr/local/bin",
"last_heartbeat": 1740397828780808752,
"state_name": "Up"
},
"status": {
"capacity": "1.441TiB",
"available": "233.1GiB",
"used_size": "473.3MiB",
"leader_count": 3,
"leader_weight": 1,
"leader_score": 3,
"leader_size": 242,
"region_count": 5,
"region_weight": 1,
"region_score": 2100005737.90182,
"region_size": 244,
"slow_score": 1,
"slow_trend": {
"cause_value": 250055.40273037544,
"cause_rate": 0,
"result_value": 36.5,
"result_rate": 0
},
"start_ts": "2025-02-02T08:40:58+08:00",
"last_heartbeat_ts": "2025-02-24T19:50:28.780808752+08:00",
"uptime": "539h9m30.780808752s"
}
},
{
"store": {
"id": 195,
"address": "166.18.0.23:20160",
"version": "8.5.0-alpha",
"peer_address": "166.18.0.23:20160",
"status_address": "127.0.0.1:20180",
"git_hash": "Unknown git hash",
"start_timestamp": 1736939894,
"deploy_path": "/usr/local/bin",
"last_heartbeat": 1740397833821703738,
"state_name": "Up"
},
"status": {
"capacity": "1.441TiB",
"available": "233.1GiB",
"used_size": "476MiB",
"leader_count": 2,
"leader_weight": 1,
"leader_score": 2,
"leader_size": 2,
"region_count": 4,
"region_weight": 1,
"region_score": 2100005483.4373696,
"region_size": 157,
"slow_score": 1,
"slow_trend": {
"cause_value": 250045.62457337885,
"cause_rate": 0,
"result_value": 0,
"result_rate": 0
},
"start_ts": "2025-01-15T19:18:14+08:00",
"last_heartbeat_ts": "2025-02-24T19:50:33.821703738+08:00",
"uptime": "960h32m19.821703738s"
}
},
{
"store": {
"id": 260,
"address": "166.18.0.24:20160",
"version": "8.5.0-alpha",
"peer_address": "166.18.0.24:20160",
"status_address": "127.0.0.1:20180",
"git_hash": "Unknown git hash",
"start_timestamp": 1736939933,
"deploy_path": "/usr/local/bin",
"last_heartbeat": 1740397833182651508,
"state_name": "Up"
},
"status": {
"capacity": "1.441TiB",
"available": "233.1GiB",
"used_size": "485.1MiB",
"leader_count": 0,
"leader_weight": 1,
"leader_score": 0,
"leader_size": 0,
"region_count": 4,
"region_weight": 1,
"region_score": 2100005328.422923,
"region_size": 90,
"slow_score": 1,
"slow_trend": {
"cause_value": 250030.39726027398,
"cause_rate": 0,
"result_value": 0,
"result_rate": 0
},
"start_ts": "2025-01-15T19:18:53+08:00",
"last_heartbeat_ts": "2025-02-24T19:50:33.182651508+08:00",
"uptime": "960h31m40.182651508s"
}
}
]
}
3. Log Observation:
Observe the logs for each component. Critical log excerpts include:
PD Node (node0) Logs:
```txt
[2025/02/18 15:20:17.497 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/settings] [range-end=resource_group/settingt] [start-revision=2866522]
[2025/02/18 15:20:17.497 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/controller] [range-end=resource_group/controlles] [start-revision=2866522]
[2025/02/18 15:21:20.682 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/settings] [range-end=resource_group/settingt] [start-revision=2866588]
[2025/02/18 15:21:20.682 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/controller] [range-end=resource_group/controlles] [start-revision=2866588]
[2025/02/18 15:22:16.970 +08:00] [INFO] [grpc_service.go:2230] ["update service GC safe point"] [service-id=gc_worker] [expire-at=-9223372035114912473] [safepoint=456094577311612928]
[2025/02/18 15:22:23.860 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/settings] [range-end=resource_group/settingt] [start-revision=2866662]
[2025/02/18 15:22:23.860 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/controller] [range-end=resource_group/controlles] [start-revision=2866662]
[2025/02/18 15:23:27.092 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/controller] [range-end=resource_group/controlles] [start-revision=2866732]
[2025/02/18 15:23:27.092 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/settings] [range-end=resource_group/settingt] [start-revision=2866732]
[2025/02/18 15:23:57.028 +08:00] [INFO] [grpc_service.go:2174] ["updated gc safe point"] [safe-point=456094577311612928]
[2025/02/18 15:24:30.274 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/settings] [range-end=resource_group/settingt] [start-revision=2866803]
[2025/02/18 15:24:30.274 +08:00] [INFO] [grpc_service.go:96] ["watch request"] [key=resource_group/controller] [range-end=resource_group/controlles] [start-revision=2866803]
```
TiKV Node (node2) Logs:
```txt
[2025/02/18 15:21:22.772 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=7]
[2025/02/18 15:22:26.003 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=8]
[2025/02/18 15:22:26.003 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=9]
[2025/02/18 15:22:26.003 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=11]
[2025/02/18 15:22:26.003 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=7]
[2025/02/18 15:23:29.181 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=8]
[2025/02/18 15:23:29.181 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=7]
[2025/02/18 15:23:29.181 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=11]
[2025/02/18 15:23:29.181 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=10]
[2025/02/18 15:24:32.362 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=10]
[2025/02/18 15:24:32.362 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=11]
[2025/02/18 15:24:32.362 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=9]
```
TiDB Node (node2) Logs:
```txt
[2025/02/18 00:15:04.908 +08:00] [INFO] [advancer.go:664] ["No tasks yet, skipping advancing."]
[2025/02/18 00:15:16.908 +08:00] [INFO] [advancer.go:664] ["No tasks yet, skipping advancing."]
[2025/02/18 00:15:22.955 +08:00] [INFO] [queue.go:319] ["Start to fetch DML changes of tables"] [category=stats] [sampled=]
[2025/02/18 00:15:28.908 +08:00] [INFO] [advancer.go:664] ["No tasks yet, skipping advancing."]
[2025/02/18 00:15:40.908 +08:00] [INFO] [advancer.go:664] ["No tasks yet, skipping advancing."]
```
4. (Optional) Stress Testing:
If the issue is not immediately reproducible, trigger additional GC activities (e.g., frequent DDL operations or heavy workload) to force a GC safe point update and check if PD produces a negative expire-at value.
### 2. What did you expect to see? (Required)
Correct GC Safe Point Calculation:
PD should compute and update the GC safe point with a valid, positive expire-at timestamp.
Stable RPC Communication:
TiKV should process batch_commands without "RemoteStopped" errors.
Normal Cluster Operation:
Resource group watch requests and PD/TSO communication should work normally.
### 3. What did you see instead (Required)
Abnormal GC Safe Point Update in PD:
At 15:22:16.970, PD logs show:
```txt
[2025/02/18 15:22:16.970 +08:00] [INFO] [grpc_service.go:2230] ["update service GC safe point"] [service-id=gc_worker] [expire-at=-9223372035114912473] [safepoint=456094577311612928]
The expire-at value is an extremely negative number, indicating an integer underflow or miscalculation.
```
RPC Failures on TiKV:
Shortly after, TiKV logs repeatedly report:
```txt
[2025/02/18 15:22:26.003 +08:00] [INFO] [kv.rs:1083] ["kv rpc failed"] [err=RemoteStopped] [request=batch_commands] [thread_id=...]
This suggests that the invalid GC safe point is causing RPC failures.
```
PD/TSO Communication Disruption:
TiDB logs indicate context cancellations and PD service discovery errors (e.g., "context canceled"), implying that the abnormal GC safe point update is affecting overall cluster coordination.
### 4. What is your TiDB version? (Required)
TiDB Version: v9.0.0-alpha-100-g91706ec8df-dirty
Git Commit Hash: 91706ec8dfbf3fd07fe1643cf0d0b6eb2d67eb83
Git Branch: master
UTC Build Time: 2025-02-08 13:04:09
### Additional Information
Potential Cause:
The negative expire-at value suggests an error in PD’s GC safe point update logic—possibly due to an integer underflow or improper timestamp arithmetic. While the safe point (456094577311612928) appears plausible, the expiration timestamp is invalid.
Impact:
Repeated "RemoteStopped" RPC errors on TiKV.
Disruption of PD/TSO communication, causing context cancellations and instability.
Potential risk to GC operations and data consistency across the cluster.
Request:
Please review the GC safe point update logic in PD. Consider:
Validating arithmetic operations to prevent integer underflow.
Adding safeguards to ensure expire-at is a valid, positive timestamp.
Ensuring that appropriate data types are used in time calculations.
Contributor guide
Assessment
This issue has not been assessed yet.