Hello Ralf,
Very interesting analysis! I have spent a lot of time trying to get the
piping to log files, while keeping out/err separation working with as
little performance impact as possible. I was aware of problem 3, which
causes some annoying output ordering sometimes, but I had not
encountered 1 and 2 before. Checking my latest local Windows build, I do
indeed have some truncated files, not as many as you, but still 79 (less
virus scanning). That would certainly make incremental builds unreliable.
I tried your suggestion for problem 1 and it works for me too. We should
definitely get that fix in. I have filed JDK-8207001. Do you mind if I
use your patch for it?
I agree on the only solution for the 3rd problem, but I would not want
to go there. Delaying output can have lots of weird consequences, if you
for example interrupt a build with ctrl-c.
Another option would be to revert to our previous solution, where we
used this script:
http://hg.openjdk.java.net/jdk8u/jdk8u/file/090b27d25e19/common/bin/logger.sh
The problem with that was performance as it created more extra shell
instances for each compile command.
The only solution to fix problem 2 would be to stop separating out/err.
I wonder how big of a problem that actually is though?
/Erik
On 2018-07-10 05:34, Schmelter, Ralf wrote:
Hi,
while building openjdk on Windows, I've stumbled over a problem which leads to
truncated *.obj.log files, which in turn leads to empty dependency files (which
are generated from the contents of the *.obj.log files on Windows). In the end,
the incremental build will not be reliable.
The reason seems to be this code from the ExecuteWithLog macro in
common/MakeBase.gmk:
( $(strip $2) > >($(TEE) $(strip $1).log) 2> >($(TEE) $(strip $1).log >&2) || \
...
This executes the command given in $2 and tries to write stdout/stderr to the
file given by $1 and to 'normal' stdout/stderr via process substitution. But it
has a few problems.
The first problem occurs when the stdout-tee truncates the file, then it writes
some of the input it got into the file and only after this the stderr-tee has
run far enough to truncate the same file, which leads to the loss of at least a
part of stdout.
Another problem appears when the command writes to stdout and stderr. Since
each tee has its own file position, they would overwrite one another.
The third problem arises because when the command $2 has ended, the bash shell
will not wait for the process substitutions (the two tee commands) to end and
instead will process the next command. Here we try to copy the log file in case
of an error. But the tee commands might not have written the whole input they
have got, so not the whole content of the file might get copied.
In my case it seems to be the first problem which I see most. When doing a
fresh build on my Windows machine (which has quite an aggressive virus scanner
active), I get something like the following:
find . -name "*.obj.log" -size 0 | wc -l
424
find . -name "*.obj.log" -not -size 0 | wc -l
1603
Which means about 20% of the *.obj.log files are truncated.
When I replace the code above with:
( $(strip $2) > >($(TEE) $(strip $1).log) 2>&1 || \
...
I see no more truncated *.obj.log files. The cost is that stderr is redirected to
stdout (since the >&2 of the second tee is missing). The last problem can be
avoided by using something like:
($(RM) -f $(strip $1).log && $(strip $2) > >($(TEE) -a $(strip $1).log) 2> >($(TEE)
-a $(strip $1).log >&2) || \
...
This also leads to no truncated files, but the relative order of stdout/stderr
might be wrong.
If the third problem should be solved too, the only solution I've found was to redierect
via > $(strip $1).log 2>&1 to the file and then later use 'cat' to write the
output to stdout (losing the distinction between stdout and stderr).
Best regards,
Ralf
