Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CDC: reactor stalled up to 17000 ms after change cdc log table property #6098

Closed
aleksbykov opened this issue Mar 30, 2020 · 6 comments · Fixed by #6312
Closed

CDC: reactor stalled up to 17000 ms after change cdc log table property #6098

aleksbykov opened this issue Mar 30, 2020 · 6 comments · Fixed by #6312
Assignees
@haaawk
Labels
area/cdc
Milestone
4.1

Comments

@aleksbykov
Copy link
Contributor

Installation details
Scylla version (or git commit hash):
version 666.development-0.20200325.9fee712d62 with build-id 0908e1527b1f134a4e4a46ca44ffe85f0f877318
Cluster size: 3
OS (RHEL/CentOS/Ubuntu/AWS AMI): ami-045e69a7ca1cb853f

Cluster was configured with cdc feature. For base table cdc_test.test_table_preimage cdc preimage was enabled. After several minutes, for cdc log table properties was changed:
ALTER TABLE cdc_test.test_table_preimage_scylla_cdc_log WITH dclocal_read_repair_chance = 0.5

after that, on several nodes were found next messages in log

2020-03-26T13:48:28+00:00  longevity-cdc-100gb-4h-master-db-node-77890b52-5 !WARNING | scylla: [shard 3] storage_proxy - Failed to apply mutation from 10.0.135.90#3: seastar::named_semaphore_timed_out (Semaphore timed out: smp_service_group#2 13->3 semaphore)
2020-03-26T13:48:28+00:00  longevity-cdc-100gb-4h-master-db-node-77890b52-5 !WARNING | scylla: [shard 3] storage_proxy - Failed to apply mutation from 10.0.135.90#3: seastar::named_semaphore_timed_out (Semaphore timed out: smp_service_group#2 13->3 semaphore)
2020-03-26T13:48:28+00:00  longevity-cdc-100gb-4h-master-db-node-77890b52-5 !ERR     | scylla: [shard 3] storage_proxy - exception during mutation write to 10.0.121.232: seastar::named_semaphore_timed_out (Semaphore timed out: smp_service_group#2 13->3 semaphore)
2020-03-26T13:48:28+00:00  longevity-cdc-100gb-4h-master-db-node-77890b52-5 !ERR     | scylla: [shard 3] storage_proxy - exception during mutation write to 10.0.121.232: seastar::named_semaphore_timed_out (Semaphore timed out: smp_service_group#2 13->3 semaphore)

and reactor stalled reached up to 17000 ms:

2020-03-26T13:48:32+00:00  longevity-cdc-100gb-4h-master-db-node-77890b52-5 !INFO    | scylla: Reactor stalled for 8759 ms on shard 13.

void seastar::backtrace<seastar::backtrace_buffer::append_backtrace()::{lambda(seastar::frame)#1}>(seastar::backtrace_buffer::append_backtrace()::{lambda(seastar::frame)#1}&&) at /usr/include/fmt/format.h:1158
seastar::backtrace_buffer::append_backtrace() at /usr/include/fmt/format.h:1158
 (inlined by) print_with_backtrace at ./build/release/seastar/./seastar/src/core/reactor.cc:755
seastar::internal::cpu_stall_detector::generate_trace() at /usr/include/fmt/format.h:1158
seastar::internal::cpu_stall_detector::maybe_report() at /usr/include/fmt/format.h:1158
 (inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1062
 (inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1185
?? ??:0
managed_bytes::size() const at /usr/include/fmt/format.h:1158
 (inlined by) managed_bytes::managed_bytes(managed_bytes const&) at ././utils/managed_bytes.hh:233
compound_wrapper<clustering_key_prefix, clustering_key_prefix_view>::compound_wrapper(compound_wrapper<clustering_key_prefix, clustering_key_prefix_view> const&) at /usr/include/boost/intrusive/pointer_plus_bits.hpp:89
 (inlined by) prefix_compound_wrapper<clustering_key_prefix, clustering_key_prefix_view, clustering_key_prefix>::prefix_compound_wrapper(prefix_compound_wrapper<clustering_key_prefix, clustering_key_prefix_view, clustering_key_prefix> const&) at ./keys.hh:558
 (inlined by) clustering_key_prefix::clustering_key_prefix(clustering_key_prefix const&) at ./keys.hh:784
 (inlined by) rows_entry::rows_entry(schema const&, rows_entry const&) at ./mutation_partition.hh:1054
 (inlined by) rows_entry* allocation_strategy::construct<rows_entry, schema const&, rows_entry const&>(schema const&, rows_entry const&) at ././utils/allocation_strategy.hh:152
 (inlined by) operator()<rows_entry> at ./mutation_partition.cc:161
 (inlined by) operator() at ./intrusive_set_external_comparator.hh:229
 (inlined by) operator() at /usr/include/boost/intrusive/rbtree_algorithms.hpp:59
 (inlined by) clone_subtree<boost::intrusive::rbtree_node_cloner<boost::intrusive::rbtree_node_traits<void*, true>, intrusive_set_external_comparator<Elem, PtrToMember>::clone_from(const intrusive_set_external_comparator<Elem, PtrToMember>&, Cloner, Disposer) [with Cloner = mutation_partition::mutation_partition(const schema&, const mutation_partition&)::<lambda(const auto:147&)>; Disposer = current_deleter() [with T = rows_entry]::<lambda(rows_entry*)>; Elem = rows_entry; intrusive_set_external_comparator_member_hook Elem::* PtrToMember = &rows_entry::_link]::<lambda(boost::intrusive::compact_rbtree_node<void*>* const&)> >, intrusive_set_external_comparator<Elem, PtrToMember>::clone_from(const intrusive_set_external_comparator<Elem, PtrToMember>&, Cloner, Disposer) [with Cloner = mutation_partition::mutation_partition(const schema&, const mutation_partition&)::<lambda(const auto:147&)>; Disposer = current_deleter() [with T = rows_entry]::<lambda(rows_entry*)>; Elem = rows_entry; intrusive_set_external_comparator_member_hook Elem::* PtrToMember = &rows_entry::_link]::<lambda(boost::intrusive::compact_rbtree_node<void*>* const&)> > at /usr/include/boost/intrusive/bstree_algorithms.hpp:1978
 (inlined by) clone<boost::intrusive::rbtree_node_cloner<boost::intrusive::rbtree_node_traits<void*, true>, intrusive_set_external_comparator<Elem, PtrToMember>::clone_from(const intrusive_set_external_comparator<Elem, PtrToMember>&, Cloner, Disposer) [with Cloner = mutation_partition::mutation_partition(const schema&, const mutation_partition&)::<lambda(const auto:147&)>; Disposer = current_deleter() [with T = rows_entry]::<lambda(rows_entry*)>; Elem = rows_entry; intrusive_set_external_comparator_member_hook Elem::* PtrToMember = &rows_entry::_link]::<lambda(boost::intrusive::compact_rbtree_node<void*>* const&)> >, intrusive_set_external_comparator<Elem, PtrToMember>::clone_from(const intrusive_set_external_comparator<Elem, PtrToMember>&, Cloner, Disposer) [with Cloner = mutation_partition::mutation_partition(const schema&, const mutation_partition&)::<lambda(const auto:147&)>; Disposer = current_deleter() [with T = rows_entry]::<lambda(rows_entry*)>; Elem = rows_entry; intrusive_set_external_comparator_member_hook Elem::* PtrToMember = &rows_entry::_link]::<lambda(boost::intrusive::compact_rbtree_node<void*>* const&)> > at /usr/include/boost/intrusive/bstree_algorithms.hpp:1303
 (inlined by) clone<intrusive_set_external_comparator<Elem, PtrToMember>::clone_from(const intrusive_set_external_comparator<Elem, PtrToMember>&, Cloner, Disposer) [with Cloner = mutation_partition::mutation_partition(const schema&, const mutation_partition&)::<lambda(const auto:147&)>; Disposer = current_deleter() [with T = rows_entry]::<lambda(rows_entry*)>; Elem = rows_entry; intrusive_set_external_comparator_member_hook Elem::* PtrToMember = &rows_entry::_link]::<lambda(boost::intrusive::compact_rbtree_node<void*>* const&)>, intrusive_set_external_comparator<Elem, PtrToMember>::clone_from(const intrusive_set_external_comparator<Elem, PtrToMember>&, Cloner, Disposer) [with Cloner = mutation_partition::mutation_partition(const schema&, const mutation_partition&)::<lambda(const auto:147&)>; Disposer = current_deleter() [with T = rows_entry]::<lambda(rows_entry*)>; Elem = rows_entry; intrusive_set_external_comparator_member_hook Elem::* PtrToMember = &rows_entry::_link]::<lambda(boost::intrusive::compact_rbtree_node<void*>* const&)> > at /usr/include/boost/intrusive/rbtree_algorithms.hpp:322
 (inlined by) clone_from<mutation_partition::mutation_partition(const schema&, const mutation_partition&)::<lambda(const auto:147&)>, current_deleter() [with T = rows_entry]::<lambda(rows_entry*)> > at ./intrusive_set_external_comparator.hh:226
 (inlined by) mutation_partition::mutation_partition(schema const&, mutation_partition const&) at ./mutation_partition.cc:163
partition_entry::squashed(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>) at /usr/include/fmt/format.h:1158
partition_entry::upgrade(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>, mutation_cleaner&, cache_tracker*) at /usr/include/fmt/format.h:1158
operator() at /usr/include/fmt/format.h:1158
 (inlined by) with_linearized_managed_bytes<row_cache::upgrade_entry(cache_entry&)::<lambda()>::<lambda()> > at ./utils/managed_bytes.hh:428
 (inlined by) operator() at ./row_cache.cc:1296
 (inlined by) with_allocator<row_cache::upgrade_entry(cache_entry&)::<lambda()> > at ././utils/allocation_strategy.hh:307
 (inlined by) row_cache::upgrade_entry(cache_entry&) at ./row_cache.cc:1295
operator() at /usr/include/fmt/format.h:1158
 (inlined by) operator() at ./row_cache.cc:961
 (inlined by) with_reclaiming_disabled<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()>::<lambda()>&> at ././utils/logalloc.hh:745
 (inlined by) operator() at ././utils/logalloc.hh:767
 (inlined by) with_reserve<logalloc::allocating_section::operator()(logalloc::region&, Func&&) [with Func = row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()>::<lambda()>]::<lambda()> > at ././utils/logalloc.hh:717
 (inlined by) operator()<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()>::<lambda()> > at ././utils/logalloc.hh:768
 (inlined by) operator() at ./row_cache.cc:957
 (inlined by) with_linearized_managed_bytes<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()> > at ./utils/managed_bytes.hh:428
 (inlined by) operator() at ./row_cache.cc:955
 (inlined by) with_allocator<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()> > at ././utils/allocation_strategy.hh:307
 (inlined by) operator() at ./row_cache.cc:944
apply at /usr/include/fmt/format.h:1158
 (inlined by) apply<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> > at ././seastar/include/seastar/core/apply.hh:44
 (inlined by) apply_tuple<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> > at ././seastar/include/seastar/core/future.hh:1618
 (inlined by) apply<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> > at ././seastar/include/seastar/core/future.hh:1652
 (inlined by) operator() at ././seastar/include/seastar/core/thread.hh:253
 (inlined by) call at ././seastar/include/seastar/util/noncopyable_function.hh:101
seastar::noncopyable_function<void ()>::operator()() const at ./build/release/seastar/./seastar/include/seastar/util/noncopyable_function.hh:184
 (inlined by) seastar::thread_context::main() at ./build/release/seastar/./seastar/src/core/thread.cc:286

2020-03-26T13:48:59+00:00  longevity-cdc-100gb-4h-master-db-node-77890b52-2 !INFO    | scylla: Reactor stalled for 17334 ms on shard 2.

void seastar::backtrace<seastar::backtrace_buffer::append_backtrace()::{lambda(seastar::frame)#1}>(seastar::backtrace_buffer::append_backtrace()::{lambda(seastar::frame)#1}&&) at /usr/include/fmt/format.h:1158
seastar::backtrace_buffer::append_backtrace() at /usr/include/fmt/format.h:1158
 (inlined by) print_with_backtrace at ./build/release/seastar/./seastar/src/core/reactor.cc:755
seastar::internal::cpu_stall_detector::generate_trace() at /usr/include/fmt/format.h:1158
seastar::internal::cpu_stall_detector::maybe_report() at /usr/include/fmt/format.h:1158
 (inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1062
 (inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1185
?? ??:0
?? ??:0
std::_Hash_impl::hash(void const*, unsigned long, unsigned long) at /usr/include/fmt/format.h:1158
 (inlined by) std::hash<std::basic_string_view<char, std::char_traits<char> > >::operator()(std::basic_string_view<char, std::char_traits<char> > const&) const at /usr/include/c++/9/string_view:610
 (inlined by) std::hash<std::basic_string_view<signed char, std::char_traits<signed char> > >::operator()(std::basic_string_view<signed char, std::char_traits<signed char> >) const at ././bytes.hh:47
 (inlined by) std::hash<seastar::basic_sstring<signed char, unsigned int, 31u, false> >::operator()(seastar::basic_sstring<signed char, unsigned int, 31u, false> const&) const at ././seastar/include/seastar/core/sstring.hh:664
 (inlined by) std::__detail::_Hash_code_base<seastar::basic_sstring<signed char, unsigned int, 31u, false>, std::pair<seastar::basic_sstring<signed char, unsigned int, 31u, false> const, column_definition const*>, std::__detail::_Select1st, std::hash<seastar::basic_sstring<signed char, unsigned int, 31u, false> >, std::__detail::_Mod_range_hashing, std::__detail::_Default_ranged_hash, true>::_M_hash_code(seastar::basic_sstring<signed char, unsigned int, 31u, false> const&) const at /usr/include/c++/9/bits/hashtable_policy.h:1384
 (inlined by) std::_Hashtable<seastar::basic_sstring<signed char, unsigned int, 31u, false>, std::pair<seastar::basic_sstring<signed char, unsigned int, 31u, false> const, column_definition const*>, std::allocator<std::pair<seastar::basic_sstring<signed char, unsigned int, 31u, false> const, column_definition const*> >, std::__detail::_Select1st, std::equal_to<seastar::basic_sstring<signed char, unsigned int, 31u, false> >, std::hash<seastar::basic_sstring<signed char, unsigned int, 31u, false> >, std::__detail::_Mod_range_hashing, std::__detail::_Default_ranged_hash, std::__detail::_Prime_rehash_policy, std::__detail::_Hashtable_traits<true, false, true> >::find(seastar::basic_sstring<signed char, unsigned int, 31u, false> const&) const at /usr/include/c++/9/bits/hashtable.h:1433
 (inlined by) std::unordered_map<seastar::basic_sstring<signed char, unsigned int, 31u, false>, column_definition const*, std::hash<seastar::basic_sstring<signed char, unsigned int, 31u, false> >, std::equal_to<seastar::basic_sstring<signed char, unsigned int, 31u, false> >, std::allocator<std::pair<seastar::basic_sstring<signed char, unsigned int, 31u, false> const, column_definition const*> > >::find(seastar::basic_sstring<signed char, unsigned int, 31u, false> const&) const at /usr/include/c++/9/bits/unordered_map.h:925
 (inlined by) schema::get_column_definition(seastar::basic_sstring<signed char, unsigned int, 31u, false> const&) const at ./schema.cc:569
converting_mutation_partition_applier::accept_row_cell(unsigned int, atomic_cell_view) at /usr/include/fmt/format.h:1158
operator() at /usr/include/boost/intrusive/pointer_plus_bits.hpp:89
 (inlined by) maybe_invoke_with_hash<mutation_partition::accept(const schema&, mutation_partition_visitor&) const::<lambda(column_id, const atomic_cell_or_collection&)>, const cell_and_hash> at ./mutation_partition.hh:255
 (inlined by) for_each_cell<mutation_partition::accept(const schema&, mutation_partition_visitor&) const::<lambda(column_id, const atomic_cell_or_collection&)> > at ./mutation_partition.hh:280
 (inlined by) mutation_partition::accept(schema const&, mutation_partition_visitor&) const at ./mutation_partition.cc:1949
mutation_partition::upgrade(schema const&, schema const&) at /usr/include/boost/intrusive/pointer_plus_bits.hpp:89
partition_entry::squashed(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>) at /usr/include/fmt/format.h:1158
partition_entry::upgrade(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>, mutation_cleaner&, cache_tracker*) at /usr/include/fmt/format.h:1158
operator() at /usr/include/fmt/format.h:1158
 (inlined by) with_linearized_managed_bytes<row_cache::upgrade_entry(cache_entry&)::<lambda()>::<lambda()> > at ./utils/managed_bytes.hh:428
 (inlined by) operator() at ./row_cache.cc:1296
 (inlined by) with_allocator<row_cache::upgrade_entry(cache_entry&)::<lambda()> > at ././utils/allocation_strategy.hh:307
 (inlined by) row_cache::upgrade_entry(cache_entry&) at ./row_cache.cc:1295
operator() at /usr/include/fmt/format.h:1158
 (inlined by) operator() at ./row_cache.cc:961
 (inlined by) with_reclaiming_disabled<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()>::<lambda()>&> at ././utils/logalloc.hh:745
 (inlined by) operator() at ././utils/logalloc.hh:767
 (inlined by) with_reserve<logalloc::allocating_section::operator()(logalloc::region&, Func&&) [with Func = row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()>::<lambda()>]::<lambda()> > at ././utils/logalloc.hh:717
 (inlined by) operator()<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()>::<lambda()> > at ././utils/logalloc.hh:768
 (inlined by) operator() at ./row_cache.cc:957
 (inlined by) with_linearized_managed_bytes<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()> > at ./utils/managed_bytes.hh:428
 (inlined by) operator() at ./row_cache.cc:955
 (inlined by) with_allocator<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()> > at ././utils/allocation_strategy.hh:307
 (inlined by) operator() at ./row_cache.cc:944
apply at /usr/include/fmt/format.h:1158
 (inlined by) apply<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> > at ././seastar/include/seastar/core/apply.hh:44
 (inlined by) apply_tuple<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> > at ././seastar/include/seastar/core/future.hh:1618
 (inlined by) apply<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> > at ././seastar/include/seastar/core/future.hh:1652
 (inlined by) operator() at ././seastar/include/seastar/core/thread.hh:253
 (inlined by) call at ././seastar/include/seastar/util/noncopyable_function.hh:101
seastar::noncopyable_function<void ()>::operator()() const at ./build/release/seastar/./seastar/include/seastar/util/noncopyable_function.hh:184
 (inlined by) seastar::thread_context::main() at ./build/release/seastar/./seastar/src/core/thread.cc:286

2020-03-26T13:49:37+00:00  longevity-cdc-100gb-4h-master-db-node-77890b52-5 !INFO    | scylla: Reactor stalled for 17097 ms on shard 3.

void seastar::backtrace<seastar::backtrace_buffer::append_backtrace()::{lambda(seastar::frame)#1}>(seastar::backtrace_buffer::append_backtrace()::{lambda(seastar::frame)#1}&&) at /usr/include/fmt/format.h:1158
seastar::backtrace_buffer::append_backtrace() at /usr/include/fmt/format.h:1158
 (inlined by) print_with_backtrace at ./build/release/seastar/./seastar/src/core/reactor.cc:755
seastar::internal::cpu_stall_detector::generate_trace() at /usr/include/fmt/format.h:1158
seastar::internal::cpu_stall_detector::maybe_report() at /usr/include/fmt/format.h:1158
 (inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1062
 (inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1185
?? ??:0
logalloc::region_impl::compaction_lock::compaction_lock(logalloc::region_impl&) at ./utils/logalloc.cc:1145
 (inlined by) logalloc::region_impl::free(void*, unsigned long) at ./utils/logalloc.cc:1421
logalloc::region_impl::free(void*) at ./utils/logalloc.cc:1417
imr::utils::object<imr::structure<imr::member<data::cell::tags::flags, imr::flags<data::cell::tags::collection, data::cell::tags::live, data::cell::tags::expiring, data::cell::tags::counter_update, data::cell::tags::empty, data::cell::tags::external_data> >, imr::member<data::cell::tags::cell, imr::variant<data::cell::tags::cell, imr::member<data::cell::tags::atomic_cell, imr::structure<imr::member<data::cell::tags::timestamp, imr::pod<long> >, imr::member<data::cell::tags::expiring, imr::optional<data::cell::tags::expiring, imr::structure<imr::member<data::cell::tags::ttl, imr::pod<int> >, imr::member<data::cell::tags::expiry, imr::pod<long> > > > >, imr::member<data::cell::tags::value, imr::variant<data::cell::tags::value, imr::member<data::cell::tags::dead, imr::pod<long> >, imr::member<data::cell::tags::counter_update, imr::pod<long> >, imr::member<data::cell::tags::fixed_value, imr::buffer<data::cell::tags::fixed_value> >, imr::member<data::cell::tags::variable_value, imr::structure<imr::member<data::cell::tags::value_size, imr::pod<unsigned int> >, imr::member<data::cell::tags::value_data, imr::variant<data::cell::tags::value_data, imr::member<data::cell::tags::pointer, imr::tagged_type<data::cell::tags::pointer, imr::pod<unsigned char*> > >, imr::member<data::cell::tags::data, imr::buffer<data::cell::tags::data> > > > > > > > > >, imr::member<data::cell::tags::collection, imr::structure<imr::member<data::cell::tags::value_size, imr::pod<unsigned int> >, imr::member<data::cell::tags::value_data, imr::variant<data::cell::tags::value_data, imr::member<data::cell::tags::pointer, imr::tagged_type<data::cell::tags::pointer, imr::pod<unsigned char*> > >, imr::member<data::cell::tags::data, imr::buffer<data::cell::tags::data> > > > > > > > > >::~object() at /usr/include/boost/intrusive/pointer_plus_bits.hpp:89
 (inlined by) atomic_cell_or_collection::~atomic_cell_or_collection() at ./atomic_cell_or_collection.hh:33
 (inlined by) cell_and_hash::~cell_and_hash() at ./mutation_partition.hh:76
 (inlined by) managed_vector<cell_and_hash, 5u, unsigned int>::pop_back() at ./utils/managed_vector.hh:221
 (inlined by) managed_vector<cell_and_hash, 5u, unsigned int>::clear() at ./utils/managed_vector.hh:177
 (inlined by) managed_vector<cell_and_hash, 5u, unsigned int>::clear_and_release() at ./utils/managed_vector.hh:84
 (inlined by) managed_vector<cell_and_hash, 5u, unsigned int>::~managed_vector() at ./utils/managed_vector.hh:134
 (inlined by) row::vector_storage::~vector_storage() at ./mutation_partition.hh:160
 (inlined by) row::~row() at ./mutation_partition.cc:1564
deletable_row::~deletable_row() at /usr/include/boost/intrusive/pointer_plus_bits.hpp:89
 (inlined by) rows_entry::~rows_entry() at ./mutation_partition.hh:1001
 (inlined by) void allocation_strategy::destroy<rows_entry>(rows_entry*) at ././utils/allocation_strategy.hh:164
 (inlined by) auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1}::operator()(rows_entry*) const at ././utils/allocation_strategy.hh:238
 (inlined by) void intrusive_set_external_comparator<rows_entry, &rows_entry::_link>::clear_and_dispose<auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1}>(auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1})::{lambda(boost::intrusive::compact_rbtree_node<void*>* const&)#1}::operator()(boost::intrusive::compact_rbtree_node<void*>* const) const at ./intrusive_set_external_comparator.hh:185
 (inlined by) void boost::intrusive::bstree_algorithms<boost::intrusive::rbtree_node_traits<void*, true> >::dispose_subtree<void intrusive_set_external_comparator<rows_entry, &rows_entry::_link>::clear_and_dispose<auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1}>(auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1})::{lambda(boost::intrusive::compact_rbtree_node<void*>* const&)#1}>(boost::intrusive::compact_rbtree_node<void*>, auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1}) at /usr/include/boost/intrusive/bstree_algorithms.hpp:2017
 (inlined by) void boost::intrusive::bstree_algorithms<boost::intrusive::rbtree_node_traits<void*, true> >::clear_and_dispose<void intrusive_set_external_comparator<rows_entry, &rows_entry::_link>::clear_and_dispose<auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1}>(auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1})::{lambda(boost::intrusive::compact_rbtree_node<void*>* const&)#1}>(boost::intrusive::compact_rbtree_node<void*>* const, auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1}) at /usr/include/boost/intrusive/bstree_algorithms.hpp:615
 (inlined by) void intrusive_set_external_comparator<rows_entry, &rows_entry::_link>::clear_and_dispose<auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1}>(auto current_deleter<rows_entry>()::{lambda(rows_entry*)#1}) at ./intrusive_set_external_comparator.hh:183
 (inlined by) mutation_partition::~mutation_partition() at ./mutation_partition.cc:235
partition_entry::squashed(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>) at /usr/include/fmt/format.h:1158
partition_entry::upgrade(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>, mutation_cleaner&, cache_tracker*) at /usr/include/fmt/format.h:1158
operator() at /usr/include/fmt/format.h:1158
 (inlined by) with_linearized_managed_bytes<row_cache::upgrade_entry(cache_entry&)::<lambda()>::<lambda()> > at ./utils/managed_bytes.hh:428
 (inlined by) operator() at ./row_cache.cc:1296
 (inlined by) with_allocator<row_cache::upgrade_entry(cache_entry&)::<lambda()> > at ././utils/allocation_strategy.hh:307
 (inlined by) row_cache::upgrade_entry(cache_entry&) at ./row_cache.cc:1295
operator() at /usr/include/fmt/format.h:1158
 (inlined by) operator() at ./row_cache.cc:961
 (inlined by) with_reclaiming_disabled<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()>::<lambda()>&> at ././utils/logalloc.hh:745
 (inlined by) operator() at ././utils/logalloc.hh:767
 (inlined by) with_reserve<logalloc::allocating_section::operator()(logalloc::region&, Func&&) [with Func = row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()>::<lambda()>]::<lambda()> > at ././utils/logalloc.hh:717
 (inlined by) operator()<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()>::<lambda()> > at ././utils/logalloc.hh:768
 (inlined by) operator() at ./row_cache.cc:957
 (inlined by) with_linearized_managed_bytes<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()>::<lambda()> > at ./utils/managed_bytes.hh:428
 (inlined by) operator() at ./row_cache.cc:955
 (inlined by) with_allocator<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> mutable::<lambda()> > at ././utils/allocation_strategy.hh:307
 (inlined by) operator() at ./row_cache.cc:944
apply at /usr/include/fmt/format.h:1158
 (inlined by) apply<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> > at ././seastar/include/seastar/core/apply.hh:44
 (inlined by) apply_tuple<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> > at ././seastar/include/seastar/core/future.hh:1618
 (inlined by) apply<row_cache::do_update(row_cache::external_updater, memtable&, Updater) [with Updater = row_cache::update(row_cache::external_updater, memtable&)::<lambda(logalloc::allocating_section&, boost::intrusive::set<cache_entry, boost::intrusive::member_hook<cache_entry, boost::intrusive::set_member_hook<boost::intrusive::link_mode<(boost::intrusive::link_mode_type)2> >, &cache_entry::_cache_link>, boost::intrusive::constant_time_size<false>, boost::intrusive::compare<cache_entry::compare> >::iterator, memtable_entry&, partition_presence_checker&, real_dirty_memory_accounter&)>]::<lambda()>::<lambda()> > at ././seastar/include/seastar/core/future.hh:1652
 (inlined by) operator() at ././seastar/include/seastar/core/thread.hh:253
 (inlined by) call at ././seastar/include/seastar/util/noncopyable_function.hh:101
seastar::noncopyable_function<void ()>::operator()() const at ./build/release/seastar/./seastar/include/seastar/util/noncopyable_function.hh:184
 (inlined by) seastar::thread_context::main() at ./build/release/seastar/./seastar/src/core/thread.cc:286

DB nodes log link:
https://cloudius-jenkins-test.s3.amazonaws.com/77890b52-9030-4a13-95d8-42764428086a/20200326_174910/db-cluster-77890b52.zip
@amoskong
Copy link
Contributor

amoskong commented Apr 1, 2020

/CC @slivne @haaawk

@haaawk haaawk self-assigned this Apr 1, 2020
@haaawk
Copy link
Contributor

haaawk commented Apr 1, 2020

Those stalls are in cache update when memtable is flushed. The good think is I'm finishing a PR that will make CDC Log not use cache. That should fix the issue.

@haaawk haaawk added the area/cdc label Apr 8, 2020
@slivne slivne added this to the 4.1 milestone Apr 14, 2020
@haaawk haaawk mentioned this issue Apr 28, 2020
Merged
avikivity added a commit that referenced this issue May 5, 2020
@avikivity
Merge 'Make it possible to turn caching off per table and stop cachin…
6cf9324 
…g CDC Log' from Piotr

We inherited from Origin a `caching` table parameter. It's a map of named caching parameters. Before this PR two caching parameters were expected: `keys` and `rows_per_partition`. So far we have been ignoring them. This PR adds a new caching parameter called `enabled` which can be set to `true` or `false` and controls the usage of the cache for the table. By default, it's set to `true` which reflects Scylla behavior before this PR.

This new capability is used to disable caching for CDC Log table. It is desirable because CDC Log entries are not expected to be read often. They also put much more pressure on memory than entries in Base Table. This is caused by the fact that some writes to Base Table can override previous writes. Every write to CDC Log is unique and does not invalidate any previous entry.

Fixes #6098
Fixes #6146

Tests: unit(dev, release), manual

* haaawk-dont_cache_cdc:
  cdc: Don't cache CDC Log table
  table: invalidate disabled cache on memtable flush
  table: Add cache_enabled member function
  cf_prop_defs: persist caching_options in schema
  feature: add PER_TABLE_CACHING feature
  caching_options: add enabled parameter
@avikivity
Copy link
Member

It fixed the direct cause, but it can still happen on another table.

I see it is a duplicate of #2577. And indeed the title says that a property was changed.

@avikivity
Copy link
Member

cdc=experimental, so not backporting.

@tzach
Copy link
Contributor

tzach commented Jul 23, 2020

I see it is a duplicate of #2577. And indeed the title says that a property was changed.

@avikivity #2577 is till open, should we close it?

@haaawk
Copy link
Contributor

haaawk commented Jul 23, 2020

@tzach no. This issue was fixed by avoiding using cache. The issue still exists in cache.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@haaawk haaawk

Labels
area/cdc
Projects
None yet
Milestone
4.1
Development

Successfully merging a pull request may close this issue.

Make it possible to turn caching off per table and stop caching CDC Log
7 participants
@tzach @amoskong @avikivity @haaawk @slivne @scylladb-promoter @aleksbykov