What SurfaceFlinger is doing when Buffer of Layers can not be dequeued

The backtrace of the main threadof com.android.phone:

#00  pc 0001b4a8 /system/lib/libc.so (__ioctl+8)

__ioctl

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/bionic/libc/arch-arm/syscalls/__ioctl.S:9

#01  pc 0002baf3 /system/lib/libc.so (ioctl+14)

ioctl

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/bionic/libc/bionic/ioctl.c:41

#02  pc 0001b539 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)

android::IPCThreadState::talkWithDriver(bool)

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/binder/IPCThreadState.cpp:810

#03  pc 0001ba23 /system/lib/libbinder.so(android::IPCThreadState::waitForResponse(android::Parcel*, int*)+42)

android::IPCThreadState::waitForResponse(android::Parcel*,int*)

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/binder/IPCThreadState.cpp:672

#04  pc 0001bc2b /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int,android::Parcel const&, android::Parcel*, unsigned int)+118)

android::IPCThreadState::transact(int,unsigned int, android::Parcel const&, android::Parcel*, unsigned int)

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/binder/IPCThreadState.cpp:564

#05  pc 00018489 /system/lib/libbinder.so (android::BpBinder::transact(unsigned int,android::Parcel const&, android::Parcel*, unsigned int)+30)

android::BpBinder::transact(unsignedint, android::Parcel const&, android::Parcel*, unsigned int)

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/binder/BpBinder.cpp:165

#06  pc 0002341f /system/lib/libgui.so

android::BpGraphicBufferProducer::dequeueBuffer(int*, android::sp<android::Fence>*, unsigned int,unsigned int, unsigned int, unsigned int)

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/gui/IGraphicBufferProducer.cpp:94

#07  pc 00027035 /system/lib/libgui.so (android::Surface::dequeueBuffer(ANativeWindowBuffer**,int*)+92)

android::Surface::dequeueBuffer(ANativeWindowBuffer**,int*)

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/gui/Surface.cpp:191

#08  pc 00027503 /system/lib/libgui.so (android::Surface::lock(ANativeWindow_Buffer*,ARect*)+94)

android::Surface::lock(ANativeWindow_Buffer*,ARect*)

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/gui/Surface.cpp:794

#09  pc 00063631 /system/lib/libandroid_runtime.so

android::nativeLockCanvas(_JNIEnv*,_jclass*, int, _jobject*, _jobject*)

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/base/core/jni/android_view_Surface.cpp:228

#10  pc 000203cc /system/lib/libdvm.so (dvmPlatformInvoke+112)

dvmPlatformInvoke

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/dalvik/vm/arch/arm/CallEABI.S:258

#11  pc 00050d8f /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Methodconst*, Thread*)+398)

dvmCallJNIMethod(unsigned intconst*, JValue*, Method const*, Thread*)

/opt/Weekly_Release/Integration/5865/5865_userdebug_ss/dalvik/vm/Jni.cpp:1214

#12  pc 00000214 /dev/ashmem/dalvik-jit-code-cache (deleted)

 

The backtrace of binder workerthread:

#0  0xb6ed877c in __futex_syscall3                  /system/lib/libc.so

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/bionic/libc/arch-arm/bionic/futex_arm.S:41

#1  0xb6eca854 in__pthread_cond_timedwait_relative+0x0034(+52)  /system/lib/libc.so

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/bionic/libc/bionic/pthread.c:1127

#2  0xb6eca8b4 in__pthread_cond_timedwait+0x0044(+68)  /system/lib/libc.so

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/bionic/libc/bionic/pthread.c:1150

#3  [INLINE]  android::Condition::wait

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/include/utils/Condition.h:106

#4  0xb6ce48b6 in android::BufferQueue::dequeueBuffer+0x018e(+398) /system/lib/libgui.so

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/gui/BufferQueue.cpp:422

#5  0xb6ce917e in android::BnGraphicBufferProducer::onTransact+0x00ea(+234)  /system/lib/libgui.so

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/gui/IGraphicBufferProducer.cpp:248

#6  0xb6d21f1e inandroid::BBinder::transact+0x003e(+62)  /system/lib/libbinder.so

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/binder/Binder.cpp:108

#7  0xb6d258e6 inandroid::IPCThreadState::executeCommand+0x01fe(+510) /system/lib/libbinder.so

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/binder/IPCThreadState.cpp:1036    

#8  0xb6d25cf6 inandroid::IPCThreadState::joinThreadPool+0x00ba(+186) /system/lib/libbinder.so

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/libs/binder/IPCThreadState.cpp:468

#9  [INLINE]  ~sp

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/include/binder/BinderService.h:51

#10 0xb6f2b8f2 inandroid::BinderService<android::SurfaceFlinger>::publishAndJoinThreadPool+0x009a(+154) /system/bin/surfaceflinger

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/include/binder/BinderService.h:51

#11 0xb6f2b928 inmain+0x001c(+28)  /system/bin/surfaceflinger

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/cmds/surfaceflinger/main_surfaceflinger.cpp:26

 

Tri-graphic-buffer is used.

this->mSlots:

$9 = {{mGraphicBuffer = {m_ptr =0xb7443c20}, mEglDisplay = 0x1, mBufferState = android::BufferQueue::BufferSlot::QUEUED, mRequestBufferCalled = true, mCrop = {<ARect> = {left = 0, top= 0,

        right= 0, bottom = 0}, <android::LightFlattenablePod<android::Rect>> ={<android::LightFlattenable<android::Rect>> = {<No datafields>}, <No data fields>}, <No data fields>}, mTransform = 0,

    mScalingMode= 0, mTimestamp = 11708518004184, mFrameNumber = 10, mEglFence = 0x0, mFence ={m_ptr = 0xb7443070}, mAcquireCalled = true, mNeedsCleanupOnRelease = false},{mGraphicBuffer = {

     m_ptr = 0xb7419638}, mEglDisplay = 0x1, mBufferState = android::BufferQueue::BufferSlot::ACQUIRED, mRequestBufferCalled = true, mCrop = {<ARect> ={left = 0, top = 0, right = 0,

        bottom= 0}, <android::LightFlattenablePod<android::Rect>> ={<android::LightFlattenable<android::Rect>> = {<No datafields>}, <No data fields>}, <No data fields>}, mTransform = 0,

    mScalingMode= 0, mTimestamp = 11708484875382, mFrameNumber = 8, mEglFence = 0x0, mFence ={m_ptr = 0xb7304c08}, mAcquireCalled = true, mNeedsCleanupOnRelease = false},{mGraphicBuffer = {

     m_ptr = 0xb7443968}, mEglDisplay = 0x1, mBufferState =android::BufferQueue::BufferSlot::QUEUED, mRequestBufferCalled = true, mCrop = {<ARect> ={left = 0, top = 0, right = 0,

        bottom= 0}, <android::LightFlattenablePod<android::Rect>> ={<android::LightFlattenable<android::Rect>> = {<No datafields>}, <No data fields>}, <No data fields>}, mTransform = 0,

    mScalingMode= 0, mTimestamp = 11708501788507, mFrameNumber = 9, mEglFence = 0x0, mFence ={m_ptr = 0xb7436870}, mAcquireCalled = true, mNeedsCleanupOnRelease = false},{mGraphicBuffer = {

     m_ptr = 0x0}, mEglDisplay = 0x0, mBufferState =android::BufferQueue::BufferSlot::FREE, mRequestBufferCalled = false, mCrop ={<ARect> = {left = 0, top = 0, right = -1,

        bottom= -1}, <android::LightFlattenablePod<android::Rect>> ={<android::LightFlattenable<android::Rect>> = {<No datafields>}, <No data fields>}, <No data fields>}, mTransform = 0,

    mScalingMode= 0, mTimestamp = 0, mFrameNumber = 0, mEglFence = 0x0, mFence = {m_ptr = 0x0},mAcquireCalled = false, mNeedsCleanupOnRelease = false}

    .......

   

frame buffer 10 is ACQUIRED anddisplayed while frame buffer 8 and 9 are queued and waiting to be displayed.

SurfaceFlinger should be checkedto investigate why the buffers are not consumed quickly enough.

 

Thread in SurfaceFlinger group.

PID: 232    TASK:d7f95400  CPU: 0   COMMAND: "Binder_2"

  PID:297    TASK: d8768000  CPU: 1   COMMAND:"SurfaceFlinger"

  PID:453    TASK: d8e43200  CPU: 0   COMMAND:"hwcUeventThread"

  PID:454    TASK: d7d43700  CPU: 0   COMMAND:"hwcVsyncThread"

  PID:462    TASK: d7696300  CPU: 0   COMMAND: "GLupdater"

  PID:466    TASK: d7f12800  CPU: 0   COMMAND:"EventThread"

  PID:467    TASK: d74cf200  CPU: 0   COMMAND:"Binder_1"

  PID:501    TASK: d77d0500  CPU: 0   COMMAND:"Binder_3"

  PID: 1247  TASK: ce0fc000  CPU: 0   COMMAND: "Binder_4"

  PID: 4960  TASK: cf6ab200  CPU: 0   COMMAND: "Binder_5"

 

userspace backtrace:"SurfaceFlinger"[PID: 297] is in screen off/release handling andstuck in hwc_blank.

#0  0xb6ed74ac in__ioctl  /system/lib/libc.so

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/bionic/libc/arch-arm/syscalls/__ioctl.S:10

     size of frame = 0

#1  0xb6ee7af6 inioctl+0x0012(+18)  /system/lib/libc.so

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/bionic/libc/bionic/ioctl.c:41

     fd (int) = <optimized out>

     request (int) = 17937

     ap (__va_list) = {

       __ap (void *) = 0xb6bb2c90}

     arg (void *) = <optimized out>

#2  0xb6850f32 in hwc_blank+0x008a(+138) /system/lib/hw/hwcomposer.msm8610.so

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/hardware/qcom/display/libhwcomposer/hwc.cpp:351

     dev (hwc_composer_device_1 *) = 0xb7309728

     dpy (int) = 0

     blank (int) = 54

     <inner block>

     ___tracer (ScopedTrace) = {

       mTag (long long unsigned int) = 2050(0x802)}

     __FUNCTION__ (char [10]) =  "hwc_blank" {[0]'h', [1]'w', [2]'c',[3]'_', [4]'b', [5]'l', [6]'a', [7]'n', [8]'k', [9]'\0'}

     ctx (hwc_context_t *) = 0xb7309728

     _l (Autolock) = <optimized out>

     ret (int) = 0

     value (int) = 4

#3  0xb6e818e4 inandroid::HWComposer::release+0x001c(+28)  /system/lib/libsurfaceflinger.so

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/services/surfaceflinger/DisplayHardware/HWComposer.cpp:714

     this (HWComposer *) = 0xb7307350

     disp (int) = 0 [@ENTRY=0]

#4  0xb6e7a208 inandroid::SurfaceFlinger::onScreenReleased+0x0058(+88) /system/lib/libsurfaceflinger.so

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/services/surfaceflinger/SurfaceFlinger.cpp:2202

     this (SurfaceFlinger *) = 0xb7305478

     hw (sp<const android::DisplayDevice> &) = <optimized out>

     <inner block>

     type (int) = 0

#5  0xb6e7b925 in_ZZN7android14SurfaceFlinger5blankERKNS_2spINS_7IBinderEEEEN21MessageScreenReleased7handlerEv /system/lib/libsurfaceflinger.so

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/frameworks/native/services/surfaceflinger/SurfaceFlinger.cpp:2245

     size of frame = 0

 

Kernel stack for pid 297

#0  [INLINE]  context_switch

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/sched/core.c:2105

     next (task_struct *) = 0xd8c78000

     prev (task_struct *) = 0xd8768000

     rq (rq *) = 0xc15a8640

     <inner block>

     mm (mm_struct *) = 0x0

     oldmm (mm_struct *) = 0xd7d74000

#1  0xc0867d98 in__schedule+0x03cc(+972)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/sched/core.c:3252

     prev (task_struct *) = 0xd8768000

     next (task_struct *) = 0xd8c78000

    switch_count (long unsigned int *) = <optimized out>

     rq (rq *) = 0xc15a8640

     cpu (int) = <optimized out>

#2  [INLINE]  blk_needs_flush_plug

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/include/linux/blkdev.h:961

     tsk (task_struct *) = <optimized out>

     <inner block>

     plug (blk_plug *) = <optimized out>

#3  [INLINE]  sched_submit_work

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/include/linux/blkdev.h:961

     tsk (task_struct *) = <optimized out>

#4  0xc0868290 inschedule+0x0074(+116)    [tail call]

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/sched/core.c:3290

     tsk (task_struct *) = <unknown value for register r3>

#5  0xc0865d60 inschedule_timeout+0x01d4(+468)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/timer.c:1500

     timeout (long int) = 2147483647 [@ENTRY=2147483647]

     timer (timer_list) = {

       entry (list_head) = {

         next (list_head *) = 0xc593e838,

          prev(list_head *) = 0xc593d438},

        expires(long unsigned int) = 3223040336(0xc01bb150),

        base(tvec_base *) = 0x00000aa6,

        function(void *) = 0xc593e800,

        data(long unsigned int) = 3230705200(0xc090a630),

        slack(int) = -980167680,

        start_pid(int) = -1051068864,

        start_site(void *) = 0x0,

        start_comm(char [16]) =  "@\366Y\301" {[0]'@', [1]'\366', [2]'Y',[3]'\301', [4]'\0', [5]'\350', [6]'\223', [7]'\305', [8]'@', [9]'&',[10]'\341', [11]'\300', [12]'\264', [13]'>', [14]'\33', [15]'\300'}}

     expire (long unsigned int) = <optimized out>

#6  [INLINE]  do_wait_for_common

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/sched/core.c:3582

     iowait (int) = 0

     state (int) = 2

     timeout (long int) = 2147483647

      x(completion *) = 0xd74ffd64

     <inner block>

     wait (__wait_queue) = {

       flags (unsigned int) = 1,

        private(void *) = 0xd8768000,

        func(int *) = 0xc01b7044,

        task_list(list_head) = {

         next (list_head *) = 0xd74ffd78,

          prev(list_head *) = 0xd74ffd78}}

#7  0xc08678a8 inwait_for_common+0x0118(+280)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/sched/core.c:3602

      x(completion *) = 0xd74ffd64

     timeout(long int) = <optimized out>

     state (int) = 2

     iowait (int) = 0

#8  [INLINE]  wait_on_cpu_work

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2535

     work (work_struct *) = <optimized out>

      gcwq(global_cwq *) = 0xc159c840

     <inner block>

     barr (wq_barrier) = {

       work (work_struct) = {

         data (atomic_t) = {

           counter (int) = -1051056139},

          entry(list_head) = {

           next (list_head *) = 0xd7f05e98,

            prev(list_head *) = 0xd4fa6890},

          func(void *) = 0xc019ee70},

        done(completion) = {

         done (unsigned int) = 0,

          wait(__wait_queue_head) = {

           lock (spinlock) = {

             <unknown> (?) = {

               rlock (raw_spinlock) = {

                 raw_lock (arch_spinlock_t) = {

                   lock (unsigned int) = 65537(0x10001)},

                  magic(unsigned int) = 3735899821(0xdead4ead),

                  owner_cpu(unsigned int) = 4294967295(0xffffffff),

                  owner(void *) = 0xffffffff}}},

            task_list(list_head) = {

             next (list_head *) = 0xd74ffd18,

              prev(list_head *) = 0xd74ffd18}}}}

     worker (worker *) = 0xd87836dc

#9  0xc01a1e80 in wait_on_work+0x00e0(+224)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:486

     work (work_struct *) = 0xd87836dc [@ENTRY=0xd87836dc]

     ret (_Bool) = <optimized out>

     cpu (int) = <optimized out>

#10 0xc01a2024 in__cancel_work_timer+0x00b8(+184)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2643

     work (work_struct *) = 0xd87836dc [@ENTRY=0xd87836dc]

     timer (timer_list *) = 0xd87836ec [@ENTRY=0xd87836ec]

     ret (int) = -1

#11 0xc01a2078 in cancel_delayed_work_sync+0x0008(+8)   [tail call]

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2728

     dwork (delayed_work *) = <optimized out>

#12 [INLINE]   elan_ktf2k_ts_suspend

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/drivers/input/touchscreen/ektf2k.c:3290

     dev (device *) = 0xd8dada20

     <inner block>

     client (i2c_client *) = 0xd8dada00

     ts (elan_ktf2k_ts_data *) = 0xd87836c0

     rc (int) = 0

     __func__ (char [22]) =  "elan_ktf2k_ts_suspend" {[0]'e', [1]'l',[2]'a', [3]'n', [4]'_', [5]'k', [6]'t', [7]'f', [8]'2', [9]'k', [10]'_',[11]'t', [12]'s', [13]'_', [14]'s', [15]'u', [16]'s', [17]'p', [18]'e',[19]'n', [20]'d', [21]'\0'}

#13 0xc0500378 infb_notifier_callback+0x00d4(+212)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/drivers/input/touchscreen/ektf2k.c:2926

     self (notifier_block *) = <optimized out>

     event (long unsigned int) = <optimized out>

     data (void *) = <optimized out>

     evdata (fb_event *) = <optimized out>

     blank (int *) = <optimized out>

     elan_dev_data (elan_ktf2k_ts_data *) = <optimized out>

#14 0xc086ad64 innotifier_call_chain+0x0044(+68)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/notifier.c:93

     nl (notifier_block * *) = 0xc0e558cc [@ENTRY=0xc0e558cc]

     val (long unsigned int) = 9 [@ENTRY=9]

      v(void *) = 0xd74ffe40 [@ENTRY=0xd74ffe40]

     nr_to_call (int) = -3 [@ENTRY=-1]

     nr_calls (int *) = 0x0

     ret (int) = -1058711348

     nb (notifier_block *) = 0x0

     next_nb (notifier_block *) = 0x0

#15 0xc01abfb8 in__blocking_notifier_call_chain+0x0048(+72)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/notifier.c:314

     nh(blocking_notifier_head *) = 0xc0e558b0

     val (long unsigned int) = 9

      v(void *) = 0xd74ffe40

     nr_to_call (int) = -1 [@ENTRY=-1]

     nr_calls (int *) = 0x0

     ret (int) = 0

#16 0xc01abfe8 inblocking_notifier_call_chain+0x0018(+24)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/notifier.c:325

     nh (blocking_notifier_head *) = <optimized out>

     val (long unsigned int) = <optimized out>

      v(void *) = <optimized out>

#17 0xc03a35bc infb_blank+0x0058(+88)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/drivers/video/fbmem.c:1062

     info (fb_info *) = 0xd8ed9800 [@ENTRY=0xd8ed9800]

     blank (int) = -1069926980 [@ENTRY=4]

     ret (int) = <optimized out>

     <inner block>

     event (fb_event) = {

       info (fb_info *) = 0xd8ed9800,

        data(void *) = 0xd74ffe3c}

#18 0xc03a4294 indo_fb_ioctl+0x0418(+1048)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/drivers/video/fbmem.c:1180

     info (fb_info *) = 0xd8ed9800

     cmd (unsigned int) = <optimized out>

     arg (long unsigned int) = 4

     fb (fb_ops *) = <optimized out>

     var (fb_var_screeninfo) = {

 

     event (fb_event) = {

       info (fb_info *) = 0xd74fe000,

        data(void *) = 0xc0868e58}

     argp (void *) = 0x00000004

     ret (long int) = 0

#19 [INLINE]  vfs_ioctl

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/fs/ioctl.c:43

     arg (long unsigned int) = <optimized out>

     cmd (unsigned int) = <optimized out>

     filp (file *) = <optimized out>

     <inner block>

     error (int) = <optimized out>

#20 0xc0261cc0 indo_vfs_ioctl+0x0084(+132)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/fs/ioctl.c:40

     filp (file *) = 0xd7f59540

     fd (unsigned int) = 15(0xf)

     cmd (unsigned int) = <optimized out>

     arg (long unsigned int) = 4

     error (int) = 0

     argp (int *) = 0x00000004

     inode (inode *) = 0xd7e80750

#21 0xc026221c insys_ioctl+0x0034(+52)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/fs/ioctl.c:618

     fd (unsigned int) = 15(0xf)

     cmd (unsigned int) = 17937(0x4611)

     arg (long unsigned int) = 4

     filp (file *) = 0xd7f59540

     error (int) = <optimized out>

     fput_needed (int) = -1071242724

#22 System call exception frame.

   Registers fromuserland:

     r00=0x0000000f  r01=0x00004611  r02=0x00000004  r03=0xb6bb2c90

     r04=0x00000802  r05=0xb7309a5c  r06=0xb7309728  r07=0x00000036

     r08=0x00000000  r09=0xb73066e0  r10=0xb6e50993  r11=0xb6e5089c

     r12=0x00000001   SP=0xb6bb2c80   LR=0xb6ee7af7  PC=0xb6ed74ac

 

It is stuck in touch screenpanel's suspend routine, waiting delayed_work cancelation.

3332//static intelan_ktf2k_ts_suspend(struct i2c_client *client, pm_message_t mesg)

3333static intelan_ktf2k_ts_suspend(struct device *dev)

3334{

3335      struct i2c_client *client = to_i2c_client(dev);

3336      struct elan_ktf2k_ts_data *ts = i2c_get_clientdata(client);

3337      int rc = 0;

3338

3339      if(tp_sleep_status==1)

3340      {

3341                      if(power_lock==0) /* The power_lock can be removed when firmware upgradeprocedure will not be enter into suspend mode.  */

3342                      {

3343                                      disable_irq(client->irq);

3344                                      cancel_delayed_work_sync(&ts->check_work); ************

3345                                      rc = cancel_work_sync(&ts->work); ***********

3346                                      if (rc)

3347                                                     enable_irq(client->irq);

3348

3349                                      rc = elan_ktf2k_ts_set_power_state(client, PWR_STATE_DEEP_SLEEP);

3350                      }

3351                      tp_sleep_status = 0;

3352      }

3353      return 0;

3354}

 

2716/**

2717 * cancel_delayed_work_sync- cancel a delayed work and wait for it to finish

2718 * @dwork: the delayed workcancel

2719 *

2720 * This iscancel_work_sync() for delayed works.

2721 *

2722 * RETURNS:

2723 * %true if @dwork waspending, %false otherwise.

2724 */

2725boolcancel_delayed_work_sync(struct delayed_work *dwork)

2726{

2727      return __cancel_work_timer(&dwork->work, &dwork->timer);

2728}

2729EXPORT_SYMBOL(cancel_delayed_work_sync);

 

why the check_work is notcanceled immediately?

Fromwait_for_completion=>wait_for_common calling, we can know the delayed workis executed and has an associated worker.

 

check what the delayed_work isdoing and why not finished.

in which thread the delayed_workis executed?

 

#8  [INLINE]  wait_on_cpu_work

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2535

     work (work_struct *) = <optimized out>

     gcwq (global_cwq *) = 0xc159c840

     <inner block>

     barr (wq_barrier) = {

       work (work_struct) = {

         data (atomic_t) = {

           counter (int) = -1051056139},

          entry(list_head) = {

           next (list_head *) = 0xd7f05e98,

            prev(list_head *) = 0xd4fa6890},

          func(void *) = 0xc019ee70},

        done(completion) = {

         done (unsigned int) = 0,

          wait(__wait_queue_head) = {

           lock (spinlock) = {

             <unknown> (?) = {

               rlock (raw_spinlock) = {

                 raw_lock (arch_spinlock_t) = {

                   lock (unsigned int) = 65537(0x10001)},

                  magic(unsigned int) = 3735899821(0xdead4ead),

                  owner_cpu(unsigned int) = 4294967295(0xffffffff),

                  owner(void *) = 0xffffffff}}},

            task_list(list_head) = {

             next (list_head *) = 0xd74ffd18,

              prev(list_head *) = 0xd74ffd18}}}}

     worker (worker *) = 0xd87836dc

#9  0xc01a1e80 in wait_on_work+0x00e0(+224)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:486

     work (work_struct *) = 0xd87836dc [@ENTRY=0xd87836dc]

     ret (_Bool) = <optimized out>

     cpu (int) = <optimized out>

#10 0xc01a2024 in __cancel_work_timer+0x00b8(+184)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2643

     work (work_struct *) = 0xd87836dc [@ENTRY=0xd87836dc]  ***** delayed checkwork

     timer (timer_list *) = 0xd87836ec [@ENTRY=0xd87836ec]

 

The barrier worker is linked onworker->scheduled list according to following code.

we can get the followingscheduled list.

  0xd4fa6890, scheduled listhead

  0xd74ffd58 

  0xd7f05e98 

 

struct worker {

      union {

  [0]     struct list_head entry;

  [0]     struct hlist_node hentry;

      };

   [8] structwork_struct *current_work;

  [12] structcpu_workqueue_struct *current_cwq;

  [16] struct list_headscheduled;   ******

  [24] structtask_struct *task;

  [28] struct worker_pool*pool;

  [32] unsigned longlast_active;

  [36] unsigned int flags;

  [40] int id;

  [44] struct work_structrebind_work;

}

SIZE: 60

 

struct worker @ 0xd4fa6880

struct worker {

  {

    entry = {

     next = 0x0,

      prev= 0xc159c940

    },

    hentry ={

     next = 0x0,

      pprev= 0xc159c940

    }

  },

  current_work =0xd87836dc, ****** matched

  current_cwq =0xc15a2700,  ****** matched

  scheduled = {

    next =0xd74ffd58,

    prev =0xd7f05e98        ****** matched

  },

  task = 0xd00f2300,

  pool = 0xc159c958,

  last_active =590751,

  flags = 1,

  id = 6,

  rebind_work = {

    data = {

     counter = 1280

    },

    entry ={

     next = 0xd4fa68b0,

      prev= 0xd4fa68b0

    },

    func =0xc019f3b0 <worker_rebind_fn>

  }

}

struct worker.task @ 0xd4fa6880

  task = 0xd00f2300

struct task_struct.pid @0xd00f2300

  pid = 6028

 

Examine ts check_work workerthread.

#8  [INLINE]  wait_on_cpu_work

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2535

     work (work_struct *) = <optimized out>

     gcwq (global_cwq *) = 0xc0f83180

     <inner block>

     barr (wq_barrier) = {

       work (work_struct) = {

         data (atomic_t) = {

           counter (int) = -669451019},

          entry(list_head) = {

           next (list_head *) = 0xd4d83c10,  ******* only one barrier work

           prev (list_head *) = 0xd4d83c10},

          func(void *) = 0xc019ee70},

        done(completion) = {

         done (unsigned int) = 0,

          wait(__wait_queue_head) = {

           lock (spinlock) = {

             <unknown> (?) = {

               rlock (raw_spinlock) = {

                 raw_lock (arch_spinlock_t) = {

                   lock (unsigned int) = 65537(0x10001)},

                  magic(unsigned int) = 3735899821(0xdead4ead),

                  owner_cpu(unsigned int) = 4294967295(0xffffffff),

                  owner(void *) = 0xffffffff}}},

            task_list(list_head) = {

             next (list_head *) = 0xd2ef9ea0,

              prev(list_head *) = 0xd2ef9ea0}}}}

     worker (worker *) = 0xd87836cc

#9  0xc01a1e80 inwait_on_work+0x00e0(+224)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:486

     work (work_struct *) = 0xd87836cc [@ENTRY=0xd87836cc]   ************ts.work

     ret (_Bool) = <optimized out>

     cpu (int) = <optimized out>

#10 0xc01a1fd8 in __cancel_work_timer+0x006c(+108)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2643

     work (work_struct *) = 0xd87836cc

     timer (timer_list *) = 0x0 [@ENTRY=0x0]

     ret (int) = 0

#11 0xc01a2080 in cancel_work_sync+0x0008(+8)   [tail call]

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2671

     work (work_struct *) = <optimized out>

#12 0xc04ffb70 in elan_ktf2k_ts_check_work_func+0x0030(+48)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/drivers/input/touchscreen/ektf2k.c:2652

     work (work_struct *) = <optimized out>

 

From source code, we can see itis cancelling ts.work;

2705static voidelan_ktf2k_ts_check_work_func(struct work_struct *work) @ ektf2k.c

2706{

2707

2708      int do_tp_reset = 0;

2709      int touch_retry =0;

2710

2711      printk(KERN_EMERG "%s, chip may crash, we need to reset it\n",__func__);

2712

2713      //cancel_delayed_work_sync(&private_ts->check_work);

2714

2715      disable_irq(private_ts->client->irq);

2716      cancel_work_sync(&private_ts->work);

 

Same as above callingwait_for_completion=>wait_for_common, we can deduce the ts.work worker insame way.

 

struct list_head @ 0xd4d83c10

struct list_head {

  next = 0xd2ef9ee0,

  prev = 0xd2ef9ee0

}

struct worker @ 0xd4d83c00

struct worker {

  {

    entry = {

     next = 0x0,

      prev= 0xc0f8327c <unbound_global_cwq+252>

    },

    hentry ={

     next = 0x0,

      pprev= 0xc0f8327c <unbound_global_cwq+252>

    }

  },

  current_work =0xd87836cc,  ******** matched

  current_cwq =0xd818fc00,   ******** matched

  scheduled = {

    next =0xd2ef9ee0,

    prev =0xd2ef9ee0

  },

  task = 0xd0234f00,

  pool = 0xc0f83298<unbound_global_cwq+280>,

  last_active =590751,

  flags = 129,

  id = 1,

  rebind_work = {

    data = {

     counter = 1280

    },

    entry ={

     next = 0xd4d83c30,

      prev= 0xd4d83c30

    },

    func =0xc019f3b0 <worker_rebind_fn>

  }

}

struct worker.task @ 0xd4d83c00

  task = 0xd0234f00

struct task_struct.pid @0xd0234f00

  pid = 4528 

 

Examine ts work worker thread.

#7  0xc08678a8 inwait_for_common+0x0118(+280)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/sched/core.c:3602

      x(completion *) = 0xd7f05ea4

     timeout (long int) = <optimized out>

     state (int) = 2

     iowait (int) = 0

#8  [INLINE]  wait_on_cpu_work

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2535

     work (work_struct *) = <optimized out>

     gcwq (global_cwq *) = 0xc159c840

     <inner block>

     barr (wq_barrier) = {

       work (work_struct) = {

         data (atomic_t) = {

           counter (int) = -1051056139},

          entry(list_head) = {

           next (list_head *) = 0xd4fa6890,    ****** another barrier workfor delayed_work.

           prev (list_head *) = 0xd74ffd58},

          func(void *) = 0xc019ee70},

        done(completion) = {

         done (unsigned int) = 0,

          wait(__wait_queue_head) = {

           lock (spinlock) = {

             <unknown> (?) = {

               rlock (raw_spinlock) = {

                 raw_lock (arch_spinlock_t) = {

                   lock (unsigned int) = 65537(0x10001)},

                  magic(unsigned int) = 3735899821(0xdead4ead),

                  owner_cpu(unsigned int) = 4294967295(0xffffffff),

                  owner(void *) = 0xffffffff}}},

            task_list(list_head) = {

             next (list_head *) = 0xd7f05e58,

              prev(list_head *) = 0xd7f05e58}}}}

     worker (worker *) = 0xd87836dc

#9  0xc01a1e80 inwait_on_work+0x00e0(+224)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:486

     work (work_struct *) = 0xd87836dc [@ENTRY=0xd87836dc]

     ret (_Bool) = <optimized out>

     cpu (int) = <optimized out>

#10 0xc01a1fd8 in__cancel_work_timer+0x006c(+108)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2643

     work(work_struct *) = 0xd87836dc [@ENTRY=0xd87836dc]   ***** it is thedelayed_work

     timer (timer_list *) = 0xd87836ec [@ENTRY=0xd87836ec]

     ret (int) = 0

#11 0xc01a2078 in cancel_delayed_work_sync+0x0008(+8)   [tail call]

   /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:2728

     dwork (delayed_work *) = <optimized out>

#12 0xc04ffe38 in elan_ktf2k_ts_work_func+0x0028(+40)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/drivers/input/touchscreen/ektf2k.c:2680

     work (work_struct *) = 0xd87836cc

     rc (int) = <optimized out>

     ts (elan_ktf2k_ts_data *) = 0xd87836c0

     buf (unsigned char [12]) = {[0]0 <repeats 12 times>}

#13 0xc01a1150 inprocess_one_work+0x0124(+292)  

    /opt/Weekly_Release/Integration/5865/5865_userdebug_ss/kernel/kernel/workqueue.c:1866

     worker (worker *) = 0xd4d83c00 [@ENTRY=0xd4d83c00]

     work (work_struct *) = 0xd87836cc

     cwq (cpu_workqueue_struct *) = 0xd818fc00

     pool (worker_pool *) = <optimized out>

     gcwq (global_cwq *) = 0xc0f83180

     bwh (hlist_head *) = 0xd7f04000

     cpu_intensive (_Bool) = 0

      f(void *) = 0xc0e1dd60

     work_color (int) = 0

     collision (worker *) = <optimized out>

From above elan_ktf2k_ts_work_func is waiting delayed_work cancellation.

2751static voidelan_ktf2k_ts_work_func(struct work_struct *work) @ ektf2k.c

2752{

2753      int rc;

2754      struct elan_ktf2k_ts_data *ts =

2755      container_of(work, struct elan_ktf2k_ts_data, work);

2756      uint8_t buf[4+PACKET_SIZE] = { 0 };

2757      #ifdef ELAN_BUFFER_MODE

2758      uint8_t buf1[PACKET_SIZE] = { 0 };

2759      #endif

2760

2761      cancel_delayed_work_sync(&ts->check_work);

2762

2763      if (gpio_get_value(ts->intr_gpio))

 

[reason]

As can be seen in source code ofelan_ktf2k_ts_check_work_func and elan_ktf2k_ts_work_func in the touch screenpanel's driver,

elan_ktf2k_ts_check_work_functhat is ts.check_work is in cancel_work_sync(ts.work) while ts.work that iselan_ktf2k_ts_work_func is in cancel_delayed_work_sync(ts.check_work).

Dead Lock caused bycancel-work-syncly mutually in touch screen device driver.

 

[Reference Solution]

Do not mutually cancel eachother in elan_ktf2k_ts_check_work_func and elan_ktf2k_ts_work_func.