Closed Bug 818141 Opened 13 years ago Closed 6 years ago

Report duration of each reftest test

Categories

(Testing :: General, defect)

Product:
Testing
Component:
General
Platform:
x86
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED WONTFIX

People

(Reporter: gbrown, Assigned: jmaher)

References

Details

Attachments

(1 file, 1 obsolete file)

updated WIP patch, would like to fix test-end to be for the actual test (0.99)
1.81 KB, patch
Details | Diff | Splinter Review
It would be nice to know the duration of each individual reftest in a run. Or, if that's impractical, to know when a test is long-running (exceeds some arbitrary timeout). For instance, in bug 816574, we know that Android R3 takes about 60 minutes to run and are suspicious that certain tests are taking a long time, but we cannot tell from the logs.
Blocks: 816574
Blocks: 816038
Blocks: 816501
Blocks: 818244
marking this patch as a WIP since it has a few undefined values. I need to investigate those in more details.
Assignee: nobody → jmaher
Status: NEW → ASSIGNED
Attachment #688917 - Flags: feedback?(gbrown)
Comment on attachment 688917 [details] [diff] [review] print runtime for each reftest WIP (0.9) Review of attachment 688917 [details] [diff] [review]: ----------------------------------------------------------------- Thanks for this. It is a step in the right direction, but the large proportion of undefined values limits the usefulness. Off the cuff, I wonder if it would be better to use Date.now() - gCurrentTestStartTime ?
Attachment #688917 - Flags: feedback?(gbrown) → feedback+
In order to not diverge our log formats any farther than they already are, can we use the same log format for this notation that mochitest uses: INFO TEST-END | /tests/Harness_sanity/test_SpecialPowersExtension.html | finished in 220ms Ideally we would put in a true TEST-END notice with the test name and the timing output. I really don't want anything r+'d that is going to make our logs MORE difficult to parse.
The WIP patch would also mean that the runtime shows in the TBPL annotated summary, making it longer (and thus more likely to wrap, which IME slows me down using TBPL) & also meaning I'd need to trim the suffix when filing new intermittent failure bugs. The format Clint mentions would avoid both of these (and also avoid making our log format inconsistencies worse) :-)
I now have a patch that produces: REFTEST INFO | drawWindow flags = DRAWWINDOW_DRAW_CARET | DRAWWINDOW_DRAW_VIEW | DRAWWINDOW_USE_WIDGET_LAYERS; window size = 800,1000; test browser size = 800,1000 REFTEST TEST-START | about:blank | 0 / 8825 (0%) REFTEST TEST-PASS | data:text/html,<body> | image comparison (==) REFTEST TEST-END | about:blank | finished in: 58ms REFTEST INFO | Loading a blank page REFTEST TEST-START | data:text/plain, | 1 / 8825 (0%) REFTEST TEST-PASS | data:text/plain, | image comparison (==) REFTEST TEST-END | about:blank | finished in: 84ms REFTEST INFO | Loading a blank page REFTEST TEST-START | data:text/plain,HELLO | 2 / 8825 (0%) REFTEST TEST-PASS | data:text/plain,HELLO | image comparison (!=) REFTEST TEST-END | about:blank | finished in: 35ms REFTEST INFO | Loading a blank page REFTEST TEST-START | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-async.xul | 3 / 8825 (0%) REFTEST TEST-START | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-async-ref.xul | 3 / 8825 (0%) REFTEST TEST-PASS | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-async.xul | image comparison (==) REFTEST TEST-END | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-async-ref.xul | finished in: 24ms REFTEST INFO | Loading a blank page REFTEST TEST-START | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-async.html | 4 / 8825 (0%) REFTEST TEST-START | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-async-ref.html | 4 / 8825 (0%) REFTEST TEST-PASS | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-async.html | image comparison (==) REFTEST TEST-END | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-async-ref.html | finished in: 17ms REFTEST INFO | Loading a blank page REFTEST TEST-START | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-zoom.html | 5 / 8825 (0%) REFTEST TEST-START | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-zoom-ref.html | 5 / 8825 (0%) REFTEST TEST-PASS | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-zoom.html | image comparison (==) REFTEST TEST-END | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/test-zoom-ref.html | finished in: 31ms REFTEST INFO | Loading a blank page REFTEST TEST-START | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/no-root.html | 6 / 8825 (0%) REFTEST TEST-PASS | file:///builds/slave/talos-slave/test/build/reftest/tests/layout/reftests/reftest-sanity/no-root.html | image comparison (==) REFTEST TEST-END | about:blank | finished in: 28ms REFTEST INFO | Loading a blank page I am not sure if we should keep the lingering "REFTEST INFO | Loading a blank page". That seems overkill. It seems like there are still corner cases as the test-end doesn't always align with the test-start, and sometimes there is >1 test-start.
See Also: → 736090
looking at this more, the concept of test-start is not the same that we have in mochitest. We have 2 files that we need to load for a given reftest. We cache these files once loaded, so at the beginning we will do many calls to TEST-START to indicate loading a file. This is why we see two TEST-START calls for one TEST-PASS/END. As we go further in the test suite (usually per manifest), we find that TEST-START is not called since we will have one or both of the test files loaded already. Actually TEST-END is accurate in what we are reporting for the test (the test image, not the reference image). While we could land this patch, it would be confusing and we should really figure out how we want to track and report data from reftests.
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: