echo 2 or 3 to /proc/sys/vm/drop_caches hangs with 3.17rc5 kernel

[eric0e]

After creating a zpool, running the commands:
echo 2 > /proc/sys/vm/drop_caches
or
echo 3 > /proc/sys/vm/drop_caches
hangs the echo command, and it never returns to prompt. Top shows bash is using 100% of a CPU

The commands used to reproduce this issue:

zpool status
 no pools available

time echo 1 > /proc/sys/vm/drop_caches
 real   0m0.011s
 user   0m0.000s
 sys    0m0.013s

time echo 2 > /proc/sys/vm/drop_caches
 real   0m0.014s
 user   0m0.000s
 sys    0m0.016s

time echo 3 > /proc/sys/vm/drop_caches
 real   0m0.002s
 user   0m0.001s
 sys    0m0.000s

zpool create ztest /dev/sdd
 zpool status
  pool: ztest
 state: ONLINE
  scan: none requested
 config:
    NAME        STATE     READ WRITE CKSUM
    ztest       ONLINE       0     0     0
      sdd       ONLINE       0     0     0

errors: No known data errors

 time echo 1 > /proc/sys/vm/drop_caches
real    0m0.003s
user    0m0.000s
sys 0m0.002s

 time echo 2 > /proc/sys/vm/drop_caches

  Never comes back
 

$ cat /proc/version
Linux version 3.17.0-031700rc5-generic (apw@gomeisa) (gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) ) #201409151105 SMP Mon Sep 15 15:08:10 UTC 2014

$ modinfo spl
filename: /lib/modules/3.17.0-031700rc5-generic/extra/spl/spl/spl.ko
version: 0.6.3-9_gf9bde4f
srcversion: BACB1C5837216AFB6BD3BA5

$ modinfo zfs
filename: /lib/modules/3.17.0-031700rc5-generic/extra/zfs/zfs/zfs.ko
version: 0.6.3-75_g2d50158
srcversion: E3A63E39BC625D2A37EE083

I dumped the running processes with:
echo l > /proc/sysrq-trigger
The whole output is at: http://pastebin.com/6ixmrqCf

The section with the spl processes:

Sep 15 21:49:14 kc80 kernel: [ 1905.403024] NMI backtrace for cpu 11
Sep 15 21:49:14 kc80 kernel: [ 1905.403028] CPU: 11 PID: 2334 Comm: bash Tainted: P           OE  3.17.0-031700rc5-generic #201409151105
Sep 15 21:49:14 kc80 kernel: [ 1905.403029] Hardware name: HP ProLiant DL380p Gen8, BIOS P70 12/14/2012
Sep 15 21:49:14 kc80 kernel: [ 1905.403033] task: ffff880bec21c600 ti: ffff880bd5c00000 task.ti: ffff880bd5c00000
Sep 15 21:49:14 kc80 kernel: [ 1905.403038] RIP: 0010:[]  [] deactivate_slab+0x73/0x490
Sep 15 21:49:14 kc80 kernel: [ 1905.403044] RSP: 0018:ffff880bd5c03ab0  EFLAGS: 00000006
Sep 15 21:49:14 kc80 kernel: [ 1905.403045] RAX: ffff8817f8e83c00 RBX: ffff8817f8e83c00 RCX: 0000000000000000
Sep 15 21:49:14 kc80 kernel: [ 1905.403046] RDX: 0000000180200013 RSI: ffffea005fe3a000 RDI: ffff880c0f403500
Sep 15 21:49:14 kc80 kernel: [ 1905.403047] RBP: ffff880bd5c03b60 R08: ffff88183b400180 R09: 0000000000000100
Sep 15 21:49:14 kc80 kernel: [ 1905.403048] R10: ffff8817f8980000 R11: 0000000000000002 R12: ffffea005fe3a000
Sep 15 21:49:14 kc80 kernel: [ 1905.403049] R13: ffff8817f8e84c00 R14: ffff880c0f403500 R15: ffff8817f8e85c00
Sep 15 21:49:14 kc80 kernel: [ 1905.403051] FS:  00007f53a10f3740(0000) GS:ffff88183b860000(0000) knlGS:0000000000000000
Sep 15 21:49:14 kc80 kernel: [ 1905.403052] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Sep 15 21:49:14 kc80 kernel: [ 1905.403057] CR2: 00007f2e12815028 CR3: 0000000bf964f000 CR4: 00000000000407e0
Sep 15 21:49:14 kc80 kernel: [ 1905.403062] Stack:
Sep 15 21:49:14 kc80 kernel: [ 1905.403063]  0000000000000000 ffffffff811cbb10 ffff880c0f403500 0000000000000002
Sep 15 21:49:14 kc80 kernel: [ 1905.403066]  ffff880bd5c03b60 0000000000000008 ffffffff811cbb10 0000000f811cbb10
Sep 15 21:49:14 kc80 kernel: [ 1905.403068]  ffff880bd5c03b20 ffffffff810f1957 ffff880bd5c03b20 0000000180200012
Sep 15 21:49:14 kc80 kernel: [ 1905.403070] Call Trace:
Sep 15 21:49:14 kc80 kernel: [ 1905.403075]  [] ? slab_cpuup_callback+0xe0/0xe0
Sep 15 21:49:14 kc80 kernel: [ 1905.403078]  [] ? slab_cpuup_callback+0xe0/0xe0
Sep 15 21:49:14 kc80 kernel: [ 1905.403083]  [] ? smp_call_function_single+0x67/0xa0
Sep 15 21:49:14 kc80 kernel: [ 1905.403085]  [] ? smp_call_function_many+0x21f/0x260
Sep 15 21:49:14 kc80 kernel: [ 1905.403087]  [] flush_cpu_slab+0x40/0x70
Sep 15 21:49:14 kc80 kernel: [ 1905.403093]  [] ? slab_cpuup_callback+0xe0/0xe0
Sep 15 21:49:14 kc80 kernel: [ 1905.403095]  [] on_each_cpu_mask+0x5d/0x80
Sep 15 21:49:14 kc80 kernel: [ 1905.403101]  [] ? arch_local_irq_save+0x20/0x20
Sep 15 21:49:14 kc80 kernel: [ 1905.403103]  [] ? slab_cpuup_callback+0xe0/0xe0
Sep 15 21:49:14 kc80 kernel: [ 1905.403106]  [] on_each_cpu_cond+0xb3/0xe0
Sep 15 21:49:14 kc80 kernel: [ 1905.403108]  [] ? __kmem_cache_shrink+0x2f/0x1e0
Sep 15 21:49:14 kc80 kernel: [ 1905.403112]  [] flush_all+0x2a/0x30
Sep 15 21:49:14 kc80 kernel: [ 1905.403115]  [] __kmem_cache_shrink+0x48/0x1e0
Sep 15 21:49:14 kc80 kernel: [ 1905.403119]  [] kmem_cache_shrink+0x23/0x40
Sep 15 21:49:14 kc80 kernel: [ 1905.403127]  [] spl_kmem_cache_reap_now+0x284/0x320 [spl]
Sep 15 21:49:14 kc80 kernel: [ 1905.403131]  [] ? put_super+0x31/0x40
Sep 15 21:49:14 kc80 kernel: [ 1905.403133]  [] ? drop_super+0x22/0x30
Sep 15 21:49:14 kc80 kernel: [ 1905.403138]  [] __spl_kmem_cache_generic_shrinker.isra.11+0x6f/0xe0 [spl]
Sep 15 21:49:14 kc80 kernel: [ 1905.403142]  [] spl_kmem_cache_generic_shrinker_scan_objects+0x12/0x30 [spl]
Sep 15 21:49:14 kc80 kernel: [ 1905.403146]  [] shrink_slab_node+0x140/0x2c0
Sep 15 21:49:14 kc80 kernel: [ 1905.403149]  [] shrink_slab+0x8a/0x130
Sep 15 21:49:14 kc80 kernel: [ 1905.403154]  [] drop_caches_sysctl_handler+0x73/0x110
Sep 15 21:49:14 kc80 kernel: [ 1905.403157]  [] proc_sys_call_handler+0xbc/0xd0
Sep 15 21:49:14 kc80 kernel: [ 1905.403159]  [] proc_sys_write+0x14/0x20
Sep 15 21:49:14 kc80 kernel: [ 1905.403161]  [] vfs_write+0xc7/0x1f0
Sep 15 21:49:14 kc80 kernel: [ 1905.403163]  [] SyS_write+0x4f/0xb0
Sep 15 21:49:14 kc80 kernel: [ 1905.403167]  [] system_call_fastpath+0x1a/0x1f

Arcstats

cat /proc/spl/kstat/zfs/arcstats
5 1 0x01 85 4080 19370112934 4549977028381
name                            type data
hits                            4    68
misses                          4    184
demand_data_hits                4    0
demand_data_misses              4    0
demand_metadata_hits            4    68
demand_metadata_misses          4    184
prefetch_data_hits              4    0
prefetch_data_misses            4    0
prefetch_metadata_hits          4    0
prefetch_metadata_misses        4    0
mru_hits                        4    68
mru_ghost_hits                  4    0
mfu_hits                        4    0
mfu_ghost_hits                  4    0
deleted                         4    0
recycle_miss                    4    0
mutex_miss                      4    0
evict_skip                      4    0
evict_l2_cached                 4    0
evict_l2_eligible               4    0
evict_l2_ineligible             4    0
hash_elements                   4    27
hash_elements_max               4    27
hash_collisions                 4    0
hash_chains                     4    0
hash_chain_max                  4    0
p                               4    25335384064
c                               4    50670768128
c_min                           4    4194304
c_max                           4    50670768128
size                            4    485040
hdr_size                        4    10528
data_size                       4    0
meta_size                       4    414208
other_size                      4    60304
anon_size                       4    16384
anon_evict_data                 4    0
anon_evict_metadata             4    0
mru_size                        4    396800
mru_evict_data                  4    0
mru_evict_metadata              4    245248
mru_ghost_size                  4    0
mru_ghost_evict_data            4    0
mru_ghost_evict_metadata        4    0
mfu_size                        4    1024
mfu_evict_data                  4    0
mfu_evict_metadata              4    1024
mfu_ghost_size                  4    0
mfu_ghost_evict_data            4    0
mfu_ghost_evict_metadata        4    0
l2_hits                         4    0
l2_misses                       4    0
l2_feeds                        4    0
l2_rw_clash                     4    0
l2_read_bytes                   4    0
l2_write_bytes                  4    0
l2_writes_sent                  4    0
l2_writes_done                  4    0
l2_writes_error                 4    0
l2_writes_hdr_miss              4    0
l2_evict_lock_retry             4    0
l2_evict_reading                4    0
l2_free_on_write                4    0
l2_abort_lowmem                 4    0
l2_cksum_bad                    4    0
l2_io_error                     4    0
l2_size                         4    0
l2_asize                        4    0
l2_hdr_size                     4    0
l2_compress_successes           4    0
l2_compress_zeros               4    0
l2_compress_failures            4    0
memory_throttle_count           4    0
duplicate_buffers               4    0
duplicate_buffers_size          4    0
duplicate_reads                 4    0
memory_direct_count             4    0
memory_indirect_count           4    0
arc_no_grow                     4    0
arc_tempreserve                 4    0
arc_loaned_bytes                4    0
arc_prune                       4    0
arc_meta_used                   4    485040
arc_meta_limit                  4    38003076096
arc_meta_max                    4    321168

$ free
             total       used       free     shared    buffers     cached
Mem:      98966344    1747076   97219268       1292      14424      31512
-/+ buffers/cache:    1701140   97265204
Swap:      3553532          0    3553532

[behlendorf]

Thanks for the report.

[jpecar]

Also observed on el7 kernel 3.10.0-123.13.2.el7.x86_64 with recent build v0.6.3-165_g2d9d57b

[chrisrd]

See comment on drop_caches by @dweeezil in #420 (comment)

As to drop_caches, on a sufficiently busy system, it is certainly possible for it to hang or take a very long time. Its worker function is drop_slab() from fs/drop_caches.c and it does this:

   do {
           nr_objects = shrink_slab(&shrink, 1000, 1000);
   } while (nr_objects > 10);

So long as the total number of objects freed is greater than 10, it keeps looping. With XFS, ZFS, etc. in your system, there are likely quite a few registered shrinkers and they're likely freeing something.

I.e. the general advice around on the interwebs to issue drop_caches to alleviate memory issues should be "considered dangerous".

[mickg10]

I can reproduce this on Ubuntu Trusty,

Linux host 3.13.0-45-generic #74-Ubuntu SMP Tue Jan 13 19:36:28 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

libzfs2 0.6.3-5~trusty
mountall 2.53-zfs1
ubuntu-zfs 8~trusty
zfs-auto-snapshot 1.1.0-0ubuntu1~trusty
zfs-dkms 0.6.3-5~trusty
zfs-doc 0.6.3-5~trusty
zfsutils 0.6.3-5~trusty
zfswatcher 0.03-2

Interestingly, the echo command cannot be even interrupted with a kill -9

[dweeezil]

It looks like the 0.6.3-5~trusty release is missing openzfs/zfs@3c832b8 which should make drop_caches a lot safer and actually cause it to do something.

That said, I still think using drop_caches is not a Good Idea as indicated by my comments referred to above.

[mickg10]

I agree with you. The problem is: openzfs/zfs#3085 - the ticket I submitted regarding runaway RAM usage. Hence the drop_caches attempt.

I just tried restarting the system with a grossly undersized ARC - 3GB. Let's see what happens.

[pmwoodward3]

I can anecdotally confirm that I've seen this hang happen before with drop_caches (~3.16 Ubuntu & Debian).

20-30 seconds hang is what i've experienced.

[snajpa]

Also reproducible on recent RHEL6 + OpenVZ kernels. Under heavier load, drop_caches never finishes and ARC tries to shrink to 0 infinitely.

[darkpixel]

It's not just Ubuntu/Trusty, I hit this on Debian 8.2.

root@kvm2:~# lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux 8.2 (jessie)
Release:    8.2
Codename:   jessie
root@kvm2:~# uname -r
3.16.0-4-amd64
root@kvm2:~# 

[behlendorf]

If this is still an issue with a current version let's reopen this issue on the zfs tracker.