Re: [PATCH 0/9] ci: make Git's GitHub workflow output much more helpful

[Johannes Schindelin <Johannes.Schindelin@gmx.de>]

[-- Attachment #1: Type: text/plain, Size: 8957 bytes --]

Hi Phillip,

On Wed, 23 Feb 2022, Phillip Wood wrote:

> On 22/02/2022 13:31, Ævar Arnfjörð Bjarmason wrote:
> > [...]
> > So just to make the point about one of those mentioned in my [1] with
> > some further details (I won't go into the whole thing to avoid repeating
> > myself):
> >
> > I opened both of:
> >
> > https://github.com/git-for-windows/git/runs/4822802185?check_suite_focus=true
> > https://github.com/dscho/git/runs/4840190622?check_suite_focus=true
> >
> > Just now in Firefox 91.5.0esr-1. Both having been opened before, so
> > they're in cache, and I've got a current 40MB/s real downlink speed etc.
> >
> > The former fully loads in around 5100ms, with your series here that's
> > just short of 18000ms.
> >
> > So your CI changes are making the common case of just looking at a CI
> > failure more than **3x as slow as before**.
>
> I don't think that is the most useful comparison between the two. When I
> am investigating a test failure the time that matters to me is the time
> it takes to display the output of the failing test case.

Thank you for expressing this so clearly. I will adopt a variation of this
phrasing in my commit message, if you don't mind?

> With the first link above the initial page load is faster but to get to
> the output of the failing test case I have click on "Run
> ci/print_test_failures.sh" then wait for that to load and then search
> for "not ok" to actually get to the information I'm after.

And that's only because you are familiar with what you have to do.

Any new contributor would be stuck with the information presented on the
initial load, without any indication that more information _is_ available,
just hidden away in the next step's log (which is marked as "succeeding",
therefore misleading the inclined reader into thinking that this cannot
potentially contain any information pertinent to the _failure_ that needs
to be investigated).

> With the second link the initial page load does feel slower but then I'm
> presented with the test failures nicely highlighted in red, all I have
> to do is click on one and I've got the information I'm after.
>
> Overall that is much faster and easier to use.

Thank you for your comment. I really started to doubt myself, getting the
idea that it's just a case of me holding this thing wrong.

For what it's worth, I did make a grave mistake by using that particular
`seen` CI failure with all of those failing p4 tests, which obviously
resulted in an incredibly large amount of logs. Obviously that _must_ be
slow to load. I just did not have the time to fabricate a CI failure.

However, I do agree with you that the large amount of logs would have to
be looked at _anyway_, whether it is shown upon loading the job's logs or
only when expanding the `print-test-failures` step's logs. The amount of
the logs is a constant, after all, I did not change anything there (nor
would I).

So a better example might be my concrete use case yesterday: the CI build
of `seen` failed. Here is the link to the regular output:

	https://github.com/git/git/actions/runs/1890665968

On that page, you see the following:


	Annotations
	8 errors and 1 warning

	ⓧ win test (3)
	  Process completed with exit code 2.

	ⓧ win test (6)
	  Process completed with exit code 2.

	ⓧ win test (2)
	  Process completed with exit code 2.

	ⓧ win+VS test (3)
	  Process completed with exit code 2.

	ⓧ win+VS test (6)
	  Process completed with exit code 2.

	ⓧ win+VS test (2)
	  Process completed with exit code 2.

	ⓧ osx-gcc (macos-latest)
	  Process completed with exit code 2.

	ⓧ osx-clang (macos-latest)
	  Process completed with exit code 2.

	⚠ CI: .github#L1
	  windows-latest workflows now use windows-2022. For more details, see https://github.com/actions/virtual-environments/issues/4856

So I merged my branch into `seen` and pushed it. The corresponding run can
be seen here:

	https://github.com/dscho/git/actions/runs/1892982393

On that page, you see the following:

	Annotations
	50 errors and 1 warning

	ⓧ win test (3)
	  failed: t7527.1 explicit daemon start and stop

	ⓧ win test (3)
	  failed: t7527.2 implicit daemon start

	ⓧ win test (3)
	  failed: t7527.3 implicit daemon stop (delete .git)

	ⓧ win test (3)
	  failed: t7527.4 implicit daemon stop (rename .git)

	ⓧ win test (3)
	  failed: t7527.5 implicit daemon stop (rename GIT~1)

	ⓧ win test (3)
	  failed: t7527.6 implicit daemon stop (rename GIT~2)

	ⓧ win test (3)
	  failed: t7527.8 cannot start multiple daemons

	ⓧ win test (3)
	  failed: t7527.10 update-index implicitly starts daemon

	ⓧ win test (3)
	  failed: t7527.11 status implicitly starts daemon

	ⓧ win test (3)
	  failed: t7527.12 edit some files

	ⓧ win test (2)
	  failed: t0012.81 fsmonitor--daemon can handle -h

	ⓧ win test (2)
	  Process completed with exit code 1.

	ⓧ win test (6)
	  failed: t7519.2 run fsmonitor-daemon in bare repo

	ⓧ win test (6)
	  failed: t7519.3 run fsmonitor-daemon in virtual repo

	ⓧ win test (6)
	  Process completed with exit code 1.

	ⓧ win+VS test (3)
	  failed: t7527.1 explicit daemon start and stop

	ⓧ win+VS test (3)
	  failed: t7527.2 implicit daemon start

	ⓧ win+VS test (3)
	  failed: t7527.3 implicit daemon stop (delete .git)

	ⓧ win+VS test (3)
	  failed: t7527.4 implicit daemon stop (rename .git)

	ⓧ win+VS test (3)
	  failed: t7527.5 implicit daemon stop (rename GIT~1)

	ⓧ win+VS test (3)
	  failed: t7527.6 implicit daemon stop (rename GIT~2)

	ⓧ win+VS test (3)
	  failed: t7527.8 cannot start multiple daemons

	ⓧ win+VS test (3)
	  failed: t7527.10 update-index implicitly starts daemon

	ⓧ win+VS test (3)
	  failed: t7527.11 status implicitly starts daemon

	ⓧ win+VS test (3)
	  failed: t7527.12 edit some files

	ⓧ win+VS test (2)
	  failed: t0012.81 fsmonitor--daemon can handle -h

	ⓧ win+VS test (2)
	  Process completed with exit code 1.

	ⓧ win+VS test (6)
	  failed: t7519.2 run fsmonitor-daemon in bare repo

	ⓧ win+VS test (6)
	  failed: t7519.3 run fsmonitor-daemon in virtual repo

	ⓧ win+VS test (6)
	  Process completed with exit code 1.

	ⓧ osx-clang (macos-latest)
	  failed: t0012.81 fsmonitor--daemon can handle -h

	ⓧ osx-clang (macos-latest)
	  failed: t7519.2 run fsmonitor-daemon in bare repo

	ⓧ osx-clang (macos-latest)
	  failed: t7527.1 explicit daemon start and stop

	ⓧ osx-clang (macos-latest)
	  failed: t7527.2 implicit daemon start

	ⓧ osx-clang (macos-latest)
	  failed: t7527.3 implicit daemon stop (delete .git)

	ⓧ osx-clang (macos-latest)
	  failed: t7527.4 implicit daemon stop (rename .git)

	ⓧ osx-clang (macos-latest)
	  failed: t7527.7 MacOS event spelling (rename .GIT)

	ⓧ osx-clang (macos-latest)
	  failed: t7527.8 cannot start multiple daemons

	ⓧ osx-clang (macos-latest)
	  failed: t7527.10 update-index implicitly starts daemon

	ⓧ osx-clang (macos-latest)
	  failed: t7527.11 status implicitly starts daemon

	ⓧ osx-gcc (macos-latest)
	  failed: t0012.81 fsmonitor--daemon can handle -h

	ⓧ osx-gcc (macos-latest)
	  failed: t7519.2 run fsmonitor-daemon in bare repo

	ⓧ osx-gcc (macos-latest)
	  failed: t7527.1 explicit daemon start and stop

	ⓧ osx-gcc (macos-latest)
	  failed: t7527.2 implicit daemon start

	ⓧ osx-gcc (macos-latest)
	  failed: t7527.3 implicit daemon stop (delete .git)

	ⓧ osx-gcc (macos-latest)
	  failed: t7527.4 implicit daemon stop (rename .git)

	ⓧ osx-gcc (macos-latest)
	  failed: t7527.7 MacOS event spelling (rename .GIT)

	ⓧ osx-gcc (macos-latest)
	  failed: t7527.8 cannot start multiple daemons

	ⓧ osx-gcc (macos-latest)
	  failed: t7527.10 update-index implicitly starts daemon

	ⓧ osx-gcc (macos-latest)
	  failed: t7527.11 status implicitly starts daemon

	⚠ CI: .github#L1
	  windows-latest workflows now use windows-2022. For more details, see https://github.com/actions/virtual-environments/issues/4856

In my mind, this is already an improvement. (Even if this is a _lot_ of
output, and a lot of individual errors, given that all of them are fixed
with a single, small patch to adjust an option usage string, but that's
not the fault of my patch series, but of the suggestion to put the check
for the option usage string linting into the `parse_options()` machinery
instead of into the static analysis job.)

Since there are still plenty of failures, the page admittedly does load
relatively slowly. But that's not the time I was trying to optimize for.
My time comes at quite a premium these days, so if the computer has to
work a little harder while I can do something else, as long as it saves
_me_ time, I'll take that time. Every time.

Ciao,
Dscho