Ninja build (on Windows anyway) may be doing redundant work

This afternoon I did a clean build of llvm using ninja and MSVC 2015 on
Windows 10. I saw something curious and wondered if any of the ninja or
CMake experts out there can explain/fix it.

[2663/3121] Linking CXX shared library bin\LTO.dll
   Creating library lib\LTO.dll and object lib\LTO.exp
   Creating library lib\LTO.dll and object lib\LTO.exp
[3120/3121] Running the LLVM regression tests
[[[ etc ]]]

I'm curious about the "creating library" message popping out twice.
Sometimes ninja builds will die on me, complaining about a corrupted
object file, usually related to LTO. Rerunning ninja usually completes
successfully. So I wonder if there's some mishap in the dependencies
somewhere that actually causes the build to try to link the DLL twice,
which of course might corrupt a file if the links are overlapping in
time.

Thought I'd throw this out there in case someone wants to take a look.
--paulr

+Nico Weber

Do you still see this if you use lld-link for linking?

The “corrupt obj file” is something we saw on chrome’s bots every now and then before we switched to lld.

I’m more concerned about seeing the message come out twice, which implies Ninja is executing a rule twice when it doesn’t need to.

–paulr

Since there’s no "[2663/3121] " line between the two messages, the two lines are from the same link.exe invocation. I don’t know why link.exe thinks it needs to print this line twice, ninja doesn’t have anything to do with it.

OK, worth knowing. Thanks.

–paulr

(resend to the list)

And of course, just as I say that, my next ninja build shows the line only once.

On reflection I am less sure that the lack of a [N/M] line means they are from the same invocation. Surely ninja could spawn two links, which then independently report “Creating library” after ninja emits the [N/M] lines.

–paulr

Ninja makes subprocesses write to a pipe and prints their output preceded by the [N/M] line before printing their output the process is done, to not get interleaving output from parallel processes and to make it easy to see which process a given output belongs to. So link.exe definitely prints this line twice.

So when ninja says “[N/M] Building foobar” that means it’s actually all done building foobar. Excellent.

Re. the double message, “blame Microsoft” as I’m not motivated to dig into it any further.

Thanks for the info! It did help.

–paulr

It depends on if ninja is writing to a interactive terminal or no. If it’s writing to an interactive terminal, it prints the “[N/M] building foobar” line when it starts running it, and then it prints it again followed by the subprocesses output when it’s done running it (usually with a different value for N). If it’s writing to a buildbot log, then it only prints the line when it’s done running the command, followed by the command’s output.