AudioFlinger issue

[prasannakulkarni]

Hi,

We have made a device using imx6solo and wm8958 codec. everything working fine but,during voice call we are facing some issues, like whenever we want to switch between Earpiece to LoudSpeaker/Headset there is a delay of 8-9 seconds to switch to appropriate mode. and in logcat we are getting like this

W/AudioFlinger( 2098): write blocked for 9997 msecs, 3 delayed writes, thread 0x159f878

we are suspecting because of above AudioFlinger, creating a delay, if anybody knows about it kindly help us in solving this issue.

[gfine]

Hi Prasanna,

What is at process 2098?  You can find out by using 'adb shell ps | grep 2098' at a command line. Whatever is at that process PID is doing the blocking.

Cheers,

Glen

[prasannakulkarni]

Hi Glen Fine,

           Here is the log when i make a Voice call and shift it to Speaker mode

D/CallController( 2310): placeCall()...  intent = Intent { act=android.intent.action.CALL dat=tel:xxxxxxxxxx (has extras) }

D/OtaUtils( 2310): isOtaspCallIntent(Intent { act=android.intent.action.CALL dat=tel:xxxxxxxxxx (has extras) })...

D/OpenGLRenderer( 2418): Flushing caches (mode 0)

D/AudioHardwareInterface( 2072): setMode(IN_CALL)

W/iMXALSA ( 2072): s_close-- android::status_t android_audio_legacy::s_close(android_audio_legacy::alsa_handle_t*)

D/iMXALSA ( 2072): android::status_t android_audio_legacy::s_open(android_audio_legacy::alsa_handle_t*, uint32_t, int) open called for devices 00000001 in mode 2...

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) **** List of PLAYBACK Hardware Devices ****

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) card 0: wm8958audio [wm8958-audio], device 0: HiFi wm8994-aif1-0 []

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) device have=HiFi wm8994-aif1-0

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) card 0: wm8958audio [wm8958-audio], device 1: Voice wm8994-aif2-1 []

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) device have=Voice wm8994-aif2-1

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) selected device =1

W/iMXALSA ( 2072): Don't enable MMAP access for PCM

W/iMXALSA ( 2072): Set sample rate to 8000 HZ

W/iMXALSA ( 2072): Buffer size: 4096

W/iMXALSA ( 2072): Latency: 512000

I/iMXALSA ( 2072): android::status_t android_audio_legacy::s_open(android_audio_legacy::alsa_handle_t*, uint32_t, int) Initialized ALSA PLAYBACK device hw:0,1

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) **** List of PLAYBACK Hardware Devices ****

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) card 0: wm8958audio [wm8958-audio], device 0: HiFi wm8994-aif1-0 []

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) device have=HiFi wm8994-aif1-0

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) card 0: wm8958audio [wm8958-audio], device 1: Voice wm8994-aif2-1 []

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) device have=Voice wm8994-aif2-1

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) selected device =1

D/iMXALSA ( 2072): void android_audio_legacy::setDefaultControls(uint32_t, int, const char*) setDefaultControls set card: hw:00

D/iMXALSA ( 2072): mode == AudioSystem::MODE_IN_CALL

D/iMXALSA ( 2072): *********Inside Earpiece*************

I/AudioService( 2161):  AudioFocus  requestAudioFocus() from AudioFocus_For_Phone_Ring_And_Calls

I/ActivityManager( 2161): START {act=android.intent.action.MAIN flg=0x10840000 cmp=com.android.phone/.InCallScreen} from pid 2310

D/Bluetooth HS/HF( 2310): CDMA call state: SINGLE_ACTIVE prev state:IDLE

D/PhoneStatusBar( 2233): disable: < expand icons ALERTS* ticker system_info back home recent clock >

D/Bluetooth HS/HF( 2310): CDMA call state: SINGLE_ACTIVE prev state:IDLE

D/InCallScreen( 2310): onNewIntent: intent = Intent { act=android.intent.action.MAIN flg=0x10c40000 cmp=com.android.phone/.InCallScreen }, phone state = OFFHOOK

D/PhoneStatusBar( 2233): disable: < EXPAND* icons ALERTS ticker system_info back home recent clock >

V/CRL-TESTING( 2310): - startDialerSession: mLocalToneEnabled = false

I/power   ( 2161): *** set_screen_state 1

E/SurfaceTexture( 2069): [com.android.phone/com.android.phone.InCallScreen] dequeueBuffer: can't dequeue multiple buffers without setting the buffer count

D/Bluetooth HS/HF( 2310): CDMA call state: SINGLE_ACTIVE prev state:IDLE

W/InputManagerService( 2161): Starting input on non-focused client com.android.internal.view.IInputMethodClient$Stub$Proxy@414267f0 (uid=10000 pid=2418)

D/Bluetooth HS/HF( 2310): CDMA call state: SINGLE_ACTIVE prev state:IDLE

E/DefaultVoicemailNotifier( 2418): No voicemails to notify about: clear the notification.

D/Bluetooth HS/HF( 2310): CDMA call state: SINGLE_ACTIVE prev state:IDLE

D/CallNotifier( 2310): SignalInfoTonePlayer.run(toneId = 98)...

W/AudioHardwareALSA( 2072): badstate and do recovery.....

D/InCallScreen( 2310): toggleSpeaker(): newSpeakerState = true

So when I press LoudSpeaker Button on phone app the above line will come immediately. but after 10-15 seconds following log will come.

W/AudioHardwareALSA( 2072): underrun and do recovery.....

W/AudioFlinger( 2072): write blocked for 19999 msecs, 4 delayed writes, thread 0xf43290

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) **** List of PLAYBACK Hardware Devices ****

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) card 0: wm8958audio [wm8958-audio], device 0: HiFi wm8994-aif1-0 []

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) device have=HiFi wm8994-aif1-0

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) card 0: wm8958audio [wm8958-audio], device 1: Voice wm8994-aif2-1 []

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) device have=Voice wm8994-aif2-1

D/iMXALSA ( 2072): const char* android_audio_legacy::deviceName(android_audio_legacy::alsa_handle_t*, uint32_t, int, int) selected device =1

D/iMXALSA ( 2072): void android_audio_legacy::setDefaultControls(uint32_t, int, const char*) setDefaultControls set card: hw:00

D/iMXALSA ( 2072): mode == AudioSystem::MODE_IN_CALL

D/iMXALSA ( 2072): devices & AudioSystem::DEVICE_OUT_SPEAKER

D/dalvikvm( 2532): GC_CONCURRENT freed 444K, 6% free 9094K/9671K, paused 2ms+2ms

^C

130|root@android:/ # ps | busybox grep 2072                                   

media     2072  1     34872  7504  ffffffff 400df690 S /system/bin/mediaserver

root@android:/ #

So mediaserver is creating problem?

[gfine]

Audioflinger is simply a nexus in Android that joins (via the mediaserver) audio source(s) and output(s).  See this article for how it is architected. ( http://source.android.com/devices/audio.html ). From what I read AudioFlinger is a part of mediaserver.  If there is a problem in a setup (or device binding) it manifests itself in the delay you see or in a crash.  What casues the delay is going to be a process of elimination. Check to see if the audio inputs and outputs are defined.  What Weidong suggested above seems to be a good place to start.

Glen

[weidong_sun]

Hello,Prasanna,

      Even I can not be sure exact position of the issue, but I can give you some advice to debug it. The following files are related to monitor headset in android4.2 .

(1)sound card driver.

In the driver, interrupt should be used to response headset plug in or out, and it's state is reported to application level, like path "sys/class/switch/../state" , you can add degug information in driver to test response time and observe it on console.

(2)android audio HAL (tinyalsa.c : ~/myandroid/hardware/imx/alsa/)

It is used to connect ALSA lib and Audio Service of android application. you can also add debug information in it.

(3)Headset Observer ( WiredAccessoryManager.java---~/myandroid/frameworks/base/services/java/com/android/server/)

This is java source code, it is used to start headset monitorning and handling events.

     Please try to trace source code and find what caused the issue !

Regards,

Weidong

[prasannakulkarni]

Hi Weidong Sun,

           Thanks for your reply.. All the events like headset insertion/removal is happening fine only.. it works fine during media play(Music) the problem is only during voice call.. we are using alsa_imx.cpp in HAL as it is having support for AIF1 and AIF2 (2 ports on wm8958 card). beginning we thought  it is a routing delay in HAL. but When we added debug msgs in alsa_imx.cpp we found that there is delay in entering this file (alsa_imx.cpp) itself. so is it a Audioflinger problem?

[YixingKong]

Prasanna

I am going to branch your question to an internal group and have an engineer to look into it.

Thanks,

Yixing