8146132: Excessive output from make test-image

[coleenp]

This change makes native output files be only printed when building with LOG=info, to make the build not have so many pages of output.
Tested with GHA and locally (tbd)

---

Progress

• Change must be properly reviewed (1 review required, with at least 1 Reviewer)
• Change must not contain extraneous whitespace
• Commit message must refer to an issue

Issue

• JDK-8146132: Excessive output from make test-image

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk pull/11930/head:pull/11930
$ git checkout pull/11930

Update a local copy of the PR:
$ git checkout pull/11930
$ git pull https://git.openjdk.org/jdk pull/11930/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 11930

View PR using the GUI difftool:
$ git pr show -t 11930

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/11930.diff

[bridgekeeper]

👋 Welcome back coleenp! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

[openjdk]

@coleenp The following label will be automatically applied to this pull request:

• build

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

[mlbridge]

Webrevs

• 01: Full - Incremental (e1a221f9)
• 00: Full (59fea279)

[erikj79]

I'm sorry, but I don't think this is the right solution here. I agree that the log level needs to be altered in some way when compiling the tests, as there are so many of them, but this removes logging at the default level for all native targets. I also think it's inconsistent if the "Creating ..." log message is on info while the "Updating ..." of the same thing is still on warn.

I think a better solution would be to give SetupNativeCompilation a parameter or two that controls log level, and that the SetupTestCompilation macro could use that to lower the level for test compilations, while probably also adding a meta log message for all the tests it's building to replace the individual log messages on level warn.

[coleenp]

Hi Erik, I'm so annoyed with this page of messages that I don't want to see every time I run tests for the first time. I kept the Updating message on Warn because that is an interesting message (ie you've touched a .c file and want to see it got compiled).
As far as the second paragraph goes, I have no idea what that means. I don't want to have more special options in my build scripts. I want this "Creating every.o file in our test system" message to not come out by default for me or for anyone.
Can you make this happen? I'd rather not have this private patch in all the repositories I create from now on because seeing pages of these messages is that annoying to me.

[coleenp]

Turning on LOG=info for test-images has reams of information that probably should be LOG=debug. Really nobody needs to see each native object file copied here and there.

[coleenp]

@erikj79 @magicus I added a parameter but not the meta log message for the tests. It seems to work.

[magicus]

Hm. I fully agree on the problem description, but not entirely sure about this solution. In contrast with Erik, I was more thinking along the lines that the decision to be more quiet could be made by SetupNativeCompilation itself, based on the number of files it compiled. So if it only compiled a single c file into a single dll, then it should be quiet.

With "meta message", I think Erik means that if all tests are suddenly being quiet, we should compensate by printing a more general high-level message like
"Building NN native tests".

[coleenp]

The reason I'm picking on the test files and not the message Creating blah because of (1) file is because it has the logic in TestFilesCompilation.gmk compiles each individually.
Adding a message at the end of it like:

+  $$(call LogWarn, Creating $$($1_OUTPUT_DIR)/support/ from $$(words \
+               $$(filter-out %.vardeps, $$($1_FILTERED_FILE_LIST))) file(s))

comes out whether anything compiled or not, which nobody wants.
Unless you can pass status back from this 'foreach' loop. I guess I'm stuck.

[erikj79]

Hm. I fully agree on the problem description, but not entirely sure about this solution. In contrast with Erik, I was more thinking along the lines that the decision to be more quiet could be made by SetupNativeCompilation itself, based on the number of files it compiled. So if it only compiled a single c file into a single dll, then it should be quiet.

With "meta message", I think Erik means that if all tests are suddenly being quiet, we should compensate by printing a more general high-level message like "Building NN native tests".

I think such a rule is too generic and could easily end up not logging a JDK library or launcher. My idea with having SetupTestCompilation control the log level for tests was that it could add a single "meta" log message saying something like "Building NN native tests", which would then replace all of those hidden messages that would otherwise have been printed by SetupNativeCompilation. At least in my mind, that divides the responsibility better with less risk of hiding future useful log messages.

comes out whether anything compiled or not, which nobody wants.
Unless you can pass status back from this 'foreach' loop. I guess I'm stuck.

Yes, getting this right is more tricky. We also want the message to be printed before the compilation starts. To do this, we need to create a rule with a dummy (but real) target that depends on all the source files found by SetupTestCompilation, prints the message and then touches the target file. It's possible we need to some more tweaking to make it work well, not sure.

[coleenp]

I don't know how to do this. My local solution:

make jdk-image test-image | grep -v "Creating "