Instrument code related to Offline Page Caching to ease investigating perf regressions |
|||||||||
Issue descriptionTo 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.
,
Sep 16 2016
,
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
,
Sep 21 2016
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.
,
Sep 23 2016
,
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
,
Sep 30 2016
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.
,
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
,
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
,
Oct 11 2016
I'd like to request the merge of change 90bf4f0c77709ddb65b1f8d86e04065aacae02ac.
,
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
,
Oct 12 2016
Your change meets the bar and is auto-approved for M55 (branch: 2883)
,
Oct 12 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
,
Oct 13 2016
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.
,
Oct 25 2016
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.
,
Oct 27 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
,
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
,
Nov 4 2016
[Automated comment] removing mislabelled merge-merged-2840
,
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
,
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
,
Jan 26 2017
Considering this one fixed. |
|||||||||
►
Sign in to add a comment |
|||||||||
Comment 1 by carlosk@chromium.org
, Sep 9 2016