[dolphin][perf] It took about 1.8-2.2s for music to start play

RESOLVED WONTFIX

Status

defect
P1
normal
RESOLVED WONTFIX
5 years ago
4 years ago

People

(Reporter: angelc04, Unassigned)

Tracking

({perf})

unspecified
Other
Other

Firefox Tracking Flags

(blocking-b2g:-)

Details

(Whiteboard: [sprd319473][partner-blocker][c=progress p= s= u=])

Attachments

(9 attachments)

Steps to reproduce
-----------------------------------------------------------------------------
1. Launch Music
2. Select a song
3. Tap on the song to play
   --> User can hear the music about 2.9s after user tap to play the music.

Here is the test results:
Buri V1.4:       avg time is 2.5s
flame v1.4:      avg time is 2.4s
Dolphin:         avg time is 2.9s
7715 android:    avg time is 1.6s
Whiteboard: [sprd319473][partner-blocker][perf]
Keywords: perf
Priority: -- → P3
Whiteboard: [sprd319473][partner-blocker][perf] → [sprd319473][partner-blocker][progress p= s= u=]
Whiteboard: [sprd319473][partner-blocker][progress p= s= u=] → [sprd319473][partner-blocker][c=progress p= s= u=]
blocking-b2g: --- → 1.4?
Hi Evelyn,

Mind if you can take a look this one and see if the bug 1038080 can help to resolve this issue?
Flags: needinfo?(ehung)
How does this compare with 1.3?

Dominic/Jim: Can one of you please investigate
Flags: needinfo?(squibblyflabbetydoo)
Flags: needinfo?(dkuo)
Keywords: qawanted
Jim probably does not have a dolphin so I am taking this.
Assignee: nobody → dkuo
Flags: needinfo?(squibblyflabbetydoo)
Flags: needinfo?(dkuo)
ni on me to check
Flags: needinfo?(pcheng)
I tested on dolphin,buri v1.3, and buri v1.4 using the "same" music in the "same" SD card. 
Each device was tested 4 times, and for each time, I kill Music and relaunched.

The measurement is from taping on music to hearing music sound. Here is the result:

Avg time on dolphin: 2.1s
Avg time on buri v1.3: 1.5s
Avg time on buri v1.4: 1.6s
Flags: needinfo?(pcheng)
(In reply to Dominic Kuo [:dkuo] from comment #3)
> Jim probably does not have a dolphin so I am taking this.

I do have a dolphin, but I'm not 100% sure how to flash it.
This is release blocker according to symptom.
blocking-b2g: 1.4? → 1.4+
(In reply to Jim Porter (:squib) from comment #6)
> (In reply to Dominic Kuo [:dkuo] from comment #3)
> > Jim probably does not have a dolphin so I am taking this.
> 
> I do have a dolphin, but I'm not 100% sure how to flash it.

Hi Jim, can you try this wiki to flash your dolphin? Thanks!
https://intranet.mozilla.org/B2G_Team/Dolphin
blocking-b2g: 1.4+ → 1.4?
Flags: needinfo?(squibblyflabbetydoo)
Comment conflict during the triage. This is blocker.
blocking-b2g: 1.4? → 1.4+
(In reply to thomas tsai from comment #8)
> (In reply to Jim Porter (:squib) from comment #6)
> > (In reply to Dominic Kuo [:dkuo] from comment #3)
> > > Jim probably does not have a dolphin so I am taking this.
> > 
> > I do have a dolphin, but I'm not 100% sure how to flash it.
> 
> Hi Jim, can you try this wiki to flash your dolphin? Thanks!
> https://intranet.mozilla.org/B2G_Team/Dolphin

It needs Windows, so I won't be able to flash until I wipe my laptop and set it up to dual-boot...
Flags: needinfo?(squibblyflabbetydoo)
Peipei,

Would you please describe how you measure the time on start playing a song? I just got a dolphin with the latest build from the Taipei QA team, and tested the music app on it, the start-to-play time seems no significant delay for me so I might need your information, thanks!
Flags: needinfo?(pcheng)
(In reply to Dominic Kuo [:dkuo] from comment #11)
> Peipei,
> 
> Would you please describe how you measure the time on start playing a song?
> I just got a dolphin with the latest build from the Taipei QA team, and
> tested the music app on it, the start-to-play time seems no significant
> delay for me so I might need your information, thanks!

Sorry for not making the steps clear. Here is the steps:
1. Launch music
2. Go to Songs list (the fifth tab)
3. Tap on one song

The time is from "taping on a song" to "user can hear the music comes out". This may differ for different songs since some song may have some silence at the beginning. So I used the same song on the same SD card to test on dolphin,buri v1.3, and buri v1.4.

Hope this helps.
Flags: needinfo?(pcheng)
Dominic is helping. Thanks!
Flags: needinfo?(ehung)
Thanks Peipei, and base on your description, I try to measure the time from where the music app start playing a song to the first audio's timeupdate event, this duration should be close to what you described in comment 12.

The result is about 1600ms to 1800ms, looks like acceptable but is different from 2900ms, Peipei, could we have a video to compare with my test result here? thanks.
Flags: needinfo?(pcheng)
(In reply to Dominic Kuo [:dkuo] from comment #14)
> Thanks Peipei, and base on your description, I try to measure the time from
> where the music app start playing a song to the first audio's timeupdate
> event, this duration should be close to what you described in comment 12.
> 
> The result is about 1600ms to 1800ms, looks like acceptable but is different
> from 2900ms, Peipei, could we have a video to compare with my test result
> here? thanks.

This 2900ms data comes from partner. My test result is as mentioned in comment 5. 
Avg time on dolphin: 2.1s
Avg time on buri v1.3: 1.5s
Avg time on buri v1.4: 1.6s
It's very close to your result. But the performance on dolphin is worse than buri or 7715 android. 
So partner think this is unacceptable to be slower than 7715 android.
Flags: needinfo?(pcheng)
(In reply to pcheng from comment #12)
> (In reply to Dominic Kuo [:dkuo] from comment #11)
> > Peipei,
> > 
> > Would you please describe how you measure the time on start playing a song?
> > I just got a dolphin with the latest build from the Taipei QA team, and
> > tested the music app on it, the start-to-play time seems no significant
> > delay for me so I might need your information, thanks!
> 
> Sorry for not making the steps clear. Here is the steps:
> 1. Launch music
> 2. Go to Songs list (the fifth tab)
> 3. Tap on one song
> 
> The time is from "taping on a song" to "user can hear the music comes out".
> This may differ for different songs since some song may have some silence at
> the beginning. So I used the same song on the same SD card to test on
> dolphin,buri v1.3, and buri v1.4.
> 
> Hope this helps.

pcheng, could you also provide the song you used for this test to dominic since he is seeing 300-500ms difference on dolphin
Target Milestone: --- → 2.1 S1 (1aug)
Hi Peipei, Could you please kindly help with comment16 ? Thanks!
Flags: needinfo?(pcheng)
Dominic, please find the music file I use here: https://mega.co.nz/#!A8FkwbwY!WrvSV_0oDW7u7B4rfF1oCotcx_Tl65ReElUFkSekV4w
Flags: needinfo?(pcheng)
(In reply to Peipei Cheng from comment #18)
> Dominic, please find the music file I use here:
> https://mega.co.nz/#!A8FkwbwY!WrvSV_0oDW7u7B4rfF1oCotcx_Tl65ReElUFkSekV4w

Thanks Peipei.

I am assuming the start-to-play time is approximately the sum of: ui response + load file + decode audio.

And we could probably ignore the ui response time because it should less then 50ms, so I have log the file loading time and the audio decoding time to see what's the differences between flame and dolphin.

Flame:
----------------------------------------
file load time: ~500ms
decode time(first timeupdate event): ~1000ms

Dolphin:
----------------------------------------
file load time: ~500ms
decode time(first timeupdate event): ~1600ms

The file loading time is almost the same for flame and dolphin, so probably what have some differences on how we decode the audio files on flame and dolphin, which caused this issue.

Chris, do you know who could possibly help on this audio issue? looks like we need some helps here, thanks.
Flags: needinfo?(cpearce)
Flags: needinfo?(brsun)
To decrease framcount value for creating track object.
Hi, Peipei

Could you help to try the patch (attachment 8464482 [details] [diff] [review]) and provide the logcat log?
Thanks
Flags: needinfo?(brsun) → needinfo?(pcheng)
Cancelling the needinfo because Star is working on this.
Flags: needinfo?(cpearce)
Hi Peipei,could you please kindly help test the patch in coment21 ? Thanks !
Flags: needinfo?(pcheng)
Priority: P3 → P1
Posted file adb log
Star, please see attached log. Test starts: 07-31 14:48:27.520
Flags: needinfo?(pcheng)
(In reply to Peipei Cheng from comment #24)
> Created attachment 8465220 [details]
> adb log
> 
> Star, please see attached log. Test starts: 07-31 14:48:27.520

Hi, Peipei

Could you provide the avg time of testing like comment 0? (Please test flame & Dolphin device with the SW which includes my patch)
Thanks!

Here is the test results:
flame v1.4:      avg time is ?? s
Dolphin:         avg time is ?? s
Flags: needinfo?(pcheng) → needinfo?(pcheng)
Posted file log.txt
I tried to add logs to profile our music playback time based on our current gecko master (196658:f61a27b00e05).

I found that the period between the timing when HTMLMediaElement::Play() was called and the timing when AudioStream::DataCallback() finished writing first audio data to libcubeb is less than 500ms.

Take attachment 8465230 [details] for example:
 - 07-31 15:11:37.540   665   665 I brsun   : HTMLMediaElement::Play() enters
 - 07-31 15:11:38.050   665   731 I brsun   : AudioStream::DataCallback() wrote data (servicedFrames:1103)

There are five more similar logs compressed in attachment 8465231 [details].
(In reply to Bruce Sun [:brsun] from comment #28)
> Take attachment 8465230 [details] for example:
>  - 07-31 15:11:37.540   665   665 I brsun   : HTMLMediaElement::Play() enters
>  - 07-31 15:11:38.050   665   731 I brsun   : AudioStream::DataCallback()
> wrote data (servicedFrames:1103)

Just want to make this information more clear. This 500ms period includes all things below:
 - loading resource
 - decoding necessary data
 - copying the first data to libcubeb
I tested on two devices. One use the gonk with Star's patch and the other not. But both devices has the same gaia and gecko.
Then I played the same music at the same time. But it's really hard to tell the difference between these two devices. So the improvement is not noticeable.

Could we add some log like Bruce did so we can calculate the time instead of doing it manually?
dominic: Could you help measure the time duration between the timing when user touch the screen and the timing when Audio.play() is called?
padenot: Do you know how we could measure the time duration precisely between the timing when libcubeb receives data and the timing when the speaker generates corresponding sound?
Flags: needinfo?(paul)
Flags: needinfo?(dkuo)
(In reply to Peipei Cheng from comment #30)
> I tested on two devices. One use the gonk with Star's patch and the other
> not. But both devices has the same gaia and gecko.
> Then I played the same music at the same time. But it's really hard to tell
> the difference between these two devices. So the improvement is not
> noticeable.
> 
> Could we add some log like Bruce did so we can calculate the time instead of
> doing it manually?

Hi, Peipei

How did you measure the number of avg time in comment 0? Could you do it again by using the device with my patch?
Bruce, just call cubeb_stream_get_latency [0]. The value is in frame, so you need to divide by the sample rate and multiply by 1000 to get values in milliseconds.

[0]: http://dxr.mozilla.org/mozilla-central/source/media/libcubeb/include/cubeb.h#273
Flags: needinfo?(paul)
Posted file log_latency.txt
Thank you, Paul.

From the attachment 8465935 [details], the latency between the timing when data has been copied to libcubeb and the timing when the sound has been generated could be calculated as a constant value: 215ms.
 - 08-01 10:41:09.810   663   724 I brsun   : AudioStream::DataCallback() wrote data (servicedFrames:1103, latency:215 = GetLatencyInFrames(9525) * 1000 / GetRate(44100)
(In reply to Star Cheng [:scheng] from comment #33)
> (In reply to Peipei Cheng from comment #30)
> > I tested on two devices. One use the gonk with Star's patch and the other
> > not. But both devices has the same gaia and gecko.
> > Then I played the same music at the same time. But it's really hard to tell
> > the difference between these two devices. So the improvement is not
> > noticeable.
> > 
> > Could we add some log like Bruce did so we can calculate the time instead of
> > doing it manually?
> 
> Hi, Peipei
> 
> How did you measure the number of avg time in comment 0? Could you do it
> again by using the device with my patch?

Hi Star, the data in comment 0 comes from partner. My test data is in comment #5. That's: the avg time on dolphin was 2.1s while buri v1.3 and v1.4 were 1.5s and 1.6s.

I tested your patch and collect the data on dolphin manually. The average for 7 tests is "1.96s" which is very close to the result without patch.

I didn't test on Flame since I don't have Flame code. Anyway, we only compare performance issues with buri.
Flags: needinfo?(pcheng)
(In reply to Star Cheng [:scheng] from comment #21)
> Hi, Peipei
> 
> Could you help to try the patch (attachment 8464482 [details] [diff] [review]
> [review]) and provide the logcat log?
> Thanks

Xinhe, can you help?
Flags: needinfo?(xinhe.yan)
(In reply to James Zhang (Spreadtrum) from comment #38)
> (In reply to Star Cheng [:scheng] from comment #21)
> > Hi, Peipei
> > 
> > Could you help to try the patch (attachment 8464482 [details] [diff] [review]
> > [review]) and provide the logcat log?
> > Thanks
> 
> Xinhe, can you help?

xinhe, when you do the test, please make sure that you use the same song, because some song does not have sound in the beginning and it may make user think it took long time for music to start.
Posted image initial_silence.png
(In reply to Peipei Cheng from comment #18)
> Dominic, please find the music file I use here:
> https://mega.co.nz/#!A8FkwbwY!WrvSV_0oDW7u7B4rfF1oCotcx_Tl65ReElUFkSekV4w

Just want to take note. The initial silence period of this song itself is roughly 136ms.
(In reply to Bruce Sun [:brsun] from comment #31)
> dominic: Could you help measure the time duration between the timing when
> user touch the screen and the timing when Audio.play() is called?

The timing should be close to what I mentioned in comment 19, it should be the sum of the ui response + load file, and on dolphin it takes about 500~600ms, hope this helps. Please let me know if you need more info from the gaia layer.
Flags: needinfo?(dkuo)
Thanks Dominic.

The overall latency that an user experienced for "Because Of You.mp3" can be separated as:
 [a] From the user touches the screen to HTMLMediaElement::Play() is called:
  - As common 41, this is roughly 500~600ms.
 [b] From HTMLMediaElement::Play() is called to libcubeb receives the first decoded audio data:
  - As common 28, this is roughly 500ms.
 [c] From libcubeb receives the decoded audio data to the audio output device generates the sound:
  - As common 36, this is roughly 215ms.
 [d] From the beginning of this song to the first audible music data within it:
  - As common 40, this is roughly 136ms.

In summary, an user experiences roughly 1351~1451ms silent period after (s)he select "Because Of You.mp3".
(In reply to Bruce Sun [:brsun] from comment #42)
> Thanks Dominic.
> 
> The overall latency that an user experienced for "Because Of You.mp3" can be
> separated as:
>  [a] From the user touches the screen to HTMLMediaElement::Play() is called:
>   - As common 41, this is roughly 500~600ms.
>  [b] From HTMLMediaElement::Play() is called to libcubeb receives the first
> decoded audio data:
>   - As common 28, this is roughly 500ms.
>  [c] From libcubeb receives the decoded audio data to the audio output
> device generates the sound:
>   - As common 36, this is roughly 215ms.
>  [d] From the beginning of this song to the first audible music data within
> it:
>   - As common 40, this is roughly 136ms.
> 
> In summary, an user experiences roughly 1351~1451ms silent period after
> (s)he select "Because Of You.mp3".

s/common/comment/
The most variable part within the overall experience is [d]. If we neglect this period, the user roughly experiences 1215~1315ms latency after (s)he selects one song from the list.
(In reply to Peipei Cheng from comment #15)
> It's very close to your result. But the performance on dolphin is worse than
> buri or 7715 android. 
> So partner think this is unacceptable to be slower than 7715 android.

Hi Peipei,
Is the performance of 7715 android a hard requirement of FirefoxOS on dolphin?
Or what is the acceptance criteria of FirefoxOS on dolphin?
Flags: needinfo?(pcheng)
(In reply to Bruce Sun [:brsun] from comment #45)
> (In reply to Peipei Cheng from comment #15)
> > It's very close to your result. But the performance on dolphin is worse than
> > buri or 7715 android. 
> > So partner think this is unacceptable to be slower than 7715 android.
> 
> Hi Peipei,
> Is the performance of 7715 android a hard requirement of FirefoxOS on
> dolphin?
> Or what is the acceptance criteria of FirefoxOS on dolphin?

I can check on latest build. I will have a meeting with QA and PM this evening.  
I guess I can give feedback tomorrow whether they can accept it.
Flags: needinfo?(xinhe.yan)
(In reply to Bruce Sun [:brsun] from comment #45)
> (In reply to Peipei Cheng from comment #15)
> > It's very close to your result. But the performance on dolphin is worse than
> > buri or 7715 android. 
> > So partner think this is unacceptable to be slower than 7715 android.
> 
> Hi Peipei,
> Is the performance of 7715 android a hard requirement of FirefoxOS on
> dolphin?
> Or what is the acceptance criteria of FirefoxOS on dolphin?

Partner took 7715 android performance as baseline for their tests. So they hope the performance on dolphin should be as good as 7715 android. Otherwise, later it might be a concern for their customer.

Thanks xinhe for helping.
Flags: needinfo?(pcheng)
I think Buri is a good reference for performance issue. Buri is single core platform with similar ram size and similar cpu speed.
(In reply to thomas tsai from comment #48)
> I think Buri is a good reference for performance issue. Buri is single core
> platform with similar ram size and similar cpu speed.

Yes, I also tested in Buri, dolphin is about 400ms slower than buri. Please see comment 37 and comment 5. I think the UI response time on dolphin is slower than buri.

Bruce, could you please also help analysis on buri? Please let me know if you need my help.
Flags: needinfo?(brsun)
Posted video VIDEO0003.mp4
I recorded a video to show how dolphin performed while playing "Because Of You.mp3". I would say the overall experienced latency was close to my breakdown as comment 42. I am wondering whether it is really a big trouble for users to listen music with dolphin.

echou: what do you think?
Flags: needinfo?(echou)
(In reply to Bruce Sun [:brsun] from comment #50)
> Created attachment 8467689 [details]
> VIDEO0003.mp4
> 
> I recorded a video to show how dolphin performed while playing "Because Of
> You.mp3". I would say the overall experienced latency was close to my
> breakdown as comment 42. I am wondering whether it is really a big trouble
> for users to listen music with dolphin.
> 
> echou: what do you think?

From the video, IMO the latency this is totally acceptable to an user.

So I'm curious: do we really have a strict criteria of 'the latency before playing the music' and it has been spec'ed anywhere? If there isn't, then why is this blocking? Partner said that "this is unacceptable to be slower than 7715 android" but I have never received such requirements to compare a FxOS with an Android device. cc Marvin, product manager of multimedia platform, to figure this out.

In addition, since the latency may be affected by the circumstances such as memory and CPU usage, Peipei, Bruce may need to know more details about the testing environment in order to dig into it. Would you mind recording a video of how you test?
Flags: needinfo?(pcheng)
Flags: needinfo?(mkhoo)
Flags: needinfo?(echou)
I get data from tester. They test two audio source yesterday.
One consume 1.8s. Another consume 2.2s. The data is roughly equal to Buri.
Android consume around 0.5s-1s. 
I guess the flow in music app is different.

But PM can not accepte the data.
Summary: [dolphin][perf] It took about 2.9s for music to start play → [dolphin][perf] It took about 1.8-2.2s for music to start play
(In reply to Xinhe Yan from comment #52)
> I get data from tester. They test two audio source yesterday.
> One consume 1.8s. Another consume 2.2s. The data is roughly equal to Buri.
> Android consume around 0.5s-1s. 
> I guess the flow in music app is different.
> 
> But PM can not accepte the data.

Would you mind providing those two audio sources?
Flags: needinfo?(xinhe.yan)
(In reply to Bruce Sun [:brsun] from comment #53)
> (In reply to Xinhe Yan from comment #52)
> > I get data from tester. They test two audio source yesterday.
> > One consume 1.8s. Another consume 2.2s. The data is roughly equal to Buri.
> > Android consume around 0.5s-1s. 
> > I guess the flow in music app is different.
> > 
> > But PM can not accepte the data.
> 
> Would you mind providing those two audio sources?
https://mega.co.nz/#!vlR2xIwA!vdvYwOiDNnM-Lmm59S4TcSa4SG2oyhN77bsjFVySI_U
Flags: needinfo?(xinhe.yan)
Initial silent duration within "1.mp3" itself is 109ms.
Initial silent duration within "2.mp3" itself is 1025ms, which is longer than 1 second.
It would be a surprise for me that "2.mp3" could be heard within 1 second on any other platform after playing from the beginning.
Removing blocker flag to this as this does NOT seems to be a blocker.

As discussed internal with TAM, this should not be blocker as the result, is already closed to Buri.
our benchmark for this project is Buri not Android. hope this clarified.
blocking-b2g: 1.4+ → -
Flags: needinfo?(pcheng)
Flags: needinfo?(mkhoo)
Flags: needinfo?(brsun)
Just check with tester, they might only record the time of 1.mp3.

I run a test myself.

FFOS
1.mp3 1.5,1.42,1.4,1.2, avg 1.38
2.mp3 2.7,2.58,2.16,2.4, avg 2.46  
Android
1.mp3 around 0.8s 
2.mp3 1.6,1.5,1.7,1.67, avg 1.61

Results from our tester is 1.8s/2.2s. I use  stopwatch to check time. It is not very accurate.

As I sad in comment #52:
The data is roughly equal to Buri.
I am not working on the patch, just helping to log the times so unassigning myself first.
Assignee: dkuo → nobody
Target Milestone: 2.1 S1 (1aug) → ---
We no longer support these configs.
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.