ashmem: ashmem_shrink:inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage;possible deadlock situation

[psh2001]

Hi,

 

I have been facing this possible deadlock lockdep warning under low memory conditions.I am using kernel 3.4 version

 

<4>1[ 704.818328] 526 inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.

<4>1[ 704.825805] 526 kswapd0/526 [HC0[0]:SC0[0]:HE1:SE1] takes:

<4>1[ 704.831909] 526 (&sb->s_type->i_mutex_key#4){+.+.?.}, at: [<c00b6e58>] vmtruncate_range+0x7c/0xec

<4>1[ 704.841491] 526 {RECLAIM_FS-ON-W} state was registered at:

<4>1[ 704.847595] 526 [<c007ccb8>] mark_held_locks+0x60/0x120

<4>1[ 704.853607] 526 [<c007d488>] lockdep_trace_alloc+0x88/0xf4

<4>1[ 704.859863] 526 [<c00b1114>] __alloc_pages_nodemask+0x70/0x778

<4>1[ 704.866485] 526 [<c00d61ec>] new_slab+0x68/0x220

<4>1[ 704.871887] 526 [<c05a13a8>] __slab_alloc.isra.51.constprop.55+0x4ac/0x56c

<4>1[ 704.879547] 526 [<c00d71f4>] kmem_cache_alloc+0x10c/0x118

<4>1[ 704.885711] 526 [<c00f2894>] __d_alloc+0x1c/0x154

<4>1[ 704.891204] 526 [<c00f2c24>] d_alloc+0x10/0x60

<4>1[ 704.896423] 526 [<c00e6714>] __lookup_hash+0xac/0xdc

<1>0[ 704.901306] 3389 [1373374124.123] sndp : sndp_fsi_trigger(): PLAYBACK val[0x20] TRIGGER_STOP

<4>1[ 704.911132] 526 [<c00e69a4>] do_lookup+0x260/0x2c4

<4>1[ 704.916687] 526 [<c00e97ec>] do_last.isra.30+0x134/0x6bc

<4>1[ 704.922790] 526 [<c00e9f74>] path_openat+0xb8/0x388

<4>1[ 704.928436] 526 [<c00ea32c>] do_filp_open+0x2c/0x80

<4>1[ 704.934112] 526 [<c00dac10>] do_sys_open+0xdc/0x174

<4>1[ 704.939758] 526 [<c000ee80>] ret_fast_syscall+0x0/0x3c

<4>1[ 704.945678] 526 irq event stamp: 1219094

<4>1[ 704.950195] 526 hardirqs last enabled at (1219094): [<c05a4a08>] mutex_trylock+0x184/0x1fc

<4>1[ 704.959167] 526 hardirqs last disabled at (1219093): [<c05a48d0>] mutex_trylock+0x4c/0x1fc

<4>1[ 704.968017] 526 softirqs last enabled at (1215303): [<c00371c4>] irq_exit+0xa0/0xa8

<4>1[ 704.976379] 526 softirqs last disabled at (1215274): [<c00371c4>] irq_exit+0xa0/0xa8

<4>1[ 704.984741] 526

<4>1[ 704.984741] 526 other info that might help us debug this:

<4>1[ 704.993164] 526 Possible unsafe locking scenario:

<4>1[ 704.993164] 526

<4>1[ 705.000976] 526 CPU0

<4>1[ 705.004364] 526 ----

<4>1[ 705.007781] 526 lock(&sb->s_type->i_mutex_key#4);

<4>1[ 705.013275] 526 <Interrupt>

<4>1[ 705.016845] 526 lock(&sb->s_type->i_mutex_key#4);

<4>1[ 705.022521] 526

<4>1[ 705.022521] 526 *** DEADLOCK ***

<4>1[ 705.022521] 526

<4>1[ 705.031311] 526 2 locks held by kswapd0/526:

<4>1[ 705.036163] 526 #0: (shrinker_rwsem){++++..}, at: [<c00b7450>] shrink_slab+0x28/0x24c

<4>1[ 705.044799] 526 #1: (ashmem_mutex){+.+.+.}, at: [<c03757ec>] ashmem_shrink+0x30/0x12c

<4>1[ 705.053466] 526 stack backtrace:

<4>1[ 705.059722] 526 [<c001543c>] (unwind_backtrace+0x0/0xf8) from [<c059feb0>] (print_usage_bug+0x250/0x2b8)

<4>1[ 705.069824] 526 [<c059feb0>] (print_usage_bug+0x250/0x2b8) from [<c007a584>] (mark_lock+0x530/0x66c)

<4>1[ 705.079559] 526 [<c007a584>] (mark_lock+0x530/0x66c) from [<c007abc4>] (__lock_acquire+0x504/0x1a28)

<4>1[ 705.089263] 526 [<c007abc4>] (__lock_acquire+0x504/0x1a28) from [<c007c58c>] (lock_acquire+0x60/0x74)

<4>1[ 705.099090] 526 [<c007c58c>] (lock_acquire+0x60/0x74) from [<c05a582c>] (mutex_lock_nested+0x6c/0x3f0)

<4>1[ 705.109008] 526 [<c05a582c>] (mutex_lock_nested+0x6c/0x3f0) from [<c00b6e58>] (vmtruncate_range+0x7c/0xec)

<4>1[ 705.119262] 526 [<c00b6e58>] (vmtruncate_range+0x7c/0xec) from [<c0375864>] (ashmem_shrink+0xa8/0x12c)

<4>1[ 705.129150] 526 [<c0375864>] (ashmem_shrink+0xa8/0x12c) from [<c00b75d8>] (shrink_slab+0x1b0/0x24c)

<4>1[ 705.138793] 526 [<c00b75d8>] (shrink_slab+0x1b0/0x24c) from [<c00b9800>] (kswapd+0x52c/0x9b4)

<4>1[ 705.147918] 526 [<c00b9800>] (kswapd+0x52c/0x9b4) from [<c004df08>] (kthread+0x84/0x90)

<4>1[ 705.156524] 526 [<c004df08>] (kthread+0x84/0x90) from [<c000f9dc>] (kernel_thread_exit+0x0/0x8)

 

while removing vmtruncate_range usage in ashmem.c as part of this patch (commit 3f31d07571eeea18a7d34db9af21d2285b807a17 ), author has suggested using shmem_truncate_range directly but no patch is proposed or upstreamed regarding this .

Currently in my code,  i still use vmtruncate_range() instead of do_fallocate but still both these functions take mutex lock and hence issue is still possible with using do_fallocate()

I have tried using shmem_truncate_range() in ashmem_shrink, and i don't see the lockdep warning anymore.

but still i want the confirmation or any side effects of using shmem_truncate_range directly if any.

 

Thanks

Shiva

 

 

[冯力]

What's you test program? can you paste it out or send a copy to me?

It's a deadlock which had been discused in linux-kernel mail list.

I want to know the detail.But It's hard to reproduct.

在 2013年7月10日星期三UTC+8下午4时23分23秒，psh2001写道：

[psh2001]

My test scenario is:

1.Set vmalloc to 400M

2. Load 5 game apps.(

com.imangi.templerun2-1.apk
com.imangi.templerun-1.apk
com.rovio.angrybirdsseasons-1.apk
com.rovio.angrybirdsrio-1.apk
com.ArtInGames.AirAttackHDLite-1.apk)

3. Start Youtube 3G Streaming

4. start 5 to 6 filedownloads from http://www.thinkbroadband.com/download.html 

 

Switch b/w steps 2 and 3 periodically.

 

Keep checking log file for lockdep warning. Also keep checking cat /proc/meminfo. memfree should be b/w 7M to 15M. Issue is reproducible within 30 minutes.

 

Regards

Shiva

[冯力]

Thanks for your answer.
What brand of phone are you using to reproduce?and what's your
android version and kernel version. I use nexus 4，it has a big memory
to 2G. and vmalloc is 245M.The Step1 set vmalloc to 400M,how to
achieve it? modify the boot cmd? and where is it?

Do you have a try to write a exploit to let it reproduce easily?I have
tried ,but I'm failed to let the kernel go to the deadlock path.
BTW,what's the meaning of b/w?

2013/7/15 psh2001 <pshe...@gmail.com>:

> --
> --
> unsubscribe: android-kerne...@googlegroups.com
> website: http://groups.google.com/group/android-kernel
> ---
> You received this message because you are subscribed to a topic in the
> Google Groups "Android Linux Kernel Development" group.
> To unsubscribe from this topic, visit
> https://groups.google.com/d/topic/android-kernel/u6VtNa_it9c/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to
> android-kerne...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>



--
Thanks and Best Regards,
vonnyfly

Cell:13401157876
Email :lifen...@gmail.com
Addr: Rm. 911,DaYunCun,Zhichun Road,Haidian Districts Beijing,100191

[psh2001]

Sorry for the delayed response.

I am using a reference development platform .

i am using kernel version 3.4.5.

Android version : JB 4.2.2

 

If the vmalloc in your setup is 245M then no need to change it. You should be able to hit the scenario by

performing below operations simultaneously

 

1.start 5 to 6 filedownloads from
    http://www.thinkbroadband.com/download.html

2. Load 5 game apps.( 
com.imangi.templerun2-1.apk 
com.imangi.templerun-1.apk 
com.rovio.angrybirdsseasons-1.apk 
com.rovio.angrybirdsrio-1.apk 
com.ArtInGames.AirAttackHDLite-1.apk

3. 3g/4g streaming on youtube.

 

switch between steps 2 and 3 alternatively.

 

Also the cat /proc/memfree should be between 9mb to 15mb . Then you will see the deadlock scenario.

 

Its easily reproduced withing 10 minutes  with the above mentioned steps.

 

new kernel lockdep warning log:

--------------------------------------------------

<4>0[ 851.390045] 536 =================================

<4>0[ 851.395477] 536 [ INFO: inconsistent lock state ]

<4>0[ 851.400909] 536 3.4.5 #1 Tainted: G O

<4>0[ 851.406158] 536 ---------------------------------

<4>0[ 851.411621] 536 inconsistent {RECLAIM_FS-ON-W} -> {IN-RECLAIM_FS-W} usage.

<4>0[ 851.419219] 536 kswapd0/536 [HC0[0]:SC0[0]:HE1:SE1] takes:

<4>0[ 851.425445] 536 (&sb->s_type->i_mutex_key#4){+.+.?.}, at: [<c00e66e4>] shmem_fallocate+0x2c/0x120

<4>0[ 851.435852] 536 {RECLAIM_FS-ON-W} state was registered at:

<4>0[ 851.442077] 536 [<c00881d4>] mark_held_locks+0x60/0x120

<4>0[ 851.448364] 536 [<c00889a4>] lockdep_trace_alloc+0x88/0xf4

<4>0[ 851.454925] 536 [<c00d5c0c>] __alloc_pages_nodemask+0x70/0x8c4

<4>0[ 851.461822] 536 [<c0107c88>] new_slab+0x68/0x220

<4>0[ 851.467498] 536 [<c062551c>] __slab_alloc.isra.45.constprop.49+0x4ac/0x56c

<4>0[ 851.475463] 536 [<c01090cc>] kmem_cache_alloc+0x12c/0x270

<4>0[ 851.481933] 536 [<c012c2f0>] __d_alloc+0x1c/0x154

<4>0[ 851.487701] 536 [<c012c680>] d_alloc+0x10/0x60

<4>0[ 851.493194] 536 [<c0120170>] __lookup_hash+0xac/0xdc

<4>0[ 851.499237] 536 [<c0120400>] do_lookup+0x260/0x2c4

<4>0[ 851.505096] 536 [<c0123248>] do_last.isra.30+0x134/0x6bc

<4>0[ 851.511444] 536 [<c01239d0>] path_openat+0xb8/0x388

<4>0[ 851.517364] 536 [<c0123d88>] do_filp_open+0x2c/0x80

<4>0[ 851.523284] 536 [<c01143d8>] do_sys_open+0xdc/0x174

<4>0[ 851.529235] 536 [<c000ee80>] ret_fast_syscall+0x0/0x3c

<4>0[ 851.535430] 536 irq event stamp: 3274624

<4>0[ 851.540100] 536 hardirqs last enabled at (3274624): [<c0628e7c>] mutex_trylock+0x184/0x1fc

<4>0[ 851.549346] 536 hardirqs last disabled at (3274623): [<c0628d44>] mutex_trylock+0x4c/0x1fc

<4>0[ 851.558532] 536 softirqs last enabled at (3270965): [<c0039578>] irq_exit+0xa0/0xa8

<4>0[ 851.567169] 536 softirqs last disabled at (3270946): [<c0039578>] irq_exit+0xa0/0xa8

<4>0[ 851.575805] 536

<4>0[ 851.575805] 536 other info that might help us debug this:

<4>0[ 851.584503] 536 Possible unsafe locking scenario:

<4>0[ 851.584503] 536

<4>0[ 851.592590] 536 CPU0

<4>0[ 851.596130] 536 ----

<4>0[ 851.599670] 536 lock(&sb->s_type->i_mutex_key#4);

<4>0[ 851.605743] 536 <Interrupt>

<4>0[ 851.609436] 536 lock(&sb->s_type->i_mutex_key#4);

<4>0[ 851.615661] 536

<4>0[ 851.615661] 536 *** DEADLOCK ***

<4>0[ 851.615661] 536

<4>0[ 851.624877] 536 2 locks held by kswapd0/536:

<4>0[ 851.629913] 536 #0: (shrinker_rwsem){++++..}, at: [<c00df2cc>] shrink_slab+0x28/0x588

<4>0[ 851.639404] 536 #1: (ashmem_mutex){+.+.+.}, at: [<c03ef634>] ashmem_shrink+0x30/0x13c

<4>0[ 851.648895] 536

<4>0[ 851.648895] 536 stack backtrace:

<4>0[ 851.655426] 536 [<c001543c>] (unwind_backtrace+0x0/0xf8) from [<c0623940>] (print_usage_bug+0x250/0x2b8)

<4>0[ 851.665679] 536 [<c0623940>] (print_usage_bug+0x250/0x2b8) from [<c00857dc>] (mark_lock+0x530/0x66c)

<4>0[ 851.675537] 536 [<c00857dc>] (mark_lock+0x530/0x66c) from [<c0085e1c>] (__lock_acquire+0x504/0x1a28)

<4>0[ 851.685394] 536 [<c0085e1c>] (__lock_acquire+0x504/0x1a28) from [<c0087954>] (lock_acquire+0x90/0x1f8)

<4>0[ 851.695434] 536 [<c0087954>] (lock_acquire+0x90/0x1f8) from [<c0629ca0>] (mutex_lock_nested+0x6c/0x3f0)

<4>0[ 851.705566] 536 [<c0629ca0>] (mutex_lock_nested+0x6c/0x3f0) from [<c00e66e4>] (shmem_fallocate+0x2c/0x120)

<4>0[ 851.715942] 536 [<c00e66e4>] (shmem_fallocate+0x2c/0x120) from [<c0113cbc>] (do_fallocate+0xdc/0x104)

<4>0[ 851.725921] 536 [<c0113cbc>] (do_fallocate+0xdc/0x104) from [<c03ef6c0>] (ashmem_shrink+0xbc/0x13c)

<4>0[ 851.735687] 536 [<c03ef6c0>] (ashmem_shrink+0xbc/0x13c) from [<c00df478>] (shrink_slab+0x1d4/0x588)

<4>0[ 851.745483] 536 [<c00df478>] (shrink_slab+0x1d4/0x588) from [<c00e2670>] (kswapd+0x5c4/0xcdc)

<4>0[ 851.754760] 536 [<c00e2670>] (kswapd+0x5c4/0xcdc) from [<c0054da0>] (kthread+0x84/0x90)

<4>0[ 851.763519] 536 [<c0054da0>] (kthread+0x84/0x90) from [<c000f9dc>] (kernel_thread_exit+0x0/0x8)

<6>0[ 852.090393] 762 [TSP] R 00 176, 462

<6>0[ 853.165649] 762 [TSP] P 00 168, 424, w=7