bugmake - Bugs: bug #22923, option to prevent...

 
 

bug #22923: option to prevent "interspersed" output in parallel builds

Submitter:  Brian Kustel <bkustel>
Submitted:  Wed 16 Apr 2008 03:26:47 AM UTC
   
 
Severity:  3 - Normal Item Group:  Enhancement
Status:  Fixed Privacy:  Public
Assigned to:  psmith Open/Closed:  Closed
Component Version:  3.81 Operating System:  Any
Fixed Release:  4.0 Triage Status:  None
* Mandatory Fields

Add a New Comment Rich Markup
   

Jump to the original submission

Sun 04 May 2014 10:34:44 PM UTC, comment #10: 

I'm not sure how I missed this bug, but this feature was implemented in GNU make 4.0 (read about output synchronization).

Paul D. Smith <psmith>
Group administrator
Tue 19 Jan 2010 12:31:54 AM UTC, comment #9: 

I agree with comment #2 that polling pipes would incur unnecessary overhead and that the generic solution would pair each spawned action against the pre-defined template of a "logger" command.

Looking at the recipient of messages in the existing implementation, it's the file system.  Perhaps, another generic approach could be a file system driver that translates the "open" and "write" operations from separate processes using a pre-defined template of a "logger" command and/or sending the contents directly to an established network log service.

I agree that extra line buffering and line splitting may need to be implemented.

Ilguiz Latypov <ilgiz>
Fri 15 Jan 2010 09:23:44 AM UTC, comment #8: 


Hi

My team do this with GNU make at the moment by using a replacement shell. 

It was proprietary until fairly recently and now it has been released under the EPL.  It is hosted by the Symbian Foundation and you'd need a login but since it's EPLd now there's nothing stopping me from mailing it to someone.

It's called Talon and you use it by setting

SHELL:=talon
TALON_SHELL:=bash

So make executes recipes in the Talon shell and Talon spawns them in Bash. It buffers the full command output and finally tries to grab a system-wide semaphore (not on clusters) before printing the output.

There are some tricks. e.g. if you have multiline recipes then  you need to join them up into one line to prevent the iondividual steps from interleaving e.g.

fred.exe: fred.o bob.o
    link $^ -o $@.sym
    elf2e32 $@.sym -o $@

. . .becomes . . .

fred.exe: fred.o bob.o
    link $^ -o $@.sym && \
    elf2e32 $@.sym -o $@

 


It has some other nice features like:

  • timeouts - don't let a single badly behaved command prevent you from finding all the other issues in your 10 hour build.


  • retries - being able to retry build commands (in case of intermittent compiler license server failures or network problems).


  • easily-parsed logs - It is also able (optionally) to wrap each bit of output in delimiters (XML actually) and print the exit  code of commands.  You basically don't have to have hundreds of programs different error regexps in a table to know what went wrong in the build.  You can also see clearly where commands from one recipe stop and commands for the next recipe begin.


  • performance data - it can print out the time taken by each command and commands can be given a type e.g. "link" so that you can easily find out at the end of the build how much time linking takes as a proportion and you know if it's more critical than other types of task.


We used to do most of this in bash but had problems with implementing timeout and retry.  Bash 4 seems to have those so it might be worth another look.  At the moment Talon is in plain C, works on Windows and Linux and someone got it going on a Mac with a small effort.

In "Example Recipe 1", at the end of this post, I've listed the de-interleaved output for one recipe. All most log parsers need to know is if a recipe failed or not (in the status tag at the bottom) and which component and project to blame for the build failure (in the start tag). The time is also in the tag at the bottom, 




EXAMPLE RECIPE 1

<recipe name='postlink' target='/home/tmurphy/test-epocroot/epoc32/release/armv5/urel/test_pp2.exe' host='rhodes' layer='' component='' bldinf='/home/tmurphy/hg/build/sbsv2/raptor/test/smoke_suite/test_resources/pp/pp2.inf' mmp='/home/tmurphy/hg/build/sbsv2/raptor/test/smoke_suite/test_resources/pp/pp2.mmp' config='arm.v5.urel.gcce4_4_1' platform='armv5' phase='ALL' source=''>
<![CDATA[
+ /home/tmurphy/test-epocroot/epoc32/tools/elf2e32 --sid=0x10003a5c --version=10.0 --capability=TCB+ProtServ+DiskAdmin+AllFiles+PowerMgmt+CommDD '--linkas=test_pp2{000a0000}[00000001].exe' --fpu=softvfp --targettype=EXE --output=/home/tmurphy/test-epocroot/epoc32/release/armv5/urel/test_pp2.exe --elfinput=/home/tmurphy/test-epocroot/epoc32/release/armv5/urel/test_pp2.exe.sym --uid1=0x1000007a --uid2=0x100039ce --uid3=0x00000001 --priority=Low --stack=0x2000 --heap=0x5000,0xffff --debuggable --paged --compressionmethod=inflate --libpath=/home/tmurphy/test-epocroot/epoc32/release/armv5/lib

]]><time start='1262514094.06189' elapsed='0.014' />
<status exit='ok' attempt='1' />
</recipe>



The various data about the target (e.g. which component the target belongs to) is cuistomisable and can be added to the start tag through adding a special prefix onto commands.

fred.exe: fred.o bob.o
    |NAME='linknpostlink';COMPONENT=mycomponent;PROJECT=fred.prj;|link $^ -o $@.sym && \
    elf2e32 $@.sym -o $@

# then we can tell Talon how to use these parameters we sent it:

TALON_RECIPE_ATTRIBUTES:=name='$$NAME' component='$$COMPONENT' project='$$PROJECT'

which gives you somethig roughly like:

<recipe name='linknpostlink' component='mycomponent' project='fred.prj'>
<![CDATA[
+ link fred.o bob.o -o fred.exe.sym
+ elf2e32 fred.exe.sym -o fred.exe

]]><time start='1262514064.04133' elapsed='0.023' />
<status exit='ok' attempt='1' />
</recipe>


I'll put it up somewhere if anyone is actually interested.

Regards,

Tim

Timothy N Murphy <tnmurphy>
Fri 15 Jan 2010 06:14:16 AM UTC, comment #7: 

Reaching back 25 years again, this is basically what Alliant Concentrix parallel make did. It prefixed each output line with the job number |1|, |2| and so on. (This is also why in my original proposal for make -j, I used different numbered job tokens, so that each make invocation could output its own unique number.) Obviously the way that was done was by using a pipe for each spawned jobs' stdout/stderr, so that the invoking make could attach the prefix to any output lines. Of course, in the context of the current make -j server, this would only allow us to handle 255 concurrent jobs. After working on a Connection Machine with 1024 nodes, it became obvious that this wasn't a perfect solution...

As a side note - stdout is always linebuffered by default. It's stderr that may present problems, since by default it is unbuffered.

Just using each jobs' PID as a prefix isn't quite as pleasant, you get a much noisier output since a single job can spawn a lot of processes and thus cycle thru many PIDs in rapid succession.

Howard Chu <hyc>
Fri 15 Jan 2010 05:54:12 AM UTC, comment #6: 

I don't really see the difference between comment #5 and the original description.  I've addressed why this is hard to do in comment #2.

Paul D. Smith <psmith>
Group administrator
Fri 15 Jan 2010 05:20:10 AM UTC, comment #5: 

Another idea mentioned in a Python bug discussion on file handles contention is to have each spawned make process redirect stdout and stderr of its spawned actions to a socket opened by the main make process.  (Perhaps, each make process could do that by opening pipes to poll stdout and stderr from its spawned actions and by sending the received messages over the client socket).  The main make process would be able to read each message separately and save it in stdout or stderr along with the sender's PID.

Ilguiz Latypov <ilgiz>
Tue 27 Oct 2009 02:34:50 PM UTC, comment #4: 

We have implemented output merging with a shell wrapper script. We ask make to use this wrapper script via the SHELL variable.

The script itself is pretty simple, although it may be bash-centric:

----------------------------------------
#!/bin/sh

# Simple shell wrapper for stdout and stderr buffering
# Created 2002, Erik Cumps
#
# Use with parallel makes to prevent confusing output.
# Run make SHELL=makesh ... or edit makefile.
#
# This version merges stdout/stderr.

cleanup() {
        if [ -f /tmp/makesh-$$ ]; then
                cat /tmp/makesh-$$
                rm -f /tmp/makesh-$$
        fi
        if [ "${RC}" = "beach" ]; then
                # interrupted before reaping child status or weird error
                echo "*** makesh: interrupted by signal before reaping child status" 1>&2
                exit 42
        else
                exit ${RC}
        fi
}

# Run command, redirect stdout/stderr to temp file
# Remember command's exit status
RC="beach"
trap cleanup SIGHUP SIGINT SIGQUIT SIGTERM
/bin/bash -c "$@" 1>/tmp/makesh-$$ 2>&1
RC=$?

cleanup
----------------------------------------

Erik Cumps <svslay>
Thu 26 Mar 2009 06:22:14 PM UTC, comment #3: 

Thanks ipjrest and psmith for both replies. They are very appreciated.

Responding to ipjrest's comments:
=================================
I agree some commands are long-running and that if "watching" progress is important, the proposed behavior may not be desireable. This is one reason I suggested the proposed new behavior be optional.

1) Line-buffering: While it would help in some cases, not intermixing lines from different processes is only partially helpful. The fact that a "single line" from process A might be interrupted by a line from process B is my concern here. For example, instead of seeing
  Process A Fragment 1 was emitted and then fragment 2 was emitted.
  Process B Message
one might see
  A: Process A Fragment 1 was emitted
  B: Process B Message
  A: and then fragment 2 was emitted.
if the line for process A is emitted in 2 separate write operations.
2) The VS line prefixing would be OK. In fact I like this idea. But it still has the problem that single lines can be broken if the tool being run sometimes emits lines "in pieces". I have noticed that gcc has this problem in some cases (at least the gcc version I am currently using, 4.1.0).

Responding to psmith's comments:
================================
Thanks for pointing out that make is not multithreaded. I guess I was assuming it was. I agree this complicates matters somewhat. Also, I see your point about my original stdout/stderr "marking" idea. In both cases I assumed make would have either an auxilliary thread or its main thread doing these tasks but I now realize that this is not how make currently works.

But I think something along the lines of your "special variable" idea could be employed in a generic fashion. Perhaps this is what you intended your second paragraph below to imply? Specifically, the proposed option could cause all "commands" to have their output piped to a standard tool which stores (its) stdin to a temp file and then writes it synchronously to stdout after stdin is closed. Also, I think it could be reasonable to allow for an option to either combine stdout/stderr here or to pipe them to separate processes (so that stdout/stderr could be atomically emitted to stdout/stderr respectively).

While I have nothing against the "special variable" idea, I'd very much like to see a way to accomplish this via a make command-line option and the variable idea sounded as if it might require a makefile modification.

Brian Kustel <bkustel>
Sat 06 Sep 2008 03:50:13 AM UTC, comment #2: 

It's not actually quite that simple, although it's do-able.  Make is not a multi-threaded application, and so it cannot read from multiple streams at the same time (such as stdin and stderr, either for a single job or for multiple jobs) without a lot of complexity and potential loss of performance.

The only realistic way this could be done would be, as bkustel mentions, redirecting the output of each job to a temporary file then printing the contents of that file after the job is complete.  It would be necessary to redirect both stdout and stderr for each job to one file and there's no way to "mark" them, since make is not actually processing the output of the jobs.

Similarly, ijprest's idea of having make read lines and print them, prefixed with a job number, cannot really be implemented by make itself for the reasons mentioned in the first paragraph.

However, one idea would be a new special variable that defined a program that job output would be piped to.  If that variable was set, then every time make runs a job it would run this program and arrange for all stdout/stderr from the job to be piped to the command line that was the value of that variable.  It could have various format options that could optionally be provided, to give a job number, the command being invoked, or whatever.  Then people could provide their own script or program that did whatever they liked: stored the output and printed it all at the end, or printed it line-by-line with a job prefix, etc.

Paul D. Smith <psmith>
Group administrator
Fri 05 Sep 2008 08:15:55 PM UTC, comment #1: 

Some commands are long-running.  And while it would be useful for post-build analysis to have the entire output of each command grouped together, it's much less fun to watch.  :)

Perhaps something like MSFT did with parallel builds in Visual Studio?  That is:

1) Line-buffer (i.e., don't intermix output from multiple processes on the same line); and
2) Prefix each line with a number to indicate which process generated the message.  (Visual Studio uses "1>", "2>", etc.)


Ian Prest <ijprest>
Wed 16 Apr 2008 03:26:47 AM UTC, original submission:  

In the Parallel Execution section of the manual, it accurately states:

   "One unpleasant consequence of running several commands
    simultaneously is that output generated by the commands
    appears whenever each command sends it, so messages
    from different commands may be interspersed."

But it should be possible have the output of each parallel command/process batch up its output and only write it to the primary stdout & stderr streams when the process completes in a synchronized fashion. This seems like it should be relatively simple to accomplish. The only downside I can see is that for LONG processes with lots of output, the display would not be in real time and there could potentially be some storage issues with holding onto that data until the process completes. But I imagine one could spool the stdout and stderr off to a temp file marking which blocks are stdout and which are stderr and then this could be replayed back later to reproduce the proper ordering of the stdout/stderr output.

I suspect most users of the Parallel execution feature would prefer to have the output of each individual command be contiguous, though perhaps some would not.

Thus, I propose that an option be added to force the output of each parallel process to be made continguous in the primary stdout & stderr streams.

Brian Kustel <bkustel>

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

Attached Files
file #18953:  makesh-split added by svslay (856B - application/octet-stream - Shell wrapper scripts attached because inline copy lost indentation)
file #18952:  makesh added by svslay (725B - application/octet-stream - Shell wrapper scripts attached because inline copy lost indentation)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by tnmurphy (Posted a comment)
  • -email is unavailable- added by hyc (Posted a comment)
  • -email is unavailable- added by ilgiz (Posted a comment)
  • -email is unavailable- added by svslay (Posted a comment)
  • -email is unavailable- added by psmith (Posted a comment)
  • -email is unavailable- added by ijprest (Posted a comment)
  • -email is unavailable- added by bkustel (Submitted the item)
  •  

    There are 0 votes so far. Votes easily highlight which items people would like to see resolved in priority, independently of the priority of the item set by tracker managers.

    Only logged-in users can vote.

     

    Follow 6 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2014-05-04 psmith StatusNone Fixed
        Assigned toNone psmith
        Open/ClosedOpen Closed
        Fixed ReleaseNone 4.0
    2009-10-27 svslay Attached File- Added makesh, #18952
        Attached File- Added makesh-split, #18953

    Back to the top

    Powered by Savane 3.13-f8d8.
    Corresponding source code