[YSQL] Sysbench read_only workload is failing on 2.19.3.0-b76 onwards #19090
Assignees
Labels
area/docdb
YugabyteDB core features
kind/enhancement
This is an enhancement of an existing feature
priority/medium
Medium priority issue
Comments
sonalsagarwal
added
area/ysql
yugabyte-ci
added
kind/enhancement
rthallamko3
added
area/docdb
mbautin
added a commit
that referenced
this issue
Sep 14, 2023
Summary: Disable reactor-based outbound call expiration by default because it causes sysbench perf test failures. Test Plan: Jenkins Reviewers: bogdan, mlillibridge Reviewed By: bogdan Subscribers: ybase Differential Revision: https://phorge.dev.yugabyte.com/D28515
mbautin
added a commit
to mbautin/yugabyte-db
that referenced
this issue
Sep 16, 2023
Summary: Fix memory leak in tracked_outbound_calls_ in Reactor by cleaning up that data structure more aggressively. Test Plan: Jenkins Local sysbench Reviewers: sergei Subscribers: ybase Differential Revision: https://phorge.dev.yugabyte.com/D28531
mbautin
added a commit
that referenced
this issue
Sep 17, 2023
Summary: Fix a memory leak in tracked_outbound_calls_ in Reactor by cleaning up that data structure more aggressively: - When traversing tracked calls in the order of increasing next check time, even if it already greater than the current time, stay in the loop and continue removing entries where the callback has been called or the weak pointer has expired. - When a callback is invoked, notify the reactor through a multi-producer single-consumer queue that is accessed from the OutboundCall via a weak pointer. Also remove the FinalizeTrackedCall function that was likely useless because it was called concurrently with the callback being handled by the thread pool. In addition, we are switching OutboundCall allocation away from using make_shared to prevent long-lived weak OutboundCall pointers from consuming memory. Test Plan: Jenkins Local sysbench testing: ``` ./yb_build.sh release --no-tests --skip-java bin/yb-ctl wipe_restart --tserver_flag="memory_limit_hard_bytes=$(( 4 * 1024 * 1024 * 1024 ))" bin/yb-ctl add_node bin/yb-ctl add_node ``` Verify we have 3 nodes: ``` bin/yb-ctl status ``` Run sysbench with a table size of 1000000 using a modified version of the run_sysbench.sh script ( https://gist.githubusercontent.com/mbautin/6f0d441b28479232bd2af9b434bed242/raw ) ``` ./run_sysbench.sh --tablesize 1000000 ``` Wait until the run completes. Check the logs for errors (there should be none): ``` find ~/yugabyte-data -name "yb-tserver.INFO" -exec grep -E "Stuck|large number" {} \; ``` Reviewers: sergei Reviewed By: sergei Subscribers: yql, ybase Differential Revision: https://phorge.dev.yugabyte.com/D28531
1 task
mbautin
added a commit
to mbautin/yugabyte-db
that referenced
this issue
Oct 10, 2023
…actor level
Summary:
Track all outbound calls submitted to a Reactor in a multi-index container in that reactor. Remove them from the container as soon as we learn the callback has been called. Report stuck calls with detailed debug information. A call is considered stuck if it is a certain time past its expiration (specified by reactor_based_outbound_call_expiration_delay_ms -- set it to 0 to disable this feature). If the call does not have a timeout, the default value stuck_outbound_call_default_timeout_sec is used for reporting only, but not for timeout enforcement.
OutboundCall now keeps track of its expiration deadline, and an additional field active_call_state_, which indicates whether the call was added to the connection's active_calls_ in the corresponding connection, or removed from it, and the removal reason.
If in the OutboundCall destructor the state of the call is not final, or the callback has not been called, we will log that even in release build.
In OutboundCall::SetState, if the current state is already finished, treat this the same as any other invalid state transition. Logically, there should never be a race between e.g. processing a call response and a call timeout, because both events happen on the reactor thread.
Fixing error handling in DoQueueOutboundData. If there is an error sending the call, we destroy the connection.
Introduce a typedef CallHandle and a special value kUnknownCallHandle instead of just using the max value of size_t in case the call handle is unknown or not being used. Change the error handling logic in Connection::DoQueueOutboundData to avoid returning kUnknownCallHandle in case of errors, and make sure the callback is called on the call in case of those errors. The connection was already being shut down.
Update the YB_STRUCT_TO_STRING macro implementation to always add parentheses around an explicitly specified field value.
We introduce multiple ways to simulate stuck outbound calls for testing.
- TEST_simulated_sent_stuck_call_probability specifies the probability of pretending a call is sent to the remote server in `Connection::QueueOutboundCall`, but instead just transitioning it to a SENT state. This is similar to the situation that we have observed.
- TEST_simulated_failure_to_send_call_probability specifies the probability of a network error in `stream_->Send()` called from `Connection::DoQueueOutboundData`. This will cause the connection to be closed. Prior to this revision, this kind of an error would cause `Connection::QueueOutboundCall` to attempt to schedule a timer in a connection that has already been shut down.
- TEST_outbound_call_skip_callback_probability specifies the probability of skipping calling the callback on a particular remote RPC call. We don't do this for local calls.
Also replacing a DFATAL with an WARNING log in InboundCall::QueueResponse to avoid crashing tests during shutdown. Failures to queue a response on the server side should just result in timeouts on the client side in the worst case.
Test Plan:
Jenkins
Manual testing details below.
First test mode
===============
```
bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_sent_stuck_call_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3
java -jar yb-sample-apps.jar --workload CassandraBatchKeyValue --nodes 127.0.0.1:9042,127.0.0.2:9042,127.0.0.3:9042 --num_threads_read 16 --num_threads_write 16 --num_reads 1000000000000 --num_writes 1000000000000
```
Look for output like this in the logs:
```
W0907 06:27:34.604096 54296 connection.cc:302] Connection (0x0000147cbdb4de18) client 127.0.0.1:51949 => 127.0.0.2:9100: Simulating a call stuck in SENT state: RPC call 0x0000147cba7f4de0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 5 protocol: 0x00007f276aefeb60 -> tcpc }, id: 7840, state: SENT, transfer_state: PENDING, start_time: 3491.468s (0.001s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: +inf, now: 3491.469s, connection: Connection (0x0000147cbdb4de18) client 127.0.0.1:51949 => 127.0.0.2:9100, active_call_state: kNotAdded
...
W0907 06:27:38.667785 54296 reactor.cc:676] TabletServer_R010: Stuck OutboundCall: RPC call 0x0000147cba7f4de0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 5 protocol: 0x00007f276aefeb60 -> tcpc }, id: 7840, state: SENT, transfer_state: PENDING, start_time: 3491.468s (4.064s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: 3494.469s (1.063s ago), now: 3495.532s, connection: Connection (0x0000147cbdb4de18) client 127.0.0.1:51949 => 127.0.0.2:9100, active_call_state: kNotAdded (forcing a timeout)
W0907 06:27:38.667878 54602 consensus_peers.cc:603] T 49b1706cfba3483b8da3a286fd2115b1 P 02949377cfb94b308697b79fd5581fcf -> Peer fb5b7429056348329f3af97271a630ac ([host: "127.0.0.2" port: 9100], []): Couldn't send request. Status: Timed out (yb/rpc/outbound_call.cc:603): UpdateConsensus RPC (request call id 7840) to 127.0.0.2:9100 timed out after 3.000s. Retrying in the next heartbeat period. Already tried 1 times. State: 2
```
Ensure that all stuck outbound calls are eventually detected. After stopping the workload, the output of the command below should gradually decrease to zero after a couple of minutes:
```
log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Simulating a call stuck in SENT state" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l
```
Also, these stuck calls should stop appearing in the log because they would be forcibly timed out. If they were not, they would be logged every minute.
Second test mode
================
```
bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_failure_to_send_call_probability=0.00001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3
```
Same workload as above.
Look for "Simulated failure to send outbound data" in the tablet server log:
```
W0907 06:35:47.248174 58709 connection.cc:391] Simulated network failure: Network error (yb/rpc/connection.cc:390): Simulated failure to send outbound data for 0x0000068b3935f500 -> Call yb.tserver.TabletServerService.Write 127.0.0.2:47425 => 127.0.0.1:9100 (request call id 6511747)
...
W0907 06:35:47.248219 58709 inbound_call.cc:95] 0x0000068b3935f500 -> Call yb.tserver.TabletServerService.Write 127.0.0.2:47425 => 127.0.0.1:9100 (request call id 6511747): Connection torn down before Call yb.tserver.TabletServerService.Write 127.0.0.2:47425 => 127.0.0.1:9100 (request call id 6511747) could send its response: Network error (yb/rpc/connection.cc:390): Simulated failure to send outbound data for 0x0000068b3935f500 -> Call yb.tserver.TabletServerService.Write 127.0.0.2:47425 => 127.0.0.1:9100 (request call id 6511747)
```
There should be no stuck outbound calls in the log, because these simulated failures will just result in the connection being closed. Depending on the value TEST_simulated_failure_to_send_call_probability, the workload may succeed or fail. With the value 0.00001, it manages to make progress in my experience.
Third test mode
===============
```
bin/yb-ctl wipe_restart --tserver_flags="TEST_outbound_call_skip_callback_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3
```
Same workload as above.
Look for "Skipping OutboundCall callback as a test" and "Stuck OutboundCall" in the log.
Output:
```
W0907 06:38:05.760689 60982 outbound_call.cc:422] OutboundCall@0x00000774ff2a3ba0: Skipping OutboundCall callback as a test: RPC call 0x00000774ff2a3ba0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 7 protocol: 0x00007f776d81eb60 -> tcpc }, id: 703, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 4122.626s (now), sent_time: 4122.626s (now), trigger_callback_time: 4122.626s (now), invoke_callback_time: -inf, expiration_time: 4125.626s (3.000s from now), now: 4122.626s, connection: Connection (0x00000774fd76a158) client 127.0.0.1:46355 => 127.0.0.2:9100, active_call_state: kErasedOnResponse
...
W0907 06:38:09.768546 60605 reactor.cc:676] TabletServer_R012: Stuck OutboundCall: RPC call 0x00000774ff2a3ba0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 7 protocol: 0x00007f776d81eb60 -> tcpc }, id: 703, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 4122.626s (4.008s ago), sent_time: 4122.626s (4.008s ago), trigger_callback_time: 4122.626s (4.008s ago), invoke_callback_time: -inf, expiration_time: 4125.626s (1.008s ago), now: 4126.634s, connection: Connection (0x00000774fd76a158) client 127.0.0.1:46355 => 127.0.0.2:9100, active_call_state: kErasedOnResponse
...
W0907 06:39:09.867923 60605 reactor.cc:676] TabletServer_R012: Stuck OutboundCall: RPC call 0x00000774ff2a3ba0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 7 protocol: 0x00007f776d81eb60 -> tcpc }, id: 703, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 4122.626s (64.106s ago), sent_time: 4122.626s (64.106s ago), trigger_callback_time: 4122.626s (64.106s ago), invoke_callback_time: -inf, expiration_time: 4125.626s (61.106s ago), now: 4186.733s, connection: Connection (0x00000774fd76a158) client 127.0.0.1:46355 => 127.0.0.2:9100, active_call_state: kErasedOnResponse
```
Similarly to the first test, wait for all stuck outbound calls to get reported:
```
log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Skipping OutboundCall callback as a test" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l
```
In this mode, because we are skipping callbacks but allowing state transitions to the finished state, forced expiration at reactor level does not work.
Reviewers: sergei, kpopali
Reviewed By: sergei
Subscribers: bogdan, ybase
Differential Revision: https://phorge.dev.yugabyte.com/D27735
[yugabyte#19090] Disable reactor-based outbound call expiration by default
Summary: Disable reactor-based outbound call expiration by default because it causes sysbench perf test failures.
Test Plan: Jenkins
Reviewers: bogdan, mlillibridge
Reviewed By: bogdan
Subscribers: ybase
Differential Revision: https://phorge.dev.yugabyte.com/D28515
[yugabyte#19090] Fix a memory leak in tracked outbound calls in Reactor
Summary:
Fix a memory leak in tracked_outbound_calls_ in Reactor by cleaning up that data structure more aggressively:
- When traversing tracked calls in the order of increasing next check time, even if it already greater than the current time, stay in the loop and continue removing entries where the callback has been called or the weak pointer has expired.
- When a callback is invoked, notify the reactor through a multi-producer single-consumer queue that is accessed from the OutboundCall via a weak pointer.
Also remove the FinalizeTrackedCall function that was likely useless because it was called concurrently with the callback being handled by the thread pool.
In addition, we are switching OutboundCall allocation away from using make_shared to prevent long-lived weak OutboundCall pointers from consuming memory.
Test Plan:
Jenkins
Local sysbench testing:
```
./yb_build.sh release --no-tests --skip-java
bin/yb-ctl wipe_restart --tserver_flag="memory_limit_hard_bytes=$(( 4 * 1024 * 1024 * 1024 ))"
bin/yb-ctl add_node
bin/yb-ctl add_node
```
Verify we have 3 nodes:
```
bin/yb-ctl status
```
Run sysbench with a table size of 1000000 using a modified version of the run_sysbench.sh script ( https://gist.githubusercontent.com/mbautin/6f0d441b28479232bd2af9b434bed242/raw )
```
./run_sysbench.sh --tablesize 1000000
```
Wait until the run completes. Check the logs for errors (there should be none):
```
find ~/yugabyte-data -name "yb-tserver.INFO" -exec grep -E "Stuck|large number" {} \;
```
Reviewers: sergei
Reviewed By: sergei
Subscribers: yql, ybase
Differential Revision: https://phorge.dev.yugabyte.com/D28531
mbautin
added a commit
to mbautin/yugabyte-db
that referenced
this issue
Oct 10, 2023
…actor level
Summary:
Track all outbound calls submitted to a Reactor in a multi-index container in that reactor. Remove them from the container as soon as we learn the callback has been called. Report stuck calls with detailed debug information. A call is considered stuck if it is a certain time past its expiration (specified by reactor_based_outbound_call_expiration_delay_ms -- set it to 0 to disable this feature). If the call does not have a timeout, the default value stuck_outbound_call_default_timeout_sec is used for reporting only, but not for timeout enforcement.
OutboundCall now keeps track of its expiration deadline, and an additional field active_call_state_, which indicates whether the call was added to the connection's active_calls_ in the corresponding connection, or removed from it, and the removal reason.
If in the OutboundCall destructor the state of the call is not final, or the callback has not been called, we will log that even in release build.
In OutboundCall::SetState, if the current state is already finished, treat this the same as any other invalid state transition. Logically, there should never be a race between e.g. processing a call response and a call timeout, because both events happen on the reactor thread.
Fixing error handling in DoQueueOutboundData. If there is an error sending the call, we destroy the connection.
Introduce a typedef CallHandle and a special value kUnknownCallHandle instead of just using the max value of size_t in case the call handle is unknown or not being used. Change the error handling logic in Connection::DoQueueOutboundData to avoid returning kUnknownCallHandle in case of errors, and make sure the callback is called on the call in case of those errors. The connection was already being shut down.
Update the YB_STRUCT_TO_STRING macro implementation to always add parentheses around an explicitly specified field value.
We introduce multiple ways to simulate stuck outbound calls for testing.
- TEST_simulated_sent_stuck_call_probability specifies the probability of pretending a call is sent to the remote server in `Connection::QueueOutboundCall`, but instead just transitioning it to a SENT state. This is similar to the situation that we have observed.
- TEST_simulated_failure_to_send_call_probability specifies the probability of a network error in `stream_->Send()` called from `Connection::DoQueueOutboundData`. This will cause the connection to be closed. Prior to this revision, this kind of an error would cause `Connection::QueueOutboundCall` to attempt to schedule a timer in a connection that has already been shut down.
- TEST_outbound_call_skip_callback_probability specifies the probability of skipping calling the callback on a particular remote RPC call. We don't do this for local calls.
Also replacing a DFATAL with an WARNING log in InboundCall::QueueResponse to avoid crashing tests during shutdown. Failures to queue a response on the server side should just result in timeouts on the client side in the worst case.
Test Plan:
Jenkins
Manual testing details below.
First test mode
===============
```
bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_sent_stuck_call_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3
java -jar yb-sample-apps.jar --workload CassandraBatchKeyValue --nodes 127.0.0.1:9042,127.0.0.2:9042,127.0.0.3:9042 --num_threads_read 16 --num_threads_write 16 --num_reads 1000000000000 --num_writes 1000000000000
```
Look for output like this in the logs:
```
W0907 06:27:34.604096 54296 connection.cc:302] Connection (0x0000147cbdb4de18) client 127.0.0.1:51949 => 127.0.0.2:9100: Simulating a call stuck in SENT state: RPC call 0x0000147cba7f4de0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 5 protocol: 0x00007f276aefeb60 -> tcpc }, id: 7840, state: SENT, transfer_state: PENDING, start_time: 3491.468s (0.001s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: +inf, now: 3491.469s, connection: Connection (0x0000147cbdb4de18) client 127.0.0.1:51949 => 127.0.0.2:9100, active_call_state: kNotAdded
...
W0907 06:27:38.667785 54296 reactor.cc:676] TabletServer_R010: Stuck OutboundCall: RPC call 0x0000147cba7f4de0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 5 protocol: 0x00007f276aefeb60 -> tcpc }, id: 7840, state: SENT, transfer_state: PENDING, start_time: 3491.468s (4.064s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: 3494.469s (1.063s ago), now: 3495.532s, connection: Connection (0x0000147cbdb4de18) client 127.0.0.1:51949 => 127.0.0.2:9100, active_call_state: kNotAdded (forcing a timeout)
W0907 06:27:38.667878 54602 consensus_peers.cc:603] T 49b1706cfba3483b8da3a286fd2115b1 P 02949377cfb94b308697b79fd5581fcf -> Peer fb5b7429056348329f3af97271a630ac ([host: "127.0.0.2" port: 9100], []): Couldn't send request. Status: Timed out (yb/rpc/outbound_call.cc:603): UpdateConsensus RPC (request call id 7840) to 127.0.0.2:9100 timed out after 3.000s. Retrying in the next heartbeat period. Already tried 1 times. State: 2
```
Ensure that all stuck outbound calls are eventually detected. After stopping the workload, the output of the command below should gradually decrease to zero after a couple of minutes:
```
log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Simulating a call stuck in SENT state" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l
```
Also, these stuck calls should stop appearing in the log because they would be forcibly timed out. If they were not, they would be logged every minute.
Second test mode
================
```
bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_failure_to_send_call_probability=0.00001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3
```
Same workload as above.
Look for "Simulated failure to send outbound data" in the tablet server log:
```
W0907 06:35:47.248174 58709 connection.cc:391] Simulated network failure: Network error (yb/rpc/connection.cc:390): Simulated failure to send outbound data for 0x0000068b3935f500 -> Call yb.tserver.TabletServerService.Write 127.0.0.2:47425 => 127.0.0.1:9100 (request call id 6511747)
...
W0907 06:35:47.248219 58709 inbound_call.cc:95] 0x0000068b3935f500 -> Call yb.tserver.TabletServerService.Write 127.0.0.2:47425 => 127.0.0.1:9100 (request call id 6511747): Connection torn down before Call yb.tserver.TabletServerService.Write 127.0.0.2:47425 => 127.0.0.1:9100 (request call id 6511747) could send its response: Network error (yb/rpc/connection.cc:390): Simulated failure to send outbound data for 0x0000068b3935f500 -> Call yb.tserver.TabletServerService.Write 127.0.0.2:47425 => 127.0.0.1:9100 (request call id 6511747)
```
There should be no stuck outbound calls in the log, because these simulated failures will just result in the connection being closed. Depending on the value TEST_simulated_failure_to_send_call_probability, the workload may succeed or fail. With the value 0.00001, it manages to make progress in my experience.
Third test mode
===============
```
bin/yb-ctl wipe_restart --tserver_flags="TEST_outbound_call_skip_callback_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3
```
Same workload as above.
Look for "Skipping OutboundCall callback as a test" and "Stuck OutboundCall" in the log.
Output:
```
W0907 06:38:05.760689 60982 outbound_call.cc:422] OutboundCall@0x00000774ff2a3ba0: Skipping OutboundCall callback as a test: RPC call 0x00000774ff2a3ba0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 7 protocol: 0x00007f776d81eb60 -> tcpc }, id: 703, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 4122.626s (now), sent_time: 4122.626s (now), trigger_callback_time: 4122.626s (now), invoke_callback_time: -inf, expiration_time: 4125.626s (3.000s from now), now: 4122.626s, connection: Connection (0x00000774fd76a158) client 127.0.0.1:46355 => 127.0.0.2:9100, active_call_state: kErasedOnResponse
...
W0907 06:38:09.768546 60605 reactor.cc:676] TabletServer_R012: Stuck OutboundCall: RPC call 0x00000774ff2a3ba0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 7 protocol: 0x00007f776d81eb60 -> tcpc }, id: 703, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 4122.626s (4.008s ago), sent_time: 4122.626s (4.008s ago), trigger_callback_time: 4122.626s (4.008s ago), invoke_callback_time: -inf, expiration_time: 4125.626s (1.008s ago), now: 4126.634s, connection: Connection (0x00000774fd76a158) client 127.0.0.1:46355 => 127.0.0.2:9100, active_call_state: kErasedOnResponse
...
W0907 06:39:09.867923 60605 reactor.cc:676] TabletServer_R012: Stuck OutboundCall: RPC call 0x00000774ff2a3ba0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 7 protocol: 0x00007f776d81eb60 -> tcpc }, id: 703, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 4122.626s (64.106s ago), sent_time: 4122.626s (64.106s ago), trigger_callback_time: 4122.626s (64.106s ago), invoke_callback_time: -inf, expiration_time: 4125.626s (61.106s ago), now: 4186.733s, connection: Connection (0x00000774fd76a158) client 127.0.0.1:46355 => 127.0.0.2:9100, active_call_state: kErasedOnResponse
```
Similarly to the first test, wait for all stuck outbound calls to get reported:
```
log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Skipping OutboundCall callback as a test" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l
```
In this mode, because we are skipping callbacks but allowing state transitions to the finished state, forced expiration at reactor level does not work.
Reviewers: sergei, kpopali
Reviewed By: sergei
Subscribers: bogdan, ybase
Differential Revision: https://phorge.dev.yugabyte.com/D27735
[yugabyte#19090] Disable reactor-based outbound call expiration by default
Summary: Disable reactor-based outbound call expiration by default because it causes sysbench perf test failures.
Test Plan: Jenkins
Reviewers: bogdan, mlillibridge
Reviewed By: bogdan
Subscribers: ybase
Differential Revision: https://phorge.dev.yugabyte.com/D28515
[yugabyte#19090] Fix a memory leak in tracked outbound calls in Reactor
Summary:
Fix a memory leak in tracked_outbound_calls_ in Reactor by cleaning up that data structure more aggressively:
- When traversing tracked calls in the order of increasing next check time, even if it already greater than the current time, stay in the loop and continue removing entries where the callback has been called or the weak pointer has expired.
- When a callback is invoked, notify the reactor through a multi-producer single-consumer queue that is accessed from the OutboundCall via a weak pointer.
Also remove the FinalizeTrackedCall function that was likely useless because it was called concurrently with the callback being handled by the thread pool.
In addition, we are switching OutboundCall allocation away from using make_shared to prevent long-lived weak OutboundCall pointers from consuming memory.
Test Plan:
Jenkins
Local sysbench testing:
```
./yb_build.sh release --no-tests --skip-java
bin/yb-ctl wipe_restart --tserver_flag="memory_limit_hard_bytes=$(( 4 * 1024 * 1024 * 1024 ))"
bin/yb-ctl add_node
bin/yb-ctl add_node
```
Verify we have 3 nodes:
```
bin/yb-ctl status
```
Run sysbench with a table size of 1000000 using a modified version of the run_sysbench.sh script ( https://gist.githubusercontent.com/mbautin/6f0d441b28479232bd2af9b434bed242/raw )
```
./run_sysbench.sh --tablesize 1000000
```
Wait until the run completes. Check the logs for errors (there should be none):
```
find ~/yugabyte-data -name "yb-tserver.INFO" -exec grep -E "Stuck|large number" {} \;
```
Reviewers: sergei
Reviewed By: sergei
Subscribers: yql, ybase
Differential Revision: https://phorge.dev.yugabyte.com/D28531
mbautin
added a commit
that referenced
this issue
Oct 18, 2023
…alls Summary: Track all outbound calls submitted to a Reactor in a multi-index container in that reactor. Remove them from the container as soon as we learn the callback has been called, using a multiple-producer single-consumer (MPSC) queue where the consumer is the reactor thread. Report stuck calls with detailed debug information. A call is considered stuck if it is a certain time past its expiration (specified by reactor_based_outbound_call_expiration_delay_ms -- set it to 0 to disable this feature). If the call does not have a timeout, the default value stuck_outbound_call_default_timeout_sec is used for reporting only, but not for timeout enforcement. OutboundCall now keeps track of its expiration deadline, and an additional field active_call_state_, which indicates whether the call was added to the connection's active_calls_ in the corresponding connection, or removed from it, and the removal reason. If in the OutboundCall destructor the state of the call is not final, or the callback has not been called, we will log that even in release build. In OutboundCall::SetState, if the current state is already finished, treat this the same as any other invalid state transition. Logically, there should never be a race between e.g. processing a call response and a call timeout, because both events happen on the reactor thread. Fixing error handling in DoQueueOutboundData. If there is an error sending the call, we destroy the connection. Introduce a typedef CallHandle and a special value kUnknownCallHandle instead of just using the max value of size_t in case the call handle is unknown or not being used. Change the error handling logic in Connection::DoQueueOutboundData to avoid returning kUnknownCallHandle in case of errors, and make sure the callback is called on the call in case of those errors. The connection was already being shut down. Update the YB_STRUCT_TO_STRING macro implementation to always add parentheses around an explicitly specified field value. We introduce multiple ways to simulate stuck outbound calls for testing. TEST_simulated_sent_stuck_call_probability specifies the probability of pretending a call is sent to the remote server in Connection::QueueOutboundCall, but instead just transitioning it to a SENT state. This is similar to the situation that we have observed. TEST_simulated_failure_to_send_call_probability specifies the probability of a network error in stream_->Send() called from Connection::DoQueueOutboundData. This will cause the connection to be closed. Prior to this revision, this kind of an error would cause Connection::QueueOutboundCall to attempt to schedule a timer in a connection that has already been shut down. TEST_outbound_call_skip_callback_probability specifies the probability of skipping calling the callback on a particular remote RPC call. We don't do this for local calls. Also replacing a DFATAL with an WARNING log in InboundCall::QueueResponse to avoid crashing tests during shutdown. Failures to queue a response on the server side should just result in timeouts on the client side in the worst case. We are combining multiple original revisions from the master branch to avoid introducing and then fixing a memory leak bug, and to keep the resulting patch cleaner. Original revisions: - D27735 ( 1fbff49 ) [#18685] Track stuck OutboundCalls and enforce timeouts at Reactor level - D27919 ( ddb817b ) [#18808] A write-once lock-free weak pointer class: it is frequently necessary to have a weak pointer equivalent that can only be written to once, but can be read without locking for performance. - D28085 ( a5ba08f ) [#18855] Add functions for formatting a CoarseTimePoint relative to the current time. Useful for logging deadlines. - D28138 ( d0a44db ) [#18877] Log invalid OutboundCall state transitions and other OutboundCall improvements. OutboundCall will track invalid state transitions and report them in the DebugString and in the destructor, in addition to reporting them as they happen. Do not allow OutboundCall callback to be invoked more than once and log occurrences of that. Use a compare-and-swap loop in RpcCall::Transferred and log invalid transfer_state transitions. invoke_callback_time_ and sent_time_ in OutboundCall were being accessed without synchronization, so making them atomic. OutboundCall::DebugString should not queue a task in the reactor to print the connection details in relation to the call anymore. That is now done by a separate method, QueueDumpConnectionState, called explicitly. - D28531 ( 0648341 ) [#19090] Fix a memory leak in tracked outbound calls in Reactor. When an OutboundCall callback is invoked, notify the reactor through a multi-producer single-consumer queue that is accessed from the OutboundCall via a weak pointer. Also switching OutboundCall allocation away from using make_shared to prevent long-lived weak OutboundCall pointers from consuming memory. Test Plan: Jenkins --- Manual testing details below. First test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_sent_stuck_call_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 java -jar yb-sample-apps.jar --workload CassandraBatchKeyValue --nodes 127.0.0.1:9042,127.0.0.2:9042,127.0.0.3:9042 --num_threads_read 16 --num_threads_write 16 --num_reads 1000000000000 --num_writes 1000000000000 ``` Look for output like this in the logs: ``` W1017 21:23:13.309160 2187266 connection.cc:300] Connection (0x0000556728cd2158) client 127.0.0.1:38331 => 127.0.0.2:9100: Simulating a call stuck in SENT state: RPC call 0x000055672aea9080: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 4 protocol: 0x00007f03547e75d0 -> tcpc }, id: 70811, state: SENT, transfer_state: PENDING, start_time: 257388.919s (0.004s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: +inf, now: 257388.923s, connection: Connection (0x0000556728cd2158) client 127.0.0.1:38331 => 127.0.0.2:9100, active_call_state: kNotAdded ... W1017 21:23:17.377820 2187266 reactor.cc:682] TabletServer_R000: Stuck OutboundCall: RPC call 0x000055672aea9080: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 4 protocol: 0x00007f03547e75d0 -> tcpc }, id: 70811, state: SENT, transfer_state: PENDING, start_time: 257388.919s (4.073s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: 257391.923s (1.069s ago), now: 257392.992s, connection: Connection (0x0000556728cd2158) client 127.0.0.1:38331 => 127.0.0.2:9100, active_call_state: kNotAdded (forcing a timeout) W1017 21:23:17.378927 2187522 consensus_peers.cc:605] T 775284184b9241a89206fc0cdaa59302 P a5cddad5f52643e183e281d890cea703 -> Peer 1b86c67a8a50457794972712d3f0a860 ([host: "127.0.0.2" port: 9100], []): Couldn't send request. Status: Timed out (yb/rpc/outbound_call.cc:614): UpdateConsensus RPC (request call id 70811) to 127.0.0.2:9100 timed out after 3.000s. Retrying in the next heartbeat period. Already tried 1 times. State: 2 ``` Ensure that all stuck outbound calls are eventually detected. After stopping the workload, the output of the command below should gradually decrease to zero after a couple of minutes: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Simulating a call stuck in SENT state" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` Also, these stuck calls should stop appearing in the log because they would be forcibly timed out. If they were not, they would be logged every minute. Second test mode ================ ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_failure_to_send_call_probability=0.00001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Simulated failure to send outbound data" in the tablet server log: ``` W1017 21:37:57.068120 2190494 connection.cc:389] Simulated network failure: Network error (yb/rpc/connection.cc:388): Simulated failure to send outbound data for 0x00005623a3e23b80 -> Call yb.tserver.TabletServerService.Write 127.0.0.3:36207 => 127.0.0.1:9100 (request call id 907743) ... W1017 21:37:57.068182 2190494 inbound_call.cc:99] 0x00005623a3e23b80 -> Call yb.tserver.TabletServerService.Write 127.0.0.3:36207 => 127.0.0.1:9100 (request call id 907743): Connection torn down before Call yb.tserver.TabletServerService.Write 127.0.0.3:36207 => 127.0.0.1:9100 (request call id 907743) could send its response: Network error (yb/rpc/connection.cc:388): Simulated failure to send outbound data for 0x00005623a3e23b80 -> Call yb.tserver.TabletServerService.Write 127.0.0.3:36207 => 127.0.0.1:9100 (request call id 907743) ``` There should be no stuck outbound calls in the log, because these simulated failures will just result in the connection being closed. Depending on the value TEST_simulated_failure_to_send_call_probability, the workload may succeed or fail. With the value 0.00001, it manages to make progress in my experience. Third test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_outbound_call_skip_callback_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Skipping OutboundCall callback as a test" and "Stuck OutboundCall" in the log. Output: ``` W1017 21:40:48.326967 2193494 outbound_call.cc:421] OutboundCall@0x00005578719ec2c0: Skipping OutboundCall callback as a test: RPC call 0x00005578719ec2c0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 2 protocol: 0x00007f11979b25d0 -> tcpc }, id: 3497, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 258443.926s (0.016s ago), sent_time: 258443.926s (0.016s ago), trigger_callback_time: 258443.941s (0.001s ago), invoke_callback_time: -inf, expiration_time: 258446.926s (2.983s from now), now: 258443.942s, connection: Connection (0x000055786dd06158) client 127.0.0.1:52911 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1017 21:40:52.362062 2193263 reactor.cc:682] TabletServer_R002: Stuck OutboundCall: RPC call 0x00005578719ec2c0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 2 protocol: 0x00007f11979b25d0 -> tcpc }, id: 3497, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 258443.926s (4.050s ago), sent_time: 258443.926s (4.050s ago), trigger_callback_time: 258443.941s (4.035s ago), invoke_callback_time: -inf, expiration_time: 258446.926s (1.050s ago), now: 258447.976s, connection: Connection (0x000055786dd06158) client 127.0.0.1:52911 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1017 21:41:22.461496 2193263 reactor.cc:682] TabletServer_R002: Stuck OutboundCall: RPC call 0x00005578719ec2c0: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 2 protocol: 0x00007f11979b25d0 -> tcpc }, id: 3497, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 258443.926s (34.149s ago), sent_time: 258443.926s (34.149s ago), trigger_callback_time: 258443.941s (34.134s ago), invoke_callback_time: -inf, expiration_time: 258446.926s (31.149s ago), now: 258478.075s, connection: Connection (0x000055786dd06158) client 127.0.0.1:52911 => 127.0.0.2:9100, active_call_state: kErasedOnResponse ``` Similarly to the first test, wait for all stuck outbound calls to get reported: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Skipping OutboundCall callback as a test" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` In this mode, because we are skipping callbacks but allowing state transitions to the finished state, forced expiration at reactor level does not work. Reviewers: bogdan, rthallam, sergei Reviewed By: sergei Subscribers: ybase Differential Revision: https://phorge.dev.yugabyte.com/D29215
mbautin
added a commit
to mbautin/yugabyte-db
that referenced
this issue
Oct 24, 2023
…alls Summary: Track all outbound calls submitted to a Reactor in a multi-index container in that reactor. Remove them from the container as soon as we learn the callback has been called, using a multiple-producer single-consumer (MPSC) queue where the consumer is the reactor thread. Report stuck calls with detailed debug information. A call is considered stuck if it is a certain time past its expiration (specified by reactor_based_outbound_call_expiration_delay_ms -- set it to 0 to disable this feature). If the call does not have a timeout, the default value stuck_outbound_call_default_timeout_sec is used for reporting only, but not for timeout enforcement. OutboundCall now keeps track of its expiration deadline, and an additional field active_call_state_, which indicates whether the call was added to the connection's active_calls_ in the corresponding connection, or removed from it, and the removal reason. If in the OutboundCall destructor the state of the call is not final, or the callback has not been called, we will log that even in release build. In OutboundCall::SetState, if the current state is already finished, treat this the same as any other invalid state transition. Logically, there should never be a race between e.g. processing a call response and a call timeout, because both events happen on the reactor thread. Fixing error handling in DoQueueOutboundData. If there is an error sending the call, we destroy the connection. Introduce a typedef CallHandle and a special value kUnknownCallHandle instead of just using the max value of size_t in case the call handle is unknown or not being used. Change the error handling logic in Connection::DoQueueOutboundData to avoid returning kUnknownCallHandle in case of errors, and make sure the callback is called on the call in case of those errors. The connection was already being shut down. Update the YB_STRUCT_TO_STRING macro implementation to always add parentheses around an explicitly specified field value. We introduce multiple ways to simulate stuck outbound calls for testing. - TEST_simulated_sent_stuck_call_probability specifies the probability of pretending a call is sent to the remote server in -Connection::QueueOutboundCall, but instead just transitioning it to a SENT state. This is similar to the situation that we have observed. - TEST_simulated_failure_to_send_call_probability specifies the probability of a network error in stream_->Send() called from Connection::DoQueueOutboundData. This will cause the connection to be closed. Prior to this revision, this kind of an error would cause Connection::QueueOutboundCall to attempt to schedule a timer in a connection that has already been shut down. - TEST_outbound_call_skip_callback_probability specifies the probability of skipping calling the callback on a particular remote RPC call. We don't do this for local calls. Also replacing a DFATAL with an WARNING log in InboundCall::QueueResponse to avoid crashing tests during shutdown. Failures to queue a response on the server side should just result in timeouts on the client side in the worst case. We are combining multiple original revisions from the master branch to avoid introducing and then fixing a memory leak bug, and to keep the resulting patch cleaner. This revision was backported from the 2.18 backport D29215 ( d028fe2 ). Original revisions in master: - D27735 ( 1fbff49 ) [yugabyte#18685] Track stuck OutboundCalls and enforce timeouts at Reactor level - D27919 ( ddb817b ) [yugabyte#18808] A write-once lock-free weak pointer class: it is frequently necessary to have a weak pointer equivalent that can only be written to once, but can be read without locking for performance. - D28085 ( a5ba08f ) [yugabyte#18855] Add functions for formatting a CoarseTimePoint relative to the current time. Useful for logging deadlines. - D28138 ( d0a44db ) [yugabyte#18877] Log invalid OutboundCall state transitions and other OutboundCall improvements. OutboundCall will track invalid state transitions and report them in the DebugString and in the destructor, in addition to reporting them as they happen. Do not allow OutboundCall callback to be invoked more than once and log occurrences of that. Use a compare-and-swap loop in RpcCall::Transferred and log invalid transfer_state transitions. invoke_callback_time_ and sent_time_ in OutboundCall were being accessed without synchronization, so making them atomic. OutboundCall::DebugString should not queue a task in the reactor to print the connection details in relation to the call anymore. That is now done by a separate method, QueueDumpConnectionState, called explicitly. - D28531 ( 0648341 ) [yugabyte#19090] Fix a memory leak in tracked outbound calls in Reactor. When an OutboundCall callback is invoked, notify the reactor through a multi-producer single-consumer queue that is accessed from the OutboundCall via a weak pointer. Also switching OutboundCall allocation away from using make_shared to prevent long-lived weak OutboundCall pointers from consuming memory. Also, parts of D23468 ( 4879cfb ) "[yugabyte#16380] Use thread safety analysis annotations to enforce the reactor thread requirement" are included. That commit is present in 2.18 but not in 2.16. Test Plan: Jenkins --- Manual testing details below. First test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_sent_stuck_call_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 java -jar yb-sample-apps.jar --workload CassandraBatchKeyValue --nodes 127.0.0.1:9042,127.0.0.2:9042,127.0.0.3:9042 --num_threads_read 16 --num_threads_write 16 --num_reads 1000000000000 --num_writes 1000000000000 ``` Look for output like this in the logs: ``` W1024 21:29:58.941679 1731793 connection.cc:307] Connection (0x0000564dbd812298) client 127.0.0.1:39689 => 127.0.0.2:9100: Simulating a call stuck in SENT state: RPC call 0x0000564dbbf3e580: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 6 protocol: 0x00007fd157f9cd70 -> tcpc }, id: 85493, state: SENT, transfer_state: PENDING, start_time: 455775.550s (0.001s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: +inf, now: 455775.551s, connection: Connection (0x0000564dbd812298) client 127.0.0.1:39689 => 127.0.0.2:9100, active_call_state: kNotAdded ... W1024 21:30:03.017571 1731793 reactor.cc:1142] TabletServer_R002: Stuck OutboundCall: RPC call 0x0000564dbbf3e580: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 6 protocol: 0x00007fd157f9cd70 -> tcpc }, id: 85493, state: SENT, transfer_state: PENDING, start_time: 455775.550s (4.077s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: 455778.551s (1.076s ago), now: 455779.628s, connection: Connection (0x0000564dbd812298) client 127.0.0.1:39689 => 127.0.0.2:9100, active_call_state: kNotAdded (forcing a timeout) W1024 21:30:03.017947 1731995 consensus_peers.cc:611] T 9735d87712974ea9b848cc606db8d664 P 9dcaaf7955ea4ca78667b1fa92c89192 -> Peer b6dbb1d832e14b0080d2143ac43fbaae ([host: "127.0.0.2" port: 9100], []): Couldn't send request. Status: Timed out (yb/rpc/outbound_call.cc:612): UpdateConsensus RPC (request call id 85493) to 127.0.0.2:9100 timed out after 3.000s. Retrying in the next heartbeat period. Already tried 1 times. State: 2 ``` Ensure that all stuck outbound calls are eventually detected. After stopping the workload, the output of the command below should gradually decrease to zero after a couple of minutes: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Simulating a call stuck in SENT state" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` Also, these stuck calls should stop appearing in the log because they would be forcibly timed out. If they were not, they would be logged every minute. Second test mode ================ ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_failure_to_send_call_probability=0.00001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Simulated failure to send outbound data" in the tablet server log: ``` W1024 22:33:22.772235 1739663 connection.cc:401] Simulated network failure: Network error (yb/rpc/connection.cc:400): Simulated failure to send outbound data for 0x000055999706f040 -> CQL Call from 127.0.0.1:50690, stream id: 9792 ... W1024 22:33:22.772346 1739663 inbound_call.cc:104] 0x000055999706f040 -> CQL Call from 127.0.0.1:50690, stream id: 9792: Connection torn down before CQL Call from 127.0.0.1:50690, stream id: 9792 could send its response: Network error (yb/rpc/connection.cc:400): Simulated failure to send outbound data for 0x000055999706f040 -> CQL Call from 127.0.0.1:50690, stream id: 9792 ``` There should be no stuck outbound calls in the log, because these simulated failures will just result in the connection being closed. Depending on the value TEST_simulated_failure_to_send_call_probability, the workload may succeed or fail. With the value 0.00001, it manages to make progress in my experience. Third test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_outbound_call_skip_callback_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Skipping OutboundCall callback as a test" and "Stuck OutboundCall" in the log. Output: ``` W1024 22:45:47.389113 1743081 outbound_call.cc:419] OutboundCall@0x0000562012975600: Skipping OutboundCall callback as a test: RPC call 0x0000562012975600: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 1 protocol: 0x00007fbff47fed70 -> tcpc }, id: 3815, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 460323.999s (0.001s ago), sent_time: 460323.999s (0.001s ago), trigger_callback_time: 460323.999s (0.001s ago), invoke_callback_time: -inf, expiration_time: 460326.999s (2.998s from now), now: 460324.000s, connection: Connection (0x00005620102b0798) client 127.0.0.1:55971 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1024 22:45:51.463742 1742860 reactor.cc:1142] TabletServer_R001: Stuck OutboundCall: RPC call 0x0000562012975600: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 1 protocol: 0x00007fbff47fed70 -> tcpc }, id: 3815, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 460323.999s (4.075s ago), sent_time: 460323.999s (4.075s ago), trigger_callback_time: 460323.999s (4.075s ago), invoke_callback_time: -inf, expiration_time: 460326.999s (1.075s ago), now: 460328.074s, connection: Connection (0x00005620102b0798) client 127.0.0.1:55971 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1024 22:46:21.564029 1742860 reactor.cc:1142] TabletServer_R001: Stuck OutboundCall: RPC call 0x0000562012975600: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 1 protocol: 0x00007fbff47fed70 -> tcpc }, id: 3815, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 460323.999s (34.175s ago), sent_time: 460323.999s (34.175s ago), trigger_callback_time: 460323.999s (34.175s ago), invoke_callback_time: -inf, expiration_time: 460326.999s (31.175s ago), now: 460358.174s, connection: Connection (0x00005620102b0798) client 127.0.0.1:55971 => 127.0.0.2:9100, active_call_state: kErasedOnResponse ``` Similarly to the first test, wait for all stuck outbound calls to get reported: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Skipping OutboundCall callback as a test" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` In this mode, because we are skipping callbacks but allowing state transitions to the finished state, forced expiration at reactor level does not work. Reviewers: sergei, bogdan Reviewed By: sergei Subscribers: bogdan Differential Revision: https://phorge.dev.yugabyte.com/D29539
mbautin
added a commit
that referenced
this issue
Oct 25, 2023
…alls Summary: Track all outbound calls submitted to a Reactor in a multi-index container in that reactor. Remove them from the container as soon as we learn the callback has been called, using a multiple-producer single-consumer (MPSC) queue where the consumer is the reactor thread. Report stuck calls with detailed debug information. A call is considered stuck if it is a certain time past its expiration (specified by reactor_based_outbound_call_expiration_delay_ms -- set it to 0 to disable this feature). If the call does not have a timeout, the default value stuck_outbound_call_default_timeout_sec is used for reporting only, but not for timeout enforcement. OutboundCall now keeps track of its expiration deadline, and an additional field active_call_state_, which indicates whether the call was added to the connection's active_calls_ in the corresponding connection, or removed from it, and the removal reason. If in the OutboundCall destructor the state of the call is not final, or the callback has not been called, we will log that even in release build. In OutboundCall::SetState, if the current state is already finished, treat this the same as any other invalid state transition. Logically, there should never be a race between e.g. processing a call response and a call timeout, because both events happen on the reactor thread. Fixing error handling in DoQueueOutboundData. If there is an error sending the call, we destroy the connection. Introduce a typedef CallHandle and a special value kUnknownCallHandle instead of just using the max value of size_t in case the call handle is unknown or not being used. Change the error handling logic in Connection::DoQueueOutboundData to avoid returning kUnknownCallHandle in case of errors, and make sure the callback is called on the call in case of those errors. The connection was already being shut down. Update the YB_STRUCT_TO_STRING macro implementation to always add parentheses around an explicitly specified field value. We introduce multiple ways to simulate stuck outbound calls for testing. - TEST_simulated_sent_stuck_call_probability specifies the probability of pretending a call is sent to the remote server in -Connection::QueueOutboundCall, but instead just transitioning it to a SENT state. This is similar to the situation that we have observed. - TEST_simulated_failure_to_send_call_probability specifies the probability of a network error in stream_->Send() called from Connection::DoQueueOutboundData. This will cause the connection to be closed. Prior to this revision, this kind of an error would cause Connection::QueueOutboundCall to attempt to schedule a timer in a connection that has already been shut down. - TEST_outbound_call_skip_callback_probability specifies the probability of skipping calling the callback on a particular remote RPC call. We don't do this for local calls. Also replacing a DFATAL with an WARNING log in InboundCall::QueueResponse to avoid crashing tests during shutdown. Failures to queue a response on the server side should just result in timeouts on the client side in the worst case. We are combining multiple original revisions from the master branch to avoid introducing and then fixing a memory leak bug, and to keep the resulting patch cleaner. This revision was backported from the 2.18 backport D29215 ( d028fe2 ). Original revisions in master: - D27735 ( 1fbff49 ) [#18685] Track stuck OutboundCalls and enforce timeouts at Reactor level - D27919 ( ddb817b ) [#18808] A write-once lock-free weak pointer class: it is frequently necessary to have a weak pointer equivalent that can only be written to once, but can be read without locking for performance. - D28085 ( a5ba08f ) [#18855] Add functions for formatting a CoarseTimePoint relative to the current time. Useful for logging deadlines. - D28138 ( d0a44db ) [#18877] Log invalid OutboundCall state transitions and other OutboundCall improvements. OutboundCall will track invalid state transitions and report them in the DebugString and in the destructor, in addition to reporting them as they happen. Do not allow OutboundCall callback to be invoked more than once and log occurrences of that. Use a compare-and-swap loop in RpcCall::Transferred and log invalid transfer_state transitions. invoke_callback_time_ and sent_time_ in OutboundCall were being accessed without synchronization, so making them atomic. OutboundCall::DebugString should not queue a task in the reactor to print the connection details in relation to the call anymore. That is now done by a separate method, QueueDumpConnectionState, called explicitly. - D28531 ( 0648341 ) [#19090] Fix a memory leak in tracked outbound calls in Reactor. When an OutboundCall callback is invoked, notify the reactor through a multi-producer single-consumer queue that is accessed from the OutboundCall via a weak pointer. Also switching OutboundCall allocation away from using make_shared to prevent long-lived weak OutboundCall pointers from consuming memory. Also, parts of D23468 ( 4879cfb ) "[#16380] Use thread safety analysis annotations to enforce the reactor thread requirement" are included. That commit is present in 2.18 but not in 2.16. Test Plan: Jenkins --- Manual testing details below. First test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_sent_stuck_call_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 java -jar yb-sample-apps.jar --workload CassandraBatchKeyValue --nodes 127.0.0.1:9042,127.0.0.2:9042,127.0.0.3:9042 --num_threads_read 16 --num_threads_write 16 --num_reads 1000000000000 --num_writes 1000000000000 ``` Look for output like this in the logs: ``` W1024 21:29:58.941679 1731793 connection.cc:307] Connection (0x0000564dbd812298) client 127.0.0.1:39689 => 127.0.0.2:9100: Simulating a call stuck in SENT state: RPC call 0x0000564dbbf3e580: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 6 protocol: 0x00007fd157f9cd70 -> tcpc }, id: 85493, state: SENT, transfer_state: PENDING, start_time: 455775.550s (0.001s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: +inf, now: 455775.551s, connection: Connection (0x0000564dbd812298) client 127.0.0.1:39689 => 127.0.0.2:9100, active_call_state: kNotAdded ... W1024 21:30:03.017571 1731793 reactor.cc:1142] TabletServer_R002: Stuck OutboundCall: RPC call 0x0000564dbbf3e580: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 6 protocol: 0x00007fd157f9cd70 -> tcpc }, id: 85493, state: SENT, transfer_state: PENDING, start_time: 455775.550s (4.077s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: 455778.551s (1.076s ago), now: 455779.628s, connection: Connection (0x0000564dbd812298) client 127.0.0.1:39689 => 127.0.0.2:9100, active_call_state: kNotAdded (forcing a timeout) W1024 21:30:03.017947 1731995 consensus_peers.cc:611] T 9735d87712974ea9b848cc606db8d664 P 9dcaaf7955ea4ca78667b1fa92c89192 -> Peer b6dbb1d832e14b0080d2143ac43fbaae ([host: "127.0.0.2" port: 9100], []): Couldn't send request. Status: Timed out (yb/rpc/outbound_call.cc:612): UpdateConsensus RPC (request call id 85493) to 127.0.0.2:9100 timed out after 3.000s. Retrying in the next heartbeat period. Already tried 1 times. State: 2 ``` Ensure that all stuck outbound calls are eventually detected. After stopping the workload, the output of the command below should gradually decrease to zero after a couple of minutes: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Simulating a call stuck in SENT state" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` Also, these stuck calls should stop appearing in the log because they would be forcibly timed out. If they were not, they would be logged every minute. Second test mode ================ ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_failure_to_send_call_probability=0.00001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Simulated failure to send outbound data" in the tablet server log: ``` W1024 22:33:22.772235 1739663 connection.cc:401] Simulated network failure: Network error (yb/rpc/connection.cc:400): Simulated failure to send outbound data for 0x000055999706f040 -> CQL Call from 127.0.0.1:50690, stream id: 9792 ... W1024 22:33:22.772346 1739663 inbound_call.cc:104] 0x000055999706f040 -> CQL Call from 127.0.0.1:50690, stream id: 9792: Connection torn down before CQL Call from 127.0.0.1:50690, stream id: 9792 could send its response: Network error (yb/rpc/connection.cc:400): Simulated failure to send outbound data for 0x000055999706f040 -> CQL Call from 127.0.0.1:50690, stream id: 9792 ``` There should be no stuck outbound calls in the log, because these simulated failures will just result in the connection being closed. Depending on the value TEST_simulated_failure_to_send_call_probability, the workload may succeed or fail. With the value 0.00001, it manages to make progress in my experience. Third test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_outbound_call_skip_callback_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Skipping OutboundCall callback as a test" and "Stuck OutboundCall" in the log. Output: ``` W1024 22:45:47.389113 1743081 outbound_call.cc:419] OutboundCall@0x0000562012975600: Skipping OutboundCall callback as a test: RPC call 0x0000562012975600: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 1 protocol: 0x00007fbff47fed70 -> tcpc }, id: 3815, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 460323.999s (0.001s ago), sent_time: 460323.999s (0.001s ago), trigger_callback_time: 460323.999s (0.001s ago), invoke_callback_time: -inf, expiration_time: 460326.999s (2.998s from now), now: 460324.000s, connection: Connection (0x00005620102b0798) client 127.0.0.1:55971 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1024 22:45:51.463742 1742860 reactor.cc:1142] TabletServer_R001: Stuck OutboundCall: RPC call 0x0000562012975600: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 1 protocol: 0x00007fbff47fed70 -> tcpc }, id: 3815, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 460323.999s (4.075s ago), sent_time: 460323.999s (4.075s ago), trigger_callback_time: 460323.999s (4.075s ago), invoke_callback_time: -inf, expiration_time: 460326.999s (1.075s ago), now: 460328.074s, connection: Connection (0x00005620102b0798) client 127.0.0.1:55971 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1024 22:46:21.564029 1742860 reactor.cc:1142] TabletServer_R001: Stuck OutboundCall: RPC call 0x0000562012975600: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 1 protocol: 0x00007fbff47fed70 -> tcpc }, id: 3815, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 460323.999s (34.175s ago), sent_time: 460323.999s (34.175s ago), trigger_callback_time: 460323.999s (34.175s ago), invoke_callback_time: -inf, expiration_time: 460326.999s (31.175s ago), now: 460358.174s, connection: Connection (0x00005620102b0798) client 127.0.0.1:55971 => 127.0.0.2:9100, active_call_state: kErasedOnResponse ``` Similarly to the first test, wait for all stuck outbound calls to get reported: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Skipping OutboundCall callback as a test" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` In this mode, because we are skipping callbacks but allowing state transitions to the finished state, forced expiration at reactor level does not work. Reviewers: sergei, bogdan Reviewed By: sergei Subscribers: bogdan Differential Revision: https://phorge.dev.yugabyte.com/D29539
mbautin
added a commit
to mbautin/yugabyte-db
that referenced
this issue
Oct 25, 2023
…alls Summary: Track all outbound calls submitted to a Reactor in a multi-index container in that reactor. Remove them from the container as soon as we learn the callback has been called, using a multiple-producer single-consumer (MPSC) queue where the consumer is the reactor thread. Report stuck calls with detailed debug information. A call is considered stuck if it is a certain time past its expiration (specified by reactor_based_outbound_call_expiration_delay_ms -- set it to 0 to disable this feature). If the call does not have a timeout, the default value stuck_outbound_call_default_timeout_sec is used for reporting only, but not for timeout enforcement. OutboundCall now keeps track of its expiration deadline, and an additional field active_call_state_, which indicates whether the call was added to the connection's active_calls_ in the corresponding connection, or removed from it, and the removal reason. If in the OutboundCall destructor the state of the call is not final, or the callback has not been called, we will log that even in release build. In OutboundCall::SetState, if the current state is already finished, treat this the same as any other invalid state transition. Logically, there should never be a race between e.g. processing a call response and a call timeout, because both events happen on the reactor thread. Fixing error handling in DoQueueOutboundData. If there is an error sending the call, we destroy the connection. Introduce a typedef CallHandle and a special value kUnknownCallHandle instead of just using the max value of size_t in case the call handle is unknown or not being used. Change the error handling logic in Connection::DoQueueOutboundData to avoid returning kUnknownCallHandle in case of errors, and make sure the callback is called on the call in case of those errors. The connection was already being shut down. Update the YB_STRUCT_TO_STRING macro implementation to always add parentheses around an explicitly specified field value. We introduce multiple ways to simulate stuck outbound calls for testing. - TEST_simulated_sent_stuck_call_probability specifies the probability of pretending a call is sent to the remote server in -Connection::QueueOutboundCall, but instead just transitioning it to a SENT state. This is similar to the situation that we have observed. - TEST_simulated_failure_to_send_call_probability specifies the probability of a network error in stream_->Send() called from Connection::DoQueueOutboundData. This will cause the connection to be closed. Prior to this revision, this kind of an error would cause Connection::QueueOutboundCall to attempt to schedule a timer in a connection that has already been shut down. - TEST_outbound_call_skip_callback_probability specifies the probability of skipping calling the callback on a particular remote RPC call. We don't do this for local calls. Also replacing a DFATAL with an WARNING log in InboundCall::QueueResponse to avoid crashing tests during shutdown. Failures to queue a response on the server side should just result in timeouts on the client side in the worst case. We are combining multiple original revisions from the master branch to avoid introducing and then fixing a memory leak bug, and to keep the resulting patch cleaner. This revision was backported from the 2.18 backport D29215 ( d028fe2 ). Original revisions in master: - D27735 ( 1fbff49 ) [yugabyte#18685] Track stuck OutboundCalls and enforce timeouts at Reactor level - D27919 ( ddb817b ) [yugabyte#18808] A write-once lock-free weak pointer class: it is frequently necessary to have a weak pointer equivalent that can only be written to once, but can be read without locking for performance. - D28085 ( a5ba08f ) [yugabyte#18855] Add functions for formatting a CoarseTimePoint relative to the current time. Useful for logging deadlines. - D28138 ( d0a44db ) [yugabyte#18877] Log invalid OutboundCall state transitions and other OutboundCall improvements. OutboundCall will track invalid state transitions and report them in the DebugString and in the destructor, in addition to reporting them as they happen. Do not allow OutboundCall callback to be invoked more than once and log occurrences of that. Use a compare-and-swap loop in RpcCall::Transferred and log invalid transfer_state transitions. invoke_callback_time_ and sent_time_ in OutboundCall were being accessed without synchronization, so making them atomic. OutboundCall::DebugString should not queue a task in the reactor to print the connection details in relation to the call anymore. That is now done by a separate method, QueueDumpConnectionState, called explicitly. - D28531 ( 0648341 ) [yugabyte#19090] Fix a memory leak in tracked outbound calls in Reactor. When an OutboundCall callback is invoked, notify the reactor through a multi-producer single-consumer queue that is accessed from the OutboundCall via a weak pointer. Also switching OutboundCall allocation away from using make_shared to prevent long-lived weak OutboundCall pointers from consuming memory. Also, parts of D23468 ( 4879cfb ) "[yugabyte#16380] Use thread safety analysis annotations to enforce the reactor thread requirement" are included. That commit is present in 2.18 but not in 2.16. Test Plan: Jenkins --- Manual testing details below. First test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_sent_stuck_call_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 java -jar yb-sample-apps.jar --workload CassandraBatchKeyValue --nodes 127.0.0.1:9042,127.0.0.2:9042,127.0.0.3:9042 --num_threads_read 16 --num_threads_write 16 --num_reads 1000000000000 --num_writes 1000000000000 ``` Look for output like this in the logs: ``` W1024 21:29:58.941679 1731793 connection.cc:307] Connection (0x0000564dbd812298) client 127.0.0.1:39689 => 127.0.0.2:9100: Simulating a call stuck in SENT state: RPC call 0x0000564dbbf3e580: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 6 protocol: 0x00007fd157f9cd70 -> tcpc }, id: 85493, state: SENT, transfer_state: PENDING, start_time: 455775.550s (0.001s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: +inf, now: 455775.551s, connection: Connection (0x0000564dbd812298) client 127.0.0.1:39689 => 127.0.0.2:9100, active_call_state: kNotAdded ... W1024 21:30:03.017571 1731793 reactor.cc:1142] TabletServer_R002: Stuck OutboundCall: RPC call 0x0000564dbbf3e580: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 6 protocol: 0x00007fd157f9cd70 -> tcpc }, id: 85493, state: SENT, transfer_state: PENDING, start_time: 455775.550s (4.077s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: 455778.551s (1.076s ago), now: 455779.628s, connection: Connection (0x0000564dbd812298) client 127.0.0.1:39689 => 127.0.0.2:9100, active_call_state: kNotAdded (forcing a timeout) W1024 21:30:03.017947 1731995 consensus_peers.cc:611] T 9735d87712974ea9b848cc606db8d664 P 9dcaaf7955ea4ca78667b1fa92c89192 -> Peer b6dbb1d832e14b0080d2143ac43fbaae ([host: "127.0.0.2" port: 9100], []): Couldn't send request. Status: Timed out (yb/rpc/outbound_call.cc:612): UpdateConsensus RPC (request call id 85493) to 127.0.0.2:9100 timed out after 3.000s. Retrying in the next heartbeat period. Already tried 1 times. State: 2 ``` Ensure that all stuck outbound calls are eventually detected. After stopping the workload, the output of the command below should gradually decrease to zero after a couple of minutes: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Simulating a call stuck in SENT state" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` Also, these stuck calls should stop appearing in the log because they would be forcibly timed out. If they were not, they would be logged every minute. Second test mode ================ ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_failure_to_send_call_probability=0.00001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Simulated failure to send outbound data" in the tablet server log: ``` W1024 22:33:22.772235 1739663 connection.cc:401] Simulated network failure: Network error (yb/rpc/connection.cc:400): Simulated failure to send outbound data for 0x000055999706f040 -> CQL Call from 127.0.0.1:50690, stream id: 9792 ... W1024 22:33:22.772346 1739663 inbound_call.cc:104] 0x000055999706f040 -> CQL Call from 127.0.0.1:50690, stream id: 9792: Connection torn down before CQL Call from 127.0.0.1:50690, stream id: 9792 could send its response: Network error (yb/rpc/connection.cc:400): Simulated failure to send outbound data for 0x000055999706f040 -> CQL Call from 127.0.0.1:50690, stream id: 9792 ``` There should be no stuck outbound calls in the log, because these simulated failures will just result in the connection being closed. Depending on the value TEST_simulated_failure_to_send_call_probability, the workload may succeed or fail. With the value 0.00001, it manages to make progress in my experience. Third test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_outbound_call_skip_callback_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Skipping OutboundCall callback as a test" and "Stuck OutboundCall" in the log. Output: ``` W1024 22:45:47.389113 1743081 outbound_call.cc:419] OutboundCall@0x0000562012975600: Skipping OutboundCall callback as a test: RPC call 0x0000562012975600: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 1 protocol: 0x00007fbff47fed70 -> tcpc }, id: 3815, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 460323.999s (0.001s ago), sent_time: 460323.999s (0.001s ago), trigger_callback_time: 460323.999s (0.001s ago), invoke_callback_time: -inf, expiration_time: 460326.999s (2.998s from now), now: 460324.000s, connection: Connection (0x00005620102b0798) client 127.0.0.1:55971 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1024 22:45:51.463742 1742860 reactor.cc:1142] TabletServer_R001: Stuck OutboundCall: RPC call 0x0000562012975600: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 1 protocol: 0x00007fbff47fed70 -> tcpc }, id: 3815, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 460323.999s (4.075s ago), sent_time: 460323.999s (4.075s ago), trigger_callback_time: 460323.999s (4.075s ago), invoke_callback_time: -inf, expiration_time: 460326.999s (1.075s ago), now: 460328.074s, connection: Connection (0x00005620102b0798) client 127.0.0.1:55971 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1024 22:46:21.564029 1742860 reactor.cc:1142] TabletServer_R001: Stuck OutboundCall: RPC call 0x0000562012975600: yb.consensus.ConsensusService.UpdateConsensus -> { remote: 127.0.0.2:9100 idx: 1 protocol: 0x00007fbff47fed70 -> tcpc }, id: 3815, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 460323.999s (34.175s ago), sent_time: 460323.999s (34.175s ago), trigger_callback_time: 460323.999s (34.175s ago), invoke_callback_time: -inf, expiration_time: 460326.999s (31.175s ago), now: 460358.174s, connection: Connection (0x00005620102b0798) client 127.0.0.1:55971 => 127.0.0.2:9100, active_call_state: kErasedOnResponse ``` Similarly to the first test, wait for all stuck outbound calls to get reported: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Skipping OutboundCall callback as a test" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` In this mode, because we are skipping callbacks but allowing state transitions to the finished state, forced expiration at reactor level does not work. Reviewers: sergei, bogdan Subscribers: bogdan Tags: #jenkins-ready Differential Revision: https://phorge.dev.yugabyte.com/D29679
mbautin
added a commit
that referenced
this issue
Oct 26, 2023
…alls Summary: Track all outbound calls submitted to a Reactor in a multi-index container in that reactor. Remove them from the container as soon as we learn the callback has been called, using a multiple-producer single-consumer (MPSC) queue where the consumer is the reactor thread. Report stuck calls with detailed debug information. A call is considered stuck if it is a certain time past its expiration (specified by reactor_based_outbound_call_expiration_delay_ms -- set it to 0 to disable this feature). If the call does not have a timeout, the default value stuck_outbound_call_default_timeout_sec is used for reporting only, but not for timeout enforcement. OutboundCall now keeps track of its expiration deadline, and an additional field active_call_state_, which indicates whether the call was added to the connection's active_calls_ in the corresponding connection, or removed from it, and the removal reason. If in the OutboundCall destructor the state of the call is not final, or the callback has not been called, we will log that even in release build. In OutboundCall::SetState, if the current state is already finished, treat this the same as any other invalid state transition. Logically, there should never be a race between e.g. processing a call response and a call timeout, because both events happen on the reactor thread. Fixing error handling in DoQueueOutboundData. If there is an error sending the call, we destroy the connection. Introduce a typedef CallHandle and a special value kUnknownCallHandle instead of just using the max value of size_t in case the call handle is unknown or not being used. Change the error handling logic in Connection::DoQueueOutboundData to avoid returning kUnknownCallHandle in case of errors, and make sure the callback is called on the call in case of those errors. The connection was already being shut down. Update the YB_STRUCT_TO_STRING macro implementation to always add parentheses around an explicitly specified field value. We introduce multiple ways to simulate stuck outbound calls for testing. - TEST_simulated_sent_stuck_call_probability specifies the probability of pretending a call is sent to the remote server in -Connection::QueueOutboundCall, but instead just transitioning it to a SENT state. This is similar to the situation that we have observed. - TEST_simulated_failure_to_send_call_probability specifies the probability of a network error in stream_->Send() called from Connection::DoQueueOutboundData. This will cause the connection to be closed. Prior to this revision, this kind of an error would cause Connection::QueueOutboundCall to attempt to schedule a timer in a connection that has already been shut down. - TEST_outbound_call_skip_callback_probability specifies the probability of skipping calling the callback on a particular remote RPC call. We don't do this for local calls. Also replacing a DFATAL with an WARNING log in InboundCall::QueueResponse to avoid crashing tests during shutdown. Failures to queue a response on the server side should just result in timeouts on the client side in the worst case. We are combining multiple original revisions from the master branch to avoid introducing and then fixing a memory leak bug, and to keep the resulting patch cleaner. This revision was backported from the 2.18 backport D29215 ( d028fe2 ). Original revisions in master: - D27735 ( 1fbff49 ) [#18685] Track stuck OutboundCalls and enforce timeouts at Reactor level - D27919 ( ddb817b ) [#18808] A write-once lock-free weak pointer class: it is frequently necessary to have a weak pointer equivalent that can only be written to once, but can be read without locking for performance. - D28085 ( a5ba08f ) [#18855] Add functions for formatting a CoarseTimePoint relative to the current time. Useful for logging deadlines. - D28138 ( d0a44db ) [#18877] Log invalid OutboundCall state transitions and other OutboundCall improvements. OutboundCall will track invalid state transitions and report them in the DebugString and in the destructor, in addition to reporting them as they happen. Do not allow OutboundCall callback to be invoked more than once and log occurrences of that. Use a compare-and-swap loop in RpcCall::Transferred and log invalid transfer_state transitions. invoke_callback_time_ and sent_time_ in OutboundCall were being accessed without synchronization, so making them atomic. OutboundCall::DebugString should not queue a task in the reactor to print the connection details in relation to the call anymore. That is now done by a separate method, QueueDumpConnectionState, called explicitly. - D28531 ( 0648341 ) [#19090] Fix a memory leak in tracked outbound calls in Reactor. When an OutboundCall callback is invoked, notify the reactor through a multi-producer single-consumer queue that is accessed from the OutboundCall via a weak pointer. Also switching OutboundCall allocation away from using make_shared to prevent long-lived weak OutboundCall pointers from consuming memory. Also, parts of D23468 ( 4879cfb ) "[#16380] Use thread safety analysis annotations to enforce the reactor thread requirement" are included. That commit is present in 2.18 but not in 2.16. Test Plan: Jenkins --- Manual testing details below. First test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_sent_stuck_call_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 java -jar yb-sample-apps.jar --workload CassandraBatchKeyValue --nodes 127.0.0.1:9042,127.0.0.2:9042,127.0.0.3:9042 --num_threads_read 16 --num_threads_write 16 --num_reads 1000000000000 --num_writes 1000000000000 ``` Look for output like this in the logs: ``` W1026 21:24:56.539093 414631 connection.cc:309] Connection (0x0000000002eb4798) client 127.0.0.1:39823 => 127.0.0.3:9100: Simulating a call stuck in SENT state: RPC call 0x00000000027de000: yb.tserver.TabletServerService.Read -> { remote: 127.0.0.3:9100 idx: 6 protocol: 0x00007f881e43d288 -> tcpc }, id: 40542, state: SENT, transfer_state: PENDING, start_time: 11115.055s (now), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: +inf, now: 11115.055s, connection: Connection (0x0000000002eb4798) client 127.0.0.1:39823 => 127.0.0.3:9100, active_call_state: kNotAdded ... W1026 21:25:57.560870 414631 reactor.cc:1160] TabletServer_R000: Stuck OutboundCall: RPC call 0x00000000027de000: yb.tserver.TabletServerService.Read -> { remote: 127.0.0.3:9100 idx: 6 protocol: 0x00007f881e43d288 -> tcpc }, id: 40542, state: SENT, transfer_state: PENDING, start_time: 11115.055s (61.021s ago), sent_time: -inf, trigger_callback_time: -inf, invoke_callback_time: -inf, expiration_time: 11175.055s (1.021s ago), now: 11176.077s, connection: Connection (0x0000000002eb4798) client 127.0.0.1:39823 => 127.0.0.3:9100, active_call_state: kNotAdded (forcing a timeout) W1026 21:25:57.560998 414715 tablet_rpc.cc:473] Timed out (yb/rpc/outbound_call.cc:607): Failed Read(tablet: 1a3b09b848f1430f81a9351fbc467969, num_ops: 1, num_attempts: 1, txn: 00000000-0000-0000-0000-000000000000, subtxn: [none]) to tablet 1a3b09b848f1430f81a9351fbc467969 on tablet server { uuid: 082e0b47233a4c3aa675aa325a33f2b9 private: [host: "127.0.0.3" port: 9100] cloud_info: placement_cloud: "cloud1" placement_region: "datacenter1" placement_zone: "rack1" after 1 attempt(s): Read RPC (request call id 40542) to 127.0.0.3:9100 timed out after 60.000s ``` Ensure that all stuck outbound calls are eventually detected. After stopping the workload, the output of the command below should gradually decrease to zero after a couple of minutes: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Simulating a call stuck in SENT state" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` Also, these stuck calls should stop appearing in the log because they would be forcibly timed out. If they were not, they would be logged every minute. Second test mode ================ ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_simulated_failure_to_send_call_probability=0.00001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Simulated failure to send outbound data" in the tablet server log: ``` W1026 21:44:12.015067 424964 connection.cc:404] Simulated network failure: Network error (yb/rpc/connection.cc:403): Simulated failure to send outbound data for 0x0000000006874800 -> Call yb.consensus.ConsensusService.UpdateConsensus 127.0.0.2:50031 => 127.0.0.1:9100 (request call id 6989) . . . W1026 21:44:12.015129 424964 inbound_call.cc:104] 0x0000000006874800 -> Call yb.consensus.ConsensusService.UpdateConsensus 127.0.0.2:50031 => 127.0.0.1:9100 (request call id 6989): Connection torn down before Call yb.consensus.ConsensusService.UpdateConsensus 127.0.0.2:50031 => 127.0.0.1:9100 (request call id 6989) could send its response: Network error (yb/rpc/connection.cc:403): Simulated failure to send outbound data for 0x0000000006874800 -> Call yb.consensus.ConsensusService.UpdateConsensus 127.0.0.2:50031 => 127.0.0.1:9100 (request call id 6989) ``` There should be no stuck outbound calls in the log, because these simulated failures will just result in the connection being closed. Depending on the value TEST_simulated_failure_to_send_call_probability, the workload may succeed or fail. With the value 0.00001, it manages to make progress in my experience. Third test mode =============== ``` bin/yb-ctl wipe_restart --tserver_flags="TEST_outbound_call_skip_callback_probability=0.0001,reactor_based_outbound_call_expiration_delay_ms=1000" --rf=3 ``` Same workload as above. Look for "Skipping OutboundCall callback as a test" and "Stuck OutboundCall" in the log. Output: ``` W1026 21:49:18.330013 427274 outbound_call.cc:414] OutboundCall@0x0000000007f9cdc0: Skipping OutboundCall callback as a test: RPC call 0x0000000007f9cdc0: yb.tserver.TabletServerService.Write -> { remote: 127.0.0.2:9100 idx: 5 protocol: 0x00007f4e5cb17288 -> tcpc }, id: 58289, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 12576.835s (0.011s ago), sent_time: 12576.835s (0.011s ago), trigger_callback_time: 12576.847s (now), invoke_callback_time: -inf, expiration_time: 12636.835s (59.988s from now), now: 12576.847s, connection: Connection (0x0000000004a51058) client 127.0.0.1:55591 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1026 21:50:19.366196 426374 reactor.cc:1160] TabletServer_R001: Stuck OutboundCall: RPC call 0x0000000007f9cdc0: yb.tserver.TabletServerService.Write -> { remote: 127.0.0.2:9100 idx: 5 protocol: 0x00007f4e5cb17288 -> tcpc }, id: 58289, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 12576.835s (61.047s ago), sent_time: 12576.835s (61.047s ago), trigger_callback_time: 12576.847s (61.035s ago), invoke_callback_time: -inf, expiration_time: 12636.835s (1.047s ago), now: 12637.883s, connection: Connection (0x0000000004a51058) client 127.0.0.1:55591 => 127.0.0.2:9100, active_call_state: kErasedOnResponse . . . W1026 21:50:49.467150 426374 reactor.cc:1160] TabletServer_R001: Stuck OutboundCall: RPC call 0x0000000007f9cdc0: yb.tserver.TabletServerService.Write -> { remote: 127.0.0.2:9100 idx: 5 protocol: 0x00007f4e5cb17288 -> tcpc }, id: 58289, state: FINISHED_SUCCESS, transfer_state: FINISHED, start_time: 12576.835s (91.148s ago), sent_time: 12576.835s (91.148s ago), trigger_callback_time: 12576.847s (91.136s ago), invoke_callback_time: -inf, expiration_time: 12636.835s (31.148s ago), now: 12667.984s, connection: Connection (0x0000000004a51058) client 127.0.0.1:55591 => 127.0.0.2:9100, active_call_state: kErasedOnResponse ``` Similarly to the first test, wait for all stuck outbound calls to get reported: ``` log_path="$HOME/yugabyte-data/node-1/disk-1/yb-data/tserver/logs/yb-tserver.INFO"; grep "Skipping OutboundCall callback as a test" "$log_path" | egrep -Eo 'id: [0-9]+' | awk '{print $NF}' | sort -n | while read c; do if ! grep "id: $c," "$log_path" | grep -q "Stuck OutboundCall"; then echo "Undetected stuck OutboundCall: id=$c"; fi; done | wc -l ``` In this mode, because we are skipping callbacks but allowing state transitions to the finished state, forced expiration at reactor level does not work. Reviewers: sergei, bogdan Reviewed By: sergei Subscribers: bogdan Differential Revision: https://phorge.dev.yugabyte.com/D29679
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Jira Link: DB-7900
Description
There is no exception at the client side.
The cause of failure is still under investigation, but it could be because of oom-killer killing one of the process:
Warning: Please confirm that this issue does not contain any sensitive information
The text was updated successfully, but these errors were encountered: