1641940 - Clock on a build log is not sync with the task

Status: NEW

(Toolkit :: Crash Reporting, defect)

Description

[Calixte Denizet (:calixte)]

Attachment: image.png

In the log here:
https://firefoxci.taskcluster-artifacts.net/dVoX4Y2gTrOQPckI16U60g/0/public/logs/live_backing.log

search for string Beginning work for file: /builds/worker/workspace/obj-build/toolkit/library/build/libxul.so.
The total time spent for this stuff is 236.58s (see 4 lines after) and the two first columns show that almost no time has been spent here: the five lines are almost stuck on 10:17:26.
I'd expect to see almost 4 minutes between the beginning and the end.

Comment 1

[Ricky Stewart]

Forwarding to the component that actually owns this script.

A sys.stderr.flush() at the right moment would probably be in order to make the logs match up to reality here.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:gsvelto, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 3

[Sylvestre Ledru [:Sylvestre]]

As we think we can save a lot of time, I would like to fix that bug asap to be able to evaluate the savings.

Comment 4

[Sylvestre Ledru [:Sylvestre]]

Ricky, I tried to flush stderr in a bunch of places
https://hg.mozilla.org/try/rev/b27fed0a650c3ed65bab3db2a002844384907d50
https://hg.mozilla.org/try/rev/64e0fb458562cde1388b0a7ce059fc9069f7ee0e
https://hg.mozilla.org/try/rev/3d8541bb26568f8811a4b65255b3c6ec64f359b4
but no impact

https://treeherder.mozilla.org/#/jobs?repo=try&revision=fa0263d38f8c9cb6eca926bfaa00bd07db67edd8
[task 2020-06-25T09:56:02.131Z] 09:56:02     INFO -  /builds/worker/workspace/obj-build/_virtualenvs/init_py3/bin/python -m mozbuild.action.dumpsymbols /builds/worker/workspace/obj-build/toolkit/library/gtest/libxul.so /builds/worker/workspace/obj-build/toolkit/library/gtest/libxul.so_syms.track
[task 2020-06-25T09:56:02.131Z] 09:56:02     INFO -  Running: /builds/worker/workspace/obj-build/_virtualenvs/init_py3/bin/python /builds/worker/checkouts/gecko/toolkit/crashreporter/tools/symbolstore.py -c --vcs-info --install-manifest=/builds/worker/workspace/obj-build/_build_manifests/install/dist_include,/builds/worker/workspace/obj-build/dist/include -s /builds/worker/checkouts/gecko /builds/worker/workspace/obj-build/dist/host/bin/dump_syms /builds/worker/workspace/obj-build/dist/crashreporter-symbols /builds/worker/workspace/obj-build/toolkit/library/gtest/libxul.so
[task 2020-06-25T09:56:02.131Z] 09:56:02     INFO -  Beginning work for file: /builds/worker/workspace/obj-build/toolkit/library/gtest/libxul.so
[task 2020-06-25T09:56:02.132Z] 09:56:02     INFO -  Processing file: /builds/worker/workspace/obj-build/toolkit/library/gtest/libxul.so
[task 2020-06-25T09:56:02.132Z] 09:56:02     INFO -  /builds/worker/workspace/obj-build/dist/host/bin/dump_syms /builds/worker/workspace/obj-build/toolkit/library/gtest/libxul.so
[task 2020-06-25T09:56:02.132Z] 09:56:02     INFO -  Finished processing /builds/worker/workspace/obj-build/toolkit/library/gtest/libxul.so in 287.80s
[task 2020-06-25T09:56:02.132Z] 09:56:02     INFO -  make[4]: Leaving directory '/builds/worker/workspace/obj-build/toolkit/library/gtest'

any idea? merci!

Comment 5

[Mike Hommey [:glandium]]

The problem is https://searchfox.org/mozilla-central/source/build/moz-automation.mk#33

Comment 6

[Sylvestre Ledru [:Sylvestre]]

on riot, Mike said:

like completely mixed output, with, in the worst case, lines from one process interrupting lines from another
the only viable alternative is --output-sync=line, which doesn't do what you'd think it does
it syncs per command line, as opposed to per output line
so when you have one target with multiple commands, it syncs each of them independently
but if one of them prints something, waits 10s and prints something else, both prints will appear at the end
the lesson is: don't rely on timestamps
they're a vague indicator
the only reliable thing they can tell you is when a command finishes
that said, with --output-sync=line, there's Entering directory and Leaving directory messages around each line, which is confusing, but those would actually have the right timestamps

Comment 7

[Ricky Stewart]

Looks like my NI can be cleared since mike got to it?

Comment 8

[Sylvestre Ledru [:Sylvestre]]

build_resources.json ( ex: https://firefoxci.taskcluster-artifacts.net/B0K4hI4ISHOF56K3FWeN-w/0/public/build/build_resources.json )
is the source of truth

(thanks Nathan)

Comment 9

[Sylvestre Ledru [:Sylvestre]]

No clue how to fix that

Comment 10

[Sylvestre Ledru [:Sylvestre]]

See:
https://bugzilla.mozilla.org/show_bug.cgi?id=1648761#c4
for more ideas