Closed Bug 1240249 Opened 9 years ago Closed 2 years ago

Calling console.profileEnd() does not finish the profiling

Categories

(DevTools :: Performance Tools (Profiler/Timeline), defect, P3)

Product:
DevTools
Component:
Performance Tools (Profiler/Timeline)
Version:
43 Branch
Platform:
x86_64
All
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INVALID

People

(Reporter: sworddragon2, Assigned: julienw)

References

Details

Attachments

(1 file)

testcase
(deleted), text/html
Details
User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:43.0) Gecko/20100101 Firefox/43.0 Build ID: 20160106234842 Steps to reproduce: 1. Start Firefox. 2. Go to the menu bar -> Tools -> "Web Developer" -> "Web Console". 3. Execute "console.profile();". 4. Execute "console.profileEnd();". Actual results: While the "Performance" entry changed its background color from green back to default the cpu usage of Firefox on my system was still ~40%/600%. Expected results: No cpu usage from profiling should appear anymore.
Blocks: 1215347
What version of Firefox/Operating system? Typing console.profile() and console.profileEnd ends and loads the profile for me -- except if the two statements are in the same tick, then you'll run into bug 1173588, which will not stop the profile -- is that what's happening?
I'm on Linux 4.3.3 and using Firefox 43.0.4. Both commands were executed as separate commands.
(In reply to sworddragon2 from comment #0) > While the "Performance" entry changed its background color from green back > to default the cpu usage of Firefox on my system was still ~40%/600%. What do you mean the cpu usage of Firefox on your system was 40%/600%? The buffer usage? Was it still recording? Do you have a gif/video/screenshot that'd help explain it?
After calling console.profileEnd() the Firefox process has still utilized ~40%/600% of the available processor time (6 cores).
I'm still not following what you were seeing -- the profiler doesn't know anything about your CPU cores. Did the tool stop recording and were you able to see the results? Do you have a screenshot?
The cpu activity was monitored with an external tool and the profiling hasn't shown me anything special.
Do you have a dump of that profiler data then? What frame do you see still consuming resources in the external profiler? Is the recording finalized after console.profileEnd() and the recording is visible in the developer tools? I'm sorry, this isn't a lot of clear information to go off of.
OS: Unspecified → Linux
Hardware: Unspecified → x86_64
(In reply to Jordan Santell [:jsantell] [@jsantell] (Please needinfo) from comment #7) > Do you have a dump of that profiler data then? How can this dump created/accessed? (In reply to Jordan Santell [:jsantell] [@jsantell] (Please needinfo) from comment #7) > What frame do you see still > consuming resources in the external profiler? I'm still in the console and don't see anything special there. If you want to know something specific just tell me what to do. (In reply to Jordan Santell [:jsantell] [@jsantell] (Please needinfo) from comment #7) > Is the recording finalized > after console.profileEnd() and the recording is visible in the developer > tools? Same as above.
I'm also able to reproduce this bug on Windows 10 with Firefox 43.0.4 (both 64 bit). @Jordan Santell: Can you try to reproduce this issue again and make a look at the cpu usage of Firefox (for example with the task manager)? What is the cpu usage of Firefox on idle (for example if you wait a bit after doing step 1 of the reproduction steps) and what is the cpu usage of Firefox after step 4 of the reproduction steps?
Flags: needinfo?(jsantell)
OS: Linux → All
Component: Untriaged → Developer Tools: Performance Tools (Profiler/Timeline)
Triaging. Filter on LULUGUBRIOUSUS.
Status: UNCONFIRMED → NEW
Ever confirmed: true
Priority: -- → P3
on OSX, I'm at 10% idle, 25% with tools open, and during profiling, spikes up to 40-50%, but settles down to 25% afterwards. I'm not that familiar with using profiling tools on Linux/Windows, but could you profile Firefox itself with one of those OS tools to record samples of Firefox after performing the console.profile/profileEnd? Curious to see what in Firefox is causing the extra CPU cycles after profiling, as the profiler should be pretty much inactive after recording.
Flags: needinfo?(jsantell)
Still seeing this on 57.0.3 (64-bit, macOS), the profiler keeps recording after profileEnd(). The smallest amount of code to reproduce is the following: <!doctype html> <script> console.profile() console.profileEnd() </script>
Attached file testcase (deleted) —
adding the aforementioned testcase so that it's easier to run
Assignee: nobody → felash
Attachment #8939567 - Attachment filename: file_1240249.txt → file_1240249.html
Attachment #8939567 - Attachment mime type: text/plain → text/html
I reproduce in latest nightly.
From a quick test, I see the bug happens with synchronous code, but not when profileEnd is called asynchronously. This is not completely surprising as the "active" state is kept in a structure called "RacyFeatures" ;)
Actually this is easily reproducible by: 1. shift + F5 to open the perf panel 2. enable the bottom console if not enabled yet (key Esc) 3. enter "console.profile(); console.profileEnd()" => notice the recording isn't stopped. However with "console.profile(); setTimeout(console.profileEnd)" this works as expected.
Note: the initial description in comment 0 doesn't seem to apply anymore.
Product: Firefox → DevTools
I gave a closer look. The issue comes from the fact that for `console.profile()` we add the new recording after a bunch of asynchronous actions (and especially after starting the profiler) in [1], but for `console.profileEnd()` we look in the state at the start at [2]. Then when someone runs `profile` and `profileEnd` in a short succession, we look in the state before it's been populated, and exit early. I believe there's a set of actions we can do: 1. add a state earlier in `console.profile()`, before any asynchronous task starts. 2. return a promise from `console.profile()`, being resolved when the profiler is actually started. Alternatively we could make this call synchronous, but at this time and age this would be a shame. This sounds like 2 different bugs, so we can focus on 1. in this issue, and I'm filing a new bug for 2. [1] https://searchfox.org/mozilla-central/rev/3d989d097fa35afe19e814c6d5bc2f2bf10867e1/devtools/server/performance/recorder.js#365-366 [2] https://searchfox.org/mozilla-central/rev/3d989d097fa35afe19e814c6d5bc2f2bf10867e1/devtools/server/performance/recorder.js#196-209
Filed bug 1499699 for 2.
Severity: normal → S3

This report is related to the old DevTools Profiler.
The Performance panel now points to the new Firefox profiler available at profiler.firefox.com
Closing as Invalid bug

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: