ReadTimeoutException error on client during performing multiple Add/Drop columns commands during long period of time #15312
Comments
|
@xemul - can you please take a look? |
|
io-properties: So disk is able ~{700Mb/s, 100kiops} reads and ~{500Mb/s, 60kiops} writes. Commitlog consumes 200Mbs / 2kiops (writes) That's on the edge of disk abilities, it just cannot (well -- not allowed to by scheduler) do more. |
|
scylladb/seastar#1641 still applies, though, and it does makes things worse |
|
Some nodes consume all the available CPU |
|
Also streaming is causing troubles by "stalling" CPUs with quota violations, which is bad, it makes Io scheduler's throttling notably worse |
|
And the last worrisome thing is IO starvation times
They are pretty big, with huge queue length values it should've been much smaller. But it can be due to scylladb/seastar#1641 |
|
@temichus please re-try with the latest master, the problem should be addressed with Kamil's fix for schema versioning. |
|
@temichus also please start Scylla with |
|
the issue was reproduced (5 runs 4 fails) Installation detailsKernel Version: 5.15.0-1045-aws Cluster size: 3 nodes (i4i.xlarge) Scylla Nodes used in this run:
OS / Image: Test: Logs and commands
Logs:
|
|
I'm looking at the logs. One thing I noticed is that you don't provide original Scylla node logs with millisecond resolution timestamps like this: the milliseconds would be useful for my investigation here TBH... but maybe I'll find something out without it |
|
Why don't the metrics have read timeout data? |
May be because we do not sent zero metrics any longer? |
|
They should be nonzero though, after all we're getting |
|
I don't have read timeout metrics, but I have coordinator read p99 latency metrics. Sometimes those reach 2s. These events don't seem to correlate with schema read barriers. For example, around 13:48:15 - 13:48:30, on 10.4.3.118 shard 1: Around this time I didn't see any "Performing read barrier" / "Mark schema ... as synced" logs on this node. The closest barrier messages are: before, and after. I only looked at few such data points though. Also it seems that 2s is for some reason a favorite value for this metric. Why 2s in particular? Is it somehow related to write timeout setting which is 2s? But we're looking at reads here, which have 5s timeout setting. Maybe it's read repair, and it's using 2s for the internal write? |
Also the stressor app doesn't provide timestamps when the timeouts happened. Very convenient. |
|
Ok there's this one event when read p99 latency jumps to >5s on 10.4.3.22, so above timeout threshold: the data points seem to be gathered every ~15 seconds... If I understand correctly, these high latency reads were observed anywhere between 15:07:00 and 15:07:30. And indeed, we can see some read barriers finishing at 15:07:00: and there is a batch of |
|
Lots of messages like these around this time: looks like these reads are happening during schema merging. cc @tgrabiec |
That's only on the coordinator node though, and the read requires a quorum. Perhaps the two other nodes are waiting on barriers. Indeed I found some very long running barriers on 10.4.3.118 during this time: That's 15 seconds to do a read barrier! I didn't find such long barrier on the third node (10.4.2.192), so theoretically we should have a QUORUM... But who knows, the situation is complex when we consider speculative reads. Maybe the metric used to perform the speculative read was already high, we picked |
|
A read barrier latency metric could be useful perhaps... |
Do we want to print in the log how long it took to sync the schema? (instead / in addition to a metric? I think a log entry is more useful?) |
|
Try looking at |
|
Used |
|
I'm trying to build the metric so it shows it for every node, but apparently I cannot into grafana |
|
|
|
Around 15:07:00
the spike is 15:07:00 |
That is sort of expected for such a workload. We could improve it by expiring tombstones sooner with raft, by using tombstone gc mode = repair, and treating state machine catch up as repair. |
Never heard of such databases. Everyone have their tricks to overcome this 'when and how frequently I sync'. |
|
Are you saying that no databases give actual durability guarantees? |
I know we have commitlog metrics of course. But now we have two commitlogs, so my question is can we see metrics for each one separately. One for the statement may starve, but one for the raft/schema/local tables can be fine. |
Example - https://docs.portworx.com/portworx-enterprise/concepts/io-profiles#the-db_remote-profile |
|
I restored monitor stack again, but it looks like there is no data? |
There is data for 23/09/06 |
|
Damn it, I restored monitor from the original post. |
|
So here's an interesting turn of events Apparently schema commitlog is running on a separate scheduling group, the default scheduling group, called "main". The regular commit log uses this code: db::commitlog::config db::commitlog::config::from_db_config(const db::config& cfg, seastar::scheduling_group sg, size_t shard_available_memory) {
config c;
c.sched_group = std::move(sg);future<>
database::init_commitlog() {
if (_commitlog) {
return make_ready_future<>();
}
return db::commitlog::create_commitlog(db::commitlog::config::from_db_config(_cfg, _dbcfg.commitlog_scheduling_group, _dbcfg.available_memory)).then([this](db::commitlog&& log) {but schema commitlog uses this: void database::maybe_init_schema_commitlog() {
assert(this_shard_id() == 0);
if (!_feat.schema_commitlog && !_cfg.force_schema_commit_log()) {
dblog.info("Not using schema commit log.");
_listeners.push_back(_feat.schema_commitlog.when_enabled([] {
dblog.warn("All nodes can now switch to use the schema commit log. Restart is needed for this to take effect.");
}));
_uses_schema_commitlog = false;
return;
}
dblog.info("Using schema commit log.");
_uses_schema_commitlog = true;
db::commitlog::config c;
c.commit_log_location = _cfg.schema_commitlog_directory();
c.fname_prefix = db::schema_tables::COMMITLOG_FILENAME_PREFIX;
c.metrics_category_name = "schema-commitlog";
c.commitlog_total_space_in_mb = 2 * _cfg.schema_commitlog_segment_size_in_mb();
c.commitlog_segment_size_in_mb = _cfg.schema_commitlog_segment_size_in_mb();
c.mode = db::commitlog::sync_mode::BATCH;
c.extensions = &_cfg.extensions();
c.use_o_dsync = _cfg.commitlog_use_o_dsync();
c.allow_going_over_size_limit = true; // for lower latency
_schema_commitlog = std::make_unique<db::commitlog>(db::commitlog::create_commitlog(std::move(c)).get0());
And from the metrics, the default scheduling group seems to be doing fine? |
|
We need those raft=trace logs |
|
According to @xemul --- it could still be that we're waiting for the scheduler, scylladb/seastar#1641 but I don't know how to determine if that's the case |
|
I opened #15566 |
here it is: run with append_scylla_args: --logger-log-level migration_manager=trace:group0_raft_sm=trace:raft=trace Installation detailsKernel Version: 5.15.0-1045-aws Cluster size: 3 nodes (i4i.xlarge) Scylla Nodes used in this run:
OS / Image: Test: Logs and commands
Logs:
|
|
I'm running the test with modified Scylla with additional/modified logging: |
* seastar bab1625c...17183ed4 (73): > thread_pool: Reference reactor, not point to > sstring: inherit publicly from string_view formatter > circleci: use conditional steps > weak_ptr: include used header > build: disable the -Wunused-* warnings for checkheaders > resource: move variable into smaller lexical scope > resource: use structured binding when appropriate > httpd: Added server and client addresses to request structure > io_queue: do not dereference moved-away shared pointer > treewide: explicitly define ctor and assignment operator > memory: use `err` for the error string > doc: Add document describing all the math behind IO scheduler > io_queue: Add flow-rate based self slowdown backlink > io_queue: Make main throttler uncapped > io_queue: Add queue-wide metrics > io_queue: Introduce "flow monitor" > io_queue: Count total number of dispatched and completed requests so far > io_queue: Introduce io_group::io_latency_goal() > tests: test the vector overload for when_all_succeed > core: add a vector overload to when_all_succeed > loop: Fix iterator_range_estimate_vector_capacity for random iters > loop: Add test for iterator_range_estimate_vector_capacity > core/posix return old behaviour using non-portable pthread_attr_setaffinity_np when present > memory: s/throw()/noexcept/ > build: enable -Wdeprecated compiler option > reactor: mark kernel_completion's dtor protected > tests: always wait for promise > http, json, net: define-generated copy ctor for polymorphic types > treewide: do not define constexpr static out-of-line > reactor: do not define dtor of kernel_completion > http/exception: stop using dynamic exception specification > metrics: replace vector with deque > metrics: change metadata vector to deque > utils/backtrace.hh: make simple_backtrace formattable > reactor: Unfriend disk_config_params > reactor: Move add_to_flush_poller() to internal namespace > reactor: Unfriend a bunch of sched group template calls > rpc_test: Test rpc send glitches > net: Implement batch flush support for existing sockets > iostream: Configure batch flushes if sink can do it > net: Added remote address accessors > circleci: update the image to CircleCI "standard" image > build: do not add header check target if no headers to check > build: pass target name to seastar_check_self_contained > build: detect glibc features using CMake > build: extract bits checking libc into CheckLibc.cmake > http/exception: add formatter for httpd::base_exception > http/client: Mark write_body() const > http/client: Introduce request::_bytes_written > http/client: Mark maybe_wait_for_continue() const > http/client: Mark send_request_head() const > http/client: Detach setup_request() > http/api_docs: copy in api_docs's copy constructor > script: do not inherit from object > scripts: addr2line: change StdinBacktraceIterator to a function > scripts: addr2line: use yield instead defining a class > tests: skip tests that require backtrace if execinfo.h is not found > backtrace: check for existence of execinfo.h > core: use ino_t and off_t as glibc sets these to 64bit if 64bit api is used > core: add sleep_abortable instantiation for manual_clock > tls: Return EPIPE exception when writing to shutdown socket > http/client: Don't cache connection if server advertises it > http/client: Mark connection as "keep in cache" > core: fix strerror_r usage from glibc extension > reactor: access sigevent.sigev_notify_thread_id with a macro > posix: use pthread_setaffinity_np instead of pthread_attr_setaffinity_np > reactor: replace __mode_t with mode_t > reactor: change sys/poll.h to posix poll.h > rpc: Add unit test for per-domain metrics > rpc: Report client connections metrics > rpc: Count dead client stats > rpc: Add seastar::rpc::metrics > rpc: Make public queues length getters io-scheduler fixes refs: scylladb#15312 refs: scylladb#11805 http client fixes refs: scylladb#13736 refs: scylladb#15509 rpc fixes refs: scylladb#15462
* seastar bab1625c...17183ed4 (73): > thread_pool: Reference reactor, not point to > sstring: inherit publicly from string_view formatter > circleci: use conditional steps > weak_ptr: include used header > build: disable the -Wunused-* warnings for checkheaders > resource: move variable into smaller lexical scope > resource: use structured binding when appropriate > httpd: Added server and client addresses to request structure > io_queue: do not dereference moved-away shared pointer > treewide: explicitly define ctor and assignment operator > memory: use `err` for the error string > doc: Add document describing all the math behind IO scheduler > io_queue: Add flow-rate based self slowdown backlink > io_queue: Make main throttler uncapped > io_queue: Add queue-wide metrics > io_queue: Introduce "flow monitor" > io_queue: Count total number of dispatched and completed requests so far > io_queue: Introduce io_group::io_latency_goal() > tests: test the vector overload for when_all_succeed > core: add a vector overload to when_all_succeed > loop: Fix iterator_range_estimate_vector_capacity for random iters > loop: Add test for iterator_range_estimate_vector_capacity > core/posix return old behaviour using non-portable pthread_attr_setaffinity_np when present > memory: s/throw()/noexcept/ > build: enable -Wdeprecated compiler option > reactor: mark kernel_completion's dtor protected > tests: always wait for promise > http, json, net: define-generated copy ctor for polymorphic types > treewide: do not define constexpr static out-of-line > reactor: do not define dtor of kernel_completion > http/exception: stop using dynamic exception specification > metrics: replace vector with deque > metrics: change metadata vector to deque > utils/backtrace.hh: make simple_backtrace formattable > reactor: Unfriend disk_config_params > reactor: Move add_to_flush_poller() to internal namespace > reactor: Unfriend a bunch of sched group template calls > rpc_test: Test rpc send glitches > net: Implement batch flush support for existing sockets > iostream: Configure batch flushes if sink can do it > net: Added remote address accessors > circleci: update the image to CircleCI "standard" image > build: do not add header check target if no headers to check > build: pass target name to seastar_check_self_contained > build: detect glibc features using CMake > build: extract bits checking libc into CheckLibc.cmake > http/exception: add formatter for httpd::base_exception > http/client: Mark write_body() const > http/client: Introduce request::_bytes_written > http/client: Mark maybe_wait_for_continue() const > http/client: Mark send_request_head() const > http/client: Detach setup_request() > http/api_docs: copy in api_docs's copy constructor > script: do not inherit from object > scripts: addr2line: change StdinBacktraceIterator to a function > scripts: addr2line: use yield instead defining a class > tests: skip tests that require backtrace if execinfo.h is not found > backtrace: check for existence of execinfo.h > core: use ino_t and off_t as glibc sets these to 64bit if 64bit api is used > core: add sleep_abortable instantiation for manual_clock > tls: Return EPIPE exception when writing to shutdown socket > http/client: Don't cache connection if server advertises it > http/client: Mark connection as "keep in cache" > core: fix strerror_r usage from glibc extension > reactor: access sigevent.sigev_notify_thread_id with a macro > posix: use pthread_setaffinity_np instead of pthread_attr_setaffinity_np > reactor: replace __mode_t with mode_t > reactor: change sys/poll.h to posix poll.h > rpc: Add unit test for per-domain metrics > rpc: Report client connections metrics > rpc: Count dead client stats > rpc: Add seastar::rpc::metrics > rpc: Make public queues length getters io-scheduler fixes refs: scylladb#15312 refs: scylladb#11805 http client fixes refs: scylladb#13736 refs: scylladb#15509 rpc fixes refs: scylladb#15462
* seastar bab1625c...17183ed4 (73): > thread_pool: Reference reactor, not point to > sstring: inherit publicly from string_view formatter > circleci: use conditional steps > weak_ptr: include used header > build: disable the -Wunused-* warnings for checkheaders > resource: move variable into smaller lexical scope > resource: use structured binding when appropriate > httpd: Added server and client addresses to request structure > io_queue: do not dereference moved-away shared pointer > treewide: explicitly define ctor and assignment operator > memory: use `err` for the error string > doc: Add document describing all the math behind IO scheduler > io_queue: Add flow-rate based self slowdown backlink > io_queue: Make main throttler uncapped > io_queue: Add queue-wide metrics > io_queue: Introduce "flow monitor" > io_queue: Count total number of dispatched and completed requests so far > io_queue: Introduce io_group::io_latency_goal() > tests: test the vector overload for when_all_succeed > core: add a vector overload to when_all_succeed > loop: Fix iterator_range_estimate_vector_capacity for random iters > loop: Add test for iterator_range_estimate_vector_capacity > core/posix return old behaviour using non-portable pthread_attr_setaffinity_np when present > memory: s/throw()/noexcept/ > build: enable -Wdeprecated compiler option > reactor: mark kernel_completion's dtor protected > tests: always wait for promise > http, json, net: define-generated copy ctor for polymorphic types > treewide: do not define constexpr static out-of-line > reactor: do not define dtor of kernel_completion > http/exception: stop using dynamic exception specification > metrics: replace vector with deque > metrics: change metadata vector to deque > utils/backtrace.hh: make simple_backtrace formattable > reactor: Unfriend disk_config_params > reactor: Move add_to_flush_poller() to internal namespace > reactor: Unfriend a bunch of sched group template calls > rpc_test: Test rpc send glitches > net: Implement batch flush support for existing sockets > iostream: Configure batch flushes if sink can do it > net: Added remote address accessors > circleci: update the image to CircleCI "standard" image > build: do not add header check target if no headers to check > build: pass target name to seastar_check_self_contained > build: detect glibc features using CMake > build: extract bits checking libc into CheckLibc.cmake > http/exception: add formatter for httpd::base_exception > http/client: Mark write_body() const > http/client: Introduce request::_bytes_written > http/client: Mark maybe_wait_for_continue() const > http/client: Mark send_request_head() const > http/client: Detach setup_request() > http/api_docs: copy in api_docs's copy constructor > script: do not inherit from object > scripts: addr2line: change StdinBacktraceIterator to a function > scripts: addr2line: use yield instead defining a class > tests: skip tests that require backtrace if execinfo.h is not found > backtrace: check for existence of execinfo.h > core: use ino_t and off_t as glibc sets these to 64bit if 64bit api is used > core: add sleep_abortable instantiation for manual_clock > tls: Return EPIPE exception when writing to shutdown socket > http/client: Don't cache connection if server advertises it > http/client: Mark connection as "keep in cache" > core: fix strerror_r usage from glibc extension > reactor: access sigevent.sigev_notify_thread_id with a macro > posix: use pthread_setaffinity_np instead of pthread_attr_setaffinity_np > reactor: replace __mode_t with mode_t > reactor: change sys/poll.h to posix poll.h > rpc: Add unit test for per-domain metrics > rpc: Report client connections metrics > rpc: Count dead client stats > rpc: Add seastar::rpc::metrics > rpc: Make public queues length getters io-scheduler fixes refs: #15312 refs: #11805 http client fixes refs: #13736 refs: #15509 rpc fixes refs: #15462 Closes #15774
|
@kostja, @kbr-scylla seastar_io_queue_delay even higher: but Cassandra stress has no issue: IOException |
|
Thanks @temichus. I'm aware that it's still failing. There are still some optimizations that have to be done inside The biggest issue was fixed (#15622) so it shouldn't have a large impact in real-world scenarios, where schema changes are rare. |
|
@kostja I can tell you right now that it won't be done for 6.0. |
The part we wanted for 6.0 is in, so thank you. |
Issue description
new longevity test that performs only new add/drop column nemesis PR: scylladb/scylla-cluster-tests#6530
longevity test config:
Impact
after about 2 hours of running, seastar_io_queue_delay in more than 1c and client the client gets error:
according to @gleb-cloudius "It should be million times smaller"
How frequently does it reproduce?
at 5 runs on i4i.xlarge nodes, 4 fails 1 pass
seastar_io_queue_delay in passed run(4bc31d25-f6c4-4c39-95f1-b0f5e95db8b9)
at runs on i3en.large - 100% fails (according to @gleb-cloudius : "The instance has small memory (16G) so it probably flashes memtables a lot.")
Comments from email corresponding with developers
@xemul:
"There's a known issue found in the scheduler (seastar#1641, and a work
around discussion at seastar#1766) so they could be better. Starvation
time is too large, but it can be due to that issue."
Installation details
Kernel Version: 5.15.0-1043-aws
Scylla version (or git commit hash):
5.4.0~dev-20230904.9a3d57256a60with build-id4c60ca8c4afe862855242a77b77b35a377e373dcCluster size: 3 nodes (i4i.xlarge)
Scylla Nodes used in this run:
OS / Image:
ami-09a5684fbf0955c84(aws: undefined_region)Test:
longevity-schema-changes-3h-testTest id:
527c69a1-d03d-42ba-9b38-eba7b4e782c8Test name:
scylla-staging/artsiom_mishuta/longevity-schema-changes-3h-testTest config file(s):
Logs and commands
$ hydra investigate show-monitor 527c69a1-d03d-42ba-9b38-eba7b4e782c8$ hydra investigate show-logs 527c69a1-d03d-42ba-9b38-eba7b4e782c8Logs:
Jenkins job URL
Argus
The text was updated successfully, but these errors were encountered: