[PATCH 0/2] clarify sideband muxing in GIT_TRACE_PACKET

[PATCH 0/2] clarify sideband muxing in GIT_TRACE_PACKET

[Jeff King]

I happened to be debugging push with GIT_TRACE_PACKET today, and got
confused by the mixture of trace from the sideband demuxer and push
itself (details in patch 2/2). This series fixes it by showing a
distinct prefix for the sideband reads.

There's some trickery with start_async() involved, so I've tested it
both with and without NO_PTHREADS set.

  [1/2]: run-command: provide in_async query function
  [2/2]: pkt-line: show packets in async processes as "sideband"

-Peff

[PATCH 1/2] run-command: provide in_async query function

[Jeff King]

It's not easy for arbitrary code to find out whether it is
running in an async process or not. A top-level function
which is fed to start_async() can know (you just pass down
an argument saying "you are async"). But that function may
call other global functions, and we would not want to have
to pass the information all the way through the call stack.

Nor can we simply set a global variable, as those may be
shared between async threads and the main thread (if the
platform supports pthreads). We need pthread tricks _or_ a
global variable, depending on how start_async is
implemented.

The callers don't have enough information to do this right,
so let's provide a simple query function that does.
Fortunately we can reuse the existing infrastructure to make
the pthread case simple (and even simplify die_async() by
using our new function).

Signed-off-by: Jeff King <peff@peff.net>
---
 run-command.c | 16 +++++++++++++++-
 run-command.h |  1 +
 2 files changed, 16 insertions(+), 1 deletion(-)

diff --git a/run-command.c b/run-command.c
index 3277cf7..c8029f2 100644
--- a/run-command.c
+++ b/run-command.c
@@ -595,7 +595,7 @@ static NORETURN void die_async(const char *err, va_list params)
 {
 	vreportf("fatal: ", err, params);
 
-	if (!pthread_equal(main_thread, pthread_self())) {
+	if (in_async()) {
 		struct async *async = pthread_getspecific(async_key);
 		if (async->proc_in >= 0)
 			close(async->proc_in);
@@ -614,6 +614,13 @@ static int async_die_is_recursing(void)
 	return ret != NULL;
 }
 
+int in_async(void)
+{
+	if (!main_thread_set)
+		return 0; /* no asyncs started yet */
+	return !pthread_equal(main_thread, pthread_self());
+}
+
 #else
 
 static struct {
@@ -653,6 +660,12 @@ int git_atexit(void (*handler)(void))
 }
 #define atexit git_atexit
 
+static int process_is_async;
+int in_async(void)
+{
+	return process_is_async;
+}
+
 #endif
 
 int start_async(struct async *async)
@@ -712,6 +725,7 @@ int start_async(struct async *async)
 		if (need_out)
 			close(fdout[0]);
 		git_atexit_clear();
+		process_is_async = 1;
 		exit(!!async->proc(proc_in, proc_out, async->data));
 	}
 
diff --git a/run-command.h b/run-command.h
index 5b4425a..629fab7 100644
--- a/run-command.h
+++ b/run-command.h
@@ -118,5 +118,6 @@ struct async {
 
 int start_async(struct async *async);
 int finish_async(struct async *async);
+int in_async(void);
 
 #endif
-- 
2.5.1.739.g7891f6b

[PATCH 2/2] pkt-line: show packets in async processes as "sideband"

[Jeff King]

If you run "GIT_TRACE_PACKET=1 git push", you may get
confusing output like (line prefixes omitted for clarity):

   packet:      push< \1000eunpack ok0019ok refs/heads/master0000
   packet:      push< unpack ok
   packet:      push< ok refs/heads/master
   packet:      push< 0000
   packet:      push< 0000

Why do we see the data twice, once apparently wrapped inside
another pkt-line, and once unwrapped? Why do we get two
flush packets?

The answer is that we start an async process to demux the
sideband data. The first entry comes from the sideband
process reading the data, and the second from push itself.
Likewise, the first flush is inside the demuxed packet, and
the second is an actual sideband flush.

We can make this a bit more clear by marking the sideband
demuxer explicitly as "sideband" rather than "push". The
most elegant way to do this would be to simply call
packet_trace_identity() inside the sideband demuxer. But we
can't do that reliably, because it relies on a global
variable, which might be shared if pthreads are in use.

What we really need is thread-local storage for
packet_trace_identity. But the async code does not provide
an interface for that, and it would be messy to add it here
(we'd have to care about pthreads, initializing our
pthread_key_t ahead of time, etc).

So instead, let us just assume that any async process is
handling sideband data. That's always true now, and is
likely to remain so in the future.

The output looks like:

   packet:  sideband< \1000eunpack ok0019ok refs/heads/master0000
   packet:      push< unpack ok
   packet:      push< ok refs/heads/master
   packet:      push< 0000
   packet:  sideband< 0000

Signed-off-by: Jeff King <peff@peff.net>
---
 pkt-line.c | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/pkt-line.c b/pkt-line.c
index 08a1427..62fdb37 100644
--- a/pkt-line.c
+++ b/pkt-line.c
@@ -1,5 +1,6 @@
 #include "cache.h"
 #include "pkt-line.h"
+#include "run-command.h"
 
 char packet_buffer[LARGE_PACKET_MAX];
 static const char *packet_trace_prefix = "git";
@@ -11,6 +12,11 @@ void packet_trace_identity(const char *prog)
 	packet_trace_prefix = xstrdup(prog);
 }
 
+static const char *get_trace_prefix(void)
+{
+	return in_async() ? "sideband" : packet_trace_prefix;
+}
+
 static int packet_trace_pack(const char *buf, unsigned int len, int sideband)
 {
 	if (!sideband) {
@@ -57,7 +63,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)
 	strbuf_init(&out, len+32);
 
 	strbuf_addf(&out, "packet: %12s%c ",
-		    packet_trace_prefix, write ? '>' : '<');
+		    get_trace_prefix(), write ? '>' : '<');
 
 	/* XXX we should really handle printable utf8 */
 	for (i = 0; i < len; i++) {
-- 
2.5.1.739.g7891f6b

Re: [PATCH 1/2] run-command: provide in_async query function

[Jeff King]

On Tue, Sep 01, 2015 at 04:22:43PM -0400, Jeff King wrote:

> diff --git a/run-command.c b/run-command.c
> index 3277cf7..c8029f2 100644
> --- a/run-command.c
> +++ b/run-command.c

This diff is a little funny to read because the interesting context is
far away, and it is not immediately obvious why we are defining the
function twice. This:

> @@ -595,7 +595,7 @@ static NORETURN void die_async(const char *err, va_list params)
>  {
>  	vreportf("fatal: ", err, params);
>  
> -	if (!pthread_equal(main_thread, pthread_self())) {
> +	if (in_async()) {
>  		struct async *async = pthread_getspecific(async_key);
>  		if (async->proc_in >= 0)
>  			close(async->proc_in);
> @@ -614,6 +614,13 @@ static int async_die_is_recursing(void)
>  	return ret != NULL;
>  }
>  
> +int in_async(void)
> +{
> +	if (!main_thread_set)
> +		return 0; /* no asyncs started yet */
> +	return !pthread_equal(main_thread, pthread_self());
> +}
> +
>  #else

is all inside #ifndef NO_PTHREADS, and this:

> @@ -653,6 +660,12 @@ int git_atexit(void (*handler)(void))
>  }
>  #define atexit git_atexit
>  
> +static int process_is_async;
> +int in_async(void)
> +{
> +	return process_is_async;
> +}
> +
>  #endif

is the "#else" case where we fork.

-Peff

Re: [PATCH 1/2] run-command: provide in_async query function

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> It's not easy for arbitrary code to find out whether it is
> running in an async process or not. A top-level function
> which is fed to start_async() can know (you just pass down
> an argument saying "you are async"). But that function may
> call other global functions, and we would not want to have
> to pass the information all the way through the call stack.
>
> Nor can we simply set a global variable, as those may be
> shared between async threads and the main thread (if the
> platform supports pthreads). We need pthread tricks _or_ a
> global variable, depending on how start_async is
> implemented.
>
> The callers don't have enough information to do this right,
> so let's provide a simple query function that does.
> Fortunately we can reuse the existing infrastructure to make
> the pthread case simple (and even simplify die_async() by
> using our new function).
>
> Signed-off-by: Jeff King <peff@peff.net>
> ---

What is not immediately obvious from the above description is why a
code may want to care if it is in_async() in the first place.

If there weren't the die_async() update, the readers might have been
left utterly baffled (or they can somehow see this is related to
2/2) but it is a bit hard to arrange in "git log" as going to child
is harder.

The patch looks good.  Thanks.

>  run-command.c | 16 +++++++++++++++-
>  run-command.h |  1 +
>  2 files changed, 16 insertions(+), 1 deletion(-)
>
> diff --git a/run-command.c b/run-command.c
> index 3277cf7..c8029f2 100644
> --- a/run-command.c
> +++ b/run-command.c
> @@ -595,7 +595,7 @@ static NORETURN void die_async(const char *err, va_list params)
>  {
>  	vreportf("fatal: ", err, params);
>  
> -	if (!pthread_equal(main_thread, pthread_self())) {
> +	if (in_async()) {
>  		struct async *async = pthread_getspecific(async_key);
>  		if (async->proc_in >= 0)
>  			close(async->proc_in);
> @@ -614,6 +614,13 @@ static int async_die_is_recursing(void)
>  	return ret != NULL;
>  }
>  
> +int in_async(void)
> +{
> +	if (!main_thread_set)
> +		return 0; /* no asyncs started yet */
> +	return !pthread_equal(main_thread, pthread_self());
> +}
> +
>  #else
>  
>  static struct {
> @@ -653,6 +660,12 @@ int git_atexit(void (*handler)(void))
>  }
>  #define atexit git_atexit
>  
> +static int process_is_async;
> +int in_async(void)
> +{
> +	return process_is_async;
> +}
> +
>  #endif
>  
>  int start_async(struct async *async)
> @@ -712,6 +725,7 @@ int start_async(struct async *async)
>  		if (need_out)
>  			close(fdout[0]);
>  		git_atexit_clear();
> +		process_is_async = 1;
>  		exit(!!async->proc(proc_in, proc_out, async->data));
>  	}
>  
> diff --git a/run-command.h b/run-command.h
> index 5b4425a..629fab7 100644
> --- a/run-command.h
> +++ b/run-command.h
> @@ -118,5 +118,6 @@ struct async {
>  
>  int start_async(struct async *async);
>  int finish_async(struct async *async);
> +int in_async(void);
>  
>  #endif

Re: [PATCH 2/2] pkt-line: show packets in async processes as "sideband"

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> What we really need is thread-local storage for
> packet_trace_identity. But the async code does not provide
> an interface for that, and it would be messy to add it here
> (we'd have to care about pthreads, initializing our
> pthread_key_t ahead of time, etc).

True.

> So instead, let us just assume that any async process is
> handling sideband data. That's always true now, and is
> likely to remain so in the future.

Hmm, does Stefan's thread-pool thing interact with this decision in
any way?
>
> The output looks like:
>
>    packet:  sideband< \1000eunpack ok0019ok refs/heads/master0000
>    packet:      push< unpack ok
>    packet:      push< ok refs/heads/master
>    packet:      push< 0000
>    packet:  sideband< 0000
>
> Signed-off-by: Jeff King <peff@peff.net>
> ---
>  pkt-line.c | 8 +++++++-
>  1 file changed, 7 insertions(+), 1 deletion(-)
>
> diff --git a/pkt-line.c b/pkt-line.c
> index 08a1427..62fdb37 100644
> --- a/pkt-line.c
> +++ b/pkt-line.c
> @@ -1,5 +1,6 @@
>  #include "cache.h"
>  #include "pkt-line.h"
> +#include "run-command.h"
>  
>  char packet_buffer[LARGE_PACKET_MAX];
>  static const char *packet_trace_prefix = "git";
> @@ -11,6 +12,11 @@ void packet_trace_identity(const char *prog)
>  	packet_trace_prefix = xstrdup(prog);
>  }
>  
> +static const char *get_trace_prefix(void)
> +{
> +	return in_async() ? "sideband" : packet_trace_prefix;
> +}
> +
>  static int packet_trace_pack(const char *buf, unsigned int len, int sideband)
>  {
>  	if (!sideband) {
> @@ -57,7 +63,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)
>  	strbuf_init(&out, len+32);
>  
>  	strbuf_addf(&out, "packet: %12s%c ",
> -		    packet_trace_prefix, write ? '>' : '<');
> +		    get_trace_prefix(), write ? '>' : '<');
>  
>  	/* XXX we should really handle printable utf8 */
>  	for (i = 0; i < len; i++) {

Re: [PATCH 1/2] run-command: provide in_async query function

[Jeff King]

On Tue, Sep 01, 2015 at 03:09:56PM -0700, Junio C Hamano wrote:

> Jeff King <peff@peff.net> writes:
> 
> > It's not easy for arbitrary code to find out whether it is
> > running in an async process or not. A top-level function
> > which is fed to start_async() can know (you just pass down
> > an argument saying "you are async"). But that function may
> > call other global functions, and we would not want to have
> > to pass the information all the way through the call stack.
> >
> > Nor can we simply set a global variable, as those may be
> > shared between async threads and the main thread (if the
> > platform supports pthreads). We need pthread tricks _or_ a
> > global variable, depending on how start_async is
> > implemented.
> >
> > The callers don't have enough information to do this right,
> > so let's provide a simple query function that does.
> > Fortunately we can reuse the existing infrastructure to make
> > the pthread case simple (and even simplify die_async() by
> > using our new function).
> >
> > Signed-off-by: Jeff King <peff@peff.net>
> > ---
> 
> What is not immediately obvious from the above description is why a
> code may want to care if it is in_async() in the first place.
> 
> If there weren't the die_async() update, the readers might have been
> left utterly baffled (or they can somehow see this is related to
> 2/2) but it is a bit hard to arrange in "git log" as going to child
> is harder.
> 
> The patch looks good.  Thanks.

Yeah, I almost mentioned "...in the next patch we'll need this", but I
wasn't sure how to bring that up without going into the complicated
reasoning in that patch. I don't know if it's worth adding "we don't
have any callers yet, but we will add one in a moment".

-Peff

Re: [PATCH 2/2] pkt-line: show packets in async processes as "sideband"

[Jeff King]

On Tue, Sep 01, 2015 at 03:13:25PM -0700, Junio C Hamano wrote:

> > So instead, let us just assume that any async process is
> > handling sideband data. That's always true now, and is
> > likely to remain so in the future.
> 
> Hmm, does Stefan's thread-pool thing interact with this decision in
> any way?

I don't think so. It is true that:

  start_async(...);
  finish_async(...);
  pthread_create(foo);

would incorrectly report in_async() inside the foo function (because we
know that async has been kicked off, and we know that we are in a thread
that is not the main one).

But I don't think it matters in the current code base, because we tend
to use async for I/O tasks like muxing/demuxing, and real threads in
CPU-heavy tasks like pack-objects.

Still, I admit it is a little gross, and may be a problem in the future.

An alternate approach would be to have the async system provide a
thread-local storage abstraction. With pthreads, we'd build on
pthread_setspecific(), and without, it becomes a simple global variable.

That's more work, but a lot less error-prone, and it may come in handy
in the future.

-Peff

Re: [PATCH 2/2] pkt-line: show packets in async processes as "sideband"

[Stefan Beller]

On Tue, Sep 1, 2015 at 3:13 PM, Junio C Hamano <gitster@pobox.com> wrote:
> Jeff King <peff@peff.net> writes:
>
>> What we really need is thread-local storage for
>> packet_trace_identity. But the async code does not provide
>> an interface for that, and it would be messy to add it here
>> (we'd have to care about pthreads, initializing our
>> pthread_key_t ahead of time, etc).
>
> True.
>
>> So instead, let us just assume that any async process is
>> handling sideband data. That's always true now, and is
>> likely to remain so in the future.
>
> Hmm, does Stefan's thread-pool thing interact with this decision in
> any way?

I do not plan to actually fetch from inside the thread pool, but each thread
is just a proxy for starting a new process doing the fetch and getting
the output
in order.

That seems to be the least amount of work to me. Very long term we may want to
do the fetch directly in a thread pool worker, but then we can also
add the thread
local storage interface.

>>
>> The output looks like:
>>
>>    packet:  sideband< \1000eunpack ok0019ok refs/heads/master0000
>>    packet:      push< unpack ok
>>    packet:      push< ok refs/heads/master
>>    packet:      push< 0000
>>    packet:  sideband< 0000
>>
>> Signed-off-by: Jeff King <peff@peff.net>
>> ---
>>  pkt-line.c | 8 +++++++-
>>  1 file changed, 7 insertions(+), 1 deletion(-)
>>
>> diff --git a/pkt-line.c b/pkt-line.c
>> index 08a1427..62fdb37 100644
>> --- a/pkt-line.c
>> +++ b/pkt-line.c
>> @@ -1,5 +1,6 @@
>>  #include "cache.h"
>>  #include "pkt-line.h"
>> +#include "run-command.h"
>>
>>  char packet_buffer[LARGE_PACKET_MAX];
>>  static const char *packet_trace_prefix = "git";
>> @@ -11,6 +12,11 @@ void packet_trace_identity(const char *prog)
>>       packet_trace_prefix = xstrdup(prog);
>>  }
>>
>> +static const char *get_trace_prefix(void)
>> +{
>> +     return in_async() ? "sideband" : packet_trace_prefix;
>> +}
>> +
>>  static int packet_trace_pack(const char *buf, unsigned int len, int sideband)
>>  {
>>       if (!sideband) {
>> @@ -57,7 +63,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)
>>       strbuf_init(&out, len+32);
>>
>>       strbuf_addf(&out, "packet: %12s%c ",
>> -                 packet_trace_prefix, write ? '>' : '<');
>> +                 get_trace_prefix(), write ? '>' : '<');
>>
>>       /* XXX we should really handle printable utf8 */
>>       for (i = 0; i < len; i++) {

Re: [PATCH 2/2] pkt-line: show packets in async processes as "sideband"

[Jeff King]

On Tue, Sep 01, 2015 at 03:23:06PM -0700, Stefan Beller wrote:

> > Hmm, does Stefan's thread-pool thing interact with this decision in
> > any way?
> 
> I do not plan to actually fetch from inside the thread pool, but each thread
> is just a proxy for starting a new process doing the fetch and getting
> the output
> in order.

Ah, right, I think I misunderstood Junio's question. Yes, if we start
calling cmd_fetch() from inside the threads, things may get confusing.

I'll see how painful the thread storage approach would be.

-Peff

Re: [PATCH 2/2] pkt-line: show packets in async processes as "sideband"

[Stefan Beller]

On Tue, Sep 1, 2015 at 3:26 PM, Jeff King <peff@peff.net> wrote:
> On Tue, Sep 01, 2015 at 03:23:06PM -0700, Stefan Beller wrote:
>
>> > Hmm, does Stefan's thread-pool thing interact with this decision in
>> > any way?
>>
>> I do not plan to actually fetch from inside the thread pool, but each thread
>> is just a proxy for starting a new process doing the fetch and getting
>> the output
>> in order.
>
> Ah, right, I think I misunderstood Junio's question. Yes, if we start
> calling cmd_fetch() from inside the threads, things may get confusing.
>
> I'll see how painful the thread storage approach would be.

I think that may be part of the thread pool API eventually.

I don't plan on relying on thread local storage, which is why I did
not add it there,
though I guess it can be added in there quite conveniently.

>
> -Peff

Re: [PATCH 2/2] pkt-line: show packets in async processes as "sideband"

[Jeff King]

On Tue, Sep 01, 2015 at 03:31:41PM -0700, Stefan Beller wrote:

> > Ah, right, I think I misunderstood Junio's question. Yes, if we start
> > calling cmd_fetch() from inside the threads, things may get confusing.
> >
> > I'll see how painful the thread storage approach would be.
> 
> I think that may be part of the thread pool API eventually.
> 
> I don't plan on relying on thread local storage, which is why I did
> not add it there,
> though I guess it can be added in there quite conveniently.

I think the task_queue and the async code are two separate things,
though. The task_queue, when we do not have threads, falls back to doing
things serially in a single process. Changing "thread local" variables
there is OK, but tasks need to be aware that they might affect
subsequent tasks.

Whereas for async code, we fall back to doing things in a forked
sub-process. And there "thread local" really is local to the async
process, no cleanup required.

-Peff