Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Chrome .cpuprofile importer: Get profile start time from URL (Chrome DevTools UI format) #4797

Merged
merged 31 commits into from
Nov 19, 2024

Conversation

kazarmy
Copy link
Contributor

@kazarmy kazarmy commented Nov 11, 2023

This PR obtains a Chrome .cpuprofile start time from its URL / filename. The timestamp format currently supported is what is generated by the Chrome DevTools UI when one manually saves a profile from the Performance tab. The format, and the claim that the timestamp is generated on profile save, is based on https://chromium.googlesource.com/chromium/blink/+/refs/heads/main/Source/devtools/front_end/profiler/CPUProfileView.js#727.

Change will manifest itself as an accurate timestamp here:

profile-timestamp

Questions:

  1. Currently, the URL is from window.location.href. Should profileUrl be passed to unserializeProfileOfArbitraryFormat() instead?
  2. Add test (that has profile with timestamp in filename)?

(As a side note, the profile given to the Profiler.consoleProfileFinished event handler is slightly different from the profile generated when it is saved manually through the UI. No idea why.)

┆Issue is synchronized with this Jira Task

@kazarmy kazarmy force-pushed the chrome-profile-start-time branch from 2eeb84d to 1f92eb0 Compare November 11, 2023 09:08
Copy link

codecov bot commented Nov 11, 2023

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 88.62%. Comparing base (532edf0) to head (b262540).
Report is 32 commits behind head on main.

Additional details and impacted files
@@           Coverage Diff           @@
##             main    #4797   +/-   ##
=======================================
  Coverage   88.62%   88.62%           
=======================================
  Files         308      308           
  Lines       28051    28059    +8     
  Branches     7596     7598    +2     
=======================================
+ Hits        24859    24867    +8     
  Misses       2978     2978           
  Partials      214      214           

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.


🚨 Try these New Features:

@kazarmy
Copy link
Contributor Author

kazarmy commented Nov 11, 2023

  1. Add test (that has profile with timestamp in filename)?

I guess Codecov has answered this question.

@julienw julienw requested review from julienw and canova November 16, 2023 14:57
@kazarmy kazarmy force-pushed the chrome-profile-start-time branch from 697460e to 444a45e Compare November 20, 2023 15:19
@kazarmy
Copy link
Contributor Author

kazarmy commented Nov 20, 2023

  1. Currently, the URL is from window.location.href. Should profileUrl be passed to unserializeProfileOfArbitraryFormat() instead?

The profile conversion tests don't run a (headless) browser and so window.location.href isn't available in the tests and I had no choice but to pass profileUrl to unserializeProfileOfArbitraryFormat().

The test profile is actually an old profile produced using node --cpu-prof that I loaded and resaved in Node DevTools. Sorry for the lack of movement on this, current geopolitical situation not helping.

@kazarmy kazarmy force-pushed the chrome-profile-start-time branch from 444a45e to 77ebebf Compare November 20, 2023 15:28
@julienw
Copy link
Contributor

julienw commented Nov 23, 2023

Just checking: I see you were doing some changes recently, so can you please precise if it's ready for review now? Thanks :-)

@kazarmy kazarmy marked this pull request as draft November 24, 2023 00:41
@kazarmy kazarmy marked this pull request as ready for review November 24, 2023 01:06
@kazarmy
Copy link
Contributor Author

kazarmy commented Nov 24, 2023

... so can you please precise if it's ready for review now?

Yes, it's ready for review.

Copy link
Contributor

@julienw julienw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for your patience, while we were busy with other work.

I believe it is reasonable to pass "something" to the unserializing function.

We also need to pass the file name from retrieveProfileFromFile in the same file, and also the file name from the file in a zip archive in viewProfileFromZip in actions/zipped-profiles.js.

My slight concern is that we do have startTime and endTime information in a .cpuprofile file, but I'm not sure what value they are. Do you know? Do you have pointers to where these values are set or to some documentation about those?
I won't say I'm super happy about this. I wish we could use the existing startTime and endTime instead...

I left a few comments otherwise.
Tell me what you think!

Comment on lines 688 to 689
const timeStampRe =
/(\d{4})(\d{2})(\d{2})T(\d{2})(\d{2})(\d{2}).*\.cpuprofile(?:$|\/|\?|#)/;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
const timeStampRe =
/(\d{4})(\d{2})(\d{2})T(\d{2})(\d{2})(\d{2}).*\.cpuprofile(?:$|\/|\?|#)/;
const timeStampRe =
/(\d{4})(\d{2})(\d{2})T(\d{2})(\d{2})(\d{2}).*\.cpuprofile\b/;

In a regexp \b means "a word boundary", which is exactly what you're looking for here.

Why do you have this .* between the timestamp and .cpuprofile?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In a regexp \b means "a word boundary", which is exactly what you're looking for here.

I beg to differ, (?:$|\/|\?|#) implements the concept of "end of URL subdirectory" which is more strict than "end of word". In particular, \b treats characters like % and [ as a boundary which could result in profiles being accepted that do not have exactly the .cpuprofile extension (for whatever deliberate reason).

That said, practically there probably isn't much point to be strict about this, and perhaps some people do put additional information on a filename after the file extension. I do prefer that a regex be as strict as possible though.

On the other hand, afaik Firefox Profiler doesn't specifically check for the .cpuprofile extension, instead it looks at the profile's contents to determine profile type. So for consistency, the regex should just match a timestamp i.e. it should just be /(\d{4})(\d{2})(\d{2})T(\d{2})(\d{2})(\d{2})/. What do you think?

Why do you have this .* between the timestamp and .cpuprofile?

The basic filename produced (e.g. CPU-20230928T151126.cpuprofile) is lacking in what the profile is all about, and the current regex already ignores everything before the timestamp. The .* allows the regex to ignore everything after the timestamp before the extension. This is to cater for people who prefer to add identifying information after the timestamp rather than before it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

3c62513 -- now I think it's best to be consistent with the rest of Firefox Profiler that doesn't specially treat the .cpuprofile extension.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

251b59c matches on the last timestamp found, just in case someone sticks a timestamp on a folder. I wanted to use String.matchAll(), but Flow 0.96.0 doesn't have a definition for it (!).

Comment on lines 702 to 703
(profileEvent.args.data.cpuProfile.endTime -
profileEvent.args.data.cpuProfile.startTime) /
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it's not clear to me that the difference will be in milliseconds. It seems to me this may be tenths of milliseconds, but I'm not so sure.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

emm not sure whether I'm getting you here -- it's known that cpuProfile.startTime / .endTime is in microseconds, and one can convert both to milliseconds first before doing the difference (using / 1000), but a / 1000 - b / 1000 is mathematically equivalent to (a - b) / 1000 via algebra, and the latter involves less operations.

If 1 startTime / endTime tick is not actually 1 microsecond though, I suppose there has to be a way to change this assumption.

Copy link
Contributor Author

@kazarmy kazarmy Dec 25, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would be amazed if there is a startTime / endTime that actually exceeds Number.MAX_SAFE_INTEGER (that would probably be a profile that has a lifespan longer than the average human), but since we require only millisecond precision, I suppose I should convert startTime and endTime to milliseconds first before doing the difference.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

0e626fd converted startTime and endTime to milliseconds first but was reverted because I got a test profilingEndTime of 190.7039999961853 (due to floating point rounding error) instead of the correct 190.704.

@@ -678,10 +680,28 @@ async function processTracingEvents(
}

if (profileEvent.name === 'CpuProfile') {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I noticed there's a similar if condition above in the same function, where we do also set the threadInfo.lastSeenTime information. I think it would be good to move all of this in the if block above (especially that it's closer to the Profile block too). It would also be good to add a comment to remind the reader about the fact that CpuProfile is added by us in wrapCpuProfileInEvent because it took me 30min to remember that :D

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hopefully will also get to this by early this week (or at least before this week ends).

Copy link
Contributor Author

@kazarmy kazarmy Dec 29, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I noticed there's a similar if condition above in the same function, where we do also set the threadInfo.lastSeenTime information. I think it would be good to move all of this in the if block above (especially that it's closer to the Profile block too).

Done in f1108a4.

It would also be good to add a comment to remind the reader about the fact that CpuProfile is added by us in wrapCpuProfileInEvent ...

Done in 0ba0c39. The ts field should matter?

if (match) {
const dateTimeString = `${match[1]}-${match[2]}-${match[3]}T${match[4]}:${match[5]}:${match[6]}`;
const startTime = new Date(dateTimeString);
profile.meta.startTime = startTime.getTime();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note that startTime represent the moment the main thread started. So it's not great. But I don't see a better option with our current code.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As long as the (adjustable) start time provided is reasonably close to the actual start time, I think it's going to be ok. Support for milliseconds could be added later on for more accuracy.

@kazarmy
Copy link
Contributor Author

kazarmy commented Dec 24, 2023

Thanks for your patience, while we were busy with other work.

No worries, I'm under resourced too, sometimes terribly so, though partially it's because I don't really prefer focusing on just 1 project/language/topic unless I have to.

We also need to pass the file name from retrieveProfileFromFile in the same file, and also the file name from the file in a zip archive in viewProfileFromZip in actions/zipped-profiles.js.

I'll get to this hopefully sometime early next week.

My slight concern is that we do have startTime and endTime information in a .cpuprofile file, but I'm not sure what value they are. Do you know? Do you have pointers to where these values are set or to some documentation about those?

I actually did some spelunking in the Node V8 source code regarding this, and while I'm not 100% sure (largely because I don't have a Node build environment set up to test whether I'm actually looking at irrelevant duplicate code, and am not looking forward to building Node due to the build times involved), it appears that:

  1. startTime gets its value from a TimeTicks static method (ref, ref, ref).
  2. The TimeTicks class comment states that it is a form of time in microseconds but not convertible to a human-readable time (ref) ...
  3. ... probably because its origin is not known in terms of human time (ref).

I didn't get much deeper than that, though it appears that on Windows QueryPerformanceCounter can be involved (ref) which according to this MSDN page, "isn't synchronized to any external time reference".

I won't say I'm super happy about this. I wish we could use the existing startTime and endTime instead...

I'm not happy about this either, but short of persuading the V8 team to record as well the actual system clock time for startTime, I suppose we have to do the recording ourselves.

@kazarmy kazarmy marked this pull request as draft December 26, 2023 12:53
@kazarmy
Copy link
Contributor Author

kazarmy commented Dec 28, 2023

We also need to pass the file name from retrieveProfileFromFile in the same file, and also the file name from the file in a zip archive in viewProfileFromZip in actions/zipped-profiles.js.

Done in 257485d, tested only manually though.

@kazarmy kazarmy marked this pull request as ready for review December 29, 2023 11:08
@kazarmy
Copy link
Contributor Author

kazarmy commented Dec 29, 2023

Ok, it's ready for review.

@kazarmy kazarmy force-pushed the chrome-profile-start-time branch from 2982534 to 0ba0c39 Compare December 29, 2023 11:12
@julienw julienw self-requested a review January 19, 2024 17:53
kazarmy and others added 10 commits November 7, 2024 20:51
Previously we were only doing this for CPUProfile profiles. But chrome
adds this timestamp to all of its profile files including the Tracing
files. See their source code here:
https://source.chromium.org/chromium/chromium/src/+/main:third_party/devtools-frontend/src/front_end/panels/timeline/TimelinePanel.ts;l=1242-1251;drc=0cc387000bc7c9369fc34c2f2390d3cbc67f65ab
So that's why this commit makes sure that we check the profile url for
every type of chrome profiles, and not only for CPU profiles.
…n that

We need the profilingStartTime for calculating the time range. That's
why we can't simply put zero. But also we need to make sure that
profiler frontend reports the correct time. Profiler calculates the
recording start timestamp as `startTime + profilingStartTime`. So to be
able to tell the user about the correct timestamp we read from the
profile file name, we have to calculate the `startTime` like this:
`timestamp from name - profilingStartTime`. This commit changes this to
make sure that we always show the correct timestamp.
`getEmptyProfile` function already sets the `startTime` to zero.
@canova
Copy link
Member

canova commented Nov 19, 2024

Thanks for the PR @kazarmy! It looks great, I tweaked some things and pushed additional commits, mainly to make sure that it works well together with #5187.

The things I've changed:

Here's an example profile

Comment on lines +781 to +783
// timestamp is of profile save instead of profile start, but one can generate a
// more accurate start timestamp through e.g. handling the Chrome DevTools
// Protocol `Profiler.consoleProfileStarted` event.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't understand how "one" can do something here. Is that something we can do now, or something that could be done in the future?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that's the event that's mentioned here: https://chromedevtools.github.io/devtools-protocol/1-2/Profiler/#event-consoleProfileStarted
It's an event that's a part of CDP.

I can't find the same event inside the profile data, so I'm not so sure how to do that. Maybe we can do that for chrome extension. But I'm not so sure, maybe @kazarmy had something else in mind while writing that.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that's the event that's mentioned here: https://chromedevtools.github.io/devtools-protocol/1-2/Profiler/#event-consoleProfileStarted

Yes that's the event. I have code (from 11 months ago -- bit-rotted a bit but fortunately can still be made to run) that runs Chrome and attaches to it via https://github.com/cyrus-and/chrome-remote-interface.

Copy link
Member

@canova canova Nov 19, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah I see. We also have this one btw: https://github.com/firefox-devtools/firefox-profiler-for-chrome We recently published it on the Chrome Web Store. That's why I was spending some time on improving the importer.
(It's not an alternative to the one you linked, just another way to visualize the data)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh cool! I do prefer to programmatically start the Chrome profiler if possible, though I understand this might not be the best way to spend precious engineer time in a work environment.

Copy link
Contributor

@julienw julienw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @kazarmy and @canova !
This looks pretty good to me, let's land this!

@canova please use a merge commit so that we retain the commits from both of you as well as the useful commit logs.

@canova canova merged commit 8764e83 into firefox-devtools:main Nov 19, 2024
18 checks passed
@kazarmy
Copy link
Contributor Author

kazarmy commented Nov 19, 2024

Thanks! 🎉

@canova canova mentioned this pull request Nov 27, 2024
canova added a commit that referenced this pull request Nov 27, 2024
[Julien Wajsberg] Fix the network bars not being properly positioned in
Chrome (#5209)
[Nazım Can Altınova] Only show the NavigationStart in the timeline if it
has innerWindowID (#5210)
[Nisarg Jhaveri] Fix loading and error messages for /from-post-message
(#5175)
[Khairul Azhar Kasmiran] Chrome `.cpuprofile` importer: Get profile
start time from URL (Chrome DevTools UI format) (#4797)
[Khairul Azhar Kasmiran] Remove "Recording started" line from Profile
Info if startTime is 0 (#5219)
[Sean Kim] Add HTTP protocol version for a request in the profiler
network tab (#5206)
[Julien Wajsberg] Switch to a maintained fork of npm-run-all (#5221)
[Nicolas Chevobbe] Adapt Tabs in High Contrast Mode (#5220)
[Markus Stange] Fix test debugging in VS Code. (#5227)
[Julien Wajsberg] Added appropriate null check to handle missing unified
string optional values (#5192)

And thanks to our localizers:
de: Michael Köhler
el: Jim Spentzos
en-CA: chutten
en-GB: Ian Neal
es-CL: ravmn
fy-NL: Fjoerfoks
ia: Melo46
it: Michele Rodaro
kab: ZiriSut
nl: Mark Heijl
pt-BR: Marcelo Ghelman
ru: Valery Ledovskoy
sv-SE: Andreas Pettersson
tr: Grk
zh-CN: Olvcpr423
zh-TW: Pin-guang Chen
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants