1682840 - Intermittent GeckoProfiler.Markers | Expected equality of these values:

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P3)

Description

[Treeherder Bug Filer]

Filed by: ccoroiu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=324681172&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/OHmYhfEGSlmmmytUhIwm4A/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-12-16T12:45:50.788Z] 12:45:50     INFO -  TEST-PASS | SrtpParamInit/TransportSrtpParameterTest.TestSrtpCiphersMismatchCombinations/2 | test completed (time: 213ms)
[task 2020-12-16T12:45:50.788Z] 12:45:50  WARNING -  TEST-UNEXPECTED-FAIL | GTest unit test: failed
[task 2020-12-16T12:45:50.788Z] 12:45:50     INFO -  Passed: 6094
[task 2020-12-16T12:45:50.788Z] 12:45:50  WARNING -  Failed: 1
[task 2020-12-16T12:45:50.788Z] 12:45:50  WARNING -  One or more unittests failed.
[task 2020-12-16T12:45:50.804Z] 12:45:50     INFO -  ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-12-16T12:45:52.144Z] 12:45:52     INFO -  Finished running GTest tests.
[task 2020-12-16T12:45:52.191Z] 12:45:52     INFO -  gtest INFO | gtest | process wait complete, returncode=1
[task 2020-12-16T12:45:52.191Z] 12:45:52     INFO -  mozcrash checking /builds/worker/workspace/build/tests/gtest for minidumps...
[task 2020-12-16T12:45:52.191Z] 12:45:52  WARNING -  gtest TEST-UNEXPECTED-FAIL | gtest | test failed with return code 1
[task 2020-12-16T12:45:52.191Z] 12:45:52     INFO -  gtest INFO | rungtests.py exits with code 1
[task 2020-12-16T12:45:52.237Z] 12:45:52    ERROR - Return code: 1
[task 2020-12-16T12:45:52.237Z] 12:45:52     INFO - TinderboxPrint: gtest-gtest<br/>6094/<em class="testfail">1</em>
[task 2020-12-16T12:45:52.237Z] 12:45:52  WARNING - # TBPL FAILURE #
[task 2020-12-16T12:45:52.237Z] 12:45:52  WARNING - setting return code to 2
[task 2020-12-16T12:45:52.237Z] 12:45:52  WARNING - The gtest suite: gtest ran with return status: FAILURE
[task 2020-12-16T12:45:52.237Z] 12:45:52     INFO - Running post-action listener: _package_coverage_data
[task 2020-12-16T12:45:52.237Z] 12:45:52     INFO - Running post-action listener: _resource_record_post_action
[task 2020-12-16T12:45:52.237Z] 12:45:52     INFO - Running post-action listener: process_java_coverage_data
[task 2020-12-16T12:45:52.237Z] 12:45:52     INFO - [mozharness: 2020-12-16 12:45:52.237581Z] Finished run-tests step (success)
[task 2020-12-16T12:45:52.237Z] 12:45:52     INFO - Running post-run listener: _resource_record_post_run
[task 2020-12-16T12:45:52.366Z] 12:45:52     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2020-12-16T12:45:52.370Z] 12:45:52     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 17.773575498575493}, {"name": "io_write_bytes", "value": 1767931904}, {"name": "io.read_bytes", "value": 115904512}, {"name": "io_write_time", "value": 102276}, {"name": "io_read_time", "value": 2616}], "extraOptions": ["taskcluster-c5.xlarge"], "name": "gtest.gtest.overall"}, {"subtests": [{"name": "time", "value": 0.014920949935913086}], "name": "gtest.gtest.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 10.638453960418701}, {"name": "cpu_percent", "value": 25.055555555555557}], "name": "gtest.gtest.install"}, {"subtests": [{"name": "time", "value": 0.165543794631958}], "name": "gtest.gtest.stage-files"}, {"subtests": [{"name": "time", "value": 692.3721978664398}, {"name": "cpu_percent", "value": 17.655643994211285}], "name": "gtest.gtest.run-tests"}]}
[task 2020-12-16T12:45:52.370Z] 12:45:52     INFO - Total resource usage - Wall time: 703s; CPU: 18.0%; Read bytes: 115904512; Write bytes: 1767931904; Read time: 2616; Write time: 102276
[task 2020-12-16T12:45:52.370Z] 12:45:52     INFO - TinderboxPrint: CPU usage<br/>17.7%
[task 2020-12-16T12:45:52.370Z] 12:45:52     INFO - TinderboxPrint: I/O read bytes / time<br/>115,904,512 / 2,616
[task 2020-12-16T12:45:52.370Z] 12:45:52     INFO - TinderboxPrint: I/O write bytes / time<br/>1,767,931,904 / 102,276
[task 2020-12-16T12:45:52.371Z] 12:45:52     INFO - TinderboxPrint: CPU idle<br/>2,298.7 (82.2%)
[task 2020-12-16T12:45:52.371Z] 12:45:52     INFO - TinderboxPrint: CPU system<br/>176.0 (6.3%)
[task 2020-12-16T12:45:52.371Z] 12:45:52     INFO - TinderboxPrint: CPU user<br/>314.5 (11.3%)
[task 2020-12-16T12:45:52.371Z] 12:45:52     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2020-12-16T12:45:52.371Z] 12:45:52     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-12-16T12:45:52.372Z] 12:45:52     INFO - install - Wall time: 11s; CPU: 25.0%; Read bytes: 0; Write bytes: 6799360; Read time: 0; Write time: 3684
[task 2020-12-16T12:45:52.372Z] 12:45:52     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-12-16T12:45:52.377Z] 12:45:52     INFO - run-tests - Wall time: 692s; CPU: 18.0%; Read bytes: 115609600; Write bytes: 1761132544; Read time: 2568; Write time: 98592
[task 2020-12-16T12:45:52.485Z] 12:45:52  WARNING - returning nonzero exit status 2```

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

[task 2020-12-16T17:48:55.456Z] 17:48:55     INFO -  TEST-START | GeckoProfiler.Markers
[task 2020-12-16T17:48:56.000Z] 17:48:55  WARNING -  TEST-UNEXPECTED-FAIL | GeckoProfiler.Markers | Expected equality of these values:
[task 2020-12-16T17:48:56.001Z] 17:48:55     INFO -    display.size()
[task 2020-12-16T17:48:56.001Z] 17:48:55     INFO -      Which is: 2
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -    3u
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -      Which is: 3 @ /builds/worker/checkouts/gecko/tools/profiler/tests/gtest/GeckoProfiler.cpp:1494
[task 2020-12-16T17:48:56.001Z] 17:48:56  WARNING -  TEST-UNEXPECTED-FAIL | GeckoProfiler.Markers | Expected equality of these values:
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -    display[2u].asString()
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -      Which is: ""
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -    "timeline-overview" @ /builds/worker/checkouts/gecko/tools/profiler/tests/gtest/GeckoProfiler.cpp:1497
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -  Profiler buffer range: 271047 .. 1466462 (10758735 bytes)
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -  Stats:         min(us) .. mean(us) .. max(us)  [count]
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -  - Intervals:     989.6 ..  1058.9  .. 31231.7  [514]
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -  - Overheads:      38.7 ..   107.7  .. 31167.9  [515]
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -    - Locking:       0.5 ..    61.1  .. 31102.7  [515]
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -    - Clearning:     0.5 ..     0.6  ..     3.6  [515]
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -    - Counters:      1.9 ..     2.1  ..     6.0  [515]
[task 2020-12-16T17:48:56.001Z] 17:48:56     INFO -    - Threads:      35.6 ..    43.9  ..    72.3  [515]
[task 2020-12-16T17:48:56.021Z] 17:48:56  WARNING -  TEST-UNEXPECTED-FAIL | GeckoProfiler.Markers | test completed (time: 563ms)

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Frequent failure for Linux shippable GTest - Gerald, can you find the change which triggered this?

Comment 3

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

It's not a critical issue, only a discrepancy between a small change in bug 1682349 and the related test -- Sorry I didn't think of that when reviewing.
Easy to fix, I'm on it.

Comment 4

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1682840 - Remove timelineOverview from expected display locations in BHR marker schema gtest - r?julienw

This is to match the trivial change in bug 1682349.

The failure was intermittent because we only test the BHR marker schema if that marker was actually used, and there's no easy way to force it during our tests; however while running the full gtest suite, it's possible that a previous test triggered that marker and failed in the non-updated test.

Comment 5

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

Set release status flags based on info from the regressing bug 1682349

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4725b8bc7c79
Remove timelineOverview from expected display locations in BHR marker schema gtest - r=julienw

Comment 7

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/4725b8bc7c79

Comment 8

[Intermittent Failures Robot]

11 failures in 3421 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 6
• autoland: 5

Platform breakdown:

• linux1804-64-shippable: 4
• linux1804-64-shippable-qr: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1682840&startday=2020-12-14&endday=2020-12-20&tree=all