Re: Some rough edges of core.fsmonitor

From: Duy Nguyen <pclouds@gmail.com>
Date: Jan 27, 2018, 13:09 UTC
Message-ID: <20180127130954.GA19922@ash>
In-Reply-To: <CACsJy8CJtW3LZ+4Z_06uM4rJO88FXsNvcw+zzVqdFpsQUKrvrg@mail.gmail.com>

On Sat, Jan 27, 2018 at 07:39:27PM +0700, Duy Nguyen wrote:

Show 23 quoted lines

> On Sat, Jan 27, 2018 at 6:43 PM, Ævar Arnfjörð Bjarmason
> <avarab@gmail.com> wrote:
> > a) no fsmonitor
> >
> >     $ time GIT_TRACE_PERFORMANCE=1 ~/g/git/git-status
> >     12:32:44.947651 read-cache.c:1890       performance: 0.053153609 s: read cache .git/index
> >     12:32:44.967943 preload-index.c:112     performance: 0.020161093 s: preload index
> >     12:32:44.974217 read-cache.c:1446       performance: 0.006230611 s: refresh index
> >
> > ...
> >
> > b) with fsmonitor
> >
> >     $ time GIT_TRACE_PERFORMANCE=1 ~/g/git/git-status
> >     12:34:23.833625 read-cache.c:1890       performance: 0.049485685 s: read cache .git/index
> >     12:34:23.838622 preload-index.c:112     performance: 0.001221197 s: preload index
> >     12:34:23.858723 fsmonitor.c:170         performance: 0.020059647 s: fsmonitor process '.git/hooks/fsmonitor-watchman'
> >     12:34:23.871532 read-cache.c:1446       performance: 0.032870818 s: refresh index
> 
> Hmm.. why does refresh take longer with fsmonitor/watchman? With the
> help from watchman, we know what files are modified. We don't need
> manual stat()'ing and this line should be lower than the "no
> fsmonitor" case, which is 0.006230611s.

Ahh.. my patch probably does not see that fsmonitor could be activated lazily inside refresh_index() call. The patch below should fix it.

But between your normal refresh time (0.020 preload + 0.006 actual refresh) and fsmonitor taking 0.020 just to talk to watchman, this repo seems "too small" for fsmonitor/watchman to shine.

I'm still a bit curious that refresh index time, after excluding 0.020 for fsmonitor, is stil 0.012s. What does it do? It should really be doing nothing. Either way, read index time seems to be the elephant in the room now.

-- 8< --

diff --git a/read-cache.c b/read-cache.c
index eac74bc9f1..d60e0a8480 100644
--- a/read-cache.c
+++ b/read-cache.c
@@ -1367,12 +1367,21 @@ int refresh_index(struct index_state *istate, unsigned int flags,
 	unsigned int options = (CE_MATCH_REFRESH |
 				(really ? CE_MATCH_IGNORE_VALID : 0) |
 				(not_new ? CE_MATCH_IGNORE_MISSING : 0));
+	int ignore_fsmonitor = options & CE_MATCH_IGNORE_FSMONITOR;
 	const char *modified_fmt;
 	const char *deleted_fmt;
 	const char *typechange_fmt;
 	const char *added_fmt;
 	const char *unmerged_fmt;
-	uint64_t start = getnanotime();
+	uint64_t start;
+
+	/*
+	 * If fsmonitor is used, force its communication early to
+	 * accurately measure how long this function takes without it.
+	 */
+	if (!ignore_fsmonitor)
+		refresh_fsmonitor(istate);
+	start = getnanotime();
 
 	modified_fmt = (in_porcelain ? "M\t%s\n" : "%s: needs update\n");
 	deleted_fmt = (in_porcelain ? "D\t%s\n" : "%s: needs update\n");
-- 8< --