nsMemoryCacheDevice::mTotalSize can go negative after leaving private browsing

RESOLVED FIXED in mozilla15

Status

()

Core
Networking: Cache
RESOLVED FIXED
6 years ago
5 years ago

People

(Reporter: Bram Speeckaert, Assigned: michal)

Tracking

12 Branch
mozilla15
x86
Windows XP
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(2 attachments)

(Reporter)

Description

6 years ago
Created attachment 584034 [details]
about:memory?verbose output

I've been seeing negative heap-unclassified values after coming back from Private Browsing. I've attached my about:memory?verbose output taken right after disabling Private Browsing, displaying a heap-unclassified value of -4,264,738,013 B (-4168.44%).

The following steps usually trigger this bug:
1. Open Firefox and do some browsing.
2. Start Private Browsing and do some more browsing.
3. Exit Private Browsing and check about:memory.

I've managed to trigger this bug on Windows XP and Windows 7 64-bit using the latest Nightly 32-bit builds. Firefox 11 (currently in Aurora) probably also has this bug, since I first noticed it about a week ago (when Firefox 11 was still Nightly).
"heap-unclassified" is derived from all the other measurements.  Here's the real problem:

├──4,294,967,289 B (4197.99%) -- network-memory-cache

That is (2^32 - 7) bytes, and nsMemoryCacheDevice::TotalSize() returns a |size_t| which is 32 bits on Windows builds, so it's almost certainly trying to return -7 for some reason.

And TotalSize() uses a counter to record the memory size, so something has gone wrong (as it often does) with the maintenance of that counter.
Summary: Negative heap-unclassified after Private Browsing → Ridiculously high "network-memory-cache" measurement after Private Browsing
Blocks: 716323

Comment 2

6 years ago
This issue is reproducible every time for me - I see 4,294,967,274 B for network-memory-cache after going into Private Browsing and back. Only reason I'm not confirming this bug: it's most likely in the wrong component and I'm not sure which would be the correct one. Core / Networking: Cache?
Component: Private Browsing → Networking: Cache
Product: Firefox → Core
QA Contact: private.browsing → networking.cache

Updated

6 years ago
Status: UNCONFIRMED → NEW
Ever confirmed: true
Whiteboard: [MemShrink]
Whiteboard: [MemShrink] → [MemShrink:P2]
I assume this bug is that we're reporting absurdly high RAM use, rather than actually using it.  Either way we should fix, of course...
(In reply to Jason Duell (:jduell) from comment #3)
> I assume this bug is that we're reporting absurdly high RAM use, rather than
> actually using it.

Correct; see comment 1.
My preferred option is to convert this memory reporter from a "counter-based" one to a "traversal-based" one.  (See https://wiki.mozilla.org/Memory_Reporting#Two_Ways_to_Measure for details.)  I haven't looked at the code to determine how easy this is.
(In reply to Nicholas Nethercote [:njn] from comment #5)
> My preferred option is to convert this memory reporter from a
> "counter-based" one to a "traversal-based" one.

I filed 736919 for this.

I'm morphing this bug to be about the negative nsMemoryCacheDevice::TotalSize(), i.e. it's now completely unrelated to memory reporting.  FWIW, I was unable to reproduce the symptoms reported after using private browsing.
Whiteboard: [MemShrink:P2]
Summary: Ridiculously high "network-memory-cache" measurement after Private Browsing → nsMemoryCacheDevice::mTotalSize can go negative after leaving private browsing

Comment 7

6 years ago
I cannot reproduce this either using the current nightly (14.0a1 20120318), network-memory-cache is being reported with 0 bytes.
(Assignee)

Comment 8

6 years ago
I was able to reproduce it, so I'll have a look at it.
Assignee: nobody → michal.novotny
Could the missing lock mentioned in bug 736919 comment 2 be the cause?
(Reporter)

Comment 10

6 years ago
Just managed to trigger the bug again in the latest Nightly:

184,062,209 B (100.0%) -- explicit
├──4,294,967,173 B (2333.43%) ── network-memory-cache [?!]
├──100,833,228 B (54.78%) ++ js
├───38,088,296 B (20.69%) ++ storage
├────7,401,968 B (04.02%) ++ window-objects
├────7,400,234 B (04.02%) ── spell-check
├────1,145,888 B (00.62%) ── atom-table
├──────968,736 B (00.53%) ── xpti-working-set
├──────822,661 B (00.45%) ++ startup-cache
├──────727,868 B (00.40%) ++ images
├──────216,408 B (00.12%) ++ layout
├───────36,964 B (00.02%) ── cycle-collector
├───────16,160 B (00.01%) ── history-links-hashtable
└──-4,268,563,375 B (-2319.09%) ── heap-unclassified [?!]
Using the patch from bug 709326 comment 13 and changing...

> window.setTimeout(sendHeapMinNotificationsInner, 1000);
to
> window.setTimeout(sendHeapMinNotificationsInner, 0);

...seems to trigger this bug on occasion using the steps from bug 709326 comment 14.
Duplicate of this bug: 747646
(Assignee)

Comment 13

5 years ago
Created attachment 617485 [details] [diff] [review]
fix

We count both metadata size as well as data size into the total size of memory cache. But we do track changes only of data size, so the total size goes wrong when metadata is changed after the entry is bound to the memory device. This happens very rarely, so far I was able to reproduce it only in case when the server's response doesn't contain Content-type header. Testcase is at http://michal.etc.cz/bug713203/test.html and the backtrace of the problematic metadata change is below.

To be able to track the changes of metadata size we would need to create a new method nsCacheDevice::OnMetaDataSizeChange() which would be used only by memory device (disk device counts the usage in a different way). Also in contrary to nsCacheDevice::OnDataSizeChange() we don't know the difference of size in advance and therefore we couldn't refuse to set the metadata when the total size would exceed the limit. So the easiest way to fix this is to count only the data size, which I think is acceptable.


(gdb) bt
#0  nsCacheEntry::SetMetaDataElement (this=0xe9286040, key=0x32e3a9f "charset", value=0xf3485c48 "ISO-8859-1") at /opt/moz/hg/netwerk/cache/nsCacheEntry.h:121
#1  0x012e2c91 in nsCacheEntryDescriptor::SetMetaDataElement (this=0xe92a1980, key=0x32e3a9f "charset", value=0xf3485c48 "ISO-8859-1")
    at /opt/moz/hg/netwerk/cache/nsCacheEntryDescriptor.cpp:538
#2  0x0136bf28 in nsHttpChannel::SetCacheTokenCachedCharset (this=0xe9273800, aCharset=...) at /opt/moz/hg/netwerk/protocol/http/nsHttpChannel.cpp:4586
#3  0x01b08d27 in nsHTMLDocument::StartDocumentLoad (this=0xecb0d400, aCommand=0x3645665 "view", aChannel=0xe9273834, aLoadGroup=0xe9257900, aContainer=
    0xe92780c0, aDocListener=0xe92b4980, aReset=true, aSink=0x0) at /opt/moz/hg/content/html/document/src/nsHTMLDocument.cpp:841
#4  0x014ceb99 in nsContentDLF::CreateDocument (this=0xf3465ef0, aCommand=0x3645665 "view", aChannel=0xe9273834, aLoadGroup=0xe9257900, aContainer=0xe92780c0, 
    aDocumentCID=..., aDocListener=0xe92b4980, aContentViewer=0xffce15b8) at /opt/moz/hg/layout/build/nsContentDLF.cpp:461
#5  0x014cdf8b in nsContentDLF::CreateInstance (this=0xf3465ef0, aCommand=0x3645665 "view", aChannel=0xe9273834, aLoadGroup=0xe9257900, aContentType=
    0xe92bf148 "text/html", aContainer=0xe92780c0, aExtraInfo=0x0, aDocListener=0xe92b4980, aDocViewer=0xffce15b8)
    at /opt/moz/hg/layout/build/nsContentDLF.cpp:252
#6  0x0228d93c in nsDocShell::NewContentViewerObj(char const*, nsIRequest*, nsILoadGroup*, nsIStreamListener**, nsIContentViewer**) ()
   from /opt/moz/hg/_obj-browser-release-tb-fp-dbg/dist/bin/libxul.so
#7  0x0228ce83 in nsDocShell::CreateContentViewer(char const*, nsIRequest*, nsIStreamListener**) ()
   from /opt/moz/hg/_obj-browser-release-tb-fp-dbg/dist/bin/libxul.so
#8  0x022a713a in nsDSURIContentListener::DoContent (this=0xe9cf85b0, aContentType=0xe92bf148 "text/html", aIsContentPreferred=false, request=0xe9273834, 
    aContentHandler=0xe92b4980, aAbortProcess=0xffce16c7) at /opt/moz/hg/docshell/base/nsDSURIContentListener.cpp:164
#9  0x022aed31 in nsDocumentOpenInfo::TryContentListener (this=0xe92b4970, aListener=0xe9cf85b0, aChannel=0xe9273834)
    at /opt/moz/hg/uriloader/base/nsURILoader.cpp:709
#10 0x022adba8 in nsDocumentOpenInfo::DispatchContent (this=0xe92b4970, request=0xe9273834, aCtxt=0x0) at /opt/moz/hg/uriloader/base/nsURILoader.cpp:406
#11 0x022ad58f in nsDocumentOpenInfo::OnStartRequest (this=0xe92b4970, request=0xe9273834, aCtxt=0x0) at /opt/moz/hg/uriloader/base/nsURILoader.cpp:294
#12 0x012c5938 in nsUnknownDecoder::FireListenerNotifications (this=0xe92d1b80, request=0xe9273834, aCtxt=0x0)
    at /opt/moz/hg/netwerk/streamconv/converters/nsUnknownDecoder.cpp:629
#13 0x012c3be7 in nsUnknownDecoder::OnDataAvailable (this=0xe92d1b80, request=0xe9273834, aCtxt=0x0, aStream=0xe92d1c40, aSourceOffset=512, aCount=641)
    at /opt/moz/hg/netwerk/streamconv/converters/nsUnknownDecoder.cpp:185
#14 0x0129fbd7 in nsStreamListenerTee::OnDataAvailable (this=0xe92b9d20, request=0xe9273834, context=0x0, input=0xe92cfa0c, offset=0, count=1153)
    at /opt/moz/hg/netwerk/base/src/nsStreamListenerTee.cpp:122
#15 0x0136b887 in nsHttpChannel::OnDataAvailable (this=0xe9273800, request=0xe9260dc0, ctxt=0x0, input=0xe92cfa0c, offset=0, count=1153)
    at /opt/moz/hg/netwerk/protocol/http/nsHttpChannel.cpp:4478
#16 0x01268915 in nsInputStreamPump::OnStateTransfer (this=0xe9260dc0) at /opt/moz/hg/netwerk/base/src/nsInputStreamPump.cpp:514
#17 0x0126841b in nsInputStreamPump::OnInputStreamReady (this=0xe9260dc0, stream=0xe92cfa0c) at /opt/moz/hg/netwerk/base/src/nsInputStreamPump.cpp:402
#18 0x029320ba in nsInputStreamReadyEvent::Run (this=0xe92879c0) at /opt/moz/hg/xpcom/io/nsStreamUtils.cpp:114
#19 0x029523a8 in nsThread::ProcessNextEvent (this=0xf74ac100, mayWait=true, result=0xffce1c6f) at /opt/moz/hg/xpcom/threads/nsThread.cpp:657
#20 0x028eaa07 in NS_ProcessNextEvent_P (thread=0xf74ac100, mayWait=true) at /opt/moz/hg/_obj-browser-release-tb-fp-dbg/xpcom/build/nsThreadUtils.cpp:245
#21 0x02774caa in mozilla::ipc::MessagePump::Run (this=0xf74c5dc0, aDelegate=0xf741c420) at /opt/moz/hg/ipc/glue/MessagePump.cpp:134
#22 0x029b339e in MessageLoop::RunInternal (this=0xf741c420) at /opt/moz/hg/ipc/chromium/src/base/message_loop.cc:208
#23 0x029b3329 in MessageLoop::RunHandler (this=0xf741c420) at /opt/moz/hg/ipc/chromium/src/base/message_loop.cc:201
#24 0x029b32cd in MessageLoop::Run (this=0xf741c420) at /opt/moz/hg/ipc/chromium/src/base/message_loop.cc:175
#25 0x0261527b in nsBaseAppShell::Run (this=0xf5e50740) at /opt/moz/hg/widget/xpwidgets/nsBaseAppShell.cpp:189
#26 0x0235f476 in nsAppStartup::Run (this=0xf5ece220) at /opt/moz/hg/toolkit/components/startup/nsAppStartup.cpp:295
#27 0x01214af1 in XRE_main (argc=3, argv=0xffce4564, aAppData=0x8063b00) at /opt/moz/hg/toolkit/xre/nsAppRunner.cpp:3703
#28 0x08049ad9 in do_main (argc=3, argv=0xffce4564) at /opt/moz/hg/browser/app/nsBrowserApp.cpp:190
#29 0x08049cf6 in main (argc=3, argv=0xffce4564) at /opt/moz/hg/browser/app/nsBrowserApp.cpp:277
Attachment #617485 - Flags: review?(jduell.mcbugs)
Comment on attachment 617485 [details] [diff] [review]
fix

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

Michal:  how big is the metadata per entry?
(Assignee)

Comment 15

5 years ago
I've collected a sample data and 4845 entries consist of 63430598 bytes of data and 1629168 bytes of metadata. So in my case metadata is 2.5% of the total size.
Comment on attachment 617485 [details] [diff] [review]
fix

OK, then it sounds like we can live w/o counting metadata in the total.
Attachment #617485 - Flags: review?(jduell.mcbugs) → review+
(Assignee)

Comment 17

5 years ago
http://hg.mozilla.org/integration/mozilla-inbound/rev/6a9fa2a964fa
Next time please remember the "r=jduell" in the commit message :)
https://hg.mozilla.org/mozilla-central/rev/6a9fa2a964fa
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla15
You need to log in before you can comment on or make changes to this bug.