[PATCH 0/4] fsmonitor fixes

[PATCH 0/4] fsmonitor fixes

[Alex Vandiver]

A few fixes found from playing around with the fsmonitor branch in
next.
 - Alex

[PATCH 1/4] fsmonitor: Watch, and ask about, the top of the repo, not the CWD

[Alex Vandiver]

Signed-off-by: Alex Vandiver <alexmv@dropbox.com>
---
 t/t7519/fsmonitor-watchman                 | 3 ++-
 templates/hooks--fsmonitor-watchman.sample | 3 ++-
 2 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/t/t7519/fsmonitor-watchman b/t/t7519/fsmonitor-watchman
index a3e30bf54..377edc7be 100755
--- a/t/t7519/fsmonitor-watchman
+++ b/t/t7519/fsmonitor-watchman
@@ -41,7 +41,8 @@ if ($system =~ m/^MSYS_NT/ || $system =~ m/^MINGW/) {
 	$git_work_tree =~ s/[\r\n]+//g;
 	$git_work_tree =~ s,\\,/,g;
 } else {
-	$git_work_tree = $ENV{'PWD'};
+	$git_work_tree = `git rev-parse --show-toplevel`;
+	chomp $git_work_tree;
 }
 
 my $retry = 1;
diff --git a/templates/hooks--fsmonitor-watchman.sample b/templates/hooks--fsmonitor-watchman.sample
index 9eba8a740..7df590d29 100755
--- a/templates/hooks--fsmonitor-watchman.sample
+++ b/templates/hooks--fsmonitor-watchman.sample
@@ -40,7 +40,8 @@ if ($system =~ m/^MSYS_NT/ || $system =~ m/^MINGW/) {
 	$git_work_tree =~ s/[\r\n]+//g;
 	$git_work_tree =~ s,\\,/,g;
 } else {
-	$git_work_tree = $ENV{'PWD'};
+	$git_work_tree = `git rev-parse --show-toplevel`;
+	chomp $git_work_tree;
 }
 
 my $retry = 1;
-- 
2.15.0.rc1.417.g05670bb6e

[PATCH 2/4] fsmonitor: Don't bother pretty-printing JSON from watchman

[Alex Vandiver]

This provides small performance savings.

Signed-off-by: Alex Vandiver <alexmv@dropbox.com>
---
 t/t7519/fsmonitor-watchman                 | 2 +-
 templates/hooks--fsmonitor-watchman.sample | 2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/t/t7519/fsmonitor-watchman b/t/t7519/fsmonitor-watchman
index 377edc7be..eba46c78b 100755
--- a/t/t7519/fsmonitor-watchman
+++ b/t/t7519/fsmonitor-watchman
@@ -51,7 +51,7 @@ launch_watchman();
 
 sub launch_watchman {
 
-	my $pid = open2(\*CHLD_OUT, \*CHLD_IN, 'watchman -j')
+	my $pid = open2(\*CHLD_OUT, \*CHLD_IN, 'watchman -j --no-pretty')
 	    or die "open2() failed: $!\n" .
 	    "Falling back to scanning...\n";
 
diff --git a/templates/hooks--fsmonitor-watchman.sample b/templates/hooks--fsmonitor-watchman.sample
index 7df590d29..60eb7e70b 100755
--- a/templates/hooks--fsmonitor-watchman.sample
+++ b/templates/hooks--fsmonitor-watchman.sample
@@ -50,7 +50,7 @@ launch_watchman();
 
 sub launch_watchman {
 
-	my $pid = open2(\*CHLD_OUT, \*CHLD_IN, 'watchman -j')
+	my $pid = open2(\*CHLD_OUT, \*CHLD_IN, 'watchman -j --no-pretty')
 	    or die "open2() failed: $!\n" .
 	    "Falling back to scanning...\n";
 
-- 
2.15.0.rc1.417.g05670bb6e

Re: [PATCH 2/4] fsmonitor: Don't bother pretty-printing JSON from watchman

[Johannes Schindelin]

Hi Alex,

On Thu, 19 Oct 2017, Alex Vandiver wrote:

> This provides small performance savings.
> 
> diff --git a/t/t7519/fsmonitor-watchman b/t/t7519/fsmonitor-watchman
> index 377edc7be..eba46c78b 100755
> --- a/t/t7519/fsmonitor-watchman
> +++ b/t/t7519/fsmonitor-watchman
> @@ -51,7 +51,7 @@ launch_watchman();
>  
>  sub launch_watchman {
>  
> -	my $pid = open2(\*CHLD_OUT, \*CHLD_IN, 'watchman -j')
> +	my $pid = open2(\*CHLD_OUT, \*CHLD_IN, 'watchman -j --no-pretty')

While I am very much infavor of this change (I was not aware of the
--no-pretty option), I would like to see some statistics on that. Could
you measure the impact, please, and include the results in the commit
message?

Ciao,
Johannes

Re: [PATCH 2/4] fsmonitor: Don't bother pretty-printing JSON from watchman

[Ben Peart]

On 10/20/2017 9:00 AM, Johannes Schindelin wrote:
> Hi Alex,
> 
> On Thu, 19 Oct 2017, Alex Vandiver wrote:
> 
>> This provides small performance savings.
>>
>> diff --git a/t/t7519/fsmonitor-watchman b/t/t7519/fsmonitor-watchman
>> index 377edc7be..eba46c78b 100755
>> --- a/t/t7519/fsmonitor-watchman
>> +++ b/t/t7519/fsmonitor-watchman
>> @@ -51,7 +51,7 @@ launch_watchman();
>>   
>>   sub launch_watchman {
>>   
>> -	my $pid = open2(\*CHLD_OUT, \*CHLD_IN, 'watchman -j')
>> +	my $pid = open2(\*CHLD_OUT, \*CHLD_IN, 'watchman -j --no-pretty')
> 
> While I am very much infavor of this change (I was not aware of the
> --no-pretty option), I would like to see some statistics on that. Could
> you measure the impact, please, and include the results in the commit
> message?
> 
> Ciao,
> Johannes
> 

I was also unaware of the --no-pretty option. I've tested this on 
Windows running version 4.9.0 of Watchman and verified that it does work 
correctly.  I'm also curious if it produces any measurable difference in 
performance.

Re: [PATCH 2/4] fsmonitor: Don't bother pretty-printing JSON from watchman

[Alex Vandiver]

On Fri, 20 Oct 2017, Ben Peart wrote:
> > While I am very much infavor of this change (I was not aware of the
> > --no-pretty option), I would like to see some statistics on that. Could
> > you measure the impact, please, and include the results in the commit
> > message?
> > 
> > Ciao,
> > Johannes
> > 
> 
> I was also unaware of the --no-pretty option. I've tested this on Windows
> running version 4.9.0 of Watchman and verified that it does work correctly.
> I'm also curious if it produces any measurable difference in performance.

On a repository with ~160k files, the following test harness, which
requests all files inside the repository and parses that output:

--------------8<-----------
#!/usr/bin/perl

use strict;
use warnings;
use IPC::Open2;

my $pid = open2(\*CHLD_OUT, \*CHLD_IN, "watchman -j @ARGV")
    or die "open2() failed: $!\n" .
    "Falling back to scanning...\n";

my $query = qq|["query", "$ENV{PWD}", {}]|;

print CHLD_IN $query;
close CHLD_IN;
my $response = do {local $/; <CHLD_OUT>};

my $json_pkg;
eval {
    require JSON::XS;
    $json_pkg = "JSON::XS";
    1;
} or do {
    require JSON::PP;
    $json_pkg = "JSON::PP";
};

my $o = $json_pkg->new->utf8->decode($response);
--------------8<-----------

...run with dumbbench[1], produces:

    $ dumbbench -- ./test.pl
    cmd: Ran 22 iterations (2 outliers).
    cmd: Rounded run time per iteration: 5.240e+00 +/- 1.1e-02 (0.2%)
    $ dumbbench -- ./test.pl --no-pretty
    cmd: Ran 21 iterations (1 outliers).
    cmd: Rounded run time per iteration: 4.866e+00 +/- 1.3e-02 (0.3%)

...so a modest 8% speedup.  I note that those numbers are for a perl
with JSON::XS installed; without it installed, the runtime is so long
that I gave up waiting for it.

Anyways, I'll put that in the commit message in the re-roll.
 - Alex


[1] https://metacpan.org/release/Dumbbench

Re: [PATCH 2/4] fsmonitor: Don't bother pretty-printing JSON from watchman

[Johannes Schindelin]

Hi Alex,

On Wed, 25 Oct 2017, Alex Vandiver wrote:

> [Johannes asked about the speedup when using --no-pretty]
>
> ...so a modest 8% speedup.  I note that those numbers are for a perl
> with JSON::XS installed; without it installed, the runtime is so long
> that I gave up waiting for it.

Very nice! AFAIR Git for Windows does *not* come with JSON::XS.

> Anyways, I'll put that in the commit message in the re-roll.

Thank you,
Johannes

[PATCH 3/4] fsmonitor: Document GIT_TRACE_FSMONITOR

[Alex Vandiver]

Signed-off-by: Alex Vandiver <alexmv@dropbox.com>
---
 Documentation/git.txt | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/Documentation/git.txt b/Documentation/git.txt
index 1fca63634..720db196e 100644
--- a/Documentation/git.txt
+++ b/Documentation/git.txt
@@ -594,6 +594,10 @@ into it.
 Unsetting the variable, or setting it to empty, "0" or
 "false" (case insensitive) disables trace messages.
 
+`GIT_TRACE_FSMONITOR`::
+	Enables trace messages for the filesystem monitor extension.
+	See `GIT_TRACE` for available trace output options.
+
 `GIT_TRACE_PACK_ACCESS`::
 	Enables trace messages for all accesses to any packs. For each
 	access, the pack file name and an offset in the pack is
-- 
2.15.0.rc1.417.g05670bb6e

Re: [PATCH 3/4] fsmonitor: Document GIT_TRACE_FSMONITOR

[Ben Peart]

On 10/19/2017 9:11 PM, Alex Vandiver wrote:
> Signed-off-by: Alex Vandiver <alexmv@dropbox.com>
> ---
>   Documentation/git.txt | 4 ++++
>   1 file changed, 4 insertions(+)
> 
> diff --git a/Documentation/git.txt b/Documentation/git.txt
> index 1fca63634..720db196e 100644
> --- a/Documentation/git.txt
> +++ b/Documentation/git.txt
> @@ -594,6 +594,10 @@ into it.
>   Unsetting the variable, or setting it to empty, "0" or
>   "false" (case insensitive) disables trace messages.
>   
> +`GIT_TRACE_FSMONITOR`::
> +	Enables trace messages for the filesystem monitor extension.
> +	See `GIT_TRACE` for available trace output options.
> +
>   `GIT_TRACE_PACK_ACCESS`::
>   	Enables trace messages for all accesses to any packs. For each
>   	access, the pack file name and an offset in the pack is
> 

Looks like a reasonable addition.  Thank you.

[PATCH 4/4] fsmonitor: Delay updating state until after split index is merged

[Alex Vandiver]

If the fsmonitor extension is used in conjunction with the split index
extension, the set of entries in the index when it is first loaded is
only a subset of the real index.  This leads to only the non-"base"
index being marked as CE_FSMONITOR_VALID.

Delay the expansion of the ewah bitmap until after tweak_split_index
has been called to merge in the base index as well.

Signed-off-by: Alex Vandiver <alexmv@dropbox.com>
---
 cache.h      |  1 +
 fsmonitor.c  | 38 ++++++++++++++++++++++++--------------
 read-cache.c |  4 ++++
 3 files changed, 29 insertions(+), 14 deletions(-)

diff --git a/cache.h b/cache.h
index 25adcf681..0a4f43ec2 100644
--- a/cache.h
+++ b/cache.h
@@ -348,6 +348,7 @@ struct index_state {
 	unsigned char sha1[20];
 	struct untracked_cache *untracked;
 	uint64_t fsmonitor_last_update;
+	struct ewah_bitmap *fsmonitor_dirty;
 };
 
 extern struct index_state the_index;
diff --git a/fsmonitor.c b/fsmonitor.c
index 7c1540c05..4c2668f57 100644
--- a/fsmonitor.c
+++ b/fsmonitor.c
@@ -49,20 +49,7 @@ int read_fsmonitor_extension(struct index_state *istate, const void *data,
 		ewah_free(fsmonitor_dirty);
 		return error("failed to parse ewah bitmap reading fsmonitor index extension");
 	}
-
-	if (git_config_get_fsmonitor()) {
-		/* Mark all entries valid */
-		for (i = 0; i < istate->cache_nr; i++)
-			istate->cache[i]->ce_flags |= CE_FSMONITOR_VALID;
-
-		/* Mark all previously saved entries as dirty */
-		ewah_each_bit(fsmonitor_dirty, fsmonitor_ewah_callback, istate);
-
-		/* Now mark the untracked cache for fsmonitor usage */
-		if (istate->untracked)
-			istate->untracked->use_fsmonitor = 1;
-	}
-	ewah_free(fsmonitor_dirty);
+	istate->fsmonitor_dirty = fsmonitor_dirty;
 
 	trace_printf_key(&trace_fsmonitor, "read fsmonitor extension successful");
 	return 0;
@@ -238,6 +225,29 @@ void remove_fsmonitor(struct index_state *istate)
 
 void tweak_fsmonitor(struct index_state *istate)
 {
+	int i;
+
+	if (istate->fsmonitor_dirty) {
+		/* Mark all entries valid */
+		trace_printf_key(&trace_fsmonitor, "fsmonitor is enabled; cache is %d", istate->cache_nr);
+		for (i = 0; i < istate->cache_nr; i++) {
+			istate->cache[i]->ce_flags |= CE_FSMONITOR_VALID;
+		}
+		trace_printf_key(&trace_fsmonitor, "marked all as valid");
+
+		/* Mark all previously saved entries as dirty */
+		trace_printf_key(&trace_fsmonitor, "setting each bit on %p", istate->fsmonitor_dirty);
+		ewah_each_bit(istate->fsmonitor_dirty, fsmonitor_ewah_callback, istate);
+
+		/* Now mark the untracked cache for fsmonitor usage */
+		trace_printf_key(&trace_fsmonitor, "setting untracked state");
+		if (istate->untracked)
+			istate->untracked->use_fsmonitor = 1;
+		ewah_free(istate->fsmonitor_dirty);
+	} else {
+		trace_printf_key(&trace_fsmonitor, "fsmonitor not enabled");
+	}
+
 	switch (git_config_get_fsmonitor()) {
 	case -1: /* keep: do nothing */
 		break;
diff --git a/read-cache.c b/read-cache.c
index c18e5e623..3b5cd00a2 100644
--- a/read-cache.c
+++ b/read-cache.c
@@ -330,6 +330,10 @@ int ie_match_stat(struct index_state *istate,
 		return 0;
 	if (!ignore_fsmonitor && (ce->ce_flags & CE_FSMONITOR_VALID))
 		return 0;
+	if (ce->ce_flags & CE_FSMONITOR_VALID)
+		trace_printf_key(&trace_fsmonitor, "fsmon marked valid for %s", ce->name);
+	if (ignore_fsmonitor)
+		trace_printf_key(&trace_fsmonitor, "Ignoring fsmonitor for %s", ce->name);
 
 	/*
 	 * Intent-to-add entries have not been added, so the index entry
-- 
2.15.0.rc1.417.g05670bb6e

Re: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged

[Johannes Schindelin]

Hi Alex,

On Thu, 19 Oct 2017, Alex Vandiver wrote:

>  extern struct index_state the_index;
> diff --git a/fsmonitor.c b/fsmonitor.c
> index 7c1540c05..4c2668f57 100644
> --- a/fsmonitor.c
> +++ b/fsmonitor.c
> @@ -49,20 +49,7 @@ int read_fsmonitor_extension(struct index_state *istate, const void *data,
>  		ewah_free(fsmonitor_dirty);
>  		return error("failed to parse ewah bitmap reading fsmonitor index extension");
>  	}
> -
> -	if (git_config_get_fsmonitor()) {
> -		/* Mark all entries valid */
> -		for (i = 0; i < istate->cache_nr; i++)
> -			istate->cache[i]->ce_flags |= CE_FSMONITOR_VALID;
> -
> -		/* Mark all previously saved entries as dirty */
> -		ewah_each_bit(fsmonitor_dirty, fsmonitor_ewah_callback, istate);
> -
> -		/* Now mark the untracked cache for fsmonitor usage */
> -		if (istate->untracked)
> -			istate->untracked->use_fsmonitor = 1;
> -	}
> -	ewah_free(fsmonitor_dirty);
> +	istate->fsmonitor_dirty = fsmonitor_dirty;

From the diff, it is not immediately clear that fsmonitor_dirty is not
leaked in any code path.

Could you clarify this in the commit message, please?

> @@ -238,6 +225,29 @@ void remove_fsmonitor(struct index_state *istate)
>  
>  void tweak_fsmonitor(struct index_state *istate)
>  {
> +	int i;
> +
> +	if (istate->fsmonitor_dirty) {
> +		/* Mark all entries valid */
> +		trace_printf_key(&trace_fsmonitor, "fsmonitor is enabled; cache is %d", istate->cache_nr);

Sadly, a call to trace_printf_key() is not really a noop when tracing is
disabled. The call to trace_printf_key() hands off to trace_vprintf_fl(),
which in turn calls prepare_trace_line() which asks trace_want() whether
we need to trace, which finally calls get_trace_fd(). This last function
initializes a trace key if needed, and this entire call stack takes time.

In this case, where we trace whether fsmonitor is enabled essentially once
during the life cycle of the current Git command invocation, it may be
okay, but later we perform a trace for every single ie_match_stat() call,
which I think should be guarded to avoid unnecessary code churn in
performance critical code paths (O(N) is pretty good until the constant
factor becomes large).

> +		for (i = 0; i < istate->cache_nr; i++) {
> +			istate->cache[i]->ce_flags |= CE_FSMONITOR_VALID;
> +		}
> +		trace_printf_key(&trace_fsmonitor, "marked all as valid");
> +
> +		/* Mark all previously saved entries as dirty */
> +		trace_printf_key(&trace_fsmonitor, "setting each bit on %p", istate->fsmonitor_dirty);
> +		ewah_each_bit(istate->fsmonitor_dirty, fsmonitor_ewah_callback, istate);
> +
> +		/* Now mark the untracked cache for fsmonitor usage */
> +		trace_printf_key(&trace_fsmonitor, "setting untracked state");
> +		if (istate->untracked)
> +			istate->untracked->use_fsmonitor = 1;
> +		ewah_free(istate->fsmonitor_dirty);

At this point, please set istate->fsmonitor_dirty = NULL, as it is not
immediately obvious from this patch (or from the postimage of this diff)
that the array is not used later on.

> +	} else {
> +		trace_printf_key(&trace_fsmonitor, "fsmonitor not enabled");
> +	}
> +
>  	switch (git_config_get_fsmonitor()) {
>  	case -1: /* keep: do nothing */
>  		break;
> diff --git a/read-cache.c b/read-cache.c
> index c18e5e623..3b5cd00a2 100644
> --- a/read-cache.c
> +++ b/read-cache.c
> @@ -330,6 +330,10 @@ int ie_match_stat(struct index_state *istate,
>  		return 0;
>  	if (!ignore_fsmonitor && (ce->ce_flags & CE_FSMONITOR_VALID))
>  		return 0;
> +	if (ce->ce_flags & CE_FSMONITOR_VALID)
> +		trace_printf_key(&trace_fsmonitor, "fsmon marked valid for %s", ce->name);
> +	if (ignore_fsmonitor)
> +		trace_printf_key(&trace_fsmonitor, "Ignoring fsmonitor for %s", ce->name);

This is the code path I am fairly certain should not be penalized if
tracing is disabled.

Ciao,
Johannes

Re: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged

[Ben Peart]

On 10/20/2017 9:16 AM, Johannes Schindelin wrote:
> Hi Alex,
> 
> On Thu, 19 Oct 2017, Alex Vandiver wrote:
> 
>>   extern struct index_state the_index;
>> diff --git a/fsmonitor.c b/fsmonitor.c
>> index 7c1540c05..4c2668f57 100644
>> --- a/fsmonitor.c
>> +++ b/fsmonitor.c
>> @@ -49,20 +49,7 @@ int read_fsmonitor_extension(struct index_state *istate, const void *data,
>>   		ewah_free(fsmonitor_dirty);
>>   		return error("failed to parse ewah bitmap reading fsmonitor index extension");
>>   	}
>> -
>> -	if (git_config_get_fsmonitor()) {
>> -		/* Mark all entries valid */
>> -		for (i = 0; i < istate->cache_nr; i++)
>> -			istate->cache[i]->ce_flags |= CE_FSMONITOR_VALID;
>> -
>> -		/* Mark all previously saved entries as dirty */
>> -		ewah_each_bit(fsmonitor_dirty, fsmonitor_ewah_callback, istate);
>> -
>> -		/* Now mark the untracked cache for fsmonitor usage */
>> -		if (istate->untracked)
>> -			istate->untracked->use_fsmonitor = 1;
>> -	}
>> -	ewah_free(fsmonitor_dirty);
>> +	istate->fsmonitor_dirty = fsmonitor_dirty;
> 
>  From the diff, it is not immediately clear that fsmonitor_dirty is not
> leaked in any code path.
> 
> Could you clarify this in the commit message, please?
> 
>> @@ -238,6 +225,29 @@ void remove_fsmonitor(struct index_state *istate)
>>   
>>   void tweak_fsmonitor(struct index_state *istate)
>>   {
>> +	int i;
>> +

Here we should test git_config_get_fsmonitor() (see the logic where you 
moved this from) as there is no reason to set up the fsmonitor state if 
we're about to remove the extension.  Save the results and use them in 
the case statement below.

>> +	if (istate->fsmonitor_dirty) {
>> +		/* Mark all entries valid */
>> +		trace_printf_key(&trace_fsmonitor, "fsmonitor is enabled; cache is %d", istate->cache_nr);
> 
> Sadly, a call to trace_printf_key() is not really a noop when tracing is
> disabled. The call to trace_printf_key() hands off to trace_vprintf_fl(),
> which in turn calls prepare_trace_line() which asks trace_want() whether
> we need to trace, which finally calls get_trace_fd(). This last function
> initializes a trace key if needed, and this entire call stack takes time.
> 
> In this case, where we trace whether fsmonitor is enabled essentially once
> during the life cycle of the current Git command invocation, it may be
> okay, but later we perform a trace for every single ie_match_stat() call,
> which I think should be guarded to avoid unnecessary code churn in
> performance critical code paths (O(N) is pretty good until the constant
> factor becomes large).
> 
>> +		for (i = 0; i < istate->cache_nr; i++) {
>> +			istate->cache[i]->ce_flags |= CE_FSMONITOR_VALID;
>> +		}
>> +		trace_printf_key(&trace_fsmonitor, "marked all as valid");
>> +
>> +		/* Mark all previously saved entries as dirty */
>> +		trace_printf_key(&trace_fsmonitor, "setting each bit on %p", istate->fsmonitor_dirty);
>> +		ewah_each_bit(istate->fsmonitor_dirty, fsmonitor_ewah_callback, istate);
>> +
>> +		/* Now mark the untracked cache for fsmonitor usage */
>> +		trace_printf_key(&trace_fsmonitor, "setting untracked state");
>> +		if (istate->untracked)
>> +			istate->untracked->use_fsmonitor = 1;
>> +		ewah_free(istate->fsmonitor_dirty);
> 
> At this point, please set istate->fsmonitor_dirty = NULL, as it is not
> immediately obvious from this patch (or from the postimage of this diff)
> that the array is not used later on.
> 
>> +	} else {
>> +		trace_printf_key(&trace_fsmonitor, "fsmonitor not enabled");
>> +	}
>> +

I'd remove the trace statement above as it isn't always accurate. 
fsmonitor could be enabled but just hasn't written/read the extension yet.

>>   	switch (git_config_get_fsmonitor()) {
>>   	case -1: /* keep: do nothing */
>>   		break;
>> diff --git a/read-cache.c b/read-cache.c
>> index c18e5e623..3b5cd00a2 100644
>> --- a/read-cache.c
>> +++ b/read-cache.c
>> @@ -330,6 +330,10 @@ int ie_match_stat(struct index_state *istate,
>>   		return 0;
>>   	if (!ignore_fsmonitor && (ce->ce_flags & CE_FSMONITOR_VALID))
>>   		return 0;
>> +	if (ce->ce_flags & CE_FSMONITOR_VALID)
>> +		trace_printf_key(&trace_fsmonitor, "fsmon marked valid for %s", ce->name);
>> +	if (ignore_fsmonitor)
>> +		trace_printf_key(&trace_fsmonitor, "Ignoring fsmonitor for %s", ce->name);
> 
> This is the code path I am fairly certain should not be penalized if
> tracing is disabled.
> 

Definitely agree with the need to remove this tracing as it will get 
called a lot and we don't want to pay the perf penalty.

> Ciao,
> Johannes
> 

Thank you for detecting the issue with split index and even better, 
sending patches to fix it!

Re: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged

[Junio C Hamano]

Ben Peart <peartben@gmail.com> writes:

>>> +	} else {
>>> +		trace_printf_key(&trace_fsmonitor, "fsmonitor not enabled");
>>> +	}
>>> +
>
> I'd remove the trace statement above as it isn't always
> accurate. fsmonitor could be enabled but just hasn't written/read the
> extension yet.

I agree; when it is not enabled, we shouldn't be paying the penalty,
either.  I wonder if tweak_*() function can return early upfront if
we know fsmonitor is not enabled to make it even more obvious.

>>> +	if (ignore_fsmonitor)
>>> +		trace_printf_key(&trace_fsmonitor, "Ignoring fsmonitor for %s", ce->name);
>>
>> This is the code path I am fairly certain should not be penalized if
>> tracing is disabled.
>
> Definitely agree with the need to remove this tracing as it will get
> called a lot and we don't want to pay the perf penalty.

Yes.

Re: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged

[Jeff King]

On Fri, Oct 20, 2017 at 03:16:20PM +0200, Johannes Schindelin wrote:

> >  void tweak_fsmonitor(struct index_state *istate)
> >  {
> > +	int i;
> > +
> > +	if (istate->fsmonitor_dirty) {
> > +		/* Mark all entries valid */
> > +		trace_printf_key(&trace_fsmonitor, "fsmonitor is enabled; cache is %d", istate->cache_nr);
> 
> Sadly, a call to trace_printf_key() is not really a noop when tracing is
> disabled. The call to trace_printf_key() hands off to trace_vprintf_fl(),
> which in turn calls prepare_trace_line() which asks trace_want() whether
> we need to trace, which finally calls get_trace_fd(). This last function
> initializes a trace key if needed, and this entire call stack takes time.

It seems like we could pretty easily turn noop traces into a trivial
conditional, like:

diff --git a/trace.h b/trace.h
index 179b249c59..c46b92cbde 100644
--- a/trace.h
+++ b/trace.h
@@ -80,8 +80,11 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);
 #define trace_printf(...) \
 	trace_printf_key_fl(TRACE_CONTEXT, __LINE__, NULL, __VA_ARGS__)
 
-#define trace_printf_key(key, ...) \
-	trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__)
+#define trace_printf_key(key, ...) do { \
+	if (!key->initialized || key->fd) \
+		trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__) \
+} while(0)
+
 
 #define trace_argv_printf(argv, ...) \
 	trace_argv_printf_fl(TRACE_CONTEXT, __LINE__, argv, __VA_ARGS__)


(OK, that's got an OR, but if we are really pinching instructions we
could obviously store a single "I've been initialized and am disabled"
flag).

I don't have an opinion one way or the other on these particular
messages, but in general I'd like to see _more_ tracing in Git, not
less. I've often traced Git with a debugger or other tools like perf,
but there's real value in the author of code annotating high-level
logical events.

-Peff

Re: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged

[Johannes Schindelin]

Hi Peff,

On Fri, 20 Oct 2017, Jeff King wrote:

> On Fri, Oct 20, 2017 at 03:16:20PM +0200, Johannes Schindelin wrote:
> 
> > >  void tweak_fsmonitor(struct index_state *istate)
> > >  {
> > > +	int i;
> > > +
> > > +	if (istate->fsmonitor_dirty) {
> > > +		/* Mark all entries valid */
> > > +		trace_printf_key(&trace_fsmonitor, "fsmonitor is enabled; cache is %d", istate->cache_nr);
> > 
> > Sadly, a call to trace_printf_key() is not really a noop when tracing is
> > disabled. The call to trace_printf_key() hands off to trace_vprintf_fl(),
> > which in turn calls prepare_trace_line() which asks trace_want() whether
> > we need to trace, which finally calls get_trace_fd(). This last function
> > initializes a trace key if needed, and this entire call stack takes time.
> 
> It seems like we could pretty easily turn noop traces into a trivial
> conditional, like:
> 
> diff --git a/trace.h b/trace.h
> index 179b249c59..c46b92cbde 100644
> --- a/trace.h
> +++ b/trace.h
> @@ -80,8 +80,11 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);
>  #define trace_printf(...) \
>  	trace_printf_key_fl(TRACE_CONTEXT, __LINE__, NULL, __VA_ARGS__)
>  
> -#define trace_printf_key(key, ...) \
> -	trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__)
> +#define trace_printf_key(key, ...) do { \
> +	if (!key->initialized || key->fd) \
> +		trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__) \
> +} while(0)
> +
>  
>  #define trace_argv_printf(argv, ...) \
>  	trace_argv_printf_fl(TRACE_CONTEXT, __LINE__, argv, __VA_ARGS__)
> 
> 
> (OK, that's got an OR, but if we are really pinching instructions we
> could obviously store a single "I've been initialized and am disabled"
> flag).

I'd really like that.

> I don't have an opinion one way or the other on these particular
> messages, but in general I'd like to see _more_ tracing in Git, not
> less. I've often traced Git with a debugger or other tools like perf,
> but there's real value in the author of code annotating high-level
> logical events.

Yes, I like that idea, too: to add more tracing.

Thanks,
Dscho

Re: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged

[Ben Peart]

On 10/23/2017 5:57 AM, Johannes Schindelin wrote:
> Hi Peff,
> 
> On Fri, 20 Oct 2017, Jeff King wrote:
> 
>> On Fri, Oct 20, 2017 at 03:16:20PM +0200, Johannes Schindelin wrote:
>>
>>>>   void tweak_fsmonitor(struct index_state *istate)
>>>>   {
>>>> +	int i;
>>>> +
>>>> +	if (istate->fsmonitor_dirty) {
>>>> +		/* Mark all entries valid */
>>>> +		trace_printf_key(&trace_fsmonitor, "fsmonitor is enabled; cache is %d", istate->cache_nr);
>>>
>>> Sadly, a call to trace_printf_key() is not really a noop when tracing is
>>> disabled. The call to trace_printf_key() hands off to trace_vprintf_fl(),
>>> which in turn calls prepare_trace_line() which asks trace_want() whether
>>> we need to trace, which finally calls get_trace_fd(). This last function
>>> initializes a trace key if needed, and this entire call stack takes time.
>>
>> It seems like we could pretty easily turn noop traces into a trivial
>> conditional, like:
>>
>> diff --git a/trace.h b/trace.h
>> index 179b249c59..c46b92cbde 100644
>> --- a/trace.h
>> +++ b/trace.h
>> @@ -80,8 +80,11 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);
>>   #define trace_printf(...) \
>>   	trace_printf_key_fl(TRACE_CONTEXT, __LINE__, NULL, __VA_ARGS__)
>>   
>> -#define trace_printf_key(key, ...) \
>> -	trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__)
>> +#define trace_printf_key(key, ...) do { \
>> +	if (!key->initialized || key->fd) \
>> +		trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__) \
>> +} while(0)
>> +
>>   
>>   #define trace_argv_printf(argv, ...) \
>>   	trace_argv_printf_fl(TRACE_CONTEXT, __LINE__, argv, __VA_ARGS__)
>>
>>
>> (OK, that's got an OR, but if we are really pinching instructions we
>> could obviously store a single "I've been initialized and am disabled"
>> flag).
> 
> I'd really like that.
> 
>> I don't have an opinion one way or the other on these particular
>> messages, but in general I'd like to see _more_ tracing in Git, not
>> less. I've often traced Git with a debugger or other tools like perf,
>> but there's real value in the author of code annotating high-level
>> logical events.
> 
> Yes, I like that idea, too: to add more tracing.
> 
> Thanks,
> Dscho
> 

Two big thumbs up.

I find turning on tracking very informative as I can better see the flow 
of execution and sometimes am surprised by what I discover. :)

I've often added additional tracing while working on a feature only to 
remove it before submitting the patch because of the performance 
overhead.  Being able to leave that in would be very helpful.

Re: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged

[Alex Vandiver]

On Fri, 20 Oct 2017, Johannes Schindelin wrote:
> From the diff, it is not immediately clear that fsmonitor_dirty is not
> leaked in any code path.
> 
> Could you clarify this in the commit message, please?

Will do!

> > @@ -238,6 +225,29 @@ void remove_fsmonitor(struct index_state *istate)
> >  
> >  void tweak_fsmonitor(struct index_state *istate)
> >  {
> > +	int i;
> > +
> > +	if (istate->fsmonitor_dirty) {
> > +		/* Mark all entries valid */
> > +		trace_printf_key(&trace_fsmonitor, "fsmonitor is enabled; cache is %d", istate->cache_nr);
> 
> Sadly, a call to trace_printf_key() is not really a noop when tracing is
> disabled. [snip]

Apologies -- I'd meant to remove the tracing before committing.  I
think we're all on the same page that it would be nice to lower the
impact of tracing to let it be more prevalent, but I'd rather not
block these changes on that.

Thanks for the comments!
 - Alex

Re: [PATCH 1/4] fsmonitor: Watch, and ask about, the top of the repo, not the CWD

[Johannes Schindelin]

Hi Alex,

On Thu, 19 Oct 2017, Alex Vandiver wrote:

> Signed-off-by: Alex Vandiver <alexmv@dropbox.com>
> ---
>  t/t7519/fsmonitor-watchman                 | 3 ++-
>  templates/hooks--fsmonitor-watchman.sample | 3 ++-
>  2 files changed, 4 insertions(+), 2 deletions(-)
> 
> diff --git a/t/t7519/fsmonitor-watchman b/t/t7519/fsmonitor-watchman
> index a3e30bf54..377edc7be 100755
> --- a/t/t7519/fsmonitor-watchman
> +++ b/t/t7519/fsmonitor-watchman
> @@ -41,7 +41,8 @@ if ($system =~ m/^MSYS_NT/ || $system =~ m/^MINGW/) {
>  	$git_work_tree =~ s/[\r\n]+//g;
>  	$git_work_tree =~ s,\\,/,g;
>  } else {
> -	$git_work_tree = $ENV{'PWD'};
> +	$git_work_tree = `git rev-parse --show-toplevel`;
> +	chomp $git_work_tree;

This is super expensive, as it means a full-blown new process instead of
just a simple environment variable expansion.

The idea behind using `PWD` instead was that Git will already have done
all of the work of figuring out the top-level directory and switched to
there before calling the fsmonitor hook.

Did you see any case where the script was *not* called from the top-level
directory?

Ciao,
Johannes

Re: [PATCH 1/4] fsmonitor: Watch, and ask about, the top of the repo, not the CWD

[Alex Vandiver]

On Fri, 20 Oct 2017, Johannes Schindelin wrote:
> This is super expensive, as it means a full-blown new process instead of
> just a simple environment variable expansion.
> 
> The idea behind using `PWD` instead was that Git will already have done
> all of the work of figuring out the top-level directory and switched to
> there before calling the fsmonitor hook.

I'm not seeing that PWD has been at all altered.  The following does
seem like a better solution:
------8<-----
diff --git a/fsmonitor.c b/fsmonitor.c
index 7c1540c05..4ea44dcc6 100644
--- a/fsmonitor.c
+++ b/fsmonitor.c
@@ -121,6 +121,7 @@ static int query_fsmonitor(int version, uint64_t last_update, struct strbuf *que
        argv[3] = NULL;
        cp.argv = argv;
        cp.use_shell = 1;
+       cp.dir = get_git_work_tree();

        return capture_command(&cp, query_result, 1024);
 }
------8<-----

I'll re-roll with that.

> Did you see any case where the script was *not* called from the top-level
> directory?

Merely calling `git status` inside a subdirectory is enough to for the
stock watchman config to report that it's in a "new" directory:

    $ watchman watch-list
    {
        "roots": [],
        "version": "4.7.0"
    }
    $ git status
    Adding '/Users/alexmv/src/git' to watchman's watch list.
    On branch test
    nothing to commit, working tree clean
    $ cd builtin/
    $ git status
    Adding '/Users/alexmv/src/git/builtin' to watchman's watch list.
    On branch test
    nothing to commit, working tree clean
    $ watchman watch-list
    {
        "roots": [
            "/Users/alexmv/src/git/builtin",
            "/Users/alexmv/src/git"
        ],
        "version": "4.7.0"
    }

As I understand it, that means that it then loses all performance
gains in the new directory, as it spits out "all dirty."

 - Alex

Re: [PATCH 1/4] fsmonitor: Watch, and ask about, the top of the repo, not the CWD

[Johannes Schindelin]

Hi Alex,

On Wed, 25 Oct 2017, Alex Vandiver wrote:

> On Fri, 20 Oct 2017, Johannes Schindelin wrote:
> > This is super expensive, as it means a full-blown new process instead of
> > just a simple environment variable expansion.
> > 
> > The idea behind using `PWD` instead was that Git will already have done
> > all of the work of figuring out the top-level directory and switched to
> > there before calling the fsmonitor hook.
> 
> I'm not seeing that PWD has been at all altered.

No, PWD is not altered.

But a simple environment variable expansion (fast) was replaced by
spawning to `git rev-parse --show-top-level` (slow, ~60ms on Windows).

*That* is expensive.

Ciao,
Johannes

Re: [PATCH 0/4] fsmonitor fixes

[Johannes Schindelin]

Hi Alex,

On Thu, 19 Oct 2017, Alex Vandiver wrote:

> A few fixes found from playing around with the fsmonitor branch in
> next.

Thank you for having a look, and even better: for sending a couple of
improvements on top of Ben's & my work.

I sent a couple of suggestions and hope you will find the useful?

Ciao,
Johannes