Closed Bug 1491037 Opened 6 years ago Closed 6 years ago

2.73 - 8.8% Heap Unclassified (linux64, linux64-stylo-sequential, osx-10-10, windows10-64, windows7-32) regression on push 43a95f0f47256ac54ce6bb2044216de7a9406574 (Tue Sep 11 2018)

Categories

(Core :: JavaScript Engine, defect)

Product:
Core
Component:
JavaScript Engine
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
VERIFIED FIXED
Milestone:
mozilla64
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox62 --- unaffected
firefox63 --- unaffected
firefox64 --- fixed

People

(Reporter: jmaher, Assigned: jonco)

References

Details

(Keywords: perf, regression)

Attachments

(2 files)

bug1490055-free-helper-lifo
5.26 KB, patch
nbp
: review+
Details | Diff | Splinter Review
bug1491037-report-helper-context
8.33 KB, patch
nbp
: review+
Details | Diff | Splinter Review 
We have detected an awsy regression from push:

https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?changeset=43a95f0f47256ac54ce6bb2044216de7a9406574

As author of one of the patches included in that push, we need your help to address this regression.

Regressions:

  9%  Heap Unclassified windows10-64 opt stylo                            36,892,554.12 -> 40,140,708.21
  9%  Heap Unclassified windows10-64 pgo stylo                            36,865,815.53 -> 40,004,513.82
  7%  Heap Unclassified windows7-32 pgo stylo                             28,986,104.53 -> 31,015,126.35
  7%  Heap Unclassified windows7-32 opt stylo                             29,098,938.99 -> 31,051,457.64
  3%  Heap Unclassified osx-10-10 opt stylo                               66,237,545.71 -> 68,440,557.46
  3%  Heap Unclassified linux64-stylo-sequential opt stylo-sequential     60,132,963.51 -> 62,078,396.85
  3%  Heap Unclassified linux64 opt stylo                                 60,987,423.01 -> 62,650,406.41


You can find links to graphs and comparison views for each of the above tests at: https://treeherder.mozilla.org/perf.html#/alerts?id=15801

On the page above you can see an alert for each affected platform as well as a link to a graph showing the history of scores for this test. There is also a link to a treeherder page showing the jobs in a pushlog format.

To learn more about the regressing test(s), please see: https://wiki.mozilla.org/AWSY/Tests
:jonco, I see you authored the patches in bug 1490055, can you take a look at these regressions and determine if we can do anything to fix this?
Component: General → JavaScript Engine
Flags: needinfo?(jcoppeard)
Product: Testing → Core
Bug 1490055 made us use the JSContext's LifoAlloc for helper threads rather than a temporary LifoAlloc that was created and destroyed per parse task.  There's two issues here: firstly, the size of these may build up over time since they are never freed, and secondly JSContext memory is not reported.
Assignee: nobody → jcoppeard
Flags: needinfo?(jcoppeard)
Patch to free helper thread LifoAlloc memory when the main thread runtime does a GC.
Attachment #9009159 - Flags: review?(nicolas.b.pierron)
I'm not sure about this patch.

This moves the JSContext to be part of the HelperThread class so we can report memory use for for it, but only for idle helper threads.  It's not safe to do this for active threads.

What do you think, is this better it to report memory where we can or to be consistent and never report this memory for helper threads?
Attachment #9009163 - Flags: review?(nicolas.b.pierron)
Comment on attachment 9009159 [details] [diff] [review]
bug1490055-free-helper-lifo

Review of attachment 9009159 [details] [diff] [review]:
-----------------------------------------------------------------

::: js/src/vm/HelperThreads.cpp
@@ +2577,5 @@
>              // block occurs.
>              mozilla::recordreplay::NotifyUnrecordedWait(WakeupAll);
>          }
>  
> +        maybeFreeUnusedMemory(&cx);

nit: As there is no guarantee on how the LifoAlloc are going to be used. Iterating over multiple task might leave unused memory in allocated chunks. "freeAll()" will deallocate everything, still think we should ensure that at the end of any task, all the LifoAlloc space is reclaimed by calling "cx->tempLifoAlloc().releaseAll();"
Attachment #9009159 - Flags: review?(nicolas.b.pierron) → review+
Comment on attachment 9009163 [details] [diff] [review]
bug1491037-report-helper-context

Review of attachment 9009163 [details] [diff] [review]:
-----------------------------------------------------------------

This patch looks good to me.
Attachment #9009163 - Flags: review?(nicolas.b.pierron) → review+
:jonco, is there more work to do in order to land this patch?
Flags: needinfo?(jcoppeard)
Pushed by jcoppeard@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/9a1cfe1a7bee
Periodically free helper thread LifoAlloc memory r=nbp
https://hg.mozilla.org/integration/mozilla-inbound/rev/a1502c0643fc
Report JSContext memory for idle helper threads r=nbp
Flags: needinfo?(jcoppeard)
Note that bug 1491395 was inadvertently backed out for these failures, so I did a try push with some logging around those test failures. Posting them here [1] in case they're useful.

[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=9e822258aa61d864da8886e1731b9cb78a5d3dd3
There is also the clipboard failure: https://treeherder.mozilla.org/logviewer.html#?job_id=200057123&repo=mozilla-inbound&lineNumber=2333

00:21:12     INFO - TEST-OK | toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | took 2319ms
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file z:/build/build/src/xpcom/threads/nsThread.cpp, line 866
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file z:/build/build/src/xpcom/threads/nsThread.cpp, line 866
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file z:/build/build/src/xpcom/threads/nsThread.cpp, line 866
00:21:12     INFO - GECKO(8156) | [Parent 8156, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:21:12     INFO - GECKO(8156) | [Parent 8156, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x80004005: file z:/build/build/src/docshell/shistory/nsSHistory.cpp, line 1291
00:21:12     INFO - GECKO(8156) | [Parent 8156, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x80004005: file z:/build/build/src/docshell/shistory/nsSHistory.cpp, line 1291
00:21:12     INFO - GECKO(8156) | ++DOMWINDOW == 63 (0000025DAC676C00) [pid = 8156] [serial = 63] [outer = 0000025DBB41D800]
00:21:12     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | assertion count 6 is more than expected 0 assertions
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!gThread', file z:/build/build/src/xpcom/threads/nsTimerImpl.cpp, line 399
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!gThread', file z:/build/build/src/xpcom/threads/nsTimerImpl.cpp, line 399
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!gThread', file z:/build/build/src/xpcom/threads/nsTimerImpl.cpp, line 399
00:21:12     INFO - TEST-START | Shutdown
00:21:12     INFO - Passed:  24
00:21:12     INFO - Failed:  0
00:21:12     INFO - Todo:    0
00:21:12     INFO - Mode:    non-e10s
00:21:12     INFO - Slowest: 2318ms - chrome://mochitests/content/chrome/toolkit/components/aboutmemory/tests/test_aboutmemory5.xul
00:21:12     INFO - SimpleTest FINISHED
00:21:12     INFO - TEST-INFO | Ran 1 Loops
00:21:12     INFO - SimpleTest FINISHED
00:21:12     INFO - GECKO(8156) | --DOCSHELL 0000027604D46800 == 0 [pid = 4564] [id = {6bfd6f9f-add9-45a4-9edc-b84f238376f7}]
00:21:12     INFO - GECKO(8156) | --DOMWINDOW == 2 (0000027604D13800) [pid = 4564] [serial = 1] [outer = 0000000000000000] [url = about:blank]
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 4564, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | --DOMWINDOW == 1 (000002760C87EC00) [pid = 4564] [serial = 3] [outer = 0000000000000000] [url = about:blank]
00:21:12     INFO - GECKO(8156) | --DOMWINDOW == 0 (000002760A497C00) [pid = 4564] [serial = 2] [outer = 0000000000000000] [url = about:blank]
00:21:12     INFO - GECKO(8156) | --DOMWINDOW == 2 (00000230AD677400) [pid = 2992] [serial = 3] [outer = 0000000000000000] [url = about:blank]
00:21:12     INFO - GECKO(8156) | --DOCSHELL 00000230A5E46800 == 0 [pid = 2992] [id = {16207fb0-b0b2-4179-b4ea-a826528d356c}]
00:21:12     INFO - GECKO(8156) | --DOMWINDOW == 1 (00000230A5E13A00) [pid = 2992] [serial = 1] [outer = 0000000000000000] [url = about:blank]
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 2992, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | --DOMWINDOW == 0 (00000230AB498C00) [pid = 2992] [serial = 2] [outer = 0000000000000000] [url = about:blank]
00:21:12     INFO - GECKO(8156) | --DOCSHELL 0000028926D47800 == 0 [pid = 6552] [id = {ae4b085d-dec9-4f99-acfc-a76ab1496bad}]
00:21:12     INFO - GECKO(8156) | --DOMWINDOW == 2 (0000028926D14A00) [pid = 6552] [serial = 1] [outer = 0000000000000000] [url = about:blank]
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | [Child 6552, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 564
00:21:12     INFO - GECKO(8156) | --DOMWINDOW == 1 (000002892E67FC00) [pid = 6552] [serial = 3] [outer = 0000000000000000] [url = about:blank]
00:21:12     INFO - GECKO(8156) | --DOMWINDOW == 0 (000002892C49CC00) [pid = 6552] [serial = 2] [outer = 0000000000000000] [url = about:blank]
00:21:12     INFO - GECKO(8156) | nsStringStats
00:21:12     INFO - GECKO(8156) |  => mAllocCount:           6968
00:21:12     INFO - GECKO(8156) |  => mReallocCount:            0
00:21:12     INFO - GECKO(8156) |  => mFreeCount:            6968
00:21:12     INFO - GECKO(8156) |  => mShareCount:           4717
00:21:12     INFO - GECKO(8156) |  => mAdoptCount:            497
00:21:12     INFO - GECKO(8156) |  => mAdoptFreeCount:        497
00:21:12     INFO - GECKO(8156) |  => Process ID: 2992, Thread ID: 1160
00:21:12     INFO - GECKO(8156) | nsStringStats
00:21:12     INFO - GECKO(8156) |  => mAllocCount:           7044
00:21:12     INFO - GECKO(8156) |  => mReallocCount:            0
00:21:12     INFO - GECKO(8156) |  => mFreeCount:            7044
00:21:12     INFO - GECKO(8156) |  => mShareCount:           4751
00:21:12     INFO - GECKO(8156) |  => mAdoptCount:            497
00:21:12     INFO - GECKO(8156) |  => mAdoptFreeCount:        497
00:21:12     INFO - GECKO(8156) |  => Process ID: 4564, Thread ID: 3172
00:21:12     INFO - GECKO(8156) | nsStringStats
00:21:12     INFO - GECKO(8156) |  => mAllocCount:           7006
00:21:12     INFO - GECKO(8156) |  => mReallocCount:            0
00:21:12     INFO - GECKO(8156) |  => mFreeCount:            7006
00:21:12     INFO - GECKO(8156) |  => mShareCount:           4734
00:21:12     INFO - GECKO(8156) |  => mAdoptCount:            497
00:21:12     INFO - GECKO(8156) |  => mAdoptFreeCount:        497
00:21:12     INFO - GECKO(8156) |  => Process ID: 6552, Thread ID: 3644
00:21:12     INFO - GECKO(8156) | ++DOMWINDOW == 64 (0000025DB2FEF000) [pid = 8156] [serial = 64] [outer = 0000025DBB41D800]
00:21:12     INFO - GECKO(8156) | JavaScript error: resource://activity-stream/lib/TopSitesFeed.jsm, line 86: TypeError: setting getter-only property "_currentSearchHostname"
It's failing a sanity assertion that heap-unclassified is > 0 [1]. This implies that the 'explicit/' heap allocated values total more than what was actually heap-allocated. 

[1] https://searchfox.org/mozilla-central/rev/a0333927deabfe980094a14d0549b589f34cbe49/testing/awsy/awsy/parse_about_memory.py#65-67
it looks like bug 1491395 was relanded- when this was landed we had AWSY improvements, and when this was backed out we had regressions- there is still work to do on this bug.
:jonco, is this something you are still working on?
(In reply to Eric Rahm [:erahm] from comment #12)
Thanks for the explanation.  I still don't understand why this is happening though.

I'm going to reland the first patch only and hope that that is enough to fix the regression.
Flags: needinfo?(jcoppeard)
Pushed by jcoppeard@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/7a9384b6a6c9
Periodically free helper thread LifoAlloc memory r=nbp
Setting leave-open until we know whether this worked.
Keywords: leave-open
It looks like the regressions got fixed on all OS platforms. I think we can close this bug as FIXED. Thank you!
This is the new baseline:

== Change summary for alert #16079 (as of Fri, 21 Sep 2018 06:26:25 GMT) ==

Improvements:

  9%  Heap Unclassified windows7-32 pgo stylo                             31,301,884.90 -> 28,571,600.80
  9%  Heap Unclassified windows10-64 opt stylo                            40,516,117.84 -> 37,044,964.57
  8%  Heap Unclassified windows10-64 pgo stylo                            40,499,502.85 -> 37,236,824.55
  8%  Heap Unclassified windows7-32 opt stylo                             31,337,345.55 -> 28,950,840.16
  4%  Resident Memory linux64-qr opt stylo                                1,066,178,465.47 -> 1,020,714,382.72
  3%  Heap Unclassified linux64-stylo-sequential opt stylo-sequential     61,935,330.26 -> 59,836,683.77
  3%  Heap Unclassified linux64 opt stylo                                 62,484,800.96 -> 60,637,899.23
  3%  Heap Unclassified osx-10-10 opt stylo                               68,532,303.37 -> 66,666,514.50

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=16079
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
status-firefox62: --- → unaffected
status-firefox63: --- → unaffected
status-firefox64: --- → fixed
status-firefox-esr60: --- → unaffected
Target Milestone: --- → mozilla64
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: