Closed Bug 1736256 Opened 3 years ago Closed 3 years ago

Intermittent glvideo, glterrain | IO Completion Port failed to signal process shutdown

Categories

(Core :: Graphics: CanvasWebGL, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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


[task 2021-10-17T22:48:30.548Z] 22:48:30     INFO -  PID 2244 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\task_1634497305\\AppData\\Local\\Temp\\tmpr136xtcq\\profile\\search.json.mozlz4", (void 0)))
[task 2021-10-17T22:48:40.120Z] 22:48:40     INFO -  PID 2244 | [talos glvideo result] Mean tick time across 100 ticks: 4.344399999999996 ms
[task 2021-10-17T22:48:40.121Z] 22:48:40     INFO -  PID 2244 | Cycle 1(1): loaded http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html (next: http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html)
[task 2021-10-17T22:48:41.705Z] 22:48:41     INFO -  PID 2244 | [talos glvideo result] Mean tick time across 100 ticks: 3.8966000000000007 ms
[task 2021-10-17T22:48:41.706Z] 22:48:41     INFO -  PID 2244 | Cycle 1(2): loaded http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html (next: http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html)
[task 2021-10-17T22:48:43.261Z] 22:48:43     INFO -  PID 2244 | [talos glvideo result] Mean tick time across 100 ticks: 3.9998 ms
[task 2021-10-17T22:48:43.262Z] 22:48:43     INFO -  PID 2244 | Cycle 1(3): loaded http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html (next: http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html)
[task 2021-10-17T22:48:44.472Z] 22:48:44     INFO -  PID 2244 | [talos glvideo result] Mean tick time across 100 ticks: 4.0760000000000005 ms
[task 2021-10-17T22:48:44.472Z] 22:48:44     INFO -  PID 2244 | Cycle 1(4): loaded http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html (next: http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html)
[task 2021-10-17T22:48:45.716Z] 22:48:45     INFO -  PID 2244 | [talos glvideo result] Mean tick time across 100 ticks: 4.1628 ms
[task 2021-10-17T22:48:45.717Z] 22:48:45     INFO -  PID 2244 | Cycle 1(5): loaded http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html (next: http://127.0.0.1:49842/tests/webgl/benchmarks/video/video_upload.html)
[task 2021-10-17T22:48:45.967Z] 22:48:45     INFO -  PID 2244 | __start_tp_report
[task 2021-10-17T22:48:45.969Z] 22:48:45     INFO -  PID 2244 | _x_x_mozilla_page_load
[task 2021-10-17T22:48:45.969Z] 22:48:45     INFO -  PID 2244 | _x_x_mozilla_page_load_details
[task 2021-10-17T22:48:45.969Z] 22:48:45     INFO -  PID 2244 | |i|pagename|runs|
[task 2021-10-17T22:48:45.970Z] 22:48:45     INFO -  PID 2244 | |0;Mean tick time across 100 ticks: ;4.344399999999996;3.8966000000000007;3.9998;4.0760000000000005;4.1628
[task 2021-10-17T22:48:45.971Z] 22:48:45     INFO -  PID 2244 | __end_tp_report
[task 2021-10-17T22:48:45.972Z] 22:48:45     INFO -  PID 2244 | __start_cc_report
[task 2021-10-17T22:48:45.975Z] 22:48:45     INFO -  PID 2244 | _x_x_mozilla_cycle_collect,146.99038123487662
[task 2021-10-17T22:48:45.975Z] 22:48:45     INFO -  PID 2244 | __end_cc_report
[task 2021-10-17T22:48:45.976Z] 22:48:45     INFO -  PID 2244 | __startTimestamp14873.699521109742__endTimestamp
[task 2021-10-17T22:48:45.976Z] 22:48:45     INFO -  PID 2244 |
[task 2021-10-17T22:48:45.976Z] 22:48:45     INFO -  PID 2244 | ------- Summary: start -------
[task 2021-10-17T22:48:45.977Z] 22:48:45     INFO -  PID 2244 | Number of tests: 1
[task 2021-10-17T22:48:45.977Z] 22:48:45     INFO -  PID 2244 |
[task 2021-10-17T22:48:45.977Z] 22:48:45     INFO -  PID 2244 | [#0] Mean tick time across 100 ticks:   Cycles:5  Average:4.10  Median:4.08  stddev:0.17 (4.2%)  stddev-sans-first:0.11
[task 2021-10-17T22:48:45.978Z] 22:48:45     INFO -  PID 2244 | Values: 4.3  3.9  4.0  4.1  4.2
[task 2021-10-17T22:48:45.978Z] 22:48:45     INFO -  PID 2244 | -------- Summary: end --------
[task 2021-10-17T22:48:45.978Z] 22:48:45     INFO -  PID 2244 |
[task 2021-10-17T22:48:46.334Z] 22:48:46     INFO -  PID 2244 | [Parent 4068, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2021-10-17T22:48:51.240Z] 22:48:51     INFO -  mozcrash checking C:\Users\task_1634497305\AppData\Local\Temp\tmpr136xtcq\profile\minidumps for minidumps...
[task 2021-10-17T22:48:51.241Z] 22:48:51     INFO -  TEST-UNEXPECTED-ERROR | glvideo | IO Completion Port failed to signal process shutdown
[task 2021-10-17T22:48:51.241Z] 22:48:51    ERROR -  Traceback (most recent call last):
[task 2021-10-17T22:48:51.241Z] 22:48:51     INFO -    File "C:\Users\task_1634497305\build\venv\lib\site-packages\mozprocess\processhandler.py", line 710, in _custom_wait
[task 2021-10-17T22:48:51.241Z] 22:48:51     INFO -      item = self._process_events.get(timeout=timeout)
[task 2021-10-17T22:48:51.242Z] 22:48:51     INFO -    File "c:\mozilla-build\python3\lib\queue.py", line 172, in get
[task 2021-10-17T22:48:51.242Z] 22:48:51     INFO -      raise Empty
[task 2021-10-17T22:48:51.242Z] 22:48:51     INFO -  queue.Empty
[task 2021-10-17T22:48:51.243Z] 22:48:51     INFO -  During handling of the above exception, another exception occurred:
[task 2021-10-17T22:48:51.243Z] 22:48:51    ERROR -  Traceback (most recent call last):
[task 2021-10-17T22:48:51.243Z] 22:48:51     INFO -    File "C:\Users\task_1634497305\build\tests\talos\talos\run_tests.py", line 336, in run_tests
[task 2021-10-17T22:48:51.244Z] 22:48:51     INFO -      talos_results.add(mytest.runTest(browser_config, test))
[task 2021-10-17T22:48:51.244Z] 22:48:51     INFO -    File "C:\Users\task_1634497305\build\tests\talos\talos\ttest.py", line 65, in runTest
[task 2021-10-17T22:48:51.244Z] 22:48:51     INFO -      return self._runTest(browser_config, test_config, setup)
[task 2021-10-17T22:48:51.245Z] 22:48:51     INFO -    File "C:\Users\task_1634497305\build\tests\talos\talos\ttest.py", line 215, in _runTest
[task 2021-10-17T22:48:51.245Z] 22:48:51     INFO -      debugger_args=browser_config["debugger_args"],
[task 2021-10-17T22:48:51.245Z] 22:48:51     INFO -    File "C:\Users\task_1634497305\build\tests\talos\talos\talos_process.py", line 176, in run_browser
[task 2021-10-17T22:48:51.245Z] 22:48:51     INFO -      if proc.wait(1) is not None:
[task 2021-10-17T22:48:51.246Z] 22:48:51     INFO -    File "C:\Users\task_1634497305\build\venv\lib\site-packages\mozprocess\processhandler.py", line 1054, in wait
[task 2021-10-17T22:48:51.246Z] 22:48:51     INFO -      self.returncode = self.proc.wait(timeout)
[task 2021-10-17T22:48:51.247Z] 22:48:51     INFO -    File "C:\Users\task_1634497305\build\venv\lib\site-packages\mozprocess\processhandler.py", line 286, in wait
[task 2021-10-17T22:48:51.247Z] 22:48:51     INFO -      self.returncode = self._custom_wait(timeout=timeout)
[task 2021-10-17T22:48:51.247Z] 22:48:51     INFO -    File "C:\Users\task_1634497305\build\venv\lib\site-packages\mozprocess\processhandler.py", line 717, in _custom_wait
[task 2021-10-17T22:48:51.248Z] 22:48:51     INFO -      "IO Completion Port failed to signal process shutdown"
[task 2021-10-17T22:48:51.248Z] 22:48:51     INFO -  OSError: IO Completion Port failed to signal process shutdown
[task 2021-10-17T22:48:51.248Z] 22:48:51     INFO -  TEST-INFO took 46585ms
[task 2021-10-17T22:48:51.248Z] 22:48:51     INFO -  SUITE-END | took 278s
[task 2021-10-17T22:48:51.522Z] 22:48:51    ERROR -  Traceback (most recent call last):
[task 2021-10-17T22:48:51.523Z] 22:48:51     INFO -    File "C:\Users\task_1634497305\build\venv\lib\site-packages\mozprocess\processhandler.py", line 710, in _custom_wait
[task 2021-10-17T22:48:51.523Z] 22:48:51     INFO -      item = self._process_events.get(timeout=timeout)
[task 2021-10-17T22:48:51.524Z] 22:48:51     INFO -    File "c:\mozilla-build\python3\lib\queue.py", line 172, in get
[task 2021-10-17T22:48:51.524Z] 22:48:51     INFO -      raise Empty
[task 2021-10-17T22:48:51.524Z] 22:48:51     INFO -  queue.Empty
[task 2021-10-17T22:48:51.525Z] 22:48:51     INFO -  IO Completion Port unexpectedly closed
[task 2021-10-17T22:51:56.578Z] WARNING | IO Completion Port failed to signal process shutdown
[task 2021-10-17T22:51:56.578Z] Parent process 624 exited with children alive:
[task 2021-10-17T22:51:56.578Z] PIDS: 3764, 1492, 2512, 3328, 6684, 3512, 3160
[task 2021-10-17T22:51:56.578Z] Attempting to kill them, but no guarantee of success
[task 2021-10-17T22:51:56.579Z] 22:51:56    ERROR - Return code: 2
[task 2021-10-17T22:51:56.579Z] 22:51:56  WARNING - setting return code to 2
[task 2021-10-17T22:51:56.579Z] 22:51:56    ERROR - # TBPL FAILURE #
[task 2021-10-17T22:51:56.579Z] 22:51:56     INFO - Running post-action listener: _package_coverage_data
[task 2021-10-17T22:51:56.579Z] 22:51:56     INFO - Running post-action listener: _resource_record_post_action
[task 2021-10-17T22:51:56.579Z] 22:51:56     INFO - Running post-action listener: process_java_coverage_data
[task 2021-10-17T22:51:56.579Z] 22:51:56     INFO - [mozharness: 2021-10-17 22:51:56.579033Z] Finished run-tests step (success)
[task 2021-10-17T22:51:56.580Z] 22:51:56     INFO - Running post-run listener: _resource_record_post_run
[task 2021-10-17T22:51:56.728Z] 22:51:56     INFO - Total resource usage - Wall time: 475s; CPU: 24%; Read bytes: 1052465664; Write bytes: 357139456; Read time: 360; Write time: 293
[task 2021-10-17T22:51:56.728Z] 22:51:56     INFO - TinderboxPrint: CPU usage<br/>23.6%
[task 2021-10-17T22:51:56.728Z] 22:51:56     INFO - TinderboxPrint: I/O read bytes / time<br/>1,052,465,664 / 360
[task 2021-10-17T22:51:56.728Z] 22:51:56     INFO - TinderboxPrint: I/O write bytes / time<br/>357,139,456 / 293
[task 2021-10-17T22:51:56.728Z] 22:51:56     INFO - TinderboxPrint: CPU idle<br/>1,456.8 (76.1%)
[task 2021-10-17T22:51:56.728Z] 22:51:56     INFO - TinderboxPrint: CPU system<br/>190.1 (9.9%)
[task 2021-10-17T22:51:56.728Z] 22:51:56     INFO - TinderboxPrint: CPU user<br/>254.5 (13.3%)
[task 2021-10-17T22:51:56.729Z] 22:51:56     INFO - install - Wall time: 11s; CPU: 9%; Read bytes: 929792; Write bytes: 161865728; Read time: 4; Write time: 33
[task 2021-10-17T22:51:56.732Z] 22:51:56     INFO - run-tests - Wall time: 466s; CPU: 24%; Read bytes: 1050905600; Write bytes: 185611264; Read time: 356; Write time: 257
[task 2021-10-17T22:51:56.866Z] 22:51:56  WARNING - returning nonzero exit status 2
See Also: → 1635776
Summary: Intermittent glvideo | IO Completion Port failed to signal process shutdown → Intermittent glvideo, glterrain | IO Completion Port failed to signal process shutdown
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.