problem report of features/output-sync fails

[Kazushi (Jam) Marukawa]

Hi,

I'd like to explain about a problem in features/output-sync test program.
There were several reports about this problem in the past of this mailing
list, but the source of problem is not recognized yet.  This time, I'd
like to drill it down to make it clear.

The problem is:

  $ make check
  ...
  features/output-sync .................................... 
  Test timed out after 30 seconds
  Error running .../make-4.2/tests/../make (expected 0; got 14): 
.../tests/../make -f work/features/output-sync.mk -j -Orecurse

  Caught signal 14!
  FAILED (14/15 passed)

This problem happens rarely on real machine but very often on VM in my
experience.  And this happens only if I run this test through
run_make_test script.  If I type `../make -f ...` by hand, it works.

I'll explain details.  The sturcutre of output-sync.mk is:

  output-sync.mk:
    foo/Makefile:
      all: foo
      foo: foo-base; date > ../mksync.foo
      foo-base:      wait for mksync.bar
    bar/Makefile:
      all: bar baz
      bar: bar-base; date > ../mksync.bar
      bar-base:      output messages
      baz: baz-base
      baz-base:      wait for mksync.foo

So correct steps of execution are something like below.

  1: run each base

    make -C foo:
      foo-base:      wait for mksync.bar

    make -C bar:
      bar-base:      output messages
      baz-base:      wait for mksync.foo

  2: run bar after bar-base

    make -C foo:
      foo-base:      wait for mksync.bar

    make -C bar:
      bar:           date > ../mksync.bar
      baz-base:      wait for mksync.foo

However, this bar job doesn't start sometime and it cause the problem
described at the top.

  bad: wait forever

    make -C foo:
      foo-base:      wait for mksync.bar

    make -C bar:
      bar:           won't start
      baz-base:      wait for mksync.foo

When I check the detail of job assignentment, there are differences.

  good case:
    make -C bar:
      Putting child 0x20f3c50 (bar-base) PID 7495 on the chain.
      Live child 0x20f3c50 (bar-base) PID 7495
      Need a job token; we have children
      Live child 0x20f3c50 (bar-base) PID 7495
      Obtained token for child 0x20f4110 (baz-base).
      Putting child 0x20f4110 (baz-base) PID 7496 on the chain.
      Live child 0x20f4110 (baz-base) PID 7496
      Live child 0x20f3c50 (bar-base) PID 7495
      Reaping winning child 0x20f3c50 PID 7495
      Live child 0x20f4110 (baz-base) PID 7496
      Live child 0x20f3c50 (bar-base) PID 7497
      Reaping winning child 0x20f4110 PID 7496
      Live child 0x20f4110 (baz-base) PID 7498
      Live child 0x20f3c50 (bar-base) PID 7497
      Reaping winning child 0x20f3c50 PID 7497
      bar: start
      bar: end
      Removing child 0x20f3c50 PID 7497 from chain.
      Released token for child 0x20f3c50 (bar-base).
      Live child 0x20f4110 (baz-base) PID 7498
      Live child 0x20f4110 (baz-base) PID 7498
      Need a job token; we have children             <-- we have children to 
assign bar
      Live child 0x20f4110 (baz-base) PID 7498
      Obtained token for child 0x20f3db0 (bar).
      Putting child 0x20f3db0 (bar) PID 7499 on the chain.
      Live child 0x20f3db0 (bar) PID 7499
      Live child 0x20f4110 (baz-base) PID 7498
      Reaping winning child 0x20f3db0 PID 7499
      date > ../mksync.bar
      Removing child 0x20f3db0 PID 7499 from chain.
      Released token for child 0x20f3db0 (bar).
      Live child 0x20f4110 (baz-base) PID 7498

  bad case:
    make -C bar:
      Putting child 0x1609c50 (bar-base) PID 9747 on the chain.
      Live child 0x1609c50 (bar-base) PID 9747
      Reaping winning child 0x1609c50 PID 9747
      Live child 0x1609c50 (bar-base) PID 9749
      Reaping winning child 0x1609c50 PID 9749
      bar: start
      bar: end
      Removing child 0x1609c50 PID 9749 from chain.
      Need a job token; we don't have children       <-- we don't have children 
and bar is never assigned
      Putting child 0x1609c50 (baz-base) PID 9750 on the chain.
      Live child 0x1609c50 (baz-base) PID 9750
      Reaping winning child 0x1609c50 PID 9750
      Live child 0x1609c50 (baz-base) PID 9751

I'm not sure why these differences happen.  Does someone know it?
If any futhur information is needed, please let me know.  Thanks.

Best regards,
-- Kazushi