pkg/machine/e2e: improve timeout handling #23162
Conversation
|
[APPROVALNOTIFIER] This PR is APPROVED This pull-request has been approved by: Luap99 The full list of commands accepted by this bot can be found here. The pull request process is described here
Needs approval from an approver in each of these files:
Approvers can indicate their approval by writing |
openshift-ci
bot
added
the
approved
|
LGTM |
openshift-ci
bot
added
the
do-not-merge/work-in-progress
Luap99
changed the title
openshift-ci
bot
removed
the
do-not-merge/work-in-progress
|
@edsantiago @baude @ashley-cui PTAL Let's see how this goes, I am not sure why all of the sudden the flake (#22551) is so much worse (maybe #23068?) but from my limited debugging it really looks like it is slow to copy the VM file on init and there is no hang/lock or anything. So let's hope the extra minute is enough. |
|
LGTM. Wonder why the other pr made it worse.. |
yeah I don't understand it either, maybe they are located on different disks/volumes which makes copy slower or something like that? |
|
Yeah really strange..., maybe not the slow IO after all. I have another idea that I can try. |
|
/hold |
openshift-ci
bot
added
the
do-not-merge/hold
Found this command in the progress bar handling code, I pushed a commit to drop the progress bar on decompress. No idea if this is actually the problem but worth a try. |
|
Sigh. No luck. |
Looks like it worked though? No mac flake, seems to have failed on linux on start with an entirely different stack trace. Of course I might just be lucky on this run so I will repush again and see if it passes again. |
That is a new one to me, https://api.cirrus-ci.com/v1/artifact/task/6224808554266624/html/sys-podman-fedora-39-root-host-boltdb.log.html But looks like all machine tests passed on the first try so that is good. |
|
That looks ... impossible? The |
Until I saw this I would have said yes, now not so much... For now I focus on the machine madness and this looks good. I will repush one last time to be sure and even lower the timeout a bit. |
(At the end-user level, macOS uses quite a bit of disk space (frequently gigabytes) of “purgeable” storage. I don’t quite know how that works — running low on space tends to trigger attempts to delete some of that “purgeable” storage, but IIRC it is also quite possible to hit an “out of space” error when writing too fast. I really have no idea how much of that is happening at the UX “document” abstraction vs. the low-level filesystem syscall API, i.e. whether a
My reading of https://developer.apple.com/support/downloads/Apple-File-System-Reference.pdf is that there is a single “allocation” layer per the whole container, with each volume allocating storage for a file/directory as necessary. (But there does exist a feature to reserve space for a volume, or to impose a quota on a volume.) |
yes I found that too, see containers/automation#204 |
Luap99
force-pushed
the
machine-hang
branch
4 times, most recently
from
e90c3e6 to
f352dc3
Compare
| @@ -123,7 +123,7 @@ func (sw *sparseWriter) Close() error { | |||
| return errors.New("file is already closed") | |||
| } | |||
| if sw.pendingZeroes != 0 { | |||
| if holeSize := sw.pendingZeroes - 1; holeSize >= zerosThreshold { | |||
| if holeSize := sw.pendingZeroes; holeSize >= zerosThreshold { | |||
There was a problem hiding this comment.
AFAICS this will corrupt the image: the code will do a seek(+6 GB) (which does not change the file contents) without writing a trailing non-hole byte; the VM image will be 6 GB shorter.
There was a problem hiding this comment.
The passing machine test seems to disagree: https://cirrus-ci.com/task/5791451773140992
I am not going to pretend I know how sparse files work in general, I am sure there is good reason for the final write but at least on macos it appears to work like this
There was a problem hiding this comment.
I meant “corrupt” as in “will have a different length and digest”.
If this is a raw image, I would’t be surprised if the VM using it would (try to?) extend the file by writing to the unallocated parts of the image; i.e. this moves the sparse-file extension / allocation from the decompression time to the VM time.
If this change actually preserves length / digest … I’m extremely confused. (Also, in that case, there should not be any speedup! Creating a 6GB-1 hole and issuing a 1-byte write should not be substantially slower than creating a 6GB hole and not issuing a 1-byte write.)
There was a problem hiding this comment.
ls -lh did report the full size and du did show the actual size on disk without holes so I guess it worked fine
unless I tested the wrong binary
Feel free test things yourself, I am not saying any of this is correct I am just trying to test things until we can get this insane flake fixed
There was a problem hiding this comment.
Testing this on Mac with a completely default filesystem, with the holeSize := sw.pendingZeroes, sparse_writer.go as is otherwise, and
func main() {
srcBytes := [10_000_000]byte{}
src := bytes.NewReader(srcBytes[:])
dest, err := os.OpenFile("t", os.O_RDWR|os.O_CREATE, 0o600)
if err != nil {
panic(err)
}
sw := NewSparseWriter(dest)
cnt, err := io.Copy(sw, src)
if err != nil {
panic(err)
}
fmt.Printf("copy count %d\n", cnt)
err = sw.Close()
if err != nil {
panic(err)
}
err = dest.Close()
if err != nil {
panic(err)
}
}I see, per fs_usage:
open F=3 (RWC________X) t
fstat64 F=3
lseek F=3 O=0x00989680 <SEEK_CUR>
write F=3 B=0x0
close F=3
and the created file is 0 bytes long. So the trailing zeroes were not written.
With holeSize := sw.pendingZeroes - 1, this is seek(N-1)+1-byte write, as expected; but the output is
% ls -la t
-rw------- 1 … … 10000000 … t
% du -h t
9,5M t
% stat -f '%z %b %k' t
10000000 19536 4096i.e. it does not look sparse.
On further testing, a 10M file is not created sparse, but a ~1G one is:
% stat -f '%z %b %k' t
1000000000 8 4096This is going to make experiments so confusing.
The precise trigger seems to be 16 MiB of a hole (16MiB +1 total size), at least in this test case.
There was a problem hiding this comment.
Yeah, I have absolutely no idea what is going on and if you found a way to avoid the flakes, that’s definitely very valuable.
(I’d probably push for this “don’t write trailing zeroes” mode of SparseWriter (assuming that’s what it does) to be opt-in, because not writing the input data as given would be so surprising. But if we know that’s fine for VM images, sure, let’s do that.)
There was a problem hiding this comment.
if you follow the machine init code there is actually a truncate on the raw disk image based to actual requested VM disk size at the end. So I guess is doesn't matter for our sparse writer to write the remaining zeros because of that. And the truncate doesn't cause the weird write behaviour we are seeing here. So maybe should we try to switch seek over to truncate for the remaining zeros?
There was a problem hiding this comment.
Sure, why not.
(I’d still like to, eventually, understand what is going on here — the kernel, ~by definition, doesn’t know that the 1-byte write is “the last write”, so I think whatever is happening could also happen in the middle of some other VM image. But that’s not as important as keeping CI sane.)
There was a problem hiding this comment.
Looks like with truncate is seems to hang even more and I also noticed a hang within the regular write() not at the end in Close() so yes you are right in can happen in the middle...
There was a problem hiding this comment.
I’d still like to, eventually, understand what is going on here
There's an apple developer page on writing sparse files. IIRC, there are some unique requirements. The one that struck me was some statement that seemed like it would un-sparse the file if it was re-opened. Perhaps I'm reading that wrongly.
|
Also FYI I did some disk speed tests, 10g (not sparsed) file was written in like 12s at the beginning of the test and 20g took 25s so I really don't think IO speed is the problem. |
Luap99
force-pushed
the
machine-hang
branch
2 times, most recently
from
9cd609e to
39cfa34
Compare
|
I bumped the timeout up to 10 mins and it passed on first try, I will rerun several times to check It took over 7 mins for this one test to run, all others are much faster. |
In case of timeouts actually log the command again and make sure to send SIGABRT to the process as go will create a useful stack strace where we can see where things are hanging. It also kill the process unlike the default Eventually().Should(Exit()) call the leaves the process around. The output will be captured by default in the log so we just see the stack trace there. And while at it bump the timout up to 10 mins, we are hitting hard flakes in CI where machine init takes longer than 5 mins for unknown reasons but this seems to be good enough. Signed-off-by: Paul Holzinger <[email protected]>
To debug the slow machine init command. Let's see the disk image size. Signed-off-by: Paul Holzinger <[email protected]>
Makes it easier to see which tests are slow. Signed-off-by: Paul Holzinger <[email protected]>
openshift-ci
bot
removed
the
do-not-merge/work-in-progress
|
I think this is good to review, I had several runs without flakes now. There are still some debug command in here to see the file sizes but that should not hurt us and makes finding patterns easier so I like to keep them for now. So the fix for now is to bump the timeout to 10 minutes as somehow it magically takes like around 6-7m sometimes??? So fat the pattern I can see is when it is super slow the file does not seem sparse, it is always one of the early test (often the first one). Some tests write sparse files with different sizes (I would have assumed it be deterministic but looks like it is not?!) Even tests that do not write the file sparse still write fast enough, it is just sometimes where it starts to hang. |
|
Neat trick with the func() string using SIGABRT. LGTM |
|
LGTM, nice work |
|
/lgtm |
|
/hold cancel |
openshift-ci
bot
removed
the
do-not-merge/hold
stale-locking-app
bot
added
the
locked - please file new issue/PR
There seems to be a very bad flake where podman machine init takes to
long. It doesn't seem to be deadlocked it just has to copy the entire
image which is super slow in CI for some reason.
As such increase the timeout by 1m to 5m total. Hopefully this is good
enough for now. Second in case we still hit a timeout send SIGABRT which
makes go dump the stack trace sow e know if it seems to be doing
something or hangs on lock.
Does this PR introduce a user-facing change?