[4.1-rc] File was modified, but mtime stayed the same (according to unison)

[4.1-rc] File was modified, but mtime stayed the same (according to unison)

[Pavel Machek]

Hi!

Today, I got strange warning from unison:

pavel/.config/chromium/Default/Extension State/LOG.old — transport
failure
• The source file /data/pavel/.config/chromium/Default/Extension
State/LOG.old
has been modified but the fast update detection mechanism
failed to detect it.  Try running once with the fastcheck
option set to 'no'.

Filesystem is plain ext4.
pavel@amd:~$ cat /proc/mounts  | grep /data
/dev/sda2 /data ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
pavel@amd:~$ uname -a
Linux amd 4.1.0-rc5 #23 SMP Wed May 27 09:19:18 CEST 2015 x86_64
GNU/Linux

Now, I know mount -oloop can do such "silent updates"... but that
should not be case for chromium. unison 2.40.102. Any ideas?

Thanks,
								Pavel

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: [4.1-rc] File was modified, but mtime stayed the same (according to unison)

[Theodore Ts'o]

On Tue, Jun 09, 2015 at 12:43:30PM +0200, Pavel Machek wrote:
> 
> Hi!
> 
> Today, I got strange warning from unison:
> 
> pavel/.config/chromium/Default/Extension State/LOG.old — transport
> failure
> • The source file /data/pavel/.config/chromium/Default/Extension
> State/LOG.old
> has been modified but the fast update detection mechanism
> failed to detect it.  Try running once with the fastcheck
> option set to 'no'.

What does this mean, precisely?  Is Unison checking that files have
been modified using some kind of a checksum or file comparison
mechanism?  And I assume that the "fast update detection mechanism"
using mtime?

And if it has modified, how was it modified (can you do a diff with
what the other side of the synchronization setup had for that file),
and do you know by which process. and what was it trying to do?  And
how is unison being run?

One thing that could be going on is that if you have a file which is
mmap'ed, the mtime field is set the first time the page is modified
(when the page table entry is set to read/write from read-only).  If
unison then takes a snapshot of the file, and then file is
subsequently modified via a write to the mmap'ed page, the mtime field
will not be updated again.  We *could* constantly reset the page table
flags but it would be disastrous from a performance standpoint, and if
mmap is involved, Posix does *not* guarantee that mtime field will be
set each time a process writes to the mmap'ed segment --- because that
would be insane.

Regards,

						- Ted

Re: [4.1-rc] File was modified, but mtime stayed the same (according to unison)

[Pavel Machek]

On Tue 2015-06-09 11:12:09, Theodore Ts'o wrote:
> On Tue, Jun 09, 2015 at 12:43:30PM +0200, Pavel Machek wrote:
> > 
> > Hi!
> > 
> > Today, I got strange warning from unison:
> > 
> > pavel/.config/chromium/Default/Extension State/LOG.old — transport
> > failure
> > • The source file /data/pavel/.config/chromium/Default/Extension
> > State/LOG.old
> > has been modified but the fast update detection mechanism
> > failed to detect it.  Try running once with the fastcheck
> > option set to 'no'.
> 
> What does this mean, precisely?  Is Unison checking that files have
> been modified using some kind of a checksum or file comparison
> mechanism?  And I assume that the "fast update detection mechanism"
> using mtime?

I believe it is using checksum in the process, yes. 

> And if it has modified, how was it modified (can you do a diff with
> what the other side of the synchronization setup had for that file),
> and do you know by which process. and what was it trying to do?  And
> how is unison being run?

No, sorry, I don't think I can get old version of file.

> One thing that could be going on is that if you have a file which is
> mmap'ed, the mtime field is set the first time the page is modified
> (when the page table entry is set to read/write from read-only).  If
> unison then takes a snapshot of the file, and then file is
> subsequently modified via a write to the mmap'ed page, the mtime field
> will not be updated again.  We *could* constantly reset the page table
> flags but it would be disastrous from a performance standpoint, and if
> mmap is involved, Posix does *not* guarantee that mtime field will be
> set each time a process writes to the mmap'ed segment --- because that
> would be insane.

Ok, I guess mmap() can explain this. So... basically mtime is useless
in detecting if file have been updated?

Thats... not welcome.

I see that constantly updating on-disk timestamp is not
feasible. Could we do something like

  on page_being_mmapped_rw:
	     file.mtime = "future".

  on last_rw_mmap_disappearing:
  	     file.mtime = now().

  stat():
	if file.mtime != "future":
		result.mtime = file.mtime
	else:
		result.mtime = now()

? I see making stat slower is not welcome, but having to read complete
files to determine if they were modified is even worse than that...

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: [4.1-rc] File was modified, but mtime stayed the same (according to unison)

[Theodore Ts'o]

On Tue, Jun 09, 2015 at 05:34:29PM +0200, Pavel Machek wrote:
> 
> Ok, I guess mmap() can explain this. So... basically mtime is useless
> in detecting if file have been updated?
> 
> Thats... not welcome.

Using mtime to detect if a file has been updated if there is a process
updating the file at the same time you are trying to take snapshots
and using mtime is inherently racy.

This was much more obvious for file systems with a one second mtime
granularity, but because of mmap(2), it's still not true even if you
have a file system with nanosecond timestamps.

> I see that constantly updating on-disk timestamp is not
> feasible. Could we do something like
> 
>   on page_being_mmapped_rw:
> 	     file.mtime = "future".
> 
>   on last_rw_mmap_disappearing:
>   	     file.mtime = now().
> 
>   stat():
> 	if file.mtime != "future":
> 		result.mtime = file.mtime
> 	else:
> 		result.mtime = now()
> 
> ? I see making stat slower is not welcome, but having to read complete
> files to determine if they were modified is even worse than that...

Doing this would violate POSIX, and would probably break other
programs that would be surprised when mtime goes backwards.  I suspect
a better thing to do is to add a new system call interface which
allows a userspace process to query whether a file is either (a)
opened for read, (b) opened for write, and/or (c) mmap'ed.  Not all
file systems would be able to return this bitfield --- for example, it
wouldn't be possible to do this for NFS, for example, and it's not
clear how this should or could work for overlayfs.

Unison could then be modified to use this new system call interface,
so it can take special care if the file is currently opened for write
or mmap'ed.  Note that because of the mtime granularity issues, which
can be constrained by the on-disk file system field, as well as the
granularity of the hardware clocks available to the system, unison
could get fooled nonetheless.

Regards,

						- Ted

Re: [4.1-rc] File was modified, but mtime stayed the same (according to unison)

[Dave Chinner]

On Tue, Jun 09, 2015 at 11:12:09AM -0400, Theodore Ts'o wrote:
> On Tue, Jun 09, 2015 at 12:43:30PM +0200, Pavel Machek wrote:
> > 
> > Hi!
> > 
> > Today, I got strange warning from unison:
> > 
> > pavel/.config/chromium/Default/Extension State/LOG.old — transport
> > failure
> > • The source file /data/pavel/.config/chromium/Default/Extension
> > State/LOG.old
> > has been modified but the fast update detection mechanism
> > failed to detect it.  Try running once with the fastcheck
> > option set to 'no'.
> 
> What does this mean, precisely?  Is Unison checking that files have
> been modified using some kind of a checksum or file comparison
> mechanism?  And I assume that the "fast update detection mechanism"
> using mtime?
> 
> And if it has modified, how was it modified (can you do a diff with
> what the other side of the synchronization setup had for that file),
> and do you know by which process. and what was it trying to do?  And
> how is unison being run?
> 
> One thing that could be going on is that if you have a file which is
> mmap'ed, the mtime field is set the first time the page is modified
> (when the page table entry is set to read/write from read-only).  If
> unison then takes a snapshot of the file, and then file is
> subsequently modified via a write to the mmap'ed page, the mtime field
> will not be updated again.

That's not right: when dirty mmap pages are cleaned by writeback the
PTEs are cleaned, too.  Hence on the next modification of that page
we will get a new write page fault that modifies the mtime. IOWs, if
the "snapshot" involves writing back the file, then it will be
marked clean and the next page fault will cause the mtime to be
updated.

In general, this means that constantly dirtied mmap files will have
the mtime updated at least every 30s and background writeback cleans
dirty pages. Usually, however, it is much more often than that as
each clean page that is dirtied will cause the mtime to be updated
due to traversal through the ->page_mkwrite -> ext4_page_mkwrite()
-> file_update_time() path.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com