nvoking |make mozmill| TB test suite by running DEBUG BUILD of TB
under valgrind has turned out to be useful in finding memory-related
errors, AND timing-related thread race issues. The issues of second
kind, i.e., timing issues, are not usually noticed, but often they
become obvious due to the large execution time skew caused by running
TB under valgrind. I found that code that ran without proper
ordering (by means of mutex, etc.) suddenly causes problems under valgrind.
Since refreshing my local copy of comm-central tree a couple of days
ago (my previous update was around Dec 25+ last year), I have not been
able to run the test suite |make mozmill| for TB (local DEBUG BUILD)
under valgrind (Debian GNU/Linux, both under 32-bit and 64-bit
versions).
Simply put, although I lengthened the timeout value, all the tests
timed out and no useful information could be obtained. This was not
the case only a few weeks ago or so before the source update. I
lengthened the timeout by 60 seconds, still no go. (That is, I
had already set it to 330 before, and increased it this time
to 390 to no avail.)
I have no idea how long I should lengthen the timeout value. So I got
curious and ran the locally built DEBUG BUILD TB under valgrind
MANUALLY and see if anything stood out.
And some DID certainly. There are a few cases of locking failure(?)
in one run, and strange assertion/warning regarding startup cache. I
have never seen them before.
Possibly the locking failure may explain the timeout under valgrind.
I wonder if anyone can shed light on these new assertions/warnings.
Sorry for long posting. Below is the log printed to the
tty console where TB was started under valgrind.
(1) Strange locking issue?
Please note the warning, "PRFileDescAutoLock cannot get fd!: 'mFd'",
and "Security network blocking I/O on Main Thread"
[... during startup...]
JavaScript strict warning: chrome://messenger/content/tabmail.xml, line
352: reference to undefined property aTabType.panelId
[30685] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file
/REF-COMM-CENTRAL/comm-central/mozilla/netwerk/base/src/nsSocketTransport2.h,
line 195
[30685] WARNING: Security network blocking I/O on Main Thread: file
/REF-COMM-CENTRAL/comm-central/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp,
line 423
++DOMWINDOW == 24 (0x1e495e68) [pid = 30685] [serial = 27] [outer =
0x1e46fb98]
++DOCSHELL 0x2b85ca60 == 12 [pid = 30685] [id = 12]
++DOMWINDOW == 25 (0x2b6eb948) [pid = 30685] [serial = 28] [outer = (nil)]
++DOMWINDOW == 26 (0x26f48768) [pid = 30685] [serial = 29] [outer =
0x2b6eb948]
--DOMWINDOW == 25 (0x2b5f3188) [pid = 30685] [serial = 15] [outer =
0x1c5e3da8] [url = about:blank]
[30685] WARNING: NS_ENSURE_TRUE(enabled) failed: file
/REF-COMM-CENTRAL/comm-central/mozilla/dom/base/Navigator.cpp, line 1869
[30685] WARNING: NS_ENSURE_TRUE(enabled) failed: file
/REF-COMM-CENTRAL/comm-central/mozilla/dom/base/Navigator.cpp, line 1710
[30685] WARNING: Security network blocking I/O on Main Thread: file
/REF-COMM-CENTRAL/comm-central/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp,
line 423
--DOMWINDOW == 24 (0x2a95a8f8) [pid = 30685] [serial = 18] [outer =
(nil)] [url = about:blank]
--DOCSHELL 0x2b85ca60 == 11 [pid = 30685] [id = 12]
[30685] WARNING: Could not get disk status from nsIDiskSpaceWatcher:
file
/REF-COMM-CENTRAL/comm-central/mozilla/uriloader/prefetch/nsOfflineCacheUpdateService.cpp,
line 325
++DOCSHELL 0x1e1d4c10 == 12 [pid = 30685] [id = 13]
[... eventually TB started up, and I quit it...]
(1.5) Another instance of "PRFileDescAutoLock cannot get fd!" and
"blocking I/O", this time
when TB checked add-on during startup.
[... during start up... ]
*** LOG addons.xpi-utils: Writing add-ons list
[27847] WARNING: dependent window created without a parent: file
/REF-COMM-CENTRAL/comm-central/mozilla/toolkit/components/startup/nsAppStartup.cpp,
line 650
++DOCSHELL 0x1dce9da0 == 1 [pid = 27847] [id = 1]
++DOMWINDOW == 1 (0x1dcefaf8) [pid = 27847] [serial = 1] [outer = (nil)]
++DOMWINDOW == 2 (0x1eb11c28) [pid = 27847] [serial = 2] [outer =
0x1dcefaf8]
*** LOG DeferredSave/extensions.json: Starting timer
*** LOG DeferredSave/extensions.json: Starting write
Chrome file doesn't exist:
/REF-OBJ-DIR/objdir-tb3/mozilla/dist/bin/chrome/toolkit/skin/classic/mozapps/update/update.png
<--- maybe because I am testing TB without "installing" it(?)
[27847] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result
0x80520012: file
/REF-COMM-CENTRAL/comm-central/mozilla/netwerk/base/src/nsFileStreams.cpp,
line 210
[27847] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result
0x80520012: file
/REF-COMM-CENTRAL/comm-central/mozilla/netwerk/base/src/nsFileStreams.cpp,
line 482
[27847] WARNING: Asking for app status on a principal with an unknown
app id: 'mAppId != nsIScriptSecurityManager::UNKNOWN_APP_ID', file
/REF-COMM-CENTRAL/comm-central/mozilla/caps/src/nsPrincipal.cpp, line 532
<--- Never seen this error before!
[27847] WARNING: NS_ENSURE_TRUE(enabled) failed: file
/REF-COMM-CENTRAL/comm-central/mozilla/dom/base/Navigator.cpp, line 1869
[27847] WARNING: NS_ENSURE_TRUE(enabled) failed: file
/REF-COMM-CENTRAL/comm-central/mozilla/dom/base/Navigator.cpp, line 1710
LoadPlugin()
/usr/lib/mozilla/plugins/librhythmbox-itms-detection-plugin.so returned
200c6300
*** LOG addons.repository: Requesting
https://services.addons.mozilla.org/en-US/thunderbird/api/1.5/search/guid:tbtestpilot%40labs.mozilla.com,%7B972ce4c6-7e08-4474-a285-3208198ce6fd%7D,%7Bd10d0bf8-f5b5-c8b4-a8b2-2b9879e08c5d%7D?src=thunderbird&appOS=Linux&appVersion=29.0a1
--DOCSHELL 0x1dce9da0 == 0 [pid = 27847] [id = 1]
*** LOG addons.xpi-utils: Writing add-ons list
GetSpecialSystemDirectory: aSystemSystemDirectory=4
<== a dump I inserted.
++DOCSHELL 0x1f33e280 == 1 [pid = 27847] [id = 2]
++DOMWINDOW == 3 (0x1ee7b9b8) [pid = 27847] [serial = 3] [outer = (nil)]
++DOMWINDOW == 4 (0x1f3069d8) [pid = 27847] [serial = 4] [outer =
0x1ee7b9b8]
++DOCSHELL 0x1f917cb0 == 2 [pid = 27847] [id = 3]
++DOMWINDOW == 5 (0x2dcafa58) [pid = 27847] [serial = 5] [outer = (nil)]
++DOMWINDOW == 6 (0x2dcb11b8) [pid = 27847] [serial = 6] [outer =
0x2dcafa58]
++DOMWINDOW == 7 (0x5b891d8) [pid = 27847] [serial = 7] [outer = 0x1ee7b9b8]
[27847] WARNING: PRFileDescAutoLock cannot get fd!: 'mFd', file
/REF-COMM-CENTRAL/comm-central/mozilla/netwerk/base/src/nsSocketTransport2.h,
line 195
*** LOG DeferredSave/addons.json: Save changes
*** LOG DeferredSave/addons.json: Starting timer
*** LOG addons.updates: Requesting
https://versioncheck.addons.mozilla.org/update/VersionCheck.php?reqVersion=2&id=tbtestpi...@labs.mozilla.com&version=1.3.9&maxAppVersion=17.*&status=userDisabled&appID={3550f703-e582-4d05-9a08-453d09bdfdc6}&appVersion=29.0a1&appOS=Linux&appABI=x86_64-gcc3&locale=en-US¤tAppVersion=29.0a1&updateType=35&compatMode=normal
[... two (2) more LOG addons.updates lines ...]
*** LOG DeferredSave/addons.json: Starting write
[27847] WARNING: Security network blocking I/O on Main Thread: file
/REF-COMM-CENTRAL/comm-central/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp,
line 423
[27847] WARNING: Security network blocking I/O on Main Thread: file
/REF-COMM-CENTRAL/comm-central/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp,
line 423
[27847] WARNING: Security network blocking I/O on Main Thread: file
/REF-COMM-CENTRAL/comm-central/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp,
line 423
*** LOG addons.updates: Found an update entry for
{d10d0bf8-f5b5-c8b4-a8b2-2b9879e08c5d} version 2.4
*** LOG DeferredSave/extensions.json: Save changes
*** LOG DeferredSave/extensions.json: Data changed while write in progress
[... many lines are omitted ...]
[27847] WARNING: Could not get disk status from nsIDiskSpaceWatcher:
file
/REF-COMM-CENTRAL/comm-central/mozilla/uriloader/prefetch/nsOfflineCacheUpdateService.cpp,
line 325
--DOMWINDOW == 24 (0x1ec816c8) [pid = 27847] [serial = 30] [outer =
(nil)] [url = chrome://messenger/content/systemIntegrationDialog.xul]
[... eventually TB started up, and I quit it...]
(2) StartupCache issues.
(This particular issue could be caused my mixing of profile from an
earlier version of released TB, and running local build of TB under a
user account which is different from the TB test account without any
profile. Butif so, do users have to clear the startup cache when a new
version is installed manually, or is it taken care of automagically
during install?).
Please notice the strange 'zipItem == nullptr',
and 'NS_SUCCEEDED(rv) && hasEntry == false' assertions.
These happened in a few runs (but not always). I wonder if the
code that check for 'zipItem == nullptr' in StartupCache.cpp is
correct or not.
FYI, I have also included the typical messy shutdown error(s) often
seen in TB. I am not sure I have not seen '!gThread' warning before.
Also, '!compMgr' also indicates the problem during shutdown.
Maybe there are new timing / thread-race issues exposed by the
timing difference caused by valgrind, or there may be simply more
explicit checks for inconsistency in the code now.
[... startup ...]
++DOMWINDOW == 9 (0x1fcb7108) [pid = 28989] [serial = 9] [outer = (nil)]
[28989] ###!!! ASSERTION: Existing entry in disk StartupCache.: 'zipItem
== nullptr', file
/REF-COMM-CENTRAL/comm-central/mozilla/startupcache/StartupCache.cpp,
line 368
--DOMWINDOW == 8 (0x2b1498e8) [pid = 28989] [serial = 2] [outer =
0x2b1328b8] [url = about:blank]
[... omitted ...]
JavaScript strict warning: chrome://global/content/bindings/findbar.xml,
line 262: reference to undefined property this._browser.finder
JavaScript error: chrome://global/content/bindings/findbar.xml, line
262: this._browser.finder is undefined
[... omitted ...]]
[28989] ###!!! ASSERTION: Existing entry in disk StartupCache.:
'NS_SUCCEEDED(rv) && hasEntry == false', file
/REF-COMM-CENTRAL/comm-central/mozilla/startupcache/StartupCache.cpp,
line 422
[28989] WARNING: cache entry deleted but not written to disk.: file
/REF-COMM-CENTRAL/comm-central/mozilla/startupcache/StartupCache.cpp,
line 427
JavaScript strict warning: chrome://messenger/content/tabmail.xml, line
352: reference to undefined property aTabType.panelId
[...]
[28989] WARNING: Could not get disk status from nsIDiskSpaceWatcher:
file
/REF-COMM-CENTRAL/comm-central/mozilla/uriloader/prefetch/nsOfflineCacheUpdateService.cpp,
line 325
--DOMWINDOW == 24 (0x1c562cf8) [pid = 28989] [serial = 18] [outer =
(nil)] [url = about:blank]
[... omitted ...]
[... now I am shutting TB down by clicking [x] button on
the window pane ...]
*** LOG addons.xpi: Notifying XPI shutdown observers
*** LOG addons.manager: Async provider shutdown done
[28989] WARNING: unable to Flush() dirty datasource during XPCOM
shutdown: file
/REF-COMM-CENTRAL/comm-central/mozilla/rdf/base/src/nsRDFXMLDataSource.cpp,
line 747
--DOMWINDOW == 11 (0x1a5d5658) [pid = 28989] [serial = 5] [outer =
0x2b1328b8] [url = resource://gre-resources/hiddenWindow.html]
--DOMWINDOW == 10 (0x2b1328b8) [pid = 28989] [serial = 1] [outer =
(nil)] [url = resource://gre-resources/hiddenWindow.html]
[28989] WARNING: '!gThread', file
/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/threads/nsTimerImpl.cpp,
line 320
[28989] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result
0xC1F30001: file
/REF-COMM-CENTRAL/comm-central/mozilla/image/src/DiscardTracker.cpp, line 77
--DOCSHELL 0x1dea88c0 == 0 [pid = 28989] [id = 5]
--DOMWINDOW == 9 (0x342f6078) [pid = 28989] [serial = 29] [outer =
(nil)] [url = about:blank]
--DOMWINDOW == 8 (0x354a9ae8) [pid = 28989] [serial = 28] [outer =
(nil)] [url = chrome://messenger/content/systemIntegrationDialog.xul]
[...]
[28989] WARNING: not an nsIRDFRemoteDataSource: 'remote != nullptr',
file
/REF-COMM-CENTRAL/comm-central/mozilla/rdf/datasource/src/nsLocalStore.cpp,
line 279
[28989] WARNING: not an nsIRDFRemoteDataSource: 'remote != nullptr',
file
/REF-COMM-CENTRAL/comm-central/mozilla/rdf/datasource/src/nsLocalStore.cpp,
line 279
[28989] WARNING: not an nsIRDFRemoteDataSource: 'remote != nullptr',
file
/REF-COMM-CENTRAL/comm-central/mozilla/rdf/datasource/src/nsLocalStore.cpp,
line 279
[28989] WARNING: '!compMgr', file
/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/glue/nsComponentManagerUtils.cpp,
line 59
nsStringStats
=> mAllocCount: 46476
=> mReallocCount: 2095
=> mFreeCount: 46476
=> mShareCount: 70885
=> mAdoptCount: 5309
=> mAdoptFreeCount: 5309
=> Process ID: 28989, Thread ID: 67464640
[then I get the shell prompt. TB under valgrind finished.]
TIA
_______________________________________________
dev-platform mailing list
dev-platform@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-platform
