tests/test-propertycache.py.out
author Gregory Szorc <gregory.szorc@gmail.com>
Thu, 14 Jan 2016 13:44:01 -0800
changeset 27897 2fdbf22a1b63
parent 19846 9789670992d6
permissions -rw-r--r--
streamclone: use backgroundfilecloser (issue4889) Closing files that have been appended to is slow on Windows/NTFS. CloseHandle() calls on this platform often take 1-10ms - and that's on my i7-6700K Skylake processor with a modern and fast SSD. Contrast with other I/O operations, such as writing data, which take <100us. This means that creating/appending thousands of files can add significant overhead. For example, cloning mozilla-central creates ~232,000 revlog files. Assuming 1ms per CloseHandle(), that yields 232s (3:52) of wall time waiting for file closes! The impact of this overhead can be measured most directly when applying stream clone bundles. Applying these files is effectively uncompressing a tar archive (read: it's very fast). Using a RAM disk (read: no I/O wait), the difference in wall time for a `hg debugapplystreamclonebundle` for a ~1731 MB mozilla-central bundle between Windows and Linux from the same machine is drastic: Linux: ~12.8s (128MB/s) Windows: ~352.0s (4.7MB/s) Windows is ~27.5x slower. Yikes! After this patch: Linux: ~12.8s (128MB/s) Windows: ~102.1s (16.1MB/s) Windows is now ~3.4x faster. Unfortunately, it is still ~8x slower than Linux. Profiling reveals a few hot code paths that could likely be improved. But those are for other patches. This patch introduces test-clone-uncompressed.t because existing tests of `clone --uncompressed` are scattered about and adding a variation for background thread closing to e.g. test-http.t doesn't feel correct.


=== property cache ===

calllog: []
cached value (unfiltered): NOCACHE

= first access on unfiltered, should do a call
access: 0
calllog: [0]
cached value (unfiltered): 0

= second access on unfiltered, should not do call
access 0
calllog: [0]
cached value (unfiltered): 0

= first access on "visible" view, should do a call
cached value ("visible" view): NOCACHE
access: 7
calllog: [0, 7]
cached value (unfiltered): 0
cached value ("visible" view): 7

= second access on "visible view", should not do call
access: 7
calllog: [0, 7]
cached value (unfiltered): 0
cached value ("visible" view): 7

= no effect on other view
cached value ("immutable" view): NOCACHE
access: 9
calllog: [0, 7, 9]
cached value (unfiltered): 0
cached value ("visible" view): 7
cached value ("immutable" view): 9


=== unfiltered property cache ===

unficalllog: []
cached value (unfiltered):       NOCACHE
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE

= first access on unfiltered, should do a call
access (unfiltered): 100
unficalllog: [100]
cached value (unfiltered):       100

= second access on unfiltered, should not do call
access (unfiltered): 100
unficalllog: [100]
cached value (unfiltered):       100

= access on view should use the unfiltered cache
access (unfiltered):       100
access ("visible" view):   100
access ("immutable" view): 100
unficalllog: [100]
cached value (unfiltered):       100
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE

= even if we clear the unfiltered cache
cached value (unfiltered):       NOCACHE
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE
unficalllog: [100]
access ("visible" view):   100
unficalllog: [100, 100]
cached value (unfiltered):       100
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE
access ("immutable" view): 100
unficalllog: [100, 100]
cached value (unfiltered):       100
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE
access (unfiltered):       100
unficalllog: [100, 100]
cached value (unfiltered):       100
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE