[zfs-devel] "Hang" when trying to drop_caches

Phil Pokorny ppokorny at penguincomputing.com
Wed Jul 1 13:51:09 EDT 2015


Hello,

I have a test system with CentOS 7 that "hung" when attempting to "echo 3 >
/proc/sys/vm/drop_caches"

ZFS is the latest from the repo, just installed and compiled last night:

[root at localhost ~]# dkms status
spl, 0.6.4.2, 3.10.0-1.1.0.79.VCA, x86_64: installed
zfs, 0.6.4.2, 3.10.0-1.1.0.79.VCA, x86_64: installed
spl, 0.6.4.2, 3.10.0-229.el7.x86_64, x86_64: installed-weak from
3.10.0-1.1.0.79.VCA
zfs, 0.6.4.2, 3.10.0-229.el7.x86_64, x86_64: installed-weak from
3.10.0-1.1.0.79.VCA

The kernel has some custom patches for device drivers (the VCA thing...)
but they don't touch filesystems.

The filesystem was idle (ie no read/write traffic) and had been under test
workloads several hours ago (creating/rewriting large files, creating small
files) so the ARC and VFS cache were relatively populated:

"vmstat 3" looked like this:

procs -----------memory---------- ---swap-- -----io---- -system--
------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
wa st
 0  0      0 16490884   2060 13025108    0    0     0     0  102  174  0  0
100  0  0
 0  0      0 16490792   2060 13025100    0    0     0     0  160  356  0  0
100  0  0
 0  0      0 16490884   2060 13025100    0    0     0     0  112  198  0  0
100  0  0
 0  0      0 16490868   2060 13025100    0    0     0     0  108  141  0  0
100  0  0
 0  0      0 16490868   2060 13025100    0    0     0     0   95  158  0  0
100  0  0
 0  0      0 16490900   2060 13025100    0    0     0     0  109  134  0  0
100  0  0
 0  0      0 16490900   2060 13025100    0    0     0     0  111  141  0  0
100  0  0

Then I issued the "echo 3 > /proc/sys/vm/drop_caches" and this happened:

 0  0      0 16487112   2060 13025376    0    0     0     0  108  133  0  0
100  0  0
 0  0      0 16487112   2060 13025376    0    0     0     0  148  310  0  0
100  0  0
 1  0      0 19385544      0 10230796    0    0    20    40 1307  752  0  1
99  0  0
 1  0      0 19405424      0 10210992    0    0     0     0  838  833  0  1
99  0  0
 3  0      0 19409252      0 10207220    0    0   439     5  927  863  0  1
99  0  0
 1  0      0 19415148      0 10201836    0    0     4     0  819  777  0  1
99  0  0
procs -----------memory---------- ---swap-- -----io---- -system--
------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
wa st
 2  0      0 19446984      0 10170208    0    0    25     0  955  881  0  1
99  0  0
 1  0      0 19446012      0 10170936    0    0   728     0  956  928  0  1
99  0  0
 1  0      0 19445952      0 10171976    0    0    65     0  838  856  0  1
99  0  0
 1  0      0 19445916      0 10171624    0    0     0     0  796  743  0  1
99  0  0
 1  0      0 19445932      0 10171744    0    0     0     0  641  462  0  1
99  0  0
 1  0      0 19445944      0 10171744    0    0     0     0  725  589  0  1
99  0  0
 1  0      0 19445944      0 10171744    0    0     0     0  733  627  0  1
99  0  0

And it stuck there.  Two bursts of activity about 2 minutes apart and then
no progress for 5-10 minutes.  Bash shell hung and can't kill the "echo"
command, strace on the bash shell hangs.  vmstat looks like this:

procs -----------memory---------- ---swap-- -----io---- -system--
------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
wa st
 1  0      0 28498888      0 7474408    0    0     0     0 1066 1067  0  1
99  0  0
 1  0      0 28561728      0 7474400    0    0     0     0  913  903  0  1
99  0  0
 1  0      0 28626504      0 7474400    0    0     0     0  972 1005  0  1
99  0  0
 1  0      0 28699704      0 7474332    0    0     0     0  937 1024  0  1
99  0  0
 1  0      0 28762100      0 7474308    0    0     0     0 1005 1051  0  1
99  0  0


Triggering stack traces via /proc/sysrq_trigger shows this:

[50689.184056] NMI backtrace for cpu 10
[50689.184062] CPU: 10 PID: 77074 Comm: bash Tainted: PF
IO--------------   3.10.0-1.1.0.79.VCA #1
[50689.184064] Hardware name: Intel Corporation S2600WTT/S2600WTT, BIOS
SE5C610.86B.01.01.1008.031920151331 03/19/2015
[50689.184065] task: ffff88101580c440 ti: ffff880fe63b0000 task.ti:
ffff880fe63b0000
[50689.184067] RIP: 0010:[<ffffffff812edfe5>]  [<ffffffff812edfe5>]
__list_del_entry+0x35/0xd0
[50689.184075] RSP: 0018:ffff880fe63b3cb0  EFLAGS: 00000046
[50689.184075] RAX: ffff8810207353d0 RBX: ffff8807c7ea7090 RCX:
dead000000200200
[50689.184076] RDX: ffffea0001a7f420 RSI: 0000000000000010 RDI:
ffffea000161a620
[50689.184077] RBP: ffff880fe63b3cb0 R08: ffffea000161a620 R09:
ffff88103e5564a0
[50689.184081] R10: ffffea0030cd7e00 R11: ffffffff812d4e39 R12:
ffffea000161a600
[50689.184082] R13: ffffea0001a7f400 R14: ffffea000161a620 R15:
ffff8810207353c0
[50689.184083] FS:  00007f3cad567740(0000) GS:ffff88103e540000(0000)
knlGS:0000000000000000
[50689.184084] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[50689.184085] CR2: 00007f19cbc2f000 CR3: 0000000fa8c83000 CR4:
00000000001407e0
[50689.184086] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[50689.184087] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
0000000000000400
[50689.184088] Stack:
[50689.184088]  ffff880fe63b3d20 ffffffff811ad440 ffff8807c7ea70a0
0000000100000000
[50689.184093]  0000000000000246 ffff8810207c8f00 0000000000000002
ffff8810207353d0
[50689.184096]  ffff8807c7ea7080 ffff880fbcc00000 ffff880fbcc00000
ffff880fbcef0000
[50689.184098] Call Trace:
[50689.184104]  [<ffffffff811ad440>] kmem_cache_shrink+0x140/0x250
[50689.184117]  [<ffffffffa0556acc>] spl_kmem_cache_reap_now+0x11c/0x170
[spl]
[50689.184152]  [<ffffffffa06931cb>] arc_kmem_reap_now+0x4b/0xb0 [zfs]
[50689.184164]  [<ffffffffa06932ad>] arc_shrinker_func+0x7d/0x170 [zfs]
[50689.184169]  [<ffffffff81169205>] shrink_slab+0x165/0x300
[50689.184175]  [<ffffffff81615472>] ? _raw_spin_lock+0x12/0x50
[50689.184180]  [<ffffffff812244c3>] drop_caches_sysctl_handler+0xc3/0x120
[50689.184185]  [<ffffffff812393f3>] proc_sys_call_handler+0xd3/0xf0
[50689.184191]  [<ffffffff81239424>] proc_sys_write+0x14/0x20
[50689.184197]  [<ffffffff811c6cad>] vfs_write+0xbd/0x1e0
[50689.184199]  [<ffffffff811c76f8>] SyS_write+0x58/0xb0
[50689.184202]  [<ffffffff8161e1a9>] system_call_fastpath+0x16/0x1b
[50689.184203] Code: 00 00 ad de 48 8b 47 08 48 89 e5 48 39 ca 74 29 48 b9
00 02 20 00 00 00 ad de 48 39 c8 74 7a 4c 8b 00 4c 39 c7 75 53 4c 8b 42 08
<4c> 39 c7 75 2b 48 89 42 08 48 89 10 5d c3 49 89 d0 48 89 f9 48

I then tried to see if the filesystem itself was hung.  So I started doing
I/O to the filesystem and suddenly things started making progress again...
eventually with this state after my I/O completed.  It appears hung again
for  about 30 seconds.

procs -----------memory---------- ---swap-- -----io---- -system--
------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
wa st
 3  0      0 52170860      0 6977744    0    0  3609     0 5062 7670  0  3
96  1  0
 2  0      0 52159444      0 6988652    0    0  8625     0 6564 8964  0  3
96  1  0
 4  1      0 52152328      0 6995448    0    0  9398   745 6306 7850  0  3
96  1  0
 4  0      0 52146252      0 7002444    0    0  3257   472 5507 7085  0  3
96  1  0
 3  0      0 52138360      0 7009848    0    0  5881     0 5431 7428  0  3
96  1  0
 2  1      0 52133500      0 7014908    0    0  3058     0 4730 5795  0  3
96  1  0
 2  0      0 52126884      0 7021584    0    0  3085   913 5371 7169  0  3
96  1  0
 2  2      0 52119768      0 7028228    0    0  5699   539 6449 8219  0  3
95  1  0
 2  1      0 52110508      0 7037332    0    0  4273   415 6831 8890  0  3
96  1  0
 1  0      0 52106652      0 7041168    0    0  4013   913 4295 5332  0  3
96  1  0
 1  0      0 52106732      0 7041200    0    0     0     0 1212 1155  0  2
98  0  0
 1  0      0 52107152      0 7041284    0    0     0     3 1118  943  0  2
98  0  0
 1  0      0 52107168      0 7041284    0    0     0     0 1055  819  0  2
98  0  0
 2  0      0 52107152      0 7041284    0    0     0     0 1071  889  0  2
98  0  0
 1  0      0 52107152      0 7041284    0    0     0     0 1204 1130  0  2
98  0  0
 1  0      0 52107152      0 7041284    0    0     0     0 1198 1108  0  2
98  0  0
 1  0      0 52107152      0 7041284    0    0     0     0 1260 1086  0  2
98  0  0

immediately followed by this:

 2  0      0 53079416      0 6069412    0    0     0 33152 13146 33176  0
4 95  0  0
 0  1      0 55176156      0 3980260    0    0   288 53265 7227 69450  0  4
94  2  0
 1  0      0 55304332      0 3852112    0    0   156 21373 1620 2610  0  1
98  1  0
 1  0      0 55305432      0 3851096    0    0     0     0  105  139  0  0
100  0  0
procs -----------memory---------- ---swap-- -----io---- -system--
------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
wa st
 1  0      0 55311732      0 3845056    0    0    10 16051 1593 3574  0  1
99  0  0
 1  0      0 55311604      0 3845164    0    0     0     0  116  150  0  0
100  0  0
 0  0      0 55311684      0 3845128    0    0     1     0  105  131  0  0
100  0  0
 0  0      0 55311684      0 3845116    0    0     0     0  102  128  0  0
100  0  0
 0  0      0 55311444      0 3845376    0    0     0     0  118  185  0  0
100  0  0

A burst of activity and then the echo completes (notice the "r" column
drops from >0 to 0)

Is this an understood behavior?

Anything I can do to "fix" this?  Point me in the right direction and I can
probably put together a patch.

Phil P.



-- 
Philip Pokorny, RHCE
Chief Technology Officer
PENGUIN COMPUTING, Inc
www.penguincomputing.com

Changing the world through technical innovation
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://list.zfsonlinux.org/pipermail/zfs-devel/attachments/20150701/cd268885/attachment.html>


More information about the zfs-devel mailing list