Closed Bug 626956 Opened 14 years ago Closed 14 years ago

Nearly constant leak of 3 instances of nsStringBuffer in Windows mochitest-chrome

Categories

(Core :: General, defect)

Product:
Core
Component:
General
Platform:
x86
Windows 7
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: philor, Unassigned)

References

Details

(Keywords: intermittent-failure)

This started with http://tbpl.mozilla.org/?rev=022475b85087 so at first we blamed it, despite that not being very likely, but didn't back it out, and then when it failed to happen a few pushes later, we decided that since it was intertwingled with the bug 620991 thing of having some plugin test claiming that it is test_windowed_invalidate.html running during shutdown, that it was that doing the leaking too. Then today, after having a leak in virtually every run since, we finally backed out 022475b85087, and unsurprisingly it still leaked. More surprisingly, several times today the leak hasn't been accompanied by any evidence of tests running during shutdown. Despite that, in http://tbpl.mozilla.org/?rev=1ceb49844869 I disabled test_visibility.html (the test rumored to be what makes test_windowed_invalidate.html appear to run during shutdown) on Windows, and still it leaks. Given the frequency, it's unlikely to have been caused by something more than a few pushes before that first instance, the prior three being (the equally unlikely): http://hg.mozilla.org/mozilla-central/rev/50245d5d1bec http://hg.mozilla.org/mozilla-central/rev/b27366868c80 and http://hg.mozilla.org/mozilla-central/rev/70f1fbe19abb http://hg.mozilla.org/mozilla-central/rev/48e1cb943266 Sample recent log: http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1295417395.1295421315.18545.gz Rev3 WINNT 6.1 mozilla-central debug test mochitest-other on 2011/01/18 22:09:55 s: talos-r3-w7-021 nsTraceRefcntImpl::DumpStatistics: 1254 entries TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 24 bytes during test execution TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 3 instances of nsStringBuffer with size 8 bytes each (24 bytes total)
This seems to be accompanied by two crashes in plugin-container.exe, involving js-ctypes... 0 mozjs.dll!js::ctypes::ConvertToJS(JSContext *,JSObject *,JSObject *,void *,bool,bool,jsval_layout *) [typedefs.h:b22bb39e834f : 107 + 0x3] eip = 0x692cc78c esp = 0x0026d3f0 ebp = 0x0026d5e8 ebx = 0x00000000 esi = 0x00e0b168 edi = 0xffff0007 eax = 0x00000004 ecx = 0x00000008 edx = 0x00000004 efl = 0x00010283 Found by: given as instruction pointer in context 1 mozjs.dll!js::ctypes::PointerType::ContentsGetter [CTypes.cpp:b22bb39e834f : 3393 + 0x1a] eip = 0x692d400f esp = 0x0026d5f0 ebp = 0x0026d620 Found by: call frame info 2 mozjs.dll!js::CallJSPropertyOp(JSContext *,int (*)(JSContext *,JSObject *,jsid,js::Value *),JSObject *,jsid,js::Value *) [jscntxtinlines.h:b22bb39e834f : 736 + 0x12] eip = 0x690d0f45 esp = 0x0026d628 ebp = 0x0026d63c Found by: call frame info 3 mozjs.dll!js::Shape::get(JSContext *,JSObject *,JSObject *,JSObject *,js::Value *) [jsscopeinlines.h:b22bb39e834f : 256 + 0x50] eip = 0x690d8d73 esp = 0x0026d644 ebp = 0x0026d66c Found by: call frame info 4 mozjs.dll!js_NativeGetInline [jsobj.cpp:b22bb39e834f : 5141 + 0x1b] eip = 0x690d8acf esp = 0x0026d674 ebp = 0x0026d6c8 Found by: call frame info 5 mozjs.dll!js_GetPropertyHelperWithShapeInline [jsobj.cpp:b22bb39e834f : 5320 + 0x20] eip = 0x690d9647 esp = 0x0026d6d0 ebp = 0x0026d720 Found by: call frame info 6 mozjs.dll!js_GetPropertyHelperInline [jsobj.cpp:b22bb39e834f : 5341 + 0x24] eip = 0x690d97eb esp = 0x0026d728 ebp = 0x0026d750 Found by: call frame info 7 mozjs.dll!js_GetPropertyHelper(JSContext *,JSObject *,jsid,unsigned int,js::Value *) [jsobj.cpp:b22bb39e834f : 5347 + 0x1c] eip = 0x690d97b0 esp = 0x0026d758 ebp = 0x0026d770 Found by: call frame info 8 mozjs.dll!js::Interpret(JSContext *,JSStackFrame *,unsigned int,JSInterpMode) [jsinterp.cpp:b22bb39e834f : 4201 + 0x6c] eip = 0x690a4ed6 esp = 0x0026d778 ebp = 0x0026e800 Found by: call frame info 9 mozjs.dll!js::RunScript(JSContext *,JSScript *,JSStackFrame *) [jsinterp.cpp:b22bb39e834f : 657 + 0x10] eip = 0x69094d2c esp = 0x0026e808 ebp = 0x0026e828 ebx = 0x00000000 Found by: call frame info 10 mozjs.dll!js::Invoke(JSContext *,js::CallArgs const &,unsigned int) [jsinterp.cpp:b22bb39e834f : 737 + 0x10] eip = 0x69095197 esp = 0x0026e830 ebp = 0x0026e888 Found by: call frame info 11 mozjs.dll!js::ExternalInvoke(JSContext *,js::Value const &,js::Value const &,unsigned int,js::Value *,js::Value *) [jsinterp.cpp:b22bb39e834f : 858 + 0xe] eip = 0x690961c3 esp = 0x0026e890 ebp = 0x0026e8c8 Found by: call frame info 12 mozjs.dll!js::ExternalInvoke [jsinterp.h:b22bb39e834f : 961 + 0x29] eip = 0x68ff2500 esp = 0x0026e8d0 ebp = 0x0026e8f0 Found by: call frame info 13 mozjs.dll!JS_CallFunctionValue [jsapi.cpp:b22bb39e834f : 5019 + 0x37] eip = 0x68ff2954 esp = 0x0026e8f8 ebp = 0x0026e924 Found by: call frame info 14 xul.dll!mozilla::jetpack::JetpackActorCommon::RecvMessage(JSContext *,nsString const &,InfallibleTArray<mozilla::jetpack::Variant> const &,InfallibleTArray<mozilla::jetpack::Variant> *) [JetpackActorCommon.cpp:b22bb39e834f : 475 + 0x37] eip = 0x6971d491 esp = 0x0026e92c ebp = 0x0026ea60 Found by: call frame info 15 xul.dll!mozilla::jetpack::JetpackChild::RecvSendMessage(nsString const &,InfallibleTArray<mozilla::jetpack::Variant> const &) [JetpackChild.cpp:b22bb39e834f : 191 + 0x21] eip = 0x697167d5 esp = 0x0026ea68 ebp = 0x0026ea98 Found by: call frame info 16 xul.dll!mozilla::jetpack::PJetpackChild::OnMessageReceived(IPC::Message const &) [PJetpackChild.cpp:b22bb39e834f : 276 + 0x1a] eip = 0x69abe9a2 esp = 0x0026eaa0 ebp = 0x0026eb80 Found by: call frame info 17 xul.dll!mozilla::ipc::AsyncChannel::OnDispatchMessage(IPC::Message const &) [AsyncChannel.cpp:b22bb39e834f : 262 + 0x1d] eip = 0x6991585b esp = 0x0026eb88 ebp = 0x0026eb94 Found by: call frame info 18 xul.dll!mozilla::ipc::RPCChannel::OnMaybeDequeueOne() [RPCChannel.cpp:b22bb39e834f : 433 + 0xb] eip = 0x6991d5a1 esp = 0x0026eb9c ebp = 0x0026ec14 Found by: call frame info 19 xul.dll!DispatchToMethod<mozilla::ipc::RPCChannel,bool ( mozilla::ipc::RPCChannel::*)(void)>(mozilla::ipc::RPCChannel *,bool ( mozilla::ipc::RPCChannel::*)(void),Tuple0 const &) [tuple.h:b22bb39e834f : 383 + 0x8] eip = 0x6992643c esp = 0x0026ec1c ebp = 0x0026ec1c Found by: call frame info 20 xul.dll!RunnableMethod<mozilla::ipc::RPCChannel,bool ( mozilla::ipc::RPCChannel::*)(void),Tuple0>::Run() [task.h:b22bb39e834f : 307 + 0x1d] eip = 0x6992582e esp = 0x0026ec24 ebp = 0x0026ec38 Found by: call frame info 21 xul.dll!mozilla::ipc::RPCChannel::RefCountedTask::Run() [RPCChannel.h:b22bb39e834f : 450 + 0x19] eip = 0x6991d25a esp = 0x0026ec40 ebp = 0x0026ec44 Found by: call frame info 22 xul.dll!mozilla::ipc::RPCChannel::DequeueTask::Run() [RPCChannel.h:b22bb39e834f : 475 + 0x18] eip = 0x6991d229 esp = 0x0026ec4c ebp = 0x0026ec50 Found by: call frame info 23 xul.dll!MessageLoop::RunTask(Task *) [message_loop.cc:b22bb39e834f : 343 + 0xc] eip = 0x6aaae23e esp = 0x0026ec58 ebp = 0x0026ec78 Found by: call frame info 24 xul.dll!MessageLoop::DeferOrRunPendingTask(MessageLoop::PendingTask const &) [message_loop.cc:b22bb39e834f : 351 + 0xd] eip = 0x6aaae2ae esp = 0x0026ec80 ebp = 0x0026ec88 Found by: call frame info 25 xul.dll!MessageLoop::DoWork() [message_loop.cc:b22bb39e834f : 451 + 0xb] eip = 0x6aaae60d esp = 0x0026ec90 ebp = 0x0026ecb4 Found by: call frame info 26 xul.dll!base::MessagePumpForUI::DoRunLoop() [message_pump_win.cc:b22bb39e834f : 213 + 0x1a] eip = 0x6aada023 esp = 0x0026ecbc ebp = 0x0026ecc8 Found by: call frame info 27 xul.dll!base::MessagePumpWin::RunWithDispatcher(base::MessagePump::Delegate *,base::MessagePumpWin::Dispatcher *) [message_pump_win.cc:b22bb39e834f : 52 + 0xc] eip = 0x6aad9b7f esp = 0x0026ecd0 ebp = 0x0026ecec ebx = 0x7ffd7000 Found by: call frame info 28 xul.dll!base::MessagePumpWin::Run(base::MessagePump::Delegate *) [message_pump_win.h:b22bb39e834f : 78 + 0x14] eip = 0x6aad9ce5 esp = 0x0026ecf4 ebp = 0x0026ed00 Found by: call frame info 29 xul.dll!MessageLoop::RunInternal() [message_loop.cc:b22bb39e834f : 219 + 0x1e] eip = 0x6aaadde6 esp = 0x0026ed08 ebp = 0x0026ed24 Found by: call frame info 30 xul.dll!MessageLoop::RunHandler() [message_loop.cc:b22bb39e834f : 202 + 0x7] eip = 0x6aaadd22 esp = 0x0026ed2c ebp = 0x0026ed5c Found by: call frame info 31 xul.dll!MessageLoop::Run() [message_loop.cc:b22bb39e834f : 176 + 0x7] eip = 0x6aaadc4d esp = 0x0026ed64 ebp = 0x0026ed7c ebx = 0x0026cfdc Found by: call frame info 32 xul.dll!XRE_InitChildProcess [nsEmbedFunctions.cpp:b22bb39e834f : 515 + 0xa] eip = 0x695b22c8 esp = 0x0026ed84 ebp = 0x0026fa3c Found by: call frame info 33 plugin-container.exe!NS_internal_main(int,char * *) [MozillaRuntimeMain.cpp:b22bb39e834f : 80 + 0x11] eip = 0x00f517db esp = 0x0026fa44 ebp = 0x0026fa60 Found by: call frame info 34 plugin-container.exe!wmain [nsWindowsWMain.cpp:b22bb39e834f : 128 + 0xc] eip = 0x00f511b9 esp = 0x0026fa68 ebp = 0x0026fa94 Found by: call frame info 35 plugin-container.exe!__tmainCRTStartup [crtexe.c : 594 + 0x18] eip = 0x00f51b66 esp = 0x0026fa9c ebp = 0x0026fae4 Found by: call frame info 36 plugin-container.exe!wmainCRTStartup [crtexe.c : 413 + 0x4] eip = 0x00f519bd esp = 0x0026faec ebp = 0x0026faec ebx = 0x0026cfdc Found by: call frame info 37 kernel32.dll + 0x51173 eip = 0x767f1174 esp = 0x0026faf4 ebp = 0x0026faf8 Found by: call frame info 38 ntdll.dll + 0x5b3f4 eip = 0x76e7b3f5 esp = 0x0026fb00 ebp = 0x0026fb38 Found by: previous frame's frame pointer 39 ntdll.dll + 0x5b3c7 eip = 0x76e7b3c8 esp = 0x0026fb40 ebp = 0x0026fb50 Found by: previous frame's frame pointer
OS: Windows 7 → Windows XP
I believe those are intentional.
They are, see http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1295457432.1295461462.23309.gz&fulltext=1 for what a perfectly happy green run with no leaks looks like, including those two "PROCESS-CRASH | Main app process exited normally" intentional takedowns.
Depends on: 627279
From the bottom up (instead of the top down, the foolish way I ran it on try), nine runs of mochitest-other on http://hg.mozilla.org/mozilla-central/rev/48e1cb943266 showed no leaks, and the very first run on http://hg.mozilla.org/mozilla-central/rev/70f1fbe19abb did leak (better odds than further up, it took me four runs to get two leaks from b27366868c80 and nine runs to get two leaks from 50245d5d1bec). So, the resizer patch from bug 489303 leaks (mostly 1 to 3 nsStringBuffers, but I think at least one of the misplaced starrings included a couple of CSSImportantRules, too), only in mochitest-chrome, and only on Windows, and only most of the time, not quite all.
Blocks: 489303
OS: Windows XP → Windows 7
Are you sure this is the resizer patch? There were no leaks the last time this was checked in.
My statistics professors would be disappointed, but unsurprised, to hear that 30 years on, I can no longer tell you how confident I am, but it should be easy enough to reproduce my results. hg up -r 48e1cb943266, stick an empty patch on top with "try: -b d -p win32 -u mochitest-o -t none", push to try, hg up -r 70f1fbe19abb, another empty patch, push to try, wait for the builds to finish and then file a releng bug asking for however many extra runs of mochitest-other you want. I got 9 runs on the cset before the resizer with 0 leaks, and on various pushes of the resizer and things afterward, I got 2 leaks in 9 runs, 2 leaks in 4 runs, and 1 leak in 1 run. That makes me believe the leak existed in every cset starting with the resizer, and that it didn't exist (or maybe more accurately, didn't show, since it could well be a latent leak that the resizer just exposes) on the cset before the resizer. I have less confidence in the lack-of-leaks result the last time it was in the tree - I pushed it, on Christmas Eve when I was looking for things to push to keep the tree from freezing solid from inactivity, and though we know it must have gotten 5 runs for the Talos regression script to finger it, it probably didn't get much more than that before Gavin backed it out Christmas Day. Plus, things may well have changed underneath it since then, who knows? And given that we put the first twenty or so instances of this leak into another bug, it might have even leaked a time or two, and we just called it something else.
Neil, do you mind grabbing a winxp machine from releng and start to debug the leak there? Given comment 18, there is a very good chance that your patch is at fault, and this seems to be easy enough to reproduce that debugging might actually help us figure out what's leaking.
Where by XP he probably means 7 - we're not currently running debug tests on XP, so we don't actually know whether or not it leaks there.
Apparently I don't know how the Talos regression script works (or I forgot to count nightlies, or both) - it was in for three pushes, plus another round from nightlies, when it landed before.
I did a comparison of the assertions present in these two logs: (In reply to comment #36) > http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1295622212.1295625804.28359.gz (In reply to comment #5) > They are, see > http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1295457432.1295461462.23309.gz&fulltext=1 > for what a perfectly happy green run with no leaks looks like, including those > two "PROCESS-CRASH | Main app process exited normally" intentional takedowns. and found exactly three differences: + 1 ###!!! ASSERTION: no xul:window: 'windowElement', file e:/builds/moz2_slave/cen-w32-dbg/build/xpfe/appshell/src/nsXULWindow.cpp, line 1206 + 1 ###!!! ASSERTION: no xul:window: 'windowElement', file e:/builds/moz2_slave/cen-w32-dbg/build/xpfe/appshell/src/nsXULWindow.cpp, line 1125 + 1 ###!!! ASSERTION: no xul:window: 'windowElement', file e:/builds/moz2_slave/cen-w32-dbg/build/xpfe/appshell/src/nsXULWindow.cpp, line 1056 These assertions occur between: 195 INFO TEST-START | chrome://mochitests/content/chrome/content/xul/document/test/test_bug583948.xul and: 196 INFO TEST-PASS | chrome://mochitests/content/chrome/content/xul/document/test/test_bug583948.xul | didn't crash after 6 attempts To check this relationship, I looked at the two most recent green windows debug mochitest-other logs: http://tinderbox.mozilla.org/Firefox/1295630696.1295634356.3046.gz http://tinderbox.mozilla.org/Firefox/1295628383.1295631975.23683.gz and they also did not have the assertions. However, of the two other most recent orange ones (comment 34 and comment 35), the log in comment 35 also had these assertions, but the log in comment 34 did not. The log in comment 33 also did not. So it seems like there might be a relationship between these assertions and the leaks, but there probably isn't...
http://tbpl.mozilla.org/?tree=MozillaTry&rev=42cc6997cea7 is intended to debug this: it prints the contents of any leaked string buffers
I got the leak on the first try (see comment 41), and all three leaked strings are PRUnichar* strings of "mozilla.com": nsStringStats => mAllocCount: 1326168 => mReallocCount: 257605 => mFreeCount: 1326165 -- LEAKED 3 !!! Leaked string aBuffer 0E4498C0, storage size 24: string[0] = 0x6D (m) string[1] = 0x00 string[2] = 0x6F (o) string[3] = 0x00 string[4] = 0x7A (z) string[5] = 0x00 string[6] = 0x69 (i) string[7] = 0x00 string[8] = 0x6C (l) string[9] = 0x00 string[10] = 0x6C (l) string[11] = 0x00 string[12] = 0x61 (a) string[13] = 0x00 string[14] = 0x2E (.) string[15] = 0x00 string[16] = 0x63 (c) string[17] = 0x00 string[18] = 0x6F (o) string[19] = 0x00 string[20] = 0x6D (m) string[21] = 0x00 string[22] = 0x00 string[23] = 0x00 Leaked string aBuffer 0E442390, storage size 24: string[0] = 0x6D (m) string[1] = 0x00 string[2] = 0x6F (o) string[3] = 0x00 string[4] = 0x7A (z) string[5] = 0x00 string[6] = 0x69 (i) string[7] = 0x00 string[8] = 0x6C (l) string[9] = 0x00 string[10] = 0x6C (l) string[11] = 0x00 string[12] = 0x61 (a) string[13] = 0x00 string[14] = 0x2E (.) string[15] = 0x00 string[16] = 0x63 (c) string[17] = 0x00 string[18] = 0x6F (o) string[19] = 0x00 string[20] = 0x6D (m) string[21] = 0x00 string[22] = 0x00 string[23] = 0x00 Leaked string aBuffer 0E44DB00, storage size 24: string[0] = 0x6D (m) string[1] = 0x00 string[2] = 0x6F (o) string[3] = 0x00 string[4] = 0x7A (z) string[5] = 0x00 string[6] = 0x69 (i) string[7] = 0x00 string[8] = 0x6C (l) string[9] = 0x00 string[10] = 0x6C (l) string[11] = 0x00 string[12] = 0x61 (a) string[13] = 0x00 string[14] = 0x2E (.) string[15] = 0x00 string[16] = 0x63 (c) string[17] = 0x00 string[18] = 0x6F (o) string[19] = 0x00 string[20] = 0x6D (m) string[21] = 0x00 string[22] = 0x00 string[23] = 0x00 => mShareCount: 1728987 => mAdoptCount: 72481 => mAdoptFreeCount: 72481
(In reply to comment #41) > http://tbpl.mozilla.org/?tree=MozillaTry&rev=42cc6997cea7 is intended to debug > this: it prints the contents of any leaked string buffers What's the next step, a trace refcount log? [I wonder whether it's worth adding extra debug code to track the char type.] [I notice nsBaseHashtableMT::Init leaks locks if it's called more than once.]
(In reply to comment #65) > http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1295919844.1295923663.27138.gz > Rev3 WINNT 6.1 mozilla-central debug test mochitest-other [testfailed] Except this one was actually only *one* nsStringBuffer.
Three is far more common, but that's not the only one there has been.
Some debugging suggests that the leaking 3 24-byte strings are being allocated during the test test_domstorage.xul at approximately: http://mxr.mozilla.org/mozilla-central/source/dom/tests/mochitest/chrome/domstorage_global.js#33 At the same time a pile of warnings start occurring: WARNING: No outer window available!: file ../../../dom/base/nsGlobalWindow.cpp, line 8469 However this warning occurs whether the leak happens or not. Bug 630242 was filed on a similar testcase with this particular warning.
Indeed. Of particular note, this dom storage change made the day before the leak started appearing might have caused or exposed it: http://hg.mozilla.org/mozilla-central/rev/0d08db0bf676
(In reply to comment #135) > This will probably be fixed by Bug 630193 then. That's a crash bug. How is it related to this one?
Blocks: 624047
(In reply to comment #137) > (In reply to comment #135) > > This will probably be fixed by Bug 630193 then. > > That's a crash bug. How is it related to this one? That's bug fix is a workaround. Not fix for a leak of nsGlobalWindows. Also, it is not confirmed that a leak is a culprit of that crash, it's just a theory.
This seems to have gone away, 3 days before Bug 630193 landed though.
(In reply to comment #141) > This seems to have gone away, 3 days before Bug 630193 landed though. Do you want to resolve it then?
(In reply to comment #142) > (In reply to comment #141) > > This seems to have gone away, 3 days before Bug 630193 landed though. > > Do you want to resolve it then? Yeah, just wish I knew what fixed it :-/
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → WORKSFORME
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.