All graphs for this bug:
  https://chromeperf.appspot.com/group_report?bug_id=663032

Original alerts at time of bug-filing:
  https://chromeperf.appspot.com/group_report?keys=agxzfmNocm9tZXBlcmZyFAsSB0Fub21hbHkYgICg7any4wgM


Bot(s) for this bug's original alert(s):

chromium-rel-mac-retina

Started bisect job https://chromeperf.appspot.com/buildbucket_job_status/8996622983109745904

Started bisect job https://chromeperf.appspot.com/buildbucket_job_status/8996622954546883088

=== Auto-CCing suspected CL author csharrison@chromium.org ===

Hi csharrison@chromium.org, the bisect results pointed to your CL below as possibly
causing a regression. Please have a look at this info and see whether
your CL be related.


===== BISECT JOB RESULTS =====
Status: completed


===== SUSPECTED CL(s) =====
Subject : Avoid initializing a SecurityOrigin from a KURL for isSecure() check.
Author  : csharrison
Commit description:
  
Initializing a SecurityOrigin is not cheap. We should avoid it where possible.

Initialization causes
 - Looking up the origin in a map (blobs)
 - FastMalloc the origin
 - Many calls to StringImpl::lower() which causes allocation
 - HashMap lookups for e.g. shouldTreatURLSchemeAsLocal

This saves ~1% overhead off of resource requesting.

BUG=348655

Review-Url: https://codereview.chromium.org/2417883002
Cr-Commit-Position: refs/heads/master@{#425946}
Commit  : 616c7df79bbc2d892ecee0305dff57a0faaf80a2
Date    : Tue Oct 18 13:48:13 2016


===== TESTED REVISIONS =====
Revision         Mean     Std Dev   N  Good?
chromium@425916  25.0765  1.18615   5  good
chromium@425937  25.2802  1.49401   5  good
chromium@425942  25.8856  1.01359   5  good
chromium@425945  25.2679  1.34488   5  good
chromium@425946  37.7085  1.74959   5  bad    <--
chromium@425947  38.615   0.570891  5  bad
chromium@425957  38.1084  0.617416  5  bad

Bisect job ran on: mac_retina_perf_bisect
Bug ID: 663032

Test Command: src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=blob.create.read.10MBx30 blob_storage.blob_storage
Test Metric: blob-reads/Action_CreateAndReadBlob/blob-create-read-10MBx30
Relative Change: 51.97%
Score: 99.9

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/mac_retina_perf_bisect/builds/1792
Job details: https://chromeperf.appspot.com/buildbucket_job_status/8996622954546883088


Not what you expected? We'll investigate and get back to you!
  https://chromeperf.appspot.com/bad_bisect?try_job_id=5816874770628608

| O O | Visit http://www.chromium.org/developers/speed-infra/perf-bug-faq
|  X  | for more information addressing perf regression bugs. For feedback,
| / \ | file a bug with component Tests>AutoBisect.  Thank you!

Hm. This CL only adds a single isEmpty() check on a global set as overhead.

I wonder if it is possible that the test is only acting on unique origins, so this change suddenly starts actually initializing the trustworthy origin set.

Mike, do you have any ideas?

===== BISECT JOB RESULTS =====
Status: completed


===== SUSPECTED CL(s) =====
Subject : Avoid initializing a SecurityOrigin from a KURL for isSecure() check.
Author  : csharrison
Commit description:
  
Initializing a SecurityOrigin is not cheap. We should avoid it where possible.

Initialization causes
 - Looking up the origin in a map (blobs)
 - FastMalloc the origin
 - Many calls to StringImpl::lower() which causes allocation
 - HashMap lookups for e.g. shouldTreatURLSchemeAsLocal

This saves ~1% overhead off of resource requesting.

BUG=348655

Review-Url: https://codereview.chromium.org/2417883002
Cr-Commit-Position: refs/heads/master@{#425946}
Commit  : 616c7df79bbc2d892ecee0305dff57a0faaf80a2
Date    : Tue Oct 18 13:48:13 2016


===== TESTED REVISIONS =====
Revision         Mean     Std Dev    N  Good?
chromium@425916  4.22493  0.0505475  5  good
chromium@425937  4.29599  0.0939762  5  good
chromium@425942  4.29919  0.152655   5  good
chromium@425945  4.2613   0.0703349  5  good
chromium@425946  4.99695  0.0377969  5  bad    <--
chromium@425947  4.9797   0.0459465  5  bad
chromium@425957  4.92674  0.122271   5  bad

Bisect job ran on: mac_retina_perf_bisect
Bug ID: 663032

Test Command: src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests blob_storage.blob_storage
Test Metric: blob-reads/Action_CreateAndReadBlob
Relative Change: 16.61%
Score: 99.9

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/mac_retina_perf_bisect/builds/1791
Job details: https://chromeperf.appspot.com/buildbucket_job_status/8996622983109745904


Not what you expected? We'll investigate and get back to you!
  https://chromeperf.appspot.com/bad_bisect?try_job_id=5883863778197504

| O O | Visit http://www.chromium.org/developers/speed-infra/perf-bug-faq
|  X  | for more information addressing perf regression bugs. For feedback,
| / \ | file a bug with component Tests>AutoBisect.  Thank you!

This probably isn't a big deal, as we're talking nanoseconds. I'm fine with this regression.

Same here. Let's wontfix it.

Actually, this had the largest effect on the 30x10MB test case (Where we create 30 10MB blobs). It went from 25ms for create-to-read time to 37ms. That seems weird for one extra method call.

I ran the 10mbx30 test locally with some extra traces, and the isUrlWhitelistedTrustworthy method took .2ms in aggregate on my workstation.

I'm stumped as to how we're regressing things by 13ms. These origins aren't unique, so we actually should be saving time here!

Started bisect job https://chromeperf.appspot.com/buildbucket_job_status/8996521858887512736

Huh. I kicked off another bisect. It's the blob-create-and-read test, with the read metric.

https://chromeperf.appspot.com/report?sid=033f2cdd4e430e1379e41e61bac59323dd8416e5bfbfd7dc4d62e3067b76b3a9&start_rev=423958&end_rev=430714

===== BISECT JOB RESULTS =====
Status: completed


===== SUSPECTED CL(s) =====
Subject : Avoid initializing a SecurityOrigin from a KURL for isSecure() check.
Author  : csharrison
Commit description:
  
Initializing a SecurityOrigin is not cheap. We should avoid it where possible.

Initialization causes
 - Looking up the origin in a map (blobs)
 - FastMalloc the origin
 - Many calls to StringImpl::lower() which causes allocation
 - HashMap lookups for e.g. shouldTreatURLSchemeAsLocal

This saves ~1% overhead off of resource requesting.

BUG=348655

Review-Url: https://codereview.chromium.org/2417883002
Cr-Commit-Position: refs/heads/master@{#425946}
Commit  : 616c7df79bbc2d892ecee0305dff57a0faaf80a2
Date    : Tue Oct 18 13:48:13 2016


===== TESTED REVISIONS =====
Revision         Mean     Std Dev   N  Good?
chromium@425916  25.7779  1.90393   5  good
chromium@425937  25.1766  0.718261  5  good
chromium@425942  25.3099  0.839687  5  good
chromium@425945  26.4037  1.66587   5  good
chromium@425946  37.2944  1.08301   5  bad    <--
chromium@425947  38.3374  0.580876  5  bad
chromium@425957  37.7444  0.419125  5  bad

Bisect job ran on: mac_retina_perf_bisect
Bug ID: 663032

Test Command: src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=blob.create.read.10MBx30 blob_storage.blob_storage
Test Metric: blob-reads/Action_CreateAndReadBlob/blob-create-read-10MBx30
Relative Change: 46.42%
Score: 99.9

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/mac_retina_perf_bisect/builds/1806
Job details: https://chromeperf.appspot.com/buildbucket_job_status/8996521858887512736


Not what you expected? We'll investigate and get back to you!
  https://chromeperf.appspot.com/bad_bisect?try_job_id=5233384001896448

| O O | Visit http://www.chromium.org/developers/speed-infra/perf-bug-faq
|  X  | for more information addressing perf regression bugs. For feedback,
| / \ | file a bug with component Tests>AutoBisect.  Thank you!

:/ hrm. I can do a bit more digging tomorrow.

I'm looking at this again. Is the "read metric" notated as "BlobRequest" in the traces?

I also noticed that it seems we are regressing to our performance in this metric from where we were in august. I wonder if there is some subtle scheduling issue somewhere that we are triggering.

Yeah, the metrics are here:
https://cs.chromium.org/chromium/src/third_party/catapult/telemetry/telemetry/web_perf/metrics/blob_timeline.py?dr=C&sq=package:chromium

I think we add up all of the read event times. So this could be effected by scheduling, yes. Nothing should be on disk though.

From looking at traces I see a bimodal pattern, depending on when we execute BlobStorageMsg_MemoryItemResponse (which takes 13-20ms on my Linux desktop).

If we service the BlobStorageMsg_MemoryItemResponse ipc after the actual resource request, it is included in BlobRequest time. If we service it before, then it is not included in BlobRequest time.

I've attached a trace where you can see this. The race is between the resource request IPC and the request memory IPC. If the request wins we see worse metrics.

Deleted: blob_create_read.html 5.0 MB

blob_create_read.html 5.0 MB View Download

Wow! That totally makes sense. Thanks for looking into this, we can mark this as wontfix then.

This probably explains a LOT of the bimodal behavior we've seen w/ other storage benchmarks. I wonder if we can do smarter tracing here. I guess the main culprit is the event queue, which we have no control over.

No problem. It is a very tricky problem in general to fix this.

In this case one metric that avoids this bimodality would be |BlobRequest - BlobRequest::CountSize|.

We *should* try to fix this though, as right now the mean/median does not really make sense, and is probably way more noisy than a fixed metric.