Open
Bug 1714687
Opened 3 years ago
Updated 1 year ago
Missing talos result: "Profiler could not init with object: {}"
Categories
(Testing :: Talos, defect, P3)
Tracking
(Not tracked)
NEW
People
(Reporter: sfink, Unassigned)
References
(Blocks 1 open bug)
Details
(Whiteboard: [fxp])
I did two pushes with --rebuild 5) to get baseline and test results, but the only significant difference in the perfherder results strangely listed only 2/2 total runs. Most things showed 5/5 results, but many had varying numbers.
In looking at the log file for one of the jobs that should have reported results but didn't, I saw this message when running the relevant test:
[task 2021-06-02T05:00:28.059Z] 05:00:28 INFO - console.error: "Profiler could not init with object: {}"
I don't know if that's the actual problem, but it seems like it tried 10 times and errored out shortly after emitting that message.
Here's the full log for one of those retries:
[task 2021-06-02T05:00:30.919Z] 05:00:30 INFO - Running cycle 3/10 for sessionrestore_no_auto_restore test...
[task 2021-06-02T05:00:30.919Z] 05:00:30 INFO - Reinstalling C:\Users\task_1622609060\build\tests\talos\talos/startup_test/sessionrestore/profile\sessionstore.jsonlz4 on top of C:\Users\task_1622609060\AppData\Local\Temp\tmpkfv7p1lo\profile\sessionstore.jsonlz4
[task 2021-06-02T05:00:30.920Z] 05:00:30 INFO - Reinstalling C:\Users\task_1622609060\build\tests\talos\talos/startup_test/sessionrestore/profile\sessionstore.js on top of C:\Users\task_1622609060\AppData\Local\Temp\tmpkfv7p1lo\profile\sessionstore.js
[task 2021-06-02T05:00:30.922Z] 05:00:30 INFO - Reinstalling C:\Users\task_1622609060\build\tests\talos\talos/startup_test/sessionrestore/profile\sessionCheckpoints.json on top of C:\Users\task_1622609060\AppData\Local\Temp\tmpkfv7p1lo\profile\sessionCheckpoints.json
[task 2021-06-02T05:00:30.923Z] 05:00:30 INFO - Using env: {'ALLUSERSPROFILE': 'C:\\ProgramData',
[task 2021-06-02T05:00:30.923Z] 05:00:30 INFO - 'APPDATA': 'C:\\Users\\task_1622609060\\AppData\\Roaming',
[task 2021-06-02T05:00:30.924Z] 05:00:30 INFO - 'COMMONPROGRAMFILES': 'C:\\Program Files\\Common Files',
[task 2021-06-02T05:00:30.924Z] 05:00:30 INFO - 'COMMONPROGRAMFILES(X86)': 'C:\\Program Files (x86)\\Common Files',
[task 2021-06-02T05:00:30.924Z] 05:00:30 INFO - 'COMMONPROGRAMW6432': 'C:\\Program Files\\Common Files',
[task 2021-06-02T05:00:30.925Z] 05:00:30 INFO - 'COMPUTERNAME': 'T-W1064-MS-066',
[task 2021-06-02T05:00:30.925Z] 05:00:30 INFO - 'COMSPEC': 'C:\\windows\\system32\\cmd.exe',
[task 2021-06-02T05:00:30.925Z] 05:00:30 INFO - 'DRIVERDATA': 'C:\\Windows\\System32\\Drivers\\DriverData',
[task 2021-06-02T05:00:30.926Z] 05:00:30 INFO - 'EXTRA_MOZHARNESS_CONFIG': '{"installer_url": '
[task 2021-06-02T05:00:30.926Z] 05:00:30 INFO - '"https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/W7U6eEtBRsWJNZzwt3OZcA/artifacts/public/build/target.zip", '
[task 2021-06-02T05:00:30.927Z] 05:00:30 INFO - '"test_packages_url": '
[task 2021-06-02T05:00:30.927Z] 05:00:30 INFO - '"https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/W7U6eEtBRsWJNZzwt3OZcA/artifacts/public/build/target.test_packages.json"}',
[task 2021-06-02T05:00:30.927Z] 05:00:30 INFO - 'GECKO_HEAD_REPOSITORY': 'https://hg.mozilla.org/try',
[task 2021-06-02T05:00:30.928Z] 05:00:30 INFO - 'GECKO_HEAD_REV': '92baa778b014c861d02ab475ff37eb4cfbb9994c',
[task 2021-06-02T05:00:30.928Z] 05:00:30 INFO - 'HG_CACHE': 'C:\\tooltool-cache',
[task 2021-06-02T05:00:30.928Z] 05:00:30 INFO - 'HOMEDRIVE': 'C:',
[task 2021-06-02T05:00:30.929Z] 05:00:30 INFO - 'HOMEPATH': '\\Users\\task_1622609060',
[task 2021-06-02T05:00:30.929Z] 05:00:30 INFO - 'LD_LIBRARY_PATH': 'C:\\Users\\task_1622609060\\build\\application\\firefox',
[task 2021-06-02T05:00:30.929Z] 05:00:30 INFO - 'LOCALAPPDATA': 'C:\\Users\\task_1622609060\\AppData\\Local',
[task 2021-06-02T05:00:30.929Z] 05:00:30 INFO - 'LOGONSERVER': '\\\\T-W1064-MS-066',
[task 2021-06-02T05:00:30.930Z] 05:00:30 INFO - 'MINIDUMP_SAVE_PATH': 'C:\\Users\\task_1622609060\\build\\blobber_upload_dir',
[task 2021-06-02T05:00:30.930Z] 05:00:30 INFO - 'MINIDUMP_STACKWALK': 'C:/Users/task_1622609060/fetches\\minidump_stackwalk\\minidump_stackwalk.exe',
[task 2021-06-02T05:00:30.931Z] 05:00:30 INFO - 'MOZILLABUILD': 'C:\\mozilla-build',
[task 2021-06-02T05:00:30.931Z] 05:00:30 INFO - 'MOZ_ACCELERATED': '1',
[task 2021-06-02T05:00:30.931Z] 05:00:30 INFO - 'MOZ_AUTOMATION': '1',
[task 2021-06-02T05:00:30.932Z] 05:00:30 INFO - 'MOZ_CRASHREPORTER': '1',
[task 2021-06-02T05:00:30.932Z] 05:00:30 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1',
[task 2021-06-02T05:00:30.932Z] 05:00:30 INFO - 'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1',
[task 2021-06-02T05:00:30.932Z] 05:00:30 INFO - 'MOZ_FETCHES': '[{"artifact": "public/build/fix-stacks.tar.bz2", "extract": '
[task 2021-06-02T05:00:30.933Z] 05:00:30 INFO - 'true, "task": "Lhs91AvoT-28yyuTcna2Gw"}, {"artifact": '
[task 2021-06-02T05:00:30.933Z] 05:00:30 INFO - '"public/build/minidump_stackwalk.tar.xz", "extract": true, '
[task 2021-06-02T05:00:30.933Z] 05:00:30 INFO - '"task": "bIP8i3ujSfGk0C9FNfGpZg"}]',
[task 2021-06-02T05:00:30.934Z] 05:00:30 INFO - 'MOZ_FETCHES_DIR': 'C:/Users/task_1622609060/fetches',
[task 2021-06-02T05:00:30.934Z] 05:00:30 INFO - 'MOZ_SCM_LEVEL': '1',
[task 2021-06-02T05:00:30.934Z] 05:00:30 INFO - 'MOZ_UPLOAD_DIR': 'C:\\Users\\task_1622609060\\build\\blobber_upload_dir',
[task 2021-06-02T05:00:30.935Z] 05:00:30 INFO - 'MOZ_WEBRENDER': '1',
[task 2021-06-02T05:00:30.935Z] 05:00:30 INFO - 'NO_EM_RESTART': '1',
[task 2021-06-02T05:00:30.935Z] 05:00:30 INFO - 'NUMBER_OF_PROCESSORS': '8',
[task 2021-06-02T05:00:30.936Z] 05:00:30 INFO - 'ONEDRIVE': 'C:\\Users\\task_1622609060\\OneDrive',
[task 2021-06-02T05:00:30.936Z] 05:00:30 INFO - 'OS': 'Windows_NT',
[task 2021-06-02T05:00:30.937Z] 05:00:30 INFO - 'PATH': 'C:\\Users\\task_1622609060\\build\\venv\\Scripts;C:\\windows\\system32;C:\\windows;C:\\windows\\System32\\Wbem;C:\\windows\\System32\\WindowsPowerShell\\v1.0\\;C:\\windows\\System32\\OpenSSH\\;C:\\Program '
[task 2021-06-02T05:00:30.937Z] 05:00:30 INFO - 'Files\\Puppet Labs\\Puppet\\bin;C:\\Program '
[task 2021-06-02T05:00:30.937Z] 05:00:30 INFO - 'Files\\Mellanox\\MLNX_VPI\\IB\\Tools;C:\\Program '
[task 2021-06-02T05:00:30.937Z] 05:00:30 INFO - 'Files\\Mellanox\\MLNX_CIMProvider\\lib\\mft;C:\\Program '
[task 2021-06-02T05:00:30.938Z] 05:00:30 INFO - 'Files\\Git\\cmd;C:\\Program Files (x86)\\GNU\\GnuPG\\pub;C:\\Program '
[task 2021-06-02T05:00:30.938Z] 05:00:30 INFO - 'Files\\Mercurial\\;C:\\Program '
[task 2021-06-02T05:00:30.939Z] 05:00:30 INFO - 'Files\\Mercurial;C:\\mozilla-build\\bin;C:\\mozilla-build\\kdiff;C:\\mozilla-build\\moztools-x64\\bin;C:\\mozilla-build\\mozmake;C:\\mozilla-build\\nsis-3.01;C:\\mozilla-build\\python;C:\\mozilla-build\\python\\Scripts;C:\\mozilla-build\\python3;C:\\mozilla-build\\msys\\bin;C:\\mozilla-build\\msys\\local\\bin;C:\\Program '
[task 2021-06-02T05:00:30.939Z] 05:00:30 INFO - 'Files (x86)\\Windows Kits\\10\\Windows Performance '
[task 2021-06-02T05:00:30.940Z] 05:00:30 INFO - 'Toolkit\\;C:\\Users\\task_1622609060\\AppData\\Local\\Microsoft\\WindowsApps',
[task 2021-06-02T05:00:30.940Z] 05:00:30 INFO - 'PATHEXT': '.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC',
[task 2021-06-02T05:00:30.940Z] 05:00:30 INFO - 'PIP_DOWNLOAD_CACHE': 'C:\\pip-cache',
[task 2021-06-02T05:00:30.940Z] 05:00:30 INFO - 'PROCESSOR_ARCHITECTURE': 'AMD64',
[task 2021-06-02T05:00:30.941Z] 05:00:30 INFO - 'PROCESSOR_IDENTIFIER': 'Intel64 Family 6 Model 94 Stepping 3, GenuineIntel',
[task 2021-06-02T05:00:30.941Z] 05:00:30 INFO - 'PROCESSOR_LEVEL': '6',
[task 2021-06-02T05:00:30.941Z] 05:00:30 INFO - 'PROCESSOR_REVISION': '5e03',
[task 2021-06-02T05:00:30.942Z] 05:00:30 INFO - 'PROGRAMDATA': 'C:\\ProgramData',
[task 2021-06-02T05:00:30.942Z] 05:00:30 INFO - 'PROGRAMFILES': 'C:\\Program Files',
[task 2021-06-02T05:00:30.942Z] 05:00:30 INFO - 'PROGRAMFILES(X86)': 'C:\\Program Files (x86)',
[task 2021-06-02T05:00:30.943Z] 05:00:30 INFO - 'PROGRAMW6432': 'C:\\Program Files',
[task 2021-06-02T05:00:30.943Z] 05:00:30 INFO - 'PROMPT': '$P$G',
[task 2021-06-02T05:00:30.943Z] 05:00:30 INFO - 'PSMODULEPATH': '%ProgramFiles%\\WindowsPowerShell\\Modules;C:\\windows\\system32\\WindowsPowerShell\\v1.0\\Modules;C:\\Program '
[task 2021-06-02T05:00:30.943Z] 05:00:30 INFO - 'Files\\Mellanox\\MLNX_VPI\\Tools\\WMI\\Modules;C:\\Program '
[task 2021-06-02T05:00:30.944Z] 05:00:30 INFO - 'Files\\Mellanox\\MLNX_CIMProvider\\WMI\\Modules',
[task 2021-06-02T05:00:30.944Z] 05:00:30 INFO - 'PUBLIC': 'C:\\Users\\Public',
[task 2021-06-02T05:00:30.944Z] 05:00:30 INFO - 'PYTHON': 'c:\\mozilla-build\\python3\\python3.exe',
[task 2021-06-02T05:00:30.944Z] 05:00:30 INFO - 'PYTHONPATH': 'C:\\Users\\task_1622609060\\build\\tests\\talos',
[task 2021-06-02T05:00:30.945Z] 05:00:30 INFO - 'RUST_BACKTRACE': 'full',
[task 2021-06-02T05:00:30.945Z] 05:00:30 INFO - 'SCCACHE_DISABLE': '1',
[task 2021-06-02T05:00:30.945Z] 05:00:30 INFO - 'STYLO_FORCE_ENABLED': '1',
[task 2021-06-02T05:00:30.945Z] 05:00:30 INFO - 'SYSTEMDRIVE': 'C:',
[task 2021-06-02T05:00:30.945Z] 05:00:30 INFO - 'SYSTEMROOT': 'C:\\windows',
[task 2021-06-02T05:00:30.946Z] 05:00:30 INFO - 'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com',
[task 2021-06-02T05:00:30.946Z] 05:00:30 INFO - 'TASK_ID': 'WncOgqpeTNOcOMXyElijCg',
[task 2021-06-02T05:00:30.946Z] 05:00:30 INFO - 'TASK_STOP_TIME': '1622609548',
[task 2021-06-02T05:00:30.947Z] 05:00:30 INFO - 'TEMP': 'C:\\Users\\task_1622609060\\AppData\\Local\\Temp',
[task 2021-06-02T05:00:30.947Z] 05:00:30 INFO - 'TMP': 'C:\\Users\\task_1622609060\\AppData\\Local\\Temp',
[task 2021-06-02T05:00:30.947Z] 05:00:30 INFO - 'TOOLTOOL_CACHE': 'C:\\builds\\tooltool_cache',
[task 2021-06-02T05:00:30.947Z] 05:00:30 INFO - 'TRY_SELECTOR': 'fuzzy',
[task 2021-06-02T05:00:30.948Z] 05:00:30 INFO - 'USERDOMAIN': 'T-W1064-MS-066',
[task 2021-06-02T05:00:30.948Z] 05:00:30 INFO - 'USERDOMAIN_ROAMINGPROFILE': 'T-W1064-MS-066',
[task 2021-06-02T05:00:30.948Z] 05:00:30 INFO - 'USERNAME': 'task_1622609060',
[task 2021-06-02T05:00:30.948Z] 05:00:30 INFO - 'USERPROFILE': 'C:\\Users\\task_1622609060',
[task 2021-06-02T05:00:30.949Z] 05:00:30 INFO - 'VIRTUAL_ENV': 'C:\\Users\\task_1622609060\\build\\venv',
[task 2021-06-02T05:00:30.949Z] 05:00:30 INFO - 'WINDIR': 'C:\\windows'}
[task 2021-06-02T05:00:30.949Z] 05:00:30 INFO - TEST-INFO | started process 9860 (C:\Users\task_1622609060\build\application\firefox\firefox -wait-for-browser -no-deelevate -profile C:\Users\task_1622609060\AppData\Local\Temp\tmpkfv7p1lo\profile about:home)
[task 2021-06-02T05:00:31.407Z] 05:00:31 INFO - PID 9860 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T05:00:31.407Z] 05:00:31 INFO - PID 9860 | __start_reportNaN__end_report
[task 2021-06-02T05:00:31.408Z] 05:00:31 INFO - PID 9860 |
[task 2021-06-02T05:00:31.408Z] 05:00:31 INFO - PID 9860 | __startTimestamp290.23227046702584__endTimestamp
[task 2021-06-02T05:00:31.408Z] 05:00:31 INFO - PID 9860 |
[task 2021-06-02T05:00:31.641Z] 05:00:31 INFO - PID 9860 |
[task 2021-06-02T05:00:31.641Z] 05:00:31 INFO - PID 9860 | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-06-02T05:00:31.642Z] 05:00:31 INFO - PID 9860 |
[task 2021-06-02T05:00:31.643Z] 05:00:31 INFO - PID 9860 | [2021-06-02T05:00:31Z ERROR xulstore::persist] removeDocument error: unavailable
[task 2021-06-02T05:00:31.694Z] 05:00:31 INFO - TEST-INFO | 9860: exit 0
[task 2021-06-02T05:00:31.947Z] 05:00:31 INFO - mozcrash checking C:\Users\task_1622609060\AppData\Local\Temp\tmpkfv7p1lo\profile\minidumps for minidumps...
|
||
Updated•3 years ago
|
Whiteboard: [perftest:triage]
|
||
Comment 1•3 years ago
|
||
This is an intermittent issue. The task you are pointing to is this one I believe: https://treeherder.mozilla.org/jobs?repo=try&revision=92baa778b014c861d02ab475ff37eb4cfbb9994c&selectedTaskRun=FRTYdf4AS3COgVIxynZ8Eg.0
It looks like it may be trying to start profiling when it shouldn't.
Severity: -- → S4
Priority: -- → P3
|
|
||
Updated•3 years ago
|
Whiteboard: [perftest:triage]
|
Reporter | |
Comment 2•3 years ago
|
||
(In reply to Greg Mierzwinski [:sparky] from comment #1)
This is an intermittent issue. The task you are pointing to is this one I believe: https://treeherder.mozilla.org/jobs?repo=try&revision=92baa778b014c861d02ab475ff37eb4cfbb9994c&selectedTaskRun=FRTYdf4AS3COgVIxynZ8Eg.0
It looks like it may be trying to start profiling when it shouldn't.
Actually, the log file I posted above is from https://treeherder.mozilla.org/jobs?repo=try&revision=92baa778b014c861d02ab475ff37eb4cfbb9994c&selectedTaskRun=WncOgqpeTNOcOMXyElijCg.0 which is green. If you look at the Performance tab in it and the previous (green) build, you'll see that the previous job has a value for sessionrestore_no_auto_restore but the Wnc... job does not.
But when looking at the log for that previous job, it looks like the "Profiler could not init" message is a red herring -- that log also contains that message, despite successfully reporting results:
% less log.gz | egrep 'Profiler could not init|TEST-START'
[task 2021-06-02T04:42:32.160Z] 04:42:32 INFO - TEST-START | a11yr
[task 2021-06-02T04:43:26.091Z] 04:43:26 INFO - TEST-START | ts_paint
[task 2021-06-02T04:44:01.519Z] 04:44:01 INFO - TEST-START | twinopen
[task 2021-06-02T04:44:41.994Z] 04:44:41 INFO - TEST-START | sessionrestore
[task 2021-06-02T04:44:56.383Z] 04:44:56 INFO - PID 10032 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:45:07.487Z] 04:45:07 INFO - PID 6780 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:45:18.599Z] 04:45:18 INFO - PID 4788 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:45:29.674Z] 04:45:29 INFO - PID 8804 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:45:40.786Z] 04:45:40 INFO - PID 4224 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:45:51.870Z] 04:45:51 INFO - PID 848 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:02.983Z] 04:46:02 INFO - PID 1480 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:14.158Z] 04:46:14 INFO - PID 7416 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:25.267Z] 04:46:25 INFO - PID 2040 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:36.355Z] 04:46:36 INFO - PID 9856 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:36.765Z] 04:46:36 INFO - TEST-START | sessionrestore_no_auto_restore
[task 2021-06-02T04:46:38.375Z] 04:46:38 INFO - console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:39.783Z] 04:46:39 INFO - PID 6288 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:41.347Z] 04:46:41 INFO - PID 3572 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:42.916Z] 04:46:42 INFO - PID 6072 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:44.478Z] 04:46:44 INFO - PID 4476 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:46.017Z] 04:46:46 INFO - PID 4792 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:47.598Z] 04:46:47 INFO - PID 6696 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:49.200Z] 04:46:49 INFO - PID 4216 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:50.777Z] 04:46:50 INFO - PID 7436 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:52.101Z] 04:46:52 INFO - PID 624 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:53.673Z] 04:46:53 INFO - PID 8916 | console.error: "Profiler could not init with object: {}"
[task 2021-06-02T04:46:54.552Z] 04:46:54 INFO - TEST-START | tabpaint
[task 2021-06-02T04:47:12.838Z] 04:47:12 INFO - TEST-START | cpstartup
[task 2021-06-02T04:47:31.093Z] 04:47:31 INFO - TEST-START | startup_about_home_paint
[task 2021-06-02T04:48:06.164Z] 04:48:06 INFO - TEST-START | pdfpaint
[task 2021-06-02T04:48:26.046Z] 04:48:26 INFO - TEST-START | cross_origin_pageload
It looks like that message happens with both sessionrestore tests (and not the others), but does not prevent results from being reported.
Ah! The log message that does correspond to missing results is:
[task 2021-06-02T05:00:29.348Z] 05:00:29 INFO - PID 6192 | __start_reportNaN__end_report
Every attempt that the bad job made has the NaN in it.
|
|
Reporter | |
Comment 3•3 years ago
|
||
It looks like that comes from https://searchfox.org/mozilla-central/source/testing/talos/talos/startup_test/sessionrestore/addon/api.js#138-142
So apparently either restoreTime or startup_info.process is bogus. Something in startup_info must be wrong or missing.
|
||
Updated•1 year ago
|
Whiteboard: [fxp]
|
||
Updated•1 year ago
|
Blocks: 1840060
You need to log in
before you can comment on or make changes to this bug.
Description
•