Excessive time spent in CloseFile on Windows

[Gregory Szorc]

Using Process Monitor [1], I captured system calls and timings from `hg
unbundle` when applying a gzipped mozilla-central bundle (264,403
changesets with 1,492,215 changes to 222,507 files). This is roughly
equivalent to `hg clone` without the networking bits. The results (with the
revlog write reduction patch I just sent to the list applied) are as
follows (total times below 0.01s ignored):

Time        Count       Mean           Operation
364.28s   529,993  0.00068734s     CloseFile
 78.23s 1,009,827  0.00007747s     CreateFile
 18.61s    824,331  0.00002258s     WriteFile
  3.48s  1,223,309  0.00000284s     QueryStandardInformationFile
  1.89s       76,504  0.00002465s     ReadFile
  0.90s     249,678  0.00000359s     QueryAllInformationFile
  0.64s     249,678  0.00000256s     QueryInformationVolume
  0.61s     243,730  0.00000251s     QueryBasicInformationFile
  0.17s        2,502   0.00006782s     SetRenameInformationFile
  0.06s      16,057   0.00000369s     QueryEAFile
  0.06s      16,156   0.00000358s     SetBasicInformationFile
  0.01s        3,337   0.00000273s     QueryAttributeTagFile
  0.01s           835   0.00000604s     SetDispositionInformationFile

I made some crude histograms and CloseFile/CreateFile has local maximums in
the 1us and 0.01+s areas (these are a few magnitudes apart performance
wise). Looking at the raw data, it looks like CloseFile is significantly
slower if there were writes after CreateFile. This does seem to make sense:
I'm guessing Windows defers some operations to file close time and
CloseFile can fast path if there is nothing to do.

With the current implementation of revlogs as of my latest patch, we'll
reopen revlogs if and only if a new delta chain is started. And every new
delta chain appears to incur an I/O pause in the 1-100ms range on Windows.
These add up, as my recent followup post documenting a 5x changelog speedup
due to avoiding reopens after every revision addition showed.

FWIW in the commit message of the "avoid flush" patch I sent to the list
earlier, I said it resulted in no speedup on Windows. I only based that
claim on the hg repository. I should probably retest with mozilla-central
to test my theory about CloseFile after writes being the source of
slowdowns...

Given this data and the impact from the changelog change, I'm pretty
convinced we should refactor revlogs to share file handles so we avoid file
reopens as much as possible. This should reduce file opens by ~50% with
mozilla-central and I'm optimistic it will significantly speed up
unbundle/clone on Windows as a result. I don't think there is any good
reason not to do this work: even without this data it seems inefficient to
open ~2x the file handles as the number of files we end up touching.

Longer term, I'm thinking we might want to use multiple threads to perform
I/O operations so the data processing thread isn't idle waiting on I/O to
finish. Even longer term I'd like to explore alternate changegroup formats
that support "intertwined" "fibers" of data so consumers (and even
producers) can use multiple CPU cores for decoding and writing data
concurrently.

I'm curious if others have explored this aspect of Windows performance
before and have anything useful to add to my observations. I concede to not
being an expert on Windows performance, so please independently verify my
data and challenge my assertions.

[1] https://technet.microsoft.com/en-us/sysinternals/bb896645.aspx
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://selenic.com/pipermail/mercurial-devel/attachments/20150927/aab3fbc0/attachment.html>