17ms stalls in reclaim_from_evictable

asias commented 2 years ago

Run from: https://groups.google.com/a/scylladb.com/g/scylla-perf-results/c/7Y2EFr21U-4

Scylla version 5.1.dev-0.20220711.7e2d2cf1c18d with build-id 8d31af83d550feaccdcf3d243d522685440315a2

perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1/messages.log:2022-07-11T14:42:21+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla[6623]: Reactor stalled for 17 ms on shard 4. Backtrace: 0x4b7b652 0x4b7a2b0 0x4b7b560 0x7ff414e6ca1f 0x198072c 0x15d99e5 0x15bba15 0x15c3a67 0x15bf8f7 0x15b0669 0x15aef7f 0x15ce987 0x13edca0 0x1279cdb 0x13525c2 0x12c76de 0x12c32ad 0x122cad6 0x398fc80 0x4b8ac04 0x4b8bfe7 0x4bab1a5 0x4b5ec8a 0x92a4 0x100322

<pre>[Backtrace #0]
void seastar::backtrace&lt;seastar::backtrace_buffer::append_backtrace_oneline()::{lambda(seastar::frame)#1}&gt;(seastar::backtrace_buffer::append_backtrace_oneline()::{lambda(seastar::frame)#1}&amp;&amp;) at ./build/release/seastar/./seastar/include/seastar/util/backtrace.hh:59
 (inlined by) seastar::backtrace_buffer::append_backtrace_oneline() at ./build/release/seastar/./seastar/src/core/reactor.cc:772
 (inlined by) seastar::print_with_backtrace(seastar::backtrace_buffer&amp;, bool) at ./build/release/seastar/./seastar/src/core/reactor.cc:791
seastar::internal::cpu_stall_detector::generate_trace() at ./build/release/seastar/./seastar/src/core/reactor.cc:1366
seastar::internal::cpu_stall_detector::maybe_report() at ./build/release/seastar/./seastar/src/core/reactor.cc:1108
 (inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1125
 (inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1349
?? ??:0
data at ././utils/bptree.hh:1928
 (inlined by) standard_migrator&lt;bplus::data&lt;unsigned long, sstables::partition_index_cache::entry, sstables::partition_index_cache::key_less_comparator, 8ul, (bplus::key_search)0, (bplus::with_debug)0&gt; &gt;::migrate(void*, void*, unsigned long) const at ././utils/allocation_strategy.hh:72
operator() at ./utils/logalloc.cc:1483
 (inlined by) void logalloc::region_impl::for_each_live&lt;logalloc::region_impl::compact_segment_locked(logalloc::segment*, logalloc::segment_descriptor&amp;)::{lambda(logalloc::region_impl::object_descriptor const*, void*, unsigned long)#1}&gt;(logalloc::segment*, logalloc::region_impl::compact_segment_locked(logalloc::segment*, logalloc::segment_descriptor&amp;)::{lambda(logalloc::region_impl::object_descriptor const*, void*, unsigned long)#1}&amp;&amp;) at ./utils/logalloc.cc:1329
 (inlined by) logalloc::region_impl::compact_segment_locked(logalloc::segment*, logalloc::segment_descriptor&amp;) at ./utils/logalloc.cc:1480
logalloc::region_impl::compact() at ./utils/logalloc.cc:1802
logalloc::reclaim_from_evictable(logalloc::region_impl&amp;, unsigned long, seastar::bool_class&lt;is_preemptible_tag&gt;) at ./utils/logalloc.cc:2121
logalloc::tracker::impl::compact_and_evict_locked(unsigned long, unsigned long, seastar::bool_class&lt;is_preemptible_tag&gt;) at ./utils/logalloc.cc:2365
logalloc::tracker::impl::compact_and_evict(unsigned long, unsigned long, seastar::bool_class&lt;is_preemptible_tag&gt;) at ./utils/logalloc.cc:2299
logalloc::segment_pool::allocate_segment(unsigned long) at ./utils/logalloc.cc:970
logalloc::segment_pool::refill_emergency_reserve() at ./utils/logalloc.cc:983
 (inlined by) logalloc::allocating_section::reserve() at ./utils/logalloc.cc:2661
decltype(auto) logalloc::allocating_section::with_reserve&lt;logalloc::allocating_section::operator()&lt;replica::memtable::make_flat_reader_opt(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;)::$_5&gt;(logalloc::region&amp;, replica::memtable::make_flat_reader_opt(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;)::$_5&amp;&amp;)::{lambda()#1}&gt;(replica::memtable::make_flat_reader_opt(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;)::$_5&amp;&amp;) at ././utils/logalloc.hh:766
 (inlined by) decltype(auto) logalloc::allocating_section::operator()&lt;replica::memtable::make_flat_reader_opt(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;)::$_5&gt;(logalloc::region&amp;, replica::memtable::make_flat_reader_opt(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;)::$_5&amp;&amp;) at ././utils/logalloc.hh:817
 (inlined by) replica::memtable::make_flat_reader_opt(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;) at ./replica/memtable.cc:711
replica::table::make_reader_v2(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;) const at ./replica/table.cc:190
operator() at ./replica/table.cc:2157
 (inlined by) flat_mutation_reader_v2 std::__invoke_impl&lt;flat_mutation_reader_v2, replica::table::as_mutation_source() const::$_39&amp;, seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt; &gt;(std::__invoke_other, replica::table::as_mutation_source() const::$_39&amp;, seastar::lw_shared_ptr&lt;schema const&gt;&amp;&amp;, reader_permit&amp;&amp;, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr&amp;&amp;, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;&amp;&amp;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;&amp;&amp;) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:61
 (inlined by) std::enable_if&lt;is_invocable_r_v&lt;flat_mutation_reader_v2, replica::table::as_mutation_source() const::$_39&amp;, seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt; &gt;, flat_mutation_reader_v2&gt;::type std::__invoke_r&lt;flat_mutation_reader_v2, replica::table::as_mutation_source() const::$_39&amp;, seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt; &gt;(replica::table::as_mutation_source() const::$_39&amp;, seastar::lw_shared_ptr&lt;schema const&gt;&amp;&amp;, reader_permit&amp;&amp;, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr&amp;&amp;, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;&amp;&amp;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;&amp;&amp;) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:114
 (inlined by) std::_Function_handler&lt;flat_mutation_reader_v2 (seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;), replica::table::as_mutation_source() const::$_39&gt;::_M_invoke(std::_Any_data const&amp;, seastar::lw_shared_ptr&lt;schema const&gt;&amp;&amp;, reader_permit&amp;&amp;, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr&amp;&amp;, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;&amp;&amp;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;&amp;&amp;) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:290
std::function&lt;flat_mutation_reader_v2 (seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;)&gt;::operator()(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;) const at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:590
 (inlined by) mutation_source::make_reader_v2(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, nonwrapping_interval&lt;dht::ring_position&gt; const&amp;, query::partition_slice const&amp;, seastar::io_priority_class const&amp;, tracing::trace_state_ptr, seastar::bool_class&lt;streamed_mutation::forwarding_tag&gt;, seastar::bool_class&lt;mutation_reader::partition_range_forwarding_tag&gt;) const at ././readers/mutation_source.hh:163
 (inlined by) querier_base at ././querier.hh:79
 (inlined by) querier at ././querier.hh:146
replica::table::query(seastar::lw_shared_ptr&lt;schema const&gt;, reader_permit, query::read_command const&amp;, query::result_options, std::vector&lt;nonwrapping_interval&lt;dht::ring_position&gt;, std::allocator&lt;nonwrapping_interval&lt;dht::ring_position&gt; &gt; &gt; const&amp;, tracing::trace_state_ptr, query::result_memory_limiter&amp;, std::chrono::time_point&lt;seastar::lowres_clock, std::chrono::duration&lt;long, std::ratio&lt;1l, 1000000000l&gt; &gt; &gt;, std::optional&lt;query::querier&lt;(emit_only_live_rows)1&gt; &gt;*) at ./replica/table.cc:2064
operator() at ./replica/database.cc:1459
 (inlined by) seastar::noncopyable_function&lt;seastar::future&lt;void&gt; (reader_permit)&gt;::indirect_vtable_for&lt;replica::database::query(seastar::lw_shared_ptr&lt;schema const&gt;, query::read_command const&amp;, query::result_options, std::vector&lt;nonwrapping_interval&lt;dht::ring_position&gt;, std::allocator&lt;nonwrapping_interval&lt;dht::ring_position&gt; &gt; &gt; const&amp;, tracing::trace_state_ptr, std::chrono::time_point&lt;seastar::lowres_clock, std::chrono::duration&lt;long, std::ratio&lt;1l, 1000000000l&gt; &gt; &gt;, std::variant&lt;std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce&gt;)::$_17&gt;::call(seastar::noncopyable_function&lt;seastar::future&lt;void&gt; (reader_permit)&gt; const*, reader_permit) at ././seastar/include/seastar/util/noncopyable_function.hh:153
seastar::noncopyable_function&lt;seastar::future&lt;void&gt; (reader_permit)&gt;::operator()(reader_permit) const at ././seastar/include/seastar/util/noncopyable_function.hh:209
 (inlined by) reader_concurrency_semaphore::execution_loop() at ./reader_concurrency_semaphore.cc:620
seastar::reactor::run_tasks(seastar::reactor::task_queue&amp;) at ./build/release/seastar/./seastar/src/core/reactor.cc:2356
 (inlined by) seastar::reactor::run_some_tasks() at ./build/release/seastar/./seastar/src/core/reactor.cc:2769
seastar::reactor::do_run() at ./build/release/seastar/./seastar/src/core/reactor.cc:2938
operator() at ./build/release/seastar/./seastar/src/core/reactor.cc:4165
 (inlined by) void std::__invoke_impl&lt;void, seastar::smp::configure(seastar::smp_options const&amp;, seastar::reactor_options const&amp;)::$_90&amp;&gt;(std::__invoke_other, seastar::smp::configure(seastar::smp_options const&amp;, seastar::reactor_options const&amp;)::$_90&amp;) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:61
 (inlined by) std::enable_if&lt;is_invocable_r_v&lt;void, seastar::smp::configure(seastar::smp_options const&amp;, seastar::reactor_options const&amp;)::$_90&amp;&gt;, void&gt;::type std::__invoke_r&lt;void, seastar::smp::configure(seastar::smp_options const&amp;, seastar::reactor_options const&amp;)::$_90&amp;&gt;(seastar::smp::configure(seastar::smp_options const&amp;, seastar::reactor_options const&amp;)::$_90&amp;) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:111
 (inlined by) std::_Function_handler&lt;void (), seastar::smp::configure(seastar::smp_options const&amp;, seastar::reactor_options const&amp;)::$_90&gt;::_M_invoke(std::_Any_data const&amp;) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:290
std::function&lt;void ()&gt;::operator()() const at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:590
 (inlined by) seastar::posix_thread::start_routine(void*) at ./build/release/seastar/./seastar/src/core/posix.cc:60
?? ??:0
?? ??:0

asias commented 2 years ago

All stalls:

stalls.txt

asias commented 2 years ago

All stalls:

stalls.txt

Benny, could you run with your magic stall analysis script with this. We have 3000+ stalls.

avikivity commented 2 years ago

@bhalevy

bhalevy commented 2 years ago

Even without the stall analyzer this looks like a duplicate of #8938 But I'll run it just to practice my skills :)

bhalevy commented 2 years ago

$ ~/dev/seastar/scripts/stall-analyser.py -e scylla/libexec/scylla stalls.txt 2>/dev/null
Processed 3660 stalls lasting a total of 33200 milliseconds.
min=6 avg=9.1 median=8 p95=14 p99=20 p999=54 max=54

This graph is printed in bottom-up order, where callees are printed first.
Use --direction=top-down to print callers first.

[level#index/out_of pct%] below denotes:
  level  - nesting level in the graph
  index  - index of node among to its siblings
  out_of - number of siblings
  pct    - percentage of total stall time of this call relative to its siblings

Command line options: --address-threshold=0x100000000 --executable=scylla/libexec/scylla --direction=bottom-up --branch-threshold=0.05 --file=stalls.txt

++[0#1/380 9%] addr=0x15d9902 total=2864 count=324 avg=9:
|              utils::uleb64_decode_forwards<void (&)(char const*, unsigned long), void (&)(char const*, unsigned long)> at ././utils/vle.hh:105
|              (inlined by) logalloc::region_impl::object_descriptor::decode_forwards at ./utils/logalloc.cc:1226
|              (inlined by) logalloc::region_impl::for_each_live<logalloc::region_impl::compact_segment_locked(logalloc::segment*, logalloc::segment_descriptor&)::{lambda(logalloc::region_impl::object_descriptor const*, void*, unsigned long)#1}> at ./utils/logalloc.cc:1326
|              (inlined by) logalloc::region_impl::compact_segment_locked at ./utils/logalloc.cc:1480
++           - addr=0x15bba15:
|              logalloc::region_impl::compact at ./utils/logalloc.cc:1802
| ++[1#1/2 85%] addr=0x15c3a67 total=20296 count=2108 avg=10:
| |             logalloc::reclaim_from_evictable at ./utils/logalloc.cc:2121
| ++          - addr=0x15bf8f7:
| |             logalloc::tracker::impl::compact_and_evict_locked at ./utils/logalloc.cc:2365
| | ++[2#1/2 100%] addr=0x15b0669 total=23124 count=2512 avg=9:
| | |              logalloc::tracker::impl::compact_and_evict at ./utils/logalloc.cc:2299
| | | ++[3#1/1 100%] addr=0x15aef7f total=26232 count=2896 avg=9:
| | | |              logalloc::segment_pool::allocate_segment at ./utils/logalloc.cc:970
| | |   ++[4#1/1 100%] addr=0x15ce987 total=27180 count=2972 avg=9:
| | |   |              logalloc::segment_pool::refill_emergency_reserve at ./utils/logalloc.cc:983
| | |   |              (inlined by) logalloc::allocating_section::reserve at ./utils/logalloc.cc:2661
| | |     ++[5#1/17 42%] addr=0x13f1200 total=11328 count=1204 avg=9:
| | |     |              logalloc::allocating_section::with_reserve<logalloc::allocating_section::operator()<replica::memtable::apply(frozen_mutation const&, seastar::lw_shared_ptr<schema const> const&, db::rp_handle&&)::$_8::operator()() const::{lambda()#1}>(logalloc::region&, replica::memtable::apply(frozen_mutation const&, seastar::lw_shared_ptr<schema const> const&, db::rp_handle&&)::$_8::operator()() const::{lambda()#1}&&)::{lambda()#1}> at ././utils/logalloc.hh:766
| | |     |              (inlined by) logalloc::allocating_section::operator()<replica::memtable::apply(frozen_mutation const&, seastar::lw_shared_ptr<schema const> const&, db::rp_handle&&)::$_8::operator()() const::{lambda()#1}> at ././utils/logalloc.hh:817
| | |     |              (inlined by) operator() at ./replica/memtable.cc:791
| | |     |              (inlined by) with_allocator<replica::memtable::apply(frozen_mutation const&, seastar::lw_shared_ptr<schema const> const&, db::rp_handle&&)::$_8> at ././utils/allocation_strategy.hh:313
| | |     |              (inlined by) replica::memtable::apply at ./replica/memtable.cc:790
| | |     | ++[6#1/2 100%] addr=0x12c1159 total=11292 count=1200 avg=9:
| | |     | |              replica::table::do_apply<frozen_mutation const&, seastar::lw_shared_ptr<schema const>&> at ./replica/table.cc:1921
| | |     | |              (inlined by) operator() at ./replica/table.cc:1947
| | |     | |              (inlined by) seastar::futurize<void>::invoke<replica::table::apply(frozen_mutation const&, seastar::lw_shared_ptr<schema const>, db::rp_handle&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >)::$_36&> at ././seastar/include/seastar/core/future.hh:2139
| | |     | |              (inlined by) seastar::futurize_invoke<replica::table::apply(frozen_mutation const&, seastar::lw_shared_ptr<schema const>, db::rp_handle&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >)::$_36&> at ././seastar/include/seastar/core/future.hh:2173
| | |     | |              (inlined by) logalloc::region_group::run_when_memory_available<replica::table::apply(frozen_mutation const&, seastar::lw_shared_ptr<schema const>, db::rp_handle&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >)::$_36> at ././utils/logalloc.hh:321
| | |     | |              (inlined by) replica::table::apply at ./replica/table.cc:1946
| | |     | | ++[7#1/2 99%] addr=0x118387a total=11224 count=1188 avg=9:
| | |     | | |             operator() at ./replica/database.cc:1806
| | |     | | |             (inlined by) seastar::futurize<seastar::future<void> >::invoke<replica::database::apply_in_memory(frozen_mutation const&, seastar::lw_shared_ptr<schema const>, db::rp_handle&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >)::$_48> at ././seastar/include/seastar/core/future.hh:2142
| | |     | | |             (inlined by) seastar::futurize_invoke<replica::database::apply_in_memory(frozen_mutation const&, seastar::lw_shared_ptr<schema const>, db::rp_handle&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >)::$_48> at ././seastar/include/seastar/core/future.hh:2173
| | |     | | |             (inlined by) seastar::internal::invoke_func_with_gate<replica::database::apply_in_memory(frozen_mutation const&, seastar::lw_shared_ptr<schema const>, db::rp_handle&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >)::$_48> at ././seastar/include/seastar/core/gate.hh:221
| | |     | | |             (inlined by) seastar::with_gate<replica::database::apply_in_memory(frozen_mutation const&, seastar::lw_shared_ptr<schema const>, db::rp_handle&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >)::$_48> at ././seastar/include/seastar/core/gate.hh:239
| | |     | | |             (inlined by) replica::database::apply_in_memory at ./replica/database.cc:1805
| | |     | | |             (inlined by) replica::database::do_apply at ./replica/database.cc:1987
| | |     | | ++          - addr=0x121fb5f:
| | |     | | |             std::__invoke_impl<seastar::future<void>, seastar::future<void> (replica::database::* const&)(seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>), replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> > at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:74
| | |     | | |             (inlined by) std::__invoke<seastar::future<void> (replica::database::* const&)(seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>), replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> > at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:96
| | |     | | |             (inlined by) std::_Mem_fn_base<seastar::future<void> (replica::database::*)(seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>), true>::operator()<replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> > at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/functional:131
| | |     | | |             (inlined by) seastar::noncopyable_function<seastar::future<void> (replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)>::direct_vtable_for<std::_Mem_fn<seastar::future<void> (replica::database::*)(seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)> >::call at ././seastar/include/seastar/util/noncopyable_function.hh:124
| | |     | | | ++[8#1/1 100%] addr=0x123a1d7 total=11248 count=1192 avg=9:
| | |     | | | |              seastar::noncopyable_function<seastar::future<void> (replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)>::operator() at ././seastar/include/seastar/util/noncopyable_function.hh:209
| | |     | | | |              (inlined by) operator() at ././seastar/include/seastar/core/execution_stage.hh:338
| | |     | | | |              (inlined by) seastar::noncopyable_function<seastar::future<void> (replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)>::direct_vtable_for<seastar::inheriting_concrete_execution_stage<seastar::future<void>, replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> >::make_stage_for_group(seastar::scheduling_group)::{lambda(replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)#1}>::call at ././seastar/include/seastar/util/noncopyable_function.hh:124
| | |     | | | ++           - addr=0x11ff726:
| | |     | | | |              seastar::noncopyable_function<seastar::future<void> (replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)>::operator() at ././seastar/include/seastar/util/noncopyable_function.hh:209
| | |     | | | |              (inlined by) std::__invoke_impl<seastar::future<void>, seastar::noncopyable_function<seastar::future<void> (replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)>&, replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> > at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:61
| | |     | | | |              (inlined by) std::__invoke<seastar::noncopyable_function<seastar::future<void> (replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)>&, replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> > at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:96
| | |     | | | |              (inlined by) std::__apply_impl<seastar::noncopyable_function<seastar::future<void> (replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)>&, std::tuple<replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> >, 0ul, 1ul, 2ul, 3ul, 4ul, 5ul, 6ul> at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/tuple:1858
| | |     | | | |              (inlined by) std::apply<seastar::noncopyable_function<seastar::future<void> (replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)>&, std::tuple<replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> > > at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/tuple:1869
| | |     | | | |              (inlined by) seastar::futurize<seastar::future<void> >::apply<seastar::noncopyable_function<seastar::future<void> (replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)>&, replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> > at ././seastar/include/seastar/core/future.hh:2109
| | |     | | | |              (inlined by) seastar::concrete_execution_stage<seastar::future<void>, replica::database*, seastar::lw_shared_ptr<schema const>, frozen_mutation const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, seastar::bool_class<db::force_sync_tag>, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce> >::do_flush at ././seastar/include/seastar/core/execution_stage.hh:247
| | |     | | | ++           - addr=0x4b3cee5:
| | |     | | | |              operator() at ./build/release/seastar/./seastar/src/core/execution_stage.cc:142
| | |     | | | |              (inlined by) seastar::futurize<void>::invoke<seastar::execution_stage::flush()::$_1&> at ./build/release/seastar/./seastar/include/seastar/core/future.hh:2139
| | |     | | | |              (inlined by) seastar::lambda_task<seastar::execution_stage::flush()::$_1>::run_and_dispose at ./build/release/seastar/./seastar/include/seastar/core/make_task.hh:40
| | |     | | |   ++[9#1/1 100%] addr=0x4b8ac04 total=11300 count=1200 avg=9:
| | |     | | |   |              seastar::reactor::run_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2356
| | |     | | |   |              (inlined by) seastar::reactor::run_some_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2769
| | |     | | |     ++[10#1/1 100%] addr=0x4b8bfe7 total=29360 count=3164 avg=9:
| | |     | | |     |               seastar::reactor::do_run at ./build/release/seastar/./seastar/src/core/reactor.cc:2938
| | |     | | |       ++[11#1/2 83%] addr=0x4bab1a5 total=24352 count=2676 avg=9:
| | |     | | |       |              operator() at ./build/release/seastar/./seastar/src/core/reactor.cc:4165
| | |     | | |       |              (inlined by) std::__invoke_impl<void, seastar::smp::configure(seastar::smp_options const&, seastar::reactor_options const&)::$_90&> at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:61
| | |     | | |       |              (inlined by) std::__invoke_r<void, seastar::smp::configure(seastar::smp_options const&, seastar::reactor_options const&)::$_90&> at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:111
| | |     | | |       |              (inlined by) std::_Function_handler<void (), seastar::smp::configure(seastar::smp_options const&, seastar::reactor_options const&)::$_90>::_M_invoke at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:290
| | |     | | |       ++           - addr=0x4b5ec8a:
| | |     | | |       |              std::function<void ()>::operator() at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:590
| | |     | | |       |              (inlined by) seastar::posix_thread::start_routine at ./build/release/seastar/./seastar/src/core/posix.cc:60
| | |     | | |       ++           - addr=0x92a4: ?? ??:0
| | |     | | |       ++           - addr=0x100322: ?? ??:0
| | |     | | |       ++[11#2/2 17%] addr=0x4b8b23c total=5008 count=488 avg=10:
| | |     | | |       |              seastar::reactor::run at ./build/release/seastar/./seastar/src/core/reactor.cc:2821
| | |     | | |       ++           - addr=0x4b31588:
| | |     | | |       |              seastar::app_template::run_deprecated at ./build/release/seastar/./seastar/src/core/app-template.cc:265
| | |     | | |       ++           - addr=0x4b30a61:
| | |     | | |       |              seastar::app_template::run at ./build/release/seastar/./seastar/src/core/app-template.cc:156
| | |     | | |       ++           - addr=0x104d25f:
| | |     | | |       |              scylla_main at ./main.cc:540
| | |     | | |       ++           - addr=0x104a7aa:
| | |     | | |       |              std::function<int (int, char**)>::operator() at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:590
| | |     | | |       |              (inlined by) main at ./main.cc:1659
| | |     | | |       ++           - addr=0x27b74: ?? ??:0
| | |     | | |       ++           - addr=0x10496ed:
| | |     | | |       |              _start at ??:?
| | |     | | ++[7#2/2 1%] 1 more branches total=156 count=20 avg=8
| | |     | ++[6#2/2 0%] 1 more branches total=36 count=4 avg=9
| | |     |+[5#2/17 23%] addr=0x13edca0 total=6332 count=652 avg=10:
| | |     |              logalloc::allocating_section::with_reserve<logalloc::allocating_section::operator()<replica::memtable::make_flat_reader_opt(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<mutation_reader::partition_range_forwarding_tag>)::$_5>(logalloc::region&, replica::memtable::make_flat_reader_opt(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<mutation_reader::partition_range_forwarding_tag>)::$_5&&)::{lambda()#1}> at ././utils/logalloc.hh:766
| | |     |              (inlined by) logalloc::allocating_section::operator()<replica::memtable::make_flat_reader_opt(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<mutation_reader::partition_range_forwarding_tag>)::$_5> at ././utils/logalloc.hh:817
| | |     |              (inlined by) replica::memtable::make_flat_reader_opt at ./replica/memtable.cc:711
| | |     |+           - addr=0x1279cdb:
| | |     |              replica::table::make_reader_v2 at ./replica/table.cc:190
| | |     |+           - addr=0x13525c2:
| | |     |              operator() at ./replica/table.cc:2157
| | |     |              (inlined by) std::__invoke_impl<flat_mutation_reader_v2, replica::table::as_mutation_source() const::$_39&, seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<mutation_reader::partition_range_forwarding_tag> > at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:61
| | |     |              (inlined by) std::__invoke_r<flat_mutation_reader_v2, replica::table::as_mutation_source() const::$_39&, seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<mutation_reader::partition_range_forwarding_tag> > at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:114
| | |     |              (inlined by) std::_Function_handler<flat_mutation_reader_v2 (seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<mutation_reader::partition_range_forwarding_tag>), replica::table::as_mutation_source() const::$_39>::_M_invoke at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:290
| | |     |+           - addr=0x12c76de:
| | |     |              std::function<flat_mutation_reader_v2 (seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<mutation_reader::partition_range_forwarding_tag>)>::operator() at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:590
| | |     |              (inlined by) mutation_source::make_reader_v2 at ././readers/mutation_source.hh:163
| | |     |              (inlined by) querier_base at ././querier.hh:79
| | |     |              (inlined by) querier at ././querier.hh:146
| | |     |+           - addr=0x12c32ad:
| | |     |              replica::table::query at ./replica/table.cc:2064
| | |     |+           - addr=0x122cad6:
| | |     |              operator() at ./replica/database.cc:1459
| | |     |              (inlined by) seastar::noncopyable_function<seastar::future<void> (reader_permit)>::indirect_vtable_for<replica::database::query(seastar::lw_shared_ptr<schema const>, query::read_command const&, query::result_options, std::vector<nonwrapping_interval<dht::ring_position>, std::allocator<nonwrapping_interval<dht::ring_position> > > const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, std::variant<std::monostate, db::per_partition_rate_limit::account_only, db::per_partition_rate_limit::account_and_enforce>)::$_17>::call at ././seastar/include/seastar/util/noncopyable_function.hh:153
| | |     | ++[6#1/1 100%] addr=0x398fc80 total=6532 count=672 avg=10:
| | |     | |              seastar::noncopyable_function<seastar::future<void> (reader_permit)>::operator() at ././seastar/include/seastar/util/noncopyable_function.hh:209
| | |     | |              (inlined by) reader_concurrency_semaphore::execution_loop at ./reader_concurrency_semaphore.cc:620
| | |     | ++           - addr=0x4b8ac04:
| | |     | |              seastar::reactor::run_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2356
| | |     | |              (inlined by) seastar::reactor::run_some_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2769
| | |     | -> continued at addr=0x4b8ac04 above
| | |     |+[5#3/17 20%] addr=0x1500edb total=5400 count=652 avg=8:
| | |     |              logalloc::allocating_section::with_reserve<logalloc::allocating_section::operator()<cache::lsa_manager::run_in_read_section<cache::cache_flat_mutation_reader::fill_buffer()::{lambda()#1}::operator()() const::{lambda()#1}>(cache::cache_flat_mutation_reader::fill_buffer()::{lambda()#1}::operator()() const::{lambda()#1} const&)::{lambda()#1}>(logalloc::region&, {lambda()#1}&&)::{lambda()#1}> at ././utils/logalloc.hh:766
| | |     |              (inlined by) logalloc::allocating_section::operator()<cache::lsa_manager::run_in_read_section<cache::cache_flat_mutation_reader::fill_buffer()::{lambda()#1}::operator()() const::{lambda()#1}>(cache::cache_flat_mutation_reader::fill_buffer()::{lambda()#1}::operator()() const::{lambda()#1} const&)::{lambda()#1}> at ././utils/logalloc.hh:817
| | |     |              (inlined by) cache::lsa_manager::run_in_read_section<cache::cache_flat_mutation_reader::fill_buffer()::{lambda()#1}::operator()() const::{lambda()#1}> at ././row_cache.hh:480
| | |     |              (inlined by) operator() at ././cache_flat_mutation_reader.hh:332
| | |     |+           - addr=0x14fffe0:
| | |     |              cache::cache_flat_mutation_reader::fill_buffer at ././cache_flat_mutation_reader.hh:340
| | |     | ++[6#1/2 84%] addr=0x17f95a5 total=4584 count=548 avg=8:
| | |     | |             flat_mutation_reader_v2::fill_buffer at ././readers/flat_mutation_reader_v2.hh:510
| | |     | |             (inlined by) flat_mutation_reader_v2::impl::fill_buffer_from<flat_mutation_reader_v2> at ./readers/mutation_reader.cc:319
| | |     | | ++[7#1/2 99%] addr=0x15387bd total=4556 count=544 avg=8:
| | |     | | |             operator() at ./row_cache.cc:413
| | |     | | |             (inlined by) seastar::futurize<seastar::future<void> >::invoke<single_partition_populating_reader::fill_buffer()::{lambda()#3}&> at ././seastar/include/seastar/core/future.hh:2142
| | |     | | |             (inlined by) seastar::futurize_invoke<single_partition_populating_reader::fill_buffer()::{lambda()#3}&> at ././seastar/include/seastar/core/future.hh:2173
| | |     | | |             (inlined by) seastar::do_until<single_partition_populating_reader::fill_buffer()::{lambda()#3}, single_partition_populating_reader::fill_buffer()::{lambda()#2}> at ././seastar/include/seastar/core/loop.hh:343
| | |     | | |             (inlined by) single_partition_populating_reader::fill_buffer at ./row_cache.cc:412
| | |     | | |             (inlined by) operator() at ./row_cache.cc:409
| | |     | | ++          - addr=0x1539a41:
| | |     | | |             std::__invoke_impl<seastar::future<void>, single_partition_populating_reader::fill_buffer()::{lambda()#1}&> at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:61
| | |     | | |             (inlined by) std::__invoke<single_partition_populating_reader::fill_buffer()::{lambda()#1}&> at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:96
| | |     | | |             (inlined by) std::invoke<single_partition_populating_reader::fill_buffer()::{lambda()#1}&> at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/functional:97
| | |     | | |             (inlined by) seastar::internal::future_invoke<single_partition_populating_reader::fill_buffer()::{lambda()#1}&, seastar::internal::monostate> at ././seastar/include/seastar/core/future.hh:1216
| | |     | | |             (inlined by) operator() at ././seastar/include/seastar/core/future.hh:1589
| | |     | | |             (inlined by) seastar::futurize<seastar::future<void> >::satisfy_with_result_of<seastar::future<void>::then_impl_nrvo<single_partition_populating_reader::fill_buffer()::{lambda()#1}, seastar::future<void> >(single_partition_populating_reader::fill_buffer()::{lambda()#1}&&)::{lambda(seastar::internal::promise_base_with_type<void>&&, {lambda()#1}&, seastar::future_state<auto:1&&::monostate>&&)#1}::operator()(seastar::internal::promise_base_with_type<void>, seastar::internal::promise_base_with_type<void>&&, seastar::future_state<single_partition_populating_reader::fill_buffer()::{lambda()#1}&&::monostate>) const::{lambda()#1}> at ././seastar/include/seastar/core/future.hh:2127
| | |     | | |             (inlined by) operator() at ././seastar/include/seastar/core/future.hh:1582
| | |     | | |             (inlined by) seastar::continuation<seastar::internal::promise_base_with_type<void>, single_partition_populating_reader::fill_buffer()::{lambda()#1}, seastar::future<void>::then_impl_nrvo<{lambda()#1}, seastar::future>({lambda()#1}&&)::{lambda(seastar::internal::promise_base_with_type<void>&&, {lambda()#1}&, seastar::future_state<seastar::internal::monostate>&&)#1}, void>::run_and_dispose at ././seastar/include/seastar/core/future.hh:774
| | |     | | ++          - addr=0x4b8ac04:
| | |     | | |             seastar::reactor::run_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2356
| | |     | | |             (inlined by) seastar::reactor::run_some_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2769
| | |     | | -> continued at addr=0x4b8ac04 above
| | |     | | ++[7#2/2 1%] 1 more branches total=28 count=4 avg=7
| | |     | ++[6#2/2 16%] addr=0x1307b34 total=904 count=112 avg=8:
| | |     | |             operator() at ././readers/flat_mutation_reader_v2.hh:210
| | |     | ++          - addr=0x130b840:
| | |     | |             seastar::futurize<seastar::future<seastar::bool_class<seastar::stop_iteration_tag> > >::invoke<flat_mutation_reader_v2::impl::consume_pausable<std::reference_wrapper<flat_mutation_reader_v2::impl::consumer_adapter<compact_for_query_v2<(emit_only_live_rows)1, query_result_builder> > > >(std::reference_wrapper<flat_mutation_reader_v2::impl::consumer_adapter<compact_for_query_v2<(emit_only_live_rows)1, query_result_builder> > >)::{lambda()#1}&> at ././seastar/include/seastar/core/future.hh:2142
| | |     | |             (inlined by) seastar::futurize_invoke<flat_mutation_reader_v2::impl::consume_pausable<std::reference_wrapper<flat_mutation_reader_v2::impl::consumer_adapter<compact_for_query_v2<(emit_only_live_rows)1, query_result_builder> > > >(std::reference_wrapper<flat_mutation_reader_v2::impl::consumer_adapter<compact_for_query_v2<(emit_only_live_rows)1, query_result_builder> > >)::{lambda()#1}&> at ././seastar/include/seastar/core/future.hh:2173
| | |     | |             (inlined by) seastar::internal::repeater<flat_mutation_reader_v2::impl::consume_pausable<std::reference_wrapper<flat_mutation_reader_v2::impl::consumer_adapter<compact_for_query_v2<(emit_only_live_rows)1, query_result_builder> > > >(std::reference_wrapper<flat_mutation_reader_v2::impl::consumer_adapter<compact_for_query_v2<(emit_only_live_rows)1, query_result_builder> > >)::{lambda()#1}>::run_and_dispose at ././seastar/include/seastar/core/loop.hh:73
| | |     | ++          - addr=0x4b8ac04:
| | |     | |             seastar::reactor::run_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2356
| | |     | |             (inlined by) seastar::reactor::run_some_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2769
| | |     | -> continued at addr=0x4b8ac04 above
| | |     ++[5#4/17 15%] 14 more branches total=4120 count=464 avg=9
| | ++[2#2/2 0%] 1 more branches total=56 count=8 avg=7
| ++[1#2/2 15%] addr=0x15bf8d7 total=3636 count=456 avg=8:
| |             logalloc::tracker::impl::compact_and_evict_locked at ./utils/logalloc.cc:2367
|   ++[2#1/2 85%] addr=0x15b0669 total=3080 count=380 avg=8:
|   |             logalloc::tracker::impl::compact_and_evict at ./utils/logalloc.cc:2299
|   -> continued at addr=0x15b0669 above
|   ++[2#2/2 15%] addr=0x15bc5a2 total=556 count=76 avg=7:
|   |             logalloc::tracker::impl::reclaim_locked at ./utils/logalloc.cc:2277
|     ++[3#1/1 100%] addr=0x15ad583 total=644 count=88 avg=7:
|     |              logalloc::tracker::impl::reclaim at ./utils/logalloc.cc:2256
|       ++[4#1/1 100%] addr=0x15f330d total=764 count=104 avg=7:
|       |              seastar::noncopyable_function<void (unsigned long)>::operator() at ././seastar/include/seastar/util/noncopyable_function.hh:209
|       |              (inlined by) logalloc::background_reclaimer::main_loop at ./utils/logalloc.cc:403
|       ++           - addr=0x4b8ac04:
|       |              seastar::reactor::run_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2356
|       |              (inlined by) seastar::reactor::run_some_tasks at ./build/release/seastar/./seastar/src/core/reactor.cc:2769
|       -> continued at addr=0x4b8ac04 above
++[0#2/380 91%] 379 more branches total=29388 count=3232 avg=0

asias commented 2 years ago

For the record:

https://jenkins.scylladb.com/job/scylla-master/job/ami/983/artifact/00-Build.txt

docker-image-name-aarch64: scylla-nightly:5.1.dev-0.20220711.7e2d2cf1c18d-aarch64
docker-image-name-x86_64: scylla-nightly:5.1.dev-0.20220711.7e2d2cf1c18d-x86_64
docker-image-name: scylla-nightly:5.1.dev-0.20220711.7e2d2cf1c18d
git@github.com:scylladb/scylla.git-sha: 7e2d2cf1c18ddf471df1c2a28e805a5c1c69af50
jenkins-job-number: 1080
jenkins-job-path: scylla-master/build
reloc-pack-url: downloads.scylladb.com/unstable/scylla/master/relocatable/2022-07-11T03:03:13Z/
rpm-deb-pack-url: downloads.scylladb.com/unstable/scylla/master/build-packages/2022-07-11T03:03:13Z/
scylla-aarch64-BuildID[sha1]: 35527b61b4353540f50f44f9f691c373c94222b7
scylla-ami-id-aarch64: ami-076ff2f0e6f2e5534
scylla-ami-id-x86_64: ami-0a34ab94253143c70
scylla-debug-aarch64-BuildID[sha1]: d5c70168434849691e311535744a33de82cca7a0
scylla-debug-x86_64-BuildID[sha1]: d540d2134476c58fbfe9e80e5ccfb7fdd9698921
scylla-product: scylla
scylla-release: 0.20220711.7e2d2cf1c18d
scylla-version: 5.1.dev
scylla-x86_64-BuildID[sha1]: 8d31af83d550feaccdcf3d243d522685440315a2
timestamp: 2022-07-11T03:03:13Z
unified-deb-url: downloads.scylladb.com/unstable/scylla/master/deb/unified/2022-07-11T03:03:13Z
unified-pack-url-aarch64: downloads.scylladb.com/unstable/scylla/master/relocatable/2022-07-11T03:03:13Z/scylla-aarch64-unified-package-5.1.dev.0.20220711.7e2d2cf1c18d.tar.gz
unified-pack-url-x86_64: downloads.scylladb.com/unstable/scylla/master/relocatable/2022-07-11T03:03:13Z/scylla-x86_64-unified-package-5.1.dev.0.20220711.7e2d2cf1c18d.tar.gz
url-id: 2022-07-11T03:03:13Z

asias commented 2 years ago

@bhalevy

Let's look at level 0. It showed only two siblings: 1/380 and 2/380. What about the other siblings? The script merged similar ones into 2/380?

And the total amount of stalls does not match: 324 (from 1/380 9%)+ 3232 (from 2/380 91%) = 3556. The total should be 3660 stalls.

Processed 3660 stalls lasting a total of 33200 milliseconds.

++[0#1/380 9%] addr=0x15d9902 total=2864 count=324 avg=9:
...

++[0#2/380 91%] 379 more branches total=29388 count=3232 avg=0

So, we have 9% of stall time from 1/380 which is reclaim_from_evictable. Where does the other 91% come from?

bhalevy commented 2 years ago

@asias https://github.com/scylladb/seastar/blob/master/scripts/stall-analyser.py has a --branch-threshold BRANCH_THRESHOLD option that is 5% be default. With it, it expand only branches in the tree that a responsible to the amount relative to the total (In number of stall reports, not in total stall time. Maybe we should consider changing that).

If you want to see more details, please rerun with a lower branch threshold.

slivne commented 2 years ago

quoting avi

one option is the reservation is large - can we check the allocation we are doing - we have more logs in lsa memory
another option is that the background relcaim was not able to keep free memory up and that is the problem it should be visible in the metrics (all memory eviction should happen in free cpu time)

quoting asias

most of this is in off strategy

slivne commented 2 years ago

please add the logs and metrics so it will be easier to associate the person.

slivne commented 2 years ago

@asias please extract the info of time in the lgos so I can assign

asias commented 2 years ago

The logs are here.

Links:

    [Build URL](https://jenkins.scylladb.com/job/scylla-master/job/scylla-master-perf-regression-latency-250gb-with-nemesis/219/)
    [Download "Per server metrics nemesis" Grafana Screenshot](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_172900/grafana-screenshot-overview-20220711_172900-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)
    [Download "Overview metrics" Grafana Screenshot](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_172900/grafana-screenshot-scylla-master-perf-regression-latency-250gb-with-nemesis-scylla-per-server-metrics-nemesis-20220711_173048-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)

Logs:

    [prometheus - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/prometheus_snapshot_20220711_125458.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/prometheus_snapshot_20220711_125458.tar.gz)
    [prometheus - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/prometheus_snapshot_20220711_172828.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/prometheus_snapshot_20220711_172828.tar.gz)
    [prometheus - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/prometheus_snapshot_20220711_174252.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/prometheus_snapshot_20220711_174252.tar.gz)
    [prometheus - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/prometheus_snapshot_20220711_175803.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/prometheus_snapshot_20220711_175803.tar.gz)
    [grafana - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_124200/grafana-screenshot-overview-20220711_124200-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_124200/grafana-screenshot-overview-20220711_124200-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)
    [grafana - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_124200/grafana-screenshot-scylla-master-perf-regression-latency-250gb-with-nemesis-scylla-per-server-metrics-nemesis-20220711_124336-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_124200/grafana-screenshot-scylla-master-perf-regression-latency-250gb-with-nemesis-scylla-per-server-metrics-nemesis-20220711_124336-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)
    [grafana - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_171442/grafana-screenshot-overview-20220711_171442-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_171442/grafana-screenshot-overview-20220711_171442-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)
    [grafana - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_171442/grafana-screenshot-scylla-master-perf-regression-latency-250gb-with-nemesis-scylla-per-server-metrics-nemesis-20220711_171624-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_171442/grafana-screenshot-scylla-master-perf-regression-latency-250gb-with-nemesis-scylla-per-server-metrics-nemesis-20220711_171624-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)
    [grafana - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_172900/grafana-screenshot-overview-20220711_172900-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_172900/grafana-screenshot-overview-20220711_172900-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)
    [grafana - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_172900/grafana-screenshot-scylla-master-perf-regression-latency-250gb-with-nemesis-scylla-per-server-metrics-nemesis-20220711_173048-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_172900/grafana-screenshot-scylla-master-perf-regression-latency-250gb-with-nemesis-scylla-per-server-metrics-nemesis-20220711_173048-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)
    [grafana - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_174353/grafana-screenshot-overview-20220711_174353-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_174353/grafana-screenshot-overview-20220711_174353-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)
    [grafana - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_174353/grafana-screenshot-scylla-master-perf-regression-latency-250gb-with-nemesis-scylla-per-server-metrics-nemesis-20220711_174541-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_174353/grafana-screenshot-scylla-master-perf-regression-latency-250gb-with-nemesis-scylla-per-server-metrics-nemesis-20220711_174541-perf-latency-nemesis-perf-v12-monitor-node-b6e3deb1-1.png)
    [db-cluster - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_175912/db-cluster-b6e3deb1.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_175912/db-cluster-b6e3deb1.tar.gz)
    [loader-set - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_175912/loader-set-b6e3deb1.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_175912/loader-set-b6e3deb1.tar.gz)
    [monitor-set - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_175912/monitor-set-b6e3deb1.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_175912/monitor-set-b6e3deb1.tar.gz)
    [sct-runner - https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_175912/sct-runner-b6e3deb1.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/b6e3deb1-af09-41f6-a0a1-25efab227f6f/20220711_175912/sct-runner-b6e3deb1.tar.gz)

And the stalls are here:

https://github.com/scylladb/scylladb/issues/11038#issuecomment-1183946351)

What else do you want so you can assign to people?

avikivity commented 2 years ago

No large allocation warnings in the logs.

avikivity commented 2 years ago

We have lsa detailed logging:

2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !WARNING | scylla:  [shard 5] lsa-timing - Reclamation cycle took 8000 us, trying to release 6.111 MiB preemptibly
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - reclamation rate = 468.743 MiB/s
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - compacted segments: 2
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - compacted memory: 0.219 MiB
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !WARNING | scylla:  [shard 5] lsa-timing - Reclamation cycle took 8000 us, trying to release 6.111 MiB preemptibly
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - reclamation rate = 468.743 MiB/s
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - compacted segments: 2
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - compacted memory: 0.219 MiB

avikivity commented 2 years ago

That's preemptible allocation, so it's either a huge bug in preemptible allocation, or a kernel stall.

avikivity commented 2 years ago

It's blanketed by sudo calls:

2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !WARNING | scylla:  [shard 5] lsa-timing - Reclamation cycle took 8000 us, trying to release 6.111 MiB preemptibly
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - reclamation rate = 468.743 MiB/s
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - compacted segments: 2
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - compacted memory: 0.219 MiB
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !WARNING | scylla:  [shard 5] lsa-timing - Reclamation cycle took 8000 us, trying to release 6.111 MiB preemptibly
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - reclamation rate = 468.743 MiB/s
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - compacted segments: 2
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | scylla:  [shard 5] lsa-timing - - compacted memory: 0.219 MiB
2022-07-11T11:53:17+00:00  perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1 !INFO    | sudo: pam_unix(sudo:session): session closed for user root

avikivity commented 2 years ago

I don't know if we can trust these lsa-timing reports, there's way too many of them.

$ grep -c 'Reclamation cycle' perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1/messages.log 
14552

avikivity commented 2 years ago

More than half are for 7999ms:

$ grep -c 'Reclamation cycle.*7999' perf-latency-nemesis-perf-v12-db-node-b6e3deb1-1/messages.log 
10052

avikivity commented 2 years ago

@bhalevy please assign someone to fix these bogus reports @fgelcer please change the test not to ssh into the node all the time (and not to fork/exec all the time), these operations are expensive and can disturb the measurement.

bhalevy commented 2 years ago

@bhalevy please assign someone to fix these bogus reports

Bogus in what way? In that we should not log preemptible reclamation that took a long time? (I which we could know definitely if a stall happened, despite being preemptive)

avikivity commented 2 years ago

I don't believe we had 10000 events of reclamation taking exactly 7999 us.

bhalevy commented 2 years ago

I don't believe we had 10000 events of reclamation taking exactly 7999 us.

We use CLOCK_MONOTONIC_COARSE, so the resolution isn't 1 us. I'm not sure what it is but it's >= 1ms for sure.

avikivity commented 2 years ago

It's "the time at the last tick" so has to be at least 0.5ms resolution.

fgelcer commented 2 years ago

@fgelcer please change the test not to ssh into the node all the time (and not to fork/exec all the time), these operations are expensive and can disturb the measurement.

i have created an issue in SCT for it, and we will be investigating and fixing it once finding the root cause of these multiple connections: https://github.com/scylladb/scylla-cluster-tests/issues/5147

scylladb / scylladb

17ms stalls in reclaim_from_evictable #11038