New issue
Advanced search Search tips

Issue 645686 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Jan 2017
Components:
EstimatedDays: ----
NextAction: ----
OS: All
Pri: 2
Type: Bug

Blocked on:
issue 645308

Blocking:
issue 645685



Sign in to add a comment

Instrument code related to Offline Page Caching to ease investigating perf regressions

Project Member Reported by carlosk@chromium.org, Sep 9 2016

Issue description

To facilitate investigating performance regressions we need to instrument the critical code paths used by Offline Page Caching. We're currently adding more tracing and UMA histograms.

Note: Setting OS to All as there might be code touched that is outside of the Android-only trees.
 
Blockedon: 645308
Status: Started (was: Assigned)
Project Member

Comment 3 by bugdroid1@chromium.org, Sep 21 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/f86fb54ec35e00f6b5b744ddd35dc19049caae7c

commit f86fb54ec35e00f6b5b744ddd35dc19049caae7c
Author: carlosk <carlosk@chromium.org>
Date: Wed Sep 21 18:12:30 2016

Adds tracing to MHTML generation call chain.

This change adds tracing macro calls to many points of the MHTML
generation code over browser and renderer code, both in content and
Blink. These traces should help with futher performance investigations.

A new trace category was created: page-serialization. I don't expect it
to generate much noise so I left is as default-enabled. I also kept the
name not MHTML specific as part of the renderer code seems to be intended
to be more generic.

BUG= 645686 

Review-Url: https://codereview.chromium.org/2344153003
Cr-Commit-Position: refs/heads/master@{#420104}

[modify] https://crrev.com/f86fb54ec35e00f6b5b744ddd35dc19049caae7c/content/browser/download/mhtml_generation_manager.cc
[modify] https://crrev.com/f86fb54ec35e00f6b5b744ddd35dc19049caae7c/content/browser/download/mhtml_generation_manager.h
[modify] https://crrev.com/f86fb54ec35e00f6b5b744ddd35dc19049caae7c/content/renderer/render_frame_impl.cc
[modify] https://crrev.com/f86fb54ec35e00f6b5b744ddd35dc19049caae7c/third_party/WebKit/Source/core/frame/FrameSerializer.cpp
[modify] https://crrev.com/f86fb54ec35e00f6b5b744ddd35dc19049caae7c/third_party/WebKit/Source/web/WebFrameSerializer.cpp

Now that we have tracing, its results made clearer the current potential bottlenecks of the whole MHTML serialization. For those I'll now start adding UMA metrics.

MHTML saving is currently used by a few different known “clients”:
- Extensions through their API.
- ChomeOS for “Save to File”.
- Offline.

Initially I thought it would be useful to break down the metrics by requester "client" but filtering by OS type solves our problem as Offline is currently only enabled on Android where those other clients are not run.

Also adding client-segregated metrics would make the serialization code more complex as we'd have to identify the client in the full call chain, spawning both browser and renderer.

Looking at a current set of Offline histograms, the number of saves executed by Page Caching (aka last_n) is vastly superior to the rest that account for only 0.1452% of collected samples. So we don't need to further split these metrics right now.
Labels: -Pri-3 Pri-2
Project Member

Comment 6 by bugdroid1@chromium.org, Sep 30 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e

commit 0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e
Author: carlosk <carlosk@chromium.org>
Date: Fri Sep 30 00:16:26 2016

Add UMA histograms to MHTML save operations.

In the context of the Offline project we need more information on how
the MHTML save operation is performing, especially in regards to how
much it is interfering with the render process main thread.

This change adds UMA histograms to track the performance of the costlier
operations performed when a page is being saved to MHTML. One new
"PageSerialization" category was added to encompass serialization generically
and a "MhtmlGeneration" sub-category for the MHTML specific parts.

All histograms added in this batch are timing measurements and they map closely
to the tracing instrumentation under the "page-serialization" category.
Following is the list of them with indentation to indicate what encompasses
what:

For the complete page saving operation:

  PageSerialization.MhtmlGeneration.FullPageSavingTime
    PageSerialization.MhtmlGeneration.BrowserWaitForRendererTime.FrameTree
      PageSerialization.MhtmlGeneration.RendererMainThreadTime.FrameTree

For a single frame in a page saving operation:

  PageSerialization.MhtmlGeneration.BrowserWaitForRendererTime.SingleFrame
    PageSerialization.MhtmlGeneration.RendererMainThreadTime.SingleFrame
      PageSerialization.MhtmlGeneration.SerializationTime.SingleFrame
        PageSerialization.SerializationTime.Html
        *PageSerialization.SerializationTime.CSSElement
        *PageSerialization.SerializationTime.ImageElement
      PageSerialization.MhtmlGeneration.EncodingTime.SingleFrame
    PageSerialization.MhtmlGeneration.WriteToDiskTime.SingleFrame

*: may be executed many times under its parent.

BUG= 645686 
CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.linux:linux_site_isolation

Review-Url: https://codereview.chromium.org/2364923004
Cr-Commit-Position: refs/heads/master@{#421989}

[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/content/browser/download/mhtml_generation_manager.cc
[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/content/browser/download/mhtml_generation_manager.h
[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/content/browser/frame_host/render_frame_host_impl.cc
[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/content/browser/frame_host/render_frame_host_impl.h
[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/content/common/frame_messages.h
[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/content/renderer/render_frame_impl.cc
[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/third_party/WebKit/Source/core/frame/FrameSerializer.cpp
[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/third_party/WebKit/Source/core/frame/FrameSerializer.h
[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/third_party/WebKit/Source/web/WebFrameSerializer.cpp
[modify] https://crrev.com/0f5a7e209836a0d22f7ae69ff7729da2a1fccf3e/tools/metrics/histograms/histograms.xml

All timing related histograms I planned to add for now landed with the commit from #6. I still have a couple non-timing related to add -- excess IPC count and precise failure reasons -- but I'll first focus on a few performance improvements.
Project Member

Comment 8 by bugdroid1@chromium.org, Oct 5 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/27fa065af52591c67adba826584ff854beaa0a35

commit 27fa065af52591c67adba826584ff854beaa0a35
Author: carlosk <carlosk@chromium.org>
Date: Wed Oct 05 23:10:36 2016

Move MHTML file writing out of the renderer main thread.

This change moves the step of writing MHTML serialized and encoded data
to file out of the renderer main thread, into its FILE thread. The less
we block the main one, the more responsive the renderer remains which is
good.

Note: I mande a correction to the logic tracked by the UMA histogram
PageSerialization.MhtmlGeneration.WriteToDiskTime.SingleFrame to make sure
it includes the file close operation that might involve a buffer flush
that could be significant.

BUG= 651525 , 645686 

Review-Url: https://codereview.chromium.org/2379823003
Cr-Commit-Position: refs/heads/master@{#423331}

[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/content/renderer/render_frame_impl.cc
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/content/renderer/render_frame_impl.h
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/Source/platform/mhtml/MHTMLArchive.cpp
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/Source/platform/mhtml/MHTMLArchive.h
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/Source/web/WebFrameSerializer.cpp
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/Source/web/tests/MHTMLTest.cpp
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/public/web/WebFrameSerializer.h

Project Member

Comment 9 by bugdroid1@chromium.org, Oct 11 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/90bf4f0c77709ddb65b1f8d86e04065aacae02ac

commit 90bf4f0c77709ddb65b1f8d86e04065aacae02ac
Author: carlosk <carlosk@chromium.org>
Date: Tue Oct 11 00:49:58 2016

UMA histogram for longest renderer main thread usage for page save to MHTML.

The information about the time taken by the main render process thread
for saving a page to MHTML is the main feedback we have to see how much
the operation impacts user experience.

The existing UMA that tracks this information,
PageSerialization.MhtmlGeneration.RendererMainThreadTime.SingleFrame,
is not directly useful for the purpose above because it includes reports
for all frames in a page save operation. For pages with many frames, most
of them are very simple and quickly saved, while one -- generally the
main frame -- is the slowest. So we have a huge amount of low-value
samples pulling the statistics down.

This change adds a new histogram,
PageSerialization.MhtmlGeneration.RendererMainThreadTime.SlowestFrame,
that reports only the longest of all times from the former one in a
single HTML page saving operation, which is the most important one in
terms of user experience.

BUG= 645686 

Review-Url: https://codereview.chromium.org/2400383002
Cr-Commit-Position: refs/heads/master@{#424312}

[modify] https://crrev.com/90bf4f0c77709ddb65b1f8d86e04065aacae02ac/content/browser/download/mhtml_generation_manager.cc
[modify] https://crrev.com/90bf4f0c77709ddb65b1f8d86e04065aacae02ac/tools/metrics/histograms/histograms.xml

Labels: Merge-Request-55
I'd like to request the merge of change 90bf4f0c77709ddb65b1f8d86e04065aacae02ac.
Project Member

Comment 11 by bugdroid1@chromium.org, Oct 11 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/44ec5ba689f1949babb12bd10f5e9b38eb05f257

commit 44ec5ba689f1949babb12bd10f5e9b38eb05f257
Author: carlosk <carlosk@chromium.org>
Date: Tue Oct 11 17:30:15 2016

Fix trace parameter showing gibberish.

The async trace call affected by this CL used to add two |char *| arguments to
the event of type which are *not* copied and were -- one potentially the other
always -- destroyed before they were actually used at the event end. This caused
gibberish to be sometimes presented in the trace report view.

This CL fixes that by converting them to std:string values which are always
stored as copies.

BUG= 645686 

Review-Url: https://codereview.chromium.org/2397233004
Cr-Commit-Position: refs/heads/master@{#424470}

[modify] https://crrev.com/44ec5ba689f1949babb12bd10f5e9b38eb05f257/content/browser/download/mhtml_generation_manager.cc

Comment 12 by dimu@chromium.org, Oct 12 2016

Labels: -Merge-Request-55 Merge-Approved-55 Hotlist-Merge-Approved
Your change meets the bar and is auto-approved for M55 (branch: 2883)
Project Member

Comment 13 by bugdroid1@chromium.org, Oct 12 2016

Labels: -merge-approved-55 merge-merged-2883
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/67c28ff356fd4c8115cefb2ea2fc9bf8510db02c

commit 67c28ff356fd4c8115cefb2ea2fc9bf8510db02c
Author: Carlos Knippschild <carlosk@chromium.org>
Date: Wed Oct 12 18:04:28 2016

UMA histogram for longest renderer main thread usage for page save to MHTML.

The information about the time taken by the main render process thread
for saving a page to MHTML is the main feedback we have to see how much
the operation impacts user experience.

The existing UMA that tracks this information,
PageSerialization.MhtmlGeneration.RendererMainThreadTime.SingleFrame,
is not directly useful for the purpose above because it includes reports
for all frames in a page save operation. For pages with many frames, most
of them are very simple and quickly saved, while one -- generally the
main frame -- is the slowest. So we have a huge amount of low-value
samples pulling the statistics down.

This change adds a new histogram,
PageSerialization.MhtmlGeneration.RendererMainThreadTime.SlowestFrame,
that reports only the longest of all times from the former one in a
single HTML page saving operation, which is the most important one in
terms of user experience.

BUG= 645686 

Review-Url: https://codereview.chromium.org/2400383002
Cr-Commit-Position: refs/heads/master@{#424312}
(cherry picked from commit 90bf4f0c77709ddb65b1f8d86e04065aacae02ac)

Review URL: https://codereview.chromium.org/2413473004 .

Cr-Commit-Position: refs/branch-heads/2883@{#65}
Cr-Branched-From: 614d31daee2f61b0180df403a8ad43f20b9f6dd7-refs/heads/master@{#423768}

[modify] https://crrev.com/67c28ff356fd4c8115cefb2ea2fc9bf8510db02c/content/browser/download/mhtml_generation_manager.cc
[modify] https://crrev.com/67c28ff356fd4c8115cefb2ea2fc9bf8510db02c/tools/metrics/histograms/histograms.xml

For keeping notes, TWO non-timing UMA metrics I still want to add are:

* Record the specific reason why an MHTML save operation failed:

* How many extra FrameMsg_SerializeAsMHTML IPCs are being sent using the current one-request-per-frame when compared to one-request-per-renderer which would be optimal.

For the specific reason why an MHTML save operation can fail these are the *easily detectable* "final statuses" I could find:
- SUCCESS
- FRAME_SERIALIZATION_FORBIDDEN: a frame was not allowed to be serialized by a combination of policy and cache control; determined by the renderer
- FILE_WRITTING_ERROR: could not write serialized data to the file; determined by the renderer
- FILE_CREATION_ERROR: could not create the file that would be written to; determined by the browser
- FRAME_NO_LONGER_EXIST: DOM changed and a previously existing frame is no more; determined by the browser
- RENDER_PROCESS_EXITED: a render process needed to serialize a frame is no more; determined by the browser

What I'm considering less easy is finding sub-reasons within the ones above. For instance: what specific condition caused a policy to forbid the save (for the FRAME_SERIALIZATION_FORBIDDEN status). But I currently don't see why these would be useful.
Another metric to be added: the number of snapshots requested per navigation. This will help us further understand the actual performance impact during a page load. Initial name suggestion: OfflinePageCache.SnapshotsPerPageLoad. 
Project Member

Comment 16 by bugdroid1@chromium.org, Oct 27 2016

Labels: merge-merged-2840
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/27fa065af52591c67adba826584ff854beaa0a35

commit 27fa065af52591c67adba826584ff854beaa0a35
Author: carlosk <carlosk@chromium.org>
Date: Wed Oct 05 23:10:36 2016

Move MHTML file writing out of the renderer main thread.

This change moves the step of writing MHTML serialized and encoded data
to file out of the renderer main thread, into its FILE thread. The less
we block the main one, the more responsive the renderer remains which is
good.

Note: I mande a correction to the logic tracked by the UMA histogram
PageSerialization.MhtmlGeneration.WriteToDiskTime.SingleFrame to make sure
it includes the file close operation that might involve a buffer flush
that could be significant.

BUG= 651525 , 645686 

Review-Url: https://codereview.chromium.org/2379823003
Cr-Commit-Position: refs/heads/master@{#423331}

[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/content/renderer/render_frame_impl.cc
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/content/renderer/render_frame_impl.h
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/Source/platform/mhtml/MHTMLArchive.cpp
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/Source/platform/mhtml/MHTMLArchive.h
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/Source/web/WebFrameSerializer.cpp
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/Source/web/tests/MHTMLTest.cpp
[modify] https://crrev.com/27fa065af52591c67adba826584ff854beaa0a35/third_party/WebKit/public/web/WebFrameSerializer.h

Project Member

Comment 17 by bugdroid1@chromium.org, Oct 27 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/67c28ff356fd4c8115cefb2ea2fc9bf8510db02c

commit 67c28ff356fd4c8115cefb2ea2fc9bf8510db02c
Author: Carlos Knippschild <carlosk@chromium.org>
Date: Wed Oct 12 18:04:28 2016

UMA histogram for longest renderer main thread usage for page save to MHTML.

The information about the time taken by the main render process thread
for saving a page to MHTML is the main feedback we have to see how much
the operation impacts user experience.

The existing UMA that tracks this information,
PageSerialization.MhtmlGeneration.RendererMainThreadTime.SingleFrame,
is not directly useful for the purpose above because it includes reports
for all frames in a page save operation. For pages with many frames, most
of them are very simple and quickly saved, while one -- generally the
main frame -- is the slowest. So we have a huge amount of low-value
samples pulling the statistics down.

This change adds a new histogram,
PageSerialization.MhtmlGeneration.RendererMainThreadTime.SlowestFrame,
that reports only the longest of all times from the former one in a
single HTML page saving operation, which is the most important one in
terms of user experience.

BUG= 645686 

Review-Url: https://codereview.chromium.org/2400383002
Cr-Commit-Position: refs/heads/master@{#424312}
(cherry picked from commit 90bf4f0c77709ddb65b1f8d86e04065aacae02ac)

Review URL: https://codereview.chromium.org/2413473004 .

Cr-Commit-Position: refs/branch-heads/2883@{#65}
Cr-Branched-From: 614d31daee2f61b0180df403a8ad43f20b9f6dd7-refs/heads/master@{#423768}

[modify] https://crrev.com/67c28ff356fd4c8115cefb2ea2fc9bf8510db02c/content/browser/download/mhtml_generation_manager.cc
[modify] https://crrev.com/67c28ff356fd4c8115cefb2ea2fc9bf8510db02c/tools/metrics/histograms/histograms.xml

Comment 18 by dimu@google.com, Nov 4 2016

Labels: -merge-merged-2840
[Automated comment] removing mislabelled merge-merged-2840
Project Member

Comment 19 by bugdroid1@chromium.org, Nov 9 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/d9ff2b43b1dc1fba22fd16a913c979de09687223

commit d9ff2b43b1dc1fba22fd16a913c979de09687223
Author: carlosk <carlosk@chromium.org>
Date: Wed Nov 09 20:42:16 2016

Small tracing improvements to MHTML generation code.

The main objective of this change is to add tracing to the
RenderFrameImpl::OnWriteMHTMLToDiskComplete so that one can see in trace
report the delay introduced by the two thread hops for doing IO in the
file thread: from the "main" to the "file" and then back to "main".

This lead to a few related changes:
- The thread hops are avoided when not actually needed.
- As a consequence the WriteMHTMLToDisk function was slightly simplified.
- And a few outdated code comments were updated.

BUG= 645686 

Review-Url: https://codereview.chromium.org/2490853002
Cr-Commit-Position: refs/heads/master@{#431027}

[modify] https://crrev.com/d9ff2b43b1dc1fba22fd16a913c979de09687223/content/renderer/render_frame_impl.cc

Project Member

Comment 20 by bugdroid1@chromium.org, Nov 29 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/29da4fe0a2b453e474e6cd530332a2ed02f70576

commit 29da4fe0a2b453e474e6cd530332a2ed02f70576
Author: carlosk <carlosk@chromium.org>
Date: Tue Nov 29 00:01:29 2016

Fail when saving page as MHTML provides information about the cause.

This change adds more detailed information to tracing and UMA histograms about
the reason why a MHTML save operation has failed. This will help us understand
why some specific pages consistently fail and better handle these situations.

It introduces a new enum, MhtmlSaveStatus, that lists all tracked causes. Part
of the reasons are tracked by the browser and the others by the render process
but the reporting is centralized in the former. A few tests from
MHTMLGenerationTest were also changed to verify the MHTML failures they test for
are correctly reported.

BUG= 645686 , 655723 ,655708
CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.linux:linux_site_isolation

Review-Url: https://codereview.chromium.org/2519273002
Cr-Commit-Position: refs/heads/master@{#434783}

[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/browser/download/mhtml_generation_browsertest.cc
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/browser/download/mhtml_generation_manager.cc
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/browser/download/mhtml_generation_manager.h
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/browser/frame_host/render_frame_host_impl.cc
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/browser/frame_host/render_frame_host_impl.h
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/common/BUILD.gn
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/common/content_param_traits_macros.h
[add] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/common/download/mhtml_save_status.cc
[add] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/common/download/mhtml_save_status.h
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/common/frame_messages.h
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/renderer/render_frame_impl.cc
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/content/renderer/render_frame_impl.h
[modify] https://crrev.com/29da4fe0a2b453e474e6cd530332a2ed02f70576/tools/metrics/histograms/histograms.xml

Status: Fixed (was: Started)
Considering this one fixed.

Sign in to add a comment