Closed Bug 1675543 Opened 4 years ago Closed 4 years ago

Performance::GetEntriesByName is slow

Categories

(Core :: Performance, defect)

defect

Tracking

()

RESOLVED FIXED
84 Branch
Performance Impact ?
Tracking Status
firefox84 --- fixed

People

(Reporter: smaug, Assigned: sefeng)

Details

Attachments

(3 files)

I've seen the method taking lots of time for example with Facebook.

https://share.firefox.dev/3l1fJwV

I wonder if we end up having too many entries in mResourceEntries or in mUserEntries
and then sorting becomes very slow
https://searchfox.org/mozilla-central/rev/c938c7416c633639a5c8ce4412be586eefb48005/dom/performance/Performance.cpp#177,206

But, at least there is a clear bug in
https://searchfox.org/mozilla-central/rev/c938c7416c633639a5c8ce4412be586eefb48005/dom/performance/PerformancePaintTiming.cpp#38 and
https://searchfox.org/mozilla-central/rev/c938c7416c633639a5c8ce4412be586eefb48005/dom/performance/PerformanceResourceTiming.cpp#43
We end up calculating timestamp tons of times when sorting. We surely should
use some cached timestamp.

My guess is that bug 1518999 made this bad on Facebook.

(I wonder if this needs to tracked for FF84.)

Whiteboard: [qf]
Flags: needinfo?(sefeng)

This seems to be about resource entries.

No longer regressed by: 1518999

Aha, mResourceTimingBufferSize=100000
I guess the web site has increased that number to so high.
But still, sorting shouldn't take much time.

Attached file testcase.html (deleted) —

Indeed, calculating the startTime every time slows down the sort.

The attached test file took about 120ms ~ 150ms for the GetEntriesByName call on my machine. With a patch that caches the startTime, it only takes ~7ms.

I'll get a patch up soon.

Flags: needinfo?(sefeng)
Assignee: nobody → sefeng

PerformanceResourceTiming recalculates the startTime every time when
StartTime() method is called, which slows down GetEntriesByName()
due to this method requires StartTime() to order the entries.

In addition to that, there's not need to recalculate it every time, since all
required timings are already set when the PerformanceTimingData
object is first created.

This patch calculates the startTime in the constructor and caches it.

Currently we store the raw StartTime as a TimeStamp object, and
convert it to DOMHighResTimeStamp when calling StartTime(). However,
there's no need to do the conversion every time.

Depends on D96295

FWIW, since I saw this again today, I tried to reproduce on Chrome, and yes, I got FB consuming basically 100% of a core.

That doesn't mean that Gecko's implementation shouldn't be optimized, comparison done during the sorting is implemented badly
(and perhaps some different data structure should be used to avoid need for any sorting?).

Pushed by sefeng@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/d98cf0c9d34e Cache PerformanceResourceTiming's StartTime r=smaug https://hg.mozilla.org/integration/autoland/rev/d7af96ca92b4 Cache PerformancePaintTiming's StartTime r=smaug

Backed out for marionette failures on test_refresh_firefox.py

backout: https://hg.mozilla.org/integration/autoland/rev/3fd9592e326d96fe5927843931ffd7829004b238

push: https://treeherder.mozilla.org/jobs?repo=autoland&revision=d7af96ca92b4533e81cc0ef24c27bd98676009f1&selectedTaskRun=DuUBA5JeTHeo2p61ZkfF7g.0

failure log: https://treeherder.mozilla.org/logviewer?job_id=321213513&repo=autoland&lineNumber=57305

[task 2020-11-09T17:47:44.349Z] 17:47:44 INFO - DEBUG: Completed blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
[task 2020-11-09T17:47:44.350Z] 17:47:44 INFO - DEBUG: Finished phase xpcom-will-shutdown
[task 2020-11-09T17:47:44.986Z] 17:47:44 INFO - _RegisterApplication(), FAILED TO establish the default connection to the WindowServer, _CGSDefaultConnection() is NULL.
[task 2020-11-09T17:47:54.301Z] 17:47:54 INFO - Child process with id "2177" has been marked as detached because it is no longer in the managed process group. Keeping reference to the process id "2181" which is the new child process.
[task 2020-11-09T17:47:54.539Z] 17:47:54 INFO - TEST-UNEXPECTED-ERROR | browser/components/migration/tests/marionette/test_refresh_firefox.py TestFirefoxRefresh.testFxANoSync | KeyError: 'keyFetchToken'
[task 2020-11-09T17:47:54.539Z] 17:47:54 INFO - Traceback (most recent call last):
[task 2020-11-09T17:47:54.539Z] 17:47:54 INFO - File "/Users/cltbld/tasks/task_1604938831/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 214, in run
[task 2020-11-09T17:47:54.539Z] 17:47:54 INFO - testMethod()
[task 2020-11-09T17:47:54.539Z] 17:47:54 INFO - File "/Users/cltbld/tasks/task_1604938831/build/tests/marionette/tests/browser/components/migration/tests/marionette/test_refresh_firefox.py", line 697, in testFxANoSync
[task 2020-11-09T17:47:54.539Z] 17:47:54 INFO - self.checkFxA()
[task 2020-11-09T17:47:54.540Z] 17:47:54 INFO - File "/Users/cltbld/tasks/task_1604938831/build/tests/marionette/tests/browser/components/migration/tests/marionette/test_refresh_firefox.py", line 488, in checkFxA
[task 2020-11-09T17:47:54.540Z] 17:47:54 INFO - self.assertEqual(result["accountData"]["keyFetchToken"], "top-secret")
[task 2020-11-09T17:47:54.540Z] 17:47:54 INFO - TEST-INFO took 10381ms

Flags: needinfo?(sefeng)
Pushed by sefeng@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/9ccec3c16e42 Cache PerformanceResourceTiming's StartTime r=smaug https://hg.mozilla.org/integration/autoland/rev/5bb6a35c2193 Cache PerformancePaintTiming's StartTime r=smaug

Olli, let me know if you hit this again.

Flags: needinfo?(sefeng)
Performance Impact: --- → ?
Whiteboard: [qf]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: