Arvados

from gitter:

"We have tried this with both Singularity 3.7.4 and 3.9.1 but the error pops up in both versions."

Just to confirm, slurm is scheduling more than one job at a time on these nodes? E.g. with 4 cores that 4 jobs scheduled per core?

Peter Amstutz wrote:

Just to confirm, slurm is scheduling more than one job at a time on these nodes? E.g. with 4 cores that 4 jobs scheduled per core?

In the case of `arv-get`: yes. `bcftools convert` is using two cores per job, so two per node in the second workflow step.

I can confirm that with 4 nodes (4 cores each), this minimal reproducer fails with the same error on the same system:

$ cat echo-many.cwl 
#!/usr/bin/env cwl-runner

cwlVersion: v1.0
class: Workflow

requirements:
  ScatterFeatureRequirement: {}

inputs:
  message_array: string[] 

steps:
  echo:
    run: echo-tool.cwl
    scatter: message
    in:
      message: message_array
    out: []

outputs: []
$ cat 32-inputs.cwl 
message_array:
  - Hello World 1
  - Hello World 2
  - Hello World 3
  - Hello World 4
  - Hello World 5
  - Hello World 6
  - Hello World 7
  - Hello World 8
  - Hello World 9
  - Hello World 10
  - Hello World 11
  - Hello World 12
  - Hello World 13
  - Hello World 14
  - Hello World 15
  - Hello World 16
  - Hello World 17
  - Hello World 18
  - Hello World 19
  - Hello World 20
  - Hello World 21
  - Hello World 22
  - Hello World 23
  - Hello World 24
  - Hello World 25
  - Hello World 26
  - Hello World 27
  - Hello World 28
  - Hello World 29
  - Hello World 30
  - Hello World 31
  - Hello World 32
$ arvados-cwl-runner --disable-reuse echo-many.cwl 32-inputs.cwl

Note that it failed the first time without `--disable-reuse` but this flag is useful for making the failure reproducible. Running with these 32 inputs has failed 4/4 times I have tried it. Running with 16 inputs has failed 1/2 times, and running with 4 inputs succeeded the only time I tried.

dmesg on one of the nodes during some of these runs:

[Mon Nov 29 16:30:53 2021] loop_set_status: loop6 () has still dirty pages (nrpages=2)
[Mon Nov 29 16:30:53 2021] loop_set_status: loop6 () has still dirty pages (nrpages=2)
[Mon Nov 29 16:30:53 2021] loop_set_status: loop6 () has still dirty pages (nrpages=2)
[Mon Nov 29 16:30:54 2021] loop_set_status: loop6 () has still dirty pages (nrpages=2)
[Mon Nov 29 16:30:54 2021] loop_set_status: loop6 () has still dirty pages (nrpages=2)
[Mon Nov 29 16:30:56 2021] blk_update_request: I/O error, dev loop6, sector 4096 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[Mon Nov 29 16:30:56 2021] blk_update_request: I/O error, dev loop6, sector 4096 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[Mon Nov 29 16:30:56 2021] Buffer I/O error on dev loop6, logical block 512, async page read
[Mon Nov 29 16:30:56 2021] blk_update_request: I/O error, dev loop6, sector 4096 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[Mon Nov 29 16:30:56 2021] Buffer I/O error on dev loop6, logical block 512, async page read
[Mon Nov 29 16:34:07 2021] loop_set_status: loop6 () has still dirty pages (nrpages=2)
[Mon Nov 29 16:34:07 2021] loop_set_status: loop6 () has still dirty pages (nrpages=2)
[Mon Nov 29 16:34:07 2021] loop_set_status: loop6 () has still dirty pages (nrpages=2)
[Mon Nov 29 16:34:08 2021] loop_set_status: loop6 () has still dirty pages (nrpages=2)
[Mon Nov 29 16:34:08 2021] loop_set_status: loop6 () has still dirty pages (nrpages=128)

The singularity code (current version at https://github.com/sylabs/singularity/blob/master/pkg/util/loop/loop.go) creates/chooses a loop device where loop_set_fd syscall succeeds, then tries the loop_set_status syscall, waiting 250s and retrying up to 5 times after EAGAIN, then gives up.

The "has still dirty pages" kernel message comes with the EAGAIN response. https://github.com/torvalds/linux/blob/master/drivers/block/loop.c#L1268-L1271

I wonder whether singularity would do better to handle EAGAIN by trying to use/create the next loop device, only resorting to a delay-and-retry loop when reaching MaxLoopDevices. It seems unnecessary to wait around for the kernel to clean up loop6 if we could start using loop7 right now.

As an aside, the EAGAIN kernel behavior itself seems to be in flux.

https://lkml.org/lkml/2020/2/27/2267

I haven't thought of a reasonable way to work around this from the Arvados end.

You meant 250ms not 250s.

So retrying 5 times is only a total of 1.25s of waiting.

Perhaps there is a race condition aspect, if a multiple singularity processes are trying to start at once, could they all decide they want to take the same loop device?

This is pure speculation but if the problem is singularity racing with other singularity processes to acquire a loopback device, maybe we could use some kind of locking strategy to prevent multiple singularity processes starting within some time window (10s?).

Another possibility is for crunch-run to test for the situation where singularity will fail, and wait (longer than 1.5s) for it to clear up. Maybe 60 seconds? But this would achieve exactly the same thing as increasing "maxRetries" in singularity, so patching singularity seems more reasonable.

Summary so far:

Easiest thing that could get your workflows running reliably is to patch singularity to wait up to 150 seconds before giving up instead of 1.5 seconds. Just change maxRetries from 5 to 500 here: https://github.com/sylabs/singularity/blob/master/pkg/util/loop/loop.go#L177

• Move the F_SETFD and CmdSetStatus64 syscalls into the "try each /dev/loopN" loop
• After exhausting all loop devices, return EAGAIN instead of "no loop devices available" if any of them ended in EAGAIN
• Rename AttachFromFile to attachFromFile and add an AttachFromFile wrapper that retries attachFromFile up to 5x after EAGAIN

• if /dev/loop6 says EAGAIN but /dev/loop7 works, use /dev/loop7 right away instead of waiting for /dev/loop6
• /dev isn't flock()ed while waiting, as it is in the current implementation

I expect that with this change, delay-and-retry will be extremely rare, but removing it could conceivably break a case that could have worked with the current code, so seems best to leave it in.

A PR has been opened at https://github.com/sylabs/singularity/pull/458

Hope it gets merged in soon.

Many thanks Tom for all your help investigating this issue!

Will document "if you get this error, check for a newer version of singularity, see this PR" in #18566