RE: [ANNOUNCE] Git v2.21.0-rc1 (NonStop Results)

> On February 13, 2019 22:33, Junio C Hamano wrote:
>> A release candidate Git v2.21.0-rc1 is now available for testing at the usual
>> places.  It is comprised of 464 non-merge commits since v2.20.0, contributed
>> by 60 people, 14 of which are new faces.
>
> We are currently running through a full regression of v2.21.0-rc1
> on NonStop. It will take about 30 hours, but preliminary results,
> relative to breakages found in rc0 are:
>
> t1308 is fixed.

> On Thu, 14 Feb 2019, Randall S. Becker wrote:
> 
> > t5562 still hangs (blocking) - this breaks our CI pipeline since the
> > test hangs and we have no explanation of whether the hang is in git or
> > the tests.
> 
> I have "good" news: it now also hangs on Ubuntu 16.04 in Azure Pipelines'
> Linux agents.
> 
> There is a silver lining with those good news, though: I found a

> and it might work for you, too:
> 
> 	https://github.com/gitgitgadget/git/pull/126
> 
> (I also submitted this to the Git mailing list, as I really wanted to tag

> On Thu, 14 Feb 2019, Randall S. Becker wrote:
> 
> > t5562 still hangs (blocking) - this breaks our CI pipeline since the
> > test hangs and we have no explanation of whether the hang is in git or
> > the tests.
> 
> I have "good" news: it now also hangs on Ubuntu 16.04 in Azure Pipelines'
> Linux agents.

> To: Johannes Schindelin <Johannes.Schindelin@gmx.de>
> Cc: Randall S. Becker <rsbecker@nexbridge.com>; 'Junio C Hamano'
> <gitster@pobox.com>; git@vger.kernel.org; 'Max Kirillov'
> <max@max630.net>
> Subject: Re: [ANNOUNCE] Git v2.21.0-rc1 (NonStop Results)
> 
> On Thu, Feb 14, 2019 at 10:36:42PM +0100, Johannes Schindelin wrote:
> > On Thu, 14 Feb 2019, Randall S. Becker wrote:
> >
> > > t5562 still hangs (blocking) - this breaks our CI pipeline since the
> > > test hangs and we have no explanation of whether the hang is in git
> > > or the tests.
> >
> > I have "good" news: it now also hangs on Ubuntu 16.04 in Azure Pipelines'
> > Linux agents.
> 
> I haven't yet seen that hang in the wild and couldn't reproduce it on purpose,
> but there is definitely something fishy with t5562 even on Linux and even
> without that perl generate_zero_bytes helper.
> 
>   $ git checkout cc95bc2025^
>   Previous HEAD position was cc95bc2025 t5562: replace /dev/zero with a
> pipe from generate_zero_bytes
>   HEAD is now at 24b451e77c t5318: replace use of /dev/zero with
> generate_zero_bytes
>   $ make
>   <snip>
>   $ cd t
>   # take note of the shell's PID
>   $ echo $$
>   15522
>   $ ./t5562-http-backend-content-length.sh --stress |tee LOG
>   OK    3.0
>   OK    1.0
>   OK    6.0
>   OK    0.0
>   <snap>
> 
> And then in another terminal run this:
> 
>   $ pstree -a -p 15522
> 
> or, to make it easier noticable what changed and what stayed the same:
> 
>   $ watch -d pstree -a -p 15522
> 
> The output will sooner or later will look like this:
> 
>   bash,15522
>     └─t5562-http-back,21082 ./t5562-http-backend-content-length.sh --stress
>         ├─t5562-http-back,21089 ./t5562-http-backend-content-length.sh --
> stress
>         │   └─sh,24906 ./t5562-http-backend-content-length.sh --stress
>         ├─t5562-http-back,21090 ./t5562-http-backend-content-length.sh --
> stress
>         │   └─sh,26660 ./t5562-http-backend-content-length.sh --stress
>         ├─t5562-http-back,21092 ./t5562-http-backend-content-length.sh --
> stress
>         │   └─sh,4202 ./t5562-http-backend-content-length.sh --stress
>         │       └─sh,5696 ./t5562-http-backend-content-length.sh --stress
>         │           └─perl,5697 /home/szeder/src/git/t/t5562/invoke-with-content-
> length.pl push_body.gz.trunc git http-backend
>         │               └─(git,5722)
>         ├─t5562-http-back,21093 ./t5562-http-backend-content-length.sh --
> stress
>         │   └─sh,25572 ./t5562-http-backend-content-length.sh --stress
>   <snip>
> 
> It won't show most of the processes run in the tests, because they are just
> too fast and short-lived.  However, occasionally it does show a stuck git
> process, which is shown as <defunct> in regular 'ps aux'
> output:
> 
>   szeder   5722  0.0  0.0      0     0 pts/16   Z+   13:36   0:00 [git] <defunct>
> 
> Note that this is not a "proper" hang, in the sense that this process is not
> stuck forever, but only for about 1 minute, after which it disappears, and the
> test continues and eventually finishes with success.  I've looked into the logs
> of a couple of such stuck jobs, and it seems that it varies in which test that git
> process happened to get stuck.

> I haven't yet seen that hang in the wild and couldn't reproduce it on
> purpose, but there is definitely something fishy with t5562 even on
> Linux and even without that perl generate_zero_bytes helper.
> 
> It won't show most of the processes run in the tests, because they are
> just too fast and short-lived.  However, occasionally it does show a
> stuck git process, which is shown as <defunct> in regular 'ps aux'
> output:
> 
>   szeder   5722  0.0  0.0      0     0 pts/16   Z+   13:36   0:00 [git] <defunct>
> 
> Note that this is not a "proper" hang, in the sense that this process
> is not stuck forever, but only for about 1 minute

> On Fri, Feb 15, 2019 at 02:02:13PM +0100, SZEDER Gábor wrote:
> > I haven't yet seen that hang in the wild and couldn't reproduce it on
> > purpose, but there is definitely something fishy with t5562 even on
> > Linux and even without that perl generate_zero_bytes helper.
> >
> > It won't show most of the processes run in the tests, because they are
> > just too fast and short-lived.  However, occasionally it does show a
> > stuck git process, which is shown as <defunct> in regular 'ps aux'
> > output:
> >
> >   szeder   5722  0.0  0.0      0     0 pts/16   Z+   13:36   0:00 [git] <defunct>
> >
> > Note that this is not a "proper" hang, in the sense that this process
> > is not stuck forever, but only for about 1 minute
> 
> This is probably because of SIGCHILD comes before "sleep". I believe this is
> unrelated to the hang issue. The hang issue looks like something is wrong
> with cleanu_children(), or maybe in the child which it tries to kill and wait,
> not in tests.
> 
> As for this zombie issue, could be fixed with, for example, more busy wait
> like the following. It may with some bigger probability miss SIGCHILD to the
> first sleep because there is a bit more to do before it. But the penalty is only
> 1 second now, and as it still happens rarely there seems to be no visible
> degradation.
> 
> --- 8< -----------
> diff --git a/t/t5562/invoke-with-content-length.pl b/t/t5562/invoke-with-
> content-length.pl
> index 0943474af2..257e280e3b 100644
> --- a/t/t5562/invoke-with-content-length.pl
> +++ b/t/t5562/invoke-with-content-length.pl
> @@ -29,7 +29,12 @@
>  }
>  print $out $body_data or die "Cannot write data: $!";
> 
> -sleep 60; # is interrupted by SIGCHLD
> +my $counter = 0;
> +while (not $exited and $counter < 60) {
> +        sleep 1;
> +        $counter = $counter + 1;
> +}
> +
>  if (!$exited) {
>          close($out);
>          die "Command did not exit after reading whole body";

> To: SZEDER Gábor <szeder.dev@gmail.com>; git@vger.kernel.org
> Cc: Max Kirillov <max@max630.net>; Johannes Schindelin
> <Johannes.Schindelin@gmx.de>; Randall S. Becker
> <rsbecker@nexbridge.com>; 'Junio C Hamano' <gitster@pobox.com>
> Subject: [PATCH] t5562: chunked sleep to avoid lost SIGCHILD
> 
> If was found during stress-test run that a test may hang by 60 seconds.
> It supposedly happens because SIGCHILD was received before sleep has
> started.
> 
> Fix by looping by smaller chunks, checking $exited after each of them.
> Then lost SIGCHILD would not cause longer delay than 1 second.
> 
> Reported-by: SZEDER Gábor <szeder.dev@gmail.com>
> Signed-off-by: Max Kirillov <max@max630.net>
> ---
> Submitting as proper patch. Note: I believe it does not relate to other issues
> discussed in this thread.
>  t/t5562/invoke-with-content-length.pl | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
> 
> diff --git a/t/t5562/invoke-with-content-length.pl b/t/t5562/invoke-with-
> content-length.pl
> index 0943474af2..257e280e3b 100644
> --- a/t/t5562/invoke-with-content-length.pl
> +++ b/t/t5562/invoke-with-content-length.pl
> @@ -29,7 +29,12 @@
>  }
>  print $out $body_data or die "Cannot write data: $!";
> 
> -sleep 60; # is interrupted by SIGCHLD
> +my $counter = 0;
> +while (not $exited and $counter < 60) {
> +        sleep 1;
> +        $counter = $counter + 1;
> +}
> +
>  if (!$exited) {
>          close($out);
>          die "Command did not exit after reading whole body";

> On February 18, 2019 15:50, Max Kirillov wrote:
> > To: SZEDER Gábor <szeder.dev@gmail.com>; git@vger.kernel.org
> > Cc: Max Kirillov <max@max630.net>; Johannes Schindelin
> > <Johannes.Schindelin@gmx.de>; Randall S. Becker
> > <rsbecker@nexbridge.com>; 'Junio C Hamano' <gitster@pobox.com>
> > Subject: [PATCH] t5562: chunked sleep to avoid lost SIGCHILD
> > 
> > If was found during stress-test run that a test may hang by 60 seconds.
> > It supposedly happens because SIGCHILD was received before sleep has
> > started.
> > 
> > Fix by looping by smaller chunks, checking $exited after each of them.
> > Then lost SIGCHILD would not cause longer delay than 1 second.
> > 
> > Reported-by: SZEDER Gábor <szeder.dev@gmail.com>
> > Signed-off-by: Max Kirillov <max@max630.net>
> > ---
> > Submitting as proper patch. Note: I believe it does not relate to other issues
> > discussed in this thread.
> >  t/t5562/invoke-with-content-length.pl | 7 ++++++-
> >  1 file changed, 6 insertions(+), 1 deletion(-)
> > 
> > diff --git a/t/t5562/invoke-with-content-length.pl b/t/t5562/invoke-with-
> > content-length.pl
> > index 0943474af2..257e280e3b 100644
> > --- a/t/t5562/invoke-with-content-length.pl
> > +++ b/t/t5562/invoke-with-content-length.pl
> > @@ -29,7 +29,12 @@
> >  }
> >  print $out $body_data or die "Cannot write data: $!";
> > 
> > -sleep 60; # is interrupted by SIGCHLD
> > +my $counter = 0;
> > +while (not $exited and $counter < 60) {
> > +        sleep 1;
> > +        $counter = $counter + 1;
> > +}
> > +
> >  if (!$exited) {
> >          close($out);
> >          die "Command did not exit after reading whole body";
> 
> I tried this fix and it made no difference to the hang on
> NonStop. I do not think this fixes the root cause as sleep
> was never an issue and SIGCHLD was not missed in any test
> I conducted. Maybe on another platform it is required.

> If was found during stress-test run that a test may hang by 60 seconds.
> It supposedly happens because SIGCHILD was received before sleep has
> started.
>
> Fix by looping by smaller chunks, checking $exited after each of them.
> Then lost SIGCHILD would not cause longer delay than 1 second.
>
> Reported-by: SZEDER Gábor <szeder.dev@gmail.com>
> Signed-off-by: Max Kirillov <max@max630.net>
> ---
> Submitting as proper patch. Note: I believe it does not relate to other issues
> discussed in this thread.
>  t/t5562/invoke-with-content-length.pl | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
>
> diff --git a/t/t5562/invoke-with-content-length.pl b/t/t5562/invoke-with-content-length.pl
> index 0943474af2..257e280e3b 100644
> --- a/t/t5562/invoke-with-content-length.pl
> +++ b/t/t5562/invoke-with-content-length.pl
> @@ -29,7 +29,12 @@
>  }
>  print $out $body_data or die "Cannot write data: $!";
>  
> -sleep 60; # is interrupted by SIGCHLD

> +my $counter = 0;
> +while (not $exited and $counter < 60) {
> +        sleep 1;
> +        $counter = $counter + 1;
> +}
> +
>  if (!$exited) {
>          close($out);
>          die "Command did not exit after reading whole body";