mirrors/git-annex
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages 1 Wiki Activity Actions

started analysis

Browse source
This commit is contained in:
Joey Hess 2021-09-30 15:20:44 -04:00
parent 6de57642f4
commit 620685c73c
No known key found for this signature in database
GPG key ID: DB12DB0FF05F8F38
2 changed files with 83 additions and 0 deletions
Download patch file Download diff file Expand all files Collapse all files

31
doc/bugs/__96__sync_-C__96___takes_longer_to_get_file_than___96__get__96__/comment_7_a0b287e187396b7072e4d7bab3664621._comment Normal file
View file

@ -0,0 +1,31 @@
[[!comment format=mdwn
username="joey"
subject="""comment 7"""
date="2021-09-30T18:44:53Z"
content="""
I've received the sample repo, and can reproduce the problem using its
script. (After changing a /bin/time to not hardcode the wrong path.)
get 9BEAE03792B9FAFB-01-01--partial.dat.age (from origin...)
ok
(recording state in git...)
* Number of read(2) file operations of annex object during `get` sub-command: 3205
* op: sync -C
drop 9BEAE03792B9FAFB-01-01--partial.dat.age ok
(recording state in git...)
get 9BEAE03792B9FAFB-01-01--partial.dat.age (from origin...)
ok
(recording state in git...)
(recording state in git...)
* Number of read(2) file operations of annex object during `sync -C` sub-command: 6410
Should be possible to track down the extra work from here.
(Sample repo stored in my big annex as
`git-annex-test-repos/Reflect-varmistukset-test@issue.tar`.
Mail with details of how to use it is
`1321234683.1930009.1633025607916@privateemail.com`.
Note that NTFS filesystem needs to be 1.5 gb or larger in size.)
"""]]

52
doc/bugs/__96__sync_-C__96___takes_longer_to_get_file_than___96__get__96__/comment_8_0b4e0acecbcc6a8736849801446a189c._comment Normal file
View file

@ -0,0 +1,52 @@
[[!comment format=mdwn
username="joey"
subject="""comment 8"""
date="2021-09-30T19:15:14Z"
content="""
Initial look at the strace of the sync shows it's opening the
object file after it copies it from the remote repo, and reading
it a second time.
1654392 14:58:09.293550 openat(AT_FDCWD, "/mnt/Reflect-varmistukset-test@issue/.git/annex/objects/f19/dad/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age", O_RDONLY|O_NOCTTY|O_NONBLOCK <unfinished ...>
...
1654392 14:58:13.572543 openat(AT_FDCWD, ".git/annex/objects/f19/dad/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age", O_RDONLY|O_NOCTTY|O_NONBLOCK) = 15
1654392 14:58:13.573055 fstat(15</mnt/Reflect-varmistukset-test@issue2/.git/annex/objects/f19/dad/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age>, {st_mode=S_IFREG|0777, st_size=104883384, ...}) = 0
1654393 14:58:13.573282 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
1654392 14:58:13.573370 ioctl(15</mnt/Reflect-varmistukset-test@issue2/.git/annex/objects/f19/dad/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age>, TCGETS <unfinished ...>
1654393 14:58:13.573471 read(4<anon_inode:[timerfd]>, <unfinished ...>
1654392 14:58:13.573601 <... ioctl resumed>, 0x7ffd3d3fa9d0) = -1 EINVAL (Invalid argument)
1654392 14:58:13.573753 read(15</mnt/Reflect-varmistukset-test@issue2/.git/annex/objects/f19/dad/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age>, "age-encryption.org/v1\n-> X25519 "..., 32752) = 32752
1654393 14:58:13.574238 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
1654392 14:58:13.574356 read(15</mnt/Reflect-varmistukset-test@issue2/.git/annex/objects/f19/dad/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age>, <unfinished ...>
Certianly does look like a checksum operation.
Just before the second open is this:
1654396 14:58:13.570074 pread64(21</mnt/Reflect-varmistukset-test@issue2/.git/annex/keysdb/db>, "\n\0\0\0\0\20\0\0\17\251\0\0\0\0\0\0\0\0
\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 20480) = 4096
1654393 14:58:13.570353 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
1654396 14:58:13.570464 futex(0xb7af808, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
1654393 14:58:13.570562 read(4<anon_inode:[timerfd]>, <unfinished ...>
1654396 14:58:13.570727 <... futex resumed>) = 1
1654392 14:58:13.570834 <... futex resumed>) = 0
1654396 14:58:13.570948 futex(0xb7afb28, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
1654392 14:58:13.571040 futex(0xb7af810, FUTEX_WAKE_PRIVATE, 1) = 0
1654393 14:58:13.571239 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
1654393 14:58:13.571356 read(4<anon_inode:[timerfd]>, <unfinished ...>
1654392 14:58:13.571450 stat(".git/annex/objects/f19/dad/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age/MD5E-s104883384--4187e
ad516ef69c540aab3d27eba27c5.dat.age", {st_mode=S_IFREG|0777, st_size=104883384, ...}) = 0
1654392 14:58:13.571958 access(".git/annex/objects/f19/dad/MD5E-s104883384--4187ead516ef69c540aab3d27eba27c5.dat.age/MD5E-s104883384--418
7ead516ef69c540aab3d27eba27c5.dat.age", F_OK) = 0
1654393 14:58:13.572314 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
1654393 14:58:13.572425 read(4<anon_inode:[timerfd]>, <unfinished ...>
That looks like a query from the keys db for the inode cache,
followed by checking stat of the object to verify it.
So maybe an inode cache verification issue, which is being
resolved by a checksum..
So far, I've ruled out prepSendAnnex's call to sameInodeCache.
The InodeCache of the object verifies there. The second open comes
later.
"""]]