Last Comment Bug 773255 - Intermittent mochitest-browser-chrome leak of 5023, 8163, or 8171 bytes (4 AtomImpl, 1 MemoryReporter_StorageSQLite, 8 Mutex, 1 QuotaCallback, 4 QuotaCallbackData etc)
: Intermittent mochitest-browser-chrome leak of 5023, 8163, or 8171 bytes (4 At...
Status: RESOLVED FIXED
[MemShrink:P3]
: intermittent-failure, mlk
Product: Core
Classification: Components
Component: Networking: HTTP (show other bugs)
: Trunk
: x86 Mac OS X
: -- normal (vote)
: mozilla18
Assigned To: Patrick McManus [:mcmanus]
:
Mentors:
Depends on: 792511
Blocks: 438871 769764
  Show dependency treegraph
 
Reported: 2012-07-12 06:35 PDT by Ed Morley [:emorley]
Modified: 2012-11-25 19:31 PST (History)
6 users (show)
ryanvm: in‑testsuite+
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
patch 0 (979 bytes, patch)
2012-09-27 05:59 PDT, Patrick McManus [:mcmanus]
honzab.moz: review+
cbiesinger: review+
Details | Diff | Splinter Review

Description Ed Morley [:emorley] 2012-07-12 06:35:43 PDT
Rev3 MacOSX Leopard 10.5.8 mozilla-central debug test mochitest-other on 2012-07-11 10:24:42 PDT for push e4857e5dfb51

slave: talos-r3-leopard-026

https://tbpl.mozilla.org/php/getParsedLog.php?id=13432826&tree=Firefox

{
== BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 329

     |<----------------Class--------------->|<-----Bytes------>|<----------------Objects---------------->|<--------------References-------------->|
                                              Per-Inst   Leaked    Total      Rem      Mean       StdDev     Total      Rem      Mean       StdDev
   0 TOTAL                                          17     5023 478024100      179 (16465.50 +/- 26797.19) 576660141      100 (15994482867.11 +/-     0.00)
  13 AtomImpl                                       24       96    60853        4 ( 3422.38 +/-   939.45)  4900432       12 (30923.29 +/-  8859.71)
 184 MemoryReporter_StorageSQLite                   12       12        1        1 (    1.00 +/-     0.00)       11        1 (    3.67 +/-     1.74)
 191 Mutex                                          12       96    29919        8 (  292.69 +/-    83.97)        0        0 (    0.00 +/-     0.00)
 222 QuotaCallback                                  12       12        1        1 (    1.00 +/-     0.00)       18        4 (    3.81 +/-     1.28)
 223 QuotaCallbackData                               8       32        8        4 (    2.67 +/-     0.89)        0        0 (    0.00 +/-     0.00)
 232 ReentrantMonitor                               16       32    15999        2 (  227.37 +/-    85.88)        0        0 (    0.00 +/-     0.00)
 247 Service                                        68       68        1        1 (    1.00 +/-     0.00)     1702        1 (   22.77 +/-     2.89)
 254 SpdySession3                                  456      456        3        1 (    1.00 +/-     0.71)        6        2 (    1.90 +/-     1.20)
 261 StorageSQLiteMultiReporter                     52       52        1        1 (    1.00 +/-     0.00)        7        1 (    2.38 +/-     1.04)
 262 StringAdopt                                     1        3   356508        3 (    5.44 +/-     8.62)        0        0 (    0.00 +/-     0.00)
 273 ThirdPartyUtil                                 16       16        1        1 (    1.00 +/-     0.00)       48        1 (    2.91 +/-     0.79)
 276 TransportSecurityInfo                         140      140      756        1 (   55.88 +/-    39.48)    19113        1 (  159.37 +/-   125.25)
 459 nsCStringKey                                   20      600  1093393       30 ( 2270.02 +/-   823.23)        0        0 (    0.00 +/-     0.00)
 472 nsCategoryObserver                             64      128       52        2 (   13.32 +/-     8.81)     1318        2 (   49.18 +/-    36.42)
 519 nsCookiePermission                             36       36        1        1 (    1.00 +/-     0.00)       38        1 (    7.28 +/-     2.86)
 521 nsCookieService                                80       80        1        1 (    1.00 +/-     0.00)     1241        1 (    8.11 +/-     3.29)
 527 nsDNSRecord                                    32       32     2041        1 (    2.08 +/-     2.15)     8745        1 (    3.21 +/-     2.47)
 528 nsDNSService                                   84       84        1        1 (    1.00 +/-     0.00)     3215        1 (   23.85 +/-     1.74)
 596 nsDeque                                        52      104   656208        2 (   75.02 +/-    42.93)        0        0 (    0.00 +/-     0.00)
 666 nsEffectiveTLDService                          48       48        1        1 (    1.00 +/-     0.00)     9876        2 (    8.23 +/-     2.29)
 806 nsHashKey                                       8      240  3651352       30 ( 4350.45 +/-  1383.98)        0        0 (    0.00 +/-     0.00)
 808 nsHashtable                                    44       44    10202        1 ( 1060.84 +/-   371.10)        0        0 (    0.00 +/-     0.00)
 810 nsHostRecord                                   68       68       42        1 (    8.51 +/-     6.84)     4358        1 (   15.10 +/-     8.47)
 839 nsHttpConnection                              176      176     1560        1 (    2.26 +/-     1.98)    35815        1 (    9.93 +/-     8.84)
 840 nsHttpConnectionInfo                           40       40     2605        1 (   58.89 +/-    39.63)    10700        1 (   63.46 +/-    41.24)
 841 nsHttpConnectionMgr                           188      188        1        1 (    1.00 +/-     0.00)     8523        1 (    2.34 +/-     0.78)
 844 nsHttpHandler                                 420      420        1        1 (    1.00 +/-     0.00)   157361        1 (   54.83 +/-    51.59)
 847 nsIDNService                                   64       64        1        1 (    1.00 +/-     0.00)     3092        4 (    7.04 +/-     0.90)
 850 nsIOService                                   136      136        1        1 (    1.00 +/-     0.00)   916351        1 (   66.68 +/-    36.41)
 943 nsNSSCertificate                               60       60     1780        1 (  118.23 +/-    94.45)    13226        1 (  303.82 +/-   305.20)
 946 nsNSSSocketInfo                               188      188      448        1 (   48.11 +/-    35.02)    14907        1 (  159.73 +/-   123.47)
 964 nsNetworkLinkService                           28       28        1        1 (    1.00 +/-     0.00)        7        1 (    2.85 +/-     1.21)
 978 nsObserverService                              48       48        1        1 (    1.00 +/-     0.00)   334385        4 (   66.34 +/-    34.69)
 999 nsPermissionManager                            96       96        1        1 (    1.00 +/-     0.00)     4731        2 (    8.72 +/-     3.52)
1014 nsPrefBranch                                   76       76     1130        1 (   28.74 +/-    15.03)    11225        1 (   42.96 +/-    24.03)
1058 nsSSLStatus                                    52       52      731        1 (   55.87 +/-    38.54)     7690        1 (  153.67 +/-   124.74)
1169 nsSocketTransport                             312      312     1564        1 (    2.42 +/-     2.38)    41188        3 (   11.94 +/-    10.20)
1170 nsSocketTransportService                      120      120        1        1 (    1.00 +/-     0.00)    51180        2 (   13.19 +/-     2.71)
1180 nsStreamConverterService                       16       16        1        1 (    1.00 +/-     0.00)      130        1 (    2.95 +/-     0.75)
1185 nsStrictTransportSecurityService               60       60        1        1 (    1.00 +/-     0.00)      697        1 (    3.99 +/-     0.72)
1186 nsStringBuffer                                  8      288  7026625       36 (39249.61 +/-  9103.86) 19894616       36 (60922.84 +/- 13671.01)
1235 nsTArray_base                                   4       16 78645686        4 (73002.70 +/- 18606.02)        0        0 (    0.00 +/-     0.00)
1280 nsUnicodeNormalizer                            12       12        1        1 (    1.00 +/-     0.00)        4        1 (    1.71 +/-     0.76)
1296 nsVoidArray                                     4       68  3186889       17 (13938.05 +/-  4921.38)        0        0 (    0.00 +/-     0.00)
1299 nsWeakReference                                16       80    78854        5 ( 1832.42 +/-   730.22)  1512026        5 ( 6229.91 +/-  1934.24)
}
Comment 1 Nicholas Nethercote [:njn] 2012-07-12 19:01:55 PDT
Ed, is this a new leak?
Comment 2 Ed Morley [:emorley] 2012-07-13 01:58:40 PDT
This is the first I have seen of it.

There are also a number of other [orange] leaks, don't know if they should be marked [MemShrink] too?

https://bugzilla.mozilla.org/buglist.cgi?short_desc=leak%20bytes;resolution=---;status_whiteboard_type=allwordssubstr;chfieldto=Now;query_format=advanced;chfieldfrom=-30d;status_whiteboard=[orange];short_desc_type=allwordssubstr
Comment 7 Phil Ringnalda (:philor, back in August) 2012-08-20 00:00:48 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=14520029&tree=Mozilla-Inbound
Comment 8 Ryan VanderMeulen [:RyanVM] 2012-08-24 20:26:06 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=14668824&tree=Try
Comment 14 Phil Ringnalda (:philor, back in August) 2012-09-15 20:52:16 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15247921&tree=Mozilla-Inbound
Comment 15 Phil Ringnalda (:philor, back in August) 2012-09-16 10:01:37 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15251139&tree=Mozilla-Inbound
Comment 16 Phil Ringnalda (:philor, back in August) 2012-09-16 10:42:59 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15254468&tree=Mozilla-Inbound
Comment 17 Phil Ringnalda (:philor, back in August) 2012-09-16 15:15:57 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15257053&tree=Mozilla-Inbound
Comment 18 Phil Ringnalda (:philor, back in August) 2012-09-16 15:59:32 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15258062&tree=Mozilla-Inbound
Comment 19 Phil Ringnalda (:philor, back in August) 2012-09-16 18:33:06 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15260294&tree=Mozilla-Inbound
Comment 20 Phil Ringnalda (:philor, back in August) 2012-09-17 00:16:06 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15264340&tree=Mozilla-Inbound
Comment 21 Phil Ringnalda (:philor, back in August) 2012-09-17 00:22:30 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15264585&tree=Mozilla-Inbound
Comment 22 Phil Ringnalda (:philor, back in August) 2012-09-17 00:54:44 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15265225&tree=Mozilla-Inbound
Comment 27 Ed Morley [:emorley] 2012-09-17 07:10:22 PDT
This has regressed significantly recently.

First of the new occurrences on OS X 10.8 is:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&jobname=Rev5%20MacOSX%20Mountain%20Lion%2010.8%20mozilla-inbound%20debug%20test%20mochitest-other&rev=70ced7d14f3c

Have retriggered a loads of runs prior.
Comment 28 Ed Morley [:emorley] 2012-09-17 09:41:35 PDT
(In reply to Ed Morley (Away 18th-20th) [:edmorley UTC+1] from comment #27)
> This has regressed significantly recently.
> 
> First of the new occurrences on OS X 10.8 is:
> https://tbpl.mozilla.org/?tree=Mozilla-
> Inbound&jobname=Rev5%20MacOSX%20Mountain%20Lion%2010.8%20mozilla-
> inbound%20debug%20test%20mochitest-other&rev=70ced7d14f3c
> 
> Have retriggered a loads of runs prior.

Was caused by this push:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&jobname=Rev5%20MacOSX%20Mountain%20Lion%2010.8%20mozilla-inbound%20debug%20test%20mochitest-other&rev=6d71ff5b4b36

Have backed out 3 of the 4 csets; hopefully should do the trick :-)
Comment 29 Phil Ringnalda (:philor, back in August) 2012-09-17 23:32:41 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15297078&tree=Fx-Team
Comment 32 Phil Ringnalda (:philor, back in August) 2012-09-18 13:03:09 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=15312995&tree=Mozilla-Inbound
Comment 33 Patrick McManus [:mcmanus] 2012-09-26 13:34:03 PDT
this bug blocks 769764 because checking in that code turns this from random orange to often orange on os x 10.8. AFAICT that's coincidental due to a change in timing.

the key item being leaked here is the nsHttpConnection.. I'm not sure if the path is the same as 792511 or not.

in the orange iteration of the test a spdy session is established to www.google.com and that connection fails a IsAlive() check at some point. I don't really know why that happens, but it happens in the green version too so tracking it down is a low roi activity [I suspect it needs security callbacks that have gone away]. This forces the spdysession to close, and the connection to get passed back to the connection manger via the reclaim logic. It can't be reused (IsAlive() fails after all) so connection->close() is called and then the entry is removed from the connection manager list along with that reference.

Normally that's the last ref and the connection object dtors and takes the spdy object and the transport object and the reference to the protocol handler with it. And when the test is green, that's what happens.

But when its orange there is still a ref on the nshttpconnection object. It turns out to be the nsIAsyncOutputStream (aka mSocketOut) has a callback to nsHttpConnection (as it also implements nsIOutputStreamCallback) and nothing clears that up. So we sit there.

The obvious fix (clearing the callbacks in mSocketIn and mSocketOut during errors in close()) results in a different leak; so a fix isn't done yet.
Comment 34 Patrick McManus [:mcmanus] 2012-09-27 05:59:00 PDT
Created attachment 665385 [details] [diff] [review]
patch 0

(Christian, this one is kind of time sensitive because it blocks other work - and its just 2 lines long. if you could look at it ASAP I would appreciate it.)

clear the callbacks in mSocketOut on the error path of nsHttpConnection::Close().

mSocketIn is not treated similarly because the closed socket on the input path will result in a successful EOF callback that clears mSocketIn naturally.
Comment 35 Patrick McManus [:mcmanus] 2012-09-27 06:49:03 PDT
try runs of interest:

https://tbpl.mozilla.org/?tree=Try&rev=86ddfa4181ff shows just this patch for regression testing

https://tbpl.mozilla.org/?tree=Try&rev=1d426c2ccd70 shows this patch plus 769764 for a large number of mochi-other on osx 10.8 debug without generating the leak which is common with 769764 without this patch on that platform

https://tbpl.mozilla.org/?tree=Try&rev=7d9eb7dbad66 shows this patch with the other reviewed proxy patches (the complete push) cross platform for regression testing purposes.
Comment 36 Honza Bambas (:mayhemer) 2012-09-27 08:09:09 PDT
Comment on attachment 665385 [details] [diff] [review]
patch 0

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

Disclaimer: I don't see a problem with this, but I also cannot confirm there isn't any ;)

::: netwerk/protocol/http/nsHttpConnection.cpp
@@ +488,5 @@
>              mSocketTransport->SetSecurityCallbacks(nullptr);
>              mSocketTransport->SetEventSink(nullptr, nullptr);
>              mSocketTransport->Close(reason);
> +            if (mSocketOut)
> +                mSocketOut->AsyncWait(nullptr, 0, 0, nullptr);

Could it happen that this releases the last reference?

If there is some suspicion, then I would rather set mKeepAlive = false before all these unassignments.
Comment 37 Patrick McManus [:mcmanus] 2012-09-27 08:26:37 PDT
Honza, thanks for looking at this!

(In reply to Honza Bambas (:mayhemer) from comment #36)
>;
> 
> Could it happen that this releases the last reference?
> 
> If there is some suspicion, then I would rather set mKeepAlive = false
> before all these unassignments.

I think that can't happen - the caller should have a reference to the object.

if that weren't the case we'd already be crashing on the mKeepalive reference, or even the mSocketTransport->Close() deref of this->mSocketTransport as SetEventSink(nullptr) would have dropped the last ref to the connection object.. (because generally mSocket[In,Out] are not holding a reference, though this bug shows there are exceptions)
Comment 38 Patrick McManus [:mcmanus] 2012-09-27 10:35:30 PDT
https://hg.mozilla.org/integration/mozilla-inbound/rev/198e780680c1
Comment 39 Ryan VanderMeulen [:RyanVM] 2012-09-27 20:17:08 PDT
https://hg.mozilla.org/mozilla-central/rev/198e780680c1

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