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.

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

logalloc::region_impl::object_descriptor::encode stalls (More than 100ms reactor stalls from memory allocation) - kernel issue? #8828

Closed
asias opened this issue Jun 9, 2021 · 123 comments
Assignees
Milestone

Comments

@asias
Copy link
Contributor

asias commented Jun 9, 2021

scylla: 76d7c76

test: 6 nodes in the cluster, run replace operation to replace one of the node in a loop

+100ms reactor stalls from memory were seen.

For example:

Full log attached.

longevity-100gb-4h-ReplaceNode-test.run6.console.txt.gz

[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > 021-06-07T08:13:58+00:00  longevity-100gb-4h-rbno-db-node-b293bf81-11 !INFO    | scylla: Reactor stalled for 133 ms on shard 8. Backtrace: 0x40e1204 0x40e0541 0x40e10cf 0x7fcda136b1df 0x13ac87f 0x13b3d78 0x120b64c 0x1484a78 0x142db89 0x12ed557 0x12ebafa 0x12eafd3 0x12e9be4 0x12e8dae 0x12ac7e5 0x12ab5ac 0x156e39a 0x12d91cc 0x12d9008 0x40f415f 0x40f53e7 0x411321b 0x40bf92a 0x93f8 0x101902
[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > void seastar::backtrace<seastar::backtrace_buffer::append_backtrace_oneline()::{lambda(seastar::frame)#1}>(seastar::backtrace_buffer::append_backtrace_oneline()::{lambda(seastar::frame)#1}&&) at ./build/release/seastar/./seastar/include/seastar/util/backtrace.hh:59
[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::backtrace_buffer::append_backtrace_oneline() at ./build/release/seastar/./seastar/src/core/reactor.cc:768
[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::print_with_backtrace(seastar::backtrace_buffer&, bool) at ./build/release/seastar/./seastar/src/core/reactor.cc:787
[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::internal::cpu_stall_detector::generate_trace() at ./build/release/seastar/./seastar/src/core/reactor.cc:1219
[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::internal::cpu_stall_detector::maybe_report() at ./build/release/seastar/./seastar/src/core/reactor.cc:1100
[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1114
[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1202
[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > ?? ??:0
[2021-06-07T08:24:06.778Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > logalloc::region_impl::object_descriptor::encode(char*&, unsigned long) const at ./utils/logalloc.cc:1184
[2021-06-07T08:24:06.779Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) logalloc::region_impl::alloc_small(logalloc::region_impl::object_descriptor const&, unsigned int, unsigned long) at ./utils/logalloc.cc:1293
[2021-06-07T08:24:06.779Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > logalloc::region_impl::alloc(migrate_fn_type const*, unsigned long, unsigned long) at ./utils/logalloc.cc:1515
[2021-06-07T08:24:06.779Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > void* allocation_strategy::alloc<blob_storage>(unsigned long) at ././utils/allocation_strategy.hh:147
[2021-06-07T08:24:06.779Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) managed_bytes at ././utils/managed_bytes.hh:153
[2021-06-07T08:24:06.779Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) managed_bytes at ././utils/managed_bytes.hh:200
[2021-06-07T08:24:06.779Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) atomic_cell_or_collection::copy(abstract_type const&) const at ./atomic_cell.cc:86
[2021-06-07T08:24:06.779Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ./mutation_partition.cc:1462
[2021-06-07T08:24:06.779Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::__exception_ptr::exception_ptr compact_radix_tree::tree<cell_and_hash, unsigned int>::copy_slots<std::pair<compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head*, std::__exception_ptr::exception_ptr> compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>::clone<compact_radix_tree::tree<cell_and_hash, unsigned int>::leaf_node, row::row(schema const&, column_kind, row const&)::$_14&>(compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head const&, row::row(schema const&, column_kind, row const&)::$_14&, unsigned int) const::{lambda(unsigned int)#1}, row::row(schema const&, column_kind, row const&)::$_14&, compact_radix_tree::tree<cell_and_hash, unsigned int>::node_base<cell_and_hash, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> > >(compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head const&, cell_and_hash const*, unsigned int, unsigned int, compact_radix_tree::tree<cell_and_hash, unsigned int>::node_base<cell_and_hash, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> >&, std::pair<compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head*, std::__exception_ptr::exception_ptr> compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>::clone<compact_radix_tree::tree<cell_and_hash, unsigned int>::leaf_node, row::row(schema const&, column_kind, row const&)::$_14&>(compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head const&, row::row(schema const&, column_kind, row const&)::$_14&, unsigned int) const::{lambda(unsigned int)#1}&&, row::row(schema const&, column_kind, row const&)::$_14&) at ././utils/compact-radix-tree.hh:1406
[2021-06-07T08:24:06.780Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::pair<compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head*, std::__exception_ptr::exception_ptr> compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>::clone<compact_radix_tree::tree<cell_and_hash, unsigned int>::leaf_node, row::row(schema const&, column_kind, row const&)::$_14&>(compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head const&, row::row(schema const&, column_kind, row const&)::$_14&, unsigned int) const at ././utils/compact-radix-tree.hh:1293
[2021-06-07T08:24:06.780Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::pair<compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head*, std::__exception_ptr::exception_ptr> compact_radix_tree::tree<cell_and_hash, unsigned int>::node_base<cell_and_hash, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> >::clone<compact_radix_tree::tree<cell_and_hash, unsigned int>::leaf_node, row::row(schema const&, column_kind, row const&)::$_14&, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> >(compact_radix_tree::variadic_union<compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> > const&, row::row(schema const&, column_kind, row const&)::$_14&, unsigned int) const at ././utils/compact-radix-tree.hh:829
[2021-06-07T08:24:06.781Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::pair<compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head*, std::__exception_ptr::exception_ptr> compact_radix_tree::tree<cell_and_hash, unsigned int>::node_base<cell_and_hash, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> >::clone<compact_radix_tree::tree<cell_and_hash, unsigned int>::leaf_node, row::row(schema const&, column_kind, row const&)::$_14&, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> >(compact_radix_tree::variadic_union<compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> > const&, row::row(schema const&, column_kind, row const&)::$_14&, unsigned int) const at ././utils/compact-radix-tree.hh:832
[2021-06-07T08:24:06.781Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::pair<compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head*, std::__exception_ptr::exception_ptr> compact_radix_tree::tree<cell_and_hash, unsigned int>::node_base<cell_and_hash, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> >::clone<compact_radix_tree::tree<cell_and_hash, unsigned int>::leaf_node, row::row(schema const&, column_kind, row const&)::$_14&, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> >(compact_radix_tree::variadic_union<compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> > const&, row::row(schema const&, column_kind, row const&)::$_14&, unsigned int) const at ././utils/compact-radix-tree.hh:832
[2021-06-07T08:24:06.782Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::pair<compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head*, std::__exception_ptr::exception_ptr> compact_radix_tree::tree<cell_and_hash, unsigned int>::node_base<cell_and_hash, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)1, 4u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)2, 8u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::indirect_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)3, 16u>, compact_radix_tree::tree<cell_and_hash, unsigned int>::direct_layout<cell_and_hash, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)6, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)0, 0u, (compact_radix_tree::tree<cell_and_hash, unsigned int>::layout)4, 32u> >::clone<compact_radix_tree::tree<cell_and_hash, unsigned int>::leaf_node, row::row(schema const&, column_kind, row const&)::$_14&>(row::row(schema const&, column_kind, row const&)::$_14&, unsigned int) const at ././utils/compact-radix-tree.hh:837
[2021-06-07T08:24:06.782Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::pair<compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head*, std::__exception_ptr::exception_ptr> compact_radix_tree::tree<cell_and_hash, unsigned int>::node_head::clone<row::row(schema const&, column_kind, row const&)::$_14&>(row::row(schema const&, column_kind, row const&)::$_14&, unsigned int) const at ././utils/compact-radix-tree.hh:499
[2021-06-07T08:24:06.782Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > void compact_radix_tree::tree<cell_and_hash, unsigned int>::clone_from<row::row(schema const&, column_kind, row const&)::$_14&>(compact_radix_tree::tree<cell_and_hash, unsigned int> const&, row::row(schema const&, column_kind, row const&)::$_14&) at ././utils/compact-radix-tree.hh:1862
[2021-06-07T08:24:06.782Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) row at ./mutation_partition.cc:1465
[2021-06-07T08:24:06.782Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > deletable_row at ././mutation_partition.hh:830
[2021-06-07T08:24:06.782Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) rows_entry at ././mutation_partition.hh:939
[2021-06-07T08:24:06.782Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) rows_entry* allocation_strategy::construct<rows_entry, schema const&, clustering_key_prefix const&, deletable_row const&>(schema const&, clustering_key_prefix const&, deletable_row const&) at ././utils/allocation_strategy.hh:170
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ././cache_flat_mutation_reader.hh:495
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ././row_cache.hh:604
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _Z14with_allocatorIZZN5cache11lsa_manager36run_in_update_section_with_allocatorIZNS0_26cache_flat_mutation_reader18maybe_add_to_cacheERK14clustering_rowEUlvE_EEvOT_ENKUlvE_clEvEUlvE_EDcR19allocation_strategyS9_ at ././utils/allocation_strategy.hh:328
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ././row_cache.hh:603
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZN8logalloc18allocating_section24with_reclaiming_disabledIRZN5cache11lsa_manager36run_in_update_section_with_allocatorIZNS2_26cache_flat_mutation_reader18maybe_add_to_cacheERK14clustering_rowEUlvE_EEvOT_EUlvE_EEDcRNS_6regionESB_ at ././utils/logalloc.hh:757
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ././utils/logalloc.hh:779
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZN8logalloc18allocating_section12with_reserveIZNS0_clIZN5cache11lsa_manager36run_in_update_section_with_allocatorIZNS3_26cache_flat_mutation_reader18maybe_add_to_cacheERK14clustering_rowEUlvE_EEvOT_EUlvE_EEDcRNS_6regionESC_EUlvE_EEDcSC_ at ././utils/logalloc.hh:728
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZN8logalloc18allocating_sectionclIZN5cache11lsa_manager36run_in_update_section_with_allocatorIZNS2_26cache_flat_mutation_reader18maybe_add_to_cacheERK14clustering_rowEUlvE_EEvOT_EUlvE_EEDcRNS_6regionESB_ at ././utils/logalloc.hh:778
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) void cache::lsa_manager::run_in_update_section_with_allocator<cache::cache_flat_mutation_reader::maybe_add_to_cache(clustering_row const&)::{lambda()#1}>(cache::cache_flat_mutation_reader::maybe_add_to_cache(clustering_row const&)::{lambda()#1}&&) at ././row_cache.hh:602
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) cache::cache_flat_mutation_reader::maybe_add_to_cache(clustering_row const&) at ././cache_flat_mutation_reader.hh:487
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) cache::cache_flat_mutation_reader::maybe_add_to_cache(mutation_fragment const&) at ././cache_flat_mutation_reader.hh:474
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ././cache_flat_mutation_reader.hh:349
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ././flat_mutation_reader.hh:587
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::future<void> seastar::futurize<seastar::future<void> >::invoke<seastar::future<void> consume_mutation_fragments_until<cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda(mutation_fragment)#1}, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}>(flat_mutation_reader&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda(mutation_fragment)#1}&&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&>(flat_mutation_reader) at ././seastar/include/seastar/core/future.hh:2135
[2021-06-07T08:24:06.783Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) auto seastar::futurize_invoke<seastar::future<void> consume_mutation_fragments_until<cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda(mutation_fragment)#1}, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}>(flat_mutation_reader&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda(mutation_fragment)#1}&&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&>(flat_mutation_reader) at ././seastar/include/seastar/core/future.hh:2166
[2021-06-07T08:24:06.784Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) {lambda()#2} seastar::do_until<seastar::future<void> consume_mutation_fragments_until<cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda(mutation_fragment)#1}, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}>(flat_mutation_reader&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda(mutation_fragment)#1}&&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}, {lambda()#2} consume_mutation_fragments_until<{lambda()#1}, mutation_fragment, {lambda(mutation_fragment)#1}>(seastar::future, flat_mutation_reader, {lambda()#1}, mutation_fragment, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}>(flat_mutation_reader&, seastar::future<void>) at ././seastar/include/seastar/core/loop.hh:341
[2021-06-07T08:24:06.784Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> consume_mutation_fragments_until<cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda(mutation_fragment)#1}, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}>(flat_mutation_reader&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda(mutation_fragment)#1}&&, cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ././flat_mutation_reader.hh:585
[2021-06-07T08:24:06.784Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) cache::cache_flat_mutation_reader::read_from_underlying(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ././cache_flat_mutation_reader.hh:345
[2021-06-07T08:24:06.784Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ././cache_flat_mutation_reader.hh:305
[2021-06-07T08:24:06.784Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<seastar::future<void> >::invoke<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}>(cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&&) at ././seastar/include/seastar/core/future.hh:2135
[2021-06-07T08:24:06.784Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<seastar::future<void> >::invoke<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}>(cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&&, seastar::internal::monostate) at ././seastar/include/seastar/core/future.hh:1979
[2021-06-07T08:24:06.784Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::future<void>::then_impl<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}, seastar::future<void> >(cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&&) at ././seastar/include/seastar/core/future.hh:1601
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::internal::future_result<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}, void>::future_type seastar::internal::call_then_impl<seastar::future<void> >::run<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}>(seastar::future<void>&, seastar::internal::future_result&&) at ././seastar/include/seastar/core/future.hh:1234
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::future<void>::then<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}, seastar::future<void> >(cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}&&) at ././seastar/include/seastar/core/future.hh:1520
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ././cache_flat_mutation_reader.hh:304
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ././cache_flat_mutation_reader.hh:294
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<seastar::future<void> >::invoke<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}>(cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&&) at ././seastar/include/seastar/core/future.hh:2135
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<seastar::future<void> >::invoke<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}>(cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&&, seastar::internal::monostate) at ././seastar/include/seastar/core/future.hh:1979
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::future<void>::then_impl<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}, seastar::future<void> >(cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&&) at ././seastar/include/seastar/core/future.hh:1601
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::internal::future_result<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}, void>::future_type seastar::internal::call_then_impl<seastar::future<void> >::run<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}>(seastar::future<void>&, seastar::internal::future_result&&) at ././seastar/include/seastar/core/future.hh:1234
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::future<void>::then<cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}, seastar::future<void> >(cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&&) at ././seastar/include/seastar/core/future.hh:1520
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) cache::cache_flat_mutation_reader::do_fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ././cache_flat_mutation_reader.hh:293
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ././cache_flat_mutation_reader.hh:268
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<seastar::future<void> >::invoke<cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}&>(cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}&) at ././seastar/include/seastar/core/future.hh:2135
[2021-06-07T08:24:06.785Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) auto seastar::futurize_invoke<cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}&>(cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}&) at ././seastar/include/seastar/core/future.hh:2166
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::do_until<cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}, cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}>(cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}, cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}) at ././seastar/include/seastar/core/loop.hh:341
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ././cache_flat_mutation_reader.hh:267
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ././cache_flat_mutation_reader.hh:258
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > cache::cache_flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ././cache_flat_mutation_reader.hh:263
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > flat_mutation_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ././flat_mutation_reader.hh:423
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<bool> flat_mutation_reader::impl::fill_buffer_from<flat_mutation_reader>(flat_mutation_reader&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ./flat_mutation_reader.cc:233
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ./row_cache.cc:407
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<seastar::future<void> >::invoke<single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}&>(single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}&) at ././seastar/include/seastar/core/future.hh:2135
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) auto seastar::futurize_invoke<single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}&>(single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}&) at ././seastar/include/seastar/core/future.hh:2166
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::do_until<single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}, single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}>(single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#2}, single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#3}) at ././seastar/include/seastar/core/loop.hh:341
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ./row_cache.cc:406
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ./row_cache.cc:403
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> std::__invoke_impl<seastar::future<void>, single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&>(std::__invoke_other, single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:60
[2021-06-07T08:24:06.786Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::__invoke_result<single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&>::type std::__invoke<single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&>(std::__invoke_result&&, (single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&)...) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:95
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::invoke_result<single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&>::type std::invoke<single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&>(std::invoke_result&&, (single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&)...) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/functional:88
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) auto seastar::internal::future_invoke<single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&, seastar::internal::monostate>(single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}&, seastar::internal::monostate&&) at ././seastar/include/seastar/core/future.hh:1209
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ././seastar/include/seastar/core/future.hh:1582
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZN7seastar8futurizeINS_6futureIvEEE22satisfy_with_result_ofIZZNS2_14then_impl_nrvoIZN34single_partition_populating_reader11fill_bufferENSt6chrono10time_pointINS_12lowres_clockENS7_8durationIlSt5ratioILl1ELl1000EEEEEEEUlvE_S2_EET0_OT_ENKUlONS_8internal22promise_base_with_typeIvEERSF_ONS_12future_stateINSJ_9monostateEEEE_clESM_SN_SR_EUlvE_EEvSM_SI_ at ././seastar/include/seastar/core/future.hh:2120
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ././seastar/include/seastar/core/future.hh:1575
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::continuation<seastar::internal::promise_base_with_type<void>, single_partition_populating_reader::fill_buffer(std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::{lambda()#1}, seastar::future 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:767
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::reactor::run_tasks(seastar::reactor::task_queue&) at ./build/release/seastar/./seastar/src/core/reactor.cc:2228
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::reactor::run_some_tasks() at ./build/release/seastar/./seastar/src/core/reactor.cc:2637
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::reactor::run() at ./build/release/seastar/./seastar/src/core/reactor.cc:2796
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ./build/release/seastar/./seastar/src/core/reactor.cc:3992
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) void std::__invoke_impl<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&>(std::__invoke_other, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:60
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::enable_if<is_invocable_r_v<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&>, void>::type std::__invoke_r<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&>(seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:110
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::_Function_handler<void (), seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97>::_M_invoke(std::_Any_data const&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/std_function.h:291
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > std::function<void ()>::operator()() const at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/std_function.h:622
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::posix_thread::start_routine(void*) at ./build/release/seastar/./seastar/src/core/posix.cc:60
[2021-06-07T08:24:06.787Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > ?? ??:0
[2021-06-07T08:24:06.788Z] < t:2021-06-07 08:23:59,921 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > ?? ??:0
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > 2021-06-07 08:14:17.000: (DatabaseLogEvent Severity.DEBUG): type=REACTOR_STALLED regex=Reactor stalled line_number=11764 node=Node longevity-100gb-4h-rbno-db-node-b293bf81-11 [18.215.126.117 | 10.0.2.15] (seed: False)
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > 2021-06-07T08:14:17+00:00  longevity-100gb-4h-rbno-db-node-b293bf81-11 !INFO    | scylla: Reactor stalled for 189 ms on shard 5. Backtrace: 0x40e1204 0x40e0541 0x40e10cf 0x7fcda136b1df 0x13ac87f 0x13b3d78 0x120302e 0x1202f1a 0x14c111b 0x14a8514 0x1342f5c 0x11336de 0x1077d7e 0x107b1d9 0x101ee1b 0x10b6c7a 0x10e3d9c 0x109062b 0x409cd85 0x40f415f 0x40f53e7 0x411321b 0x40bf92a 0x93f8 0x101902
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > void seastar::backtrace<seastar::backtrace_buffer::append_backtrace_oneline()::{lambda(seastar::frame)#1}>(seastar::backtrace_buffer::append_backtrace_oneline()::{lambda(seastar::frame)#1}&&) at ./build/release/seastar/./seastar/include/seastar/util/backtrace.hh:59
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::backtrace_buffer::append_backtrace_oneline() at ./build/release/seastar/./seastar/src/core/reactor.cc:768
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::print_with_backtrace(seastar::backtrace_buffer&, bool) at ./build/release/seastar/./seastar/src/core/reactor.cc:787
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::internal::cpu_stall_detector::generate_trace() at ./build/release/seastar/./seastar/src/core/reactor.cc:1219
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::internal::cpu_stall_detector::maybe_report() at ./build/release/seastar/./seastar/src/core/reactor.cc:1100
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1114
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1202
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > ?? ??:0
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > logalloc::region_impl::object_descriptor::encode(char*&, unsigned long) const at ./utils/logalloc.cc:1184
[2021-06-07T08:24:21.779Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) logalloc::region_impl::alloc_small(logalloc::region_impl::object_descriptor const&, unsigned int, unsigned long) at ./utils/logalloc.cc:1293
[2021-06-07T08:24:21.780Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > logalloc::region_impl::alloc(migrate_fn_type const*, unsigned long, unsigned long) at ./utils/logalloc.cc:1515
[2021-06-07T08:24:21.780Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > void* allocation_strategy::alloc<blob_storage>(unsigned long) at ././utils/allocation_strategy.hh:147
[2021-06-07T08:24:21.780Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) managed_bytes at ././utils/managed_bytes.hh:153
[2021-06-07T08:24:21.780Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) managed_bytes atomic_cell_type::make_live<ser::buffer_view<bytes_ostream::fragment_iterator> >(long, ser::buffer_view<bytes_ostream::fragment_iterator> const&) at ././atomic_cell.hh:168
[2021-06-07T08:24:21.780Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > atomic_cell::make_live(abstract_type const&, long, ser::buffer_view<bytes_ostream::fragment_iterator>, seastar::bool_class<atomic_cell::collection_member_tag>) at ./atomic_cell.cc:40
[2021-06-07T08:24:21.780Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ./mutation_partition_view.cc:71
[2021-06-07T08:24:21.780Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZN5boost6detail7variant14invoke_visitorIKZN12_GLOBAL__N_116read_atomic_cellERK13abstract_typeNS_7variantIN3ser14live_cell_viewEJNS8_18expiring_cell_viewENS8_14dead_cell_viewENS8_17counter_cell_viewENS8_20unknown_variant_typeEEEEN7seastar10bool_classIN11atomic_cell21collection_member_tagEEEE19atomic_cell_visitorLb0EE14internal_visitIRS9_EENS_12disable_if_cIXaaLb0Esr7is_sameIT_SQ_EE5valueESH_E4typeEOSQ_i at /usr/include/boost/variant/variant.hpp:1028
[2021-06-07T08:24:21.780Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>::result_type boost::detail::variant::visitation_impl_invoke_impl<boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>, void*, ser::live_cell_view>(int, boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>&, void*, ser::live_cell_view*, mpl_::bool_<true>) at /usr/include/boost/variant/detail/visitation_impl.hpp:117
[2021-06-07T08:24:21.780Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>::result_type boost::detail::variant::visitation_impl_invoke<boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>, void*, ser::live_cell_view, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>::has_fallback_type_>(int, boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>&, void*, ser::live_cell_view*, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>::has_fallback_type_, int) at /usr/include/boost/variant/detail/visitation_impl.hpp:157
[2021-06-07T08:24:21.781Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>::result_type boost::detail::variant::visitation_impl<mpl_::int_<0>, boost::detail::variant::visitation_impl_step<boost::mpl::l_iter<boost::mpl::l_item<mpl_::long_<5l>, ser::live_cell_view, boost::mpl::l_item<mpl_::long_<4l>, ser::expiring_cell_view, boost::mpl::l_item<mpl_::long_<3l>, ser::dead_cell_view, boost::mpl::l_item<mpl_::long_<2l>, ser::counter_cell_view, boost::mpl::l_item<mpl_::long_<1l>, ser::unknown_variant_type, boost::mpl::l_end> > > > > >, boost::mpl::l_iter<boost::mpl::l_end> >, boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>, void*, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>::has_fallback_type_>(int, int, boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>&, void*, mpl_::bool_<false>, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>::has_fallback_type_, mpl_::int_<0>*, boost::detail::variant::visitation_impl_step<boost::mpl::l_iter<boost::mpl::l_item<mpl_::long_<5l>, ser::live_cell_view, boost::mpl::l_item<mpl_::long_<4l>, ser::expiring_cell_view, boost::mpl::l_item<mpl_::long_<3l>, ser::dead_cell_view, boost::mpl::l_item<mpl_::long_<2l>, ser::counter_cell_view, boost::mpl::l_item<mpl_::long_<1l>, ser::unknown_variant_type, boost::mpl::l_end> > > > > >, boost::mpl::l_iter<boost::mpl::l_end> >*) at /usr/include/boost/variant/detail/visitation_impl.hpp:238
[2021-06-07T08:24:21.781Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>::result_type boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>::internal_apply_visitor_impl<boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>, void*>(int, int, boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>&, void*) at /usr/include/boost/variant/variant.hpp:2337
[2021-06-07T08:24:21.781Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>::result_type boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>::internal_apply_visitor<boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false> >(boost::detail::variant::invoke_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const, false>&) at /usr/include/boost/variant/variant.hpp:2349
[2021-06-07T08:24:21.781Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) (anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const::result_type boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>::apply_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const>((anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const&) & at /usr/include/boost/variant/variant.hpp:2393
[2021-06-07T08:24:21.782Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > (anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor::result_type boost::apply_visitor<(anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>&>((anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>)::atomic_cell_visitor const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>&) at /usr/include/boost/variant/detail/apply_visitor_unary.hpp:68
[2021-06-07T08:24:21.782Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) (anonymous namespace)::read_atomic_cell(abstract_type const&, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, seastar::bool_class<atomic_cell::collection_member_tag>) at ./mutation_partition_view.cc:109
[2021-06-07T08:24:21.782Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ./mutation_partition_view.cc:162
[2021-06-07T08:24:21.782Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZN5boost6detail7variant14invoke_visitorIKZN12_GLOBAL__N_118read_and_visit_rowIZNK23mutation_partition_view9do_acceptI17partition_builderEEvRK14column_mappingRT_E12cell_visitorEEvN3ser8row_viewESA_11column_kindOSB_E33atomic_cell_or_collection_visitorLb0EE14internal_visitIRNS_7variantINSE_14live_cell_viewEJNSE_18expiring_cell_viewENSE_14dead_cell_viewENSE_17counter_cell_viewENSE_20unknown_variant_typeEEEEEENS_12disable_if_cIXaaLb0Esr7is_sameISB_SB_EE5valueEvE4typeESH_i at /usr/include/boost/variant/variant.hpp:1028
[2021-06-07T08:24:21.782Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor&&)::atomic_cell_or_collection_visitor const, false>::result_type boost::detail::variant::visitation_impl_invoke_impl<boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&)::atomic_cell_or_collection_visitor const, false>, void*, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type> >(int, partition_builder&, void*, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>*, mpl_::bool_<true>) at /usr/include/boost/variant/detail/visitation_impl.hpp:117
[2021-06-07T08:24:21.782Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor&&)::atomic_cell_or_collection_visitor const, false>::result_type boost::detail::variant::visitation_impl_invoke<boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&)::atomic_cell_or_collection_visitor const, false>, void*, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, boost::variant<boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, ser::collection_cell_view, ser::unknown_variant_type>::has_fallback_type_>(int, partition_builder&, void*, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>*, boost::variant<boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, ser::collection_cell_view, ser::unknown_variant_type>::has_fallback_type_, int) at /usr/include/boost/variant/detail/visitation_impl.hpp:157
[2021-06-07T08:24:21.783Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&)::atomic_cell_or_collection_visitor const, false>::result_type boost::detail::variant::visitation_impl<mpl_::int_<0>, boost::detail::variant::visitation_impl_step<boost::mpl::l_iter<boost::mpl::l_item<mpl_::long_<3l>, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, boost::mpl::l_item<mpl_::long_<2l>, ser::collection_cell_view, boost::mpl::l_item<mpl_::long_<1l>, ser::unknown_variant_type, boost::mpl::l_end> > > >, boost::mpl::l_iter<boost::mpl::l_end> >, boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&)::atomic_cell_or_collection_visitor const, false>, void*, boost::variant<boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, ser::collection_cell_view, ser::unknown_variant_type>::has_fallback_type_>(int, int, boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&)::atomic_cell_or_collection_visitor const, false>&, void*, mpl_::bool_<false>, boost::variant<boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, ser::collection_cell_view, ser::unknown_variant_type>::has_fallback_type_, mpl_::int_<0>*, boost::detail::variant::visitation_impl_step<boost::mpl::l_iter<boost::mpl::l_item<mpl_::long_<3l>, boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, boost::mpl::l_item<mpl_::long_<2l>, ser::collection_cell_view, boost::mpl::l_item<mpl_::long_<1l>, ser::unknown_variant_type, boost::mpl::l_end> > > >, boost::mpl::l_iter<boost::mpl::l_end> >*) at /usr/include/boost/variant/detail/visitation_impl.hpp:238
[2021-06-07T08:24:21.783Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor&&)::atomic_cell_or_collection_visitor const, false>::result_type boost::variant<boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, ser::collection_cell_view, ser::unknown_variant_type>::internal_apply_visitor_impl<boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&)::atomic_cell_or_collection_visitor const, false>, void*>(int, int, partition_builder&, void*) at /usr/include/boost/variant/variant.hpp:2337
[2021-06-07T08:24:21.783Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor&&)::atomic_cell_or_collection_visitor const, false>::result_type boost::variant<boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, ser::collection_cell_view, ser::unknown_variant_type>::internal_apply_visitor<boost::detail::variant::invoke_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&)::atomic_cell_or_collection_visitor const, false> >(partition_builder&) at /usr/include/boost/variant/variant.hpp:2349
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor&&)::atomic_cell_or_collection_visitor const::result_type boost::variant<boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, ser::collection_cell_view, ser::unknown_variant_type>::apply_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&)::atomic_cell_or_collection_visitor const>(partition_builder&) & at /usr/include/boost/variant/variant.hpp:2393
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor&&)::atomic_cell_or_collection_visitor::result_type boost::apply_visitor<void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&)::atomic_cell_or_collection_visitor, boost::variant<boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, ser::collection_cell_view, ser::unknown_variant_type>&>(void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor&&)::atomic_cell_or_collection_visitor const&, boost::variant<boost::variant<ser::live_cell_view, ser::expiring_cell_view, ser::dead_cell_view, ser::counter_cell_view, ser::unknown_variant_type>, ser::collection_cell_view, ser::unknown_variant_type>&) at /usr/include/boost/variant/detail/apply_visitor_unary.hpp:68
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) void (anonymous namespace)::read_and_visit_row<void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const::cell_visitor>(ser::row_view, column_mapping const&, column_kind, partition_builder&&) at ./mutation_partition_view.cc:182
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) void mutation_partition_view::do_accept<partition_builder>(column_mapping const&, partition_builder&) const at ./mutation_partition_view.cc:248
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ./memtable.cc:753
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZN8logalloc18allocating_section24with_reclaiming_disabledIRZZN8memtable5applyERK15frozen_mutationRKN7seastar13lw_shared_ptrIK6schemaEEON2db9rp_handleEENK3$_8clEvEUlvE_EEDcRNS_6regionEOT_ at ././utils/logalloc.hh:757
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ././utils/logalloc.hh:779
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZN8logalloc18allocating_section12with_reserveIZNS0_clIZZN8memtable5applyERK15frozen_mutationRKN7seastar13lw_shared_ptrIK6schemaEEON2db9rp_handleEENK3$_8clEvEUlvE_EEDcRNS_6regionEOT_EUlvE_EEDcSM_ at ././utils/logalloc.hh:728
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZN8logalloc18allocating_sectionclIZZN8memtable5applyERK15frozen_mutationRKN7seastar13lw_shared_ptrIK6schemaEEON2db9rp_handleEENK3$_8clEvEUlvE_EEDcRNS_6regionEOT_ at ././utils/logalloc.hh:778
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ./memtable.cc:749
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _Z14with_allocatorIZN8memtable5applyERK15frozen_mutationRKN7seastar13lw_shared_ptrIK6schemaEEON2db9rp_handleEE3$_8EDcR19allocation_strategyOT_ at ././utils/allocation_strategy.hh:328
[2021-06-07T08:24:21.784Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) memtable::apply(frozen_mutation const&, seastar::lw_shared_ptr<schema const> const&, db::rp_handle&&) at ./memtable.cc:748
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > void table::do_apply<frozen_mutation const&, seastar::lw_shared_ptr<schema const> const&>(db::rp_handle&&, frozen_mutation const&, seastar::lw_shared_ptr<schema const> const&) at ./table.cc:1856
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) table::apply(frozen_mutation const&, seastar::lw_shared_ptr<schema const> const&, db::rp_handle&&) at ./table.cc:1875
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ./database.cc:1734
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<void>::invoke<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, 1000l> > >)::$_56&>(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, 1000l> > >)::$_56&) at ././seastar/include/seastar/core/future.hh:2132
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) auto seastar::futurize_invoke<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, 1000l> > >)::$_56&>(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, 1000l> > >)::$_56&) at ././seastar/include/seastar/core/future.hh:2166
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::futurize<std::result_of<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, 1000l> > >)::$_56 ()>::type>::type logalloc::region_group::run_when_memory_available<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, 1000l> > >)::$_56>(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, 1000l> > >)::$_56&&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >) at ././utils/logalloc.hh:350
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) 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, 1000l> > >) at ./database.cc:1733
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ./database.cc:1793
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<seastar::future<void> >::invoke<database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>)::$_61, db::rp_handle>(database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>)::$_61&&, db::rp_handle&&) at ././seastar/include/seastar/core/future.hh:2135
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::future<db::rp_handle>::then_impl<database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>)::$_61, seastar::future<void> >(database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>)::$_61&&) at ././seastar/include/seastar/core/future.hh:1601
[2021-06-07T08:24:21.785Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::internal::future_result<database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>)::$_61, db::rp_handle>::future_type seastar::internal::call_then_impl<seastar::future<db::rp_handle> >::run<database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>)::$_61>(seastar::future<db::rp_handle>&, database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>)::$_61&&) at ././seastar/include/seastar/core/future.hh:1234
[2021-06-07T08:24:21.786Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::future<db::rp_handle>::then<database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>)::$_61, seastar::future<void> >(database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>)::$_61&&) at ././seastar/include/seastar/core/future.hh:1520
[2021-06-07T08:24:21.786Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) database::apply_with_commitlog(seastar::lw_shared_ptr<schema const>, table&, utils::UUID, frozen_mutation const&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, seastar::bool_class<force_sync_tag>) at ./database.cc:1792
[2021-06-07T08:24:21.786Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > database::do_apply(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, 1000l> > >, seastar::bool_class<force_sync_tag>) at ./database.cc:1816
[2021-06-07T08:24:21.786Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::future<void> std::__invoke_impl<seastar::future<void>, seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>), 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, 1000l> > >, seastar::bool_class<force_sync_tag> >(std::__invoke_memfun_deref, seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>), 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, 1000l> > >&&, seastar::bool_class<force_sync_tag>&&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:73
[2021-06-07T08:24:21.786Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::__invoke_result<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>), 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, 1000l> > >, seastar::bool_class<force_sync_tag> >::type std::__invoke<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>), 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, 1000l> > >, seastar::bool_class<force_sync_tag> >(seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>), 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, 1000l> > >&&, seastar::bool_class<force_sync_tag>&&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:95
[2021-06-07T08:24:21.786Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZNKSt12_Mem_fn_baseIM8databaseFN7seastar6futureIvEENS1_13lw_shared_ptrIK6schemaEERK15frozen_mutationN7tracing15trace_state_ptrENSt6chrono10time_pointINS1_12lowres_clockENSD_8durationIlSt5ratioILl1ELl1000EEEEEENS1_10bool_classI14force_sync_tagEEELb1EEclIJPS0_S7_SA_SC_SK_SN_EEEDTclsr3stdE8__invokedtdefpT6_M_pmfspclsr3stdE7forwardIT_Efp_EEEDpOST_ at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/functional:122
[2021-06-07T08:24:21.787Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>::direct_vtable_for<std::_Mem_fn<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)> >::call(seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)> const*, 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, 1000l> > >, seastar::bool_class<force_sync_tag>) at ././seastar/include/seastar/util/noncopyable_function.hh:124
[2021-06-07T08:24:21.787Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>::operator()(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, 1000l> > >, seastar::bool_class<force_sync_tag>) const at ././seastar/include/seastar/util/noncopyable_function.hh:209
[2021-06-07T08:24:21.787Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) operator() at ././seastar/include/seastar/core/execution_stage.hh:339
[2021-06-07T08:24:21.787Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>::direct_vtable_for<seastar::inheriting_concrete_execution_stage<seastar::future<void>, 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, 1000l> > >, seastar::bool_class<force_sync_tag> >::make_stage_for_group(seastar::scheduling_group)::{lambda(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, 1000l> > >, seastar::bool_class<force_sync_tag>)#1}>::call(seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)> const*, 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, 1000l> > >, seastar::bool_class<force_sync_tag>) at ././seastar/include/seastar/util/noncopyable_function.hh:124
[2021-06-07T08:24:21.787Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>::operator()(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, 1000l> > >, seastar::bool_class<force_sync_tag>) const at ././seastar/include/seastar/util/noncopyable_function.hh:209
[2021-06-07T08:24:21.787Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> std::__invoke_impl<seastar::future<void>, seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>&, 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, 1000l> > >, seastar::bool_class<force_sync_tag> >(std::__invoke_other, seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>&, 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, 1000l> > >&&, seastar::bool_class<force_sync_tag>&&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:60
[2021-06-07T08:24:21.788Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::__invoke_result<seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>&, 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, 1000l> > >, seastar::bool_class<force_sync_tag> >::type std::__invoke<seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>&, 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, 1000l> > >, seastar::bool_class<force_sync_tag> >(seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>&, 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, 1000l> > >&&, seastar::bool_class<force_sync_tag>&&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:95
[2021-06-07T08:24:21.788Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZSt12__apply_implIRN7seastar20noncopyable_functionIFNS0_6futureIvEEP8databaseNS0_13lw_shared_ptrIK6schemaEERK15frozen_mutationN7tracing15trace_state_ptrENSt6chrono10time_pointINS0_12lowres_clockENSF_8durationIlSt5ratioILl1ELl1000EEEEEENS0_10bool_classI14force_sync_tagEEEEESt5tupleIJS5_S9_SC_SE_SM_SP_EEJLm0ELm1ELm2ELm3ELm4ELm5EEEDcOT_OT0_St16integer_sequenceImJXspT1_EEE at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/tuple:1723
[2021-06-07T08:24:21.788Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) _ZSt5applyIRN7seastar20noncopyable_functionIFNS0_6futureIvEEP8databaseNS0_13lw_shared_ptrIK6schemaEERK15frozen_mutationN7tracing15trace_state_ptrENSt6chrono10time_pointINS0_12lowres_clockENSF_8durationIlSt5ratioILl1ELl1000EEEEEENS0_10bool_classI14force_sync_tagEEEEESt5tupleIJS5_S9_SC_SE_SM_SP_EEEDcOT_OT0_ at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/tuple:1734
[2021-06-07T08:24:21.788Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<seastar::future<void> >::apply<seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>&, 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, 1000l> > >, seastar::bool_class<force_sync_tag> >(seastar::noncopyable_function<seastar::future<void> (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, 1000l> > >, seastar::bool_class<force_sync_tag>)>&, std::tuple<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, 1000l> > >, seastar::bool_class<force_sync_tag> >&&) at ././seastar/include/seastar/core/future.hh:2102
[2021-06-07T08:24:21.788Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::concrete_execution_stage<seastar::future<void>, 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, 1000l> > >, seastar::bool_class<force_sync_tag> >::do_flush() at ././seastar/include/seastar/core/execution_stage.hh:248
[2021-06-07T08:24:21.788Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ./build/release/seastar/./seastar/src/core/execution_stage.cc:141
[2021-06-07T08:24:21.788Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::future<void> seastar::futurize<void>::invoke<seastar::execution_stage::flush()::$_5&>(seastar::execution_stage::flush()::$_5&) at ./build/release/seastar/./seastar/include/seastar/core/future.hh:2132
[2021-06-07T08:24:21.788Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::lambda_task<seastar::execution_stage::flush()::$_5>::run_and_dispose() at ./build/release/seastar/./seastar/include/seastar/core/make_task.hh:40
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::reactor::run_tasks(seastar::reactor::task_queue&) at ./build/release/seastar/./seastar/src/core/reactor.cc:2228
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::reactor::run_some_tasks() at ./build/release/seastar/./seastar/src/core/reactor.cc:2637
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > seastar::reactor::run() at ./build/release/seastar/./seastar/src/core/reactor.cc:2796
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > operator() at ./build/release/seastar/./seastar/src/core/reactor.cc:3992
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) void std::__invoke_impl<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&>(std::__invoke_other, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:60
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::enable_if<is_invocable_r_v<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&>, void>::type std::__invoke_r<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&>(seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/invoke.h:110
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) std::_Function_handler<void (), seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_97>::_M_invoke(std::_Any_data const&) at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/std_function.h:291
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > std::function<void ()>::operator()() const at /usr/lib/gcc/x86_64-redhat-linux/10/../../../../include/c++/10/bits/std_function.h:622
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  >  (inlined by) seastar::posix_thread::start_routine(void*) at ./build/release/seastar/./seastar/src/core/posix.cc:60
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > ?? ??:0
[2021-06-07T08:24:21.789Z] < t:2021-06-07 08:24:20,873 f:file_logger.py  l:80   c:sdcm.sct_events.file_logger p:INFO  > ?? ??:0
@asias
Copy link
Contributor Author

asias commented Jun 9, 2021

@avikivity FYI

@avikivity
Copy link
Member

In both cases it doesn't look like an allocator problem, instead a large row/cell problem. The code is stalling while copying large amounts of data, but there's no indication the allocator is slow.

@avikivity
Copy link
Member

@michoecho please take a look

@michoecho
Copy link
Contributor

Looking.

@michoecho michoecho self-assigned this Jun 9, 2021
@michoecho
Copy link
Contributor

I can't figure anything out. It's just as @avikivity says: all the 4 stalls in the log happen in managed_bytes, but there is no visible indication that the problem is with the allocator.
1 of those stalls is reported in the move constructor of managed_bytes (which happens after everything is already allocated).
The other 3 are reported in object_descriptor::encode, all 3 on exactly the same instruction. This is extremely weird because that instruction should be happening exactly once per allocation. I have no idea what's going on.

@michoecho michoecho removed their assignment Jun 9, 2021
@avikivity
Copy link
Member

I have some vague memory of seeing object_descriptor::encode in other places too.

Maybe it's some kind of artifact, like we're swapping and this write causes the page to be swapped in.

@avikivity
Copy link
Member

I see that scylla_setup calls scylla_memory_setup --lock-memory, but maybe s-c-t uses a custom script that bypasses that.

@avikivity
Copy link
Member

@fgelcer how does s-c-t setup nodes? maybe it's really a question for the machine image.

@michoecho
Copy link
Contributor

Right, object_descriptor::encode should be the first memory access to newly allocated segments. Swapping huge pages would explain this.

@michoecho
Copy link
Contributor

Except that 4th stall doesn't quite match the theory. It happens a bit later than object_descriptor::encode. I'm not sure what's the timing interaction between stall detector (posix timers?) and page faults in linux. Since 3 stalls happen on exactly the same instruction, it would seem that linux checks the timer (and possibly triggers a signal) when scheduling the process. But then why didn't the signal happen immediately in the 4th case, but after a short delay?

@avikivity
Copy link
Member

It cannot be a swap-in from disk since we use CLOCK_THREAD_CPUTIME_ID for the timer (see cpu_stall_detector::cpu_stall_detector()). Swapping in takes real time, not CPU time.

It could kernel compaction/zeroing (that can happen in the thread that's faulting).

As for the delays, here's an explanation:

  1. the stall detector sets a timer for 5ms (@fgelcer what's the stall detector threshold on this run?)
  2. the kernel spends 100ms zeroing a page (impossible)
  3. while that's happening, the timer fires, but the signal can't be delivered while the page fault is being serviced
  4. the page fault completes, signal is delivered. This explains why we didn't see 5ms/10ms/20ms/40ms doublings as usual
  5. the stall is reported, and the timer is doubled to 10ms
  6. the new threshold expires, and is caught a little later and reported.

I don't believe this, it doesn't completely fit the reports. The non-encode() stall is on shard 8, the same shard as an encode stall, but at different times. Are the reported times correct (e.g. scylla time or parse time)? And why would allocating and zeroing a page, even a large page, take so much time? Why would there even be problems? We start a fresh machine with all its memory free.

@fgelcer
Copy link

fgelcer commented Jun 9, 2021

@fgelcer how does s-c-t setup nodes? maybe it's really a question for the machine image.

SCT first has a definition of the instance type, then, it sends a post boot script through API to run before we even have access to it, and then we configure the scylla.yaml with the values set in the test...
so yes, probably what you are looking for is coming from machine image

if you need exact parameters we send to these post boot scripts, and scylla.yaml i can add them here

@avikivity
Copy link
Member

I need the contents of /etc/sysconfig/scylla-server (the SCYLLA_ARGS stuff)

@fgelcer
Copy link

fgelcer commented Jun 9, 2021

It cannot be a swap-in from disk since we use CLOCK_THREAD_CPUTIME_ID for the timer (see cpu_stall_detector::cpu_stall_detector()). Swapping in takes real time, not CPU time.

It could kernel compaction/zeroing (that can happen in the thread that's faulting).

As for the delays, here's an explanation:

  1. the stall detector sets a timer for 5ms (@fgelcer what's the stall detector threshold on this run?)

this test has --blocked-reactor-notify-ms 100 (this is the default to all SCT tests, but performance ones, that are 5 ms)

  1. the kernel spends 100ms zeroing a page (impossible)
  2. while that's happening, the timer fires, but the signal can't be delivered while the page fault is being serviced
  3. the page fault completes, signal is delivered. This explains why we didn't see 5ms/10ms/20ms/40ms doublings as usual
  4. the stall is reported, and the timer is doubled to 10ms
  5. the new threshold expires, and is caught a little later and reported.

I don't believe this, it doesn't completely fit the reports. The non-encode() stall is on shard 8, the same shard as an encode stall, but at different times. Are the reported times correct (e.g. scylla time or parse time)? And why would allocating and zeroing a page, even a large page, take so much time? Why would there even be problems? We start a fresh machine with all its memory free.

@fgelcer
Copy link

fgelcer commented Jun 9, 2021

I need the contents of /etc/sysconfig/scylla-server (the SCYLLA_ARGS stuff)

Command "sudo sed -i '/--blocked-reactor-notify-ms 100 --abort-on-lsa-bad-alloc 1 --abort-on-seastar-bad-alloc --abort-on-internal-error 1 --abort-on-ebadf 1 --enable-sstable-key-validation 1 --enable-repair-based-node-ops 1/! s/SCYLLA_ARGS="/&--blocked-reactor-notify-ms 100 --abort-on-lsa-bad-alloc 1 --abort-on-seastar-bad-alloc --abort-on-internal-error 1 --abort-on-ebadf 1 --enable-sstable-key-validation 1 --enable-repair-based-node-ops 1 /' /etc/sysconfig/scylla-server" finished with status 0

@fgelcer
Copy link

fgelcer commented Jun 9, 2021

grep "^SCYLLA_ARGS=" /etc/sysconfig/scylla-server"
SCYLLA_ARGS="--blocked-reactor-notify-ms 100 --abort-on-lsa-bad-alloc 1 --abort-on-seastar-bad-alloc --abort-on-internal-error 1 --abort-on-ebadf 1 --enable-sstable-key-validation 1 --enable-repair-based-node-ops 1 --log-to-syslog 1 --log-to-stdout 0 --default-log-level info --network-stack posix"

@slivne
Copy link
Contributor

slivne commented Jun 15, 2021

@fgelcer

  • I think its a separate file used for memory - search for memory.conf under /etc/scylla / etc.scylla.d

@slivne slivne added this to the 4.7 milestone Jun 15, 2021
@fgelcer
Copy link

fgelcer commented Jun 15, 2021

@fgelcer

  • I think its a separate file used for memory - search for memory.conf under /etc/scylla / etc.scylla.d

that specific job doesn't exist anymore and AFAICT we don't collect /etc/scylla.d/memory.conf (maybe we do, i will check it), but here is the content of /etc/scylla.d/memory.conf from another job (a DB node that is alive, running a longevity):

MEM_CONF="--lock-memory=1"

@fgelcer
Copy link

fgelcer commented Jun 15, 2021

@slivne , also, the content of the /etc/scylla.d/memory.conf is printed in the sct.logs:

< t:2021-06-07 05:39:04,270 f:base.py         l:220  c:RemoteCmdRunner      p:DEBUG >   --lock-memory arg                     lock all memory (prevents swapping)
< t:2021-06-07 05:39:14,500 f:cluster.py      l:1509 c:sdcm.cluster         p:DEBUG > 2021-06-07T05:39:07+00:00  longevity-100gb-4h-rbno-db-node-b293bf81-1 !INFO    | scylla: command used: "/usr/bin/scylla --blocked-reactor-notify-ms 100 --abort-on-lsa-bad-alloc 1 --abort-on-seastar-bad-alloc --abort-on-internal-error 1 --abort-on-ebadf 1 --enable-sstable-key-validation 1 --enable-repair-based-node-ops 1 --log-to-syslog 1 --log-to-stdout 0 --default-log-level info --network-stack posix --io-properties-file=/etc/scylla.d/io_properties.yaml --cpuset 1-7,9-15 --lock-memory=1"

@fgelcer
Copy link

fgelcer commented Jun 15, 2021

@slivne , also, the content of the /etc/scylla.d/memory.conf is printed in the sct.logs:

< t:2021-06-07 05:39:04,270 f:base.py         l:220  c:RemoteCmdRunner      p:DEBUG >   --lock-memory arg                     lock all memory (prevents swapping)
< t:2021-06-07 05:39:14,500 f:cluster.py      l:1509 c:sdcm.cluster         p:DEBUG > 2021-06-07T05:39:07+00:00  longevity-100gb-4h-rbno-db-node-b293bf81-1 !INFO    | scylla: command used: "/usr/bin/scylla --blocked-reactor-notify-ms 100 --abort-on-lsa-bad-alloc 1 --abort-on-seastar-bad-alloc --abort-on-internal-error 1 --abort-on-ebadf 1 --enable-sstable-key-validation 1 --enable-repair-based-node-ops 1 --log-to-syslog 1 --log-to-stdout 0 --default-log-level info --network-stack posix --io-properties-file=/etc/scylla.d/io_properties.yaml --cpuset 1-7,9-15 --lock-memory=1"

this is from the job @asias reported the issue...

@avikivity
Copy link
Member

Well, I didn't believe in the theory anyway. But now I have no other idea about what could have gone wrong.

@fruch
Copy link
Contributor

fruch commented Apr 18, 2023

Indeed I didn't find the balloon pci device on an n2 instance.

the specific reported instance is n1-highmem-8

@avikivity
Copy link
Member

Yes, so it's not the balloon

@aleksbykov
Copy link
Contributor

It again happened one time on centos rolling upgrade:
db: https://cloudius-jenkins-test.s3.amazonaws.com/5cd4dd3f-4665-410a-bc6d-ea82bb6f714e/20230613_000908/db-cluster-5cd4dd3f.tar.gz
was detected only 1 time Reactor stall 788ms on node4 and now any kernel traces

@fgelcer
Copy link

fgelcer commented Jun 15, 2023

Issue description

during rolling upgrade job, before we started to upgrade the 1st node:

2023-05-18 04:00:10.158 <2023-05-18 04:00:10.000>: (DatabaseLogEvent Severity.ERROR) period_type=one-time event_id=e47d8ed6-39d3-4bcc-8ff9-232111dd6cb6: type=REACTOR_STALLED regex=Reactor stalled line_number=29999 node=rolling-upgrade--centos-8-db-node-eab2674a-0-1
2023-05-18T04:00:10+00:00 rolling-upgrade--centos-8-db-node-eab2674a-0-1     !INFO | scylla[69055]: Reactor stalled for 1011 ms on shard 2. Backtrace: 0x46b5822 0x46b44d0 0x46b5730 0x7f6969163a1f 0x159bcd4 0x15a5377 0x148cb0b 0x148e72f 0x1486a0c 0x1484d83 0x14ff702 0x4936381
void seastar::backtrace<seastar::backtrace_buffer::append_backtrace_oneline()::{lambda(seastar::frame)#1}>(seastar::backtrace_buffer::append_backtrace_oneline()::{lambda(seastar::frame)#1}&&) 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:764
(inlined by) seastar::print_with_backtrace(seastar::backtrace_buffer&, bool) at ./build/release/seastar/./seastar/src/core/reactor.cc:783
seastar::internal::cpu_stall_detector::generate_trace() at ./build/release/seastar/./seastar/src/core/reactor.cc:1358
seastar::internal::cpu_stall_detector::maybe_report() at ./build/release/seastar/./seastar/src/core/reactor.cc:1100
(inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1117
(inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1341
?? ??:0
utils::uleb64_express_encode_impl(char*&, unsigned long, unsigned long) at ././utils/vle.hh:73
(inlined by) void utils::uleb64_express_encode<void (&)(char const*, unsigned long), void (&)(char const*, unsigned long)>(char*&, unsigned int, unsigned long, unsigned long, void (&)(char const*, unsigned long), void (&)(char const*, unsigned long)) at ././utils/vle.hh:82
(inlined by) logalloc::region_impl::object_descriptor::encode(char*&, unsigned long, unsigned long) const at ./utils/logalloc.cc:1222
(inlined by) logalloc::region_impl::alloc_small(logalloc::region_impl::object_descriptor const&, unsigned int, unsigned long) at ./utils/logalloc.cc:1309
logalloc::region_impl::alloc(migrate_fn_type const*, unsigned long, unsigned long) at ./utils/logalloc.cc:1655
void* allocation_strategy::alloc<intrusive_b::node<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0> >(unsigned long) at ././utils/allocation_strategy.hh:134
(inlined by) intrusive_b::node<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>* intrusive_b::node<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::construct<unsigned long&, intrusive_b::node<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0> >(unsigned long, unsigned long&, intrusive_b::node<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>&&) at ././utils/intrusive_btree.hh:1346
(inlined by) intrusive_b::node<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::check_linear_capacity(unsigned long&) at ././utils/intrusive_btree.hh:1556
intrusive_b::tree<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::iterator intrusive_b::tree<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::cursor::insert<std::unique_ptr<rows_entry, alloc_strategy_deleter<rows_entry> > >(std::unique_ptr<rows_entry, alloc_strategy_deleter<rows_entry> >) at ././utils/intrusive_btree.hh:251
(inlined by) intrusive_b::tree<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::iterator intrusive_b::tree<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::iterator::insert_before<std::unique_ptr<rows_entry, alloc_strategy_deleter<rows_entry> > >(std::unique_ptr<rows_entry, alloc_strategy_deleter<rows_entry> >) at ././utils/intrusive_btree.hh:933
intrusive_b::tree<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::iterator intrusive_b::tree<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::insert_before<std::unique_ptr<rows_entry, alloc_strategy_deleter<rows_entry> > >(intrusive_b::tree<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::iterator, std::unique_ptr<rows_entry, alloc_strategy_deleter<rows_entry> >) at ././utils/intrusive_btree.hh:440
(inlined by) partition_snapshot_row_cursor::ensure_entry_if_complete(position_in_partition_view) at ././partition_snapshot_row_cursor.hh:607
operator() at ./partition_version.cc:448
(inlined by) _ZN8logalloc18allocating_section24with_reclaiming_disabledIRZZN15partition_entry19apply_to_incompleteERK6schemaOS2_R16mutation_cleanerRS0_RNS_6regionER13cache_trackermR27real_dirty_memory_accounterEN4$_12clEvEUlvE_EEDcSB_OT_ at ././utils/logalloc.hh:797
(inlined by) operator() at ././utils/logalloc.hh:819
(inlined by) _ZN8logalloc18allocating_section12with_reserveIZNS0_clIZZN15partition_entry19apply_to_incompleteERK6schemaOS3_R16mutation_cleanerRS0_RNS_6regionER13cache_trackermR27real_dirty_memory_accounterEN4$_12clEvEUlvE_EEDcSC_OT_EUlvE_EEDcSK_ at ././utils/logalloc.hh:768
(inlined by) _ZN8logalloc18allocating_sectionclIZZN15partition_entry19apply_to_incompleteERK6schemaOS2_R16mutation_cleanerRS0_RNS_6regionER13cache_trackermR27real_dirty_memory_accounterEN4$_12clEvEUlvE_EEDcSB_OT_ at ././utils/logalloc.hh:818
(inlined by) operator() at ./partition_version.cc:405
(inlined by) seastar::noncopyable_function<seastar::bool_class<seastar::stop_iteration_tag> ()>::indirect_vtable_for<partition_entry::apply_to_incomplete(schema const&, partition_entry&&, mutation_cleaner&, logalloc::allocating_section&, logalloc::region&, cache_tracker&, unsigned long, real_dirty_memory_accounter&)::$_12>::call(seastar::noncopyable_function<seastar::bool_class<seastar::stop_iteration_tag> ()> const*) at ././seastar/include/seastar/util/noncopyable_function.hh:153
seastar::noncopyable_function<seastar::bool_class<seastar::stop_iteration_tag> ()>::operator()() const at ././seastar/include/seastar/util/noncopyable_function.hh:209
(inlined by) utils::coroutine::run() at ././utils/coroutine.hh:40
(inlined by) operator() at ./row_cache.cc:984
(inlined by) _Z14with_allocatorIZZZN9row_cache9do_updateIZNS0_6updateENS0_16external_updaterER8memtableE4$_20EEN7seastar6futureIvEES2_S4_T_ENKUlvE_clEvENUlvE0_clEvEUlvE1_EDcR19allocation_strategyOS9_ at ././utils/allocation_strategy.hh:315
(inlined by) operator() at ./row_cache.cc:960
(inlined by) void std::__invoke_impl<void, seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}>(std::__invoke_other, seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}&&) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:61
(inlined by) std::__invoke_result<seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}>::type std::__invoke<seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}>(seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}&&, (seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}&&)...) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:96
(inlined by) _ZSt12__apply_implIZZN9row_cache9do_updateIZNS0_6updateENS0_16external_updaterER8memtableE4$_20EEN7seastar6futureIvEES2_S4_T_ENKUlvE_clEvEUlvE0_St5tupleIJEEJEEDcOS9_OT0_St16integer_sequenceImJXspT1_EEE at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/tuple:1843
(inlined by) _ZSt5applyIZZN9row_cache9do_updateIZNS0_6updateENS0_16external_updaterER8memtableE4$_20EEN7seastar6futureIvEES2_S4_T_ENKUlvE_clEvEUlvE0_St5tupleIJEEEDcOS9_OT0_ at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/tuple:1854
(inlined by) seastar::future<void> seastar::futurize<void>::apply<seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}>(seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}&&, std::tuple<>&&) at ././seastar/include/seastar/core/future.hh:2099
(inlined by) operator() at ././seastar/include/seastar/core/thread.hh:258
(inlined by) seastar::noncopyable_function<void ()>::direct_vtable_for<seastar::futurize<std::invoke_result<seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}>::type>::type seastar::async<seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}>(seastar::thread_attributes, seastar::future<void> row_cache::do_update<row_cache::update(row_cache::external_updater, memtable&)::$_20>(row_cache::external_updater, memtable&, row_cache::update(row_cache::external_updater, memtable&)::$_20)::{lambda()#1}::operator()() const::{lambda()#2}&&, (seastar::futurize&&)...)::{lambda()#1}>::call(seastar::noncopyable_function<void ()> const*) at ././seastar/include/seastar/util/noncopyable_function.hh:124
seastar::noncopyable_function<void ()>::operator()() const at ./build/release/seastar/./seastar/include/seastar/util/noncopyable_function.hh:209
(inlined by) seastar::thread_context::main() at ./build/release/seastar/./seastar/src/core/thread.cc:299
?? ??:0

Impact

Describe the impact this issue causes to the user.

How frequently does it reproduce?

Describe the frequency with how this issue can be reproduced.

Installation details

Kernel Version: 4.18.0-489.el8.x86_64
Scylla version (or git commit hash): 2022.1.6-20230419.a71b1b3f64 with build-id 358c991dc7de52ecb9cf2ff89f7efabb69b41e9e

Cluster size: 4 nodes (n1-highmem-8)

Scylla Nodes used in this run:

  • rolling-upgrade--centos-8-db-node-eab2674a-0-4 (34.23.136.35 | 10.142.0.191) (shards: 8)
  • rolling-upgrade--centos-8-db-node-eab2674a-0-3 (34.75.220.190 | 10.142.0.182) (shards: 8)
  • rolling-upgrade--centos-8-db-node-eab2674a-0-2 (35.229.66.139 | 10.142.0.166) (shards: 8)
  • rolling-upgrade--centos-8-db-node-eab2674a-0-1 (34.23.79.178 | 10.142.0.153) (shards: 8)

OS / Image: https://www.googleapis.com/compute/v1/projects/centos-cloud/global/images/family/centos-stream-8 (gce: us-east1)

Test: rolling-upgrade-centos8-test
Test id: eab2674a-1dd7-4ba5-ad7b-2c31601c304f
Test name: enterprise-2023.1/rolling-upgrade/rolling-upgrade-centos8-test
Test config file(s):

Logs and commands
  • Restore Monitor Stack command: $ hydra investigate show-monitor eab2674a-1dd7-4ba5-ad7b-2c31601c304f
  • Restore monitor on AWS instance using Jenkins job
  • Show all stored logs command: $ hydra investigate show-logs eab2674a-1dd7-4ba5-ad7b-2c31601c304f

Logs:

Jenkins job URL
Argus

@avikivity
Copy link
Member

I have ideas for a fix, I'll try to push out something soon.

@mykaul
Copy link
Contributor

mykaul commented Jun 15, 2023

I have ideas for a fix, I'll try to push out something soon.

"I have discovered a truly marvelous demonstration of this proposition that this Github comment is too narrow to contain." ?

@avikivity
Copy link
Member

Here's an old version of the idea: avikivity/seastar@6fea38b

@avikivity
Copy link
Member

Filed scylladb/seastar#1702

xemul added a commit to scylladb/seastar that referenced this issue Jul 10, 2023
…vity

To avoid latency spikes due to page faults on anonymous memory,
we mlockall() all memory. This prevents memory from being swapped out,
but we can still see a latency spike when faulting in the memory the first time
it is touched.

It's rare for this to be a problem, as faulting in an anonymous memory page
on first use is cheap - the kernel just has to zero it. However, things are complicated
by transparent hugepages as the kernel first has to defragment memory. This can
take quite a while, as was observed in [1].

The solution is to launch background threads that will attempt to fault-in the
memory ahead of the application. We need to be careful so that these threads
themselves don't compete with the application and cause latency spikes themselves,
so we take the following steps:
1. We launch just one thread per NUMA node, reducing lock contention
2. We place the threads in the SCHED_IDLE class, so the kernel will favor application threads
3. We let the thread affinity float over the entire NUMA node, so it can find the least contended core

Tested on an old Intel E5 E5-2697. It was able to fault 200GB in 50 cpu seconds
(25 wall-clock seconds) for a rate of 8 GB/s. This shows that even a large-memory application
will be able to fault in memory faster than it will need it.

[1] scylladb/scylladb#8828

Closes #1702

* https://github.com/scylladb/seastar:
  smp: wire up memory prefaulter
  smp: introduce memory prefaulter
  resource: compute numa_node_id to cpuset mapping in resources::allocate()
  posix: add posix_thread attribute for thread affinity
  memory: return NUMA layout of allocated memory during initialization
avikivity added a commit to avikivity/scylladb that referenced this issue Jul 10, 2023
locator/*_snitch.cc updated for http::reply losing the _status_code
member without a deprecation notice.

* seastar 99d28ff057...2b7a341210 (23):
  > Merge 'Prefault memory when --lock-memory 1 is specified' from Avi Kivity
Fixes scylladb#8828.
  > reactor: use structured binding when appropriate
  > Simplify payload length and mask parsing.
  > memcached: do not used deprecated API
  > build: serialize calls to openssl certificate generation
  > reactor: epoll backend: initialize _highres_timer_pending
  > shared_ptr: deprecate lw_shared_ptr operator=(T&&)
  > tests: fail spawn_test if output is empty
  > Support specifying the "build root" in configure
  > Merge 'Cleanup RPC request/response frames maintenance' from Pavel Emelyanov
  > build: correct the syntax error in comment
  > util: print_safe: fix hex print functions
  > Add code examples for handling exceptions
  > smp: warn if --memory parameter is not supported
  > Merge 'gate: track holders' from Benny Halevy
  > file: call lambda with std::invoke()
  > deleter: Delete move and copy constructors
  > file: fix the indent
  > file: call close() without the syscall thread
  > reactor: use s/::free()/::io_uring_free_probe()/
  > Merge 'seastar-json2code: generate better-formatted code' from Kefu Chai
  > reactor: Don't re-evaliate local reactor for thread_pool
  > Merge 'Improve http::reply re-allocations and copying in client' from Pavel Emelyanov
@DoronArazii DoronArazii modified the milestones: 5.x, 5.4 Jul 16, 2023
@denesb
Copy link
Contributor

denesb commented Dec 18, 2023

@avikivity please evaluate for backport.

@bhalevy
Copy link
Member

bhalevy commented Dec 25, 2023

@avikivity please evaluate for backport.

ping @avikivity

@avikivity
Copy link
Member

I think it's pretty safe by now. But it doesn't fix a regression, and it mostly shows up in tests. In production nodes are long-lived and after they fault in their memory they don't see this problem.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.