diff --git a/doc/bugs/__96__sync_-C__96___takes_longer_to_get_file_than___96__get__96__/comment_7_a0b287e187396b7072e4d7bab3664621._comment b/doc/bugs/__96__sync_-C__96___takes_longer_to_get_file_than___96__get__96__/comment_7_a0b287e187396b7072e4d7bab3664621._comment new file mode 100644 index 0000000000..80a7f63c1d --- /dev/null +++ b/doc/bugs/__96__sync_-C__96___takes_longer_to_get_file_than___96__get__96__/comment_7_a0b287e187396b7072e4d7bab3664621._comment @@ -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.) +"""]] diff --git a/doc/bugs/__96__sync_-C__96___takes_longer_to_get_file_than___96__get__96__/comment_8_0b4e0acecbcc6a8736849801446a189c._comment b/doc/bugs/__96__sync_-C__96___takes_longer_to_get_file_than___96__get__96__/comment_8_0b4e0acecbcc6a8736849801446a189c._comment new file mode 100644 index 0000000000..575b876226 --- /dev/null +++ b/doc/bugs/__96__sync_-C__96___takes_longer_to_get_file_than___96__get__96__/comment_8_0b4e0acecbcc6a8736849801446a189c._comment @@ -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 + ... + 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, {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, TCGETS + 1654393 14:58:13.573471 read(4, + 1654392 14:58:13.573601 <... ioctl resumed>, 0x7ffd3d3fa9d0) = -1 EINVAL (Invalid argument) + 1654392 14:58:13.573753 read(15, "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, + +Certianly does look like a checksum operation. + +Just before the second open is this: + + 1654396 14:58:13.570074 pread64(21, "\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 + 1654393 14:58:13.570562 read(4, + 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 + 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, + 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, + +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. +"""]]