Last Comment Bug 713203 - nsMemoryCacheDevice::mTotalSize can go negative after leaving private browsing
: nsMemoryCacheDevice::mTotalSize can go negative after leaving private browsing
Product: Core
Classification: Components
Component: Networking: Cache (show other bugs)
: 12 Branch
: x86 Windows XP
-- normal (vote)
: mozilla15
Assigned To: Michal Novotny (:michal)
: Patrick McManus [:mcmanus]
: 747646 (view as bug list)
Depends on:
Blocks: 716323
  Show dependency treegraph
Reported: 2011-12-23 04:10 PST by Bram Speeckaert
Modified: 2012-04-25 07:26 PDT (History)
11 users (show)
See Also:
Crash Signature:
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---

about:memory?verbose output (23.41 KB, text/plain)
2011-12-23 04:10 PST, Bram Speeckaert
no flags Details
fix (4.65 KB, patch)
2012-04-23 08:28 PDT, Michal Novotny (:michal)
jduell.mcbugs: review+
Details | Diff | Splinter Review

Description User image Bram Speeckaert 2011-12-23 04:10:11 PST
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).
Comment 1 User image Nicholas Nethercote [:njn] 2011-12-23 04:35:34 PST
"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.
Comment 2 User image Wladimir Palant 2012-02-03 00:08:28 PST
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?
Comment 3 User image Jason Duell [:jduell] (needinfo me) 2012-02-14 14:36:30 PST
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...
Comment 4 User image Justin Lebar (not reading bugmail) 2012-02-14 15:03:24 PST
(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.
Comment 5 User image Nicholas Nethercote [:njn] 2012-02-14 16:42:35 PST
My preferred option is to convert this memory reporter from a "counter-based" one to a "traversal-based" one.  (See for details.)  I haven't looked at the code to determine how easy this is.
Comment 6 User image Nicholas Nethercote [:njn] 2012-03-18 20:05:10 PDT
(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.
Comment 7 User image Wladimir Palant 2012-03-19 00:13:12 PDT
I cannot reproduce this either using the current nightly (14.0a1 20120318), network-memory-cache is being reported with 0 bytes.
Comment 8 User image Michal Novotny (:michal) 2012-03-20 08:00:35 PDT
I was able to reproduce it, so I'll have a look at it.
Comment 9 User image Nicholas Nethercote [:njn] 2012-03-20 16:45:38 PDT
Could the missing lock mentioned in bug 736919 comment 2 be the cause?
Comment 10 User image Bram Speeckaert 2012-03-24 17:30:23 PDT
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 [?!]
Comment 11 User image Anthony Hughes (:ashughes) [GFX][QA][Mentor] 2012-04-12 09:14:09 PDT
Using the patch from bug 709326 comment 13 and changing...

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

...seems to trigger this bug on occasion using the steps from bug 709326 comment 14.
Comment 12 User image Nicholas Nethercote [:njn] 2012-04-21 20:11:35 PDT
*** Bug 747646 has been marked as a duplicate of this bug. ***
Comment 13 User image Michal Novotny (:michal) 2012-04-23 08:28:14 PDT
Created attachment 617485 [details] [diff] [review]

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 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/
#7  0x0228ce83 in nsDocShell::CreateContentViewer(char const*, nsIRequest*, nsIStreamListener**) ()
   from /opt/moz/hg/_obj-browser-release-tb-fp-dbg/dist/bin/
#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/
#23 0x029b3329 in MessageLoop::RunHandler (this=0xf741c420) at /opt/moz/hg/ipc/chromium/src/base/
#24 0x029b32cd in MessageLoop::Run (this=0xf741c420) at /opt/moz/hg/ipc/chromium/src/base/
#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
Comment 14 User image Jason Duell [:jduell] (needinfo me) 2012-04-24 09:52:14 PDT
Comment on attachment 617485 [details] [diff] [review]

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

Michal:  how big is the metadata per entry?
Comment 15 User image Michal Novotny (:michal) 2012-04-24 14:47:22 PDT
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 16 User image Jason Duell [:jduell] (needinfo me) 2012-04-24 15:40:39 PDT
Comment on attachment 617485 [details] [diff] [review]

OK, then it sounds like we can live w/o counting metadata in the total.
Comment 18 User image Nicholas Nethercote [:njn] 2012-04-24 16:15:53 PDT
Next time please remember the "r=jduell" in the commit message :)

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