JavaScript Stack for Web Cryptography API .then() missing from timeline, recognized as 'other'
Reported by
s...@salesforce.com,
Sep 1 2016
|
||||||||||||||||||||||||
Issue description
UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36
Steps to reproduce the problem:
1. Load the attached file bugProduction.html (Run any Web Cryptography API with the .then() method)
2. Open devtools timeline. Start recording. Click the button and wait a few seconds. End recording.
In the timeline overview pane for the CPU graph, there is a large chunk of grey “Miscellaneous resources”. The flame chart is missing a significant portion of the CPU stack trace.
See the attached actualTimeline.png
What is the expected behavior?
Attached is a CPU Profile screenshot for the same timeline (cpuprofile.png). All the JavaScript under the “PromiseHandle” trace is missing from timeline. The information is there in the timeline.json file, but it’s not recognizable by Chrome in the timeline.
Attached is also a patched version of the same timeline for what we originally expected to see (patchedTimeline.png)
What went wrong?
Issue:
This is a portion of code from the attached file to reproduce the issue.
function storeEncryptedObjectsArray() {
generateCryptoKey().then(function (cryptoKey){
doStuff();
var numberOfArrayObjects = 500;
var encryptedValues = generateEncryptedArray(cryptoKey, numberOfArrayObjects);
addArrayToIndexedDB(encryptedValues);
});
}
All the JavaScript functions to be called after the Web Cryptography API promise is resolved (doStuff(), generateEncryptedArray(), addArrayToIndexedDB() ) are missing from the JavaScript flame chart and categorized as “Other” in timeline.
MIssing:
The recorded timeline is missing a “parent” “Function Call” trace, which would allow the callback for Web Cryptography API promises to be recognized on timeline. The callback does not get routed through the same path as other JavaScript functions in Chrome, which creates this parent trace in V8ScriptRunner.cpp
What’s happening:
The Web Cryptography function is called (generateCryptoKey). The information is passed to a Crypto thread, where the actual work is done. When the information is passed back, a message that the promise has been resolved is triggered (doGenerateKeyReply). Immediately after, the callback is run when microtasks is kicked off.
What should happen:
Other functions with callbacks, such as setTimeout and requestAnimationFrame have a function that is called after the first portion is ‘resolved’.
ExecuteCallbacks.png is the snapshot of the callback for requestAnimationFrame. In the code, callback->handleEvent() is called.
handleEvent.png shows that HandleEvent calls V8ScriptRunner::callFunction
callFunction.png shows that V8ScriptRunner::callFunction creates that ‘parent’ ‘Function Call’ trace that allows the JavaScript stack to become recognized by timeline.
The callback for Cryptography promises need to follow the same standardized path.
Did this work before? No
Chrome version: 52.0.2743.116 Channel: n/a
OS Version: OS X 10.11.6
Flash Version: Shockwave Flash 22.0 r0
Note: This issue is reproducible on both stable Chrome 52.0.2743.116 and 55.0.2845.0 canary Chrome.
,
Sep 1 2016
,
Sep 1 2016
,
Sep 9 2016
Another instance of a timeline flame chart missing a large section of the CPU stack trace was found. This time the issue appears to be related to promises and OnMessageReceivedNoFilter from the IPC::ChannelProxy API
,
Nov 12 2016
,
Nov 15 2016
The first part of the issue has been fixed back in August with https://chromium.googlesource.com/v8/v8/+/607c2c329360f1c316994015fa6a4466f6595797 So the microtasks JS code should be visible on timeline. As for the gray area in between, it is a bunch of callbacks coming from the crypto API resolved promises. Since the promise then/catch actions are tiny, most of the time is an overhead spent in blink/crypto/scheduler code. This seems to be a quite artificial case having lots of encrypt calls (500) with small chunks of data (16 bytes). I wonder if it's possible to do the work synchronously on the main thread if the data chunk is small enough. I.e. when the overhead of posting tasks between thread is comparable to time spent in actual encryption. Passing this to crypto folks.
,
Nov 15 2016
"I wonder if it's possible to do the work synchronously on the main thread if the data chunk is small enough." Variations of this request have come in (e.g. Issue 414093 and Issue 615133 are two notable examples) and closed as WontFix.
,
Nov 15 2016
I'm not proposing to change the API to synchronous, but do the work right away on the main thread if the work amount if comparable to the task scheduling overhead. Then resolve the promise, so its then part will be executed on the microtasks phase.
,
Nov 15 2016
re: Comment 8 - Yes, see Issue 615133 . And there's no good way to compute the cost/benefit overhead.
,
Nov 15 2016
> This seems to be a quite artificial case having lots of encrypt calls ... This is not artificial. Our app runs some third party code (customer code) and we need to encrypt everything going to the browser cache, hence the high number of encrypt calls. > "I wonder if it's possible to do the work synchronously on the main thread ... We are definitely not suggesting more stuff on the main thread. We just want the work encapsulated by the crypto stack to show up on the timeline. For more context, you can check the blog we posted on this issue, which contains some screenshot and why its a pain-point for performance investigations: https://medium.com/salesforce-engineering/my-summer-internship-setting-out-on-a-treasure-hunt-with-the-performance-engineering-team-344fc39bab22#.zg3v54sk1
,
Nov 15 2016
I think the DevTools side of this is addressed per comment #6. @alph, is that correct? As for the performance side of things, I am not satisfied with the Web Crypto cost either. There is another proposal for addressing this in issue 435790. As Ryan mentioned there isn't an easy blanket policy for doing work synchronously. But I hope we can justify special-casing SHA and AES operations to happening synchronously in many cases. Feel free to follow-up on the overall performance side on that bug, and keep this one just about the timeline reporting
,
Nov 16 2016
In response to: > "This seems to be a quite artificial case having lots of encrypt calls (500)...." Whether the number of encrypt calls is 1 or 500, the same issue persists with the Crypto API callbacks missing from the DevTools timeline. In the case of just 1 encrypt call, the current situation is not ideal when trying to investigate possibly time consuming work done within that one callback if it's not visible in DevTools. In the case of multiple encrypt calls (whether this is 500 or not), the missing stack information adds up. In some cases, this means 3 seconds of JS traces are missing from the timeline, which is significant enough in terms of performance to lead to workarounds to investigate the traces, but those aren't ideal. > "I think the DevTools side of this is addressed per comment #6...." I agree that performance is an issue, but I think the main concern here is that the JS code in the callback coming from the crypto API promises is not being captured in the DevTools timeline.
,
Nov 16 2017
This issue has been Available for over a year. If it's no longer important or seems unlikely to be fixed, please consider closing it out. If it is important, please re-triage the issue. Sorry for the inconvenience if the bug really should have been left as Available. If you change it back, also remove the "Hotlist-Recharge-Cold" label. For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
,
Nov 23 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/b4e75fa1c1e431cd6e8bb4278bc67bf20e3c4a7b commit b4e75fa1c1e431cd6e8bb4278bc67bf20e3c4a7b Author: Alexei Filippov <alph@chromium.org> Date: Thu Nov 23 04:44:21 2017 DevTools: Instrument WebCrypto API for DevTools timeline. BUG= 643375 Change-Id: I6ebb61a29723b6a9dd1523b06d7b3ebfe978c97c Reviewed-on: https://chromium-review.googlesource.com/775736 Commit-Queue: Alexei Filippov <alph@chromium.org> Reviewed-by: Eric Roman <eroman@chromium.org> Cr-Commit-Position: refs/heads/master@{#518851} [modify] https://crrev.com/b4e75fa1c1e431cd6e8bb4278bc67bf20e3c4a7b/components/webcrypto/webcrypto_impl.cc [add] https://crrev.com/b4e75fa1c1e431cd6e8bb4278bc67bf20e3c4a7b/third_party/WebKit/LayoutTests/http/tests/devtools/tracing/timeline-misc/timeline-crypto-expected.txt [add] https://crrev.com/b4e75fa1c1e431cd6e8bb4278bc67bf20e3c4a7b/third_party/WebKit/LayoutTests/http/tests/devtools/tracing/timeline-misc/timeline-crypto.js [modify] https://crrev.com/b4e75fa1c1e431cd6e8bb4278bc67bf20e3c4a7b/third_party/WebKit/Source/devtools/front_end/timeline/TimelineUIUtils.js [modify] https://crrev.com/b4e75fa1c1e431cd6e8bb4278bc67bf20e3c4a7b/third_party/WebKit/Source/devtools/front_end/timeline_model/TimelineModel.js
,
Nov 27 2017
,
Nov 27 2017
|
||||||||||||||||||||||||
►
Sign in to add a comment |
||||||||||||||||||||||||
Comment 1 by s...@salesforce.com
, Sep 1 2016Attached are the timeline json files that correspond to the screenshots referenced above. PatchedTimeline.json was created by using a script that reads actualTimeline.json and replaces an object not used in the flamechart with a 'parent' 'Function Call' trace For example: replace: {"pid":53530,"tid":1295,"ts":392695369308,"ph":"X","cat":"toplevel","name":"TaskQueueManager::ProcessTaskFromWorkQueue","args":{"src_file":"../../components/webcrypto/webcrypto_impl.cc","src_func":"DoEncrypt"},"dur":24,"tdur":23,"tts":331455}, with: {"pid":53530,"tid":1295,"ts":392695369308,"ph":"X","cat":"devtools.timeline","name":"FunctionCall","args":{"frame":"0x172b768a1e10","functionName":"MissingCryptoParentTrace"},"dur":24},1.9 MB
1.9 MB View Download
1.8 MB
1.8 MB View Download