Closed Bug 1460811 Opened 6 years ago Closed 5 years ago

re-implement XULStore using rkv

Categories

(Toolkit :: Storage, enhancement, P3)

Product:
Toolkit
Component:
Storage
Type:
enhancement

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla68
Tracking Flags:
Tracking Status
firefox68 --- fixed

People

(Reporter: myk, Assigned: myk)

References

Details

Attachments

(1 file, 3 obsolete files)

migrate XULStore to rkv
47 bytes, text/x-phabricator-request
Details | Review 
We should re-implement XULStore using rkv to improve its reliability, reduce its complexity, and potentially improve startup performance.
Attached patch XULStore on rkv proof-of-concept (obsolete) — — Splinter Review 
Priority: -- → P3

    
    

    
  


  
Assignee: nobody → myk

        Attachment #8975635 -
        Attachment is obsolete: true

    
    

    
  
Nika, I was reading through https://github.com/servo/servo/wiki/San-Francisco-Oxidation and noticed that you're concerned about lack of usage of the Rust XPCOM bindings that you recently introduced.

FWIW, the proof of concept in this bug uses them to retrieve the profile directory from the directory service <https://github.com/mykmelez/gecko/blob/a2f791d398c6b979fff011a059f668ca64827d8e/toolkit/components/xulstore/src/lib.rs#L76-L82>.

And a complete implementation might also implement nsIObserver (to update the directory on profile-after-change), as you demonstrate in xpcom/rust/gtest/xpcom/test.rs <https://searchfox.org/mozilla-central/rev/8384a6519437f5eefbe522196f9ddf5c8b1d3fb4/xpcom/rust/gtest/xpcom/test.rs#22-40>.

I also attempted to implement nsIStringEnumerator, although I ran into the limitation "Cannot #[derive(xpcom)] on a generic type" <https://github.com/mykmelez/gecko/blob/a2f791d398c6b979fff011a059f668ca64827d8e/toolkit/components/xulstore/src/lib.rs#L478-L523>.

Perhaps there are better ways to do these things, and we shouldn't be using the XPCOM bindings for them.  I'm relatively new to Rust, and I might be misusing it.  (Or overusing it.  Perhaps we shouldn't implement the XULStore API in Rust at all but rather in C++ that calls into the underlying Rust storage engine, so all code that interacts with XPCOM is in C++).

I just thought you should know that there are at least some potential consumers.  I'd also be happy to get feedback on whether you think this potential usage is a good use of those bindings.

    
  
Status: NEW → ASSIGNED

    
    

    
  

      
      
      
      

        Attached file
          
        migrate XULStore to rkv (obsolete)
        — 
      

    


  

    
  

        Attachment #8983254 -
        Attachment is obsolete: true

    
    

    
  


  
@bgrins This is a synchronous version of a XULStore API using rkv.  I've triggered tryserver builds for the base revision (central):


https://treeherder.mozilla.org/#/jobs?repo=try&revision=1000fdb9e613e4e779e88ccf494948dfd22a74a5


As well as the async version of the API:


https://treeherder.mozilla.org/#/jobs?repo=try&revision=7e68b3b31a18460f4b0f44e37434f26c26220b4f


And this synchronous version:


https://treeherder.mozilla.org/#/jobs?repo=try&revision=9e6a6d0fc0c0eba8522b6158e565f55712d1c3e5


I'll use their results to compare the two versions of the API.



    
    

    
  
(In reply to Myk Melez [:myk] [@mykmelez] from comment #5)




I'll use their results to compare the two versions of the API.




FYI, it generally takes 6 rebuilds on talos for perfherder to be give confident results. There may be other ways to get good data out of it, but what I typically do is use this syntax in all three configurations (base, sync version applied, async version applied):


./mach try fuzzy -q '/-talos-e10s' --rebuild 6


Then plug the revs into the originalRevision and newRevision GET params at: https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=&newProject=try&newRevision=&framework=1&showOnlyImportant=1



    
    

    
  
(In reply to Brian Grinstead [:bgrins] from comment #6)




(In reply to Myk Melez [:myk] [@mykmelez] from comment #5)




I'll use their results to compare the two versions of the API.




FYI, it generally takes 6 rebuilds on talos for perfherder to be give confident results. There may be other ways to get good data out of it, but what I typically do is use this syntax in all three configurations (base, sync version applied, async version applied):


./mach try fuzzy -q '/-talos-e10s' --rebuild 6


Then plug the revs into the originalRevision and newRevision GET params at: https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=&newProject=try&newRevision=&framework=1&showOnlyImportant=1




Hm, looking again at your pushes and it seems it did do the appropriate number of rebuilds, but I don't see any rebuilds specified in https://hg.mozilla.org/try/rev/7e68b3b31a18460f4b0f44e37434f26c26220b4f. Maybe you know something I don't, or try syntax got smarter and started automatically doing this for us? Anyway, disregard Comment 6 then.



    
    

    
  
(In reply to Brian Grinstead [:bgrins] from comment #6)




./mach try fuzzy -q '/-talos-e10s' --rebuild 6




Thanks, that's helpful!  I didn't know about the --rebuild flag.


(In reply to Brian Grinstead [:bgrins] from comment #7)




Hm, looking again at your pushes and it seems it did do the appropriate number of rebuilds, but I don't see any rebuilds specified in https://hg.mozilla.org/try/rev/7e68b3b31a18460f4b0f44e37434f26c26220b4f. Maybe you know something I don't, or try syntax got smarter and started automatically doing this for us?




I manually retriggered Talos jobs via the "Trigger all Talos jobs" item in one of the Treeherder menus, which prompts for the number of times to run each job (and defaults to 6).  That works reasonably well, but it'd be even easier to specify the number of rebuilds on the command line.  I'll do that next time!



        Attachment #9051203 -
        Attachment is obsolete: true

    
  
Component: General → Storage

        Attachment #9054406 -
        Attachment description: migrate XULStore to rkv with synchronous API → migrate XULStore to rkv

    
    

    
  
Pushed by myk@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2f8f0e53a7db
migrate XULStore to rkv r=bgrins,lina

    
    

    
  
Backed out for perma failures.


Push with failure: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&searchStr=windows%2C10%2Cx64%2Cdebug%2Cmochitests%2Ctest-windows10-64%2Fdebug-mochitest-a11y-e10s%2Cm%28a11y%29&revision=2f8f0e53a7dbb3f6d2259cfb0536a83ff84267ac&selectedJob=241258442


Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=241258442&repo=autoland&lineNumber=6176


21:15:17     INFO - nsTraceRefcnt::DumpStatistics: 2368 entries

21:15:17     INFO - TEST-INFO | leakcheck | default leaked 1 CondVar

21:15:17     INFO - TEST-INFO | leakcheck | default leaked 1 Mutex

21:15:17     INFO - TEST-INFO | leakcheck | default leaked 1 ThreadEventTarget

21:15:17     INFO - TEST-INFO | leakcheck | default leaked 1 ThreadTargetSink

21:15:17     INFO - TEST-INFO | leakcheck | default leaked 3 nsTArray_base

21:15:17     INFO - TEST-INFO | leakcheck | default leaked 1 nsThread

21:15:17     INFO - TEST-UNEXPECTED-FAIL | leakcheck | default 496 bytes leaked (CondVar, Mutex, ThreadEventTarget, ThreadTargetSink, nsTArray_base, ...)

21:15:17     INFO -

21:15:17     INFO - leakcheck | Processing leak log file c:\users\task_1555618748\appdata\local\temp\tmpv486cs.mozrunner\runtests_leaks_plugin_pid10324.log

21:15:17     INFO -

21:15:17     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, plugin process 10324

21:15:17     INFO -

21:15:17     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|

21:15:17     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|

21:15:17     INFO -    0 |TOTAL                                 |       68        0|    9357        0|

21:15:17     INFO -

21:15:17     INFO - nsTraceRefcnt::DumpStatistics: 95 entries

21:15:17     INFO - TEST-PASS | leakcheck | plugin no leaks detected!

21:15:17     INFO - leakcheck | Processing leak log file c:\users\task_1555618748\appdata\local\temp\tmpv486cs.mozrunner\runtests_leaks_plugin_pid5584.log

21:15:17     INFO -

21:15:17     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, plugin process 5584

21:15:17     INFO -

21:15:17     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|

21:15:17     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|

21:15:17     INFO -    0 |TOTAL                                 |       62        0|    1388        0|

21:15:17     INFO -

21:15:17     INFO - nsTraceRefcnt::DumpStatistics: 93 entries

21:15:17     INFO - TEST-PASS | leakcheck | plugin no leaks detected!

21:15:17     INFO - runtests.py | Running tests: end.

21:15:17     INFO - Buffered messages finished

21:15:17     INFO - SUITE-END | took 274s

21:15:17     INFO - Return code: 0

21:15:17    ERROR - Got 1 unexpected statuses

21:15:17     INFO - TinderboxPrint: mochitest-a11y<br/>713/<em class="testfail">1</em>/0

21:15:17  WARNING - # TBPL WARNING #

21:15:17  WARNING - setting return code to 1

21:15:17  WARNING - The mochitest suite: a11y ran with return status: WARNING

21:15:17     INFO - Running post-action listener: _package_coverage_data

21:15:17     INFO - Running post-action listener: _resource_record_post_action

21:15:17     INFO - Running post-action listener: process_java_coverage_data

21:15:17     INFO - [mozharness: 2019-04-18 21:15:17.546000Z] Finished run-tests step (success)

21:15:17     INFO - Running post-run listener: _resource_record_post_run

21:15:17     INFO - Validating Perfherder data against Z:\task_1555618748\mozharness\external_tools\performance-artifact-schema.json

21:15:17     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 12.628421052631571}, {"name": "io_write_bytes", "value": 394473472}, {"name": "io.read_bytes", "value": 33558528}, {"name": "io_write_time", "value": 8}, {"name": "io_read_time", "value": 1}], "extraOptions": ["e10s", "taskcluster-c5.2xlarge"], "name": "mochitest.a11y.a11y.overall"}, {"subtests": [{"name": "time", "value": 2.555999994277954}, {"name": "cpu_percent", "value": 26.6875}], "name": "mochitest.a11y.a11y.install"}, {"subtests": [{"name": "time", "value": 0.0}], "name": "mochitest.a11y.a11y.stage-files"}, {"subtests": [{"name": "time", "value": 284.59100008010864}, {"name": "cpu_percent", "value": 12.4720744680851}], "name": "mochitest.a11y.a11y.run-tests"}]}

21:15:17     INFO - Total resource usage - Wall time: 286s; CPU: 12.0%; Read bytes: 33558528; Write bytes: 394473472; Read time: 1; Write time: 8

21:15:17     INFO - TinderboxPrint: CPU usage<br/>12.5%

21:15:17     INFO - TinderboxPrint: I/O read bytes / time<br/>33,558,528 / 1

21:15:17     INFO - TinderboxPrint: I/O write bytes / time<br/>394,473,472 / 8

21:15:17     INFO - TinderboxPrint: CPU idle<br/>2,002.1 (87.4%)

21:15:17     INFO - TinderboxPrint: CPU system<br/>84.7 (3.7%)

21:15:17     INFO - TinderboxPrint: CPU user<br/>203.8 (8.9%)

21:15:17     INFO - install - Wall time: 3s; CPU: 27.0%; Read bytes: 0; Write bytes: 11583488; Read time: 0; Write time: 0

21:15:17     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0

21:15:17     INFO - run-tests - Wall time: 285s; CPU: 12.0%; Read bytes: 33419264; Write bytes: 372568064; Read time: 1; Write time: 6

21:15:17  WARNING - returning nonzero exit status 1

[taskcluster 2019-04-18T21:15:17.733Z]    Exit Code: 1

[taskcluster 2019-04-18T21:15:17.733Z]    User Time: 0s

[taskcluster 2019-04-18T21:15:17.733Z]  Kernel Time: 15.625ms

[taskcluster 2019-04-18T21:15:17.733Z]    Wall Time: 10m5.0306786s

[taskcluster 2019-04-18T21:15:17.733Z]       Result: FAILED

[taskcluster 2019-04-18T21:15:17.733Z] === Task Finished ===

[taskcluster 2019-04-18T21:15:17.733Z] Task Duration: 10m5.0306786s

[taskcluster 2019-04-18T21:15:18.474Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-04-17T19:59:59.505Z

[taskcluster 2019-04-18T21:15:19.463Z] Uploading artifact public/test_info/a11y_errorsummary.log from file build\blobber_upload_dir\a11y_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2020-04-17T19:59:59.505Z

[taskcluster 2019-04-18T21:15:19.966Z] Uploading artifact public/test_info/a11y_raw.log from file build\blobber_upload_dir\a11y_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2020-04-17T19:59:59.505Z

[taskcluster 2019-04-18T21:15:20.978Z] Uploading artifact public/test_info/manifests.list from file build\blobber_upload_dir\manifests.list with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-04-17T19:59:59.505Z

[taskcluster 2019-04-18T21:15:21.586Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-04-17T19:59:59.505Z

[taskcluster 2019-04-18T21:15:22.116Z] Uploading artifact public/test_info/system-info.log from file build\blobber_upload_dir\system-info.log with content encoding "gzip", mime type "text/plain" and expiry 2020-04-17T19:59:59.505Z

[taskcluster 2019-04-18T21:15:22.844Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/eQN-XfUxTvqDPbwZmyOP8A/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2020-04-17T19:59:59.505Z

[taskcluster:error] exit status 1


Backout: https://hg.mozilla.org/integration/autoland/rev/cf8038ca2da37288169690932880e737024d5afc


Flags: needinfo?(myk)

    
    

    
  
Pushed by myk@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/37054e6d6bbb
migrate XULStore to rkv r=bgrins,lina

    
    

    
  
The new implementation stores a static reference to a RefPtr<nsIThread>, which is what appeared to leak on shutdown.  I fixed the apparent regression by adding an xpcom-shutdown observer that clears the static.



    
  
Flags: needinfo?(myk)

    
    

    
  
Backed out for marionette failures


Backout: https://hg.mozilla.org/integration/autoland/rev/8d72d3ac9677942ff8342aa39c61b7e6692c75a1


Failure push: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=37054e6d6bbb0285f9db1e7f30def75ba9b6521b


Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=241492803&repo=autoland&lineNumber=1419


[task 2019-04-19T20:49:45.831Z] 20:49:45     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_cli_arguments.py TestCommandLineArguments.test_start_in_safe_mode

[task 2019-04-19T20:49:45.836Z] 20:49:45     INFO -  1555706985830	Marionette	DEBUG	Closed connection 9

[task 2019-04-19T20:49:45.837Z] 20:49:45     INFO -  1555706985833	Marionette	DEBUG	Accepted connection 10 from 127.0.0.1:52492

[task 2019-04-19T20:49:45.838Z] 20:49:45     INFO -  1555706985834	Marionette	DEBUG	10 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]

[task 2019-04-19T20:49:45.840Z] 20:49:45     INFO -  1555706985835	Marionette	TRACE	[2147483649] Frame script loaded

[task 2019-04-19T20:49:45.841Z] 20:49:45     INFO -  1555706985837	Marionette	TRACE	[2147483649] Frame script registered

[task 2019-04-19T20:49:45.845Z] 20:49:45     INFO -  1555706985841	Marionette	DEBUG	10 <- [1,1,null,{"sessionId":"e7c40d16-562c-4736-8e90-6b8a4a06b0ee","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... mp/tmpuM0l_I.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]

[task 2019-04-19T20:49:45.847Z] 20:49:45     INFO -  1555706985843	Marionette	DEBUG	10 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]

[task 2019-04-19T20:49:45.849Z] 20:49:45     INFO -  1555706985843	Marionette	DEBUG	10 <- [1,2,null,{"value":null}]

[task 2019-04-19T20:49:45.850Z] 20:49:45     INFO -  1555706985844	Marionette	DEBUG	10 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]

[task 2019-04-19T20:49:45.850Z] 20:49:45     INFO -  1555706985845	Marionette	DEBUG	10 <- [1,3,null,{"value":null}]

[task 2019-04-19T20:49:45.854Z] 20:49:45     INFO -  1555706985847	Marionette	DEBUG	10 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]

[task 2019-04-19T20:49:45.859Z] 20:49:45     INFO -  1555706985847	Marionette	DEBUG	10 <- [1,4,null,{"value":null}]

[task 2019-04-19T20:49:45.895Z] 20:49:45     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -safe-mode -profile /tmp/tmpuM0l_I.mozrunner

[task 2019-04-19T20:49:46.200Z] 20:49:46     INFO -  1555706986198	Marionette	TRACE	Received observer notification profile-after-change

[task 2019-04-19T20:49:46.268Z] 20:49:46     INFO -  1555706986266	Marionette	TRACE	Received observer notification command-line-startup

[task 2019-04-19T20:49:46.269Z] 20:49:46     INFO -  1555706986266	Marionette	TRACE	Received observer notification nsPref:changed

[task 2019-04-19T20:49:46.270Z] 20:49:46     INFO -  1555706986266	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)

[task 2019-04-19T20:49:46.328Z] 20:49:46     INFO -  1555706986320	Marionette	TRACE	Received observer notification domwindowopened

[task 2019-04-19T20:49:46.329Z] 20:49:46     INFO -  1555706986321	Marionette	TRACE	Received observer notification toplevel-window-ready

[task 2019-04-19T20:49:46.414Z] 20:49:46     INFO -  1555706986410	Marionette	TRACE	Safe mode detected, supressing dialog

[task 2019-04-19T20:49:47.470Z] 20:49:47     INFO -  1555706987466	Marionette	TRACE	Received observer notification toplevel-window-ready

[task 2019-04-19T20:49:48.341Z] 20:49:48     INFO -  ExceptionHandler::GenerateDump cloned child 1208

[task 2019-04-19T20:49:48.341Z] 20:49:48     INFO -  ExceptionHandler::SendContinueSignalToChild sent continue signal to child

[task 2019-04-19T20:49:48.341Z] 20:49:48     INFO -  ExceptionHandler::WaitForContinueSignal waiting for continue signal...

[task 2019-04-19T20:49:48.439Z] 20:49:48     INFO -  Exiting due to channel error.

[task 2019-04-19T20:49:48.510Z] 20:49:48     INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/FBYeHRoTR9SXacxXg4RVew/artifacts/public/build/target.crashreporter-symbols.zip

[task 2019-04-19T20:49:52.316Z] 20:49:52     INFO - mozcrash Copy/paste: /builds/worker/workspace/build/linux64-minidump_stackwalk /tmp/tmpuM0l_I.mozrunner/minidumps/2504c4e9-492c-5754-c252-670f7e6d1214.dmp /tmp/tmpBZ81ZR

[task 2019-04-19T20:49:57.617Z] 20:49:57     INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/2504c4e9-492c-5754-c252-670f7e6d1214.dmp

[task 2019-04-19T20:49:57.617Z] 20:49:57     INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/2504c4e9-492c-5754-c252-670f7e6d1214.extra

[task 2019-04-19T20:49:57.722Z] 20:49:57     INFO - PROCESS-CRASH | testing/marionette/harness/marionette_harness/tests/unit/test_cli_arguments.py TestCommandLineArguments.test_start_in_safe_mode | application crashed [@ GeckoCrash]

[task 2019-04-19T20:49:57.722Z] 20:49:57     INFO - Crash dump filename: /tmp/tmpuM0l_I.mozrunner/minidumps/2504c4e9-492c-5754-c252-670f7e6d1214.dmp

[task 2019-04-19T20:49:57.723Z] 20:49:57     INFO - Operating system: Linux

[task 2019-04-19T20:49:57.724Z] 20:49:57     INFO -                   0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64

[task 2019-04-19T20:49:57.725Z] 20:49:57     INFO - CPU: amd64

[task 2019-04-19T20:49:57.725Z] 20:49:57     INFO -      family 6 model 62 stepping 4

[task 2019-04-19T20:49:57.725Z] 20:49:57     INFO -      2 CPUs

[task 2019-04-19T20:49:57.725Z] 20:49:57     INFO -

[task 2019-04-19T20:49:57.726Z] 20:49:57     INFO - GPU: UNKNOWN

[task 2019-04-19T20:49:57.726Z] 20:49:57     INFO -

[task 2019-04-19T20:49:57.726Z] 20:49:57     INFO - Crash reason:  SIGSEGV /SEGV_MAPERR

[task 2019-04-19T20:49:57.726Z] 20:49:57     INFO - Crash address: 0x0

[task 2019-04-19T20:49:57.726Z] 20:49:57     INFO - Process uptime: not available

[task 2019-04-19T20:49:57.727Z] 20:49:57     INFO -

[task 2019-04-19T20:49:57.727Z] 20:49:57     INFO - Thread 42 (crashed)

[task 2019-04-19T20:49:57.727Z] 20:49:57     INFO -  0  libxul.so!GeckoCrash [nsAppRunner.cpp:37054e6d6bbb0285f9db1e7f30def75ba9b6521b : 5106 + 0xa]

[task 2019-04-19T20:49:57.727Z] 20:49:57     INFO -     rax = 0x0000557145c13920   rdx = 0x00007fb10e067e12

[task 2019-04-19T20:49:57.728Z] 20:49:57     INFO -     rcx = 0x0000000000010000   rbx = 0x000000000000002a

[task 2019-04-19T20:49:57.728Z] 20:49:57     INFO -     rsi = 0x0000000000000079   rdi = 0x00007fb10e06801a

[task 2019-04-19T20:49:57.728Z] 20:49:57     INFO -     rbp = 0x00007fb10e067e00   rsp = 0x00007fb10e067e00

[task 2019-04-19T20:49:57.728Z] 20:49:57     INFO -      r8 = 0x00007fb10e06820a    r9 = 0x0000000000000000

[task 2019-04-19T20:49:57.728Z] 20:49:57     INFO -     r10 = 0x0000000000000000   r11 = 0x00007fb12c0df150

[task 2019-04-19T20:49:57.729Z] 20:49:57     INFO -     r12 = 0x00007fb1214f9a70   r13 = 0x000000000000002a

[task 2019-04-19T20:49:57.729Z] 20:49:57     INFO -     r14 = 0x0000000000000079   r15 = 0x0000000000000000

[task 2019-04-19T20:49:57.729Z] 20:49:57     INFO -     rip = 0x00007fb11e050fae

[task 2019-04-19T20:49:57.729Z] 20:49:57     INFO -     Found by: given as instruction pointer in context

[task 2019-04-19T20:49:57.730Z] 20:49:57     INFO -  1  libxul.so!gkrust_shared::panic_hook [lib.rs:37054e6d6bbb0285f9db1e7f30def75ba9b6521b : 241 + 0x9]

[task 2019-04-19T20:49:57.730Z] 20:49:57     INFO -     rbx = 0x000000000000002a   rbp = 0x00007fb121434c5b

[task 2019-04-19T20:49:57.730Z] 20:49:57     INFO -     rsp = 0x00007fb10e067e10   r12 = 0x00007fb1214f9a70

[task 2019-04-19T20:49:57.731Z] 20:49:57     INFO -     r13 = 0x000000000000002a   r14 = 0x0000000000000079

[task 2019-04-19T20:49:57.731Z] 20:49:57     INFO -     r15 = 0x0000000000000000   rip = 0x00007fb11f9d526c

[task 2019-04-19T20:49:57.731Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.731Z] 20:49:57     INFO -  2  libxul.so!core::ops::function::Fn::call [function.rs:91856ed52c58aa5ba66a015354d1cc69e9779bdf : 69 + 0x9]

[task 2019-04-19T20:49:57.732Z] 20:49:57     INFO -     rbx = 0x0000000000000001   rbp = 0x00007fb1223b4860

[task 2019-04-19T20:49:57.732Z] 20:49:57     INFO -     rsp = 0x00007fb10e068240   r12 = 0x00007fb1214f9a70

[task 2019-04-19T20:49:57.732Z] 20:49:57     INFO -     r13 = 0x000000000000002a   r14 = 0x0000000000000005

[task 2019-04-19T20:49:57.732Z] 20:49:57     INFO -     r15 = 0x0000000000000000   rip = 0x00007fb11f9d5199

[task 2019-04-19T20:49:57.733Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.733Z] 20:49:57     INFO -  3  libxul.so!rust_panic_with_hook [panicking.rs:91856ed52c58aa5ba66a015354d1cc69e9779bdf : 482 + 0x6]

[task 2019-04-19T20:49:57.733Z] 20:49:57     INFO -     rbx = 0x0000000000000001   rbp = 0x00007fb1223b4860

[task 2019-04-19T20:49:57.734Z] 20:49:57     INFO -     rsp = 0x00007fb10e068250   r12 = 0x00007fb1214f9a70

[task 2019-04-19T20:49:57.734Z] 20:49:57     INFO -     r13 = 0x000000000000002a   r14 = 0x0000000000000005

[task 2019-04-19T20:49:57.734Z] 20:49:57     INFO -     r15 = 0x0000000000000000   rip = 0x00007fb1201ebfd9

[task 2019-04-19T20:49:57.735Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.736Z] 20:49:57     INFO -  4  libxul.so!std::panicking::begin_panic [panicking.rs:91856ed52c58aa5ba66a015354d1cc69e9779bdf : 412 + 0x1d]

[task 2019-04-19T20:49:57.737Z] 20:49:57     INFO -     rbx = 0x0000000000000000   rbp = 0x00007fb10e0684a0

[task 2019-04-19T20:49:57.737Z] 20:49:57     INFO -     rsp = 0x00007fb10e068360   r12 = 0x00007fb1224f7188

[task 2019-04-19T20:49:57.738Z] 20:49:57     INFO -     r13 = 0x00007fb1224f71b0   r14 = 0x00007fb1223c1e50

[task 2019-04-19T20:49:57.738Z] 20:49:57     INFO -     r15 = 0x00007fb10e068608   rip = 0x00007fb11fab47d4

[task 2019-04-19T20:49:57.739Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.740Z] 20:49:57     INFO -  5  libxul.so!std::sync::once::Once::call_once::{{closure}} [once.rs:91856ed52c58aa5ba66a015354d1cc69e9779bdf : 220 + 0x48b]

[task 2019-04-19T20:49:57.740Z] 20:49:57     INFO -     rbx = 0x0000000000000000   rbp = 0x00007fb10e0684a0

[task 2019-04-19T20:49:57.746Z] 20:49:57     INFO -     rsp = 0x00007fb10e068380   r12 = 0x00007fb1224f7188

[task 2019-04-19T20:49:57.746Z] 20:49:57     INFO -     r13 = 0x00007fb1224f71b0   r14 = 0x00007fb1223c1e50

[task 2019-04-19T20:49:57.747Z] 20:49:57     INFO -     r15 = 0x00007fb10e068608   rip = 0x00007fb11fab8ecb

[task 2019-04-19T20:49:57.747Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.747Z] 20:49:57     INFO -  6  libxul.so!call_inner [once.rs:91856ed52c58aa5ba66a015354d1cc69e9779bdf : 387 + 0x9]

[task 2019-04-19T20:49:57.747Z] 20:49:57     INFO -     rbx = 0x0000000000000000   rbp = 0x00007fb10e0684b2

[task 2019-04-19T20:49:57.747Z] 20:49:57     INFO -     rsp = 0x00007fb10e0684b0   r12 = 0x0000000000000002

[task 2019-04-19T20:49:57.747Z] 20:49:57     INFO -     r13 = 0x00007fb1224f71b0   r14 = 0x00007fb1223c1e50

[task 2019-04-19T20:49:57.748Z] 20:49:57     INFO -     r15 = 0x00007fb10e068608   rip = 0x00007fb1201f977a

[task 2019-04-19T20:49:57.748Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.748Z] 20:49:57     INFO -  7  libxul.so!xulstore::statics::get_database [statics.rs:37054e6d6bbb0285f9db1e7f30def75ba9b6521b : 45 + 0x234]

[task 2019-04-19T20:49:57.748Z] 20:49:57     INFO -     rbx = 0x00007fb10d272970   rbp = 0x00007fb10e0688b0

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     rsp = 0x00007fb10e068550   r12 = 0x00007fb10e068720

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     r13 = 0x00007fb1224f71f8   r14 = 0x0000000000000000

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     r15 = 0x0000000000000001   rip = 0x00007fb11fab42f7

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -  8  libxul.so!<xulstore::persist::PersistTask as moz_task::Task>::run [persist.rs:37054e6d6bbb0285f9db1e7f30def75ba9b6521b : 128 + 0xf6]

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     rbx = 0x00007fb10d272970   rbp = 0x00007fb10e0688b0

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     rsp = 0x00007fb10e0686a0   r12 = 0x00007fb10d3c2000

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     r13 = 0x00007fb1224f71f8   r14 = 0x0000000000000000

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     r15 = 0x0000000000000001   rip = 0x00007fb11fabc941

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -  9  libxul.so!moz_task::TaskRunnable::allocate::Run [lib.rs:37054e6d6bbb0285f9db1e7f30def75ba9b6521b : 82 + 0x31]

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     rbx = 0x00007fb10d08a8d0   rbp = 0x00007fb10e068d00

[task 2019-04-19T20:49:57.749Z] 20:49:57     INFO -     rsp = 0x00007fb10e0688c0   r12 = 0x00007fb10a37fdc0

[task 2019-04-19T20:49:57.750Z] 20:49:57     INFO -     r13 = 0x00000000ffffffff   r14 = 0x0000000000000001

[task 2019-04-19T20:49:57.750Z] 20:49:57     INFO -     r15 = 0x0000000000000001   rip = 0x00007fb11fe2a7a1

[task 2019-04-19T20:49:57.750Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.750Z] 20:49:57     INFO - 10  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:37054e6d6bbb0285f9db1e7f30def75ba9b6521b : 1180 + 0x6]

[task 2019-04-19T20:49:57.750Z] 20:49:57     INFO -     rbx = 0x0000000000000000   rbp = 0x00007fb10e068db0

[task 2019-04-19T20:49:57.750Z] 20:49:57     INFO -     rsp = 0x00007fb10e0688e0   r12 = 0x00007fb10a37fdc0

[task 2019-04-19T20:49:57.750Z] 20:49:57     INFO -     r13 = 0x00000000ffffffff   r14 = 0x0000000000000001

[task 2019-04-19T20:49:57.750Z] 20:49:57     INFO -     r15 = 0x0000000000000001   rip = 0x00007fb11e58948f

[task 2019-04-19T20:49:57.751Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.751Z] 20:49:57     INFO - 11  libxul.so!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:37054e6d6bbb0285f9db1e7f30def75ba9b6521b : 333 + 0x12]

[task 2019-04-19T20:49:57.751Z] 20:49:57     INFO -     rbx = 0x00007fb10a37fdc0   rbp = 0x00007fb10e068e00

[task 2019-04-19T20:49:57.751Z] 20:49:57     INFO -     rsp = 0x00007fb10e068dc0   r12 = 0x00007fb10ee4ebc0

[task 2019-04-19T20:49:57.751Z] 20:49:57     INFO -     r13 = 0x00007fb10a98fe80   r14 = 0x00007fb10a98fe80

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO -     r15 = 0x00007fb10a992000   rip = 0x00007fb11eb0e93d

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO - 12  libxul.so!nsThread::ThreadFunc(void*) [nsThread.cpp:37054e6d6bbb0285f9db1e7f30def75ba9b6521b : 454 + 0x4c]

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO -     rbx = 0x00007fb10d2729d0   rbp = 0x00007fb10e068ec0

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO -     rsp = 0x00007fb10e068e10   r12 = 0x00007fb10ee4ebc0

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO -     r13 = 0x00007fb10a992040   r14 = 0x00007fb10a37fdc0

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO -     r15 = 0x0000000000000001   rip = 0x00007fb11e970642

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO - 13  libnspr4.so!_pt_root [ptthread.c:37054e6d6bbb0285f9db1e7f30def75ba9b6521b : 201 + 0x8]

[task 2019-04-19T20:49:57.752Z] 20:49:57     INFO -     rbx = 0x0000000000000002   rbp = 0x00007fb10e068f10

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     rsp = 0x00007fb10e068ed0   r12 = 0x00007fb12bd589f8

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     r13 = 0x00007fb10a992040   r14 = 0x00007fb10e069700

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     r15 = 0x00007fb12bd14080   rip = 0x00007fb12d3c74a4

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO - 14  libpthread-2.23.so + 0x76ba

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     rbx = 0x0000000000000000   rbp = 0x0000000000000000

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     rsp = 0x00007fb10e068f20   r12 = 0x0000000000000000

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     r13 = 0x00007ffcf9dd752f   r14 = 0x0000000000040000

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     r15 = 0x00007fb10ec94e70   rip = 0x00007fb12cfc76ba

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     Found by: call frame info

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO - 15  libc-2.23.so + 0x10741d

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     rsp = 0x00007fb10e068fc0   rip = 0x00007fb12c05041d

[task 2019-04-19T20:49:57.760Z] 20:49:57     INFO -     Found by: stack scanning


Flags: needinfo?(myk)

    
    

    
  
I fixed the obvious issue that caused the test bustage and relanded.


Flags: needinfo?(myk)

    
    

    
  
Pushed by myk@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/76a363f06ebd
migrate XULStore to rkv r=bgrins,lina

    
    

    
  
https://hg.mozilla.org/mozilla-central/rev/76a363f06ebd


Status: ASSIGNED → RESOLVED
Closed: 5 years ago

          status-firefox68:
          --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla68

    
    

    
  
Is this expected to do more main thread I/O than the previous implementation? This is what I'm seeing in recent startup profiles: https://perfht.ml/2W3Ct2Z


Flags: needinfo?(myk)

    
    

    
  
(In reply to Florian Quèze [:florian] from comment #17)




Is this expected to do more main thread I/O than the previous implementation? This is what I'm seeing in recent startup profiles: https://perfht.ml/2W3Ct2Z




It isn't, so I've filed bug 1546838 to investigate the file I/O that shows up in that profile.


Flags: needinfo?(myk)

    
  
See Also:  → 1584160

          You need to log in
          before you can comment on or make changes to this bug.
        






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: