A few fixes found from playing around with the fsmonitor branch in next. - Alex
[PATCH 2/4] fsmonitor: Don't bother pretty-printing JSON from watchman
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(-)
Show changes to 2 files +2 −2
t/t7519/fsmonitor-watchman, templates/hooks--fsmonitor-watchman.sample
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
Johannes SchindelinRe: [PATCH 2/4] fsmonitor: Don't bother pretty-printing JSON from watchman
Hi Alex,
On Thu, 19 Oct 2017, Alex Vandiver wrote:
Show 12 quoted lines
> 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
Ben PeartRe: [PATCH 2/4] fsmonitor: Don't bother pretty-printing JSON from watchman
On 10/20/2017 9:00 AM, Johannes Schindelin wrote:
Show 25 quoted lines
> 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
On Fri, 20 Oct 2017, Ben Peart wrote:
Show 12 quoted lines
> > 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
Johannes SchindelinRe: [PATCH 2/4] fsmonitor: Don't bother pretty-printing JSON from watchman
Hi Alex,
On Wed, 25 Oct 2017, Alex Vandiver wrote:
Show 5 quoted lines
> [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
Signed-off-by: Alex Vandiver <alexmv@dropbox.com> --- Documentation/git.txt | 4 ++++ 1 file changed, 4 insertions(+)
Show changes to Documentation/git.txt +4 −0
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
Ben PeartRe: [PATCH 3/4] fsmonitor: Document GIT_TRACE_FSMONITOR
On 10/19/2017 9:11 PM, Alex Vandiver wrote:
Show 21 quoted lines
> 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
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(-)
Show changes to 3 files +29 −14
cache.h, fsmonitor.c, read-cache.c
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
Johannes SchindelinRe: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged
Hi Alex,
On Thu, 19 Oct 2017, Alex Vandiver wrote:
Show 24 quoted lines
> 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?
Show 9 quoted lines
> @@ -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).
Show 14 quoted lines
> + 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.
Show 19 quoted lines
> + } 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
Ben PeartRe: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged
On 10/20/2017 9:16 AM, Johannes Schindelin wrote:
Show 40 quoted lines
> 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.
Show 40 quoted lines
>> + 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.
Show 19 quoted lines
>> 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!
Junio C HamanoRe: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged
Ben Peart <peartben@gmail.com> writes:
Show 8 quoted lines
>>> + } 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.
Show 8 quoted lines
>>> + 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.
Jeff KingRe: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged
On Fri, Oct 20, 2017 at 03:16:20PM +0200, Johannes Schindelin wrote:
Show 13 quoted lines
> > 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:
Show changes to trace.h +5 −3
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
Johannes SchindelinRe: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged
Hi Peff,
On Fri, 20 Oct 2017, Jeff King wrote:
Show 42 quoted lines
> 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.
Show 5 quoted lines
> 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
Ben PeartRe: [PATCH 4/4] fsmonitor: Delay updating state until after split index is merged
On 10/23/2017 5:57 AM, Johannes Schindelin wrote:
Show 60 quoted lines
> 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
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!
Show 12 quoted lines
> > @@ -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
[PATCH 1/4] fsmonitor: Watch, and ask about, the top of the repo, not the CWD
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(-)
Show changes to 2 files +4 −2
t/t7519/fsmonitor-watchman, templates/hooks--fsmonitor-watchman.sample
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
Johannes SchindelinRe: [PATCH 1/4] fsmonitor: Watch, and ask about, the top of the repo, not the CWD
Hi Alex,
On Thu, 19 Oct 2017, Alex Vandiver wrote:
Show 17 quoted lines
> 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
On Fri, 20 Oct 2017, Johannes Schindelin wrote:
Show 6 quoted lines
> 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<-----
Show changes to fsmonitor.c +1 −0
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
Johannes SchindelinRe: [PATCH 1/4] fsmonitor: Watch, and ask about, the top of the repo, not the CWD
Hi Alex,
On Wed, 25 Oct 2017, Alex Vandiver wrote:
Show 9 quoted lines
> 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
Johannes SchindelinRe: [PATCH 0/4] fsmonitor fixes
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