Odd behaviour while cloning (redundant seeks?)

[Greg Ward]

I got bored waiting for Mercurial to clone a local 900MB repository,
so I ran lsof and strace on to see what it was up to.  I noticed this
odd-looking sequence of system calls:

[...many identical _llseek() calls...]
_llseek(3, 4694016, [4694016], SEEK_SET) = 0
_llseek(3, 4694016, [4694016], SEEK_SET) = 0
_llseek(3, 4694016, [4694016], SEEK_SET) = 0
read(3, "\0\0\0\363Bf\0\0\0\0\0\341\0\0\0019\0\1\36\177\0\1\36\200\0\1\36\177\377\377\377\377"...,
4096) = 4096
_llseek(3, 4698112, [4698112], SEEK_SET) = 0
_llseek(3, 4698112, [4698112], SEEK_SET) = 0
_llseek(3, 4698112, [4698112], SEEK_SET) = 0
[...many identical _llseek() calls...]
_llseek(3, 4698112, [4698112], SEEK_SET) = 0
_llseek(3, 4698112, [4698112], SEEK_SET) = 0
_llseek(3, 4698112, [4698112], SEEK_SET) = 0
read(3, "\0\0\0\363\202\16\0\0\0\0\1\32\0\0\1\314\0\1\36\277\0\1\36\300\0\1\36\277\377\377\377\377"...,
4096) = 4096
_llseek(3, 4702208, [4702208], SEEK_SET) = 0
_llseek(3, 4702208, [4702208], SEEK_SET) = 0
_llseek(3, 4702208, [4702208], SEEK_SET) = 0
[...many identical _llseek() calls...]

Those sequences of identical _llseek() calls seem to be 30-40 calls
long.  File descriptor 3 was .hg/store/00changelog.i.  After a few
repetitions of the above cycle, I saw this:

[...more redundant _llseek()s...]
_llseek(3, 4702208, [4702208], SEEK_SET) = 0
open("/home/gward/repos/master/.hg/store/00changelog.d",
O_RDONLY|O_LARGEFILE) = 5
fstat64(5, {st_mode=S_IFREG|0644, st_size=22770915, ...}) = 0
fstat64(5, {st_mode=S_IFREG|0644, st_size=22770915, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb7f0c000
_llseek(5, 15962112, [15962112], SEEK_SET) = 0
read(5, "\356\374\3\2628O^x\234\35\312\275\16\2020\24\5`f^\302\273:HZ\240@\331\360gp#"...,
2906) = 2906
read(5, "x\234U\215\261N\3030\20\206;\347)ne\240\211c\'!\331\332\262\260U\352\200\304\202\354\313%"...,
65536) = 65536
close(5)                                = 0
munmap(0xb7f0c000, 4096)                = 0
_llseek(3, 4702208, [4702208], SEEK_SET) = 0
[...more redundant _llseek()s...]

Then it's back to four cycles of "many redundant _llseek()s followed
by a single read()".  Then it reads another chunk of 00changelog.d:

[...more redundant _llseek()s...]
_llseek(3, 4718592, [4718592], SEEK_SET) = 0
open("/home/gward/repos/fullpacs.hg/.hg/store/00changelog.d",
O_RDONLY|O_LARGEFILE) = 5
fstat64(5, {st_mode=S_IFREG|0644, st_size=22770915, ...}) = 0
fstat64(5, {st_mode=S_IFREG|0644, st_size=22770915, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb7f0c000
_llseek(5, 16027648, [16027648], SEEK_SET) = 0
read(5, "\3609\241\3251=\374Etq\230p\234\263/\322\2372\34x\234\25\215Mn\303
\24\6\367\234\342"..., 2872) = 2872
read(5, "x\2345\216\275n\3020\24Fw?\305}\2\22\223\330\1\204\20\2D\227n\331Zu\360\317\r\261"...,
65536) = 65536
close(5)                                = 0
munmap(0xb7f0c000, 4096)                = 0
_llseek(3, 4718592, [4718592], SEEK_SET) = 0
[...more redundant _llseek()s...]

Then 5 more cycles of "many redundant _llseek()s followed by a single
read()", followed by another open()+read() from 00changelog.d.

After that I got bored and killed strace.  This all happened in a few
seconds, but the redundant _llseek() calls certainly got my attention.

Oh yeah: I'm running hg from crew with a big stack of local patches.
Most of my patches are related to CVS conversion, though, so I'm
dubious that I could have screwed up cloning or reading the changelog.

Any ideas, suggestions, thoughts?  Have I uncovered a hidden
performance bug, or is this expected?  Worth investigating further?

Greg