Re: file born 30 seconds after its creation on ext4 - bug?

From	Vincent Lefevre <vincent@vinc17.net>
Newsgroups	linux.debian.user
Subject	Re: file born 30 seconds after its creation on ext4 - bug?
Date	2022-04-28 12:20 +0200
Message-ID	<Eh9pD-bKOx-1@gated-at.bofh.it> (permalink)
References	<EgtJL-bkEH-11@gated-at.bofh.it> <Eh8Df-bKjl-5@gated-at.bofh.it>
Organization	linux.* mail to news gateway

Show all headers | View raw

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)

Back to linux.debian.user | Previous | Next — Previous in thread | Find similar | Unroll thread

Thread

file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-26 15:50 +0200
  Re: file born 30 seconds after its creation on ext4 - bug? "Thomas Schmitt" <scdbackup@gmx.net> - 2022-04-26 19:10 +0200
    Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-27 04:40 +0200
      Re: file born 30 seconds after its creation on ext4 - bug? "Thomas Schmitt" <scdbackup@gmx.net> - 2022-04-27 09:10 +0200
        Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-27 10:30 +0200
          Re: file born 30 seconds after its creation on ext4 - bug? "Thomas Schmitt" <scdbackup@gmx.net> - 2022-04-27 11:40 +0200
            Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-27 15:20 +0200
              Re: file born 30 seconds after its creation on ext4 - bug? Greg Wooledge <greg@wooledge.org> - 2022-04-27 15:30 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-27 16:10 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? Stefan Monnier <monnier@iro.umontreal.ca> - 2022-04-28 04:50 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? Greg Wooledge <greg@wooledge.org> - 2022-04-28 05:10 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? duh <fill_in_the_blanks@email.com> - 2022-04-29 16:20 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? Marc Auslander <marcausl@gmail.com> - 2022-04-29 20:10 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? "sp007@caiway.net" <sp007@caiway.net> - 2022-04-29 22:10 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? <tomas@tuxteam.de> - 2022-04-30 07:40 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? "Thomas Schmitt" <scdbackup@gmx.net> - 2022-04-30 10:40 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? <tomas@tuxteam.de> - 2022-04-30 14:10 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-05-02 01:20 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? <tomas@tuxteam.de> - 2022-05-02 07:30 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? Curt <curty@free.fr> - 2022-04-30 14:40 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? <tomas@tuxteam.de> - 2022-04-30 15:10 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? "Thomas Schmitt" <scdbackup@gmx.net> - 2022-04-30 15:20 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-05-02 01:40 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? Greg Wooledge <greg@wooledge.org> - 2022-05-02 01:40 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? David Wright <deblis@lionunicorn.co.uk> - 2022-05-02 17:10 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? <tomas@tuxteam.de> - 2022-05-02 18:20 +0200
                Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-28 10:40 +0200
            Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-28 11:40 +0200
  Re: file born 30 seconds after its creation on ext4 - bug? Nicholas Geovanis <nickgeovanis@gmail.com> - 2022-04-26 19:40 +0200
    Re: file born 30 seconds after its creation on ext4 - bug? Nicholas Geovanis <nickgeovanis@gmail.com> - 2022-04-26 19:50 +0200
      Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-27 04:50 +0200
  Re: file born 30 seconds after its creation on ext4 - bug? Stefan Monnier <monnier@iro.umontreal.ca> - 2022-04-26 20:20 +0200
    Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-27 05:10 +0200
  Re: file born 30 seconds after its creation on ext4 - bug? "Thomas Schmitt" <scdbackup@gmx.net> - 2022-04-28 11:30 +0200
    Re: file born 30 seconds after its creation on ext4 - bug? Vincent Lefevre <vincent@vinc17.net> - 2022-04-28 12:20 +0200

csiph-web