Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.debian.user > #247570 > unrolled thread

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

Back to article view | Back to linux.debian.user

Contents

  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

Page 2 of 2 — ← Prev page 1 [2]

#247763

[Multipart message — attachments visible in raw view] — view raw

On Sat, Apr 30, 2022 at 12:31:07PM -0000, Curt wrote:
> On 2022-04-30, Thomas Schmitt <scdbackup@gmx.net> wrote:
> >
> > Indeed. With normal filesystem operations there should be no need to call
> > something like sync(2) in order to get a consistent representation of the
> > current filesystem state.
> >
> 
> What does the following mean, then, in that light:
> 
>  Because of delayed allocation and other performance optimizations, ext4's
>  behavior of writing files to disk is different from ext3. In ext4, when a
>  program writes to the file system, it is not guaranteed to be on-disk unless
>  the program issues an fsync() call afterwards. 

You still can't observe that during a normally running system. You'll
see the same file system behaviour regardless of whether the data have
touched the disk or are still in cache.

The only way to actually observe this in action is to "pull the plug"
before data has a chance to reach the disk. Then, of course, some
files you thought were there will have magically disappeared.

Cheers
-- 
t

[toc] | [prev] | [next] | [standalone]

#247764

Hi,

Curt wrote:
> What does the following mean, then, in that light:
>   Because of delayed allocation and other performance optimizations, ext4's
>   behavior of writing files to disk is different from ext3. In ext4, when a
>   program writes to the file system, it is not guaranteed to be on-disk unless
>   the program issues an fsync() call afterwards.
> https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/7/html/storage_administration_guide/ch-ext4

Well, the wording "delayed allocation and other performance optimizations"
could mean a lot of weird things.
But the subsequent praragraphs clearly concern the RAM-to-disk migration of
memory pages which are associated to the filesystem's disk storage.


>  And the delayed allocation will actually commit the data to disk only after
>  30-150 seconds (it is not very clear on this exact window of data loss)

I understand this and above that the data content already exists in RAM
(i.e. the written inode data with the birth timestamp, plus the file content
as written by the running script) but gets onto the physical storage medium
only later.
The motivation for these discussions is possible data loss if the system
suddenly stops working. Inconsistent filesystem behavior is not mentioned
(but to be expected when the next run of the system encounters the dirty
filesystem).


An explanation of the observed problem would need:
- a mechanism which delayed the content production of the inode while it
  was already in use for open and write,
- or a mechanism which caused ext4 to hide the inode to other processes
  and to write a wrong birth timestamp,
- or a mechanism which deleted the file shortly after it was created and
  re-created it 30 seconds later with its full expected content,
- or something of which i cannot think yet.

(The birth timestamp happens to match roughly the time when the file finally
became visible to other processes. It matches the modification time of the
finally visible file.)

--------------------------------------------------------------------------

The strange strace report around the time when the file finally appeared

  openat(AT_FDCWD, "….out", O_WRONLY|O_CREAT|O_APPEND, 0666 <unfinished ...>
  <... openat resumed>)  = 3

does not mean any disturbance, but only that strace had to deal with more
than one thread or process at the time. Between above two lines there is
supposed to have been another line with a system call, though.
man 1 strace:

   If  a  system call is being executed and meanwhile another one is being
   called from a different thread/process then strace will try to preserve
   the  order  of  those  events and mark the ongoing call as being unfin‐
   ished.  When the call returns it will be marked as resumed.

   [pid 28772] select(4, [3], NULL, NULL, NULL <unfinished ...>
   [pid 28779] clock_gettime(CLOCK_REALTIME, {1130322148, 939977000}) = 
0
   [pid 28772] <... select resumed> )      = 1 (in [3])


Have a nice day :)

Thomas

[toc] | [prev] | [next] | [standalone]

#247796

On 2022-04-30 15:19:21 +0200, Thomas Schmitt wrote:
> An explanation of the observed problem would need:
> - a mechanism which delayed the content production of the inode while it
>   was already in use for open and write,
> - or a mechanism which caused ext4 to hide the inode to other processes
>   and to write a wrong birth timestamp,
> - or a mechanism which deleted the file shortly after it was created and
>   re-created it 30 seconds later with its full expected content,
> - or something of which i cannot think yet.
> 
> (The birth timestamp happens to match roughly the time when the file finally
> became visible to other processes. It matches the modification time of the
> finally visible file.)

I'm wondering whether the data are transferred from the VFS to ext4
necessarily within the same openat system call or could just be kept
in the VFS as long as they are not needed elsewhere, i.e. the VFS
behaving like a cache. In the latter case, since the VFS doesn't
have a notion of birth timestamp (from the code I've read), a bug
in the VFS code could explain the behavior I had observed. This is
the only explanation I could have.

> --------------------------------------------------------------------------
> 
> The strange strace report around the time when the file finally appeared
> 
>   openat(AT_FDCWD, "….out", O_WRONLY|O_CREAT|O_APPEND, 0666 <unfinished ...>
>   <... openat resumed>)  = 3
> 
> does not mean any disturbance, but only that strace had to deal with more
> than one thread or process at the time. Between above two lines there is
> supposed to have been another line with a system call, though.
> man 1 strace:
> 
>    If  a  system call is being executed and meanwhile another one is being
>    called from a different thread/process then strace will try to preserve
>    the  order  of  those  events and mark the ongoing call as being unfin‐
>    ished.  When the call returns it will be marked as resumed.
> 
>    [pid 28772] select(4, [3], NULL, NULL, NULL <unfinished ...>
>    [pid 28779] clock_gettime(CLOCK_REALTIME, {1130322148, 939977000}) = 0
>    [pid 28772] <... select resumed> )      = 1 (in [3])

Thanks for the information. I'd say that "resumed" is misleading, as
it makes me think that "select" was interrupted. IMHO, "continued"
would be much better.

-- 
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)

[toc] | [prev] | [next] | [standalone]

#247797

On Mon, May 02, 2022 at 01:30:08AM +0200, Vincent Lefevre wrote:
> I'm wondering whether the data are transferred from the VFS to ext4
> necessarily within the same openat system call or could just be kept
> in the VFS as long as they are not needed elsewhere, i.e. the VFS
> behaving like a cache. In the latter case, since the VFS doesn't
> have a notion of birth timestamp (from the code I've read), a bug
> in the VFS code could explain the behavior I had observed. This is
> the only explanation I could have.

At this point, you should seriously consider asking the Linux Kernel
Mailing List, or some other place where people might know the answers
to these questions.

[toc] | [prev] | [next] | [standalone]

#247811

On Mon 02 May 2022 at 01:30:08 (+0200), Vincent Lefevre wrote:
> On 2022-04-30 15:19:21 +0200, Thomas Schmitt wrote:
> > An explanation of the observed problem would need:
> > - a mechanism which delayed the content production of the inode while it
> >   was already in use for open and write,
> > - or a mechanism which caused ext4 to hide the inode to other processes
> >   and to write a wrong birth timestamp,
> > - or a mechanism which deleted the file shortly after it was created and
> >   re-created it 30 seconds later with its full expected content,
> > - or something of which i cannot think yet.
> > 
> > (The birth timestamp happens to match roughly the time when the file finally
> > became visible to other processes. It matches the modification time of the
> > finally visible file.)
> 
> I'm wondering whether the data are transferred from the VFS to ext4
> necessarily within the same openat system call or could just be kept
> in the VFS as long as they are not needed elsewhere, i.e. the VFS
> behaving like a cache. In the latter case, since the VFS doesn't
> have a notion of birth timestamp (from the code I've read), a bug
> in the VFS code could explain the behavior I had observed. This is
> the only explanation I could have.

I'm not very familiar with files' birth as it's a relatively new
addition to filesystems, particularly how to display it even when
present. So I looked it up, and the ext4 wiki says it's the time
at which the inode is created. I also read in ext4 wikipedia:

  Multiblock allocator

    When ext3 appends to a file, it calls the block allocator, once
    for each block. Consequently, if there are multiple concurrent
    writers, files can easily become fragmented on disk. However, ext4
    uses delayed allocation, which allows it to buffer data and
    allocate groups of blocks. Consequently, the multiblock allocator
    can make better choices about allocating files contiguously on
    disk. The multiblock allocator can also be used when files are
    opened in O_DIRECT mode. This feature does not affect the disk
    format.

So I wondered whether a delayed birth time could be caused by the
filesystem waiting a while before it actually starts creating any
allocation for the file on the disk. Having amassed some data,
depending on its size, it decides where it's going to write it,
ie which block group. Only then does it create the file's inode,
so that it can keep file contents and inode close together.

Cheers,
David.

[toc] | [prev] | [next] | [standalone]

#247821

[Multipart message — attachments visible in raw view] — view raw

On Mon, May 02, 2022 at 10:04:00AM -0500, David Wright wrote:

> I'm not very familiar with files' birth as it's a relatively new
> addition to filesystems, particularly how to display it even when
> present. So I looked it up, and the ext4 wiki says it's the time
> at which the inode is created. I also read in ext4 wikipedia:

[...]

> So I wondered whether a delayed birth time could be caused by the
> filesystem waiting a while before it actually starts creating any
> allocation for the file on the disk. Having amassed some data,
> depending on its size, it decides where it's going to write it,
> ie which block group. Only then does it create the file's inode,
> so that it can keep file contents and inode close together.

That actually makes sense. It would be surprising behaviour,
but at least whithin reach; whether it's intentional or may be
considered a bug is, of course, another thing

Thanks for diving into details, cheers
-- 
t

[toc] | [prev] | [next] | [standalone]

#247689

On 2022-04-27 22:45:09 -0400, Stefan Monnier wrote:
> Another option might be that your system's time was "reset".
> This shouldn't happen, but it can happen if your NTP was down, the
> machine got out-of-sync over time and you restart the NTP server at
> which point it may(!) decide to jump the clock if the difference is
> large enough (i.e. too large to catch up gradually).
> Can't remember how large is "large enough".

I don't think that systemd does that. Anyway, even if this were
possible, that would make the output inconsistent. I recall:

cventin:~/software/mpfr[1]> lt|head                                   <14:43:42
total 7016
-rw-r--r--  1  188644 2022-04-26 14:43:42 config.log
-rw-r--r--  1    2861 2022-04-26 14:43:42 conftest.c
-rw-r--r--  1       0 2022-04-26 14:43:42 conftest.err
-rw-r--r--  1    1907 2022-04-26 14:43:42 confdefs.h
-rwxr-xr-x  1  632161 2022-04-26 14:43:16 configure.lineno*
drwxr-xr-x  2    4096 2022-04-26 14:43:11 doc/
drwxr-xr-x  3    4096 2022-04-26 14:43:11 tune/
-rwxr-xr-x  1   23568 2022-04-26 14:43:11 depcomp*
drwxr-xr-x  5   36864 2022-04-26 14:43:11 tests/
cventin:~/software/mpfr> lt|head                                      <14:43:47
total 6416
-rw-r--r--  1   19436 2022-04-26 14:43:47 config.log
-rw-r--r--  1     561 2022-04-26 14:43:47 conftest.c
-rw-r--r--  1       0 2022-04-26 14:43:47 conftest.err
-rw-r--r--  1    4138 2022-04-26 14:43:47 mpfrtests.cfgout
-rw-r--r--  1     500 2022-04-26 14:43:47 confdefs.h
-rwxr-xr-x  1  632161 2022-04-26 14:43:45 configure.lineno*
-rw-r--r--  1     878 2022-04-26 14:43:45 mpfrtests.cventin.lip.ens-lyon.fr.out
drwxr-xr-x  3    4096 2022-04-26 14:43:44 tune/
drwxr-xr-x  4   36864 2022-04-26 14:43:44 tests/

where mpfrtests.cventin.lip.ens-lyon.fr.out was actually created
a fraction of second before configure.lineno in the script.

"14:43:42" is the time I ran the first "lt|head" and "14:43:47"
is the time I ran the second "lt|head", where "lt" is ls with
various options, including "-t" to sort in decreasing date order.

With time jumps, this is theoretically possible, but this would
mean that the time jumped at least 3 times:
  1. To make the birth time as 14:43:45.
  2. To make the last modified time earlier than 14:43:11 (so that
     mpfrtests.cventin.lip.ens-lyon.fr.out doesn't appear in the
     first "lt|head" output).
  3. To go back after 14:43:42.

And this would not explain the

cventin:~/software/mpfr> tail -n 30 mpfrtests.*.out; ll mpfrtests.*.out
zsh: no match
zsh: no match
cventin:~/software/mpfr[1]> tail -n 30 mpfrtests.*.out; ll mpfrtests.*.out
zsh: no match
zsh: no match

which I did a few seconds before 14:43:42.

If the time did not jump, then the birth time 14:43:45.537241731
matches the behavior I've observed in the above commands, i.e. as if
this file were created at this time.

-- 
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)

[toc] | [prev] | [next] | [standalone]

#247691

On 2022-04-27 11:39:17 +0200, Thomas Schmitt wrote:
> It is normal that data get onto the physical storage medium only quite a
> long time after a program wrote them. But this is supposed to be kept
> consistent by the VFS and virtual memory of the Linux kernel.
[...]
> I understand that the filesystem driver writes to memory pages which
> are associated to storage device memory. The pages and their association
> are managed by the virtual memory facility of the kernel.
>   https://www.kernel.org/doc/html/latest/filesystems/vfs.html#the-address-space-object
> Any attempt to access the associated to storage device memory of a not
> yet written page is supposed to be directed to the cached page in RAM.

If I understand correctly, the VFS does not just have cached pages,
but also its own structures, like inodes. So, I'm wondering whether
the following could be possible:

* openat(AT_FDCWD, "….out", O_WRONLY|O_CREAT|O_TRUNC, 0666) creates
  a file in the VFS, which is not written back to the actual FS.

* The subsequent openat(AT_FDCWD, "….out", O_WRONLY|O_CREAT|O_APPEND, 0666)
  append data to this file in the VFS, still not written back to the
  actual FS.

When I did

  tail -n 30 mpfrtests.*.out; ll mpfrtests.*.out

this had the effect to look at the entries in the current directory.
For some reason (a bug occurring under some particular conditions?),
the dirty state due to the data written above to the VFS was ignored,
so that the file was not found. Ditto for the first "lt|head".

Between the first "lt|head" and the second one, the data were written
back to the actual FS.

This explanation is possible only if the birth time is the time at
which the VFS inode was written as the inode of the actual FS, not
the time at which the file was created in the VFS. This may be the
case, as the VFS does not seem to have the concept of birth time
(fs/inode.c has things like atime, ctime and mtime, but that's all).

-- 
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)

[toc] | [prev] | [next] | [standalone]

#247581

[Multipart message — attachments visible in raw view] — view raw

On Tue, Apr 26, 2022 at 8:45 AM Vincent Lefevre <vincent@vinc17.net> wrote:

> On an ext4 filesystem, I got a file born 30 seconds after its
> actual creation. Is this a bug?
>

Only experimentation can really back me up on this, but consider the
following:

Every time you use the "|" operator or the ";" separator on a command-line,
new processes are being spawned. Which wait to be dispatched on a core.
But you are not serializing the dispatch of those processes, and especially
with
16 fast cores, you can't predict their order of execution.


> I know that such issues can be observed with NFS, but here this
> is just a local ext4 filesystem.
>
> Here are the details.
>
> I started a shell script:
>
> cventin:~> ps -p 667828 -o lstart,cmd
>                  STARTED CMD
> Tue Apr 26 14:43:15 2022 /bin/sh /home/vlefevre/wd/mpfr/tests/mpfrtests.sh
>
> This script creates a file mpfrtests.cventin.lip.ens-lyon.fr.out
> very early. But the first attempts to look at this file failed:
>
> cventin:~/software/mpfr> tail -n 30 mpfrtests.*.out; ll mpfrtests.*.out
> zsh: no match
> zsh: no match
> cventin:~/software/mpfr[1]> tail -n 30 mpfrtests.*.out; ll mpfrtests.*.out
> zsh: no match
> zsh: no match
> cventin:~/software/mpfr[1]> lt|head
>  <14:43:42
> total 7016
> -rw-r--r--  1  188644 2022-04-26 14:43:42 config.log
> -rw-r--r--  1    2861 2022-04-26 14:43:42 conftest.c
> -rw-r--r--  1       0 2022-04-26 14:43:42 conftest.err
> -rw-r--r--  1    1907 2022-04-26 14:43:42 confdefs.h
> -rwxr-xr-x  1  632161 2022-04-26 14:43:16 configure.lineno*
> drwxr-xr-x  2    4096 2022-04-26 14:43:11 doc/
> drwxr-xr-x  3    4096 2022-04-26 14:43:11 tune/
> -rwxr-xr-x  1   23568 2022-04-26 14:43:11 depcomp*
> drwxr-xr-x  5   36864 2022-04-26 14:43:11 tests/
> cventin:~/software/mpfr> lt|head
> <14:43:47
> total 6416
> -rw-r--r--  1   19436 2022-04-26 14:43:47 config.log
> -rw-r--r--  1     561 2022-04-26 14:43:47 conftest.c
> -rw-r--r--  1       0 2022-04-26 14:43:47 conftest.err
> -rw-r--r--  1    4138 2022-04-26 14:43:47 mpfrtests.cfgout
> -rw-r--r--  1     500 2022-04-26 14:43:47 confdefs.h
> -rwxr-xr-x  1  632161 2022-04-26 14:43:45 configure.lineno*
> -rw-r--r--  1     878 2022-04-26 14:43:45
> mpfrtests.cventin.lip.ens-lyon.fr.out
> drwxr-xr-x  3    4096 2022-04-26 14:43:44 tune/
> drwxr-xr-x  4   36864 2022-04-26 14:43:44 tests/
>
> According to /usr/bin/stat, the file birth is
>
>  Birth: 2022-04-26 14:43:45.537241731 +0200
>
> thus 30 seconds after the script started!
>
> Note that the configure.lineno file is created *after*
> mpfrtests.cventin.lip.ens-lyon.fr.out, and one can see that
> at 14:43:16, configure.lineno was already created.
>
> This is a 12-core Debian/unstable machine with
>
> Linux cventin 5.17.0-1-amd64 #1 SMP PREEMPT Debian 5.17.3-1 (2022-04-18)
> x86_64 GNU/Linux
>
> --
> 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)
>
>

[toc] | [prev] | [next] | [standalone]

#247582

[Multipart message — attachments visible in raw view] — view raw

On Tue, Apr 26, 2022 at 12:37 PM Nicholas Geovanis <nickgeovanis@gmail.com>
wrote:

> On Tue, Apr 26, 2022 at 8:45 AM Vincent Lefevre <vincent@vinc17.net>
> wrote:
>
>> On an ext4 filesystem, I got a file born 30 seconds after its
>> actual creation. Is this a bug?
>>
>
> Only experimentation can really back me up on this, but consider the
> following:
>
> Every time you use the "|" operator or the ";" separator on a command-line,
> new processes are being spawned. Which wait to be dispatched on a core.
> But you are not serializing the dispatch of those processes, and
> especially with
> 16 fast cores, you can't predict their order of execution.
>

A couple more observations:
(1) It looks like you're trying to observe behavior in the very same
filesystem in which
the running executable is loaded from and its log files are being
written-to. That's
alot of variables in motion at once.

(2) Yes, the "|" is in a sense serializing I/O in "lt|head". But the
filesystem is syncing
buffered and disk-based content separately from that.


> I know that such issues can be observed with NFS, but here this
>> is just a local ext4 filesystem.
>>
>> Here are the details.
>>
>> I started a shell script:
>>
>> cventin:~> ps -p 667828 -o lstart,cmd
>>                  STARTED CMD
>> Tue Apr 26 14:43:15 2022 /bin/sh /home/vlefevre/wd/mpfr/tests/mpfrtests.sh
>>
>> This script creates a file mpfrtests.cventin.lip.ens-lyon.fr.out
>> very early. But the first attempts to look at this file failed:
>>
>> cventin:~/software/mpfr> tail -n 30 mpfrtests.*.out; ll mpfrtests.*.out
>> zsh: no match
>> zsh: no match
>> cventin:~/software/mpfr[1]> tail -n 30 mpfrtests.*.out; ll mpfrtests.*.out
>> zsh: no match
>> zsh: no match
>> cventin:~/software/mpfr[1]> lt|head
>>  <14:43:42
>> total 7016
>> -rw-r--r--  1  188644 2022-04-26 14:43:42 config.log
>> -rw-r--r--  1    2861 2022-04-26 14:43:42 conftest.c
>> -rw-r--r--  1       0 2022-04-26 14:43:42 conftest.err
>> -rw-r--r--  1    1907 2022-04-26 14:43:42 confdefs.h
>> -rwxr-xr-x  1  632161 2022-04-26 14:43:16 configure.lineno*
>> drwxr-xr-x  2    4096 2022-04-26 14:43:11 doc/
>> drwxr-xr-x  3    4096 2022-04-26 14:43:11 tune/
>> -rwxr-xr-x  1   23568 2022-04-26 14:43:11 depcomp*
>> drwxr-xr-x  5   36864 2022-04-26 14:43:11 tests/
>> cventin:~/software/mpfr> lt|head
>> <14:43:47
>> total 6416
>> -rw-r--r--  1   19436 2022-04-26 14:43:47 config.log
>> -rw-r--r--  1     561 2022-04-26 14:43:47 conftest.c
>> -rw-r--r--  1       0 2022-04-26 14:43:47 conftest.err
>> -rw-r--r--  1    4138 2022-04-26 14:43:47 mpfrtests.cfgout
>> -rw-r--r--  1     500 2022-04-26 14:43:47 confdefs.h
>> -rwxr-xr-x  1  632161 2022-04-26 14:43:45 configure.lineno*
>> -rw-r--r--  1     878 2022-04-26 14:43:45
>> mpfrtests.cventin.lip.ens-lyon.fr.out
>> drwxr-xr-x  3    4096 2022-04-26 14:43:44 tune/
>> drwxr-xr-x  4   36864 2022-04-26 14:43:44 tests/
>>
>> According to /usr/bin/stat, the file birth is
>>
>>  Birth: 2022-04-26 14:43:45.537241731 +0200
>>
>> thus 30 seconds after the script started!
>>
>> Note that the configure.lineno file is created *after*
>> mpfrtests.cventin.lip.ens-lyon.fr.out, and one can see that
>> at 14:43:16, configure.lineno was already created.
>>
>> This is a 12-core Debian/unstable machine with
>>
>> Linux cventin 5.17.0-1-amd64 #1 SMP PREEMPT Debian 5.17.3-1 (2022-04-18)
>> x86_64 GNU/Linux
>>
>> --
>> 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)
>>
>>

[toc] | [prev] | [next] | [standalone]

#247592

On 2022-04-26 12:47:53 -0500, Nicholas Geovanis wrote:
> On Tue, Apr 26, 2022 at 12:37 PM Nicholas Geovanis <nickgeovanis@gmail.com>
> wrote:
> 
> > On Tue, Apr 26, 2022 at 8:45 AM Vincent Lefevre <vincent@vinc17.net>
> > wrote:
> >
> >> On an ext4 filesystem, I got a file born 30 seconds after its
> >> actual creation. Is this a bug?
> >>
> >
> > Only experimentation can really back me up on this, but consider the
> > following:
> >
> > Every time you use the "|" operator or the ";" separator on a command-line,
> > new processes are being spawned. Which wait to be dispatched on a core.
> > But you are not serializing the dispatch of those processes, and
> > especially with
> > 16 fast cores, you can't predict their order of execution.
> >
> 
> A couple more observations:
> (1) It looks like you're trying to observe behavior in the very same
> filesystem in which
> the running executable is loaded from and its log files are being
> written-to. That's
> alot of variables in motion at once.
> 
> (2) Yes, the "|" is in a sense serializing I/O in "lt|head". But the
> filesystem is syncing
> buffered and disk-based content separately from that.

There are no parallel writes to the file, i.e. everything is
serialized from this point of view.

-- 
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)

[toc] | [prev] | [next] | [standalone]

#247584

> On an ext4 filesystem, I got a file born 30 seconds after its
> actual creation. Is this a bug?

I doubt it.
Note that a file's atime/mtime/ctime is a property of the file itself,
whereas "appearing" is defined by when the name you're checking
becomes a link to it.

IOW, most likely the file was first created under a different name and
then renamed.  This is very standard practice to make sure the final
file name never refers to an incomplete file.


        Stefan

[toc] | [prev] | [next] | [standalone]

#247593

On 2022-04-26 14:18:58 -0400, Stefan Monnier wrote:
> > On an ext4 filesystem, I got a file born 30 seconds after its
> > actual creation. Is this a bug?
> 
> I doubt it.
> Note that a file's atime/mtime/ctime is a property of the file itself,
> whereas "appearing" is defined by when the name you're checking
> becomes a link to it.
> 
> IOW, most likely the file was first created under a different name and
> then renamed.  This is very standard practice to make sure the final
> file name never refers to an incomplete file.

You mean renamed by the Linux kernel??? (The script doesn't rename it.)

FYI, the script is the following one:

  https://gitlab.inria.fr/mpfr/misc/-/blob/fed7770cf5f712871bd116ef80d93ea5885fc3f7/vl-tests/mpfrtests.sh

and the file in question is what appears as "$out".

And what I did was running from a MPFR working tree

  /path/to/mpfrtests.sh < /path/to/mpfrtests.data

where the mpfrtests.data file is the following one:

  https://gitlab.inria.fr/mpfr/misc/-/blob/e0204b3423b9bc25c31548d2acc5b8e19a73f48d/vl-tests/mpfrtests.data

Note that I had never had any issue until now. This was the first
time I got errors saying that the file was missing.

-- 
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)

[toc] | [prev] | [next] | [standalone]

#247690

Hi,

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 ?

Is the text snippet "<unfinished ...> <... openat resumed>" literally in
the output of strace ? (Or does stand for some other text ?)

Did you check the kernel logs for unusual events around 2022-04-26 14:43 ?


> 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.

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.
But i lack of any idea how this can happen as rare and unexpected event.


Have a nice day :)

Thomas

[toc] | [prev] | [next] | [standalone]

#247692

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)

[toc] | [prev] | [standalone]

Page 2 of 2 — ← Prev page 1 [2]

Back to top | Article view | linux.debian.user

csiph-web