852467 - nsDisableOldMaxSmartSizePrefEvent runs on the gecko main thread, blocks for long periods of time

Status: RESOLVED FIXED

(Core :: Networking: Cache, defect)

Description

[Kartikaya Gupta (email:[e-mail])]

See https://bugzilla.mozilla.org/show_bug.cgi?id=797615#c342.

The fact that this runnable runs on the gecko main thread and blocks on the cache in the call to nsCacheService::SetDiskSmartSize(); means that other things that need to run on the gecko main thread (e.g. some quick compositor operations) don't get to run for many seconds (I reported seeing a delay of ~18 seconds in bug 797615 comment 326). The Java UI thread needs to run these operations synchronously and times out waiting for the operations to run, which snowballs into various graphics initialization errors and much badness.

Also tagging as snappy because an 18-second block on the gecko main thread seems pretty bad.

Comment 1

[Kartikaya Gupta (email:[e-mail])]

Disabling the disk cache also fixes the intermittent testSystemPages failure. (https://tbpl.mozilla.org/?tree=Try&rev=336832f5b5d5)

Comment 2

[Jason Duell]

Poked at this, and it looks like the only obvious thing that could cause the blocking here is that the code grabs the cache lock.  So the real culprit is whatever other code is holding the lock for that time.

Comment 3

[Kartikaya Gupta (email:[e-mail])]

The try build log at [1] has the stack traces for all the threads (there are 12 instances of the crash in that log file, but they are all very similar). As an example, from the first crash in that log, there are threads running in methods like:

nsHttpConnectionMgr::GetSpdyPreferredConn(nsHttpConnectionMgr::nsConnectionEntry*)

and

nsDiskCacheBlockFile::Open(nsIFile*, unsigned int, unsigned int, nsDiskCache::CorruptCacheInfo*)

I don't know this code that well but it looks like that second one is probably holding the cache lock.

[1] https://tbpl.mozilla.org/php/getParsedLog.php?id=20803898&tree=Try&full=1

Comment 4

[Brad Lassey [:blassey] (use needinfo?)]

the bug this is blocking is tracking firefox 21

Comment 5

[bhavana bajaj [:bajaj]]

Patrick, spoke to :kats and we believe this falls under the necko team helping out with investigation/next steps here.
Assigning this to you to help with reassignment as needed.

Bug 834243 - which is a top-crasher is blocked on investigation due to this.

Comment 6

[Doug Turner (:dougt)]

Bajaj, How is this bug related to bug 834243?

Comment 7

[bhavana bajaj [:bajaj]]

(In reply to Doug Turner (:dougt) from comment #6)
> Bajaj, How is this bug related to bug 834243?

Doug, Check : https://bugzilla.mozilla.org/show_bug.cgi?id=834243#c28 , https://bugzilla.mozilla.org/show_bug.cgi?id=834243#c27 . I also checked with :kats & he said we need help from necko team resolve this issue to move forward on the top- crasher.

Comment 8

[Kartikaya Gupta (email:[e-mail])]

Most of my investigation about why this is a problem is on bug 797615. See comment 342 and nearby comments on that bug.

Comment 9

[Doug Turner (:dougt)]

Kats, do you know what the other threads are doing when we are holding that lock?

Comment 10

[Michal Novotny [:michal]]

(In reply to Doug Turner (:dougt) from comment #9)
> Kats, do you know what the other threads are doing when we are holding that
> lock?

The thread that is holding the lock is opening the disk cache. It seems that just opening few files and reading headers/bitmaps takes ages on android. 

I'm currently testing a fix for this issue on try server https://tbpl.mozilla.org/?tree=Try&rev=8626f02da4d4

Comment 11

[Michal Novotny [:michal]]

Attachment: fix

Comment 12

[Michal Novotny [:michal]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/e73333270ce5

Comment 13

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/e73333270ce5