Re: Watchman support for git

[David Turner <dturner@twopensource.com>]

On Sun, 2014-05-11 at 07:21 +0700, Duy Nguyen wrote:
> On Sun, May 11, 2014 at 1:38 AM, David Turner <dturner@twopensource.com> wrote:
> >> I got "warning: Watchman watch error: Got bad JSON from watchman
> >> get-sockname: '[' or '{' expected near end of file". Any ideas what I
> >> did wrong? I'm using watchman.git and libwatchman.git. check-0.9.11
> >> and jansson-2.4 were installed by system (gentoo).
> >
> > What do you get from watchman get-sockname on the command-line?  Do the
> > watchman tests pass?
> 
> Found the problem. "watchman" binary is not in $PATH but popen() did
> not complain (or it did but your "2>/dev/null" in watchman_connect
> suppressed it). 

I should probably not be using popen, since it doesn't offer good error
reporting.  I'll try to fix that in the next few days.

> BTW you need to update the array size of "expressions"
> in test_watchman_misc().

Thanks, fixed.

> So without watchman I got
> 
>    299.871ms read_index_from:1538 if (verify_hdr(hdr, mmap_size) < 0) go
>    498.205ms cmd_status:1300 refresh_index(&the_index, REFRESH_QUIE
>    796.050ms wt_status_collect:622 wt_status_collect_untracked(s)
> 
> and with watchman ("git status" ran several times to make sure it's cached)
> 
>    301.950ms read_index_from:1538 if (verify_hdr(hdr, mmap_size) < 0) go
>     34.918ms  read_fs_cache:347 if (verify_hdr(hdr, mmap_size) < 0) go
>   1564.096ms  watchman_load_fs_cache:628 update_fs_cache(istate, result);
>    161.930ms cmd_status:1300 refresh_index(&the_index, REFRESH_QUIE
>    251.614ms wt_status_collect:622 wt_status_collect_untracked(s)
> 
> Given the total time of "git status" without watchman is 1.9s,,
> update_fs_cache() nearly matches that number alone. All that is spent
> in the exclude update code in the function, but if you do
> last_excluding_matching() anyway, why cache it?

My numbers are different (for my test repository):

---
    30.031ms read_index:1386 r = read_index_from(istate, get_index_
    71.625ms cmd_status:1302 refresh_index(&the_index, REFRESH_QUIE
   259.712ms wt_status_collect:622 wt_status_collect_untracked(s)
----
    41.110ms read_index:1386 r = read_index_from(istate, get_index_
     9.294ms read_fs_cache:347 if (verify_hdr(hdr, mmap_size) < 0) go
     0.173ms watchman_load_fs_cache:628 update_fs_cache(istate, result)
    41.901ms read_index:1386 r = read_index_from(istate, get_index_
    18.355ms cmd_status:1302 refresh_index(&the_index, REFRESH_QUIE
    50.911ms wt_status_collect:622 wt_status_collect_untracked(s)
---

I think something must be going wrong with update_fs_cache on your
machine.  I have a few hypotheses:

1. Maybe watchman isn't fully started up when you run your tests.
2. Maybe there is a bug.

update_fs_cache should only have to update based on what it has learned
from watchman.  So if no .gitignore has been changed, it should not have
to do very much work.

I could take the fe_excluded check and move it above the
last_exclude_matching check in fs_cache_is_excluded; it causes t7300 to
fail when run under watchman but presumably that's fixable

> I think we're paying lookup cost in refresh_index(). I forced CE_VALID
> bit on as an experiment and refresh_index() went down to 33ms.

Yes, it is possible to use Watchman to set CE_VALID as well, and I
should probably do that.  It's a bit more complicated (at least, I
recall running into problems), but probably doable.

> A bit surprised about wt_status_collect_untracked number. I verified
> that last_excluding_matching() still runs (on the same number of
> entries like in no-watchman case). Replacing fs_cache_open() in
> add_excludes_from_file_to_list() to plain open() does not change the
> number, so we probably won't need that (unless your worktree is filled
> with .gitignore, which I doubt it's a norm). 

My test repo has a couple hundred of them.  Maybe that's unusual?  A
repo with a lot of projects will tend to have lots of gitignore files,
because each project will want to maintain them independently.