Peter La Reporter
	Description • 12 years ago

What makes it feel slow/broken?

It takes a little longer to startup the FM Radio app after a device reset/startup.  Timed consistently at 2.3 seconds on Unagi running Dec. 6th nightly.  David Clarke to provide more accurate, recent numbers.

Did it prevent you from doing what you wanted? Why?

FM Radio is a core entertainment app for our target launch market.  While 2.3 seconds isn't too bad, any gains we can make here would be important.

How does this make you feel?

[ ]  :)  I feel happy about it
[X]  :|  Meh
[ ]  :(  I'm upset
[ ] >:O  I'm angry

Device: Original numbers from Unagi, Dec. 6th nightly.  David Clarke to get Otoro numbers.

Details:

B2G on Unagi:               2.3 seconds
Android ICS 4.0.4 on Otoro: 1.6 seconds

David Clarke to provide updated B2G on Otoro numbers.

Bonus: can you attach a video of the problem?
See metabug 814981

	StevenLee[:slee]
	Comment 1 • 12 years ago

Hi Peter,

The long start up time is resulted from that when we enable FM radio, hal takes about 2.2 seconds to get ready. If we want shorter time, we may need vendor's support.

	Hubert Figuiere [:hub] Assignee
	Comment 2 • 11 years ago

Peter, is this still a problem on Unagi? Is it also a problem devices that ships (Alcatel/TCL, ZTE Open) ?

Strangely the problem doesn't show up in datazilla, but I'm not sure that we actually measure it properly.

Thanks,

	Hubert Figuiere [:hub] Assignee
	Comment 3 • 11 years ago

This just a debugging patch.

Apply it, then start the FMRadio app.

in the logcat we should see:

E/GeckoConsole(  112): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:730 in appLoadedHandler: apploadtime sent
E/GeckoConsole(  501): Content JS LOG at app://fm.gaiamobile.org/js/fm.js:189 in enableFMRadio: enabling the FMRadio

That show the HAL is initialised AFTER the load startup measurement. This confirm why it isn't measure in the perf bigdata.

	Hubert Figuiere [:hub] Assignee
	Comment 4 • 11 years ago

(clearing needinfo, the issue is there)

	Hubert Figuiere [:hub] Assignee
	Comment 5 • 11 years ago

With this Gecko patch we measure the initialization time and log it into the logcat. Look for "Perf:FMRadio:Enable"

	Hubert Figuiere [:hub] Assignee
	Comment 6 • 11 years ago

Comment on attachment 793438 [details] [diff] [review]
Bug 819080 - Part 1: Timing of the FM Radio hardware initialisation.

Adding Pin Zhang to review.

	Pin Zhang [:pzhang] (inactive)
	Comment 7 • 11 years ago

Comment on attachment 793438 [details] [diff] [review]
Bug 819080 - Part 1: Timing of the FM Radio hardware initialisation.

Review of attachment 793438 [details] [diff] [review]:
-----------------------------------------------------------------

Will the log message be shown in production? If not, we should use |debug| instead of |widow.dump|.

::: dom/fm/DOMFMRadioParent.jsm
@@ +335,4 @@
>      this._enabling = true;
>      let self = this;
>  
> +    let t0 = 0;

You don't have to init the variable here.

@@ +340,4 @@
>      FMRadio.addEventListener("enabled", function on_enabled() {
> +      let t1 = Date.now();
> +      let timing = t1 - t0;
> +      dump("Perf:FMRadio:Enable " + timing + " ms.");

I think |dump| won't append |\n| for you, so the log message will be messed with the following one, how about:
  dump("Perf:FMRadio:Enable " + (Date.now() - timeStart) + " ms.\n");
then you don't have to define the temp vars |t1| and |timing|.

@@ +362,4 @@
>        ppmm.broadcastAsyncMessage("DOMFMRadio:frequencyChange", { });
>      });
>  
> +    t0 = Date.now();

t0 doesn't mean anything, how about rename it to startTime, and you can init it here intead in line338: 
  let startTime = Date.now();

	Hubert Figuiere [:hub] Assignee
	Comment 8 • 11 years ago

Addressed comment from previous review.

	Hubert Figuiere [:hub] Assignee
	Comment 9 • 11 years ago

Sorry, this is actually the version with all the comments addressed.

	Hubert Figuiere [:hub] Assignee
	Comment 10 • 11 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/ec5837779ede

	Ryan VanderMeulen [:RyanVM]
	Comment 11 • 11 years ago

https://hg.mozilla.org/mozilla-central/rev/ec5837779ede

	Hubert Figuiere [:hub] Assignee
	Comment 12 • 11 years ago

The test is implemented as such:

https://bugzilla.mozilla.org/show_bug.cgi?id=819080

Not sure how to go further to have it added to DataZilla for tracking.

	Hubert Figuiere [:hub] Assignee
	Comment 13 • 11 years ago

(In reply to Hubert Figuiere [:hub] from comment #12)
> The test is implemented as such:
> 
> https://bugzilla.mozilla.org/show_bug.cgi?id=819080

Oops I meant https://github.com/mozilla/b2gperf/pull/14

	Hubert Figuiere [:hub] Assignee
	Comment 14 • 11 years ago

(In reply to StevenLee from comment #1)
> Hi Peter,
> 
> The long start up time is resulted from that when we enable FM radio, hal
> takes about 2.2 seconds to get ready. If we want shorter time, we may need
> vendor's support.

Steven, We are in the process of setting up automatic performance measurements for this. How do we go on getting the vendor's help to have an engineer fix the actual issue?

Thanks,

	StevenLee[:slee]
	Comment 15 • 11 years ago

Hi Micheal,

Can you find someone to help us on this issue?
Thanks.

	Michael Vines [:m1] [:evilmachines]
	Comment 16 • 11 years ago

This doesn't seem like that big of a deal TBH:

> How does this make you feel?
> [X]  :|  Meh

	Hubert Figuiere [:hub] Assignee
	Comment 17 • 11 years ago

Steven, now that we'll have a way to measure this, who can help us (Mozilla) address the issue and make this faster, since according to comment 1, this is a vendor driver issue.

Or maybe it has become a non issue as per comment 16.

Thanks

	StevenLee[:slee]
	Comment 18 • 11 years ago

(In reply to Hubert Figuiere [:hub] from comment #17)
> Steven, now that we'll have a way to measure this, who can help us (Mozilla)
> address the issue and make this faster, since according to comment 1, this
> is a vendor driver issue. 
> Or maybe it has become a non issue as per comment 16.
I think we may need the feedback of PM or UX. If they want to make the startup time shorted, we need the vendor's help. If not, it should not be an issue.

	Hubert Figuiere [:hub] Assignee
	Comment 19 • 11 years ago

So basically the last rewrite of the FMRadio module completely broke the test as the log entry has disappeared.

*sigh*

	Hubert Figuiere [:hub] Assignee
	Comment 20 • 11 years ago

In light of everything, morphing this bug into "write perf test".

	Hubert Figuiere [:hub] Assignee
	Comment 21 • 11 years ago

Test writing ongoing in this branch https://github.com/hfiguiere/gaia/compare/bug819080-perf

	Hubert Figuiere [:hub] Assignee
	Comment 24 • 11 years ago

Comment on attachment 8343828 [details]
Pull request

r?: Julien for the test part, pzhang for the fm radio part.

	Pin Zhang [:pzhang] (inactive)
	Comment 25 • 11 years ago

+    PerformanceTestingHelper.dispatch('fm-radio-enabled');
+    PerformanceTestingHelper.dispatch('startup-path-done');

The event 'startup-path-done' is defined in tests/performance/startup_events_test.js, right? but what 'fm-radio-enabled' is used for?

	Pin Zhang [:pzhang] (inactive)
	Comment 26 • 11 years ago

(In reply to Hubert Figuiere [:hub] from comment #19)
> So basically the last rewrite of the FMRadio module completely broke the
> test as the log entry has disappeared.
> 
> *sigh*

I'm sorry rewriting broke this, :(

	Hubert Figuiere [:hub] Assignee
	Comment 27 • 11 years ago

(In reply to Pin Zhang [:pzhang] from comment #26)
> (In reply to Hubert Figuiere [:hub] from comment #19)
> > So basically the last rewrite of the FMRadio module completely broke the
> > test as the log entry has disappeared.
> > 
> > *sigh*
> 
> I'm sorry rewriting broke this, :(

No worries about that.

	Hubert Figuiere [:hub] Assignee
	Comment 28 • 11 years ago

(In reply to Pin Zhang [:pzhang] from comment #25)
> +    PerformanceTestingHelper.dispatch('fm-radio-enabled');
> +    PerformanceTestingHelper.dispatch('startup-path-done');
> 
> The event 'startup-path-done' is defined in
> tests/performance/startup_events_test.js, right? but what 'fm-radio-enabled'
> is used for?

These are just "keys" and not events - they mark a specific timing ; they are data for the x-moz-perf event that is sent in shared/js/performance_testing_helper.js. Only the test needs to know about them.

	Julien Wajsberg [:julienw]
	Comment 29 • 11 years ago

(In reply to Hubert Figuiere [:hub] from comment #28)
> (In reply to Pin Zhang [:pzhang] from comment #25)
> > +    PerformanceTestingHelper.dispatch('fm-radio-enabled');
> > +    PerformanceTestingHelper.dispatch('startup-path-done');
> > 
> > The event 'startup-path-done' is defined in
> > tests/performance/startup_events_test.js, right? but what 'fm-radio-enabled'
> > is used for?
> 
> These are just "keys" and not events - they mark a specific timing ; they
> are data for the x-moz-perf event that is sent in
> shared/js/performance_testing_helper.js. Only the test needs to know about
> them.

The helper is designed to catch all events _until_ "startup-path-done" is received and log their timestamp :) That's the beauty of it: you can add markers whenever you want.

	Julien Wajsberg [:julienw]
	Comment 30 • 11 years ago

Comment on attachment 8343828 [details]
Pull request

I don't see it working on my device?

Even with a connected headphone, it never seems to stop.

	Julien Wajsberg [:julienw]
	Comment 31 • 11 years ago

Comment on attachment 8343828 [details]
Pull request

Also, you need to update the unit tests, they currently fail because PerformanceTestingHelper is missing.

You just need to load the file at apps/communications/contacts/test/unit/mock_performance_testing_helper.js, maybe move it to shared/, and use the mocks_helper to manage it.

	Julien Wajsberg [:julienw]
	Comment 32 • 11 years ago

Comment on attachment 8343828 [details]
Pull request

r- until these changes are done.

	Hubert Figuiere [:hub] Assignee
	Comment 33 • 11 years ago

(In reply to Julien Wajsberg [:julienw] from comment #31)
> Comment on attachment 8343828 [details]
> Pull request
> 
> Also, you need to update the unit tests, they currently fail because
> PerformanceTestingHelper is missing.
> 
> You just need to load the file at
> apps/communications/contacts/test/unit/mock_performance_testing_helper.js,
> maybe move it to shared/, and use the mocks_helper to manage it.

Since when did that change? I tested it yesterday.

	Julien Wajsberg [:julienw]
	Comment 34 • 11 years ago

I just tested the standalone file, maybe the full suite is working because the mock is loaded elsewhere. But individual files should work in a standalone way as well.

	Hubert Figuiere [:hub] Assignee
	Comment 35 • 11 years ago

Doing a |APP=fm make test-perf| or just |make test-perf| works. 

I don't get what the issue that you are having.

	Julien Wajsberg [:julienw]
	Comment 36 • 11 years ago

I was not talking about the perf tests but about the unit tests.

	Hubert Figuiere [:hub] Assignee
	Comment 37 • 11 years ago

Comment on attachment 8343828 [details]
Pull request

Updated pull request to deal with the unit test failure.

The added change is in apps/fm/test/unit/fm_test.js

	Hubert Figuiere [:hub] Assignee
	Comment 38 • 11 years ago

Addressed the nits.

	Julien Wajsberg [:julienw]
	Comment 39 • 11 years ago

Comment on attachment 8343828 [details]
Pull request

r=me

that was me being stupid and not flashing the new "fm" app...

Thanks

	Hubert Figuiere [:hub] Assignee
	Comment 40 • 11 years ago

(In reply to Julien Wajsberg [:julienw] from comment #39)

> that was me being stupid and not flashing the new "fm" app...


You don't want to know how many time this happened to me :-)

Thanks !

	Hubert Figuiere [:hub] Assignee
	Comment 41 • 11 years ago

Travis is green.

Merged.
https://github.com/mozilla-b2g/gaia/commit/6d8c461b03efe18bcdea34386cdcfbe612b098e0