Re: file born 30 seconds after its creation on ext4 - bug?
Hi,
On 2022-04-28 11:26:36 +0200, Thomas Schmitt wrote:
> Vincent Lefevre wrote:
> > and one with
> > openat(AT_FDCWD, "….out", O_WRONLY|O_CREAT|O_APPEND, 0666 <unfinished ...>
> > <... openat resumed>) = 3
> > about 30 seconds later.
>
> Oh. So the script was still running when the file finally appeared to lt,
> tail, and ll ?
Yes, the script takes several dozens of minutes to complete
on this machine.
> Is the text snippet "<unfinished ...> <... openat resumed>" literally in
> the output of strace ? (Or does stand for some other text ?)
Yes, this is just from raw copy-paste, no editing. I suppose
that the scheduler interrupted the system call.
> Did you check the kernel logs for unusual events around 2022-04-26 14:43 ?
Yes, actually the systemd journal (which gives additional information).
Nothing at this time:
[...]
Apr 26 14:42:16 cventin su[662519]: pam_unix(su:session): session closed for user root
Apr 26 14:45:01 cventin CRON[768983]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
[...]
When I looked at it, I found I/O errors with sr0 and sr1 that occurred
a bit later. I initially thought of a possible hardware problem, but
they were common and unrelated. They are triggered by Wine, which is
executed by my script (as I also test MPFR under Wine).
My bug report:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1010209
(either the kernel is really doing silly things, or this should just
be debug information that should not be in the logs by default).
> > This doesn't explain why the birth time of the file was 30 seconds
> > late.
>
> I developed the theory that it might be an effect of journaling. Like:
> Inode creation fails on storage device level, journal records the ongoing
> write requests and virtual memory serves the read requests, 30 seconds
> later journal creates inode at its final place on the storage device.
> But as it looks in
> https://ext4.wiki.kernel.org/index.php/Ext4_Disk_Layout#Journal_.28jbd2.29
> the journal is a mere data cache with no own means to create inodes and their
> timestamps.
I initially thought about journaling too.
> Still i deem it the most plausible theory that the inode to which the script
> wrote in its first second is not the same inode to which it later wrote and
> which finally shows up with shell tools.
I don't see how this is possible, except if you mean VFS inode
(with no concept of birth time) and ext4 inode. See my other mail
about that.
--
Vincent Lefèvre <vincent@vinc17.net> - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)
Reply to: