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.57k stars 1.29k forks source link

scylla-debug: frequent stalls from multiple nodes caused c-s failed #7150

Open amoskong opened 4 years ago

amoskong commented 4 years ago

Installation details Scylla version (or git commit hash): 666.development-0.20200720.5371be71e90 Cluster size: 3 OS (RHEL/CentOS/Ubuntu/AWS AMI):

Test package:

Version: 666.development-0.20200720.5371be71e90 gsutil copy -r gs://scratch.scylladb.com/penberg/scylla-debug-20200722

The package was built by @penberg

Test job

job: https://jenkins.scylladb.com/job/scylla-staging/job/amos/job/byo-longevity-test/27/console test id: 90b56d9e-20ea-47d1-9c0d-00e7ae39bc9d

db log: https://cloudius-jenkins-test.s3.amazonaws.com/90b56d9e-20ea-47d1-9c0d-00e7ae39bc9d/20200826_081252/db-cluster-90b56d9e.zip loader log: https://cloudius-jenkins-test.s3.amazonaws.com/90b56d9e-20ea-47d1-9c0d-00e7ae39bc9d/20200826_081252/loader-set-90b56d9e.zip monitor log: https://cloudius-jenkins-test.s3.amazonaws.com/90b56d9e-20ea-47d1-9c0d-00e7ae39bc9d/20200826_081252/monitor-set-90b56d9e.zip

Problem

c-s workload failed during the first nemsis (HardRebootNode) around 2020-08-26 07:23:56.

cs error:

com.datastax.driver.core.exceptions.WriteTimeoutException: Cassandra timeout during SIMPLE write query at consistency QUORUM (2 replica were required but only 1 acknowledged the write)

Db log:

I saw some cqlsh_server connection exception raised from db nodes, and there are many stalls, the stall also exists before c-s failed.

2020-08-26T07:23:56+00:00  longevity-100gb-4h-update-d-db-node-90b56d9e-4 !INFO    | scylla: [shard 1] cql_server - exception while processing connection: seas
tar::nested_exception (seastar::nested_exception)
2020-08-26T07:23:56+00:00  longevity-100gb-4h-update-d-db-node-90b56d9e-4 !INFO    | scylla: [shard 1] cql_server - exception while processing connection: seas
tar::nested_exception (seastar::nested_exception)
2020-08-26T07:23:57+00:00  longevity-100gb-4h-update-d-db-node-90b56d9e-4 !INFO    | scylla: [shard 10] cql_server - exception while processing connection: sea
star::nested_exception (seastar::nested_exception)
2020-08-26T07:23:57+00:00  longevity-100gb-4h-update-d-db-node-90b56d9e-4 !INFO    | scylla: [shard 9] cql_server - exception while processing connection: seas
tar::nested_exception (seastar::nested_exception)
2020-08-26T07:23:57+00:00  longevity-100gb-4h-update-d-db-node-90b56d9e-4 !INFO    | scylla: [shard 11] cql_server - exception while processing connection: sea
star::nested_exception (seastar::nested_exception)

2020-08-26T07:23:56+00:00  longevity-100gb-4h-update-d-db-node-90b56d9e-1 !INFO    | scylla: [shard 1] cql_server - exception while processing connection: seastar::nested_exception (seastar::nested_exception)

2020-08-26T07:24:00+00:00  longevity-100gb-4h-update-d-db-node-90b56d9e-1
| scylla: Reactor stalled for 650 ms on shard 0.
| scylla: Backtrace:
| scylla: /opt/scylladb/libreloc/libasan.so.6+0x0000000000045bad
| scylla: 0x00000000163ac3ce
| scylla: 0x000000001638b22e
| scylla: 0x0000000016268380
| scylla: 0x000000001627adc7
| scylla: 0x0000000016277570
| scylla: 0x00000000162776da
| scylla: 0x000000001627a85a
| scylla: 0x00007fed5b2a4a8f
| scylla: 0x000000000e41e632
| scylla: 0x000000000e404f04
| scylla: 0x000000000e3e9da0
| scylla: 0x000000000e3d6075
| scylla: 0x000000000e3c024f
| scylla: 0x000000000e3d646f
| scylla: 0x000000000e3c0b19
| scylla: 0x000000000e3cecff
| scylla: 0x000000000e3823d9
| scylla: 0x000000000e15422a
| scylla: 0x000000000e179877
| scylla: 0x000000000e1741d5
| scylla: 0x000000000e16b71a
| scylla: 0x000000000dc39a69
| scylla: 0x000000000e143073
| scylla: 0x000000000e15e907
| scylla: 0x000000000e143114
| scylla: 0x000000000e143d74
| scylla: 0x000000000e177b6a
| scylla: 0x000000000e1704e2
| scylla: 0x000000000e1705b6
| scylla: 0x000000000e170672
| scylla: 0x000000000da05aee
| scylla: 0x000000000d9d2fa6
| scylla: 0x000000000d9910af
| scylla: 0x000000000d941686
| scylla: 0x000000000d941765
| scylla: 0x000000000d94157f
| scylla: 0x000000000d99116e
| scylla: 0x000000000d941370
| scylla: 0x000000000da714c3
| scylla: 0x00000000162a532d
| scylla: 0x00000000162a942f
| scylla: 0x00000000162ae67a
| scylla: 0x00000000160bb4c1
| scylla: 0x00000000160b94c7
| scylla: 0x000000000cfcb4c5
| scylla: /opt/scylladb/libreloc/libc.so.6+0x0000000000027041
| scylla: 0x000000000cf7eb2d
amoskong commented 4 years ago

image

avikivity commented 4 years ago

Stalls and low performance are expected in debug mode. Disable the stall report, and use very low loads.

roydahan commented 4 years ago

we already reduced the load. If this issue is not relevant you can close it.

amoskong commented 4 years ago

Job with 1/4 workloads also failed (c-s failed in first nemesis):

Reduce the workload threads to 1/8, and reduce the dataset to 1/10.

amoskong commented 4 years ago

Job with 1/8 workloads also failed (c-s failed in first nemesis):

The job failed, because c-s workloads failed after executed 130+ mins, and I didn't found the c-s / db errors.

amoskong commented 4 years ago

/CC @avikivity @bhalevy

There are some big stall (3000+ms) in some nemesis (eg: rebuild_streaming_err) even with very small workload (cs threads=1). It causes the c-s workload failed, so the problem isn't workload heavy, but scylla itself.

c-s failed after job executed 3 hours and 40 mins. (cs workloads works well with other nemesis) total execute time: 4 hours.

Test info

Test job: https://jenkins.scylladb.com/job/scylla-staging/job/amos/job/byo-longevity-test/46/ Test-id: 0d0cf80a-0a4e-433f-bea5-f978151b4904 Start time: 2020-09-22 04:49:52 End time: 2020-09-22 08:46:57 rpm-build: gs://scratch.scylladb.com/amoskong/scylla-debug-20200914 Version: scylla-666.development-0.20200914.5f541fbdc.x86_64.rpm

the cs failed during rebuild_streaming_err nemesis

< t:2020-09-22 08:19:36,520 f:nemesis.py      l:760  c:sdcm.nemesis         p:INFO  > sdcm.nemesis.ChaosMonkey: >>>>>>>>>>>>>Started random_disrupt_method rebuild_streaming_err

< t:2020-09-22 08:22:34,904 f:nemesis.py      l:2124 c:sdcm.nemesis         p:DEBUG > sdcm.nemesis.ChaosMonkey: wait for random between 10s to 10m

< t:2020-09-22 08:29:41
com.datastax.driver.core.exceptions.WriteTimeoutException: Cassandra time
out during SIMPLE write query at consistency QUORUM (2 replica were required but only 1 acknowledged the write)

< t:2020-09-22 08:29:41,707 f:base.py         l:171  c:RemoteCmdRunner      p:DEBUG > com.datastax.driver.core.exceptions.WriteTimeoutException: Cassandra time
out during SIMPLE write query at consistency QUORUM (2 replica were required but only 1 acknowledged the write)

2020-09-22T08:30:34+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: [shard 0] init - Shutting down repair

Stall

2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: Reactor stalled for 3614 ms on shard 2.
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: Backtrace:
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: /opt/scylladb/libreloc/libasan.so.6+0x0000000000045bad
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016b47047
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016b254d8
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x00000000169fc3f2
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016a0eed7
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016a0b66a
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016a0b7d4
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016a0e96a
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x00007fe63284aa8f
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eafaedb
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eb3c537
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eb3c6cd
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eb24368
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eb0eacb
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eaf97e2
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eafa711
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eab5c06
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eab62a3
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eab7a46
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eac9e9a
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eae10ca
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000eaecbd5
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016a3d4e9
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016a41725
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016a469a2
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016a5a7f9
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016acb137
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016abc269
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016aa0740
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x000000000e403ee0
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: 0x0000000016cf6290
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: /opt/scylladb/libreloc/libpthread.so.0+0x0000000000009431
2020-09-22T08:20:45+00:00  longevity-100gb-4h-master-s-db-node-0d0cf80a-1 !INFO    | scylla: /opt/scylladb/libreloc/libc.so.6+0x0000000000101912
avikivity commented 4 years ago

Can you decode the stall?

bhalevy commented 4 years ago

what are the client and server request timeouts? In dtest we multiply the timeout by 3 for debug mode. See https://github.com/scylladb/scylla-dtest/blob/f32aef3edd705359fbaf74a1ef05137e961bf675/dtest.py#L649-L662

amoskong commented 4 years ago

Can you decode the stall?

$ addr2line -Cfpi -e /usr/lib/debug/opt/scylladb/libexec/scylla-666.development-0.20200914.5f541fbdc.x86_64.debug 
/opt/scylladb/libreloc/libasan.so.6+0x0000000000045bad
0x0000000016b47047
0x0000000016b254d8
0x00000000169fc3f2
0x0000000016a0eed7
0x0000000016a0b66a
0x0000000016a0b7d4
0x0000000016a0e96a
0x00007fe63284aa8f
0x000000000eafaedb
0x000000000eb3c537
0x000000000eb3c6cd
0x000000000eb24368
0x000000000eb0eacb
0x000000000eaf97e2
0x000000000eafa711
0x000000000eab5c06
0x000000000eab62a3
0x000000000eab7a46
0x000000000eac9e9a
0x000000000eae10ca
0x000000000eaecbd5
0x0000000016a3d4e9
0x0000000016a41725
0x0000000016a469a2
0x0000000016a5a7f9
0x0000000016acb137
0x0000000016abc269
0x0000000016aa0740
0x000000000e403ee0
0x0000000016cf6290
/opt/scylladb/libreloc/libpthread.so.0+0x0000000000009431
/opt/scylladb/libreloc/libc.so.6+0x0000000000101912?? ??:0

void seastar::backtrace<seastar::backtrace_buffer::append_backtrace()::{lambda(seastar::frame)#1}>(seastar::backtrace_buffer::append_backtrace()::{lambda(seastar::frame)#1}&&) at /jenkins/workspace/scylla-master/next/scylla/seastar/include/seastar/util/backtrace.hh:59
seastar::backtrace_buffer::append_backtrace() at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:731
seastar::print_with_backtrace(seastar::backtrace_buffer&) at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:752
seastar::internal::cpu_stall_detector::generate_trace() at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:1201 (discriminator 1)
seastar::internal::cpu_stall_detector::maybe_report() at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:1047
seastar::internal::cpu_stall_detector::on_signal() at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:1061
seastar::reactor::block_notifier(int) at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:1184
?? ??:0
__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >::operator*() const at /usr/include/c++/10/bits/stl_iterator.h:968
bool __gnu_cxx::__ops::_Iter_equals_val<decltype(nullptr) const>::operator()<__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > > >(__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >) at /usr/include/c++/10/bits/predefined_ops.h:268
__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > > std::__find_if<__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >, __gnu_cxx::__ops::_Iter_equals_val<decltype(nullptr) const> >(__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >, __gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >, __gnu_cxx::__ops::_Iter_equals_val<decltype(nullptr) const>, std::random_access_iterator_tag) at /usr/include/c++/10/bits/stl_algobase.h:1932
__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > > std::__find_if<__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >, __gnu_cxx::__ops::_Iter_equals_val<decltype(nullptr) const> >(__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >, __gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >, __gnu_cxx::__ops::_Iter_equals_val<decltype(nullptr) const>) at /usr/include/c++/10/bits/stl_algobase.h:1977
__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > > std::find<__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >, decltype(nullptr)>(__gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >, __gnu_cxx::__normal_iterator<logalloc::segment**, std::vector<logalloc::segment*, std::allocator<logalloc::segment*> > >, decltype(nullptr) const&) at /usr/include/c++/10/bits/stl_algo.h:3902
logalloc::segment_store::find_empty() at /jenkins/workspace/scylla-master/next/scylla/utils/logalloc.cc:563
logalloc::segment_store::new_idx_for_segment(logalloc::segment*) at /jenkins/workspace/scylla-master/next/scylla/utils/logalloc.cc:584
logalloc::segment_pool::allocate_segment(unsigned long) at /jenkins/workspace/scylla-master/next/scylla/utils/logalloc.cc:815
logalloc::segment_pool::refill_emergency_reserve() at /jenkins/workspace/scylla-master/next/scylla/utils/logalloc.cc:832
logalloc::segment_pool::prime(unsigned long, unsigned long) at /jenkins/workspace/scylla-master/next/scylla/utils/logalloc.cc:912 (discriminator 2)
logalloc::prime_segment_pool(unsigned long, unsigned long)::{lambda()#1}::operator()() const at /jenkins/workspace/scylla-master/next/scylla/utils/logalloc.cc:2341
seastar::future<> seastar::futurize<void>::invoke<logalloc::prime_segment_pool(unsigned long, unsigned long)::{lambda()#1}&>(logalloc::prime_segment_pool(unsigned long, unsigned long)::{lambda()#1}&) at /jenkins/workspace/scylla-master/next/scylla/seastar/include/seastar/core/future.hh:2085
seastar::smp_message_queue::async_work_item<logalloc::prime_segment_pool(unsigned long, unsigned long)::{lambda()#1}>::run_and_dispose() at /jenkins/workspace/scylla-master/next/scylla/seastar/include/seastar/core/smp.hh:220
seastar::reactor::run_tasks(seastar::reactor::task_queue&) at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:2196
seastar::reactor::run_some_tasks() at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:2575
seastar::reactor::run() at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:2730
seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::{lambda()#3}::operator()() const at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/reactor.cc:3905 (discriminator 3)
void std::__invoke_impl<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::{lambda()#3}&>(std::__invoke_other, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::{lambda()#3}&) at /usr/include/c++/10/bits/invoke.h:60
std::enable_if<is_invocable_r_v<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::{lambda()#3}&>, std::enable_if>::type std::__invoke_r<void, seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::{lambda()#3}&>(void&&, (seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::{lambda()#3}&)...) at /usr/include/c++/10/bits/invoke.h:110
std::_Function_handler<void (), seastar::smp::configure(boost::program_options::variables_map, seastar::reactor_config)::{lambda()#3}>::_M_invoke(std::_Any_data const&) at /usr/include/c++/10/bits/std_function.h:291
std::function<void ()>::operator()() const at /usr/include/c++/10/bits/std_function.h:622
seastar::posix_thread::start_routine(void*) at /jenkins/workspace/scylla-master/next/scylla/seastar/src/core/posix.cc:60
?? ??:0
?? ??:0
amoskong commented 4 years ago

what are the client and server request timeouts? In dtest we multiply the timeout by 3 for debug mode. See https://github.com/scylladb/scylla-dtest/blob/f32aef3edd705359fbaf74a1ef05137e961bf675/dtest.py#L649-L662

Thanks, I'm running another longevity with longer request timeouts:

[scyllaadm@longevity-100gb-4h-master-s-db-node-950454d9-7 ~]$ cat /etc/scylla/scylla.yaml|grep timeout
cas_contention_timeout_in_ms: 1000
range_request_timeout_in_ms: 30000
read_request_timeout_in_ms: 30000
request_timeout_in_ms: 30000
truncate_request_timeout_in_ms: 30000
write_request_timeout_in_ms: 30000
bhalevy commented 4 years ago

The stall looks like https://github.com/scylladb/scylla/issues/5192

avikivity commented 4 years ago

This is at initialization. We should disable the stall detector during startup.

amoskong commented 3 years ago

This is at initialization. We should disable the stall detector during startup.

@avikivity Did we disabled the detector during startup?

The longevity jobs keep failing for this issue, the problem isn't detected stall, but the real problem behind that. I think the job will still fail even the stall detector is disabled during startup.