Closed Bug 1234109 Opened 8 years ago Closed 7 years ago

xperf: File 'c:\users\public\desktop.ini' was accessed and we were not expecting it (and more)

Categories

(Testing :: Talos, defect)

Product:
Testing
Component:
Talos
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox46 affected)

Status:
RESOLVED WORKSFORME
Tracking Flags:
Tracking Status
firefox46 --- affected

People

(Reporter: nigelb, Unassigned)

References

(
URL
)

Details

(Keywords: intermittent-failure) 

https://treeherder.mozilla.org/logviewer.html#?job_id=18810823&repo=mozilla-inbound


TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\public\desktop.ini' was accessed and we were not expecting it. DiskReadCount: 24, DiskWriteCount: 0, DiskReadBytes: 4176, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\cltbld\music\desktop.ini' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 1012, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\cltbld\pictures\desktop.ini' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 1012, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\cltbld\appdata\roaming\microsoft\windows\libraries\pictures.library-ms' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 8192, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\cltbld\appdata\roaming\microsoft\windows\libraries\videos.library-ms' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 8192, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\public\pictures\desktop.ini' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 764, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\cltbld\videos\desktop.ini' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 1012, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\public\videos\desktop.ini' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 764, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\public\music\desktop.ini' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 764, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\cltbld\appdata\roaming\microsoft\windows\libraries\desktop.ini' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 552, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL : xperf: File 'c:\users\cltbld\appdata\roaming\microsoft\windows\libraries\music.library-ms' was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 8192, DiskWriteBytes: 0
TEST-UNEXPECTED-FAIL | tp5n | Talos has found a regression, if you have questions ask for help in irc on #perf
Traceback (most recent call last):
Return code: 1
# TBPL WARNING #
This wakes up sleeping secondary hard disks that includes Windows libraries.

Filtered Process Monitor logs:

"Time of Day","Process Name","PID","Operation","Path","Result","Detail"
"12:45:38.6112845 AM","firefox.exe","3920","CreateFile","E:\Libraries\Videos\desktop.ini","SUCCESS","Desired Access: Generic Read, Disposition: Open, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"12:45:38.6113217 AM","firefox.exe","3920","QueryStandardInformationFile","E:\Libraries\Videos\desktop.ini","SUCCESS","AllocationSize: 616, EndOfFile: 610, NumberOfLinks: 1, DeletePending: False, Directory: False"
"12:45:38.6113355 AM","firefox.exe","3920","ReadFile","E:\Libraries\Videos\desktop.ini","SUCCESS","Offset: 0, Length: 610, Priority: Normal"
"12:45:38.6113708 AM","firefox.exe","3920","QueryBasicInformationFile","E:\Libraries\Videos\desktop.ini","SUCCESS","CreationTime: 6/30/2013 8:40:20 PM, LastAccessTime: 6/30/2013 8:40:20 PM, LastWriteTime: 1/14/2016 3:23:09 PM, ChangeTime: 1/14/2016 3:23:09 PM, FileAttributes: HSA"
"12:45:38.6113833 AM","firefox.exe","3920","CloseFile","E:\Libraries\Videos\desktop.ini","SUCCESS",""
"12:49:50.5754412 AM","firefox.exe","6668","CreateFile","E:\Libraries\Videos\desktop.ini","SUCCESS","Desired Access: Generic Read, Disposition: Open, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"12:49:50.5754817 AM","firefox.exe","6668","QueryStandardInformationFile","E:\Libraries\Videos\desktop.ini","SUCCESS","AllocationSize: 616, EndOfFile: 610, NumberOfLinks: 1, DeletePending: False, Directory: False"
"12:49:50.5754962 AM","firefox.exe","6668","ReadFile","E:\Libraries\Videos\desktop.ini","SUCCESS","Offset: 0, Length: 610, Priority: Normal"
"12:49:50.5755512 AM","firefox.exe","6668","QueryBasicInformationFile","E:\Libraries\Videos\desktop.ini","SUCCESS","CreationTime: 6/30/2013 8:40:20 PM, LastAccessTime: 6/30/2013 8:40:20 PM, LastWriteTime: 1/14/2016 3:23:09 PM, ChangeTime: 1/14/2016 3:23:09 PM, FileAttributes: HSA"
"12:49:50.5755640 AM","firefox.exe","6668","CloseFile","E:\Libraries\Videos\desktop.ini","SUCCESS",""
Thanks saschanez!  this is good info.  Do you know if we can prevent this from happening?  Is this what you see on a local run or via data from automation?

If there is no way to prevent this, it might be realistic to add exceptions to the file:
https://dxr.mozilla.org/mozilla-central/source/testing/talos/talos/xtalos/xperf_whitelist.json?case=true&from=xperf_whitelist.json

The more we understand what we are doing, the less surprises we encounter:)
I'm seeing this on a local run and it should be prevented to block any unexpected HDD wakeup. Unfortunately I have no idea why this happens as of now.
that is great you could reproduce this, and this is great data to have
According to more logs, Firefox accesses "User Shell Folders" registry, get directories of user libraries, and access desktop.ini file.

https://dxr.mozilla.org/mozilla-central/source/obj-x86_64-unknown-linux-gnu/_virtualenv/lib/python2.7/site-packages/pip/utils/appdirs.py#206

It seems this file has codes for that.

More logs:

"Time of Day","Process Name","PID","Operation","Path","Result","Detail"
"2:24:04.4607349 AM","firefox.exe","3448","RegOpenKey","HKCU","SUCCESS","Desired Access: Read"
"2:24:04.4607454 AM","firefox.exe","3448","RegQueryKey","HKCU","SUCCESS","Query: HandleTags, HandleTags: 0x0"
"2:24:04.4607537 AM","firefox.exe","3448","RegOpenKey","HKCU\Software\Microsoft\Windows\CurrentVersion\Explorer\User Shell Folders","SUCCESS","Desired Access: Read"
"2:24:04.4607642 AM","firefox.exe","3448","RegCloseKey","HKCU","SUCCESS",""
"2:24:04.4607721 AM","firefox.exe","3448","RegQueryValue","HKCU\SOFTWARE\Microsoft\Windows\CurrentVersion\Explorer\User Shell Folders\{35286A68-3C57-41A1-BBB1-0EAE73D76C95}","SUCCESS","Type: REG_EXPAND_SZ, Length: 40, Data: E:\Libraries\Videos"
"2:24:04.4608073 AM","firefox.exe","3448","RegCloseKey","HKCU\SOFTWARE\Microsoft\Windows\CurrentVersion\Explorer\User Shell Folders","SUCCESS",""
"2:24:04.4608297 AM","firefox.exe","3448","RegQueryKey","HKCU\Software\Classes","SUCCESS","Query: Name"
"2:24:04.4608403 AM","firefox.exe","3448","RegQueryKey","HKCU\Software\Classes","SUCCESS","Query: HandleTags, HandleTags: 0x0"
"2:24:04.4608478 AM","firefox.exe","3448","RegQueryKey","HKCU\Software\Classes","SUCCESS","Query: HandleTags, HandleTags: 0x0"
"2:24:04.4608564 AM","firefox.exe","3448","RegOpenKey","HKCU\Software\Classes\Drive\shellex\FolderExtensions","NAME NOT FOUND","Desired Access: Enumerate Sub Keys"
"2:24:04.4608679 AM","firefox.exe","3448","RegOpenKey","HKCR\Drive\shellex\FolderExtensions","SUCCESS","Desired Access: Enumerate Sub Keys"
"2:24:04.4608818 AM","firefox.exe","3448","RegQueryKey","HKCR\Drive\shellex\FolderExtensions","SUCCESS","Query: Name"
"2:24:04.4608913 AM","firefox.exe","3448","RegQueryKey","HKCR\Drive\shellex\FolderExtensions","SUCCESS","Query: HandleTags, HandleTags: 0x0"
"2:24:04.4609025 AM","firefox.exe","3448","RegOpenKey","HKCU\Software\Classes\Drive\shellex\FolderExtensions","NAME NOT FOUND","Desired Access: Maximum Allowed"
"2:24:04.4609137 AM","firefox.exe","3448","RegEnumKey","HKCR\Drive\shellex\FolderExtensions","SUCCESS","Index: 0, Name: {fbeb8a05-beee-4442-804e-409d6c4515e9}"
"2:24:04.4609318 AM","firefox.exe","3448","RegQueryKey","HKCU\Software\Classes","SUCCESS","Query: Name"
"2:24:04.4609509 AM","firefox.exe","3448","RegQueryKey","HKCU\Software\Classes","SUCCESS","Query: HandleTags, HandleTags: 0x0"
"2:24:04.4609591 AM","firefox.exe","3448","RegQueryKey","HKCU\Software\Classes","SUCCESS","Query: HandleTags, HandleTags: 0x0"
"2:24:04.4609680 AM","firefox.exe","3448","RegOpenKey","HKCU\Software\Classes\Drive\shellex\FolderExtensions\{fbeb8a05-beee-4442-804e-409d6c4515e9}","NAME NOT FOUND","Desired Access: Query Value"
"2:24:04.4609799 AM","firefox.exe","3448","RegOpenKey","HKCR\Drive\shellex\FolderExtensions\{fbeb8a05-beee-4442-804e-409d6c4515e9}","SUCCESS","Desired Access: Query Value"
"2:24:04.4609937 AM","firefox.exe","3448","RegQueryKey","HKCR\Drive\shellex\FolderExtensions\{fbeb8a05-beee-4442-804e-409d6c4515e9}","SUCCESS","Query: Name"
"2:24:04.4610036 AM","firefox.exe","3448","RegQueryKey","HKCR\Drive\shellex\FolderExtensions\{fbeb8a05-beee-4442-804e-409d6c4515e9}","SUCCESS","Query: HandleTags, HandleTags: 0x0"
"2:24:04.4610144 AM","firefox.exe","3448","RegOpenKey","HKCU\Software\Classes\Drive\shellex\FolderExtensions\{fbeb8a05-beee-4442-804e-409d6c4515e9}","NAME NOT FOUND","Desired Access: Maximum Allowed"
"2:24:04.4610250 AM","firefox.exe","3448","RegQueryValue","HKCR\Drive\shellex\FolderExtensions\{fbeb8a05-beee-4442-804e-409d6c4515e9}\DriveMask","SUCCESS","Type: REG_DWORD, Length: 4, Data: 32"
"2:24:04.4610352 AM","firefox.exe","3448","RegCloseKey","HKCR\Drive\shellex\FolderExtensions\{fbeb8a05-beee-4442-804e-409d6c4515e9}","SUCCESS",""
"2:24:04.4610457 AM","firefox.exe","3448","RegEnumKey","HKCR\Drive\shellex\FolderExtensions","NO MORE ENTRIES","Index: 1, Length: 288"
"2:24:04.4610556 AM","firefox.exe","3448","RegCloseKey","HKCR\Drive\shellex\FolderExtensions","SUCCESS",""
"2:24:04.4611343 AM","firefox.exe","3448","CreateFile","E:\Libraries\Videos\desktop.ini","SUCCESS","Desired Access: Generic Read, Disposition: Open, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"2:24:04.4611715 AM","firefox.exe","3448","QueryStandardInformationFile","E:\Libraries\Videos\desktop.ini","SUCCESS","AllocationSize: 616, EndOfFile: 610, NumberOfLinks: 1, DeletePending: False, Directory: False"
"2:24:04.4611850 AM","firefox.exe","3448","ReadFile","E:\Libraries\Videos\desktop.ini","SUCCESS","Offset: 0, Length: 610, Priority: Normal"
"2:24:04.4612242 AM","firefox.exe","3448","QueryBasicInformationFile","E:\Libraries\Videos\desktop.ini","SUCCESS","CreationTime: 6/30/2013 8:40:20 PM, LastAccessTime: 6/30/2013 8:40:20 PM, LastWriteTime: 1/14/2016 3:23:09 PM, ChangeTime: 1/14/2016 3:23:09 PM, FileAttributes: HSA"
"2:24:04.4612367 AM","firefox.exe","3448","CloseFile","E:\Libraries\Videos\desktop.ini","SUCCESS",""
we haven't seen this in ~1 year, going to close it out
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.