Print the time taken by each test in jstests and jit-test

RESOLVED FIXED in Firefox 57



2 years ago
2 years ago


(Reporter: arai, Assigned: arai)



Firefox Tracking Flags

(firefox57 fixed)



(1 attachment)



2 years ago
Printing time taken by each testcase would help investigating intermittent timeout and slow tests.

but I thought we had hit log size limitation before and I've reduced the output text,
so, if the log size limitation is still there, it would be nice to print time if it's longer than a certain threshold (maybe timeout/2 or so)

Comment 1

2 years ago
according to emorley, buildbot's limitation is 50mb uncompressed, and taskcluster currently has no limitation but limitation will be added because of backlog caused by huge log (like 700mb)

Comment 2

2 years ago
so I'm going to print time only if it takes long time

Comment 3

2 years ago
fwiw, currently live_backing.log of SM(p) on linux64 opt is 33MB, and 20MB for debug

Comment 4

2 years ago
(In reply to Tooru Fujisawa [:arai] from comment #3)
> fwiw, currently live_backing.log of SM(p) on linux64 opt is 33MB, and 20MB
> for debug

it was SM-tc(p).
on SM(p) on win XP, it's 26MB uncompressed.

Comment 5

2 years ago
it prints like " [1.0 s]" at the end of the line if it takes timeout/2.

try is running here (but it prints regardless of time taken by test)

I have 2 questions:
  1. to avoid increasing log size, it's in very short syntax
     would it be nice to make it more search-able?
     (in case looking for slow tests, not already-known intermittent timeout)

  2. do you think timeout/2 threshold reasonable?
Assignee: nobody → arai.unmht
Attachment #8898768 - Flags: review?(jdemooij)
Comment on attachment 8898768 [details] [diff] [review]
Show time taken by test in jstests and jit-test log if it takes longer than timeout/2.

Review of attachment 8898768 [details] [diff] [review]:

Sorry for the delay. Thanks for doing this!

What do you think about adding the time unconditionally? We're printing a pretty long line anyway and adding a few characters at the end shouldn't affect things that much:

[task 2017-08-18T12:38:19.425111Z] TEST-PASS | js/src/jit-test/tests/bug847682.js | Success (code 0, args "") [0.2 s]
[task 2017-08-18T12:58:56.237829Z] TEST-PASS | test262/built-ins/Array/prototype/every/ | (args: "") [0.3 s]

r=me either way
Attachment #8898768 - Flags: review?(jdemooij) → review+

Comment 8

2 years ago
thank you for reviewing :)

in windows SM(p), there are 187064 tests, and the " [n.n s]" takes ~8 bytes for each.
currently it takes 1.5MB of 27.7MB total in the log.

I'll land with changing it to print unconditionally.
we could re-consider when log size overflows.

(In reply to Till Schneidereit [:till] from comment #6)
> See also bug 1334323.

maybe we can also enable it on automation, but this time the initial motivation is
to figure out if a certain test that hits intermittent-timeout takes long time when it doesn't hit timeout.
so, printing it in the same line seems to be better for the purpose.

Comment 9

2 years ago
Pushed by
Show time taken by test in jstests and jit-test log. r=jandem

Comment 11

2 years ago
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
You need to log in before you can comment on or make changes to this bug.