Bug Type (问题类型)
server status (启动/运行异常)
Before submit
Environment (环境信息)
- Server Version: apache/hugegraph master
36811483; the behaviour is identical in 1.7.0 and 1.5.0 (HgStoreClientConst.NODE_MAX_RETRYING_TIMES = 10 and HgStoreClientConfig.GRPC_DEFAULT_TIMEOUT_SECONDS = 100 are unchanged since 1.5.0)
- Backend: hstore, PD + 3 store nodes on 3 VMs (Debian, Temurin 17 for PD/store, Temurin 11 for the server), server with 16 REST workers (8 CPUs),
restserver.request_timeout at its default 30 s
- Also observed on a separate POC deployment with
grpc.timeout.seconds=60: PUT /graph/vertices/batch → 500 DEADLINE_EXCEEDED: deadline exceeded after 59.97s ... remote_addr=<store>:8500 in HgStoreStreamBlockingStub.scanBatchOneShot, after which the REST server stopped answering any request
Expected & Actual behavior (期望与实际表现)
Expected: when one store node stops answering (GC pause, write stall, hung process), requests that touch its partitions fail after one gRPC deadline or after restserver.request_timeout, and the server keeps serving everything else.
Actual: every write whose commit lands on a partition of the unreachable store holds a REST worker thread for 11 × grpc.timeout.seconds + 38 s (about 19 minutes on defaults, 12 minutes with 60 s), and restserver.request_timeout does not stop it. At a moderate write rate the worker pool fills within tens of seconds and LoadDetectFilter answers 503 to everything, reads and writes to healthy partitions included, and keeps doing so for minutes after the client stops writing.
Cause, hg-store-client, NodeTxExecutor.retryingInvoke():
- The commit is retried up to
NODE_MAX_RETRYING_TIMES = 10 (a constant, not configurable) with a sleep schedule of 1, 1, 1, 2, 3, 4, 5, 6, 7, 8 s, and every attempt is a blocking HgStoreSessionBlockingStub.batch call with the grpc.timeout.seconds deadline. After a DEADLINE_EXCEEDED the next attempt only waits the full deadline again.
- The
InterruptedException from Thread.sleep is caught, logged as Failed to sleep, and the loop continues. The interrupt that restserver.request_timeout sends to the Grizzly worker is therefore swallowed, and the REST request time limit is ineffective on exactly this path.
Related, not addressed here: a multi-id read (HstoreTable.query → getWithBatch → batchPrefix → one blocking scanBatchOneShot per store) has no retry and no isolation of a single store, so one unreachable node fails the whole read, including the ids that live on healthy stores. That is the path in the POC stack trace above; it does not change the conclusion, because the interrupt does work there.
Reproduction (deterministic, no need to wait for a real outage):
# 1. on one store node
kill -STOP $(pgrep -f "Dname=HugeGraphStore")
# 2. on the server: one POST /graph/vertices per second for 300 s, each in its own thread,
# and a probe GET /graph/vertices/"<id>" every 2 s, also after the writes stop
# 3. kill -CONT
Measured on the cluster above with grpc.timeout.seconds=20 so that one run fits in minutes:
|
master 36811483 |
with the fix below |
| REST unavailable (probe gets 503) |
431 of 503 s |
12 of 300 s |
| REST still dead after the writer stopped |
200 s |
0 s |
| 300 writes |
27 × 201, 243 × 503, 23 × 500 |
131 × 201, 152 × 500 after 20.0 s, 7 × 503 |
| slowest write |
257 s (= 11 × 20 + 38) |
20.1 s |
| server log |
Failed to sleep ×30, reached the upper limit ×30 |
Failed to sleep 0, Not retrying after ×152 |
kill -CONT restores the cluster without a restart in both cases. Scripts and full logs: hugegraph-validation, finding F15.
Proposed fix (PR in preparation): in retryingInvoke abort the loop when the thread is interrupted (restoring the interrupt flag) and do not retry after DEADLINE_EXCEEDED or CANCELLED; keep retrying UNAVAILABLE and other transport errors as today, since #3130 relies on that. Separately worth considering: moving the attempt count and the schedule into HgStoreClientConfig.
Vertex/Edge example (问题点 / 边数据举例)
Any vertex write whose id maps to a partition of the unreachable store; in the measurement, label node with CUSTOMIZE_STRING ids and no properties.
Schema [VertexLabel, EdgeLabel, IndexLabel] (元数据结构)
vertexLabel("node").useCustomizeStringId().create(); the problem does not depend on the schema.
Bug Type (问题类型)
server status (启动/运行异常)
Before submit
Environment (环境信息)
36811483; the behaviour is identical in 1.7.0 and 1.5.0 (HgStoreClientConst.NODE_MAX_RETRYING_TIMES = 10andHgStoreClientConfig.GRPC_DEFAULT_TIMEOUT_SECONDS = 100are unchanged since 1.5.0)restserver.request_timeoutat its default 30 sgrpc.timeout.seconds=60:PUT /graph/vertices/batch→ 500DEADLINE_EXCEEDED: deadline exceeded after 59.97s ... remote_addr=<store>:8500inHgStoreStreamBlockingStub.scanBatchOneShot, after which the REST server stopped answering any requestExpected & Actual behavior (期望与实际表现)
Expected: when one store node stops answering (GC pause, write stall, hung process), requests that touch its partitions fail after one gRPC deadline or after
restserver.request_timeout, and the server keeps serving everything else.Actual: every write whose commit lands on a partition of the unreachable store holds a REST worker thread for
11 × grpc.timeout.seconds + 38 s(about 19 minutes on defaults, 12 minutes with 60 s), andrestserver.request_timeoutdoes not stop it. At a moderate write rate the worker pool fills within tens of seconds andLoadDetectFilteranswers 503 to everything, reads and writes to healthy partitions included, and keeps doing so for minutes after the client stops writing.Cause,
hg-store-client,NodeTxExecutor.retryingInvoke():NODE_MAX_RETRYING_TIMES = 10(a constant, not configurable) with a sleep schedule of 1, 1, 1, 2, 3, 4, 5, 6, 7, 8 s, and every attempt is a blockingHgStoreSessionBlockingStub.batchcall with thegrpc.timeout.secondsdeadline. After aDEADLINE_EXCEEDEDthe next attempt only waits the full deadline again.InterruptedExceptionfromThread.sleepis caught, logged asFailed to sleep, and the loop continues. The interrupt thatrestserver.request_timeoutsends to the Grizzly worker is therefore swallowed, and the REST request time limit is ineffective on exactly this path.Related, not addressed here: a multi-id read (
HstoreTable.query→getWithBatch→batchPrefix→ one blockingscanBatchOneShotper store) has no retry and no isolation of a single store, so one unreachable node fails the whole read, including the ids that live on healthy stores. That is the path in the POC stack trace above; it does not change the conclusion, because the interrupt does work there.Reproduction (deterministic, no need to wait for a real outage):
Measured on the cluster above with
grpc.timeout.seconds=20so that one run fits in minutes:36811483Failed to sleep×30,reached the upper limit×30Failed to sleep0,Not retrying after×152kill -CONTrestores the cluster without a restart in both cases. Scripts and full logs: hugegraph-validation, finding F15.Proposed fix (PR in preparation): in
retryingInvokeabort the loop when the thread is interrupted (restoring the interrupt flag) and do not retry afterDEADLINE_EXCEEDEDorCANCELLED; keep retryingUNAVAILABLEand other transport errors as today, since #3130 relies on that. Separately worth considering: moving the attempt count and the schedule intoHgStoreClientConfig.Vertex/Edge example (问题点 / 边数据举例)
Any vertex write whose id maps to a partition of the unreachable store; in the measurement, label
nodewithCUSTOMIZE_STRINGids and no properties.Schema [VertexLabel, EdgeLabel, IndexLabel] (元数据结构)
vertexLabel("node").useCustomizeStringId().create(); the problem does not depend on the schema.