Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Also consider creation time for purge_files_after #119

Closed
chennin opened this issue Nov 18, 2024 · 7 comments
Closed

Also consider creation time for purge_files_after #119

chennin opened this issue Nov 18, 2024 · 7 comments

Comments

@chennin
Copy link

chennin commented Nov 18, 2024

OS: Ubuntu 24.04
Filesystem: ZFS. relatime=on, atime=on.

When pacoloco downloads a file, creation time is set, but access time is not set, whether it was downloaded at client request or as part of prefetch. Access time is defaulting to time 0. Then whenever purge_files_after runs, it deletes anything that hasn't been accessed in the meantime by a second client, wasting bandwidth.

The access time is the same whether I have relatime on or off, tested with new file creation. ext4 does set the access time upon file creation.

Please have purge_files_after consider creation time as well as access time, and not delete files created within the purge_files_after time.

As for workarounds: if I manually delete files with find, will pacoloco behave, or is it keeping its own database that that would mess up?

Unix epoch 0, 1969 in my time zone:

# stat /var/lib/docker/volumes/root_pacoloco/_data/pkgs/archlinux/aom-3.11.0-1-x86_64.pkg.tar.zst
  File: /var/lib/docker/volumes/root_pacoloco/_data/pkgs/archlinux/aom-3.11.0-1-x86_64.pkg.tar.zst
  Size: 2893239         Blocks: 5673       IO Block: 131072 regular file
Device: 0,40    Inode: 363956      Links: 1
Access: (0644/-rw-r--r--)  Uid: (  122/pacoloco)   Gid: ( 1999/pacoloco)
Access: 1969-12-31 19:00:00.000000000 -0500
Modify: 2024-11-17 19:50:28.000000000 -0500
Change: 2024-11-17 22:01:27.738647686 -0500
 Birth: 2024-11-17 22:01:27.178647927 -0500

Example logs of a totally wasted download - it was downloaded and deleted while I was asleep, and the computer that would download this package will be turned on and updated on tomorrow:

Nov 17 00:41:00 tarkin docker/prod-pacoloco[1936]: prefetch.go:273: Starting prefetching packages...
...
Nov 17 00:41:01 tarkin docker/prod-pacoloco[1936]: downloader.go:111: downloading https://mirrors.mit.edu/archlinux/extra/os/x86_64/edk2-shell-202408.01-1-any.pkg.tar.zst
Nov 17 00:41:01 tarkin docker/prod-pacoloco[1936]: prefetch.go:252: Successfully prefetched edk2-shell-any package
Nov 17 00:41:01 tarkin docker/prod-pacoloco[1936]: downloader.go:111: downloading https://mirrors.mit.edu/archlinux/extra/os/x86_64/edk2-shell-202408.01-1-any.pkg.tar.zst.sig
Nov 17 00:41:01 tarkin docker/prod-pacoloco[1936]: prefetch.go:250: Successfully prefetched edk2-shell-any signature
Nov 17 00:41:01 tarkin docker/prod-pacoloco[1936]: prefetch.go:275: Finished prefetching packages!
Nov 17 00:41:01 tarkin docker/prod-pacoloco[1936]: prefetch.go:276: Finished prefetching routine!
...
Nov 17 09:10:04 tarkin docker/prod-pacoloco[1936]: purge.go:56: Remove stale file /var/cache/pacoloco/pkgs/archlinux/edk2-shell-202408.01-1-any.pkg.tar.zst as its access time (1970-01-01 00:00:00 +0000 UTC) is too old
Nov 17 09:10:04 tarkin docker/prod-pacoloco[1936]: purge.go:56: Remove stale file /var/cache/pacoloco/pkgs/archlinux/edk2-shell-202408.01-1-any.pkg.tar.zst.sig as its access time (1970-01-01 00:00:00 +0000 UTC) is too old
chennin added a commit to chennin/pacoloco that referenced this issue Nov 18, 2024
Files initially created on some filesystems (ZFS) may have an access
time of the Unix epoch.

Addresses anatol#119
chennin added a commit to chennin/pacoloco that referenced this issue Nov 18, 2024
Files initially created on some filesystems (ZFS) may have an access
time of the Unix epoch.

Addresses anatol#119
@chennin
Copy link
Author

chennin commented Nov 18, 2024

This is a stab at incompletely addressing this, by ignoring files with an access time set to the Unix epoch:

chennin@156dc1d

I also had a go at using the birth time, but it doesn't look like we are able to fake the birth time, so I'm not sure what to do about the tests without changing the signature of purgeStaleFiles().

This should work, but causes a test to fail as the fileToRemove is not removed due to being created too recently.

		atime := t.AccessTime()
		var btime time.Time
		if t.HasBirthTime() {
				btime = t.BirthTime()
		}
		if atime.Before(removeIfOlder) && btime.Before(removeIfOlder) {
			log.Printf("Removing stale file %v as its access time (%v) and birth time (if available: %v) are too old", path, atime, btime)
			if err := os.Remove(path); err != nil {
				log.Print(err)
			}
		}

@anatol
Copy link
Owner

anatol commented Nov 19, 2024

So ext4 filesystem sets the access time, but not ZFS. Do we have an idea why?

What happens if you access the ZFS file, do you see that the file access time actually changed?

@chennin
Copy link
Author

chennin commented Nov 19, 2024

I do not know why, but here are the repro steps. Yes, when accessing it it changes. When using pacoloco, a second client requesting the package will update the time. As will file, but not on empty files apparently, and touch will not.

# uname -a
Linux tarkin 6.8.0-48-generic #48-Ubuntu SMP PREEMPT_DYNAMIC Fri Sep 27 14:04:52 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
# zfs version
zfs-2.2.2-0ubuntu9.1
zfs-kmod-2.2.2-0ubuntu9
# cd /tmp
# dd if=/dev/zero of=./tmpfile bs=1M count=100
# zpool create -O atime=on -O relatime=off -m /mnt test $PWD/tmpfile

# touch /mnt/a && stat /mnt/a
  File: /mnt/a
  Size: 0         	Blocks: 1          IO Block: 131072 regular empty file
Device: 0,79	Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 1969-12-31 19:00:00.000000000 -0500
Modify: 2024-11-18 20:08:52.250449435 -0500
Change: 2024-11-18 20:08:52.250449435 -0500
 Birth: 2024-11-18 20:08:52.250449435 -0500

# touch /mnt/a && stat /mnt/a
  File: /mnt/a
  Size: 0         	Blocks: 1          IO Block: 131072 regular empty file
Device: 0,79	Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 1969-12-31 19:00:00.000000000 -0500
Modify: 2024-11-18 20:08:53.231451782 -0500
Change: 2024-11-18 20:08:53.231451782 -0500
 Birth: 2024-11-18 20:08:52.250449435 -0500

# file /mnt/a && stat /mnt/a
/mnt/a: empty
  File: /mnt/a
  Size: 0         	Blocks: 1          IO Block: 131072 regular empty file
Device: 0,79	Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 1969-12-31 19:00:00.000000000 -0500
Modify: 2024-11-18 20:08:53.231451782 -0500
Change: 2024-11-18 20:08:53.231451782 -0500
 Birth: 2024-11-18 20:08:52.250449435 -0500

# echo "a" > /mnt/a && stat /mnt/a
  File: /mnt/a
  Size: 2         	Blocks: 1          IO Block: 512    regular file
Device: 0,79	Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 1969-12-31 19:00:00.000000000 -0500
Modify: 2024-11-18 20:09:04.772479272 -0500
Change: 2024-11-18 20:09:04.772479272 -0500
 Birth: 2024-11-18 20:08:52.250449435 -0500

# file /mnt/a && stat /mnt/a
/mnt/a: ASCII text
  File: /mnt/a
  Size: 2         	Blocks: 1          IO Block: 512    regular file
Device: 0,79	Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2024-11-18 20:09:07.740486308 -0500
Modify: 2024-11-18 20:09:04.772479272 -0500
Change: 2024-11-18 20:09:04.772479272 -0500
 Birth: 2024-11-18 20:08:52.250449435 -0500

# cat /mnt/a && stat /mnt/a
a
  File: /mnt/a
  Size: 2         	Blocks: 1          IO Block: 512    regular file
Device: 0,79	Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2024-11-18 20:09:15.049503576 -0500
Modify: 2024-11-18 20:09:04.772479272 -0500
Change: 2024-11-18 20:09:04.772479272 -0500
 Birth: 2024-11-18 20:08:52.250449435 -0500


# echo "a" > /mnt/two && stat /mnt/two
  File: /mnt/two
  Size: 2         	Blocks: 1          IO Block: 512    regular file
Device: 0,79	Inode: 3           Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2024-11-18 20:12:27.678932993 -0500
Modify: 2024-11-18 20:12:27.678932993 -0500
Change: 2024-11-18 20:12:27.678932993 -0500
 Birth: 2024-11-18 20:12:27.678932993 -0500

# umount /mnt; zpool destroy test

@anatol
Copy link
Owner

anatol commented Nov 19, 2024

When using pacoloco, a second client requesting the package will update the time.

In this case the problem seems in the way the file is created. Currently we set the file times only if the upstream repository has reported it with Last-Modified header.

We should set birth and access times even if the HTTP header is absent. To test this idea @chennin could you please try this change? https://github.com/anatol/pacoloco/tree/issue-119

@chennin
Copy link
Author

chennin commented Nov 19, 2024

Hi, it does not, and when I tried commenting out the os.Chtimes, access time was current. Uncommented it and we're back to 1969. I'm confused, it's as if os.Chtimes just ignores the atime and sets it to 0, or ZFS is. I'm going to have to write a smaller go reproducer to experiment with tomorrow.

@chennin
Copy link
Author

chennin commented Nov 19, 2024

So this looks a lot like a ZFS bug/PR openzfs/zfs#15773 that would need to make it in to the Ubuntu kernel to fix it for me.

I made a playground if anyone still wants to test (disclaimer: I don't know go).

Thanks for your time. For now I have a cron job that runs file on every package that has been "accessed" more than 10,000 days ago, which updates the atime successfully.

@chennin
Copy link
Author

chennin commented Nov 19, 2024

And I confirmed this does NOT reproduce on Ubuntu 24.10 with zfs-2.2.6-1ubuntu1 and 6.11.0-9-generic.

@chennin chennin closed this as completed Nov 19, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants