git@vger.kernel.org list mirror (unofficial, one of many)
 help / color / mirror / code / Atom feed
* [PATCH] run-command: don't spam trace2_child_exit()
@ 2022-04-28 20:58 Josh Steadmon
  2022-04-28 21:46 ` Junio C Hamano
  0 siblings, 1 reply; 6+ messages in thread
From: Josh Steadmon @ 2022-04-28 20:58 UTC (permalink / raw)
  To: git

In rare cases, wait_or_whine() cannot determine a child process's exit
status (and will return -1 in this case). This can cause Git to issue
trace2 child_exit events despite the fact that the child is still
running. In pathological cases, we've seen > 80 million exit events in
our trace logs for a single child process.

Fix this by only issuing trace2 events in finish_command_in_signal() if
we get a value other than -1 from wait_or_whine().

Signed-off-by: Josh Steadmon <steadmon@google.com>
---
 run-command.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/run-command.c b/run-command.c
index a8501e38ce..e0fe2418a2 100644
--- a/run-command.c
+++ b/run-command.c
@@ -983,7 +983,8 @@ int finish_command(struct child_process *cmd)
 int finish_command_in_signal(struct child_process *cmd)
 {
 	int ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);
-	trace2_child_exit(cmd, ret);
+	if (ret != -1)
+		trace2_child_exit(cmd, ret);
 	return ret;
 }
 

base-commit: faa21c10d44184f616d391c158dcbb13b9c72ef3
-- 
2.36.0.464.gb9c8b46e94-goog


^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH] run-command: don't spam trace2_child_exit()
  2022-04-28 20:58 [PATCH] run-command: don't spam trace2_child_exit() Josh Steadmon
@ 2022-04-28 21:46 ` Junio C Hamano
  2022-05-03 14:59   ` Jeff Hostetler
  2022-05-05 19:44   ` Josh Steadmon
  0 siblings, 2 replies; 6+ messages in thread
From: Junio C Hamano @ 2022-04-28 21:46 UTC (permalink / raw)
  To: Josh Steadmon; +Cc: git

Josh Steadmon <steadmon@google.com> writes:

> In rare cases, wait_or_whine() cannot determine a child process's exit
> status (and will return -1 in this case). This can cause Git to issue
> trace2 child_exit events despite the fact that the child is still
> running.

Rather, we do not even know if the child is still running when it
happens, right?  It is curious what "rare cases" makes the symptom
appear.  Do we know?

The patch looks OK from the "we do not know the child exited in this
case, so we shouldn't be reporting the child exit" point of view, of
course.  Having one event that started a child in the log and then
having millions of events that reports the exit of the (same) child
is way too broken.  With this change, we remove these phoney exit
events from the log.

Do we know, for such a child process that caused these millions
phoney exit events, we got a real exit event at the end?  Otherwise,
we'd still have a similar problem in the opposite direction, i.e. a
child has a start event recorded, many exit event discarded but the
log lacks the true exit event for the child, implying that the child
is still running because we failed to log its exit?

>  int finish_command_in_signal(struct child_process *cmd)
>  {
>  	int ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);
> -	trace2_child_exit(cmd, ret);
> +	if (ret != -1)
> +		trace2_child_exit(cmd, ret);
>  	return ret;
>  }

Will queue; thanks.

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH] run-command: don't spam trace2_child_exit()
  2022-04-28 21:46 ` Junio C Hamano
@ 2022-05-03 14:59   ` Jeff Hostetler
  2022-05-05 19:58     ` Josh Steadmon
  2022-05-05 19:44   ` Josh Steadmon
  1 sibling, 1 reply; 6+ messages in thread
From: Jeff Hostetler @ 2022-05-03 14:59 UTC (permalink / raw)
  To: Junio C Hamano, Josh Steadmon; +Cc: git



On 4/28/22 5:46 PM, Junio C Hamano wrote:
> Josh Steadmon <steadmon@google.com> writes:
> 
>> In rare cases, wait_or_whine() cannot determine a child process's exit
>> status (and will return -1 in this case). This can cause Git to issue
>> trace2 child_exit events despite the fact that the child is still
>> running.

I'm curious what is causing the spurious return values.
Could you instrument wait_or_whine() and see which of the
if/else arms are causing the -1 to be returned?

That routine is rather complicated and looks like it has 3
different ways that a -1 could be returned.


> 
> Rather, we do not even know if the child is still running when it
> happens, right?  It is curious what "rare cases" makes the symptom
> appear.  Do we know?
> 
> The patch looks OK from the "we do not know the child exited in this
> case, so we shouldn't be reporting the child exit" point of view, of
> course.  Having one event that started a child in the log and then
> having millions of events that reports the exit of the (same) child
> is way too broken.  With this change, we remove these phoney exit
> events from the log.
> 
> Do we know, for such a child process that caused these millions
> phoney exit events, we got a real exit event at the end?  Otherwise,
> we'd still have a similar problem in the opposite direction, i.e. a
> child has a start event recorded, many exit event discarded but the
> log lacks the true exit event for the child, implying that the child
> is still running because we failed to log its exit?
> 
>>   int finish_command_in_signal(struct child_process *cmd)
>>   {
>>   	int ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);
>> -	trace2_child_exit(cmd, ret);
>> +	if (ret != -1)
>> +		trace2_child_exit(cmd, ret);
>>   	return ret;
>>   }

Since this is only called from pager.c and is used to setup the
pager, I have to wonder if you're only getting these spurious events
for the pager process or for any of the other random child processes.

And whether they are received while the pager is alive and working
properly, or when you're trying to quit the pager or when the pager
is trying to signal eof.

> 
> Will queue; thanks.
> 

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH] run-command: don't spam trace2_child_exit()
  2022-04-28 21:46 ` Junio C Hamano
  2022-05-03 14:59   ` Jeff Hostetler
@ 2022-05-05 19:44   ` Josh Steadmon
  1 sibling, 0 replies; 6+ messages in thread
From: Josh Steadmon @ 2022-05-05 19:44 UTC (permalink / raw)
  To: Junio C Hamano; +Cc: git

On 2022.04.28 14:46, Junio C Hamano wrote:
> Josh Steadmon <steadmon@google.com> writes:
> 
> > In rare cases, wait_or_whine() cannot determine a child process's exit
> > status (and will return -1 in this case). This can cause Git to issue
> > trace2 child_exit events despite the fact that the child is still
> > running.
> 
> Rather, we do not even know if the child is still running when it
> happens, right?

Correct, if you'd like me to clarify the commit message I'll send a V2.


> It is curious what "rare cases" makes the symptom
> appear.  Do we know?

Unfortunately, no. The quoted 80 million exit event instance was not
reproducible.

> The patch looks OK from the "we do not know the child exited in this
> case, so we shouldn't be reporting the child exit" point of view, of
> course.  Having one event that started a child in the log and then
> having millions of events that reports the exit of the (same) child
> is way too broken.  With this change, we remove these phoney exit
> events from the log.
> 
> Do we know, for such a child process that caused these millions
> phoney exit events, we got a real exit event at the end?

We don't know. The trace log filled up the user's disk in this case, so
the log was truncated.


> Otherwise,
> we'd still have a similar problem in the opposite direction, i.e. a
> child has a start event recorded, many exit event discarded but the
> log lacks the true exit event for the child, implying that the child
> is still running because we failed to log its exit?

Yes, that is a weakness with this approach.


> >  int finish_command_in_signal(struct child_process *cmd)
> >  {
> >  	int ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);
> > -	trace2_child_exit(cmd, ret);
> > +	if (ret != -1)
> > +		trace2_child_exit(cmd, ret);
> >  	return ret;
> >  }
> 
> Will queue; thanks.

Thanks, and sorry for the delayed reply, I've been out sick for a few
days.

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH] run-command: don't spam trace2_child_exit()
  2022-05-03 14:59   ` Jeff Hostetler
@ 2022-05-05 19:58     ` Josh Steadmon
  2022-05-10 20:37       ` Jeff Hostetler
  0 siblings, 1 reply; 6+ messages in thread
From: Josh Steadmon @ 2022-05-05 19:58 UTC (permalink / raw)
  To: Jeff Hostetler; +Cc: Junio C Hamano, git

On 2022.05.03 10:59, Jeff Hostetler wrote:
> 
> 
> On 4/28/22 5:46 PM, Junio C Hamano wrote:
> > Josh Steadmon <steadmon@google.com> writes:
> > 
> > > In rare cases, wait_or_whine() cannot determine a child process's exit
> > > status (and will return -1 in this case). This can cause Git to issue
> > > trace2 child_exit events despite the fact that the child is still
> > > running.
> 
> I'm curious what is causing the spurious return values.
> Could you instrument wait_or_whine() and see which of the
> if/else arms are causing the -1 to be returned?
> 
> That routine is rather complicated and looks like it has 3
> different ways that a -1 could be returned.

Unfortunately we haven't been able to reproduce the issue, so
instrumentation won't clarify the cause unless we randomly hit another
instance.


> > 
> > Rather, we do not even know if the child is still running when it
> > happens, right?  It is curious what "rare cases" makes the symptom
> > appear.  Do we know?
> > 
> > The patch looks OK from the "we do not know the child exited in this
> > case, so we shouldn't be reporting the child exit" point of view, of
> > course.  Having one event that started a child in the log and then
> > having millions of events that reports the exit of the (same) child
> > is way too broken.  With this change, we remove these phoney exit
> > events from the log.
> > 
> > Do we know, for such a child process that caused these millions
> > phoney exit events, we got a real exit event at the end?  Otherwise,
> > we'd still have a similar problem in the opposite direction, i.e. a
> > child has a start event recorded, many exit event discarded but the
> > log lacks the true exit event for the child, implying that the child
> > is still running because we failed to log its exit?
> > 
> > >   int finish_command_in_signal(struct child_process *cmd)
> > >   {
> > >   	int ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);
> > > -	trace2_child_exit(cmd, ret);
> > > +	if (ret != -1)
> > > +		trace2_child_exit(cmd, ret);
> > >   	return ret;
> > >   }
> 
> Since this is only called from pager.c and is used to setup the
> pager, I have to wonder if you're only getting these spurious events
> for the pager process or for any of the other random child processes.
> 
> And whether they are received while the pager is alive and working
> properly, or when you're trying to quit the pager or when the pager
> is trying to signal eof.

It was for a pager run by `git diff`. The only other child process in
this instance was `git status`. I believe the events were generated
while the user was not interacting with the process; IIRC the pager was
left running in a terminal overnight and they discovered the next
morning that their disk was filled up by trace logs.

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH] run-command: don't spam trace2_child_exit()
  2022-05-05 19:58     ` Josh Steadmon
@ 2022-05-10 20:37       ` Jeff Hostetler
  0 siblings, 0 replies; 6+ messages in thread
From: Jeff Hostetler @ 2022-05-10 20:37 UTC (permalink / raw)
  To: Josh Steadmon, Junio C Hamano, git



On 5/5/22 3:58 PM, Josh Steadmon wrote:
> On 2022.05.03 10:59, Jeff Hostetler wrote:
>>
>>
>> On 4/28/22 5:46 PM, Junio C Hamano wrote:
>>> Josh Steadmon <steadmon@google.com> writes:
>>>
>>>> In rare cases, wait_or_whine() cannot determine a child process's exit
>>>> status (and will return -1 in this case). This can cause Git to issue
>>>> trace2 child_exit events despite the fact that the child is still
>>>> running.
>>
>> I'm curious what is causing the spurious return values.
>> Could you instrument wait_or_whine() and see which of the
>> if/else arms are causing the -1 to be returned?
>>
>> That routine is rather complicated and looks like it has 3
>> different ways that a -1 could be returned.
> 
> Unfortunately we haven't been able to reproduce the issue, so
> instrumentation won't clarify the cause unless we randomly hit another
> instance.
> 
> 
>>>
>>> Rather, we do not even know if the child is still running when it
>>> happens, right?  It is curious what "rare cases" makes the symptom
>>> appear.  Do we know?
>>>
>>> The patch looks OK from the "we do not know the child exited in this
>>> case, so we shouldn't be reporting the child exit" point of view, of
>>> course.  Having one event that started a child in the log and then
>>> having millions of events that reports the exit of the (same) child
>>> is way too broken.  With this change, we remove these phoney exit
>>> events from the log.
>>>
>>> Do we know, for such a child process that caused these millions
>>> phoney exit events, we got a real exit event at the end?  Otherwise,
>>> we'd still have a similar problem in the opposite direction, i.e. a
>>> child has a start event recorded, many exit event discarded but the
>>> log lacks the true exit event for the child, implying that the child
>>> is still running because we failed to log its exit?
>>>
>>>>    int finish_command_in_signal(struct child_process *cmd)
>>>>    {
>>>>    	int ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);
>>>> -	trace2_child_exit(cmd, ret);
>>>> +	if (ret != -1)
>>>> +		trace2_child_exit(cmd, ret);
>>>>    	return ret;
>>>>    }
>>
>> Since this is only called from pager.c and is used to setup the
>> pager, I have to wonder if you're only getting these spurious events
>> for the pager process or for any of the other random child processes.
>>
>> And whether they are received while the pager is alive and working
>> properly, or when you're trying to quit the pager or when the pager
>> is trying to signal eof.
> 
> It was for a pager run by `git diff`. The only other child process in
> this instance was `git status`. I believe the events were generated
> while the user was not interacting with the process; IIRC the pager was
> left running in a terminal overnight and they discovered the next
> morning that their disk was filled up by trace logs.
> 

This worries me that you've found a race or infinite loop here
and the only symptom is the child exit messages.  Suppressing
them solves the disk-fill problem, but might mean that there's
a lurking infinite loop or something.

Can you (privately) send me the part of the log before the
infinite loop?  And maybe the parent and child processes too?
I'd kinda like to understand what's happening here.

Jeff


^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2022-05-10 20:37 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-04-28 20:58 [PATCH] run-command: don't spam trace2_child_exit() Josh Steadmon
2022-04-28 21:46 ` Junio C Hamano
2022-05-03 14:59   ` Jeff Hostetler
2022-05-05 19:58     ` Josh Steadmon
2022-05-10 20:37       ` Jeff Hostetler
2022-05-05 19:44   ` Josh Steadmon

Code repositories for project(s) associated with this inbox:

	https://80x24.org/mirrors/git.git

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).