search

scylladb / scylladb

NoSQL data store using the seastar framework, compatible with Apache Cassandra
http://scylladb.com
GNU Affero General Public License v3.0
13.4k stars 1.27k forks source link

Significant drop down OPS and timeout error for scylla-bench during alter table with TWCS with new columns (duplicate of #2577 - different workload) #10028

Closed aleksbykov closed 8 months ago

aleksbykov commented 2 years ago

Installation details Kernel version: 5.11.0-1022-aws Scylla version (or git commit hash): 4.6.rc4-0.20220203.34d470967a0 with build-id bf9a6fccf70cbe9f5c482869342c931fadd4c0b2 Cluster size: 5 nodes (i3.2xlarge) Scylla running with shards number (live nodes): longevity-twcs-3h-4-6-db-node-63292728-1 (3.238.186.66 | 10.0.2.129): 8 shards longevity-twcs-3h-4-6-db-node-63292728-2 (44.200.237.145 | 10.0.1.149): 8 shards longevity-twcs-3h-4-6-db-node-63292728-3 (3.235.53.250 | 10.0.0.55): 8 shards longevity-twcs-3h-4-6-db-node-63292728-4 (44.201.35.114 | 10.0.1.104): 8 shards longevity-twcs-3h-4-6-db-node-63292728-5 (3.220.230.8 | 10.0.1.57): 8 shards OS (RHEL/CentOS/Ubuntu/AWS AMI): ami-06d4532db67cc0577 (aws: us-east-1)

Test: longevity-twcs-3h-test Test name: longevity_twcs_test.TWCSLongevityTest.test_twcs_longevity Test config file(s):

Issue description

====================================

During test longevity-TWCS-3h nemesis AddDropColumn nemesis was executed. The nemesis add drop several columns several times to table with TWCS. The payload for table is organized with Scylla-bench tool. with next commands:

stress_cmd=scylla-bench -workload=timeseries -mode=write -replication-factor=3 -partition-count=400 -clustering-row-count=10000000 -clustering-row-size=200 -concurrency=100 -rows-per-request=100 -start-timestamp=SET_WRITE_TIMESTAMP -connection-count 100 -max-rate 50000 --timeout 120s -duration=170m -error-at-row-limit 1000

stress_cmd=scylla-bench -workload=timeseries -mode=read -partition-count=20000 -concurrency=100 -replication-factor=3 -clustering-row-count=10000000 -clustering-row-size=200  -rows-per-request=100 -start-timestamp=GET_WRITE_TIMESTAMP -write-rate 125 -distribution hnormal --connection-count 100 -duration=170m -error-at-row-limit 1000

stress_cmd=scylla-bench -workload=timeseries -mode=read -partition-count=20000 -concurrency=100 -replication-factor=3 -clustering-row-count=10000000 -clustering-row-size=200  -rows-per-request=100 -start-timestamp=GET_WRITE_TIMESTAMP -write-rate 125 -distribution uniform --connection-count 100 -duration=170m -error-at-row-limit 1000

Next cql commands was executed during nemesis some of them are failed:

< t:2022-02-03 14:32:44,277 f:common.py       l:1284 c:utils                p:DEBUG > Executing CQL 'ALTER TABLE test ADD ( B7FJUEZIFP double );' ...
< t:2022-02-03 14:37:06,142 f:common.py       l:1284 c:utils                p:DEBUG > Executing CQL 'ALTER TABLE test DROP ( B7FJUEZIFP );' ...
< t:2022-02-03 14:38:18,750 f:nemesis.py      l:1453 c:sdcm.nemesis         p:DEBUG > sdcm.nemesis.SisyphusMonkey: Add/Remove Column Nemesis: CQL query 'ALTER TABLE test DROP ( B7FJUEZIFP );' execution has failed with error 'errors={'Connection defunct by heartbeat': 'Client request timeout. See Session.execute[_async](timeout)'}, last_host=10.0.1.57:9042'

< t:2022-02-03 14:39:53,091 f:common.py       l:1284 c:utils                p:DEBUG > Executing CQL 'ALTER TABLE test ADD ( NA8XE3F45V smallint, CUCUKO5FH0 uuid, WJC69NSDRY timestamp );' ...
< t:2022-02-03 14:42:16,084 f:common.py       l:1284 c:utils                p:DEBUG > Executing CQL 'ALTER TABLE test DROP ( CUCUKO5FH0, WJC69NSDRY, NA8XE3F45V, B7FJUEZIFP );' ...
< t:2022-02-03 14:42:30,446 f:nemesis.py      l:1453 c:sdcm.nemesis         p:DEBUG > sdcm.nemesis.SisyphusMonkey: Add/Remove Column Nemesis: CQL query 'ALTER TABLE test DROP ( CUCUKO5FH0, WJC69NSDRY, NA8XE3F45V, B7FJUEZIFP );' execution has failed with error 'Error from server: code=2200 [Invalid query] message="Column b7fjuezifp was not found in table test"'

< t:2022-02-03 14:45:19,092 f:common.py       l:1284 c:utils                p:DEBUG > Executing CQL 'ALTER TABLE test ADD ( IOGB1IZ2FF blob, A8KQ6LDZ1A text, SVXA2ZJPQP bigint );' ...
< t:2022-02-03 14:46:25,280 f:nemesis.py      l:1453 c:sdcm.nemesis         p:DEBUG > sdcm.nemesis.SisyphusMonkey: Add/Remove Column Nemesis: CQL query 'ALTER TABLE test ADD ( IOGB1IZ2FF blob, A8KQ6LDZ1A text, SVXA2ZJPQP bigint );' execution has failed with error 'errors={'10.0.1.104:9042': 'Client request timeout. See Session.execute[_async](timeout)'}, last_host=10.0.1.104:9042'

During this nemesis scylla bench report a lot of errors with no quorrom:

2022-02-03 14:32:48.204 <2022-02-03 14:32:48.000>: (ScyllaBenchLogEvent Severity.ERROR) period_type=one-time event_id=2dd926f6-2ed9-48f4-a1b5-580c9a6a64d1: type=ConsistencyError regex=received only line_number=4170 node=Node longevity-twcs-3h-4-6-loader-node-63292728-1 [54.160.1.0 | 10.0.0.146] (seed: False)
2022/02/03 14:32:48 Operation timed out for scylla_bench.test - received only 1 responses from 2 CL=QUORUM.
2022-02-03 14:32:48.205 <2022-02-03 14:32:48.000>: (ScyllaBenchLogEvent Severity.ERROR) period_type=one-time event_id=2dd926f6-2ed9-48f4-a1b5-580c9a6a64d1: type=ConsistencyError regex=received only line_number=4171 node=Node longevity-twcs-3h-4-6-loader-node-63292728-1 [54.160.1.0 | 10.0.0.146] (seed: False)
2022/02/03 14:32:48 Operation timed out for scylla_bench.test - received only 1 responses from 2 CL=QUORUM.
2022-02-03 14:32:48.206 <2022-02-03 14:32:48.000>: (ScyllaBenchLogEvent Severity.ERROR) period_type=one-time event_id=2dd926f6-2ed9-48f4-a1b5-580c9a6a64d1: type=ConsistencyError regex=received only line_number=4172 node=Node longevity-twcs-3h-4-6-loader-node-63292728-1 [54.160.1.0 | 10.0.0.146] (seed: False)
2022/02/03 14:32:48 Operation timed out for scylla_bench.test - received only 1 responses from 2 CL=QUORUM.
2022-02-03 14:32:48.314 <2022-02-03 14:32:48.000>: (ScyllaBenchLogEvent Severity.ERROR) period_type=one-time event_id=2dd926f6-2ed9-48f4-a1b5-580c9a6a64d1: type=ConsistencyError regex=received only line_number=4173 node=Node longevity-twcs-3h-4-6-loader-node-63292728-1 [54.160.1.0 | 10.0.0.146] (seed: False)
2022/02/03 14:32:48 Operation timed out for scylla_bench.test - received only 1 responses from 2 CL=QUORUM.

And at the end of nemesis next errors were found in nodes:

b-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-1/messages.log:2022-02-03T14:47:50+00:00 longevity-twcs-3h-4-6-db-node-63292728-1 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  900 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-1/messages.log:2022-02-03T14:49:23+00:00 longevity-twcs-3h-4-6-db-node-63292728-1 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  990 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-1/messages.log:2022-02-03T14:50:48+00:00 longevity-twcs-3h-4-6-db-node-63292728-1 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  1080 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-2/messages.log:2022-02-03T14:47:52+00:00 longevity-twcs-3h-4-6-db-node-63292728-2 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  900 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-2/messages.log:2022-02-03T14:49:25+00:00 longevity-twcs-3h-4-6-db-node-63292728-2 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  990 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-2/messages.log:2022-02-03T14:51:01+00:00 longevity-twcs-3h-4-6-db-node-63292728-2 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  1080 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-3/messages.log:2022-02-03T14:47:51+00:00 longevity-twcs-3h-4-6-db-node-63292728-3 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  900 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-3/messages.log:2022-02-03T14:49:19+00:00 longevity-twcs-3h-4-6-db-node-63292728-3 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  990 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-3/messages.log:2022-02-03T14:50:46+00:00 longevity-twcs-3h-4-6-db-node-63292728-3 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  1080 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-4/messages.log:2022-02-03T14:47:40+00:00 longevity-twcs-3h-4-6-db-node-63292728-4 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  900 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-4/messages.log:2022-02-03T14:49:17+00:00 longevity-twcs-3h-4-6-db-node-63292728-4 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  990 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-4/messages.log:2022-02-03T14:50:49+00:00 longevity-twcs-3h-4-6-db-node-63292728-4 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  1080 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-5/messages.log:2022-02-03T14:47:47+00:00 longevity-twcs-3h-4-6-db-node-63292728-5 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  900 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-5/messages.log:2022-02-03T14:49:27+00:00 longevity-twcs-3h-4-6-db-node-63292728-5 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  990 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)
db-cluster-63292728/longevity-twcs-3h-4-6-db-node-63292728-5/messages.log:2022-02-03T14:50:47+00:00 longevity-twcs-3h-4-6-db-node-63292728-5 !     ERR |  [shard 0] service_level_controller - update_from_distributed_data: failed to update configuration for more than  1080 seconds : exceptions::read_timeout_exception (Operation timed out for system_distributed.service_levels - received only 0 responses from 1 CL=ONE.)

And significant drop down in OPS: Screenshot from 2022-02-04 20-13-50 Screenshot from 2022-02-04 20-13-30

Live monitoring is available: http://44.193.212.54:3000/d/x6ey6M-nk/longevity-twcs-3h-test-scylla-per-server-metrics-nemesis-master?orgId=1&from=1643898298183&to=1643900393068

Could be related to issue #8030

====================================

Restore Monitor Stack command: $ hydra investigate show-monitor 63292728-6e2d-472b-9915-c7b64cb844fb Restore monitor on AWS instance using Jenkins job Show all stored logs command: $ hydra investigate show-logs 63292728-6e2d-472b-9915-c7b64cb844fb

Test id: 63292728-6e2d-472b-9915-c7b64cb844fb

Logs: grafana - [https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_162304/grafana-screenshot-longevity-twcs-3h-test-scylla-per-server-metrics-nemesis-20220203_162505-longevity-twcs-3h-4-6-monitor-node-63292728-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_162304/grafana-screenshot-longevity-twcs-3h-test-scylla-per-server-metrics-nemesis-20220203_162505-longevity-twcs-3h-4-6-monitor-node-63292728-1.png) grafana - [https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_162304/grafana-screenshot-overview-20220203_162305-longevity-twcs-3h-4-6-monitor-node-63292728-1.png](https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_162304/grafana-screenshot-overview-20220203_162305-longevity-twcs-3h-4-6-monitor-node-63292728-1.png) db-cluster - [https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_163721/db-cluster-63292728.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_163721/db-cluster-63292728.tar.gz) loader-set - [https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_163721/loader-set-63292728.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_163721/loader-set-63292728.tar.gz) monitor-set - [https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_163721/monitor-set-63292728.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_163721/monitor-set-63292728.tar.gz) sct - [https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_163721/sct-runner-63292728.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/63292728-6e2d-472b-9915-c7b64cb844fb/20220203_163721/sct-runner-63292728.tar.gz)

Jenkins job URL

slivne commented 2 years ago

Some parts of the cache are evicted - check the row count + row evictions

Screenshot from 2022-02-04 18-09-50

We have a standing issue that schema changes for cached data is at partition level (a partition in the cache that has an old schema and is read will be updated to the new schema all of it and not in parts).

There are stalls need to extract them and see how long they are and what they are

slivne commented 2 years ago

Are the updates of the schema done to the same tables that the loaders are reading / writing

slivne commented 2 years ago

https://github.com/scylladb/scylla/issues/2577

slivne commented 2 years ago

The reason for the eviction can be memory pressure so its unclear if its related to the schema change or not

Having said that we have prepared statement invalidation and repreperation and that has todo with the schema change - e.g. if a table that is not used is updated - we would not have prepared statements - nor followup prepare statements run

So it seems like the later is touching a table that is queried (we will be able to verify with the answers from @aleksbykov on the above https://github.com/scylladb/scylla/issues/10028#issuecomment-1030144504)

aleksbykov commented 2 years ago

Are the updates of the schema done to the same tables that the loaders are reading / writing

  • which tables are the loaders accessing

scylla_bench.test

  • which tables are the alters done on ?

scylla_bench.test

  • are the tables altered have also an ongoing workload reading /writing the data ?

yes.

eliransin commented 2 years ago

@tgrabiec here is a possible reproducer to a failed queries during altering tables. Do you think it can be the same case or something entirely different.

tgrabiec commented 2 years ago

That depends, is the slowness during schema disagreement?

haaawk commented 2 years ago

Could be related to issue https://github.com/scylladb/scylla/issues/8030

Where there any nodes added or removed @aleksbykov ?

aleksbykov commented 2 years ago

@haaawk during adding/dropping columns, no any nodes were added/removed

haaawk commented 2 years ago

Would you be able to decode this backtrace @aleksbykov please?

2022-02-03T14:45:20+00:00 longevity-twcs-3h-4-6-db-node-63292728-5 !    INFO | Reactor stalled for 3639 ms on shard 7. Backtrace: 0x3db12d2 0x3daff80 0x3db11e0 0x7f79e7e6ba1f 0x13ff572 0x1408fc4 0x1473dda 0x1549b4f 0x146c88a 0x12ed14c 0x130ad5d 0x130cf7f 0x1130ff9 0x1217272 0x12153ff 0x117a09a 0x10f89ab 0x33e43c3 0x3dc3d04 0x3dc50f7 0x3de2725 0x3d9c33a 0x9298 0x100352
haaawk commented 2 years ago

Also this:

2022-02-03T14:46:00+00:00 longevity-twcs-3h-4-6-db-node-63292728-5 !    INFO | Reactor stalled for 3252 ms on shard 0. Backtrace: 0x3db12d2 0x3daff80 0x3db11e0 0x7f79e7e6b
a1f 0x12cfc83 0x1473bab 0x1549b4f 0x146c88a 0x12ed14c 0x13667d1 0x4034b61
piodul commented 2 years ago

It is in nanoseconds:

https://github.com/scylladb/scylla/blob/34d470967a05839b393be3915e41ba850038c1b0/utils/logalloc.cc#L2199-L2200

_duration here has type std::chrono::nanoseconds. The number in the log translates to 0.16799653 seconds.

aleksbykov commented 2 years ago

0x3db12d2 0x3daff80 0x3db11e0 0x7f79e7e6ba1f 0x13ff572 0x1408fc4 0x1473dda 0x1549b4f 0x146c88a 0x12ed14c 0x130ad5d 0x130cf7f 0x1130ff9 0x1217272 0x12153ff 0x117a09a 0x10f89ab 0x33e43c3 0x3dc3d04 0x3dc50f7 0x3de2725 0x3d9c33a 0x9298 0x100352

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:770
 (inlined by) seastar::print_with_backtrace(seastar::backtrace_buffer&, bool) at ./build/release/seastar/./seastar/src/core/reactor.cc:789
seastar::internal::cpu_stall_detector::generate_trace() at ./build/release/seastar/./seastar/src/core/reactor.cc:1364
seastar::internal::cpu_stall_detector::maybe_report() at ./build/release/seastar/./seastar/src/core/reactor.cc:1106
 (inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1123
 (inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1347
?? ??:0
logalloc::region_impl::alloc_small(logalloc::region_impl::object_descriptor const&, unsigned int, unsigned long) at ./utils/logalloc.cc:1297
logalloc::region_impl::alloc(migrate_fn_type const*, unsigned long, unsigned long) at ./utils/logalloc.cc:1659
rows_entry* allocation_strategy::construct<rows_entry, schema const&, position_in_partition_view&, seastar::bool_class<dummy_tag>&, seastar::bool_class<continuous_tag>&>(schema const&, position_in_partition_view&, seastar::bool_class<dummy_tag>&, seastar::bool_class<continuous_tag>&) at ././utils/allocation_strategy.hh:168
 (inlined by) mutation_partition::clustered_row(schema const&, position_in_partition_view, seastar::bool_class<dummy_tag>, seastar::bool_class<continuous_tag>) at ./mutation_partition.cc:600
converting_mutation_partition_applier::accept_row(position_in_partition_view, row_tombstone const&, row_marker const&, seastar::bool_class<dummy_tag>, seastar::bool_class<continuous_tag>) at ./converting_mutation_partition_applier.cc:152
mutation_partition::accept(schema const&, mutation_partition_visitor&) const at ./mutation_partition.cc:1783
 (inlined by) mutation_partition::upgrade(schema const&, schema const&) at ./mutation_partition.cc:1801
partition_entry::squashed(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>) at ./partition_version.cc:493
 (inlined by) partition_entry::upgrade(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>, mutation_cleaner&, cache_tracker*) at ./partition_version.cc:507
operator() at ./row_cache.cc:1329
 (inlined by) decltype(auto) with_allocator<row_cache::upgrade_entry(cache_entry&)::$_27>(allocation_strategy&, row_cache::upgrade_entry(cache_entry&)::$_27&&) at ././utils/allocation_strategy.hh:328
 (inlined by) row_cache::upgrade_entry(cache_entry&) at ./row_cache.cc:1328
 (inlined by) operator() at ./row_cache.cc:751
 (inlined by) decltype(auto) logalloc::allocating_section::with_reclaiming_disabled<row_cache::do_make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>)::$_6&>(logalloc::region&, row_cache::do_make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>)::$_6&) at ././utils/logalloc.hh:810
 (inlined by) operator() at ././utils/logalloc.hh:832
 (inlined by) decltype(auto) logalloc::allocating_section::with_reserve<logalloc::allocating_section::operator()<row_cache::do_make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>)::$_6>(logalloc::region&, row_cache::do_make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>)::$_6&&)::{lambda()#1}>(row_cache::do_make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>)::$_6&&) at ././utils/logalloc.hh:781
 (inlined by) decltype(auto) logalloc::allocating_section::operator()<row_cache::do_make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>)::$_6>(logalloc::region&, row_cache::do_make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>)::$_6&&) at ././utils/logalloc.hh:831
 (inlined by) row_cache::do_make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>) at ./row_cache.cc:744
row_cache::make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>) at ./row_cache.cc:785
table::make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>) const at ./table.cc:199
operator() at ./table.cc:2116
 (inlined by) flat_mutation_reader std::__invoke_impl<flat_mutation_reader, table::as_mutation_source() const::$_55&, seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag> >(std::__invoke_other, table::as_mutation_source() const::$_55&, seastar::lw_shared_ptr<schema const>&&, reader_permit&&, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr&&, seastar::bool_class<streamed_mutation::forwarding_tag>&&, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>&&) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:61
 (inlined by) std::enable_if<is_invocable_r_v<flat_mutation_reader, table::as_mutation_source() const::$_55&, seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag> >, flat_mutation_reader>::type std::__invoke_r<flat_mutation_reader, table::as_mutation_source() const::$_55&, seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag> >(table::as_mutation_source() const::$_55&, seastar::lw_shared_ptr<schema const>&&, reader_permit&&, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr&&, seastar::bool_class<streamed_mutation::forwarding_tag>&&, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>&&) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:114
 (inlined by) std::_Function_handler<flat_mutation_reader (seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>), table::as_mutation_source() const::$_55>::_M_invoke(std::_Any_data const&, seastar::lw_shared_ptr<schema const>&&, reader_permit&&, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr&&, seastar::bool_class<streamed_mutation::forwarding_tag>&&, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>&&) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:291
std::function<flat_mutation_reader (seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>)>::operator()(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>) const at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:560
 (inlined by) mutation_source::make_reader(seastar::lw_shared_ptr<schema const>, reader_permit, nonwrapping_interval<dht::ring_position> const&, query::partition_slice const&, seastar::io_priority_class const&, tracing::trace_state_ptr, seastar::bool_class<streamed_mutation::forwarding_tag>, seastar::bool_class<flat_mutation_reader::partition_range_forwarding_tag>) const at ././mutation_reader.hh:281
 (inlined by) querier_base at ././querier.hh:137
querier at ././querier.hh:205
 (inlined by) table::query(seastar::lw_shared_ptr<schema const>, reader_permit, query::read_command const&, query::result_options, std::vector<nonwrapping_interval<dht::ring_position>, std::allocator<nonwrapping_interval<dht::ring_position> > > const&, tracing::trace_state_ptr, query::result_memory_limiter&, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >, std::optional<query::querier<(emit_only_live_rows)1> >*) at ./table.cc:2028
operator() at ./database.cc:1412
 (inlined by) seastar::noncopyable_function<seastar::future<void> (reader_permit)>::indirect_vtable_for<database::query(seastar::lw_shared_ptr<schema const>, query::read_command const&, query::result_options, std::vector<nonwrapping_interval<dht::ring_position>, std::allocator<nonwrapping_interval<dht::ring_position> > > const&, tracing::trace_state_ptr, std::chrono::time_point<seastar::lowres_clock, std::chrono::duration<long, std::ratio<1l, 1000l> > >)::$_38>::call(seastar::noncopyable_function<seastar::future<void> (reader_permit)> const*, reader_permit) at ././seastar/include/seastar/util/noncopyable_function.hh:153
seastar::noncopyable_function<seastar::future<void> (reader_permit)>::operator()(reader_permit) const at ././seastar/include/seastar/util/noncopyable_function.hh:209
 (inlined by) reader_concurrency_semaphore::execution_loop() at ./reader_concurrency_semaphore.cc:628
seastar::reactor::run_tasks(seastar::reactor::task_queue&) at ./build/release/seastar/./seastar/src/core/reactor.cc:2374
 (inlined by) seastar::reactor::run_some_tasks() at ./build/release/seastar/./seastar/src/core/reactor.cc:2783
seastar::reactor::do_run() at ./build/release/seastar/./seastar/src/core/reactor.cc:2952
operator() at ./build/release/seastar/./seastar/src/core/reactor.cc:4166
 (inlined by) void std::__invoke_impl<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_98&>(std::__invoke_other, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_98&) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:61
 (inlined by) std::enable_if<is_invocable_r_v<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_98&>, void>::type std::__invoke_r<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_98&>(seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_98&) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/invoke.h:111
 (inlined by) std::_Function_handler<void (), seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::$_98>::_M_invoke(std::_Any_data const&) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:291
std::function<void ()>::operator()() const at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/bits/std_function.h:560
 (inlined by) seastar::posix_thread::start_routine(void*) at ./build/release/seastar/./seastar/src/core/posix.cc:60
?? ??:0
?? ??:0
aleksbykov commented 2 years ago

Also this:

2022-02-03T14:46:00+00:00 longevity-twcs-3h-4-6-db-node-63292728-5 !    INFO | Reactor stalled for 3252 ms on shard 0. Backtrace: 0x3db12d2 0x3daff80 0x3db11e0 0x7f79e7e6b
a1f 0x12cfc83 0x1473bab 0x1549b4f 0x146c88a 0x12ed14c 0x13667d1 0x4034b61

@haaawk is it valid? Looks like you copied not all

anyway i decode it:

addr2line -Cpife 9a6fccf70cbe9f5c482869342c931fadd4c0b2.debug 0x3db12d2 0x3daff80 0x3db11e0 0x7f79e7e6b a1f 0x12cfc83 0x1473bab 0x1549b4f 0x146c88a 0x12ed14c 0x13667d1 0x4034b61
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:770
 (inlined by) seastar::print_with_backtrace(seastar::backtrace_buffer&, bool) at ./build/release/seastar/./seastar/src/core/reactor.cc:789
seastar::internal::cpu_stall_detector::generate_trace() at ./build/release/seastar/./seastar/src/core/reactor.cc:1364
seastar::internal::cpu_stall_detector::maybe_report() at ./build/release/seastar/./seastar/src/core/reactor.cc:1106
 (inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1123
 (inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1347
?? ??:0
?? ??:0
tri_compare(seastar::shared_ptr<abstract_type const>, managed_bytes_basic_view<(mutable_view)0>, managed_bytes_basic_view<(mutable_view)0>) at ././types.hh:745
 (inlined by) std::strong_ordering prefix_equality_tri_compare<__gnu_cxx::__normal_iterator<seastar::shared_ptr<abstract_type const> const*, std::vector<seastar::shared_ptr<abstract_type const>, std::allocator<seastar::shared_ptr<abstract_type const> > > >, compound_type<(allow_prefixes)1>::iterator, compound_type<(allow_prefixes)1>::iterator, std::strong_ordering (*)(seastar::shared_ptr<abstract_type const>, managed_bytes_basic_view<(mutable_view)0>, managed_bytes_basic_view<(mutable_view)0>)>(__gnu_cxx::__normal_iterator<seastar::shared_ptr<abstract_type const> const*, std::vector<seastar::shared_ptr<abstract_type const>, std::allocator<seastar::shared_ptr<abstract_type const> > > >, compound_type<(allow_prefixes)1>::iterator, compound_type<(allow_prefixes)1>::iterator, compound_type<(allow_prefixes)1>::iterator, compound_type<(allow_prefixes)1>::iterator, std::strong_ordering (*)(seastar::shared_ptr<abstract_type const>, managed_bytes_basic_view<(mutable_view)0>, managed_bytes_basic_view<(mutable_view)0>)) at ././types.hh:191
 (inlined by) bound_view::tri_compare::operator()(clustering_key_prefix const&, int, clustering_key_prefix const&, int) const at ././clustering_bounds_comparator.hh:72
std::strong_ordering position_in_partition::tri_compare::compare<position_in_partition_view, position_in_partition_view>(position_in_partition_view const&, position_in_partition_view const&) const at ././position_in_partition.hh:481
 (inlined by) position_in_partition::tri_compare::operator()(position_in_partition_view const&, position_in_partition_view const&) const at ././position_in_partition.hh:489
 (inlined by) rows_entry::tri_compare::operator()(position_in_partition_view, rows_entry const&) const at ././mutation_partition.hh:999
 (inlined by) intrusive_b::searcher<position_in_partition_view, rows_entry, &rows_entry::_link, rows_entry::tri_compare, (intrusive_b::key_search)0>::ge(position_in_partition_view const&, intrusive_b::node_base const&, rows_entry::tri_compare const&, bool&) at ././utils/intrusive_btree.hh:1092
 (inlined by) 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>::index_for<position_in_partition_view>(position_in_partition_view const&, rows_entry::tri_compare const&, bool&) const at ././utils/intrusive_btree.hh:1430
 (inlined by) bool intrusive_b::tree<rows_entry, &rows_entry::_link, rows_entry::tri_compare, 12ul, 20ul, (intrusive_b::key_search)0, (intrusive_b::with_debug)0>::key_lower_bound<position_in_partition_view>(position_in_partition_view const&, rows_entry::tri_compare const&, 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&) const at ././utils/intrusive_btree.hh:289
 (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>::const_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>::find<position_in_partition_view>(position_in_partition_view const&, rows_entry::tri_compare) const at ././utils/intrusive_btree.hh:479
 (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>::find<position_in_partition_view>(position_in_partition_view const&, rows_entry::tri_compare) at ././utils/intrusive_btree.hh:489
 (inlined by) mutation_partition::clustered_row(schema const&, position_in_partition_view, seastar::bool_class<dummy_tag>, seastar::bool_class<continuous_tag>) at ./mutation_partition.cc:597
converting_mutation_partition_applier::accept_row(position_in_partition_view, row_tombstone const&, row_marker const&, seastar::bool_class<dummy_tag>, seastar::bool_class<continuous_tag>) at ./converting_mutation_partition_applier.cc:152
mutation_partition::accept(schema const&, mutation_partition_visitor&) const at ./mutation_partition.cc:1783
 (inlined by) mutation_partition::upgrade(schema const&, schema const&) at ./mutation_partition.cc:1801
partition_entry::squashed(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>) at ./partition_version.cc:493
 (inlined by) partition_entry::upgrade(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>, mutation_cleaner&, cache_tracker*) at ./partition_version.cc:507
operator() at ./row_cache.cc:1329
 (inlined by) decltype(auto) with_allocator<row_cache::upgrade_entry(cache_entry&)::$_27>(allocation_strategy&, row_cache::upgrade_entry(cache_entry&)::$_27&&) at ././utils/allocation_strategy.hh:328
 (inlined by) row_cache::upgrade_entry(cache_entry&) at ./row_cache.cc:1328
 (inlined by) operator() at ./row_cache.cc:1046
 (inlined by) operator() at ./row_cache.cc:996
 (inlined by) decltype(auto) logalloc::allocating_section::with_reclaiming_disabled<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}::operator()()::{lambda()#2}::operator()() const::{lambda()#1}&>(logalloc::region&, 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}::operator()()::{lambda()#2}::operator()() const::{lambda()#1}&) at ././utils/logalloc.hh:810
 (inlined by) operator() at ././utils/logalloc.hh:832
 (inlined by) decltype(auto) logalloc::allocating_section::with_reserve<logalloc::allocating_section::operator()<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}::operator()()::{lambda()#2}::operator()() const::{lambda()#1}>(logalloc::region&, 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}::operator()()::{lambda()#2}::operator()() const::{lambda()#1}&&)::{lambda()#1}>({lambda()#1}) at ././utils/logalloc.hh:781
 (inlined by) decltype(auto) logalloc::allocating_section::operator()<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}::operator()()::{lambda()#2}::operator()() const::{lambda()#1}>(logalloc::region&, 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}::operator()()::{lambda()#2}::operator()() const::{lambda()#1}&&) at ././utils/logalloc.hh:831
 (inlined by) operator() at ./row_cache.cc:991
 (inlined by) decltype(auto) with_allocator<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}::operator()()::{lambda()#2}>(allocation_strategy&, 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}::operator()()::{lambda()#2}&&) at ././utils/allocation_strategy.hh:328
 (inlined by) operator() at ./row_cache.cc:978
 (inlined by) void std::__invoke_impl<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, 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<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<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}>(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}&&, (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) decltype(auto) std::__apply_impl<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<>>(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<>&&, std::integer_sequence<unsigned long>) at /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/tuple:1843
 (inlined by) decltype(auto) std::apply<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<> >(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 /usr/lib/gcc/x86_64-redhat-linux/11/../../../../include/c++/11/tuple:1854
 (inlined by) seastar::future<void> seastar::futurize<void>::apply<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}>(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::async<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, 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::decay<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}>&&)...)::{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
haaawk commented 2 years ago

is it valid? Looks like you copied not all

That's all there was in logs but we can see it's from cache so it makes sense

haaawk commented 2 years ago

Thanks @aleksbykov.

logalloc::region_impl::alloc_small(logalloc::region_impl::object_descriptor const&, unsigned int, unsigned long) at ./utils/logalloc.cc:1297
logalloc::region_impl::alloc(migrate_fn_type const*, unsigned long, unsigned long) at ./utils/logalloc.cc:1659
rows_entry* allocation_strategy::construct<rows_entry, schema const&, position_in_partition_view&, seastar::bool_class<dummy_tag>&, seastar::bool_class<continuous_tag>&>(schema const&, position_in_partition_view&, seastar::bool_class<dummy_tag>&, seastar::bool_class<continuous_tag>&) at ././utils/allocation_strategy.hh:168
 (inlined by) mutation_partition::clustered_row(schema const&, position_in_partition_view, seastar::bool_class<dummy_tag>, seastar::bool_class<continuous_tag>) at ./mutation_partition.cc:600
converting_mutation_partition_applier::accept_row(position_in_partition_view, row_tombstone const&, row_marker const&, seastar::bool_class<dummy_tag>, seastar::bool_class<continuous_tag>) at ./converting_mutation_partition_applier.cc:152
mutation_partition::accept(schema const&, mutation_partition_visitor&) const at ./mutation_partition.cc:1783
 (inlined by) mutation_partition::upgrade(schema const&, schema const&) at ./mutation_partition.cc:1801
partition_entry::squashed(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>) at ./partition_version.cc:493
 (inlined by) partition_entry::upgrade(seastar::lw_shared_ptr<schema const>, seastar::lw_shared_ptr<schema const>, mutation_cleaner&, cache_tracker*) at ./partition_version.cc:507
operator() at ./row_cache.cc:1329
 (inlined by) decltype(auto) with_allocator<row_cache::upgrade_entry(cache_entry&)::$_27>(allocation_strategy&, row_cache::upgrade_entry(cache_entry&)::$_27&&) at ././utils/allocation_strategy.hh:328
 (inlined by) row_cache::upgrade_entry(cache_entry&) at ./row_cache.cc:1328

so it seems that when cache upgrades its records to the new schema, LSA allocation is stalling for 3639 ms which is 3.7 seconds.

haaawk commented 2 years ago

I believe that this issue is not related to scylla-bench and is caused by the fact that cache needs to upgrade its entries after schema has changed. It seems that such upgrade requires allocation on LSA and for some reason it takes a long time and holds CPU for the whole time. For example for 3.7 seconds. That probably causes the traffic to pile up.

Another reason I think it's not related to scylla-bench is that when the load drops, read/write timeouts start to occur. If it was scylla-bench slowing down we wouldn't see those timeouts.

piodul commented 2 years ago

~One node seems to behave differently with respect to the cache (yellow one, 10.0.1.104:~ Edit: I didn't really read previous comments, it was already pointed out by Shlomi

image

piodul commented 2 years ago

It's also strange that the number of reads starts at some reasonable level but after 15 minutes slows down to a crawl. It happens much earlier than the schema change event (which happened around 14:33):

image

piodul commented 2 years ago

After 13:40, server side tail latencies are linearly growing:

image

avikivity commented 2 years ago

Duplicate of #2577. Is that the only problem?

aleksbykov commented 2 years ago

Issue reproduced with 5.0.rc2. During adding dropping new column there are significant drop down and a lot of warning/error messages on nodes and kernel stacks :

2022-03-25 20:11:57.780 <2022-03-25 20:11:10.000>: (DatabaseLogEvent Severity.DEBUG) period_type=one-time event_id=3af4fab7-caca-4384-8b92-be440e826fa9: type=KERNEL_CALLSTACK regex=kernel callstack: 0x.{16} line_number=27943 node=longevity-twcs-3h-5-0-db-node-a47a7343-1
2022-03-25T20:11:10+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-1 !    INFO | kernel callstack: 0xffffffffffffff80 0xffffffffa73122a0 0xffffffffa77a9542 0xffffffffa77a962f 0xffffffffa7119c73 0xffffffffa711a41e 0xffffffffa711c701 0xffffffffa711c74a 0xffffffffa7a02891 0xffffffffa7c0007c
2022-03-25 20:11:57.780 <2022-03-25 20:11:10.000>: (DatabaseLogEvent Severity.DEBUG) period_type=one-time event_id=3af4fab7-caca-4384-8b92-be440e826fa9: type=KERNEL_CALLSTACK regex=kernel callstack: 0x.{16} line_number=27944 node=longevity-twcs-3h-5-0-db-node-a47a7343-1
2022-03-25T20:11:10+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-1 !    INFO | kernel callstack: 0xffffffffffffff80 0xffffffffa6e40f40 0xffffffffa7894012 0xffffffffa788c122 0xffffffffa78826d5 0xffffffffa7882dcc 0xffffffffa78bce5f 0xffffffffa77a9589 0xffffffffa77a962f 0xffffffffa7119c73 0xffffffffa711a41e 0xffffffffa711c701 0xffffffffa711c74a 0xffffffffa7a02891 0xffffffffa7c0007c
2022-03-25 20:11:57.781 <2022-03-25 20:11:10.000>: (DatabaseLogEvent Severity.DEBUG) period_type=one-time event_id=3af4fab7-caca-4384-8b92-be440e826fa9: type=KERNEL_CALLSTACK regex=kernel callstack: 0x.{16} line_number=27948 node=longevity-twcs-3h-5-0-db-node-a47a7343-1
2022-03-25T20:11:10+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-1 !    INFO | kernel callstack: 0xffffffffffffff80 0xffffffffc0421a2d 0xffffffffa77d23ef 0xffffffffa7837a0b 0xffffffffa77d2b45 0xffffffffa77d2fb0 0xffffffffa7871d93 0xffffffffa7872fc1 0xffffffffa787312d 0xffffffffa7872daa 0xffffffffa787429a 0xffffffffa78745ff 0xffffffffa78748b5 0xffffffffa7895723 0xffffffffa78970a0 0xffffffffa7897997 0xffffffffa78802f7 0xffffffffa78813fd 0xffffffffa788159d 0xffffffffa78bcb13 0xffffffffa77a98de 0xffffffffa77a9c38 0xffffffffa77ab761 0xffffffffa77ab822 0xffffffffa77ab88f 0xffffffffa7a02891 0xffffffffa7c0007c
2022-03-25 20:11:57.781 <2022-03-25 20:11:10.000>: (DatabaseLogEvent Severity.DEBUG) period_type=one-time event_id=3af4fab7-caca-4384-8b92-be440e826fa9: type=KERNEL_CALLSTACK regex=kernel callstack: 0x.{16} line_number=27953 node=longevity-twcs-3h-5-0-db-node-a47a7343-1
2022-03-25T20:11:10+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-1 !    INFO | kernel callstack: 0xffffffffffffff80 0xffffffffa7183a21 0xffffffffa7183f13 0xffffffffa71846dd 0xffffffffa7a02891 0xffffffffa7c0007c
2022-03-25 20:11:57.783 <2022-03-25 20:11:10.000>: (DatabaseLogEvent Severity.DEBUG) period_type=one-time event_id=3af4fab7-caca-4384-8b92-be440e826fa9: type=KERNEL_CALLSTACK regex=kernel callstack: 0x.{16} line_number=27966 node=longevity-twcs-3h-5-0-db-node-a47a7343-1
2022-03-25T20:11:10+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-1 !    INFO | kernel callstack: 0xffffffffffffff80 0xffffffffa70e21b0 0xffffffffa77b3d86 0xffffffffa77b6db4 0xffffffffc041de77 0xffffffffc041e036 0xffffffffc042085a 0xffffffffc042140d 0xffffffffa77d5af1 0xffffffffa77d5fcf 0xffffffffa7e000cf 0xffffffffa6eaa814 0xffffffffa7a02b33 0xffffffffa7c00fc2
2022-03-25 20:12:15.347 <2022-03-25 20:01:43.000>: (ScyllaBenchLogEvent Severity.ERROR) period_type=one-time event_id=dac7c7af-ffa8-4f62-b691-f06981151a15: type=ConsistencyError regex=received only line_number=5953 node=Node longevity-twcs-3h-5-0-loader-node-a47a7343-1 [3.219.167.164 | 10.0.1.136] (seed: False)
2022/03/25 20:01:43 Operation timed out for scylla_bench.test - received only 1 responses from 2 CL=QUORUM.
2022-03-25 20:10:38.728 <2022-03-25 20:10:01.000>: (DatabaseLogEvent Severity.WARNING) period_type=one-time event_id=1e7010a9-f956-492a-b8a5-a929786b4cc1: type=WARNING regex=!\s*?WARNING  line_number=25115 node=longevity-twcs-3h-5-0-db-node-a47a7343-2
2022-03-25T20:10:01+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-2 ! WARNING |  [shard 3] lsa-timing - Reclamation cycle took 200001 us, trying to release 0.125 MiB non-preemptibly
2022-03-25 20:10:38.729 <2022-03-25 20:10:03.000>: (DatabaseLogEvent Severity.WARNING) period_type=one-time event_id=1e7010a9-f956-492a-b8a5-a929786b4cc1: type=WARNING regex=!\s*?WARNING  line_number=25122 node=longevity-twcs-3h-5-0-db-node-a47a7343-2
2022-03-25T20:10:03+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-2 ! WARNING |  [shard 3] lsa-timing - Reclamation cycle took 208001 us, trying to release 0.125 MiB non-preemptibly
2022-03-25 20:10:38.730 <2022-03-25 20:10:05.000>: (DatabaseLogEvent Severity.WARNING) period_type=one-time event_id=1e7010a9-f956-492a-b8a5-a929786b4cc1: type=WARNING regex=!\s*?WARNING  line_number=25128 node=longevity-twcs-3h-5-0-db-node-a47a7343-2
2022-03-25T20:10:05+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-2 ! WARNING |  [shard 6] lsa-timing - Reclamation cycle took 256001 us, trying to release 0.125 MiB non-preemptibly
2022-03-25 20:10:38.731 <2022-03-25 20:10:06.000>: (DatabaseLogEvent Severity.WARNING) period_type=one-time event_id=1e7010a9-f956-492a-b8a5-a929786b4cc1: type=WARNING regex=!\s*?WARNING  line_number=25134 node=longevity-twcs-3h-5-0-db-node-a47a7343-2
2022-03-25T20:10:06+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-2 ! WARNING |  [shard 6] lsa-timing - Reclamation cycle took 208001 us, trying to release 0.125 MiB non-preemptibly
2022-03-25 20:10:38.731 <2022-03-25 20:10:09.000>: (DatabaseLogEvent Severity.WARNING) period_type=one-time event_id=1e7010a9-f956-492a-b8a5-a929786b4cc1: type=WARNING regex=!\s*?WARNING  line_number=25140 node=longevity-twcs-3h-5-0-db-node-a47a7343-2
2022-03-25T20:10:09+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-2 ! WARNING |  [shard 0] lsa-timing - Reclamation cycle took 188001 us, trying to release 0.125 MiB non-preemptibly
2022-03-25 20:10:38.732 <2022-03-25 20:10:09.000>: (DatabaseLogEvent Severity.WARNING) period_type=one-time event_id=1e7010a9-f956-492a-b8a5-a929786b4cc1: type=WARNING regex=!\s*?WARNING  line_number=25146 node=longevity-twcs-3h-5-0-db-node-a47a7343-2
2022-03-25T20:10:09+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-2 ! WARNING |  [shard 3] lsa-timing - Reclamation cycle took 200001 us, trying to release 0.125 MiB non-preemptibly
2022-03-25 20:10:38.733 <2022-03-25 20:10:11.000>: (DatabaseLogEvent Severity.WARNING) period_type=one-time event_id=1e7010a9-f956-492a-b8a5-a929786b4cc1: type=WARNING regex=!\s*?WARNING  line_number=25152 node=longevity-twcs-3h-5-0-db-node-a47a7343-2
2022-03-25T20:10:11+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-2 ! WARNING |  [shard 0] lsa-timing - Reclamation cycle took 300001 us, trying to release 0.125 MiB non-preemptibly
2022-03-25 20:10:38.734 <2022-03-25 20:10:11.000>: (DatabaseLogEvent Severity.WARNING) period_type=one-time event_id=1e7010a9-f956-492a-b8a5-a929786b4cc1: type=WARNING regex=!\s*?WARNING  line_number=25158 node=longevity-twcs-3h-5-0-db-node-a47a7343-2
2022-03-25T20:10:11+00:00 longevity-twcs-3h-5-0-db-node-a47a7343-2 ! WARNING |  [shard 3] lsa-timing - Reclamation cycle took 240001 us, trying to release 0.125 MiB non-preemptibly

Installation details

Kernel Version: 5.13.0-1017-aws

Scylla version (or git commit hash): 5.0~rc2-20220316.839d9ef41 with build-id 1319e7e64335b7e5c7531f773e92ef997b6c51ba

Cluster size: 5 nodes (i3.2xlarge)

Scylla Nodes used in this run:

OS / Image: ami-0338c83239d0ab168 (aws: us-east-1)

Test: longevity-twcs-3h-test

Test id: a47a7343-6265-486a-b649-bb247b15e57b

Test name: longevity/longevity-twcs-3h-test

Test config file(s):

Issue description

Your description here...

<<<<<<<

Logs:

Jenkins job URL

slivne commented 2 years ago

@aleksbykov do we have backtrace with mutation_partition::upgrade if so its the same issue

slivne commented 2 years ago

I am assuming its the same removing release/triage and also pushing this out till we fix the #2577

juliayakovlev commented 2 years ago

Reproduced with 2022.1~rc5-20220515.6a1e89fbb

Screenshot from 2022-05-23 16-10-15

Installation details

Kernel Version: 5.13.0-1022-aws Scylla version (or git commit hash): 2022.1~rc5-20220515.6a1e89fbb with build-id 5cecadda59974548befb4305363bf374631fc3e1 Cluster size: 5 nodes (i3.2xlarge)

Scylla Nodes used in this run:

OS / Image: ami-0838dc54c055ad05a (aws: eu-north-1)

Test: longevity-twcs-3h-test Test id: 4f585541-af89-4da9-bd54-edf413637a9b Test name: enterprise-2022.1/longevity/longevity-twcs-3h-test Test config file(s):

Logs:

Jenkins job URL

avikivity commented 2 years ago

It's a duplicate of #2577. I don't know why we keep duplicates open.

slivne commented 2 years ago

the reason to keep this open is that it shows the workload that is hit by this the most - which is large partitions using TWCS

aleksbykov commented 8 months ago

Reproduced with 2022.2.17

Packages

Scylla version: 2022.2.17-20240122.f299acdeeac0 with build-id d975714fc9133a8f89a7118b70ebd4b42cea857c

Kernel Version: 5.15.0-1051-aws

Issue description

Describe your issue in detail and steps it took to produce it.

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

Cluster size: 5 nodes (i3.2xlarge)

Scylla Nodes used in this run:

OS / Image: ami-0c2932385954e38bd (aws: us-east-1)

Test: longevity-twcs-3h-test Test id: a6d89656-aa57-429d-9d3a-41fc2c5dbcc4 Test name: enterprise-2022.2/longevity/longevity-twcs-3h-test Test config file(s):

Logs and commands - Restore Monitor Stack command: `$ hydra investigate show-monitor a6d89656-aa57-429d-9d3a-41fc2c5dbcc4` - Restore monitor on AWS instance using [Jenkins job](https://jenkins.scylladb.com/view/QA/job/QA-tools/job/hydra-show-monitor/parambuild/?test_id=a6d89656-aa57-429d-9d3a-41fc2c5dbcc4) - Show all stored logs command: `$ hydra investigate show-logs a6d89656-aa57-429d-9d3a-41fc2c5dbcc4` ## Logs: - **db-cluster-a6d89656.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/db-cluster-a6d89656.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/db-cluster-a6d89656.tar.gz) - **monitor-set-a6d89656.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/monitor-set-a6d89656.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/monitor-set-a6d89656.tar.gz) - **loader-set-a6d89656.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/loader-set-a6d89656.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/loader-set-a6d89656.tar.gz) - **sct-runner-a6d89656.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/sct-runner-a6d89656.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/sct-runner-a6d89656.tar.gz) - **parallel-timelines-report-a6d89656.tar.gz** - [https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/parallel-timelines-report-a6d89656.tar.gz](https://cloudius-jenkins-test.s3.amazonaws.com/a6d89656-aa57-429d-9d3a-41fc2c5dbcc4/20240131_165318/parallel-timelines-report-a6d89656.tar.gz) [Jenkins job URL](https://jenkins.scylladb.com/job/enterprise-2022.2/job/longevity/job/longevity-twcs-3h-test/7/) [Argus](https://argus.scylladb.com/test/b234a1f9-1cba-4ee3-a766-adbc0a9cb50a/runs?additionalRuns[]=a6d89656-aa57-429d-9d3a-41fc2c5dbcc4)
mykaul commented 8 months ago

It's a duplicate of #2577. I don't know why we keep duplicates open.

Closing as duplicate.