Calling console.profileEnd() does not finish the profiling

NEW
Assigned to

Status

P3
normal
3 years ago
3 months ago

People

(Reporter: sworddragon2, Assigned: julienw)

Tracking

43 Branch
x86_64
All

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment)

(Reporter)

Description

3 years ago
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.
(Reporter)

Updated

3 years ago
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?
(Reporter)

Comment 2

3 years ago
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?
(Reporter)

Comment 4

3 years ago
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?
(Reporter)

Comment 6

3 years ago
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
(Reporter)

Comment 8

3 years ago
(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.
(Reporter)

Comment 9

3 years ago
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)
(Reporter)

Updated

3 years ago
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>
(Assignee)

Comment 13

a year ago
Created attachment 8939567 [details]
testcase

adding the aforementioned testcase so that it's easier to run
Assignee: nobody → felash
(Assignee)

Updated

a year ago
Attachment #8939567 - Attachment filename: file_1240249.txt → file_1240249.html
Attachment #8939567 - Attachment mime type: text/plain → text/html
(Assignee)

Comment 14

a year ago
I reproduce in latest nightly.
(Assignee)

Comment 15

a year ago
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" ;)
(Assignee)

Comment 16

a year ago
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.
(Assignee)

Comment 17

a year ago
Note: the initial description in comment 0 doesn't seem to apply anymore.

Updated

7 months ago
Product: Firefox → DevTools
(Assignee)

Comment 18

3 months ago
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
(Assignee)

Comment 19

3 months ago
Filed bug 1499699 for 2.
(Assignee)

Updated

3 months ago
See Also: → bug 1499699
You need to log in before you can comment on or make changes to this bug.