184339 - (FastLoadNewProfile) XUL.mfl created in new profile after component registration has run, nsFastLoadFile asserts and corrupts XUL.mfl on second start

Status: RESOLVED INCOMPLETE

(Core :: XUL, defect)

Description

[John Morrison]

Okay, this looks like it could be the crux of (at least some) aspects
of the 'bad fastload file' bugs.

Do the following in a debug build.

1) Delete 'compreg.dat' (which will force component reg. to occur
   at next startup.
2) 'mozilla -profilemanager' and create a brand new profile
3) Exit the application.

At this point, a XUL.mfl of size 843224 bytes has been created in 
the profile directory.

4) Start mozilla again using the profile you just created.

29 assertions will fire from nsFastLoadFile.cpp. First: 

  URI mapped to two different specs?: 'uriMapEntry->mDocMapEntry == nsnull', 
    file h:/mozilla4/mozilla/xpcom/io/nsFastLoadFile.cpp, line 418

then 13 pairs of the following:

  redundant multiplexed document?: 'docMapEntry->mString == nsnull',
    file h:/mozilla4/mozilla/xpcom/io/nsFastLoadFile.cpp, line 1336
  unknown aURI passed to EndMuxedDocument!: 'uriMapEntry->mDocMapEntry',
    file h:/mozilla4/mozilla/xpcom/io/nsFastLoadFile.cpp, line 1499

then these last two assertions:

  redundant multiplexed document?: 'docMapEntry->mString == nsnull',
    file h:/mozilla4/mozilla/xpcom/io/nsFastLoadFile.cpp, line 1336
  too many strong refs in serialization: 'entry->mInfo.mStrongRefCnt <= rc-2',
    file h:/mozilla4/mozilla/xpcom/io/nsFastLoadFile.cpp, line 1692

After the browser has started, the XUL.mfl now has a size of 1121717 bytes, 
or 270KB bigger than before even though no additional XUL or JS should 
have been serialized.

5) Exit the application and start again. No further assertions, but the 
   XUL.mfl is never deleted, even though I'd guess that it is not in the
   most stable condition.

Comment 1

[John Morrison]

This may mean something. (But still don't know why this only happens when
component registration has run earlier in the app session).

###!!! ASSERTION: redundant multiplexed document?: 
  'docMapEntry->mString == nsnull',
  file h:/mozilla4/mozilla/xpcom/io/nsFastLoadFile.cpp, line 1342

The redundant documents that it names are, in order: 

  fullscreen.js
  nsBrowserStatusHandler.js
  nsBrowserContentListener.js
  contentAreaClick.js
  contentAreaDD.js
  findUtils.js
  printing.js
  bookmarksOverlay.js
  personalToolbar.js
  browser.js
  navigator.js
  navigatorDD.js
  sessionHistoryUI.js
  navigator.xul

That is exactly the order that they are loaded in 'navigator.xul', after
'strres.js' is loaded by 'navigator.xul'. But, scripts loaded before
'strres.js' are not named as redundant documents. And, of course, 'strres.js'
is "special" in that it is loaded by both navigator.xul, and by overlays that
are loaded by navigator.xul.

See:
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/content/xul/document/src/nsXULDocument.cpp#5800
  for where the "strres.js" problem is dealt with for JS fastload, 
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/content/xul/content/src/nsXULElement.cpp#5220
  for where the "strres.js" problem is dealt with for XUL fastload.
 

Comment 2

[John Morrison]

So, brendan stepped through this code and found the following. When we start
for the second time, with a XUL.mfl file already created for the new profile,
we kick off nsFastLoadFileReader::StartMuxedDocument for navigator.xul, and
then do ...::StartMuxedDocument for each of the initial out-of-line scripts
loaded by navigator.xul (calling ...::EndMuxedDocument when we've loaded the
script, and then ...::SelectMuxedDocument to switch back to loading
navigator.xul).

That all works fine until we come to the load of 'strres.js'. We 'Start' and
'End' for 'strres.js', but then instead of 'Select' for navigator.xul, we get
a 'Start' for navigator.xul on this stack ... and the race if on!  Don't know
who is triggering the second load of navigator.xul, but need to defend against
getting it started twice.

nsFastLoadFileReader::StartMuxedDocument(nsFastLoadFileReader * const 
0x01535cfc, nsISupports * 0x02ffb180, const char * 0x0012f48c) line 398
nsFastLoadService::StartMuxedDocument(nsFastLoadService * const 0x00fd9fe8, 
nsISupports * 0x02ffb180, const char * 0x0012f48c, int 1) line 251 + 31 bytes
nsXULPrototypeCache::StartFastLoadingURI(nsIURI * 0x02ffb180, int 1) line 733 + 
36 bytes
nsXULPrototypeCache::GetPrototype(nsXULPrototypeCache * const 0x014ac028, 
nsIURI * 0x02ffb180, nsIXULPrototypeDocument * * 0x0012f594) line 260 + 14 
bytes
nsXULDocument::StartDocumentLoad(nsXULDocument * const 0x015ed520, const char * 
0x02166f30, nsIChannel * 0x015eb028, nsILoadGroup * 0x02fb9df8, nsISupports * 
0x00fe3ad4, nsIStreamListener * * 0x0012fb34, int 1, nsIContentSink * 
0x00000000) line 723 + 57 bytes
nsContentDLF::CreateRDFDocument(const char * 0x02166f30, nsIChannel * 
0x015eb028, nsILoadGroup * 0x02fb9df8, const char * 0x0012fa30, nsISupports * 
0x00fe3ad4, nsISupports * 0x00000000, nsIStreamListener * * 0x0012fb34, 
nsIContentViewer * * 0x0012f89c) line 531 + 47 bytes
nsContentDLF::CreateInstance(nsContentDLF * const 0x0300aad0, const char * 
0x02166f30, nsIChannel * 0x015eb028, nsILoadGroup * 0x02fb9df8, const char * 
0x0012fa30, nsISupports * 0x00fe3ad4, nsISupports * 0x00000000, 
nsIStreamListener * * 0x0012fb34, nsIContentViewer * * 0x0012f89c) line 271 + 
40 bytes
nsDocShell::NewContentViewerObj(nsDocShell * const 0x00fe3ab0, const char * 
0x0012fa30, nsIRequest * 0x015eb028, nsILoadGroup * 0x02fb9df8, 
nsIStreamListener * * 0x0012fb34, nsIContentViewer * * 0x0012f89c) line 4516 + 
101 bytes
nsDocShell::CreateContentViewer(nsDocShell * const 0x00fe3ab0, const char * 
0x0012fa30, nsIRequest * 0x015eb028, nsIStreamListener * * 0x0012fb34) line 
4388 + 60 bytes
nsDSURIContentListener::DoContent(nsDSURIContentListener * const 0x02f22830, 
const char * 0x0012fa30, int 0, nsIRequest * 0x015eb028, nsIStreamListener * * 
0x0012fb34, int * 0x0012fa1c) line 110 + 33 bytes
nsDocumentOpenInfo::DispatchContent(nsIRequest * 0x015eb028, nsISupports * 
0x00000000) line 430 + 96 bytes
nsDocumentOpenInfo::OnStartRequest(nsDocumentOpenInfo * const 0x015bb608, 
nsIRequest * 0x015eb028, nsISupports * 0x00000000) line 229 + 16 bytes
nsJARChannel::OnStartRequest(nsJARChannel * const 0x015eb02c, nsIRequest * 
0x01533df4, nsISupports * 0x00000000) line 583
nsOnStartRequestEvent::HandleEvent() line 161 + 53 bytes
nsARequestObserverEvent::HandlePLEvent(PLEvent * 0x02fd46d4) line 116
PL_HandleEvent(PLEvent * 0x02fd46d4) line 644 + 10 bytes
PL_ProcessPendingEvents(PLEventQueue * 0x00f9beb8) line 574 + 9 bytes
_md_TimerProc(HWND__ * 0x00a40592, unsigned int 275, unsigned int 0, unsigned 
long 2838856203) line 930 + 9 bytes
USER32! 77e13eb0()
USER32! 77e14092()
USER32! 77e13f0f()
nsAppShellService::Run(nsAppShellService * const 0x0102f3e0) line 472
main1(int 1, char * * 0x00277938, nsISupports * 0x002779b0) line 1541 + 32 
bytes
main(int 1, char * * 0x00277938) line 1902 + 37 bytes
mainCRTStartup() line 338 + 17 bytes
KERN

Comment 3

[John Morrison]

Attachment: printf output of calls to nsXULPrototypeCache::StartFastLoad, when starting without a previously existing fastload file

I stuck a couple of printf's at the top of nsXULPrototypeCache::StartFastLoad
where it bails early if not "*.xul". 

When I delete XUL.mfl from an otherwise normal profile and then start 
'mozilla -P myProfile' to the first browser window, this is what I see.
We are loading all the xul, js, etc. twice when starting without an
already created fastload file.

Comment 4

[John Morrison]

Er, correction. All of the "*.xul" files loaded twice (with tasksOverlay.xul
being loaded 4 times), and a few of the dtd/css/properties loaded twice 
(with tasksOverlay.dtd loaded 3 times).

Comment 5

[John Morrison]

Actually, the condition is 'if not in xul-cache, and not already in fastload
file, then StartFastLoad is entered twice for ".xul"' files. For example, 
start with an already existing fastload file, and then go load a pref panel
you haven't visited before.

Comment 6

[Brendan Eich [:brendan]]

Who is sending that second plevent to start loading navigator.xul, e.g.?  Any
way to find the stack of the event sender?  Maybe printfs with counters, then
some data-conditioned breakpointing?

/be

Comment 7

[John Morrison]

I have a much better idea of what's going (roughly) wrong, although I need to
look at this some more. Basically, it's trying to read in nsFastLoadService::
StartMuxedDocument, but it has no mInputStream. And we bail without doing
EndMuxedDocument after that. But I haven't grokked the full story of what 
happens at higher layers, yet. (I do know that the second load gets queued
up in ResumeWalk; or, I _think_ I know that :-/.

Comment 8

[Ben Goodger (use ben at mozilla dot org for email)]

Mass reassign of my non-Firefox bugs to [e-mail]

Comment 9

[Ben Goodger (use ben at mozilla dot org for email)]

Mass reassign of my non-Firefox bugs to [e-mail]

Comment 10

[Ben Goodger (use ben at mozilla dot org for email)]

Mass reassign of my non-Firefox bugs to [e-mail]

Comment 11

[BugBot [:suhaib / :marco/ :calixte]]

In the process of migrating remaining bugs to the new severity system, the severity for this bug cannot be automatically determined. Please retriage this bug using the new severity system.

Comment 12

[Neil Deakin]

This is too old to be relevant.