[Buildbot] #2901: Finished time of a build step does not match the elapsedTime of the same step.

[Buildbot trac]

#2901: Finished time of a build step does not match the elapsedTime of the same
step.
-------------------+--------------------
Reporter:  juj     |       Owner:
    Type:  defect  |      Status:  new
Priority:  major   |   Milestone:  0.9.0
 Version:  0.8.8   |  Resolution:
Keywords:          |
-------------------+--------------------

Comment (by juj):

 I believe the problem is that buildbot or one of its third-party
 dependencies uses one of the broken python subprocess APIs with PIPEs, see
 here: https://docs.python.org/2/library/subprocess.html and search for
 notes about 'deadlock'. I think the deadlock there means "a very long
 timeout".

 The reason I suspect that is that in the bad buildbot runs, the build step
 stdio output would hang for long time when the execution of the command in
 that step had already finished several hours ago in the slave. The outputs
 would string in large chunks at a time with a very long delay (magnitude
 of hours).

 After authoring a commit
 https://github.com/kripken/emscripten/commit/76b3cb15e8b4fa2fb17148f94d757f7c94fa329f
 that removes a lot of those stderr prints done in the build, the time
 spent in running the step immediately reduced by two hours and the
 reported times now match. See a good build at
 http://clb.demon.fi:8112/builders/win-incoming/builds/393 where step 8
 takes 15 minutes, and is properly reported to have done so.

 For comparison, here is a stdio output that exhibited the bad delays:

 http://clb.demon.fi:8112/builders/win-incoming/builds/388/steps/Tests-
 browser-firefox/logs/stdio

 and here is a good run after that commit that removed the spamming stderr
 prints:

 http://clb.demon.fi:8112/builders/win-incoming/builds/393/steps/Tests-
 browser-firefox/logs/stdio

--
Ticket URL: <http://trac.buildbot.net/ticket/2901#comment:10>
Buildbot <http://buildbot.net/>
Buildbot: build/test automation