882552 - Slow OMX codec behavior

Status: RESOLVED FIXED

(Core :: Audio/Video, defect, P1)

Description

[Robert O'Callahan (:roc) (email my personal email if necessary)]

See https://bugzilla.mozilla.org/show_bug.cgi?id=880601#c17.

Sometimes my dev phone gets into a state where calls into libstagefright codec 'read' calls are often slow (50-100ms or more, for audio or video). The data-source readAt calls are not blocking, they only read cached data, so it's probably not a network or caching issue. This makes video and audio playback intolerably jerky (although it does stay in sync now). Other times when I run the testcase, this doesn't happen at all and all the 'read' calls are fast.

See http://people.mozilla.com/~roc/troy.3gp.

Comment 1

[Sotaro Ikeda [:sotaro]]

One possibility is that omx codec driver task is blocked in kernel by other task. It might happen when data is written to flash/sd.

Comment 2

[Robert O'Callahan (:roc) (email my personal email if necessary)]

What would be the best way to try to debug this?

Comment 3

[Sotaro Ikeda [:sotaro]]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #2)
> What would be the best way to try to debug this?

If it is the case, write to MediaCache file's becomes slow. I checked write to the file. And it is not the problem in this case.

Comment 4

[Sotaro Ikeda [:sotaro]]

Attachment: patch - add logout

Comment 5

[Sotaro Ikeda [:sotaro]]

(In reply to Sotaro Ikeda [:sotaro] from comment #4)
> Created attachment 763127 [details] [diff] [review]
> patch - add logout

By applying the patch, I confirmed the OMXCodec::read() delay. I feel that Binder IPC overhead from cpu usage point of view is not significant, but IPC turn around time is big.

Comment 6

[Sotaro Ikeda [:sotaro]]

Similar thing already happened in Bug 864180. It happened because of Bug 879529.  Decreasing the thread priority causes serious IPC latency. From this, it become clear that thread scheduling affected IPC latency significantly.

Comment 7

[Sotaro Ikeda [:sotaro]]

Attachment: patch - move audio codec to app process if video track presents

The patch move audio codec to the app process and use sw codec if there is a video track. I confirmed that this patch reduces OMXCodec::read()'s time.

Current usage of audio hw codec is for long time music playback. No necessity to use hw audio codec for movie.

Comment 8

[Sotaro Ikeda [:sotaro]]

On ics_chocolate(unagi, inari), The fix of Bug 864230 is not applied. It is necessary to apply the patch to check OMXCodec::read() latency.

Comment 9

[Sotaro Ikeda [:sotaro]]

Attachment: thread priority log during youtube video playback

log of "adb shell ps -p -t" during Youtube video playback by video app.

Comment 10

[Sotaro Ikeda [:sotaro]]

(In reply to Sotaro Ikeda [:sotaro] from comment #9)
> Created attachment 763140 [details]
> thread priority log during youtube video playback
> 
> log of "adb shell ps -p -t" during Youtube video playback by video app.

Binder thread's priority is very low.

Comment 11

[Sotaro Ikeda [:sotaro]]

Attachment: patch - change Binder Thread's default priority to 0

By applying the patch. Binder thread's default priority(nice) from 18 to 0.

Comment 12

[Sotaro Ikeda [:sotaro]]

Attachment: logout of applying attachment 763164

By applying attachment 763164 [details] [diff] [review], OMXCodec::read()'s duration becomes much better. Almost all audio track's read() becomes within 40ms. Video track's read() also becomes better but still sometime takes longer time. From the log, it seems related to media cache's related thing.

Comment 13

[Robert O'Callahan (:roc) (email my personal email if necessary)]

That sounds great!

Comment 14

[Robert O'Callahan (:roc) (email my personal email if necessary)]

The log is a hard to understand because you can't see when a ReadVideo call started, so you can't tell which readAts belong to which ReadVideo call. If ReadVideo calls never overlapped, I can't explain

06-15 18:31:55.137   449   458 I GonkOmx : MediaStreamSource::readAt() duration 14
06-15 18:31:55.477   449   458 I GonkOmx : MediaStreamSource::readAt() duration 14
06-15 18:31:58.069   449   525 I GonkOmx : MediaStreamSource::readAt() duration 19
06-15 18:32:02.774   449   525 I GonkOmx : MediaStreamSource::readAt() duration 12
06-15 18:32:02.804   449   460 I GonkOmx : MediaStreamSource::readAt() duration 21
06-15 18:32:09.260   449   515 I GonkOmx : MediaStreamSource::readAt() duration 24
06-15 18:32:13.374   449   458 I GonkOmx : MediaStreamSource::readAt() duration 49
06-15 18:32:13.374   449   512 I GonkOmx : OmxDecoder::ReadVideo() 2 duration 44

where it looks like the sum of the readAt durations is much greater than the time under ReadVideo...

Comment 15

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Anyway I think we should land the patch in comment #11 and then try to debug the remaining problems separately.

Comment 17

[Michael Wu [:mwu]]

Comment on attachment 763164 [details] [diff] [review]
patch - change Binder Thread's default priority to 0

Looks fine to me, though I think jlebar might have more of an opinion on these things than I do.

Comment 18

[Justin Lebar (not reading bugmail)]

This is pretty complicated...

The binder (kernel/drivers/staging/android/binder.c) reads and saves the process's niceness when it starts up.  It renices itself all the time, and it occasionally restores itself to the niceness it originally saved.

Without knowing what the binder thread actually does, I agree that restoring itself to niceness 0 probably makes more sense than restoring itself to niceness 18, just because the process happened to have been started with niceness 18.

My main complaint here is that the code in this patch will work only if the process is launched with root permissions.  If we're not root and we try to lower our priority, we'll silently fail.  I'd prefer if we made a ruckus about it, so that we have some chance of discovering if we regress this bug.

Can you add a debug-build fatal assertion that the renice succeeds, and also print to logcat if the renice fails in a release build?

Comment 19

[Justin Lebar (not reading bugmail)]

Comment on attachment 763164 [details] [diff] [review]
patch - change Binder Thread's default priority to 0

I'd like to take another quick look here.

Comment 20

[Sotaro Ikeda [:sotaro]]

Attachment: patch v2 - change Binder Thread's default priority to 0

From comment #18, add "debug-build fatal assertion" and "print to logcat".

Comment 21

[Sotaro Ikeda [:sotaro]]

Attachment: patch v3 - change Binder Thread's default priority to 0

Fix nits.

Comment 22

[Sotaro Ikeda [:sotaro]]

Comment on attachment 765000 [details] [diff] [review]
patch v3 - change Binder Thread's default priority to 0

Can you review the updated patch?

Comment 23

[Justin Lebar (not reading bugmail)]

Comment on attachment 765000 [details] [diff] [review]
patch v3 - change Binder Thread's default priority to 0

> +    LOGE_IF(err, "setpriority failed");

Please make this a more descriptive error message.  Ideally we want something that someone can see and understand that it's a bug that should be reported.

r=me with that fixed.

Comment 24

[Sotaro Ikeda [:sotaro]]

Attachment: patch v4 - change Binder Thread's default priority to 0

Apply the comment. Carry "r+ mwu,jlebar".

Comment 25

[Sotaro Ikeda [:sotaro]]

https://tbpl.mozilla.org/?tree=Try&rev=a5d58631c6bb

Comment 26

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/880c8be7f35f

Comment 27

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/880c8be7f35f

Comment 28

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g18/rev/a34f6d62cb05

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g18_v1_1_0_hd/rev/a34f6d62cb05