Pool timed out while waiting for an open connection, ZFS

[happenslol]

Edit by @ellie:

This has become the canonical issue for Atuin/ZFS issues

If you're using ZFS with Atuin, you have likely noticed an error such as the following:

Error: pool timed out while waiting for an open connection

Location:
    /home/runner/work/atuin/atuin/crates/atuin-client/src/record/sqlite_store.rs:48:20

This is due to an issue with ZFS and SQLite. See: openzfs/zfs#14290

There are two workarounds

1. Use the Atuin daemon

This has not yet been released as stable, however is mostly without issue. The daemon takes all SQLite writes off of the hot path, therefore avoiding the issue.

Follow the steps here: #952 (comment)

2. Create an ext4 zvol for Atuin

Follow the following steps: #952 (comment)

---

I've just begun using atuin, and I absolutely love it so far. However, there's been a recurring issue for me, which I've found hard to diagnose:

My prompt regularly blocks for between 500ms to 5s whenever I run a command. I've narrowed this down to the _atuin_preexec function, by manually importing the shell hook generated from atuin init zsh and annotating it with logging and time calls. Here's a sample time call from a time where it hang:

Running pre-exec for cd ~

0.00user 0.00system 0:04.93elapsed 0%CPU (0avgtext+0avgdata 8192maxresident)k
52036inputs+1064outputs (15major+512minor)pagefaults 0swaps

Pre-exec done for cd ~

Here's how I modified the hook to get the result:

_atuin_preexec() {
    log "Running pre-exec for $1\n" >> /tmp/atuin.log
    local id
    id=$(/usr/bin/time -a -o /tmp/atuin.log atuin history start -- "$1")
    export ATUIN_HISTORY_ID="$id"
    echo "\nPre-exec done for $1" >> /tmp/atuin.log
}

I've tried to replicate the behavior in cli use outside of the hook using hyperfine, and was successful:

» hyperfine -r 1000 "atuin search --limit 5"
Benchmark 1: atuin search --limit 5
  Time (mean ± σ):      18.3 ms ± 114.8 ms    [User: 4.9 ms, System: 8.2 ms]
  Range (min … max):    12.5 ms … 2587.9 ms    1000 runs

This does not happen on every benchmark, even with 1000 runs. My initial thought was that this has to be contention on the database file, but I saw that you're already using WAL, so concurrent writes/reads should not be a problem. I can also trigger the delay by repeatedly opening the search widget, which should not even be doing writes to the database, which confuses me even more.

Do you have any idea on how I could gather further data on this?

[conradludgate]

Do you use the sync service? It's possible it's getting stuck and timing out (we run it occasionally in the pre-exec). Try ATUIN_LOG=debug atuin sync and see if there's anything interesting

[happenslol]

Yeah, I'm syncing with my own server. What exactly am I looking for in the debug output? It seems to be running fine for me, does a whole lot of queries and seems to consistently complete in around 2.5 seconds.

If the sync process is ever run in history start or history end, shouldn't that happen in a background process? Feels weird to have a process that can potentially block running in preexec. Maybe I'm just not understanding correctly, though.

[ellie]

It absolutely should not be blocking in start, and only ever runs a sync in "end" while forked to the background

What sort of disk are you using for your XDG_DATA_HOME/home directory?

The only thing that can block pre exec is writing a small amount to disk, which shouldn't be an issue unless your disk is slow or high latency

[happenslol]

That's weird then, the delay only ever happens in preexec. I'm on an NVME m.2 disk (Samsung 980 Pro), so that really shouldn't be the bottleneck. I'm on ZFS, that's the only thing that's sort of nonstandard. I don't think that should have any impact though.

Additionally, the delay can also occur in something like atuin search, that should not write anything at all afaik?

[ellie]

Ahhh I see, ZFS.

We've had a few people have issues there

NixOS/nixpkgs#169457 is relevant, I believe

[happenslol]

Interesting, would not have though that to even be an option, I haven't had that kind of issue yet. I'll dig more into this, thanks for the reference.

Is there anything we can do here, still? Otherwise, feel free to close this issue.

[happenslol]

Just tried out the kernel patches suggested in the issue you linked, and they have not made any difference. The delays still occur in pretty much exactly the same way, both for the preexec command, and the outliers happening in my benchmark are also still there. Not sure if it's ZFS or something else.

Could I enable more logging to find out where exactly the hangs occur? I'm not sure how much debug logs you provide, and I suppose I would have to find some way to redirect the logs somewhere.

[amarshall]

I’m seeing this as well. I did an strace on the shell and there’s an ftruncate call on history.db-shm that sometimes takes several seconds, and so seems to be the culprit.

I am using ZFS as well, and moving the history db to a tmpfs resolves. Switching to a Kernel with PREEMPT=y did not solve. There is a ZFS bug report already about SQLite and ftruncate (openzfs/zfs#14290).

I think it’s reasonable to conclude that this isn’t Atuin’s doing.

[happenslol]

I see, good to know where it comes from. I'll close this then. Thanks to all you guys for your quick responses!

[dbaynard]

I'm on an NVME m.2 disk (Samsung 980 Pro), so that really shouldn't be the bottleneck. I'm on ZFS, that's the only thing that's sort of nonstandard.

Thanks for taking the time to debug this — I’ve made similarly questionable life choices, and I feared it was a (the) firmware issue.

Did you resolve the issue, @happenslol ?

[happenslol]

Hey @dbaynard,
I resolved the issue by creating a tmpfs on which the database is saved, so I'm just bypassing ZFS by saving it in RAM. Then, I have a litestream service running in the background, which syncs the database back to the filesystem continuously and restores it on first startup. Probably a little overkill, but it was really easy to set up. Hit me up if you want to see how I did it.

However, recently, the issue came back and I haven't had the time to debug it yet. No idea what's causing it, since my database is still in RAM - either it's not actually writing to that database, or litestream is causing some delays, which I don't think is the case... I can post another response here when I've had the time to properly debug it, though.