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(_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 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(_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

[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(_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

[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(_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

[Junio C Hamano]

Ben Peart  writes:

>>> +   } else {
>>> +   trace_printf_key(_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(_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

[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(_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(_fsmonitor, "marked all as valid");
+
+   /* Mark all previously saved entries as dirty */
+   trace_printf_key(_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(_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(_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(_fsmonitor, "fsmon marked valid for %s", 
ce->name);
+   if (ignore_fsmonitor)
+   trace_printf_key(_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

[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(_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(_fsmonitor, "marked all as valid");
> +
> + /* Mark all previously saved entries as dirty */
> + trace_printf_key(_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(_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(_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(_fsmonitor, "fsmon marked valid for %s", 
> ce->name);
> + if (ignore_fsmonitor)
> + trace_printf_key(_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

[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 
---
 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(_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(_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(_fsmonitor, "marked all as valid");
+
+   /* Mark all previously saved entries as dirty */
+   trace_printf_key(_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(_fsmonitor, "setting untracked state");
+   if (istate->untracked)
+   istate->untracked->use_fsmonitor = 1;
+   ewah_free(istate->fsmonitor_dirty);
+   } else {
+   trace_printf_key(_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(_fsmonitor, "fsmon marked valid for %s", 
ce->name);
+   if (ignore_fsmonitor)
+   trace_printf_key(_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