[
https://issues.apache.org/jira/browse/KUDU-3149?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17217158#comment-17217158
]
ASF subversion and git services commented on KUDU-3149:
-------------------------------------------------------
Commit 483807a622bbb10558f9905e87ab0ab1b7abca35 in kudu's branch
refs/heads/master from Andrew Wong
[ https://gitbox.apache.org/repos/asf?p=kudu.git;h=483807a ]
KUDU-3149: don't block op registration on MM mutex
The maintenance manager's 'lock_' is a mutex that is taken upon access
to 'ops_', notably when iterating through 'ops_' to find the best op to
run. This particular critical section can last quite a while, as finding
the best op entails computing stats for each op, which is expensive for
compactions, blocking op registration and thus tablet bootstrapping.
This patch addresses the issue by buffering calls to RegisterOp() into a
separate op map protected by a separate spinlock, and periodically
merging the separate map into 'ops_'.
I added a unit test for the maintenance manager change, and added a
single-node test to contend several tablets' bootstrap with compactions.
I ran this with and without op buffering (via a flag that I have removed
from this patch) with the following results:
[awong@va1022 release]$ for i in {1..5}; do ./bin/tablet_server-test
--gtest_filter=*WithConcurrent* --num_tablets=300 --num_rowsets_per_tablet=30
--buffer_op_registration=true |& grep "waiting for all bootstraps to finish";
done
I1014 02:19:25.452993 80415 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 0.787s user 0.000s sys 0.002s
I1014 02:19:43.039741 82020 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 0.641s user 0.000s sys 0.004s
I1014 02:20:02.907203 83608 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 0.769s user 0.001s sys 0.002s
I1014 02:20:21.779570 85260 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 0.758s user 0.002s sys 0.001s
I1014 02:20:40.687155 86874 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 0.682s user 0.001s sys 0.002s
Average real time with op buffering: 0.727s
[awong@va1022 release]$ for i in {1..5}; do ./bin/tablet_server-test
--gtest_filter=*WithConcurrent* --num_tablets=300 --num_rowsets_per_tablet=30
--buffer_op_registration=false |& grep "waiting for all bootstraps to finish";
done
I1014 02:21:13.666689 88559 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 1.538s user 0.002s sys 0.001s
I1014 02:21:33.119479 90172 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 1.316s user 0.001s sys 0.002s
I1014 02:21:53.929062 91816 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 1.393s user 0.003s sys 0.001s
I1014 02:22:12.764689 93439 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 1.356s user 0.003s sys 0.000s
I1014 02:22:31.138669 95042 tablet_server-test.cc:4405] Time spent waiting for
all bootstraps to finish: real 1.516s user 0.000s sys 0.003s
Average real time without op buffering: 1.424s
Change-Id: I4a1b810f5b7ff6a22acc9b10b79ddffa8085c990
Reviewed-on: http://gerrit.cloudera.org:8080/16580
Tested-by: Kudu Jenkins
Reviewed-by: Alexey Serbin <[email protected]>
> Lock contention between registering ops and computing maintenance op stats
> --------------------------------------------------------------------------
>
> Key: KUDU-3149
> URL: https://issues.apache.org/jira/browse/KUDU-3149
> Project: Kudu
> Issue Type: Bug
> Components: perf, tserver
> Reporter: Andrew Wong
> Priority: Critical
>
> We saw a bunch of tablets bootstrapping extremely slowly, and many stuck
> supposedly bootstrapping, but not showing up in the {{/tablets}} page, i.e.
> we could only see INITIALIZED and RUNNING tablets, no BOOTSTRAPPING.
> Upon digging into the stacks, we saw a bunch waiting to acquire the MM lock:
> {code:java}
> TID 46577(tablet-open [wo):
> @ 0x7f1dd57147e0 (unknown)
> @ 0x7f1dd5713332 (unknown)
> @ 0x7f1dd570e5d8 (unknown)
> @ 0x7f1dd570e4a7 (unknown)
> @ 0x23b4058 kudu::Mutex::Acquire()
> @ 0x23980ff kudu::MaintenanceManager::RegisterOp()
> @ 0xb59b99 kudu::tablet::Tablet::RegisterMaintenanceOps()
> @ 0xb855a1
> kudu::tablet::TabletReplica::RegisterMaintenanceOps()
> @ 0xa0055b kudu::tserver::TSTabletManager::OpenTablet()
> @ 0x23f994c kudu::ThreadPool::DispatchThread()
> @ 0x23f3f8b kudu::Thread::SuperviseThread()
> @ 0x7f1dd570caa1 (unknown)
> @ 0x7f1dd3b18bcd (unknown)
> TID 46574(tablet-open [wo):
> @ 0x7f1dd57147e0 (unknown)
> @ 0x7f1dd5713332 (unknown)
> @ 0x7f1dd570e5d8 (unknown)
> @ 0x7f1dd570e4a7 (unknown)
> @ 0x23b4058 kudu::Mutex::Acquire()
> @ 0x23980ff kudu::MaintenanceManager::RegisterOp()
> @ 0xb59c74 kudu::tablet::Tablet::RegisterMaintenanceOps()
> @ 0xb855a1
> kudu::tablet::TabletReplica::RegisterMaintenanceOps()
> @ 0xa0055b kudu::tserver::TSTabletManager::OpenTablet()
> @ 0x23f994c kudu::ThreadPool::DispatchThread()
> @ 0x23f3f8b kudu::Thread::SuperviseThread()
> @ 0x7f1dd570caa1 (unknown)
> @ 0x7f1dd3b18bcd (unknown)
> 7 threads with same stack:
> TID 46575(tablet-open [wo):
> TID 46576(tablet-open [wo):
> TID 46578(tablet-open [wo):
> TID 46580(tablet-open [wo):
> TID 46581(tablet-open [wo):
> TID 46582(tablet-open [wo):
> TID 46583(tablet-open [wo):
> @ 0x7f1dd57147e0 (unknown)
> @ 0x7f1dd5713332 (unknown)
> @ 0x7f1dd570e5d8 (unknown)
> @ 0x7f1dd570e4a7 (unknown)
> @ 0x23b4058 kudu::Mutex::Acquire()
> @ 0x23980ff kudu::MaintenanceManager::RegisterOp()
> @ 0xb85374
> kudu::tablet::TabletReplica::RegisterMaintenanceOps()
> @ 0xa0055b kudu::tserver::TSTabletManager::OpenTablet()
> @ 0x23f994c kudu::ThreadPool::DispatchThread()
> @ 0x23f3f8b kudu::Thread::SuperviseThread()
> @ 0x7f1dd570caa1 (unknown)
> @ 0x7f1dd3b18bcd (unknown)
> TID 46573(tablet-open [wo):
> @ 0x7f1dd57147e0 (unknown)
> @ 0x7f1dd5713332 (unknown)
> @ 0x7f1dd570e5d8 (unknown)
> @ 0x7f1dd570e4a7 (unknown)
> @ 0x23b4058 kudu::Mutex::Acquire()
> @ 0x23980ff kudu::MaintenanceManager::RegisterOp()
> @ 0xb854c7
> kudu::tablet::TabletReplica::RegisterMaintenanceOps()
> @ 0xa0055b kudu::tserver::TSTabletManager::OpenTablet()
> @ 0x23f994c kudu::ThreadPool::DispatchThread()
> @ 0x23f3f8b kudu::Thread::SuperviseThread()
> @ 0x7f1dd570caa1 (unknown)
> @ 0x7f1dd3b18bcd (unknown)
> 2 threads with same stack:
> TID 43795(MaintenanceMgr ):
> TID 43796(MaintenanceMgr ):
> @ 0x7f1dd57147e0 (unknown)
> @ 0x7f1dd5713332 (unknown)
> @ 0x7f1dd570e5d8 (unknown)
> @ 0x7f1dd570e4a7 (unknown)
> @ 0x23b4058 kudu::Mutex::Acquire()
> @ 0x239a064 kudu::MaintenanceManager::LaunchOp()
> @ 0x23f994c kudu::ThreadPool::DispatchThread()
> @ 0x23f3f8b kudu::Thread::SuperviseThread()
> @ 0x7f1dd570caa1 (unknown)
> @ 0x7f1dd3b18bcd (unknown)
> {code}
> A couple more stacks show some work being done by the maintenance manager:
> {code:java}
> TID 43794(MaintenanceMgr ):
> @ 0x7f1dd57147e0 (unknown)
> @ 0xba7b41
> kudu::tablet::BudgetedCompactionPolicy::RunApproximation()
> @ 0xba8f5d
> kudu::tablet::BudgetedCompactionPolicy::PickRowSets()
> @ 0xb5b1a1 kudu::tablet::Tablet::PickRowSetsToCompact()
> @ 0xb64e93 kudu::tablet::Tablet::Compact()
> @ 0xb81071 kudu::tablet::CompactRowSetsOp::Perform()
> @ 0x2399c77 kudu::MaintenanceManager::LaunchOp()
> @ 0x23f994c kudu::ThreadPool::DispatchThread()
> @ 0x23f3f8b kudu::Thread::SuperviseThread()
> @ 0x7f1dd570caa1 (unknown)
> @ 0x7f1dd3b18bcd (unknown)
> TID 46999(maintenance_sch):
> @ 0x7f1dd57147e0 (unknown)
> @ 0x7f1dd5713332 (unknown)
> @ 0x7f1dd570e5d8 (unknown)
> @ 0x7f1dd570e4a7 (unknown)
> @ 0xb51f29 kudu::tablet::Tablet::UpdateCompactionStats()
> @ 0xb7f435 kudu::tablet::CompactRowSetsOp::UpdateStats()
> @ 0x23956e4 kudu::MaintenanceManager::FindBestOp()
> @ 0x2396af9 kudu::MaintenanceManager::FindAndLaunchOp()
> @ 0x2397858 kudu::MaintenanceManager::RunSchedulerThread()
> @ 0x23f3f8b kudu::Thread::SuperviseThread()
> @ 0x7f1dd570caa1 (unknown)
> @ 0x7f1dd3b18bcd (unknown)
> {code}
> So the question is, why is updating stats taking so long? Getting the full
> stacks, the scheduler thread is updating compaction stats, but is waiting to
> take a lock:
> {code:java}
> Thread 4 (Thread 0x7f1d7d358700 (LWP 46999)):
> #0 0x00007f1dd5713334 in __lll_lock_wait () from /lib64/libpthread.so.0
> #1 0x00007f1dd570e5d8 in _L_lock_854 () from /lib64/libpthread.so.0
> #2 0x00007f1dd570e4a7 in pthread_mutex_lock () from /lib64/libpthread.so.0
> #3 0x0000000000b51f29 in
> kudu::tablet::Tablet::UpdateCompactionStats(kudu::MaintenanceOpStats*) ()
> #4 0x0000000000b7f435 in
> kudu::tablet::CompactRowSetsOp::UpdateStats(kudu::MaintenanceOpStats*) ()
> #5 0x00000000023956e4 in kudu::MaintenanceManager::FindBestOp() ()
> #6 0x0000000002396af9 in
> kudu::MaintenanceManager::FindAndLaunchOp(std::unique_lock<kudu::Mutex>*) ()
> #7 0x0000000002397858 in kudu::MaintenanceManager::RunSchedulerThread() ()
> {code}
> And a compaction thread running the rowset-picking algorithm, which happens
> while the {{compact_select_lock_}} is held:
> {code:java}
> Thread 125 (Thread 0x7f1dce377700 (LWP 43794)):
> #0 0x0000000000ba7b90 in
> kudu::tablet::BudgetedCompactionPolicy::RunApproximation(std::vector<kudu::tablet::RowSetInfo,
> std::allocator<kudu::tablet::RowSetInfo> > const&,
> std::vector<kudu::tablet::RowSetInfo,
> std::allocator<kudu::tablet::RowSetInfo> > const&, std::vector<double,
> std::allocator<double> >*,
> kudu::tablet::BudgetedCompactionPolicy::SolutionAndValue*) const ()
> #1 0x0000000000ba8f5d in
> kudu::tablet::BudgetedCompactionPolicy::PickRowSets(kudu::tablet::RowSetTree
> const&, std::unordered_set<kudu::tablet::RowSet const*,
> std::hash<kudu::tablet::RowSet const*>, std::equal_to<kudu::tablet::RowSet
> const*>, std::allocator<kudu::tablet::RowSet const*> >*, double*,
> std::vector<std::basic_string<char, std::char_traits<char>,
> std::allocator<char> >, std::allocator<std::basic_string<char,
> std::char_traits<char>, std::allocator<char> > > >*) ()
> #2 0x0000000000b5b1a1 in
> kudu::tablet::Tablet::PickRowSetsToCompact(kudu::tablet::RowSetsInCompaction*,
> int) const ()
> #3 0x0000000000b64e93 in kudu::tablet::Tablet::Compact(int) ()
> #4 0x0000000000b81071 in kudu::tablet::CompactRowSetsOp::Perform() ()
> #5 0x0000000002399c77 in
> kudu::MaintenanceManager::LaunchOp(kudu::MaintenanceOp*) ()
> #6 0x00000000023f994c in kudu::ThreadPool::DispatchThread() ()
> #7 0x00000000023f3f8b in kudu::Thread::SuperviseThread(void*) ()
> #8 0x00007f1dd570caa1 in start_thread () from /lib64/libpthread.so.0
> #9 0x00007f1dd3b18bcd in clone () from /lib64/libc.so.6
> {code}
> It seems the computing of stats is being blocked by on-going compactions,
> contending with the {{compact_select_lock_}}. Additionally, we're holding the
> maintenance manager's {{lock_}} member, for the duration of us computing
> stats, which is contending with the registration of maintenance manager ops.
> So the compaction selection is blocking the scheduler thread, and is thus
> effectively blocking the registration of many tablet replicas' ops, and
> blocking further bootstrapping.
> A couple things come to mind with regards to the registration issue:
> - We could probably take a snapshot of the ops under lock and release the
> lock_ when finding the best op to run, so op registration would be somewhat
> independent of scheduling.
> - Additionally, we may want to consider disabling compactions entirely until
> the initial set of tablets finishes bootstrapping.
> It's worth noting that it isn't the act of compacting that is contending
> directly with registration per se, but rather the computation of the stats.
> The computation of stats happens to be contending with on-going compactions.
> Improving either contention would likely help.
> As a workaround, we used the {{set_flag}} tool to disable compactions on the
> node and noted significantly faster bootstrapping.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
