sworddragon2 Reporter
	Description • 8 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.

	Jordan Santell [:jsantell] [@jsantell]
	Comment 1 • 8 years ago

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?

	sworddragon2 Reporter
	Comment 2 • 8 years ago

I'm on Linux 4.3.3 and using Firefox 43.0.4. Both commands were executed as separate commands.

	Jordan Santell [:jsantell] [@jsantell]
	Comment 3 • 8 years ago

(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?

	sworddragon2 Reporter
	Comment 4 • 8 years ago

After calling console.profileEnd() the Firefox process has still utilized ~40%/600% of the available processor time (6 cores).

	Jordan Santell [:jsantell] [@jsantell]
	Comment 5 • 8 years ago

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?

	sworddragon2 Reporter
	Comment 6 • 8 years ago

The cpu activity was monitored with an external tool and the profiling hasn't shown me anything special.

	Jordan Santell [:jsantell] [@jsantell]
	Comment 7 • 8 years ago

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.

	sworddragon2 Reporter
	Comment 8 • 8 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.

	sworddragon2 Reporter
	Comment 9 • 8 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?

	Victor Porof [:vporof][:vp]
	Comment 10 • 8 years ago

Triaging. Filter on LULUGUBRIOUSUS.

	Jordan Santell [:jsantell] [@jsantell]
	Comment 11 • 8 years ago

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.

	Márton Salomváry
	Comment 12 • 6 years ago

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>

	Julien Wajsberg [:julienw] Assignee
	Comment 13 • 6 years ago

adding the aforementioned testcase so that it's easier to run

	Julien Wajsberg [:julienw] Assignee
	Comment 14 • 6 years ago

I reproduce in latest nightly.

	Julien Wajsberg [:julienw] Assignee
	Comment 15 • 6 years 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" ;)

	Julien Wajsberg [:julienw] Assignee
	Comment 16 • 6 years 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.

	Julien Wajsberg [:julienw] Assignee
	Comment 17 • 6 years ago

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

	Julien Wajsberg [:julienw] Assignee
	Comment 18 • 6 years 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

	Julien Wajsberg [:julienw] Assignee
	Comment 19 • 6 years ago

Filed bug 1499699 for 2.