scylla 5 segfaults on start

[Michael Wohlwend]

Hi,
scylla 5 doesn't start, gets signal 11.
one error is: "could not initialize seastar: io-group limits are too low. "
Creation of per_event based stall detector failed, falling back to posix
timer::system_error (error system:13, perf_event_open() failed: permission
denied),
Segmentation fault on shard 1"
How to adjust io-group limits for seastar? (if that's the real cause of the
fail...)
Thanks,
Michael

[Avi Kivity]

The new I/O scheduler doesn't like your disks.


Please provide your io-properties.yaml.


Pavel, I think we should increase the latency goal instead of aborting
when encountering a slow disk.

[Michael Wohlwend]

Am Dienstag, 5. Juli 2022, 13:22:21 CEST schrieb Avi Kivity:
> The new I/O scheduler doesn't like your disks.
>
>
> Please provide your io-properties.yaml.
>

cat io_properties.yaml
disks:
- mountpoint: /data/scylla-base/commitlog
read_iops: 219143
read_bandwidth: 3168451840
write_iops: 90805
write_bandwidth: 551656384
- mountpoint: /data
read_iops: 753
read_bandwidth: 522762976
write_iops: 4402
write_bandwidth: 505988832


<7data are two 7TB hdd as raid0
/commitlog is one 512GB ssd

[Pavel Emelyanov]

On 05.07.2022 14:22, Avi Kivity wrote:
> The new I/O scheduler doesn't like your disks.
>
>
> Please provide your io-properties.yaml.
>
>
> Pavel, I think we should increase the latency goal instead of aborting when encountering a slow disk.

Absolutely. Actually, io_queue::config generate_config() tries to do it already, can I see
the full start log? It should contain the "... using <number>ms IO latency goal" message.

[Michael Wohlwend]

Am Mittwoch, 6. Juli 2022, 07:08:28 CEST schrieb Pavel Emelyanov:
> On 05.07.2022 14:22, Avi Kivity wrote:
> > Pavel, I think we should increase the latency goal instead of aborting
> > when encountering a slow disk.
> Absolutely. Actually, io_queue::config generate_config() tries to do it
> already, can I see the full start log? It should contain the "... using
> <number>ms IO latency goal" message.

I don't see 'latency goal' in the log, but what is this error:
"perf_event_open() failed: Permission denied)" ?



Jul 05 10:44:24 mw-scylla09 systemd[1]: Starting Scylla Server...
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Saving the original
irqbalance configuration is in /etc/default/irqbalance.scylla.orig
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Restarting irqbalance:
going to ban the following IRQ numbers: 126, 153, 154, 155, 156, 157, 158,
159, 160, 161, 137, 138, 139, 140, 141, 142, 143, 144 ...
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Restarting irqbalance via
systemctl...
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting non-NVMe disks:
sda1, sdb1...
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
proc/irq/161/smp_affinity
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Writing 'none' to /sys/
devices/pci0000:00/0000:00:17.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/
queue/scheduler
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Writing '2' to /sys/
devices/pci0000:00/0000:00:17.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/
queue/nomerges
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Writing 'none' to /sys/
devices/pci0000:00/0000:00:17.0/ata4/host3/target3:0:0/3:0:0:0/block/sdb/
queue/scheduler
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Writing '2' to /sys/
devices/pci0000:00/0000:00:17.0/ata4/host3/target3:0:0/3:0:0:0/block/sdb/
queue/nomerges
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting NVMe disks:
nvme1n1p1...
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Writing 'none' to /sys/
devices/pci0000:00/0000:00:1d.0/0000:05:00.0/nvme/nvme1/nvme1n1/queue/
scheduler
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Writing '2' to /sys/
devices/pci0000:00/0000:00:1d.0/0000:05:00.0/nvme/nvme1/nvme1n1/queue/nomerges
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting a physical
interface enp1s0f1...
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Distributing all IRQs
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
proc/irq/137/smp_affinity
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
proc/irq/138/smp_affinity
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
proc/irq/139/smp_affinity
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
proc/irq/140/smp_affinity
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
proc/irq/141/smp_affinity
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
proc/irq/142/smp_affinity
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
proc/irq/143/smp_affinity
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
proc/irq/144/smp_affinity
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 000000ff in /
sys/class/net/enp1s0f1/queues/rx-7/rps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 000000ff in /
sys/class/net/enp1s0f1/queues/rx-5/rps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 000000ff in /
sys/class/net/enp1s0f1/queues/rx-3/rps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 000000ff in /
sys/class/net/enp1s0f1/queues/rx-1/rps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 000000ff in /
sys/class/net/enp1s0f1/queues/rx-6/rps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 000000ff in /
sys/class/net/enp1s0f1/queues/rx-4/rps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 000000ff in /
sys/class/net/enp1s0f1/queues/rx-2/rps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 000000ff in /
sys/class/net/enp1s0f1/queues/rx-0/rps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting
net.core.rps_sock_flow_entries to 32768
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting limit 4096 in /sys/
class/net/enp1s0f1/queues/rx-7/rps_flow_cnt
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting limit 4096 in /sys/
class/net/enp1s0f1/queues/rx-5/rps_flow_cnt
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting limit 4096 in /sys/
class/net/enp1s0f1/queues/rx-3/rps_flow_cnt
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting limit 4096 in /sys/
class/net/enp1s0f1/queues/rx-1/rps_flow_cnt
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting limit 4096 in /sys/
class/net/enp1s0f1/queues/rx-6/rps_flow_cnt
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting limit 4096 in /sys/
class/net/enp1s0f1/queues/rx-4/rps_flow_cnt
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting limit 4096 in /sys/
class/net/enp1s0f1/queues/rx-2/rps_flow_cnt
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting limit 4096 in /sys/
class/net/enp1s0f1/queues/rx-0/rps_flow_cnt
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Trying to enable ntuple
filtering HW offload for enp1s0f1...ok
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000001 in /
sys/class/net/enp1s0f1/queues/tx-6/xps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000010 in /
sys/class/net/enp1s0f1/queues/tx-4/xps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000002 in /
sys/class/net/enp1s0f1/queues/tx-2/xps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000020 in /
sys/class/net/enp1s0f1/queues/tx-0/xps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000004 in /
sys/class/net/enp1s0f1/queues/tx-7/xps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000040 in /
sys/class/net/enp1s0f1/queues/tx-5/xps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000008 in
perf_event_open() failed: Permission denied)/sys/class/net/enp1s0f1/queues/
tx-3/xps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Setting mask 00000080 in /
sys/class/net/enp1s0f1/queues/tx-1/xps_cpus
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Writing '4096' to /proc/
sys/net/core/somaxconn
Jul 05 10:44:25 mw-scylla09 scylla_prepare[30691]: Writing '4096' to /proc/
sys/net/ipv4/tcp_max_syn_backlog
Jul 05 10:44:25 mw-scylla09 scylla[30755]: Scylla version
5.0.0-0.20220628.c9e79cb4a with build-id
daef393310f38c086a6e5070c8f2013684973a48 starting ...
Jul 05 10:44:25 mw-scylla09 scylla[30755]: command used: "/usr/bin/scylla --
log-to-syslog 1 --log-to-stdout 0 --default-log-level info --network-stack
posix --memory=50G --io-properties-file=/etc/scylla.d/io_properties.yaml --
cpuset 1-7 --lock-memory=1"
Jul 05 10:44:25 mw-scylla09 scylla[30755]: parsed command line options: [log-
to-syslog, (positional) 1, log-to-stdout, (positional) 0, default-log-level,
(positional) info, network-stack, (positional) posix, memory: 50G, io-
properties-file: /etc/scylla.d/io_properties.yaml, cpuset, (positional) 1-7,
lock-memory: 1]
Jul 05 10:44:25 mw-scylla09 scylla[30755]: [shard 0] seastar - Creation of
perf_event based stall detector failed, falling back to posix timer:
std::system_error (error system:13, perf_event_open() failed: Permission
denied)
Jul 05 10:44:25 mw-scylla09 scylla[30755]: [shard 0] seastar - Created fair
group io-queue-66309, capacity rate 28050:792112, limit 12582912, rate
16777216 (factor 1), threshold 79270
Jul 05 10:44:25 mw-scylla09 scylla[30755]: [shard 0] seastar - Created io
group dev(66309), length limit 2097152:262144, rate 28050304:792112960
Jul 05 10:44:25 mw-scylla09 scylla[30755]: [shard 0] seastar - Created io
queue dev(66309) capacities: 512:79270/199787 1024:81981/215355
2048:87403/246490 4096:98247/308760 8192:119936/433301 16384:163313/682382
32768:250068/1180544 65536:423578/2176868 131072:770597/4169516
Jul 05 10:44:25 mw-scylla09 scylla[30755]: [shard 0] seastar - Created fair
group io-queue-2304, capacity rate 96:130690, limit 12582912, rate 16777216
(factor 1), threshold 3686448
Jul 05 10:44:25 mw-scylla09 scylla[30755]: Could not initialize seastar:
std::runtime_error (IO-group limits are too low)
Jul 05 10:44:25 mw-scylla09 scylla[30755]: [shard 1] seastar - Creation of
perf_event based stall detector failed, falling back to posix timer:
std::system_error (error system:13, perf_event_open() failed: Permission
denied)
Jul 05 10:44:25 mw-scylla09 scylla[30755]: Segmentation fault on shard 1.
Jul 05 10:44:25 mw-scylla09 scylla[30755]: Backtrace:
Jul 05 10:44:25 mw-scylla09 scylla[30755]: 0x42c8f58
Jul 05 10:44:25 mw-scylla09 scylla[30755]: 0x42f9a26
Jul 05 10:44:25 mw-scylla09 scylla[30755]: 0x7f1cde706a1f
Jul 05 10:44:25 mw-scylla09 scylla[30755]: 0x42f9e33
Jul 05 10:44:25 mw-scylla09 scylla[30755]: 0x42addea
Jul 05 10:44:25 mw-scylla09 scylla[30755]: /opt/scylladb/libreloc/
libpthread.so.0+0x9298
Jul 05 10:44:25 mw-scylla09 scylla[30755]: /opt/scylladb/libreloc/libc.so.
6+0x100352
Jul 05 10:44:25 mw-scylla09 scylla[30755]: [shard 6] seastar - Creation of
perf_event based stall detector failed, falling back to posix timer:
std::system_error (error system:13, perf_event_open() failed: Permission
denied)
Jul 05 10:44:45 mw-scylla09 systemd[1]: scylla-server.service: Main process
exited, code=killed, status=11/SEGV
Jul 05 10:44:45 mw-scylla09 systemd[1]: scylla-server.service: Failed with
result 'signal'.
Jul 05 10:44:45 mw-scylla09 systemd[1]: Failed to start Scylla Server.
Jul 05 10:44:45 mw-scylla09 systemd[1]: scylla-server.service: Service
RestartSec=100ms expired, scheduling restart.
Jul 05 10:44:45 mw-scylla09 systemd[1]: scylla-server.service: Scheduled
restart job, restart counter is at 1.
Jul 05 10:44:45 mw-scylla09 systemd[1]: Stopped Scylla Server.

[Avi Kivity]

On 06/07/2022 11.15, Michael Wohlwend wrote:
> Am Mittwoch, 6. Juli 2022, 07:08:28 CEST schrieb Pavel Emelyanov:
>> On 05.07.2022 14:22, Avi Kivity wrote:
>>> Pavel, I think we should increase the latency goal instead of aborting
>>> when encountering a slow disk.
>> Absolutely. Actually, io_queue::config generate_config() tries to do it
>> already, can I see the full start log? It should contain the "... using
>> <number>ms IO latency goal" message.
> I don't see 'latency goal' in the log, but what is this error:
> "perf_event_open() failed: Permission denied)" ?
>

It is benign. Seastar wants to use hardware performance counters for the
stall detector, your configuration denies it, so it falls back to some
other timer. I guess we need to adjust the message.

[Pavel Emelyanov]

On 05.07.2022 14:22, Avi Kivity wrote:

> The new I/O scheduler doesn't like your disks.
>
>
> Please provide your io-properties.yaml.
>
>
> Pavel, I think we should increase the latency goal instead of aborting when encountering a slow disk.

Avi, 5.0 is missing seastar commit f450489834440ae79764b8e067921594f1f5529a
But it's not all, with this particular io-properties th auto-adjustments is 0.5% off and still throws :(

Michael, you can workaround with the --io-latency-goal-ms=2.67 option.

[Avi Kivity]

On 06/07/2022 16.06, Pavel Emelyanov wrote:
>
>
> On 05.07.2022 14:22, Avi Kivity wrote:
>> The new I/O scheduler doesn't like your disks.
>>
>>
>> Please provide your io-properties.yaml.
>>
>>
>> Pavel, I think we should increase the latency goal instead of
>> aborting when encountering a slow disk.
>
> Avi, 5.0 is missing seastar commit
> f450489834440ae79764b8e067921594f1f5529a
> But it's not all, with this particular io-properties th
> auto-adjustments is 0.5% off and still throws :(
>
> Michael, you can workaround with the --io-latency-goal-ms=2.67 option.
>

With your HDDs, you'll get better throughput with =10.

[Michael Wohlwend]

Am Mittwoch, 6. Juli 2022, 16:26:19 CEST schrieb Avi Kivity:
> On 06/07/2022 16.06, Pavel Emelyanov wrote:
> > On 05.07.2022 14:22, Avi Kivity wrote:
> >> The new I/O scheduler doesn't like your disks.
> >>
> >>
> >> Please provide your io-properties.yaml.
> >>
> >>
> >> Pavel, I think we should increase the latency goal instead of
> >> aborting when encountering a slow disk.
> >
> > Avi, 5.0 is missing seastar commit
> > f450489834440ae79764b8e067921594f1f5529a
> > But it's not all, with this particular io-properties th
> > auto-adjustments is 0.5% off and still throws :(
> >
> > Michael, you can workaround with the --io-latency-goal-ms=2.67 option.
>
> With your HDDs, you'll get better throughput with =10.

interessting,
thanks.

I wanted to try that on another host.
It's a little difficult, because there are only 16G Ram available.
The values in io_properties.yaml for my hdd are much lower than on the
servers:

read_iops: 311
read_bandwidth: 128894032
write_iops:305
write_bandwidth: 130344512

This time I get this line in the log:

IO latency goal 0.75 is too low for device / , using 9.00ms instead.

I don't understand why this doesn't show up on the other cluster, moreover as
the values are much lower...
This is the same scylla version and build number for bullseye.


Michael

[Avi Kivity]

It's just a bug. Seastar tried to increase the latency goal for both,
succeeded in this one, but confused itself with the other and crashed.
It's considering both io_properties.yaml, the number of shards, and
NUMA-ness, so it's not surprising it got confused.

[Michael Wohlwend]

Hi,

will there be bug fix release for this?

Michael

[Avi Kivity]

Yes. The fix was applied to Seastar and is making its way to master and
from there to 5.0.1.


Meanwhile I recommend proceeding with --io-latency-goal. It makes sense
to set it explicitly for spinning disks anyway.

[Michael Wohlwend]

thanks for the answer, yes I will add this option to the config.

Michael