New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 175415 link

Starred by 6 users

Issue metadata

Status: Fixed
Owner:
Email to this user bounced
Closed: Mar 2013
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 1
Type: Bug-Regression

Blocked on:
issue 177119



Sign in to add a comment

~60% regression in Cookie.TimeLoadDBQueueWait on Mac and Windows in M25

Project Member Reported by sullivan@chromium.org, Feb 11 2013

Issue description

Windows:
https://uma.googleplex.com/timeline/#metric=Cookie.TimeLoadDBQueueWait&platform=win&channels=beta&dateRange=2012.9.21-2013.2.10&yAxis=zero&measure=geometric_mean&relative=false
There is a regression on dev channel starting on 11/13 when M25 is released to dev. And on beta channel on 1/14 when M25 is released to beta. Canary channel regresses slowly from 10/24 to 12/18, so I can't pinpoint a revision where the regression started.

The Mac graph also shows regressions:
https://uma.googleplex.com/timeline/#metric=Cookie.TimeLoadDBQueueWait&platform=mac&channels=beta&dateRange=2012.9.21-2013.2.10&yAxis=zero&measure=geometric_mean&relative=false
 

Comment 1 by mmenke@chromium.org, Feb 11 2013

Cc: rdsmith@chromium.org

Comment 2 by mmenke@chromium.org, Feb 11 2013

Labels: Area-Internals Internals-Network-Cookies
Labels: -Pri-2 Pri-1 Mstone-26
Owner: erikwright@chromium.org
Status: Assigned
This metric records the amount of time elapsed from the initial request to initialize the cookie store until the first task is scheduled on the DB thread.

If it regresses, that implies that the DB thread is getting increasingly bogged down - either by many tasks or by few larger tasks.

Perhaps it makes sense to move the cookie store to use the blocking pool instead of the DB thread for file access, but I don't think this is something that could go to Beta.

I'll mark as M26 for now. This is something that could have a significant impact on startup times. UMA is down at the moment but I'll try to see if other metrics reflect a user-visible regression.
Labels: ReleaseBlock-Beta
Labels: -ReleaseBlock-Beta ReleaseBlock-Stable
erikwright: any updates on this bug?
Looking at it today. May get a patch up today, else Tuesday.
That being said, I think we will only know if it helps by watching the
metrics on Canary.
Blockedon: chromium:177119
Cc: willchan@chromium.org
Would it be worthwhile trying to do some detective work about what's running on the DB thread during startup?  If the DB thread is getting bogged down, getting cookies out of the pool is one bit of goodness, but we might want to take a bigger picture perspective as well.

[Will, feel free to take yourself back off this thread if you have no interest; I'm ccing you just because I know you've been worrying about performance recently, and this issue might catch your fancy.]
More data:

M25 went to stable on the 21st of February. Comparing the M25 stable population on Feb 22nd (12 million reports) to the M24 stable population on Feb 8th (95 million reports):

TimeLoadDBQueueWait is nearly identical for the first 80th percentile. For the 90th percentile, it's already 70ms and it grows to .5s for 95th up to 3s for the 99.5th.

For TimeKeyLoadDBQueueWait (the delay before cookies blocking a network request begin loading), performance actually improved for the 90th percentile but decline for the final 10 similar to the previous metric.

For PriorityLoadCount (the number of distinct eTLD for which cookies are accessed prior to the whole store loading), performance actually improved across the board in M25.

Likewise for PriorityBlockingTime (the duration of time during which there were network requests waiting for cookies to load).

Caveats:

1) The population on M25 as of the 22nd is still incomplete and may be skewed.
2) The priority blocking count and time would also be "improved" if some other regression were preventing network requests from starting, thus giving the loading of the cookie store a head start. This is probably the most likely explanation for the gap between the DBQueueWait metrics and the priority blocking metrics.
rdsmith: I don't see any merit in tracking down what's blocking the DB thread during startup.

This is a thread that is expressly designed for doing blocking work. It makes more sense, instead, to move all of the work on the DB thread to the blocking pool, where long tasks will have a reduced impact on overall performance.
Cc: jeremy@chromium.org
Cc: -willchan@chromium.org
I'm very interested, but I'm unfortunately interested in more things than I have time for :( Jeremy may have opinions here. Removing myself.
Two CLs LGTM'd for this:

1. Fix a bug in SequencedWorkerPool
2. Convert SQLitePersistentCookieStore to the SequencedTaskRunner API (vs. MessageLoop), though still backed by the IO/DB threads.

Third CL will swap the DB thread for the blocking pool. This ought to improve performance, but the effect will need to be observed on Canary to be sure.

The first CL is simple and probably safe but in a sensitive part of the code where it could conceivably lead to crashes if clients are relying on the old buggy behaviour. As such it will need to be closely monitored before getting merged.
Project Member

Comment 15 by bugdroid1@chromium.org, Feb 27 2013

The following revision refers to this bug:
    http://src.chromium.org/viewvc/chrome?view=rev&revision=184868

------------------------------------------------------------------------
r184868 | erikwright@chromium.org | 2013-02-27T04:15:02.051901Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store_perftest.cc?r1=184868&r2=184867&pathrev=184868
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store_unittest.cc?r1=184868&r2=184867&pathrev=184868
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store.cc?r1=184868&r2=184867&pathrev=184868
   M http://src.chromium.org/viewvc/chrome/trunk/src/base/base.gyp?r1=184868&r2=184867&pathrev=184868
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store.h?r1=184868&r2=184867&pathrev=184868
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/safe_browsing/safe_browsing_service.cc?r1=184868&r2=184867&pathrev=184868
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/profiles/profile_impl_io_data.cc?r1=184868&r2=184867&pathrev=184868

Make SQLitePersistentCookieStore run on injected SequencedTaskRunners vs named BrowserThreads.

In a follow-up, I will make the production code run on the worker pool, which will hopefully speed up browser startup by eliminating delays due to other long-running DB thread tasks.

R=rdsmith@chromium.org
TBR=jar@chromium.org,mmenke@chromium.org
BUG= 175415 


Review URL: https://chromiumcodereview.appspot.com/12314015
------------------------------------------------------------------------
Project Member

Comment 16 by bugdroid1@chromium.org, Feb 27 2013

The following revision refers to this bug:
    http://src.chromium.org/viewvc/chrome?view=rev&revision=184874

------------------------------------------------------------------------
r184874 | mpearson@chromium.org | 2013-02-27T04:36:45.797413Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store_unittest.cc?r1=184874&r2=184873&pathrev=184874
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store.cc?r1=184874&r2=184873&pathrev=184874
   M http://src.chromium.org/viewvc/chrome/trunk/src/base/base.gyp?r1=184874&r2=184873&pathrev=184874
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store.h?r1=184874&r2=184873&pathrev=184874
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/safe_browsing/safe_browsing_service.cc?r1=184874&r2=184873&pathrev=184874
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/profiles/profile_impl_io_data.cc?r1=184874&r2=184873&pathrev=184874
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store_perftest.cc?r1=184874&r2=184873&pathrev=184874

Revert 184868

Seems to cause timeout in MultiThreadedCookieMonsterTest.ThreadCheckDeleteCanonicalCookie
http://build.chromium.org/p/chromium.memory/builders/Linux%20ASAN%20Tests%20%281%29/builds/6970

I often chalk timeouts up to flakes and reopen the tree and wait
but this failure (threading + cookies) seems to directly relevant to
this changelist I'm just going ahead to revert.


> Make SQLitePersistentCookieStore run on injected SequencedTaskRunners vs named BrowserThreads.
> 
> In a follow-up, I will make the production code run on the worker pool, which will hopefully speed up browser startup by eliminating delays due to other long-running DB thread tasks.
> 
> R=rdsmith@chromium.org
> TBR=jar@chromium.org,mmenke@chromium.org
> BUG= 175415 
> 
> 
> Review URL: https://chromiumcodereview.appspot.com/12314015

TBR=erikwright@chromium.org
Review URL: https://codereview.chromium.org/12342030
------------------------------------------------------------------------
While the rationale for the revert is quite reasonable, in this case it turns out to be unwarranted.

The CL affects the persistent cookie store implementation in chrome/browser/net whereas the hanging test is in net_unittests and tests only the cookie monster (the in-memory cookie model). In fact, the failing test does not link to the changed code.
Project Member

Comment 18 by bugdroid1@chromium.org, Feb 27 2013

The following revision refers to this bug:
    http://src.chromium.org/viewvc/chrome?view=rev&revision=184879

------------------------------------------------------------------------
r184879 | erikwright@chromium.org | 2013-02-27T05:17:32.456898Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/trunk/src/base/base.gyp?r1=184879&r2=184878&pathrev=184879
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store.h?r1=184879&r2=184878&pathrev=184879
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/safe_browsing/safe_browsing_service.cc?r1=184879&r2=184878&pathrev=184879
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/profiles/profile_impl_io_data.cc?r1=184879&r2=184878&pathrev=184879
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store_perftest.cc?r1=184879&r2=184878&pathrev=184879
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store_unittest.cc?r1=184879&r2=184878&pathrev=184879
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/net/sqlite_persistent_cookie_store.cc?r1=184879&r2=184878&pathrev=184879

Make SQLitePersistentCookieStore run on injected SequencedTaskRunners vs named BrowserThreads.

In a follow-up, I will make the production code run on the worker pool, which will hopefully speed up browser startup by eliminating delays due to other long-running DB thread tasks.

R=rdsmith@chromium.org
TBR=jar@chromium.org,mmenke@chromium.org
BUG= 175415 


Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=184868

Review URL: https://chromiumcodereview.appspot.com/12314015
------------------------------------------------------------------------
Project Member

Comment 19 by bugdroid1@chromium.org, Feb 27 2013

The following revision refers to this bug:
    http://src.chromium.org/viewvc/chrome?view=rev&revision=185052

------------------------------------------------------------------------
r185052 | erikwright@chromium.org | 2013-02-27T22:02:31.323913Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/trunk/src/chrome/browser/profiles/profile_impl_io_data.cc?r1=185052&r2=185051&pathrev=185052

Move cookie DB to the blocking pool.


R=mmenke@chromium.org
BUG= 175415 


Review URL: https://chromiumcodereview.appspot.com/12321143
------------------------------------------------------------------------
Labels: Merge-Requested
This change was in Canary 27.0.1425.2 (Feb 28), which I have compared against the preceding Canary 27.0.1424.0 (Feb 27). Note that there are about 50% more reports from 1424 than the newer release.

Firstly, although there were concerns about unexpected side-effects of the SequencedWorkerPool change, crash reports do not indicate any relevant new crashes.

Secondly, the change seems to have improved performance. Dramatically.

Cookie.PriorityBlockingTime
	1424	1425.2
50.00%	0.9134	0.8945	
60.00%	10.77	7.675	
70.00%	35.55	20.93	
80.00%	147.8	63.62	
90.00%	1183	364.9	
95.00%	4668	1375	
98.00%	14070	3538	
99.00%	24166	5701	
99.50%	37081	7835	

Note that the improvement stretches across the board - 3ms at the 60th percentile, 85ms at the 70th, and more than 3s at the 95th.

This is a measure of time that users waited before network requests could be initiated during browser startup. 5% of users should see their browser load _seconds_ faster with these changes.
Labels: -Merge-Requested Merge-Approved
Project Member

Comment 22 by bugdroid1@chromium.org, Mar 1 2013

The following revision refers to this bug:
    http://src.chromium.org/viewvc/chrome?view=rev&revision=185574

------------------------------------------------------------------------
r185574 | erikwright@chromium.org | 2013-03-01T19:42:16.695566Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/branches/1410/src/chrome/browser/profiles/profile_impl_io_data.cc?r1=185574&r2=185573&pathrev=185574

Merge 185052
> Move cookie DB to the blocking pool.
> 
> 
> R=mmenke@chromium.org
> BUG= 175415 
> 
> 
> Review URL: https://chromiumcodereview.appspot.com/12321143

TBR=erikwright@chromium.org
Review URL: https://codereview.chromium.org/12381046
------------------------------------------------------------------------
Project Member

Comment 23 by bugdroid1@chromium.org, Mar 1 2013

Labels: -Merge-Approved merge-merged-1410
The following revision refers to this bug:
    http://src.chromium.org/viewvc/chrome?view=rev&revision=185573

------------------------------------------------------------------------
r185573 | erikwright@chromium.org | 2013-03-01T19:41:00.114864Z

Changed paths:
   M http://src.chromium.org/viewvc/chrome/branches/1410/src/chrome/browser/net/sqlite_persistent_cookie_store_unittest.cc?r1=185573&r2=185572&pathrev=185573
   M http://src.chromium.org/viewvc/chrome/branches/1410/src/chrome/browser/net/sqlite_persistent_cookie_store.cc?r1=185573&r2=185572&pathrev=185573
   M http://src.chromium.org/viewvc/chrome/branches/1410/src/base/base.gyp?r1=185573&r2=185572&pathrev=185573
   M http://src.chromium.org/viewvc/chrome/branches/1410/src/chrome/browser/net/sqlite_persistent_cookie_store.h?r1=185573&r2=185572&pathrev=185573
   M http://src.chromium.org/viewvc/chrome/branches/1410/src/chrome/browser/safe_browsing/safe_browsing_service.cc?r1=185573&r2=185572&pathrev=185573
   M http://src.chromium.org/viewvc/chrome/branches/1410/src/chrome/browser/profiles/profile_impl_io_data.cc?r1=185573&r2=185572&pathrev=185573
   M http://src.chromium.org/viewvc/chrome/branches/1410/src/chrome/browser/net/sqlite_persistent_cookie_store_perftest.cc?r1=185573&r2=185572&pathrev=185573

Merge 184868
> Make SQLitePersistentCookieStore run on injected SequencedTaskRunners vs named BrowserThreads.
> 
> In a follow-up, I will make the production code run on the worker pool, which will hopefully speed up browser startup by eliminating delays due to other long-running DB thread tasks.
> 
> R=rdsmith@chromium.org
> TBR=jar@chromium.org,mmenke@chromium.org
> BUG= 175415 
> 
> 
> Review URL: https://chromiumcodereview.appspot.com/12314015

TBR=erikwright@chromium.org
Review URL: https://codereview.chromium.org/12387046
------------------------------------------------------------------------
Status: Fixed
Awesome! thanks for fixing it :)

Marking it as fixed for now.
Nice fix. It looks like a new version of the 1410 branch went out yesterday. Have you seen similar performance wins there?
Project Member

Comment 28 by bugdroid1@chromium.org, Mar 9 2013

Labels: -Type-Regression -Stability-Performance -Area-Internals -Internals-Network-Cookies -Mstone-26 Type-Bug-Regression Cr-Internals-Network-Cookies Cr-Internals M-26 Performance
Labels: -PerfRegression Performance-Sheriff

Sign in to add a comment