Closed Bug 1424198 Opened 6 years ago Closed 6 years ago

Intermittent TEST-UNEXPECTED-FAIL : xperf: File '{firefox}\crash reports\lastcrash' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 20, DiskWriteBytes: 0

Categories

(Testing :: Talos, defect, P5)

Product:
Testing
Component:
Talos
Version:
Version 3
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:other]) 

In the last 7 days there are 35 failures.
This occurs only on Windows 7, most of them on opt build type and also on pgo. 

This is a recent log:
https://treeherder.mozilla.org/logviewer.html#?job_id=151749849&repo=autoland&lineNumber=2004

Part of the log where the test failed: 
00:01:37     INFO -  PID 4832 | [Parent 4832, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:01:37     INFO -  PID 4832 | [Child 5356, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:01:37     INFO -  PID 4832 | [Child 5356, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:01:37     INFO -  PID 4832 | [Parent 4832, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:01:37     INFO -  PID 4832 | [Child 5704, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:01:37     INFO -  PID 4832 | [Child 5704, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:01:38     INFO -  PID 4832 | [Parent 4832, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:01:39     INFO -  TEST-INFO | 4832: exit 0
00:01:40     INFO -  The trace you have just captured "Z:\task_1513295549\build\test.etl.kernel" may contain personally identifiable information, including but not necessarily limited to paths to files accessed, paths to registry accessed and process names. Exact information depends on the events that were logged. Please be aware of this when sharing out this trace with other people.
00:01:40     INFO -  The trace you have just captured "Z:\task_1513295549\build\test.etl.user" may contain personally identifiable information, including but not necessarily limited to paths to files accessed, paths to registry accessed and process names. Exact information depends on the events that were logged. Please be aware of this when sharing out this trace with other people.
00:01:49     INFO -  Merged Etl: test.etl
00:03:37     INFO -  c:/Program Files/Microsoft Windows Performance Toolkit/xperf: warning: applying restriction of access for trace processing
00:04:30     INFO -  reading etl filename: test.etl
00:04:30     INFO -  etlparser: in readfile: test.etl.csv
00:04:30     INFO -  TEST-UNEXPECTED-FAIL : xperf: File '{firefox}\crash reports\lastcrash' was accessed and we were not expecting it.  DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 20, DiskWriteBytes: 0
00:04:35     INFO -  extending with xperf!
00:04:35     INFO -  Detected a regression for tp5n
00:04:35     INFO -  TEST-UNEXPECTED-FAIL | tp5n | Talos has found a regression, if you have questions ask for help in irc on #perf
00:04:35    ERROR -  Traceback (most recent call last):
00:04:35     INFO -    File "Z:\task_1513295549\build\tests\talos\talos\run_tests.py", line 276, in run_tests
00:04:35     INFO -      talos_results.add(mytest.runTest(browser_config, test))
00:04:35     INFO -    File "Z:\task_1513295549\build\tests\talos\talos\ttest.py", line 62, in runTest
00:04:35     INFO -      return self._runTest(browser_config, test_config, setup)
00:04:35     INFO -    File "Z:\task_1513295549\build\tests\talos\talos\ttest.py", line 267, in _runTest
00:04:35     INFO -      'Talos has found a regression, if you have questions'
00:04:35     INFO -  TalosRegression: Talos has found a regression, if you have questions ask for help in irc on #perf
00:04:35     INFO -  TEST-INFO took 268432ms
00:04:35     INFO -  SUITE-END | took 268s
00:04:35    ERROR - Return code: 1
00:04:35  WARNING - setting return code to 1
00:04:35    ERROR - # TBPL WARNING #

:rwood could you please take a look?
Flags: needinfo?(rwood)
Whiteboard: [stockwell needswork]
:igoldan, you're familiar with xperf right? Would you please have a look? thanks!
Flags: needinfo?(rwood) → needinfo?(igoldan)
There were 38 failures in the last week.
All the failures occur on the Windows 7 platform.
The affected build types are : pgo and opt, with an almost equal number of failures.

Here is a recent log file: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=153248108&lineNumber=1973
And a snippet with the failure:

23:59:14     INFO -  TEST-INFO | 4552: exit 0
1967
23:59:15     INFO -  The trace you have just captured "Z:\task_1514073022\build\test.etl.kernel" may contain personally identifiable information, including but not necessarily limited to paths to files accessed, paths to registry accessed and process names. Exact information depends on the events that were logged. Please be aware of this when sharing out this trace with other people.
1968
23:59:15     INFO -  The trace you have just captured "Z:\task_1514073022\build\test.etl.user" may contain personally identifiable information, including but not necessarily limited to paths to files accessed, paths to registry accessed and process names. Exact information depends on the events that were logged. Please be aware of this when sharing out this trace with other people.
1969
23:59:24     INFO -  Merged Etl: test.etl
1970
00:01:17     INFO -  c:/Program Files/Microsoft Windows Performance Toolkit/xperf: warning: applying restriction of access for trace processing
1971
00:02:13     INFO -  reading etl filename: test.etl
1972
00:02:13     INFO -  etlparser: in readfile: test.etl.csv
1973
00:02:13     INFO -  TEST-UNEXPECTED-FAIL : xperf: File '{firefox}\crash reports\lastcrash' was accessed and we were not expecting it.  DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 20, DiskWriteBytes: 0
1974
00:02:20     INFO -  extending with xperf!
1975
00:02:20     INFO -  Detected a regression for tp5n
1976
00:02:20     INFO -  TEST-UNEXPECTED-FAIL | tp5n | Talos has found a regression, if you have questions ask for help in irc on #perf
1977
00:02:20    ERROR -  Traceback (most recent call last):
1978
00:02:20     INFO -    File "Z:\task_1514073022\build\tests\talos\talos\run_tests.py", line 276, in run_tests
1979
00:02:20     INFO -      talos_results.add(mytest.runTest(browser_config, test))
1980
00:02:20     INFO -    File "Z:\task_1514073022\build\tests\talos\talos\ttest.py", line 62, in runTest
1981
00:02:20     INFO -      return self._runTest(browser_config, test_config, setup)
1982
00:02:20     INFO -    File "Z:\task_1514073022\build\tests\talos\talos\ttest.py", line 267, in _runTest
1983
00:02:20     INFO -      'Talos has found a regression, if you have questions'
1984
00:02:20     INFO -  TalosRegression: Talos has found a regression, if you have questions ask for help in irc on #perf
1985
00:02:20     INFO -  TEST-INFO took 280546ms
1986
00:02:20     INFO -  SUITE-END | took 280s


:igoldan, could you please take a look?
Over the past week there are 30 fails and all happen on Windows 7

Recent log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=154556855&lineNumber=1994 

14:09:56     INFO -  TEST-UNEXPECTED-FAIL : xperf: File '{firefox}\crash reports\lastcrash' was accessed and we were not expecting it.  DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 20, DiskWriteBytes: 0
14:10:02     INFO -  extending with xperf!
14:10:02     INFO -  Detected a regression for tp5n
14:10:02     INFO -  TEST-UNEXPECTED-FAIL | tp5n | Talos has found a regression, if you have questions ask for help in irc on #perf
14:10:02    ERROR -  Traceback (most recent call last):
14:10:02     INFO -    File "Z:\task_1515247188\build\tests\talos\talos\run_tests.py", line 288, in run_tests
14:10:02     INFO -      talos_results.add(mytest.runTest(browser_config, test))
14:10:02     INFO -    File "Z:\task_1515247188\build\tests\talos\talos\ttest.py", line 62, in runTest
14:10:02     INFO -      return self._runTest(browser_config, test_config, setup)
14:10:02     INFO -    File "Z:\task_1515247188\build\tests\talos\talos\ttest.py", line 267, in _runTest
14:10:02     INFO -      'Talos has found a regression, if you have questions'
14:10:02     INFO -  TalosRegression: Talos has found a regression, if you have questions ask for help in irc on #perf
14:10:02     INFO -  TEST-INFO took 315837ms
14:10:02     INFO -  SUITE-END | took 315s
14:10:03    ERROR - Return code: 1
14:10:03  WARNING - setting return code to 1
14:10:03    ERROR - # TBPL WARNING #
Flags: needinfo?(rwood)
Ah, I believe the xperf whitelist needs to be updated again.. :igoldan, you've done this in the past correct? Can you please make a fix for this when you have a chance? Thanks!
Flags: needinfo?(rwood)
Yes, I'm working on a fix for this. I cannot push it yet, as h1 and h2 tests then start to fail on Windows. So I first have to investigate why that happens.
Flags: needinfo?(igoldan)
h1/h2 have been failing more frequently- it cannot be related to an xperf whitelist change.
(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #12)
> h1/h2 have been failing more frequently- it cannot be related to an xperf
> whitelist change.

Oh, thanks for mentioning that!
:igoldan, any updates here?
Flags: needinfo?(igoldan)
This is now fixed. Bug 1423353 resolved this kind of intermittents.
Flags: needinfo?(igoldan)
Depends on: 1423353
Whiteboard: [stockwell unknown] → [stockwell fixed:other]
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.