1002917 - b2g process is using RT scheduling and running long time

Status: RESOLVED INCOMPLETE

(Firefox OS Graveyard :: GonkIntegration, defect, P1)

Description

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

Attachment: logs.zip

STR:

1.Made an MO call.
2.BT ON and paired with other device.
3.Transfered Vedio file via BT
4.Launch Browser and surf for sometime.
5.Downloaded games from MarketPlace.
6.sent multiple MO SMS.
7.MAde an MT call device got crashed.

It is difficult to reproduce as it happens randomly.

It seems to us RT scheduling enabled AudioTrack playback, introduced in https://bugzilla.mozilla.org/show_bug.cgi?id=962932

Can anyone why b2g needs to RT task for a long time ? RT task should run <1sec and yield cpu to other task. Otherwise it will cause CPU hogging and result will be crash.

Please suggest .

Comment 1

[Sotaro Ikeda [:sotaro]]

> 
> Can anyone why b2g needs to RT task for a long time ? RT task should run
> <1sec and yield cpu to other task. Otherwise it will cause CPU hogging and
> result will be crash.

I think that b2g basically should not use RT. Sorry, I do not know the reason. Some people seems to be tempted to use RT priority just to fix some use case.

Comment 2

[Gabriele Svelto [:gsvelto]]

(In reply to Tapas Kumar Kundu from comment #0)
> Can anyone why b2g needs to RT task for a long time ? RT task should run
> <1sec and yield cpu to other task. Otherwise it will cause CPU hogging and
> result will be crash.

How is RT scheduling related to the crash here? And also which device did you experience this on? IIRC bug 962932 only affects Jelly Bean and KitKat devices. I'm CC'ing the people who worked on that bug just in case.

Comment 3

[Dave Hylands [:dhylands]]

If an RT thread were to consume 100% of the CPU, then no other thread would every get scheduled, ever, until the RT thread stops using 100% of the CPU.

Comment 4

[Michael Vines [:m1] [:evilmachines]]

We are getting a watchdog bark because a kernel kworker thread can't pet the dog due enough due to the RT scheduling in the b2g process.

Comment 5

[Michael Wu [:mwu]]

RT scheduling should not be used unless we are absolutely sure the process only eats a certain percentage of CPU. Unfortunately it looks like low latency AudioTracks rely on RT scheduling. I think we can disable RT scheduling in gonksched without regressing bug 962932.

Comment 6

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Michael Wu [:mwu] from comment #5)
> RT scheduling should not be used unless we are absolutely sure the process
> only eats a certain percentage of CPU. Unfortunately it looks like low
> latency AudioTracks rely on RT scheduling. I think we can disable RT
> scheduling in gonksched without regressing bug 962932.

Shouldn't this be ok as this is how android JB works?  I thought enabling the RT scheduling for these low latency AudioTracks was the whole point of your fix for bug 962932.

Comment 7

[Michael Wu [:mwu]]

Bug 962932 was mostly fixing lag due to a timeout. Audio playback was slow because the audio thread gets permission to use low latency, and then waits a very long time for the priority boost which never happens. That wait should go away if we just deny permission.

Comment 8

[Ben Kelly [:bkelly, not reviewing]]

Do we know why these AudioTracks are running wild or using too much CPU here vs on android?  My understanding was that this is all in the omx/android code, right?  Just turning off the RT priority here seems like papering over the problem.

Michael, your build does not have FAST_TRACKS_AT_NON_NATIVE_SAMPLE_RATE enabled, does it?

Comment 9

[bhargavg1]

(In reply to Ben Kelly [:bkelly] from comment #8)
> Do we know why these AudioTracks are running wild or using too much CPU here
> vs on android?  My understanding was that this is all in the omx/android
> code, right?  Just turning off the RT priority here seems like papering over
> the problem.
> 
> Michael, your build does not have FAST_TRACKS_AT_NON_NATIVE_SAMPLE_RATE
> enabled, does it?

No its not enabled [1] 

[1] https://www.codeaurora.org/cgit/quic/la/platform/frameworks/av/tree/services/audioflinger/Configuration.h?h=b2g_kk_3.5#n36

Comment 10

[Michael Wu [:mwu]]

(In reply to Ben Kelly [:bkelly] from comment #8)
> Do we know why these AudioTracks are running wild or using too much CPU here
> vs on android?  My understanding was that this is all in the omx/android
> code, right?  Just turning off the RT priority here seems like papering over
> the problem.
> 

I don't think it's papering over the problem. We just can't use RT priority unless we can be sure that the audio callbacks finish within a bounded timeframe.

> Michael, your build does not have FAST_TRACKS_AT_NON_NATIVE_SAMPLE_RATE
> enabled, does it?

I don't think that matters. The opensl backend determines what the native sample rate is likely to be and tries to use that.

Comment 11

[Jason Smith [:jsmith]]

Can we get a crash stack?

Comment 12

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Michael Wu [:mwu] from comment #10)
> I don't think it's papering over the problem. We just can't use RT priority
> unless we can be sure that the audio callbacks finish within a bounded
> timeframe.

Right, but what is different for us vs android?  These callbacks were designed to use this scheme on android with RT priority.

Also, looking at the steps in comment 0, I don't see a ton of audio being performed that would use AudioTracks.  Don't we only trigger this code for mp3 playback?

Do we have a process listing or something that shows the audio tracks using all the CPU or is this still just a guess?

Does this occur without bluetooth in use?

Comment 13

[Ben Kelly [:bkelly, not reviewing]]

Is this related to the watchdog or unrelated?

  04-23 14:33:51.033 E/GKI_LINUX(  207): ##### ERROR : timer_thread: tick delayed > 5 slots (-71920729,-50000000) -- cpu overload ? #####

I see lots of those pretty much from the start of the log.

I also see this:

  04-23 14:31:52.873 E/GeckoConsole(  207): [JavaScript Error: "IndexedDB UnknownErr: IDBTransaction.cpp:863"]

The dmesg is empty due to a permissions error, by the way.

Comment 14

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

(In reply to Ben Kelly [:bkelly] from comment #12)

> Do we have a process listing or something that shows the audio tracks using
> all the CPU or is this still just a guess?
> 
Should we put extra logging in gecko or gonksched to know who is giving RT to a thread for more than 1 second or so ? If you can provide us WIP patch which will log these info from gecko/gonksched then we will try to reproduce this issue with your patch and update new log here. 

>> Does this occur without bluetooth in use?
We didn't check it by disabling Bluetooth so far.

Comment 15

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Tapas Kumar Kundu from comment #14)
> Should we put extra logging in gecko or gonksched to know who is giving RT
> to a thread for more than 1 second or so ? If you can provide us WIP patch
> which will log these info from gecko/gonksched then we will try to reproduce
> this issue with your patch and update new log here. 

Do you have something that indicates its a thread belonging to the b2g process?  Or is that an educated guess at this point?  I see b2g is using 30% cpu in top, but that may or may not be relevant.

As far as I know the only thing that can lead to RT priority in b2g user space is the gonksched granting permission to AudioTask.  You could log a message here to see if that is being triggered:

  https://github.com/mozilla-b2g/gonk-misc/blob/master/gonksched.cpp#L88

You can print out the tid and then we can line it up with the threads owned by b2g.  I think you can see the b2g threads by running b2g-info -t or looking in /proc/<b2g pid>/tasks.

We could also modify b2g-info -t to display the cpu time for each thread.  This might help us see which thread under b2g is using that 30% CPU and then correlate it to the audio task.

Comment 16

[Michael Wu [:mwu]]

(In reply to Ben Kelly [:bkelly] from comment #12)
> (In reply to Michael Wu [:mwu] from comment #10)
> > I don't think it's papering over the problem. We just can't use RT priority
> > unless we can be sure that the audio callbacks finish within a bounded
> > timeframe.
> 
> Right, but what is different for us vs android?  These callbacks were
> designed to use this scheme on android with RT priority.
> 

Yeah, but only for users who opt into it and understand that their code must complete within a bounded amount of time. I'm not sure we can say that for the users of the cubeb backend.

> Also, looking at the steps in comment 0, I don't see a ton of audio being
> performed that would use AudioTracks.  Don't we only trigger this code for
> mp3 playback?
> 

All audio playback involving pcm samples use AudioTracks.

Comment 17

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Michael Wu [:mwu] from comment #16)
> All audio playback involving pcm samples use AudioTracks.

I guess the other piece I don't understand is the UID check here:

  https://github.com/mozilla-b2g/gonk-misc/blob/master/gonksched.cpp#L79

It was my impression that individual threads could not have a different UID from the owning process.  Do our client processes run with the IAD_MEDIA UID?  Or is this running in the mediaserver process separate from the b2g process.

Comment 18

[Dave Hylands [:dhylands]]

I believe that the media server is the only process that runs with userid AID_MEDIA

My understanding is that gonksched is a standalone daemon that runs as root.

Comment 19

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

(In reply to Ben Kelly [:bkelly] from comment #15)
 
> Do you have something that indicates its a thread belonging to the b2g
> process?  Or is that an educated guess at this point?  I see b2g is using
> 30% cpu in top, but that may or may not be relevant.

This is confirmed by kernel debugging. Our observation:
 1-core 0 is only alive core
 2- other cores are in power collapse
 3- on core 0 b2g is running and hogging cpu
 4- b2g is running as rt (real time process) so it should not do cpu intensive work. (concluded by looking at run queue data structure )
 5- while kthread worker which is supposed to pet watchdog is runnable and follows cfs class schduling
 6- since it cannot get cpu unless rt class process leave cpu so results in watchdog bark

Comment 20

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Tapas Kumar Kundu from comment #19)
> (In reply to Ben Kelly [:bkelly] from comment #15)
>  
> > Do you have something that indicates its a thread belonging to the b2g
> > process?  Or is that an educated guess at this point?  I see b2g is using
> > 30% cpu in top, but that may or may not be relevant.
> 
> This is confirmed by kernel debugging. Our observation:
>  1-core 0 is only alive core
>  2- other cores are in power collapse
>  3- on core 0 b2g is running and hogging cpu
>  4- b2g is running as rt (real time process) so it should not do cpu
> intensive work. (concluded by looking at run queue data structure )
>  5- while kthread worker which is supposed to pet watchdog is runnable and
> follows cfs class schduling
>  6- since it cannot get cpu unless rt class process leave cpu so results in
> watchdog bark

Well, based on this:

(In reply to Dave Hylands [:dhylands] from comment #18)
> I believe that the media server is the only process that runs with userid
> AID_MEDIA

It seems a bit of a mystery how we are getting into RT priority.  That UID check means gonksched will only elevate the priority of the mediaserver process.  I don't know of anywhere else that we set RT priority currently.

Tapas, can you see which thread is running at that priority?  Or just that its some thread within b2g process?

Comment 21

[Ben Kelly [:bkelly, not reviewing]]

Well, bluedroid sets its timer thread to RT priority 32!

  http://code.metager.de/source/xref/android/4.3/external/bluetooth/bluedroid/gki/ulinux/gki_ulinux.c#742
  http://code.metager.de/source/xref/android/4.3/external/bluetooth/bluedroid/gki/ulinux/gki_int.h#46
  http://code.metager.de/source/xref/android/4.3/external/bluetooth/bluedroid/gki/ulinux/gki_int.h#53

Which combined with these error messages:

    04-23 14:33:51.033 E/GKI_LINUX(  207): ##### ERROR : timer_thread: tick delayed > 5 slots (-71920729,-50000000) -- cpu overload ? #####

From your log process 207 is the same as the parent gecko process:

04-23 14:24:13.523 I/Gonk    (  207): Setting nice for pid 207 to 0
04-23 14:24:13.523 I/Gonk    (  207): Changed nice for pid 207 from 0 to 0.

Might explain some of the problem...

Comment 22

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

ni'ing in the BT team.

Comment 23

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Ben Kelly [:bkelly] from comment #21)
>     04-23 14:33:51.033 E/GKI_LINUX(  207): ##### ERROR : timer_thread: tick
> delayed > 5 slots (-71920729,-50000000) -- cpu overload ? #####
> 
> From your log process 207 is the same as the parent gecko process:
> 
> 04-23 14:24:13.523 I/Gonk    (  207): Setting nice for pid 207 to 0
> 04-23 14:24:13.523 I/Gonk    (  207): Changed nice for pid 207 from 0 to 0.
> Might explain some of the problem...
Sorry, I opened bug 933589 when I ported Gecko to support bluedroid for JellyBean on Nexus 4, and I never know this is related to RT priority. I also check this error message (ERROR : timer_thread: tick delayed) never shows on AOSP Android devices which use the same library. And bluedroid library uses real time priority for GKI_timer_update() thread. 
http://androidxref.com/4.4.2_r2/xref/external/bluetooth/bluedroid/gki/ulinux/gki_int.h#49

Comment 24

[Preeti Raghunath(:Preeti)]

Tapas,

Can we please get a stack and signature for the crash?

Comment 25

[Preeti Raghunath(:Preeti)]

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #23)
> (In reply to Ben Kelly [:bkelly] from comment #21)
> >     04-23 14:33:51.033 E/GKI_LINUX(  207): ##### ERROR : timer_thread: tick
> > delayed > 5 slots (-71920729,-50000000) -- cpu overload ? #####
> > 
> > From your log process 207 is the same as the parent gecko process:
> > 
> > 04-23 14:24:13.523 I/Gonk    (  207): Setting nice for pid 207 to 0
> > 04-23 14:24:13.523 I/Gonk    (  207): Changed nice for pid 207 from 0 to 0.
> > Might explain some of the problem...
> Sorry, I opened bug 933589 when I ported Gecko to support bluedroid for
> JellyBean on Nexus 4, and I never know this is related to RT priority. I
> also check this error message (ERROR : timer_thread: tick delayed) never
> shows on AOSP Android devices which use the same library. And bluedroid
> library uses real time priority for GKI_timer_update() thread. 
> http://androidxref.com/4.4.2_r2/xref/external/bluetooth/bluedroid/gki/ulinux/
> gki_int.h#49

Shawn

Are we able to reproduce the crash? Do we need anything from partner here?

Comment 26

[Michael Vines [:m1] [:evilmachines]]

(In reply to Preeti Raghunath(:Preeti) from comment #24)
> Tapas,
> 
> Can we please get a stack and signature for the crash?

This is a watchdog bark and not a Gecko crash so there's no stack trace that would really be useful here.

I think next steps here are for us to dig into how the Bluedroid RT task usage in Android differs from us.  The gonksched RT usage looks like a dead end (we did have that code on v1.3 after all and didn't run into this, but BT moved from BlueZ to Bluedroid in in v1.4)

Comment 27

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

clearing NI as m1 has already answered :)

Comment 28

[Preeti Raghunath(:Preeti)]

Tim/ Eric,

Please review next steps per m1's comments on 26

Comment 29

[Tim Guan-tin Chien [:timdream] (please needinfo)]

I can't help Gonk/Gecko crash issue.

Comment 30

[Thomas Zimmermann [:tzimmermann] [:tdz]]

Hi Shawn,

What if we patch Bluedroid to set GKI_LINUX_TIMER_POLICY to SCHED_OTHER (i.e. the non-RT scheduler)? Will Bluedroid still work in this case?

Comment 31

[Ben Kelly [:bkelly, not reviewing]]

It seems to me we need to track down the issue with bug 933589.  If the timer is running out of control, we should fix that instead of lowering its priority.

Comment 32

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

(In reply to Ben Kelly [:bkelly] from comment #31)
> It seems to me we need to track down the issue with bug 933589.  If the
> timer is running out of control, we should fix that instead of lowering its
> priority.

I just verified that Android Kitkat is getting EPERM error in [1] and Android kitkat bluetooth works fine with that.

[1] https://www.codeaurora.org/cgit/external/gigabyte/platform/external/bluetooth/bluedroid/tree/gki/ulinux/gki_ulinux.c?h=caf/b2g_kk_3.5#n751

Currently we are calling [1] from b2g main process and we are changing priority successfully. 

This means that if we simply disable this portion of code[1] then bluedroid stack should work fine for us (like Android).

I can upload a simple patch for that. 

Do you still want to switch from GKI_LINUX_TIMER_POLICY to SCHED_OTHER ?

Comment 33

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Thomas Zimmermann [:tzimmermann] [:tdz] from comment #30)
> Hi Shawn,
> 
> What if we patch Bluedroid to set GKI_LINUX_TIMER_POLICY to SCHED_OTHER
> (i.e. the non-RT scheduler)? Will Bluedroid still work in this case?
It seems on Android KK, bluedroid library runs on Bluetooth java application, with only bluetooth permission, which causes scheduler based on RT policy fail to acquire. This seems can be fixed from bluedroid based on Comment 32.

Comment 34

[Michael Vines [:m1] [:evilmachines]]

Yes, the change in comment 32 can be made outside Gecko for v1.4 but it is scary that we're running Bluedroid at significantly higher privilege than our Android friends.  The widening of the BT attack surface in B2G probably deserves a new bug for v2.0 as well.

Comment 35

[Ben Kelly [:bkelly, not reviewing]]

I opened bug 1005934 to address the issues with running bluedroid from the b2g process.  Sounds like we have a plan for 1.4.

Comment 36

[Michael Vines [:m1] [:evilmachines]]

Closing this bug out as the patch to avoid the RT scheduler in this case isn't for Gecko.

Comment 37

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

https://www.codeaurora.org/cgit/quic/la/platform/external/bluetooth/bluedroid/commit/?h=b2g_kk_3.5&id=0988bf729cb295a90c67f58c33c70bade06263aa