The Build HDR histogram summary is intermittently freezing

[juliayakovlev]

Packages

Scylla version: 2025.2.0~dev-20250301.0343235aa269 with build-id cdacab4180fe76c82a6aa1b48154d56318c29c93
Kernel Version: 6.8.0-1023-aws

Issue description

• This issue is a regression.
• It is unknown if this issue is a regression.

The Build HDR histogram summary is intermittently freezing, as seen in the recent test after the second node's decommissioning. Looks like it's stuck in sdcm.utils.hdrhistogram._HdrRangeHistogramBuilder._build_histogram_from_dir during file iteration.

        for hdr_file in hdr_files:
            if os.stat(hdr_file).st_size == 0:
                LOGGER.error("File %s is empty", hdr_file)
                continue

            file_range_histogram = self._build_histogram_from_file(hdr_file, hdr_tag)
            if file_range_histogram:
                collected_histograms.append(file_range_histogram)

This is from log :

< t:2025-03-02 12:24:09,801 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > 2025-03-02 12:24:09.799: (InfoEvent Severity.NORMAL) period_type=not-set event_id=0b16e1a2-2c65-440f-93e0-fab5de58c84e: message=FinishEvent - ShrinkCluster has done decommissioning 1 nodes

< t:2025-03-02 12:24:41,360 f:decorators.py   l:267  c:sdcm.utils.decorators p:DEBUG > hdr: [{'WRITE': {'start_time': 1740915920999.0, 'end_time': 1740916521000.0, 'stddev': 'percentile_99_9': 9.51, 'percentile_99_99': 36.77, 'percentile_99_999': 40.86, 'throughput': 17528}}]
< t:2025-03-02 12:24:41,370 f:tester.py       l:3816 c:PerformanceRegressionTest p:INFO  > Build HDR histogram (tags: ['WRITE-rt', 'READ-rt']) with start time: 1740915916.0573575, end time: 1740918249.8044257; for operation: mixed

< t:2025-03-02 12:24:51,824 f:hdrhistogram.py l:243  c:/home/ubuntu/scylla-cluster-tests/sdcm/utils/hdrhistogram.py p:DEBUG > The file '/home/ubuntu/sct-results/20250302-040951-961039/perf-latency-nemesis-ubuntu-loader-set-d492be8f/perf-latency-nemesis-ubuntu-loader-node-d492be8f-1/hdrh-cs-write-l1-c0-k1-b0d9fe7d-1a6c-4c1e-82fa-cce0605690ae.hdr' does not include the time interval from `1740915916.0573575` to `1740918249.8044257`
< t:2025-03-02 12:25:15,127 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-03-02 12:25:15,132 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-03-02 12:35:15,145 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-03-02 12:35:15,155 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-03-02 12:45:15,160 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []

We need more print statements for debugging.

Impact

Test stucks and timed out after 2 days

How frequently does it reproduce?

I saw that few times

Installation details

Cluster size: 3 nodes (i3en.2xlarge)

Scylla Nodes used in this run:

• perf-latency-nemesis-ubuntu-db-node-d492be8f-7 (34.205.246.108 | 10.12.1.104) (shards: 7)
• perf-latency-nemesis-ubuntu-db-node-d492be8f-6 (44.199.201.208 | 10.12.1.75) (shards: 7)
• perf-latency-nemesis-ubuntu-db-node-d492be8f-5 (44.195.1.81 | 10.12.1.41) (shards: 7)
• perf-latency-nemesis-ubuntu-db-node-d492be8f-4 (3.236.155.65 | 10.12.2.157) (shards: 7)
• perf-latency-nemesis-ubuntu-db-node-d492be8f-3 (18.215.186.105 | 10.12.2.113) (shards: 7)
• perf-latency-nemesis-ubuntu-db-node-d492be8f-2 (18.213.193.244 | 10.12.0.225) (shards: -1)
• perf-latency-nemesis-ubuntu-db-node-d492be8f-1 (18.209.237.195 | 10.12.0.160) (shards: 7)

OS / Image: ami-09240a6402ddbb8ce (aws: undefined_region)

Test: scylla-enterprise-perf-regression-latency-650gb-with-nemesis-rbno-disabled
Test id: d492be8f-f802-416d-bf31-dc236166c832
Test name: scylla-enterprise/perf-regression/scylla-enterprise-perf-regression-latency-650gb-with-nemesis-rbno-disabled
Test method: performance_regression_test.PerformanceRegressionTest.test_latency_mixed_with_nemesis
Test config file(s):

• perf-regression-latency-650gb-with-nemesis.yaml

Logs and commands

• Restore Monitor Stack command: $ hydra investigate show-monitor d492be8f-f802-416d-bf31-dc236166c832
• Restore monitor on AWS instance using Jenkins job
• Show all stored logs command: $ hydra investigate show-logs d492be8f-f802-416d-bf31-dc236166c832

Logs:

• perf-latency-nemesis-ubuntu-db-node-d492be8f-6 - https://cloudius-jenkins-test.s3.amazonaws.com/d492be8f-f802-416d-bf31-dc236166c832/20250302_040950/perf-latency-nemesis-ubuntu-db-node-d492be8f-6-d492be8f.tar.gz
• perf-latency-nemesis-ubuntu-db-node-d492be8f-2 - https://cloudius-jenkins-test.s3.amazonaws.com/d492be8f-f802-416d-bf31-dc236166c832/20250302_040950/perf-latency-nemesis-ubuntu-db-node-d492be8f-2-d492be8f.tar.gz
• perf-latency-nemesis-ubuntu-db-node-d492be8f-1 - https://cloudius-jenkins-test.s3.amazonaws.com/d492be8f-f802-416d-bf31-dc236166c832/20250302_040950/perf-latency-nemesis-ubuntu-db-node-d492be8f-1-d492be8f.tar.gz
• perf-latency-nemesis-ubuntu-db-node-d492be8f-4 - https://cloudius-jenkins-test.s3.amazonaws.com/d492be8f-f802-416d-bf31-dc236166c832/20250302_040950/perf-latency-nemesis-ubuntu-db-node-d492be8f-4-d492be8f.tar.gz

Jenkins job URL
Argus

[vponomaryov]

Example from the READ and WRITE tests has following errors for loader commands:

14:27:30  < t:2025-03-02 12:27:29,854 f:cluster.py      l:5353 c:sdcm.cluster         p:WARNING > Cannot find summary in c-stress results: ['\tat com.datastax.shaded.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:337)', '\tat com.datastax.shaded.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:776)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)', '\tat com.datastax.shaded.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)', '\tat com.datastax.shaded.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)', '\tat com.datastax.shaded.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)', '\tat java.lang.Thread.run(Thread.java:750)']
14:27:30  < t:2025-03-02 12:27:29,856 f:cluster.py      l:5353 c:sdcm.cluster         p:WARNING > Cannot find summary in c-stress results: ['\tat com.datastax.shaded.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:337)', '\tat com.datastax.shaded.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:776)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)', '\tat com.datastax.shaded.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)', '\tat com.datastax.shaded.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)', '\tat com.datastax.shaded.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)', '\tat java.lang.Thread.run(Thread.java:750)']
14:27:30  < t:2025-03-02 12:27:29,858 f:cluster.py      l:5353 c:sdcm.cluster         p:WARNING > Cannot find summary in c-stress results: ['\tat com.datastax.shaded.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:337)', '\tat com.datastax.shaded.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:776)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)', '\tat com.datastax.shaded.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)', '\tat com.datastax.shaded.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)', '\tat com.datastax.shaded.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)', '\tat java.lang.Thread.run(Thread.java:750)']
14:27:30  < t:2025-03-02 12:27:29,859 f:cluster.py      l:5353 c:sdcm.cluster         p:WARNING > Cannot find summary in c-stress results: ['\tat com.datastax.shaded.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:337)', '\tat com.datastax.shaded.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:776)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)', '\tat com.datastax.shaded.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)', '\tat com.datastax.shaded.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)', '\tat com.datastax.shaded.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)', '\tat com.datastax.shaded.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)', '\tat java.lang.Thread.run(Thread.java:750)']

But MIXED doesn't have it.
It has following:

22:01:19  < t:2025-03-02 20:01:05,340 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > 2025-03-02 20:01:05.297: (CassandraStressEvent Severity.NORMAL) period_type=end event_id=38cbdfc7-ed22-4594-b527-1ca91cdb9a48 duration=13h20m7s: node=Node perf-latency-nemesis-ubuntu-loader-node-d492be8f-4 [3.239.201.232 | 10.12.0.51]
22:01:19  < t:2025-03-02 20:01:05,340 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > stress_cmd=cassandra-stress mixed no-warmup cl=QUORUM duration=800m -schema 'replication(strategy=NetworkTopologyStrategy,replication_factor=3)' -mode cql3 native -rate 'threads=250 fixed=8750/s' -col 'size=FIXED(128) n=FIXED(8)' -pop 'dist=gauss(1..650000000,325000000,6500000)'
22:01:19  < t:2025-03-02 20:01:06,248 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > 2025-03-02 20:01:06.225: (CassandraStressEvent Severity.NORMAL) period_type=end event_id=fad67395-c2bf-4b82-86e4-1fd7dd1f9da2 duration=13h20m8s: node=Node perf-latency-nemesis-ubuntu-loader-node-d492be8f-2 [3.235.47.84 | 10.12.2.68]
22:01:19  < t:2025-03-02 20:01:06,248 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > stress_cmd=cassandra-stress mixed no-warmup cl=QUORUM duration=800m -schema 'replication(strategy=NetworkTopologyStrategy,replication_factor=3)' -mode cql3 native -rate 'threads=250 fixed=8750/s' -col 'size=FIXED(128) n=FIXED(8)' -pop 'dist=gauss(1..650000000,325000000,6500000)'
22:01:19  < t:2025-03-02 20:01:06,261 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > 2025-03-02 20:01:06.251: (CassandraStressEvent Severity.NORMAL) period_type=end event_id=b5f3d244-5312-4b74-93ae-d880f19e3aeb duration=13h20m8s: node=Node perf-latency-nemesis-ubuntu-loader-node-d492be8f-1 [44.199.252.33 | 10.12.2.73]
22:01:19  < t:2025-03-02 20:01:06,261 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > stress_cmd=cassandra-stress mixed no-warmup cl=QUORUM duration=800m -schema 'replication(strategy=NetworkTopologyStrategy,replication_factor=3)' -mode cql3 native -rate 'threads=250 fixed=8750/s' -col 'size=FIXED(128) n=FIXED(8)' -pop 'dist=gauss(1..650000000,325000000,6500000)'
22:01:19  < t:2025-03-02 20:01:06,267 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > 2025-03-02 20:01:06.265: (CassandraStressEvent Severity.NORMAL) period_type=end event_id=b017dc82-c966-409a-8baa-2b398534c06b duration=13h20m8s: node=Node perf-latency-nemesis-ubuntu-loader-node-d492be8f-3 [34.235.150.83 | 10.12.2.241]
22:01:19  < t:2025-03-02 20:01:06,267 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > stress_cmd=cassandra-stress mixed no-warmup cl=QUORUM duration=800m -schema 'replication(strategy=NetworkTopologyStrategy,replication_factor=3)' -mode cql3 native -rate 'threads=250 fixed=8750/s' -col 'size=FIXED(128) n=FIXED(8)' -pop 'dist=gauss(1..650000000,325000000,6500000)'
08:15:25  < t:2025-03-04 06:15:12,263 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:CRITICAL > 2025-03-04 06:15:12.262: (TestTimeoutEvent Severity.CRITICAL) period_type=not-set event_id=c89d597e-8dc9-4d12-b189-2381654863f4, Test started at 2025-03-02 04:15:11, reached it's timeout (3000 minute)
08:15:25  F< t:2025-03-04 06:15:12,271 f:tester.py       l:2947 c:PerformanceRegressionTest p:INFO  > Save nodes user schema in the files
08:15:25  < t:2025-03-04 06:15:12,272 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > 2025-03-04 06:15:12.270: (InfoEvent Severity.NORMAL) period_type=not-set event_id=1535d789-f488-45a6-b9ea-309645d7d497: message=TEST_END


08:18:56  ======================================================================
08:18:56  FAIL: test_latency_mixed_with_nemesis (performance_regression_test.PerformanceRegressionTest)
08:18:56  ----------------------------------------------------------------------
08:18:56  Traceback (most recent call last):
08:18:56    File "/home/ubuntu/scylla-cluster-tests/sdcm/sct_events/events_analyzer.py", line 50, in run
08:18:56      raise TestFailure(f"Got critical event: {event}")
08:18:56  sdcm.sct_events.events_analyzer.TestFailure: Got critical event: (TestTimeoutEvent Severity.CRITICAL) period_type=not-set event_id=c89d597e-8dc9-4d12-b189-2381654863f4, Test started at 2025-03-02 04:15:11, reached it's timeout (3000 minute)
08:18:56  
08:18:56  ----------------------------------------------------------------------
08:18:56  Ran 1 test in 180523.197s
08:18:56  
08:18:56 
 FAILED (failures=1, errors=1)
09:09:39  Cancelling nested steps due to timeout
09:09:40  Sending interrupt signal to process
09:09:41  time="2025-03-04T07:09:40Z" level=error msg="error waiting for container: command [ssh -o ConnectTimeout=30 -T -l ubuntu -- 3.237.76.138 docker system dial-stdio] has exited with exit status 255, make sure the URL is valid, and Docker 18.09 or later is installed on the remote host: stderr="
09:09:41  command [ssh -o ConnectTimeout=30 -T -l ubuntu -- 3.237.76.138 docker system dial-stdio] has exited with exit status 255, make sure the URL is valid, and Docker 18.09 or later is installed on the remote host: stderr=
09:09:41  Cleaning SSH agent
09:09:41  Terminated
09:09:42  script returned exit code 143
09:09:42  [Pipeline] }
09:09:42  [Pipeline] // dir
09:09:42  [Pipeline] }
09:09:42  [Pipeline] // timeout
09:09:42  [Pipeline] }
09:09:42  [Pipeline] // withBuildUser
09:09:42  [Pipeline] }
09:09:42  Timeout has been exceeded
09:09:42  org.jenkinsci.plugins.workflow.actions.ErrorAction$ErrorId: 73897e60-9494-4c71-b261-3c1ef85b572c
09:09:42  Setting overall build result to ABORTED

Then logs were not gathered:

09:10:58  java.io.StreamCorruptedException: invalid stream header: 636F7272
09:10:58  	at java.base/java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:989)
09:10:58  	at java.base/java.io.ObjectInputStream.<init>(ObjectInputStream.java:416)
09:10:58  	at hudson.remoting.ObjectInputStreamEx.<init>(ObjectInputStreamEx.java:50)
09:10:58  	at hudson.remoting.Command.readFrom(Command.java:141)
09:10:58  	at hudson.remoting.Command.readFrom(Command.java:127)
09:10:58  	at hudson.remoting.AbstractSynchronousByteArrayCommandTransport.read(AbstractSynchronousByteArrayCommandTransport.java:35)
09:10:58  	at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:62)

SCT runner is deleted already, so there are no saved streamed C-S logs to get to know for sure what happened.

Monitoring screenshots:

The real load stopped on 2nd at about 20:00...

So, my guess is that loader stress commands hung and didn't return and it led to the test timeout where logs were not saved.

For now the solution is to rerun.

[vponomaryov]

@juliayakovlev

I see you commented in the Argus with the following text:

< t:2025-03-02 12:23:45,802 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > 2025-03-02 12:23:45.800: (InfoEvent Severity.NORMAL) period_type=not-set event_id=20bc7191-3bcc-4713-aa01-87974e555e8d: message=FinishEvent - ShrinkCluster has done decommissioning a node Node perf-latency-nemesis-ubuntu-db-node-d492be8f-4 [3.236.155.65 | 10.12.2.157]
< t:2025-03-02 12:24:09,801 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > 2025-03-02 12:24:09.799: (InfoEvent Severity.NORMAL) period_type=not-set event_id=0b16e1a2-2c65-440f-93e0-fab5de58c84e: message=FinishEvent - ShrinkCluster has done decommissioning 1 nodes

< t:2025-03-02 12:24:41,360 f:decorators.py   l:267  c:sdcm.utils.decorators p:DEBUG > hdr: [{'WRITE': {'start_time': 1740915920999.0, 'end_time': 1740916521000.0, 'stddev': 'percentile_99_9': 9.51, 'percentile_99_99': 36.77, 'percentile_99_999': 40.86, 'throughput': 17528}}]
< t:2025-03-02 12:24:41,370 f:tester.py       l:3816 c:PerformanceRegressionTest p:INFO  > Build HDR histogram (tags: ['WRITE-rt', 'READ-rt']) with start time: 1740915916.0573575, end time: 1740918249.8044257; for operation: mixed
...............................................................................................
...............................................................................................
< t:2025-03-02 12:24:51,824 f:hdrhistogram.py l:243  c:/home/ubuntu/scylla-cluster-tests/sdcm/utils/hdrhistogram.py p:DEBUG > The file '/home/ubuntu/sct-results/20250302-040951-961039/perf-latency-nemesis-ubuntu-loader-set-d492be8f/perf-latency-nemesis-ubuntu-loader-node-d492be8f-1/hdrh-cs-write-l1-c0-k1-b0d9fe7d-1a6c-4c1e-82fa-cce0605690ae.hdr' does not include the time interval from `1740915916.0573575` to `1740918249.8044257`
< t:2025-03-02 12:25:15,127 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-03-02 12:25:15,132 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-03-02 12:35:15,145 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-03-02 12:35:15,155 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-03-02 12:45:15,160 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []

Tail part is absent in the Jenkins output.
So, it means you used alive yet SCT runner.

In this case we should trigger logs gathering on this SCT runner which will do everything like in a CI job.
Example: ./docker/env/hydra.sh --execute-on-runner %sct-runner-ip% collect-logs --backend aws.

Then, after gathering logs, we should clean up the resources.

For now I deleted DB nodes and loaders.
Left only monitoring node for case it is needed.

[fruch]

I don't think it's have anything todo with summary but with the fact we lost the jenkins builder

closing for now, reopen if happens again

[juliayakovlev]

It happens again in https://argus.scylladb.com/tests/scylla-cluster-tests/cc17ad62-1cf0-4288-aaa3-ab1343c5f2e3

< t:2025-03-23 12:59:53,308 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > stress_cmd=cassandra-stress mixed no-warmup cl=QUORUM duration=800m -schema 'replication(strategy=NetworkTopologyStrategy,replication_factor=3)' -mode cql3 native -rate 'threads=250 fixed=8750/s' -col 'size=FIXED(128) n=FIXED(8)' -pop 'dist=gauss(1..650000000,325000000,6500000)'
< t:2025-03-23 12:59:53,309 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > 2025-03-23 12:59:53.304: (CassandraStressEvent Severity.NORMAL) period_type=end event_id=d0e59a72-5a64-46d5-9cab-3ff7290b734b duration=13h20m7s: node=Node perf-latency-nemesis-ubuntu-loader-node-cc17ad62-2 [44.222.183.6 | 10.12.3.39]
< t:2025-03-23 12:59:53,309 f:file_logger.py  l:101  c:sdcm.sct_events.file_logger p:INFO  > stress_cmd=cassandra-stress mixed no-warmup cl=QUORUM duration=800m -schema 'replication(strategy=NetworkTopologyStrategy,replication_factor=3)' -mode cql3 native -rate 'threads=250 fixed=8750/s' -col 'size=FIXED(128) n=FIXED(8)' -pop 'dist=gauss(1..650000000,325000000,6500000)'
< t:2025-03-23 13:06:36,539 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-03-23 13:06:36,544 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-03-23 13:16:36,550 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-03-23 13:16:36,558 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []

Load was stopped at ~ 2025-03-23 12:58:00

According to SCT log - c-s commands were completed successfully.
Then HDR analysing was started and did not finished stuck.

Connecting to loader 1

1. Logs

• journalctl - nothing in the journalctl in the time frame from Mar 23 00:25:20 to Mar 23 00:47:38

Mar 23 00:09:57 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 scylla[7102]: ============ Started disruption disrupt_run_unique_sequence (RunUniqueSequence nemesis) on the target node 'N
ode perf-latency-nemesis-ubuntu-db-node-cc17ad62-2 [44.204.127.83 | 10.12.1.156]' ============
Mar 23 00:17:01 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 CRON[7134]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Mar 23 00:17:01 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 CRON[7135]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Mar 23 00:17:01 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 CRON[7134]: pam_unix(cron:session): session closed for user root
Mar 23 00:20:57 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 sshd[7101]: Timeout, client not responding from user ubuntu 10.12.2.6 port 55098
Mar 23 00:20:57 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 sshd[7041]: pam_unix(sshd:session): session closed for user ubuntu
Mar 23 00:20:57 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 systemd[1]: session-11.scope: Deactivated successfully.
Mar 23 00:20:57 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 systemd-logind[535]: Session 11 logged out. Waiting for processes to exit.
Mar 23 00:20:57 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 systemd-logind[535]: Removed session 11.
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]: 2025-03-23 00:25:20 WARN EC2RoleProvider Failed to connect to Systems Manager with 
instance profile role credentials. Err: retrieved credentials failed to report to ssm. Error: EC2RoleRequestError: no EC2 instance role found
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]: caused by: EC2MetadataError: failed to make EC2Metadata request
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]: <?xml version="1.0" encoding="iso-8859-1"?>
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]: <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]:                  "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]: <html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]:  <head>
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]:   <title>404 - Not Found</title>
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]:  </head>
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]:  <body>
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]:   404 - Not Found
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]:  </body>
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]: </html>
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]:         status code: 404, request id:
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]: 2025-03-23 00:25:20 ERROR EC2RoleProvider Failed to connect to Systems Manager with SSM role credentials. error calling RequestManagedInstanceRoleToken: AccessDeniedException: Systems Manager's instance management role is not configured for account: 797456418907
Mar 23 00:25:20 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 amazon-ssm-agent.amazon-ssm-agent[524]:         status code: 400, request id: 38c073fd-51c5-4a9a-b1b2-edea469f96d1
Mar 23 00:47:38 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 systemd[1]: Starting Message of the Day...
Mar 23 00:47:48 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 50-motd-news[7306]:  * Ubuntu Pro delivers the most comprehensive open source security and
Mar 23 00:47:48 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 50-motd-news[7306]:    compliance features.
Mar 23 00:47:48 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 50-motd-news[7306]:    https://ubuntu.com/aws/pro
Mar 23 00:47:48 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 systemd[1]: motd-news.service: Deactivated successfully.
Mar 23 00:47:48 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 systemd[1]: Finished Message of the Day.

• /var/log/messages - nothing in the messages logs in the time frame from Mar 23 00:09:57 to Mar 23 08:45:58

Mar 23 00:09:57 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 scylla[7102]: ============ Started disruption disrupt_run_unique_sequence (RunUniqueSequence nemesis) on the target node 'Node perf-latency-nemesis-ubuntu-db-node-cc17ad62-2 [44.204.127.83 | 10.12.1.156]' ============
Mar 23 08:45:58 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 kernel: loop6: detected capacity change from 0 to 113384
Mar 24 00:00:00 perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1 syslog-ng[2537]: WARNING: Configuration file format is too old, syslog-ng is running in compatibility mode. Please update it to use the syslog-ng 3.35 format at your time of convenience. To upgrade the configuration, please review the warnings about incompatible changes printed by syslog-ng, and once completed change the @version header at the top of the configuration file; config-version='3.27'

2. Two tail processes running on the loader
   pid 5650 status - sleeping

ubuntu@perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1:~$ sudo less /proc/5650/task/5650/status | grep -i stat
State:	S (sleeping)

ubuntu      5650    5391  0 Mar22 ?        00:00:00 tail -f hdrh-cs-write-l1-c0-k1-02d2d794-2a40-4043-8220-cd5e105030ae.hdr
ubuntu@perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1:~$ sudo strace -s 99 -ffp  5650
strace: Process 5650 attached
pselect6(5, [1 4], NULL, NULL, NULL, NULL

ubuntu@perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1:~$ sudo cat /proc/5650/stack
[<0>] do_select+0x779/0x850
[<0>] core_sys_select+0x1d2/0x430
[<0>] do_pselect.constprop.0+0xca/0x180
[<0>] __x64_sys_pselect6+0x5f/0xb0
[<0>] x64_sys_call+0xd4f/0x2570
[<0>] do_syscall_64+0x56/0x90
[<0>] entry_SYSCALL_64_after_hwframe+0x73/0xdd

pid 6556 status - sleeping

ubuntu@perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1:~$ sudo less /proc/6556/task/6556/status | grep -i stat
State:	S (sleeping)

ubuntu      6556    6538  0 Mar22 ?        00:00:01 tail -f hdrh-cs-mixed-l1-c0-k1-00bab7c6-ef91-49d4-82e4-d1e7d73b3ce6.hdr
ubuntu@perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1:~$ sudo strace -s 99 -ffp 6556
strace: Process 6556 attached
pselect6(5, [1 4], NULL, NULL, NULL, NULL

ubuntu@perf-latency-nemesis-ubuntu-loader-node-cc17ad62-1:~$ sudo cat /proc/6556/stack
[<0>] do_select+0x779/0x850
[<0>] core_sys_select+0x1d2/0x430
[<0>] do_pselect.constprop.0+0xca/0x180
[<0>] __x64_sys_pselect6+0x5f/0xb0
[<0>] x64_sys_call+0xd4f/0x2570
[<0>] do_syscall_64+0x56/0x90
[<0>] entry_SYSCALL_64_after_hwframe+0x73/0xdd

[juliayakovlev]

Reproduced again

< t:2025-04-06 06:33:28,217 f:hdrhistogram.py l:248  c:/home/ubuntu/scylla-cluster-tests/sdcm/utils/hdrhistogram.py p:DEBUG > Collect data from the file '/home/ubuntu/sct-results/20250406-03
1024-679863/perf-latency-nemesis-ubuntu-loader-set-85b23e44/perf-latency-nemesis-ubuntu-loader-node-85b23e44-2/hdrh-cs-mixed-l2-c0-k1-61bfff2b-07d9-4fa8-aa45-1f189a185c96.hdr' (time interval
 from `1743919371.107428` to `1743921171.7271893`)
< t:2025-04-06 06:33:28,221 f:hdrhistogram.py l:243  c:/home/ubuntu/scylla-cluster-tests/sdcm/utils/hdrhistogram.py p:DEBUG > The file '/home/ubuntu/sct-results/20250406-031024-679863/perf-l
atency-nemesis-ubuntu-loader-set-85b23e44/perf-latency-nemesis-ubuntu-loader-node-85b23e44-2/hdrh-cs-write-l2-c0-k1-bf7ac55f-4c3c-4ea2-9668-feff6048a814.hdr' does not include the time interv
al from `1743919371.107428` to `1743921171.7271893`
< t:2025-04-06 06:36:56,107 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-04-06 06:36:56,113 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-04-06 06:46:56,118 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-04-06 06:46:56,124 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-04-06 06:56:56,135 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-04-06 06:56:56,145 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-04-06 07:06:56,151 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-04-06 07:06:56,157 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-04-06 07:16:56,162 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-04-06 07:16:56,168 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []
< t:2025-04-06 07:26:56,174 f:commit_log_check_thread.py l:205  c:CommitLogCheckThread p:DEBUG > overflow_commit_log_directory: []
< t:2025-04-06 07:26:56,179 f:commit_log_check_thread.py l:214  c:CommitLogCheckThread p:DEBUG > zero_free_segments: []

Packages

Scylla version: 2025.2.0~dev-20250405.431de48df9ac with build-id 2257b16c1eaee2237ca7c7d409374807a992abb2
Kernel Version: 6.8.0-1026-aws

Issue description

• This issue is a regression.
• It is unknown if this issue is a regression.

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: 3 nodes (i3en.2xlarge)

Scylla Nodes used in this run:

• perf-latency-nemesis-ubuntu-db-node-85b23e44-3 (35.175.109.68 | 10.12.2.122) (shards: 7)
• perf-latency-nemesis-ubuntu-db-node-85b23e44-2 (44.204.242.104 | 10.12.0.160) (shards: 7)
• perf-latency-nemesis-ubuntu-db-node-85b23e44-1 (44.193.214.39 | 10.12.2.93) (shards: 7)

OS / Image: ami-035fb35d0ab9aeae4 (aws: undefined_region)

Test: scylla-enterprise-perf-regression-latency-650gb-with-nemesis-rbno-disabled
Test id: 85b23e44-bfec-454a-8ddc-73cd0dfb9a86
Test name: scylla-enterprise/perf-regression/scylla-enterprise-perf-regression-latency-650gb-with-nemesis-rbno-disabled
Test method: performance_regression_test.PerformanceRegressionTest.test_latency_mixed_with_nemesis
Test config file(s):

• perf-regression-latency-650gb-with-nemesis.yaml

Logs and commands

• Restore Monitor Stack command: $ hydra investigate show-monitor 85b23e44-bfec-454a-8ddc-73cd0dfb9a86
• Restore monitor on AWS instance using Jenkins job
• Show all stored logs command: $ hydra investigate show-logs 85b23e44-bfec-454a-8ddc-73cd0dfb9a86

Logs:

• db-cluster-85b23e44.tar.zst - https://cloudius-jenkins-test.s3.amazonaws.com/85b23e44-bfec-454a-8ddc-73cd0dfb9a86/20250407_082740/db-cluster-85b23e44.tar.zst
• sct-runner-events-85b23e44.tar.zst - https://cloudius-jenkins-test.s3.amazonaws.com/85b23e44-bfec-454a-8ddc-73cd0dfb9a86/20250407_082740/sct-runner-events-85b23e44.tar.zst
• sct-85b23e44.log.tar.zst - https://cloudius-jenkins-test.s3.amazonaws.com/85b23e44-bfec-454a-8ddc-73cd0dfb9a86/20250407_082740/sct-85b23e44.log.tar.zst
• loader-set-85b23e44.tar.zst - https://cloudius-jenkins-test.s3.amazonaws.com/85b23e44-bfec-454a-8ddc-73cd0dfb9a86/20250407_082740/loader-set-85b23e44.tar.zst
• monitor-set-85b23e44.tar.zst - https://cloudius-jenkins-test.s3.amazonaws.com/85b23e44-bfec-454a-8ddc-73cd0dfb9a86/20250407_082740/monitor-set-85b23e44.tar.zst

Jenkins job URL
Argus