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

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: Gaia::Music, defect, P1)

Description

[Peipei Cheng (needinfo if you need my action)]

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

Comment 1

[Ivan Tsay (:ITsay)]

Hi Evelyn,

Mind if you can take a look this one and see if the bug 1038080 can help to resolve this issue?

Comment 2

[Hema Koka [:hema]]

How does this compare with 1.3?

Dominic/Jim: Can one of you please investigate

Comment 3

[Dominic Kuo [:dkuo]]

Jim probably does not have a dolphin so I am taking this.

Comment 4

[Peipei Cheng (needinfo if you need my action)]

ni on me to check

Comment 5

[Peipei Cheng (needinfo if you need my action)]

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

Comment 6

[Jim Porter (:squib)]

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

Comment 7

[Ivan Tsay (:ITsay)]

This is release blocker according to symptom.

Comment 8

[thomas tsai]

(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

Comment 9

[Ivan Tsay (:ITsay)]

Comment conflict during the triage. This is blocker.

Comment 10

[Jim Porter (:squib)]

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

Comment 11

[Dominic Kuo [:dkuo]]

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!

Comment 12

[Peipei Cheng (needinfo if you need my action)]

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

Comment 13

[Evelyn Hung]

Dominic is helping. Thanks!

Comment 14

[Dominic Kuo [:dkuo]]

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.

Comment 15

[Peipei Cheng (needinfo if you need my action)]

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

Comment 16

[Hema Koka [:hema]]

(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

Comment 17

[Rachelle Yang [:ryang][[e-mail]]]

Hi Peipei, Could you please kindly help with comment16 ? Thanks!

Comment 18

[Peipei Cheng (needinfo if you need my action)]

Dominic, please find the music file I use here: https://mega.co.nz/#!A8FkwbwY!WrvSV_0oDW7u7B4rfF1oCotcx_Tl65ReElUFkSekV4w

Comment 19

[Dominic Kuo [:dkuo]]

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

Comment 20

[Star Cheng [:scheng]]

Attachment: bug-1033337-test.patch

To decrease framcount value for creating track object.

Comment 21

[Star Cheng [:scheng]]

Hi, Peipei

Could you help to try the patch (attachment 8464482 [details] [diff] [review]) and provide the logcat log?
Thanks

Comment 22

[Dominic Kuo [:dkuo]]

Cancelling the needinfo because Star is working on this.

Comment 23

[Rachelle Yang [:ryang][[e-mail]]]

Hi Peipei,could you please kindly help test the patch in coment21 ? Thanks !

Comment 24

[Peipei Cheng (needinfo if you need my action)]

Attachment: adb log

Star, please see attached log. Test starts: 07-31 14:48:27.520

Comment 25

[Star Cheng [:scheng]]

(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

Comment 26

[Bruce Sun [:brsun]]

Attachment: log.txt

Comment 27

[Bruce Sun [:brsun]]

Attachment: 20140731_bug1033337_music_launch_time_logs.tar.gz

Comment 28

[Bruce Sun [:brsun]]

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].

Comment 29

[Bruce Sun [:brsun]]

(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

Comment 30

[Peipei Cheng (needinfo if you need my action)]

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?

Comment 31

[Bruce Sun [:brsun]]

dominic: Could you help measure the time duration between the timing when user touch the screen and the timing when Audio.play() is called?

Comment 32

[Bruce Sun [:brsun]]

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?

Comment 33

[Star Cheng [:scheng]]

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

Comment 34

[Paul Adenot (:padenot)]

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

Comment 35

[Bruce Sun [:brsun]]

Attachment: log_latency.txt

Comment 36

[Bruce Sun [:brsun]]

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)

Comment 37

[Peipei Cheng (needinfo if you need my action)]

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

Comment 38

[James Zhang (Spreadtrum)]

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

Comment 39

[Peipei Cheng (needinfo if you need my action)]

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

Comment 40

[Bruce Sun [:brsun]]

Attachment: 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.

Comment 41

[Dominic Kuo [:dkuo]]

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

Comment 42

[Bruce Sun [:brsun]]

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".

Comment 43

[Bruce Sun [:brsun]]

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

Comment 44

[Bruce Sun [:brsun]]

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.

Comment 45

[Bruce Sun [:brsun]]

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

Comment 46

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

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.

Comment 47

[Peipei Cheng (needinfo if you need my action)]

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

Comment 48

[thomas tsai]

I think Buri is a good reference for performance issue. Buri is single core platform with similar ram size and similar cpu speed.

Comment 49

[Peipei Cheng (needinfo if you need my action)]

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

Comment 50

[Bruce Sun [:brsun]]

Attachment: 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?

Comment 51

[Eric Chou [:ericchou] [: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?

Comment 52

[Xinhe Yan]

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.

Comment 53

[Bruce Sun [:brsun]]

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

Comment 54

[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

Comment 55

[Bruce Sun [:brsun]]

Attachment: music_source_1_mp3.png

Initial silent duration within "1.mp3" itself is 109ms.

Comment 56

[Bruce Sun [:brsun]]

Attachment: music_source_2_mp3.png

Initial silent duration within "2.mp3" itself is 1025ms, which is longer than 1 second.

Comment 57

[Bruce Sun [:brsun]]

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.

Comment 58

[Marvin Khoo [:Marvin_Khoo]]

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.

Comment 59

[Xinhe Yan]

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.

Comment 60

[Dominic Kuo [:dkuo]]

I am not working on the patch, just helping to log the times so unassigning myself first.

Comment 61

[Hubert Figuiere [:hub]]

We no longer support these configs.