[ https://issues.apache.org/jira/browse/KUDU-2727?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17161365#comment-17161365 ]
ASF subversion and git services commented on KUDU-2727: ------------------------------------------------------- Commit 0914eb527e82acc727828d951559981c905a7f0c in kudu's branch refs/heads/master from Alexey Serbin [ https://gitbox.apache.org/repos/asf?p=kudu.git;h=0914eb5 ] [tests] add same_tablet_concurrent_writes test Added SameTabletConcurrentWritesTest.InsertsOnly test scenario. The scenario exercises concurrent inserts from multiple clients into the same tablet. The purpose of the newly introduced test is to check for lock contention if running multiple write operations on the same tablet concurrently. There is an interaction between threads pushing Raft consensus updates and RPC worker threads serving write requests, and the test pinpoints the contention over the lock primitives used in RaftConsensus. To validate the results reported by the test, I verified that RPC queue overflows happen much less often if using the lock-free implementation of RaftConsensus::CheckLeadershipAndBindTerm() addressed in KUDU-2727 fix (da1c66b61). The rates of successful write operations was the same for both cases, and that's expected since the bottleneck is the WAL (where additional static delays are introduced per each fsync). However, the number of messages from spinlock_profiling.cc like Waited 190 ms on lock 0x237acd4 ... dropped significantly after KUDU-2727 fix (da1c66b61). That's a good news to have less contention because the freed CPU resources might be spend on something useful, like handing another RPC request from the queue (which isn't overflown and able to accommodate extra requests). Below are snippets of various measurements done for this new test before and after applying patch from 16034 review item on top. ======================================================================== Without 16034 patch: Performance counter stats for './bin/same_tablet_concurrent_writes-itest': 7449.425640 task-clock # 0.504 CPUs utilized 47,882 context-switches # 0.006 M/sec 3,454 cpu-migrations # 0.464 K/sec 28,592 page-faults # 0.004 M/sec 10,211,586,270 cycles # 1.371 GHz 10,647,306,766 instructions # 1.04 insns per cycle 1,861,229,149 branches # 249.849 M/sec 25,370,590 branch-misses # 1.36% of all branches 14.767762000 seconds time elapsed With 16034 patch: Performance counter stats for './bin/same_tablet_concurrent_writes-itest': 5646.543970 task-clock # 0.394 CPUs utilized 39,194 context-switches # 0.007 M/sec 3,715 cpu-migrations # 0.658 K/sec 30,090 page-faults # 0.005 M/sec 8,543,832,082 cycles # 1.513 GHz 9,301,870,856 instructions # 1.09 insns per cycle 1,590,579,357 branches # 281.691 M/sec 18,563,203 branch-misses # 1.17% of all branches 14.339274728 seconds time elapsed ======================================================================== ------------------------------------------------------------------------ | Without 16034 patch | With 16034 patch ------------------------------------------------------------------------ write RPC request rate | 15.8 req/sec | 16 req/sec RPC queue overflows | 1898 | 50 spinlock_contention_time | 22966310 | 9161557 ------------------------------------------------------------------------ rpc_incoming_queue_time | | | Count: 82 | Count: 82 | Mean: 199704 | Mean: 1037.87 | Percentiles: | Percentiles: | 0% (min) = 35 | 0% (min) = 21 | 25% = 5844 | 25% = 51 | 50% (med) = 196096 | 50% (med) = 67 | 75% = 388352 | 75% = 1608 | 95% = 400640 | 95% = 3334 | 99% = 598016 | 99% = 9960 | 99.9% = 599552 | 99.9% = 10064 | 99.99% = 599552 | 99.99% = 10064 | 100% (max) = 600048 | 100% (max) = 10066 ------------------------------------------------------------------------ op_apply_run_time | | | Count: 79 | Count: 80 | Mean: 99377.1 | Mean: 80796.3 | Percentiles: | Percentiles: | 0% (min) = 429 | 0% (min) = 575 | 25% = 940 | 25% = 828 | 50% (med) = 1336 | 50% (med) = 1064 | 75% = 200704 | 75% = 200704 | 95% = 391168 | 95% = 200704 | 99% = 401408 | 99% = 200704 | 99.9% = 401408 | 99.9% = 399360 | 99.99% = 401408 | 99.99% = 399360 | 100% (max) = 401432 | 100% (max) = 399703 ------------------------------------------------------------------------ handler_latency_kudu_tserver_TabletServerService_Write: | Count: 49 | Count: 45 | Mean: 3.11688e+06 | Mean: 3.08435e+06 | Percentiles: | Percentiles: | 0% (min) = 611494 | 0% (min) = 636928 | 25% = 1802240 | 25% = 2392064 | 50% (med) = 3391488 | 50% (med) = 3178496 | 75% = 4390912 | 75% = 3997696 | 95% = 4816896 | 95% = 4587520 | 99% = 5013504 | 99% = 4587520 | 99.9% = 5013504 | 99.9% = 4587520 | 99.99% = 5013504 | 99.99% = 4587520 | 100% (max) = 5023673 | 100% (max) = 4616174 ------------------------------------------------------------------------ Change-Id: I7eef6e46e7685450354473cee9d804c5054723eb Reviewed-on: http://gerrit.cloudera.org:8080/16060 Reviewed-by: Attila Bukor <abu...@apache.org> Tested-by: Kudu Jenkins Reviewed-by: Grant Henke <granthe...@apache.org> > Contention on the Raft consensus lock can cause tablet service queue overflows > ------------------------------------------------------------------------------ > > Key: KUDU-2727 > URL: https://issues.apache.org/jira/browse/KUDU-2727 > Project: Kudu > Issue Type: Improvement > Components: consensus, tserver > Reporter: William Berkeley > Assignee: Alexey Serbin > Priority: Major > Labels: performance, scalability > Fix For: 1.13.0 > > > Here's stacks illustrating the phenomenon: > {noformat} > tids=[2201] > 0x379ba0f710 <unknown> > 0x1fb951a base::internal::SpinLockDelay() > 0x1fb93b7 base::SpinLock::SlowLock() > 0xb4e68e kudu::consensus::Peer::SignalRequest() > 0xb9c0df kudu::consensus::PeerManager::SignalRequest() > 0xb8c178 kudu::consensus::RaftConsensus::Replicate() > 0xaab816 kudu::tablet::TransactionDriver::Prepare() > 0xaac0ed kudu::tablet::TransactionDriver::PrepareTask() > 0x1fa37ed kudu::ThreadPool::DispatchThread() > 0x1f9c2a1 kudu::Thread::SuperviseThread() > 0x379ba079d1 start_thread > 0x379b6e88fd clone > tids=[4515] > 0x379ba0f710 <unknown> > 0x1fb951a base::internal::SpinLockDelay() > 0x1fb93b7 base::SpinLock::SlowLock() > 0xb74c60 kudu::consensus::RaftConsensus::NotifyCommitIndex() > 0xb59307 kudu::consensus::PeerMessageQueue::NotifyObserversTask() > 0xb54058 > _ZN4kudu8internal7InvokerILi2ENS0_9BindStateINS0_15RunnableAdapterIMNS_9consensus16PeerMessageQueueEFvRKSt8functionIFvPNS4_24PeerMessageQueueObserverEEEEEEFvPS5_SC_EFvNS0_17UnretainedWrapperIS5_EEZNS5_34NotifyObserversOfCommitIndexChangeElEUlS8_E_EEESH_E3RunEPNS0_13BindStateBaseE > 0x1fa37ed kudu::ThreadPool::DispatchThread() > 0x1f9c2a1 kudu::Thread::SuperviseThread() > 0x379ba079d1 start_thread > 0x379b6e88fd clone > tids=[22185,22194,22193,22188,22187,22186] > 0x379ba0f710 <unknown> > 0x1fb951a base::internal::SpinLockDelay() > 0x1fb93b7 base::SpinLock::SlowLock() > 0xb8bff8 > kudu::consensus::RaftConsensus::CheckLeadershipAndBindTerm() > 0xaaaef9 kudu::tablet::TransactionDriver::ExecuteAsync() > 0xaa3742 kudu::tablet::TabletReplica::SubmitWrite() > 0x92812d kudu::tserver::TabletServiceImpl::Write() > 0x1e28f3c kudu::rpc::GeneratedServiceIf::Handle() > 0x1e2986a kudu::rpc::ServicePool::RunThread() > 0x1f9c2a1 kudu::Thread::SuperviseThread() > 0x379ba079d1 start_thread > 0x379b6e88fd clone > tids=[22192,22191] > 0x379ba0f710 <unknown> > 0x1fb951a base::internal::SpinLockDelay() > 0x1fb93b7 base::SpinLock::SlowLock() > 0x1e13dec kudu::rpc::ResultTracker::TrackRpc() > 0x1e28ef5 kudu::rpc::GeneratedServiceIf::Handle() > 0x1e2986a kudu::rpc::ServicePool::RunThread() > 0x1f9c2a1 kudu::Thread::SuperviseThread() > 0x379ba079d1 start_thread > 0x379b6e88fd clone > tids=[4426] > 0x379ba0f710 <unknown> > 0x206d3d0 <unknown> > 0x212fd25 google::protobuf::Message::SpaceUsedLong() > 0x211dee4 > google::protobuf::internal::GeneratedMessageReflection::SpaceUsedLong() > 0xb6658e kudu::consensus::LogCache::AppendOperations() > 0xb5c539 kudu::consensus::PeerMessageQueue::AppendOperations() > 0xb5c7c7 kudu::consensus::PeerMessageQueue::AppendOperation() > 0xb7c675 > kudu::consensus::RaftConsensus::AppendNewRoundToQueueUnlocked() > 0xb8c147 kudu::consensus::RaftConsensus::Replicate() > 0xaab816 kudu::tablet::TransactionDriver::Prepare() > 0xaac0ed kudu::tablet::TransactionDriver::PrepareTask() > 0x1fa37ed kudu::ThreadPool::DispatchThread() > 0x1f9c2a1 kudu::Thread::SuperviseThread() > 0x379ba079d1 start_thread > 0x379b6e88fd clone > {noformat} > {{kudu::consensus::RaftConsensus::CheckLeadershipAndBindTerm()}} needs to > take the lock to check the term and the Raft role. When many RPCs come in for > the same tablet, the contention can hog service threads and cause queue > overflows on busy systems. > Yugabyte switched their equivalent lock to be an atomic that allows them to > read the term and role wait-free. -- This message was sent by Atlassian Jira (v8.3.4#803005)