[dolphin] When open bluetooth,b2g-info show b2g's ppid become -1, and playing music become not smooth

RESOLVED FIXED

Status

Firefox OS
Bluetooth
--
blocker
RESOLVED FIXED
4 years ago
4 years ago

People

(Reporter: yiwen.liu, Assigned: shawnjohnjr)

Tracking

unspecified
ARM
Gonk (Firefox OS)

Firefox Tracking Flags

(b2g-v1.4 affected)

Details

(Whiteboard: [sprd308146])

Attachments

(1 attachment)

(Reporter)

Description

4 years ago
step0. make sure that  bluetooth closed
step1. reboot the phone
step2-and-test. playing music, then press power key and wake up, the music sound ok, then open bluetooth and press power key and wake up, the music sound become not smooth. Even now close the bluetooth , the problem still exist, except reboot the phone.

I try something, such as cpu usage and memory, it's ok. DS-5 show cpu idle is 54%,and memory still enough. I ask some other engineers(audio and bluetooth) for help, but it seems ok,and audio engineer said that seems some problem occurred from app, when problem occurred , no data send to audio hal.

I notice the b2g-info, when bluetooth closed,b2g-info is ok.
root@scx15_sp7715ga:/ # b2g-info                                               
                         |     megabytes     |
           NAME PID PPID CPU(s) NICE  USS  PSS  RSS VSIZE OOM_ADJ USER   
            b2g 105    1   16.1    0 54.2 60.4 71.4 158.4       0 root   
         (Nuwa) 545  105    0.9    0  3.8  9.4 20.3  50.9       0 root   
     Homescreen 564  545    2.1    1 11.4 16.3 26.4  74.3       2 u0_a564
(Preallocated a 661  545    0.6   18  5.6  9.3 17.8  56.9      11 u0_a661

And when bluetooth opened, b2g-info show :
Failed to match '105 (b2g) S 1 105 0 0 -1 1077936384 30974 606 6196 51 1324 477 0 3 -33 0 59 0 560 183476224 18567 4294967295 32768 144912 3200834064 3200824616 3068962612 0 0 4096 52991 4294967295 0 0 17 0 32 1 0 0 0 149784 151620 18735104 3200834343 3200834359 3200834359 3200835564 0
' with '^([0-9]+) \((.*)\) [A-Z] ([0-9]+) [0-9]+ [0-9]+ [0-9]+ -?[0-9]+ [0-9]+ [0-9]+ [0-9]+ [0-9]+ [0-9]+ ([0-9]+) ([0-9]+) [0-9]+ [0-9]+ [0-9]+ ([0-9]+)',returning 1.
                    |     megabytes     |
      NAME PID PPID CPU(s) NICE  USS  PSS  RSS VSIZE OOM_ADJ USER   
           105   -1    0.0    0 55.3 61.2 72.5 175.0       0 root   
    (Nuwa) 545  105    0.9    0  3.9  9.4 20.3  50.9       0 root   
Homescreen 564  545    2.1    1 11.3 16.0 26.5  74.3       2 u0_a564
     Usage 661  545    1.1    1  8.9 13.3 23.4  64.9       2 u0_a661

Need help.
(Reporter)

Updated

4 years ago
Whiteboard: [sprd308146]
(In reply to yiwen.liu from comment #0)
> step0. make sure that  bluetooth closed
> step1. reboot the phone
> step2-and-test. playing music, then press power key and wake up, the music
> sound ok, then open bluetooth and press power key and wake up, the music
> sound become not smooth. Even now close the bluetooth , the problem still
> exist, except reboot the phone.
> 
> I try something, such as cpu usage and memory, it's ok. DS-5 show cpu idle
> is 54%,and memory still enough. I ask some other engineers(audio and
> bluetooth) for help, but it seems ok,and audio engineer said that seems some
> problem occurred from app, when problem occurred , no data send to audio hal.
> 
> I notice the b2g-info, when bluetooth closed,b2g-info is ok.
> root@scx15_sp7715ga:/ # b2g-info                                            
> 
>                          |     megabytes     |
>            NAME PID PPID CPU(s) NICE  USS  PSS  RSS VSIZE OOM_ADJ USER   
>             b2g 105    1   16.1    0 54.2 60.4 71.4 158.4       0 root   
>          (Nuwa) 545  105    0.9    0  3.8  9.4 20.3  50.9       0 root   
>      Homescreen 564  545    2.1    1 11.4 16.3 26.4  74.3       2 u0_a564
> (Preallocated a 661  545    0.6   18  5.6  9.3 17.8  56.9      11 u0_a661
> 
> And when bluetooth opened, b2g-info show :
> Failed to match '105 (b2g) S 1 105 0 0 -1 1077936384 30974 606 6196 51 1324
> 477 0 3 -33 0 59 0 560 183476224 18567 4294967295 32768 144912 3200834064
> 3200824616 3068962612 0 0 4096 52991 4294967295 0 0 17 0 32 1 0 0 0 149784
> 151620 18735104 3200834343 3200834359 3200834359 3200835564 0
> ' with '^([0-9]+) \((.*)\) [A-Z] ([0-9]+) [0-9]+ [0-9]+ [0-9]+ -?[0-9]+
> [0-9]+ [0-9]+ [0-9]+ [0-9]+ [0-9]+ ([0-9]+) ([0-9]+) [0-9]+ [0-9]+ [0-9]+
> ([0-9]+)',returning 1.
>                     |     megabytes     |
>       NAME PID PPID CPU(s) NICE  USS  PSS  RSS VSIZE OOM_ADJ USER   
>            105   -1    0.0    0 55.3 61.2 72.5 175.0       0 root   
>     (Nuwa) 545  105    0.9    0  3.9  9.4 20.3  50.9       0 root   
> Homescreen 564  545    2.1    1 11.3 16.0 26.5  74.3       2 u0_a564
>      Usage 661  545    1.1    1  8.9 13.3 23.4  64.9       2 u0_a661
> 
> Need help.

Could you attach slog on bug? I didn't find log on your ftp.
Does init process still exist in this case?
Flags: needinfo?(yiwen.liu)
(Reporter)

Comment 2

4 years ago
Created attachment 8434814 [details]
2014-06-05-08-35-39.tar.bz2

2014-06-05-08-35-39.tar.bz2
The action of the log:
s1. boot the phone
s2. playing music
s3. press power key and wake up
s4. open bluetooth
s5. press power key and wake up
s6. close bluetooth
s7. playing music

include the b2g-info,b2g-ps,meminfo,ps
Flags: needinfo?(yiwen.liu)
(Assignee)

Comment 3

4 years ago
Can we adjust CPU frequency to higher upper bound and test? It looks like entering early suspend, CPU frequency drops too much and it causes limited CPU resources.
(Assignee)

Comment 4

4 years ago
What's the CPU frequency while entering early suspend (when press power down)?
I tried to keep CPU speed at max speed, I can still feel it's not smooth on music playback when suspend/resume.

How to keep CPU speed at max:
adb shell "echo performance > /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor"

How to confirm CPU speed keep at max:
watch -n 1 adb shell cat /sys/devices/system/cpu/cpu0/cpufreq/stats/time_in_state

So it might not relate to CPU speed.
(Reporter)

Comment 6

4 years ago
(In reply to Danny Liang [:dliang] from comment #5)
> I tried to keep CPU speed at max speed, I can still feel it's not smooth on
> music playback when suspend/resume.
> 
> How to keep CPU speed at max:
> adb shell "echo performance >
> /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor"
> 
> How to confirm CPU speed keep at max:
> watch -n 1 adb shell cat
> /sys/devices/system/cpu/cpu0/cpufreq/stats/time_in_state
> 
> So it might not relate to CPU speed.

I angree.

When playing music , not only press power key, but also when open some apps, such as "Setting","Message","Contact",”Browser" can trigger the problem, and I try another 4-core cpu run the same ffos1.4(kernel different,but also 3.10). Also have the problem.
(Reporter)

Comment 7

4 years ago
Before and after open BT, b2g-info had some errors with b2g, is it matter? or  just b2g-info script's error?
(Reporter)

Comment 8

4 years ago
When open and then close BT, playing music become not smooth, now kill b2g (force restart?) , after b2g stable. Playing music is ok.
Cannot reproduce this issue on Flame v1.3 and v1.4.
(Reporter)

Comment 10

4 years ago
It truly seems cpu busy. When open "Browser", msuic become not smooth, after "Browser" opened, msuic become ok. Should we give "music play" higher priority?  But why after open bluetooth?
(Reporter)

Comment 11

4 years ago
(In reply to Danny Liang [:dliang] from comment #9)
> Cannot reproduce this issue on Flame v1.3 and v1.4.

Yes, Flame v1.4 is ok, and after open BT, b2g-info is ok too.
But Flame is based on JB, Dolphin is based on KK. We need find out the difference.
blocking-b2g: --- → 1.4?
status-b2g-v1.4: --- → affected
And we can't reproduce it on dolphin Android4.4 native version. The bsp code is the same as Firefox1.4 and the app is the same as AOSP.
(Reporter)

Comment 14

4 years ago
After open bluetooth, addtional thead added, see the following:
root      686   105   174792 75600 ffffffff 00000000 S b2g
root      687   105   174792 75600 ffffffff 00000000 S BTIF
root      688   105   174792 75600 ffffffff 00000000 S A2DP-MEDIA
root      689   105   174792 75600 ffffffff 00000000 S uipc-main
root      690   105   174792 75600 ffffffff 00000000 S BTU
root      692   105   174792 75600 ffffffff 00000000 S bt_hc_worker
root      693   105   174792 75600 ffffffff 00000000 S gki timer
root      694   105   174792 75600 ffffffff 00000000 S b2g
root      695   105   174792 75600 ffffffff 00000000 S userial_read
root      696   105   174792 75600 ffffffff 00000000 S BTIF
root      697   105   174792 75600 ffffffff 00000000 S bt_hc_worker
root      700   105   174792 75600 ffffffff 00000000 S StreamTrans #2
root      706   105   174792 75600 ffffffff 00000000 S Storage I/O
root      536   105   52124  20820 ffffffff 00000000 S /system/b2g/plugin-container

And then close bluetooth, a "b2g" thread(pid 686) left. GDB show the 686's info as the following:

#0  poll () at bionic/libc/arch-arm/syscalls/poll.S:9
#1  0xb2c5ed70 in prepare_poll_fds (pfds=0xb1701b90, h=<optimized out>) at external/bluetooth/bluedroid/main/../btif/src/btif_sock_thread.c:549
#2  sock_poll_thread (arg=0x7) at external/bluetooth/bluedroid/main/../btif/src/btif_sock_thread.c:562
#3  0xb6eec21c in __thread_entry (func=0xb2c5ec69 <add_poll+356>, arg=0x7, tls=0xb1701dd0) at bionic/libc/bionic/pthread_create.cpp:105
#4  0xb6eec3b8 in pthread_create (thread_out=0xbeaea36c, attr=<optimized out>, start_routine=0xb2c5ec69 <add_poll+356>, arg=0x78) at bionic/libc/bionic/pthread_create.cpp:224
#5  0x00000000 in ?? ()

Seems POLL.

The reason I show this is once bluetooth opened, then even closed , the music problem still exist. So I try to find the different that before and after bluetooth opened.
(Assignee)

Comment 15

4 years ago
Low latency AudioTracks rely on RT scheduling. However, Bluedroid currently runs within the B2G process, which has the necessary permissions for sched_setscheduler() to succeed,
resulting in an unwanted change of the scheduling policy for the B2G main thread to real-time. It might effect AudioTracks RT scheduling.

Please try to remove these piece of code, gki/ulinux/gki_ulinux.c
if ( 0!=sched_setscheduler(main_pid, GKI_LINUX_TIMER_POLICY, &param ) )
{
  GKI_TRACE("sched_setscheduler() failed with error: %d", errno);
}

We used to debug WatchDog Timeout before because of this unexpected code inside bluedroid.
Note: In Android, Bluetooth process won't have permission to get RT scheduler (as Bluetooth permission, but b2g has root permission), so this part of timer-tick-update is dead code actually. Even if you remove it, you don't have side effect.

Then you will see PPID no longer equals to -1.
(Reporter)

Comment 16

4 years ago
(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #15)
> Low latency AudioTracks rely on RT scheduling. However, Bluedroid currently
> runs within the B2G process, which has the necessary permissions for
> sched_setscheduler() to succeed,
> resulting in an unwanted change of the scheduling policy for the B2G main
> thread to real-time. It might effect AudioTracks RT scheduling.
> 
> Please try to remove these piece of code, gki/ulinux/gki_ulinux.c
> if ( 0!=sched_setscheduler(main_pid, GKI_LINUX_TIMER_POLICY, &param ) )
> {
>   GKI_TRACE("sched_setscheduler() failed with error: %d", errno);
> }
> 
> We used to debug WatchDog Timeout before because of this unexpected code
> inside bluedroid.
> Note: In Android, Bluetooth process won't have permission to get RT
> scheduler (as Bluetooth permission, but b2g has root permission), so this
> part of timer-tick-update is dead code actually. Even if you remove it, you
> don't have side effect.
> 
> Then you will see PPID no longer equals to -1.

Thanks Shawn

Solved!
(Assignee)

Comment 17

4 years ago
After patching bluedroid, this problem fixed. Change to WORKSFORME.
Status: NEW → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → WORKSFORME

Updated

4 years ago
blocking-b2g: 1.4? → ---
(Assignee)

Updated

4 years ago
Assignee: nobody → shuang
(Assignee)

Updated

4 years ago
Resolution: WORKSFORME → FIXED
You need to log in before you can comment on or make changes to this bug.