Watchman: Watchman drastically slows down I/O from other processes on Windows

[indygreg]

I'm using Watchman 4.9.0 on Windows 10 Fall Creators Update. I'm also using Mercurial 4.4.1 with the fsmonitor extension (Watchman integration) enabled.

Having fsmonitor/watchman enabled drastically speeds up working directory operations like hg status. However, the presence of watchman.exe and its watch on the Mercurial repository drastically slows down write I/O in the .hg/ directory and in the working directory.

STR:

1. Download a Mercurial "stream" bundle from https://hg.cdn.mozilla.net/.
2. hg init repo
3. cd repo
4. hg status # starts watchman.exe + watch for this repo
5. hg debugapplystreamclonebundle path/to/stream/bundle
6. Observe speed of bundle application
7. Open process manager and kill watchman.exe
8. Observe Mercurial operation speed up by 4-5x.

If we use Sysinternals Process Monitor (procmon) and trace the python.exe process belonging to Mercurial, we see thousands of CreateFile, QueryInformationVolume, QueryAllInformationFile, WriteFile, and CloseFile operations for the thousands of Mercurial revlogs (.i and .d files).

When the watchman.exe process is running and observing the Mercurial repo, the timing of these operations changes. Specifically, CreateFile operations that result in directory or file creations are 1700-1800us with watchman running and ~80us without watchman. 1700us multiplied by 100,000 files is 170 seconds.

It is semi well-known that anti-virus scanners on Windows perform file content scanning at file close time, delaying the CloseHandle() call by a few milliseconds on average. This is why Mercurial uses a thread pool on Windows just to close file handles. However, the slowdown of file creation due to (apparently) directory watching is new to me. Perhaps internally Windows is dispatching events to watchman synchronously before completing the file open I/O request?

Anyway, the file creation overhead that is somehow introduced when watchman is watching a directory adds minutes to Mercurial operations that need to touch a few hundred thousand files. If watchman is running but not observing the directory, no slowdown occurs.

[wez]

Hmm, we had to introduce this latency tunable (https://github.com/facebook/watchman/blob/master/watcher/win32.cpp#L120-L124) because windows dispatches change notifications through to watchman extremely quickly and this was causing sharing problems for apps that didn't use relaxed sharing modes when opening file handles.

I think what you're describing sounds like a similar issue. My suggestion is that you try raising that tunable and see if you can find a sweet(er) spot for it. You can set it in the .watchmanconfig file in the repo:

{"win32_batch_latency_ms": 100}

The tunable imposes an artificial delay between when watchman is notified of file changes and when it will start to try to access the changed files. Making it larger means that we are less likely to collide with something else, but also will increase the minimum latency that you will observe with hg status by the same amount.

You'll need to stop and restart the watch for changes to that file to take effect.

If we don't have any luck here, there's another approach that could be tried; using the win32 change journal. That would be a pretty significant change because it requires administrator access which would change the security model of watchman. I've been told by folks inside MS that there's a non-privileged variant of this that will ship in a future windows update, but I don't know when that will be practically available to most folks.

[indygreg]

I should have included some hard timings.

Using a recent stream clone bundle of the mozilla-unified repo:

No watchman

$ hg init repo
$ cd repo
$ time hg debugapplystreamclonebundle  /path/to/xxx.packed1.hg
392903 files to transfer, 2.08 GB of data
transferred 2.08 GB in 211.1 seconds (10.1 MB/sec)

real    3m31.325s
user    0m0.000s
sys     0m0.000s

watchman

$ hg init repo
$ cd repo
$ hg status
$ time hg debugapplystreamclonebundle  /path/to/xxx.packed1.hg
392903 files to transfer, 2.08 GB of data
transferred 2.08 GB in 2389.9 seconds (914 KB/sec)

real    39m50.168s
user    0m0.000s
sys     0m0.000s

In the real world, watchman shouldn't be observing a repo during a clone operation, so this test isn't reflective of real world usage. However, similar I/O patterns occur during hg pull and hg update. In fact, I discovered this performance issue when I noticed hg update operations taking much longer than I thought they should.

[indygreg]

Using ETW, we see that watchman.exe is spending a ton of time in ReadDirectoryChangesW(). ~2ms per call.

Using Windows Performance analyzer to get a flame graph from stack sampling, we see the bulk of that call looks to be some memory pool activity related to delivering notifications to the file system filter driver layer.

Line # | Process | Stack | Count | Weight (in view) (ms) | TimeStamp (s) | % Weight
-- | -- | -- | -- | -- | -- | --
14 |   | \|    watchman.exe!<PDB not found> | 5563 | 5,563.890898 |   | 2.39
15 |   | \|    \|- KernelBase.dll!ReadDirectoryChangesW | 4065 | 4,065.764189 |   | 1.75
16 |   | \|    \|    \|- KernelBase.dll!ReadDirectoryChangesExW | 4064 | 4,064.764189 |   | 1.75
17 |   | \|    \|    \|    \|- ntdll.dll!ZwNotifyChangeDirectoryFileEx | 4062 | 4,062.765737 |   | 1.74
18 |   | \|    \|    \|    \|    \|- ntoskrnl.exe!KiSystemServiceCopyEnd | 4060 | 4,060.765737 |   | 1.74
19 |   | \|    \|    \|    \|    \|    ntoskrnl.exe!NtNotifyChangeDirectoryFileEx | 4060 | 4,060.765737 |   | 1.74
20 |   | \|    \|    \|    \|    \|    \|- ntoskrnl.exe!IopSynchronousServiceTail | 3661 | 3,661.745514 |   | 1.57
21 |   | \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!IofCallDriver | 3659 | 3,659.745514 |   | 1.57
22 |   | \|    \|    \|    \|    \|    \|    \|    FLTMGR.SYS!FltpDispatch | 3659 | 3,659.745514 |   | 1.57
23 |   | \|    \|    \|    \|    \|    \|    \|    \|- FLTMGR.SYS!FltpLegacyProcessingAfterPreCallbacksCompleted | 3612 | 3,612.744538 |   | 1.55
24 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!IofCallDriver | 3611 | 3,611.744538 |   | 1.55
25 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- NTFS.sys!NtfsFsdDirectoryControl | 3610 | 3,610.744538 |   | 1.55
26 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- NTFS.sys!NtfsCommonDirectoryControl | 3550 | 3,550.745636 |   | 1.52
27 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- NTFS.sys!NtfsNotifyChangeDirectory | 3545 | 3,545.745636 |   | 1.52
28 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!FsRtlNotifyFilterChangeDirectoryLite | 3538 | 3,538.745681 |   | 1.52
29 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!FsRtlNotifyCompleteIrp | 3504 | 3,504.748310 |   | 1.50
30 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!ExFreePoolWithTag | 3484 | 3,484.748325 |   | 1.50
31 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    ntoskrnl.exe!ExFreeLargePool | 3484 | 3,484.748325 |   | 1.50
32 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiFreePagedPoolPages | 3483 | 3,483.748325 |   | 1.50
33 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiDeleteSystemPagableVm | 3433 | 3,433.747349 |   | 1.47
34 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiDeleteValidSystemPage | 2782 | 2,782.439079 |   | 1.19
35 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiPfnShareCountIsZero | 2009 | 2,009.347812 |   | 0.86
36 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiInsertPageInFreeOrZeroedList | 1942 | 1,942.349419 |   | 0.83
37 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiInsertPageInFreeOrZeroedList<itself> | 1522 | 1,522.276064 |   | 0.65
38 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiCoalesceFreePages | 386 | 386.076241 |   | 0.17
39 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiClearPfnImageVerified | 31 | 31.000210 |   | 0.01
40 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!KeSetEvent | 2 | 1.996904 |   | 0.00
41 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!KxWaitForLockChainValid | 1 | 1.000000 | 54.939667490 | 0.00
42 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiPfnShareCountIsZero<itself> | 67 | 66.998393 |   | 0.03
43 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiDeleteValidSystemPage<itself> | 773 | 773.091267 |   | 0.33
44 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiDeleteSystemPagableVm<itself> | 396 | 396.245360 |   | 0.17
45 |   | \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|    \|- ntoskrnl.exe!MiRemoveWsle | 216 | 216.062910 |   | 0.09

This is somewhat concerning because Watchman is using ReadDirectoryChangesW() in asynchronous mode. That should mean ReadDirectoryChangesW() is hardly ever on the stack. 2us would be much more reasonable than 2ms!

Since we see a lot of memory activity in the stack, the following paragraph from https://msdn.microsoft.com/en-us/library/windows/desktop/aa365465(v=vs.85).aspx seems like a possible explanation:

When you first call ReadDirectoryChangesW, the system allocates a buffer to store change information. This buffer is associated with the directory handle until it is closed and its size does not change during its lifetime. Directory changes that occur between calls to this function are added to the buffer and then returned with the next call. If the buffer overflows, the entire contents of the buffer are discarded, the lpBytesReturned parameter contains zero, and the ReadDirectoryChangesW function fails with the error code ERROR_NOTIFY_ENUM_DIR.

The destination buffer overflowing due to high file creation velocity seems like a plausible explanation. However, the watchman logs say otherwise:

2017-11-11T13:15:16,581: [readchange C:/dev/tmp/repo] waiting for change notifications
2017-11-11T13:15:16,581: [readchange C:/dev/tmp/repo] wait returned with status 0
2017-11-11T13:15:16,583: [readchange C:/dev/tmp/repo] waiting for change notifications
2017-11-11T13:15:16,583: [readchange C:/dev/tmp/repo] wait returned with status 0
2017-11-11T13:15:16,585: [readchange C:/dev/tmp/repo] waiting for change notifications
2017-11-11T13:15:16,585: [readchange C:/dev/tmp/repo] wait returned with status 0
2017-11-11T13:15:16,587: [readchange C:/dev/tmp/repo] waiting for change notifications
2017-11-11T13:15:16,587: [readchange C:/dev/tmp/repo] wait returned with status 0
2017-11-11T13:15:16,589: [readchange C:/dev/tmp/repo] waiting for change notifications
2017-11-11T13:15:16,589: [readchange C:/dev/tmp/repo] wait returned with status 0

We just have thousands of these messages. So sign of a non-0 return code from ReadDirectoryChangesW(). And, the timings also collaborate the 2ms/call we see from ProcMon.

I was thinking this may have something to do with the buffer that ReadDirectoryChangesW() writes to for watchman to consume. But that is a vector<uint8_t> and appears to be statically allocated.

Given that file system filter driver symbols are in the stack, I reckon that some other buffer (not controlled by watchman) is thrashing. Since the latency appears when a watch is registered, that would seem to indicate that some file system filter driver callback is registered to ReadDirectoryChangesW() events. This is possibly IRP_MJ_DIRECTORY_CONTROL (https://msdn.microsoft.com/en-us/library/windows/hardware/ff548658(v=vs.85).aspx). That would also explain NtfsNotifyChangeDirectory() on the stack.

Next in the stack is FsRtlNotifyFilterChangeDirectoryLite(). http://www.geoffchappell.com/studies/windows/km/ntoskrnl/history/names100.htm says that symbol is new in Windows 10. So maybe this performance issue only reproduces on Windows 10?

Anyway, I'm not sure where to go from here. I think this may require kernel debugging to find out exactly what is on the receiving end of the kernel-level notifications that ReadDirectoryChangesW() is being called.

I hope this info is useful!

[wez]

Thanks for digging in! I'm not super sure what to make of this just now, so I'll let it sink in for a bit. I do wonder whether we need to do something gross like add an actual sleep in that main loop to let the kernel chill out for a bit and reduce contention elsewhere :yuck:

[sunshowers]

cc @benpeart who might have some background

[indygreg]

I can reproduce this on my work Windows desktop. Also running Windows 10 Fall Creators update. Watchman 4.1.0 though.

I'm tempted to try this with an older Windows 10 release. I've been using Watchman with Mercurial for months and I don't recall seeing this horrible performance until recently. But most of my day-to-day development is in Linux. So I may have just not noticed.

[wez]

@indygreg once the binaries show up under https://ci.appveyor.com/project/wez/watchman/build/b1418/job/5uxrilwn2750ska7/artifacts you may want to try the same sort of experiment that we did here; I'd love your input.

The idea is that we're passing in a buffer size that is too big for the kernel to decide to cache when it makes its own kernel side memory allocation, and since the notifications are very busy, we end up not filling that buffer up very much at all with the effect of thrashing the kernel memory allocator layer in an expensive way.

In #549 I added a configuration option to control the size that we use for this buffer. We did a quick run today with it set to 4096 and it seemed to help, but it wasn't done in the most scientific manner.

You can set this value by putting it in the .watchmanconfig file in the repo root:

{"win32_rdcw_buf_size": 4096}

or in the system global config file. That is (hilariously|tragically) set to /etc/watchman.json in our windows build, so the latest iteration of the pull request is setting it to C:/ProgramData/facebook/watchman.json which is not the best location either, but at least slightly more deterministic.

I suspect that we should really do some experiments with differing sizes for this to see if there is a sweet spot.

[indygreg]

Using this custom build with win32_rdcw_buf_size set to 4096 definitely changes things for the better!

Overall wall time for applying a Mercurial stream clone bundle is nearly identical to no watchman.

When I profile things, gone are the ~1ms calls to ReadDirectoryChangesW(). Replacing them (as reported in procmon) are a bunch of NotifyChangeDirectory() calls. Times on these are varied between 20-300us. There are a lot of them. But overall CPU utilization of watchman is low - maybe 1% - and stack sampling doesn't reveal anything alarming.

Since the overall CPU usage of watchman was lowered, I was initially worried that latency is being introduced elsewhere. But I could find no sign of that. So I think your theory about passing a too-large buffer into the kernel which results in the kernel silently rejecting it and allocating a new one is very plausible!

Playing around with different values, 65536 appears to be 20-30s slower than 4096. (This could be within variance, however.) Similar procmon behavior in terms of reported function calls. Ceiling for NotifyChangeDirectory() looks to be a bit higher though - 500-600us. I only spot checked things though. It would be great to see a distribution curve of these timings to confirm my suspicions. That would make sense: bigger buffer takes longer to fill and more time before you get a notification and more time for watchman to process events in a filled buffer.

131072 appears to be similar to 65536 in terms of Mercurial operation time. However, procmon didn't report any activity in watchman.exe during the Mercurial operation. watchman.exe was still consuming ~1% CPU. Stack sampling showed WaitForMultipleObjects() and ReadDirectoryChangesW() being in the stack the most, with the former being ~2x more common. And the stack under ReadDirectoryChangesW() is completely different with this patch applied. No more heap related symbols.

262144 is ~30s slower than 131072. Same procmon behavior as 131072.

16384 seems to have the same wall time behavior as 4096.

[wez]

Thanks for the detailed analysis! It sounds like 16384 would be a good default?

[indygreg]

16384 seems reasonable. Ship it!

[randomascii]

See this blog post for an explanation of exactly what is happening and instructions on how to diagnose it:

https://randomascii.wordpress.com/2018/04/17/making-windows-slower-part-1-file-access/

[wez]

@randomascii yes! I'm a subscriber and thought precisely the same thing when I was reading it yesterday