search

yugabyte / yugabyte-db

YugabyteDB - the cloud native distributed SQL database for mission-critical applications.
https://www.yugabyte.com
Other
9.01k stars 1.08k forks source link

[YSQL] Masters majority is required even for normal operations #1787

Open frozenspider opened 5 years ago

frozenspider commented 5 years ago

Jira Link: DB-2492 Running bank-multitable on Jepsen and introducing kill-master nemesis, I noticed that cluster becomes inoperable (at least) when all 3 masters are down. Test itself involved SELECT/UPDATE queries not involving system tables. Is such behaviour expected?

Take a look at this graph: latency-raw Here, 2nd and 3rd failure introduced by nemesis was killing all 3 masters, and cluster ceased serving requests for that time.

tserver log excerpt from one of the nodes for the 2nd failure, looking more-or-less the same for all of them:

// Normal operations

...
I0711 22:41:58.429186 15440 transaction_coordinator.cc:791] T 9efa9072cef243e8b640e72992a52b5b P 014d21062bf54a00a0fc450359640545: Request to unknown transaction a19da9cb-c995-471b-918a-936b7182da57: transaction_id: "\241\235\251\313\311\225G\033\221\212\223kq\202\332W" status: COMMITTED tablets: "44d89a5edda241b8a321eff394b3c656" tablets: "2feadc3824964f0fa99d0d72c44cc3a1"
I0711 22:41:58.971884 15438 transaction_coordinator.cc:791] T 80ef9fc8bcdd419680c93ee5902e35b6 P 014d21062bf54a00a0fc450359640545: Request to unknown transaction a490a525-a1e2-4632-82d8-c44d96c19ec5: transaction_id: "\244\220\245%\241\342F2\202\330\304M\226\301\236\305" status: COMMITTED tablets: "44d89a5edda241b8a321eff394b3c656" tablets: "3badce9fc5bc4e49a30feaa5c88e4a9d" tablets: "8b1bf2e391a443f59d3ebb4c6666142b" tablets: "1ff59e4f42064cadb9d2b705de4ecedd" tablets: "d9f75a0a52fc4ae69f927f698a76b0ef" tablets: "2feadc3824964f0fa99d0d72c44cc3a1" tablets: "a040f254cabb4bee9df8eb7fc2d1216d" tablets: "f5278d0be47d409783e18af34c4f38b4"

// Master going down

W0711 22:42:02.158424 15257 heartbeater.cc:574] P 014d21062bf54a00a0fc450359640545: Failed to heartbeat to n1:7100: Network error (yb/util/net/socket.cc:590): Failed to send heartbeat: recvmsg error: Connection refused (error 111) tries=0, num=3, masters=0x00000000014b2a30 -> [[n1:7100], [n2:7100], [n3:7100]], code=Network error
I0711 22:42:05.718855 15257 heartbeater.cc:283] P 014d21062bf54a00a0fc450359640545: Find leader master n1:7100 hit error Timed out (yb/rpc/outbound_call.cc:461): GetMasterRegistration RPC to 192.168.122.11:7100 timed out after 2.500s
W0711 22:42:05.719046 15257 heartbeater.cc:574] P 014d21062bf54a00a0fc450359640545: Failed to heartbeat to n1:7100: Timed out (yb/rpc/outbound_call.cc:461): GetMasterRegistration RPC to 192.168.122.11:7100 timed out after 2.500s tries=1, num=3, masters=0x00000000014b2a30 -> [[n1:7100], [n2:7100], [n3:7100]], code=Timed out
I0711 22:42:06.733880 15248 tcp_stream.cc:292] { local: 192.168.122.11:43125 remote: 192.168.122.11:7100 }:  Recv failed: Network error (yb/util/net/socket.cc:590): recvmsg error: Connection refused (error 111)
I0711 22:42:09.261698 15257 heartbeater.cc:283] P 014d21062bf54a00a0fc450359640545: Find leader master n1:7100 hit error Timed out (yb/rpc/outbound_call.cc:461): GetMasterRegistration RPC to 192.168.122.11:7100 timed out after 2.500s
W0711 22:42:09.261839 15257 heartbeater.cc:574] P 014d21062bf54a00a0fc450359640545: Failed to heartbeat to n1:7100: Timed out (yb/rpc/outbound_call.cc:461): GetMasterRegistration RPC to 192.168.122.11:7100 timed out after 2.500s tries=2, num=3, masters=0x00000000014b2a30 -> [[n1:7100], [n2:7100], [n3:7100]], code=Timed out
I0711 22:42:12.810573 15257 heartbeater.cc:283] P 014d21062bf54a00a0fc450359640545: Find leader master n1:7100 hit error Timed out (yb/rpc/outbound_call.cc:461): GetMasterRegistration RPC to 192.168.122.11:7100 timed out after 2.500s
W0711 22:42:12.810766 15257 heartbeater.cc:574] P 014d21062bf54a00a0fc450359640545: Failed to heartbeat to n1:7100: Timed out (yb/rpc/outbound_call.cc:461): GetMasterRegistration RPC to 192.168.122.11:7100 timed out after 2.500s tries=3, num=3, masters=0x00000000014b2a30 -> [[n1:7100], [n2:7100], [n3:7100]], code=Timed out
I0711 22:42:13.839411 15249 tcp_stream.cc:292] { local: 192.168.122.11:39689 remote: 192.168.122.13:7100 }:  Recv failed: Network error (yb/util/net/socket.cc:590): recvmsg error: Connection refused (error 111)
I0711 22:42:16.357856 15257 heartbeater.cc:283] P 014d21062bf54a00a0fc450359640545: Find leader master n1:7100 hit error Timed out (yb/rpc/outbound_call.cc:461): GetMasterRegistration RPC to 192.168.122.11:7100 timed out after 2.500s
W0711 22:42:16.358009 15257 heartbeater.cc:574] P 014d21062bf54a00a0fc450359640545: Failed to heartbeat to n1:7100: Timed out (yb/rpc/outbound_call.cc:461): GetMasterRegistration RPC to 192.168.122.11:7100 timed out after 2.500s tries=4, num=3, masters=0x00000000014b2a30 -> [[n1:7100], [n2:7100], [n3:7100]], code=Timed out
I0711 22:42:18.332373 15244 tcp_stream.cc:292] { local: 192.168.122.11:52343 remote: 192.168.122.12:7100 }:  Recv failed: Network error (yb/util/net/socket.cc:590): recvmsg error: Connection refused (error 111)
I0711 22:42:18.751232 15243 tcp_stream.cc:292] { local: 192.168.122.11:37361 remote: 192.168.122.13:7100 }:  Recv failed: Network error (yb/util/net/socket.cc:590): recvmsg error: Connection refused (error 111)
I0711 22:42:19.478632 15244 tcp_stream.cc:292] { local: 192.168.122.11:51319 remote: 192.168.122.13:7100 }:  Recv failed: Network error (yb/util/net/socket.cc:590): recvmsg error: Connection refused (error 111)
I0711 22:42:20.498860 15245 tcp_stream.cc:292] { local: 192.168.122.11:38741 remote: 192.168.122.13:7100 }:  Recv failed: Network error (yb/util/net/socket.cc:590): recvmsg error: Connection refused (error 111)
I0711 22:42:21.810004 15247 tcp_stream.cc:292] { local: 192.168.122.11:60859 remote: 192.168.122.12:7100 }:  Recv failed: Network error (yb/util/net/socket.cc:590): recvmsg error: Connection refused (error 111)
I0711 22:42:23.303707 15246 tcp_stream.cc:292] { local: 192.168.122.11:56503 remote: 192.168.122.13:7100 }:  Recv failed: Network error (yb/util/net/socket.cc:590): recvmsg error: Connection refused (error 111)

// Master getting up again, operations resumed

W0711 22:42:25.057536 15453 master_rpc.cc:274] More than 500 ms has passed, choosing to heartbeat to follower master 38150b10aa5d4c7eb953c039ea4e0514 after 114 iterations of all masters.
I0711 22:42:25.058336 15257 heartbeater.cc:299] P 014d21062bf54a00a0fc450359640545: Connected to a leader master server at n1:7100
W0711 22:42:25.059733 15257 heartbeater.cc:574] P 014d21062bf54a00a0fc450359640545: Failed to heartbeat to n1:7100: Service unavailable (yb/tserver/heartbeater.cc:471): master is no longer the leader tries=5, num=3, masters=0x00000000014b2a30 -> [[n1:7100], [n2:7100], [n3:7100]], code=Service unavailable
W0711 22:42:26.560830 15440 master_rpc.cc:274] More than 500 ms has passed, choosing to heartbeat to follower master 990d6968e9a446d786630567cc8fc264 after 28 iterations of all masters.
I0711 22:42:26.561612 15257 heartbeater.cc:299] P 014d21062bf54a00a0fc450359640545: Connected to a leader master server at n2:7100
W0711 22:42:26.562361 15257 heartbeater.cc:574] P 014d21062bf54a00a0fc450359640545: Failed to heartbeat to n2:7100: Service unavailable (yb/tserver/heartbeater.cc:471): master is no longer the leader tries=6, num=3, masters=0x00000000014b2a30 -> [[n1:7100], [n2:7100], [n3:7100]], code=Service unavailable
I0711 22:42:27.589871 15257 heartbeater.cc:299] P 014d21062bf54a00a0fc450359640545: Connected to a leader master server at n3:7100
W0711 22:42:27.590864 15257 heartbeater.cc:574] P 014d21062bf54a00a0fc450359640545: Failed to heartbeat to n3:7100: Service unavailable (yb/tserver/heartbeater.cc:471): master is no longer the leader tries=7, num=3, masters=0x00000000014b2a30 -> [[n1:7100], [n2:7100], [n3:7100]], code=Service unavailable
I0711 22:42:28.592788 15257 heartbeater.cc:299] P 014d21062bf54a00a0fc450359640545: Connected to a leader master server at n3:7100
I0711 22:42:28.594663 15257 heartbeater.cc:357] P 014d21062bf54a00a0fc450359640545: Registering TS with master...
I0711 22:42:28.594717 15257 server_base.cc:477] Using private ip address 192.168.122.11
I0711 22:42:28.596089 15257 heartbeater.cc:366] P 014d21062bf54a00a0fc450359640545: Sending a full tablet report to master...
I0711 22:42:28.924378 15502 transaction_participant.cc:1047] T a040f254cabb4bee9df8eb7fc2d1216d P 014d21062bf54a00a0fc450359640545: Loading transaction: ad18e546-220b-413e-aa4d-e5b6bbc26df4, for: add
I0711 22:42:28.925089 15502 transaction_participant.cc:1060] T a040f254cabb4bee9df8eb7fc2d1216d P 014d21062bf54a00a0fc450359640545: Transaction not found: ad18e546-220b-413e-aa4d-e5b6bbc26df4, for: add
...

Full logs: logs-jepsen_2019-07-12_01-54-33__bank-multi_n-km_lr_c10_t400.tar.gz

qvad commented 2 years ago

Result for latest master builds.

So killing master might drop ops to zero, but sometimes it doesn't. latency-raw