temp files in on zfs inducing avoidable i/o latency

[mjguzik]

I did some off-cpu tracing and got the following when looking at part of the run: https://people.freebsd.org/~mjg/poudriere-offcpu.svg

Some additional work shows the unlinks are of this form:

/poudriere/data/logs/bulk/head-default/2022-04-10_14h05m30s/.tmp-.poudriere.status.92.i9vO03KL
/poudriere/data/logs/bulk/head-default/2022-04-10_14h05m30s/.tmp-.poudriere.status.93.0VqfVXsR
/poudriere/data/logs/bulk/head-default/2022-04-10_14h05m30s/.tmp-.poudriere.status.93.6yEtSQC1
/poudriere/data/logs/bulk/head-default/2022-04-10_14h05m30s/.tmp-.poudriere.status.93.71HmiQl8
/poudriere/data/logs/bulk/head-default/2022-04-10_14h05m30s/.tmp-.poudriere.status.93.LZCx1TdE
/poudriere/data/logs/bulk/head-default/2022-04-10_14h05m30s/.tmp-.poudriere.status.93.MYfZjGuD
/poudriere/data/logs/bulk/head-default/2022-04-10_14h05m30s/.tmp-.poudriere.status.93.ZDRZcv58
/poudriere/data/logs/bulk/head-default/2022-04-10_14h05m30s/.tmp-.poudriere.status.93.eOLWBu4F

Is there any reason this is not taking place on a dedicated (if optional) tmpfs mount?

[igalic]

we already have lots of code that is using tmpfs: https://github.com/freebsd/poudriere/search?q=tmpfs&type=

[bdrewery]

These files are read from the web interface. It updates the .poudriere.status[.job] file when the state changes so the status of each builder can be seen. With 93 builders yeah it's going to be writing to these files a LOT. As well as the .journal% file that records each update.

It uses a tempfile -> cmp -> unlink || rename pattern. If we wrote them to a tmpfs then the rename wouldn't be atomic.

I am confused why there is any unlink involved with .poudriere.status* though. There are not any redundant status writes that I can think of. I'll have to look around more.

This should help spot them.

diff --git src/share/poudriere/include/util.sh src/share/poudriere/include/util.sh
index 61309f005..cce1f8869 100644
--- src/share/poudriere/include/util.sh
+++ src/share/poudriere/include/util.sh
@@ -1162,22 +1162,30 @@ _write_atomic() {
        ret=0
        mapfile_write "${tmpfile_handle}" || ret="$?"
        if [ "${ret}" -ne 0 ]; then
+               msg_warn "unlinking bad mapfile_write ${tmpfile}" \
+                   >&${OUTPUT_REDIRECTED_STDERR:-2}
                unlink "${tmpfile}" || :
                return "${ret}"
        fi
        ret=0
        mapfile_close "${tmpfile_handle}" || ret="$?"
        if [ "${ret}" -ne 0 ]; then
+               msg_warn "unlinking bad mapfile_close ${tmpfile} $(cat ${tmpfile})" \
+                   >&${OUTPUT_REDIRECTED_STDERR:-2}
                unlink "${tmpfile}" || :
                return "${ret}"
        fi
        if [ "${cmp}" -eq 1 ] && cmp -s "${dest}" "${tmpfile}"; then
+               msg_warn "unlinking redundant ${tmpfile} $(cat ${tmpfile})" \
+                   >&${OUTPUT_REDIRECTED_STDERR:-2}
                unlink "${tmpfile}" || :
                return 0
        fi
        ret=0
        rename "${tmpfile}" "${dest}" || ret="$?"
        if [ "${ret}" -ne 0 ]; then
+               msg_warn "unlinking bad rename ${tmpfile} $(cat ${tmpfile})" \
+                   >&${OUTPUT_REDIRECTED_STDERR:-2}
                unlink "${tmpfile}" || :
                return "${ret}"
        fi

This does reveal the .data.json file having a lot of redundant writes.

@mjguzik Can you check if you still see the unlinks with HTML_JSON_UPDATE_INTERVAL=0 in poudriere.conf?

[bdrewery]

But your log does show .poudriere.status files and not .data.json. I cannot reproduce this. Which version of Poudriere were you using?

[bdrewery]

I do see these files with dtrace now so I can debug it from here.

dtrace -qn 'fbt::kern_funlinkat:entry { printf("%s\n", copyinstr(arg2)); }'

[bdrewery]

Aha it is mktemp(1) -u doing the unlink.

[mjguzik]

If some of this needs to persist after the build is finished, you can move it in 2 steps: 1. create a temp file in the target dir 2. rename it to the expected name

in general i would expect virtually no writes to storage modulo logs and packages themselves in a TMPFS=ALL setup

[bdrewery]

@mjguzik Is it just the unlinking causing a problem or all of it? I can stop the unlinks but the rest is a feature. I could add a way to disable or delay the status saving for your purposes if needed.

[mjguzik]

it's all the i/o.

you can maintain the feature while in tmpfs as long as poudriere is running. there can be a symlink which gets flipped around to regular storage otherwise.

[bdrewery]

We would lose all logs and state on a panic forcing a full rebuild. Is the problem here worth all of the effort? Are we I/O bound during builds?

[bdrewery]

These files are shared over web and can be opened with file:// too. Symlinks from the log dirs into tmpfs is not something I want to burden users with unless it is a huge win.

Perhaps there is a ZFS tuning solution like increasing the transaction time or adding an slog.

[mjguzik]

I'm not saying package logs need to move, just the .poudriere files. you should be able to recover the state very easily by checking what packages ultimately got built.