I'm doing make all -d --trace
How do I get Gnu Make to output timestamps for every line it outputs?
More generally, how do I add a timestamp to every STDOUT and STDERR statement?
There is a solution for Linux/Bash but I'm on Windows.
I created a one line batch file add_ts.bat : echo %time% %1
I tried the following but I only got one timestamp (without the lines that were output):
make all --trace -d 2>&1 | add_ts.bat
To a first approximation you need a batch file like:
add_ts.bat
@for /F "usebackq delims==" %%i in (`%1`) do @echo %time% %%i
which you would run like:
add_ts.bat "make all -d --trace" > buildlog.txt
This however isn't good enough if you want to capture and
timestamp STDERR as well as STDOUT from the command passed as
%1, because the backticks operator around %1 will only capture STDOUT
To fix this you'll need to capture STDERR as well as STDOUT within the backticks, by using redirection in there, which in turns means you need to run a subshell to understand the redirection, and you need to escape the redirection operators so they're not interpreted by the toplevel shell. Which all comes to:
@for /F "usebackq delims==" %%i in (`cmd /C %1 2^>^&1`) do @echo %time% %%i
Run just the same way.
Later
what I don't get is why the | itself wasn't enough to send STDOUT and STDERR to STDIN of add_ts.bat
It is. I think you are labouring under the combination of two misconceptions.
One: You believe that a program's commandline arguments are the same as its standard input, or that it gets it commandline arguments from its standard input. It doesn't. A program's commandline arguments, if any, are passed to it as a fixed list of strings in the program-startup protocol. Its standard input is an input stream made available to it at the same time by the OS and connected by default to the console in which the program starts. This default can be overridden in the shell by redirection operators. The contents of that input stream are not fixed in advance. It will feed to the the program whatever is input to the console, or from its redirected proxy, as long as the program is running, as and when the program reads it. The program can parse or ignore its commandline arguments and, quite independently of that, it can read or ignore its standard input.
Your program add_ts.bat is a program that parses the first of its commandline arguments
- it uses %1 - and ignores any more. And it ignores its standard input entirely.
Two: You believe that the effect of a pipeline, e.g.
a | b
is to start an a process and then, for each line that it writes to the standard output, start
a distinct b process which will automatically receive that one line written by a as
a single commandline argument (no matter who many words are in the line) and do its stuff
with that single commandline argument.
That's not what happens. The OS starts one a process and one b process, and connects the
standard output of the one a process to the standard input of the one b process. For the
pipeline to work at all, b has got to be a program that reads its standard input. Your
add_ts.bat is not such a program. It's only a program that parses its first commandline
argument: the | doesn't give it any, and the commandline:
make all --trace -d 2>&1 | add_ts.bat
doesn't give it any either. The commandline:
make all --trace -d 2>&1 | add_ts.bat "Hello World"
would give it one commandline argument and:
make all --trace -d 2>&1 | add_ts.bat Hello World
would give it two, not one, commandline arguments, the second being ignored. But in any case it doesn't read its standard input so piping to it is futile.
The site ss64.com is perfectly good about CMD redirection and piping
but it assumes you know what a program has to do to be a pipeline-able command: To be an upstream command,
it has to write its standard output; to be a downstream command it has to read its standard input.
Using a batch file wrapper is a clever solution if you don't mind the extra overhead. Otherwise I think you'll have to modify GNU make itself to have it print out this data.
If that's not palatable for some reason, you can get that information by using ElectricMake, a GNU-make-compatible implementation of make that includes lots of enhancements, including annotated build logs that have microsecond-resolution timestamps for every job in the build. ElectricMake is part of ElectricAccelerator Huddle.
Here's a bit of the annotation for a trivial "echo Hello World!" job:
<job id="J00007fb820002000" thread="7fb82f7fe700" start="3" end="4" type="rule" name="all" file="
Makefile" line="1">
<command line="2">
<argv>echo Hello, world!</argv>
<output src="prog">Hello, world!
</output>
</command>
<commitTimes start="0.291693" wait="0.296587" commit="0.296628" write="0.296680"/>
<timing invoked="0.291403" completed="0.296544" node="ecdroid3a-59"/>
</job>
Here, the <timing> tag shows the start time (0.291403 seconds) and end time (0.296544 seconds) of the job relative to the start of the build.
These annotated build logs can be viewed and analysed graphically with ElectricInsight, a companion tool for ElectricMake.
ElectricAccelerator Huddle is the freemium version of ElectricAccelerator -- usage is entirely free up to a point, with modest pay-as-you-go fees beyond that
Disclaimer: I'm the architect of ElectricAccelerator.
