exclude ignore_vcs dirs from ignore_dirs to avoid breaking cookies

[jimpurbrick]

56fcdba introduced a significant performance regression on my system (OS X 10.8.5 (12F45)) causing a since query to take over a minute:

jimp-mbp1:watchman jimp$ time echo '["query", "/Users/jimp/devtools/buck", {"since": "n:buckd", "fields":["name","exists","new"]}]' | watchman --server-encoding=json --no-pretty -j > /dev/null

real 1m0.006s
user 0m0.003s
sys 0m0.002s

The same query using e0762ed on the same machine takes a fraction of a second:

jimp-mbp1:watchman jimp$ time echo '["query", "/Users/jimp/devtools/buck", {"since": "n:buckd", "fields":["name","exists","new"]}]' | watchman --server-encoding=json --no-pretty -j > /dev/null

real 0m0.018s
user 0m0.004s
sys 0m0.003s

The regression seems to occur whether or not I have a .watchmanconfig file in the root of the watched tree.

[wez]

The since query is slow? Did you change any files before running the since query, or is it slow as soon as you start it up? What if you query it a few minutes after it started up?

[jimpurbrick]

With 56fcdba or later the command is slow every time I run it: as soon as I start up and every subsequent time. I haven't tried other queries as this is the only query I need to run, but watchman -v is fast before and after 56fcdba.

[wez]

is there anything churning through and changing files in your buck working copy while you're running the since query?

This is what I see with a non-built buck tree:

$ time echo '["query", "/Users/wez/fb/buck", {"since": "n:w00t", "fields":["name","exists","new"]}]' | ~/fb/watchman-pure/watchman --server-encoding=json --no-pretty -j > /dev/null
echo   0.00s user 0.00s system 34% cpu 0.002 total
~/fb/watchman-pure/watchman --server-encoding=json --no-pretty -j > /dev/null  0.00s user 0.00s system 0% cpu 0.656 total

$ time echo '["query", "/Users/wez/fb/buck", {"since": "n:w00t", "fields":["name","exists","new"]}]' | ~/fb/watchman-pure/watchman --server-encoding=json --no-pretty -j > /dev/null
echo   0.00s user 0.00s system 28% cpu 0.002 total
~/fb/watchman-pure/watchman --server-encoding=json --no-pretty -j > /dev/null  0.00s user 0.00s system 28% cpu 0.019 total

The code that changed should only impact how quickly we can translate fsevents items into change nodes.
The only way that I can think of that this might somehow influence the query speed is if there is a continual stream of changes coming in and if there is lock contention here:

watchman/root.c

Line 1821 in 56fcdba

pthread_mutex_lock(&root->fse_mtx);

I'm thinking of putting in:

if (!head) {
  return;
}

ahead of that lock acquisition to avoid locking when we don't need to, but don't know that this will fundamentally change what you're seeing. Also: this wasn't changed in 56fcdba

[jimpurbrick]

Looks like this does have something to do with .watchmanconfig:

jimp-mbp1:buck jimp$ time echo '["query", "/Users/jimp/devtools/buck", {"since": "n:buckd", "fields":["name","exists","new"]}]' | watchman --server-encoding=json --no-pretty -j > /dev/null

real 0m0.019s
user 0m0.004s
sys 0m0.003s
jimp-mbp1:buck jimp$ mv .watchmanconfig.renamed .watchmanconfig
jimp-mbp1:buck jimp$ watchman shutdown-server
1387569637: tid=2033447296 failed to identify PDU: fill_buffer: No such file or directory
1387569638: tid=2033447296 failed to identify PDU: fill_buffer: Operation timed out
1387569638: tid=2033447296 unable to talk to your watchman!
jimp-mbp1:buck jimp$ time echo '["query", "/Users/jimp/devtools/buck", {"since": "n:buckd", "fields":["name","exists","new"]}]' | watchman --server-encoding=json --no-pretty -j > /dev/null

real 1m1.008s
user 0m0.004s
sys 0m0.003s

(this is with HEAD)

[jimpurbrick]

This is the contents of my .watchmanconfig:
{
"ignore_dirs": [
".git",
".buckd",
"build",
"buck-out",
"src/com/facebook/buck/cli/quickstart",
"test/com/facebook/buck/cli/testdata",
"test/com/facebook/buck/java/testdata",
"test/com/facebook/buck/junit/testdata",
"test/com/facebook/buck/parser/testdata",
"test/com/facebook/buck/shell/testdata",
"third-party/java/dalvik-jelly-bean"
]
}

[wez]

You shouldn't ignore .git as you can break the cookie detection; maybe that's the root of the problem?
I'll dig into this a bit later, but maybe just removing that one line fixes it for you?

[jimpurbrick]

Looks like that was it, thanks!

[wez]

Sounds like watchman should sanity check that you're not ignoring vcs dirs, or specifically, that you're not ignoring the selected cookie dir

[wez]

I think the behavior here should be: if a dir is listed in both ignore_vcs and ignore_dirs, ignore_dirs takes precedence and the dir is removed from the effective value of ignore_vcs for the root.

This will allow someone to explicitly ignore a dir and not break the cookie mechanism.