Slow unlink #458

behlendorf · 2011-11-21T23:30:24Z

Currently, I dd'd /dev/urandom to a 1M file, and then duplicated that in another file up to the size of 1T. I then rm'd the 1T file, and things didn't seem too bad, except for the load on the system during and shortly after the remove. The load averages jumped way up, but now as I am writing this, they are dropping down to levels that I would think are normal (0.15, 6.22, 15.02).

Some output from top taken shortly after the rm completed:

top - 10:46:18 up 1 day, 14:15,  3 users,  load average: 97.69, 66.12, 30.48
Tasks: 592 total,  92 running, 500 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.1%us, 99.7%sy,  0.0%ni,  0.2%id,  0.0%wa,  0.0%hi,  0.0%si, 0.0%st
Mem:  24599424k total, 11533504k used, 13065920k free,     1312k buffers
Swap:        0k total,        0k used,        0k free,   143948k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
10153 root       0 -20     0    0    0 R 99.7  0.0  14:11.85 txg_sync
 9980 root      39  19     0    0    0 R 18.2  0.0   0:43.47 z_fr_iss/26
10000 root      39  19     0    0    0 R 18.2  0.0   1:18.53 z_fr_iss/46
10041 root      39  19     0    0    0 R 18.2  0.0   1:19.05 z_fr_iss/87
 9997 root      39  19     0    0    0 R 17.8  0.0   1:18.76 z_fr_iss/43
10011 root      39  19     0    0    0 R 17.8  0.0   1:08.75 z_fr_iss/57

There were many more z_fs_iss processes active, I would imagine those processes are what caused the load to skyrocket like it did (possibly processes waiting on disks?).

# zeno1 /mnt > time rm bigdata

real    0m27.420s
user    0m0.000s
sys     0m3.586s

# zeno1 /mnt > zpool status
  pool: tank
 state: ONLINE
 scan: none requested
config:

        NAME        STATE     READ WRITE CKSUM
        tank        ONLINE       0     0     0
          sda       ONLINE       0     0     0
          sdb       ONLINE       0     0     0
          sdc       ONLINE       0     0     0
          sdd       ONLINE       0     0     0
          sde       ONLINE       0     0     0
          sdf       ONLINE       0     0     0
          sdg       ONLINE       0     0     0
          sdh       ONLINE       0     0     0
          sdi       ONLINE       0     0     0
          sdj       ONLINE       0     0     0
          sdk       ONLINE       0     0     0
          sdl       ONLINE       0     0     0
          sdm       ONLINE       0     0     0
          sdn       ONLINE       0     0     0
          sdo       ONLINE       0     0     0
          sdp       ONLINE       0     0     0
          sdq       ONLINE       0     0     0
          sdr       ONLINE       0     0     0
          sds       ONLINE       0     0     0
          sdt       ONLINE       0     0     0
          sdu       ONLINE       0     0     0
          sdv       ONLINE       0     0     0
          sdw       ONLINE       0     0     0
          sdx       ONLINE       0     0     0
          sdy       ONLINE       0     0     0
          sdz       ONLINE       0     0     0

errors: No known data errors

# zeno1 /mnt > zpool iostat -v
               capacity     operations    bandwidth
pool        alloc   free   read  write   read  write
----------  -----  -----  -----  -----  -----  -----
tank        1.00T  42.6T      1    186  95.7K  22.7M
  sda       32.3G  27.2G      0      6  3.68K   776K
  sdb       40.1G  1.77T      0      7  3.59K   905K
  sdc       40.1G  1.77T      0      7  3.63K   904K
  sdd       40.0G  1.77T      0      7  3.68K   904K
  sde       40.1G  1.77T      0      7  3.72K   904K
  sdf       40.1G  1.77T      0      7  3.68K   904K
  sdg       40.1G  1.77T      0      7  3.66K   904K
  sdh       40.1G  1.77T      0      7  3.76K   904K
  sdi       40.0G  1.77T      0      7  3.72K   904K
  sdj       40.1G  1.77T      0      7  3.72K   904K
  sdk       40.0G  1.77T      0      7  3.71K   904K
  sdl       40.1G  1.77T      0      7  3.76K   904K
  sdm       40.0G  1.77T      0      7  3.77K   904K
  sdn       40.0G  1.77T      0      7  3.69K   904K
  sdo       40.0G  1.77T      0      7  3.66K   903K
  sdp       32.3G  27.2G      0      6  3.60K   776K
  sdq       40.1G  1.77T      0      7  3.66K   905K
  sdr       40.1G  1.77T      0      7  3.71K   905K
  sds       40.0G  1.77T      0      7  3.70K   904K
  sdt       40.1G  1.77T      0      7  3.71K   904K
  sdu       40.1G  1.77T      0      7  3.70K   904K
  sdv       40.0G  1.77T      0      7  3.63K   904K
  sdw       40.1G  1.77T      0      7  3.65K   905K
  sdx       40.1G  1.77T      0      7  3.64K   904K
  sdy       40.0G  1.77T      0      7  3.62K   904K
  sdz       40.0G  1.77T      0      7  3.67K   903K
----------  -----  -----  -----  -----  -----  -----

Here's some output from perf top, while zfs is doings it's thing trying to remove a 1TB file:

              samples  pcnt function                     DSO
              _______ _____ ____________________________ _________________
 
            231454.00 91.1% _spin_lock_irqsave           [kernel.kallsyms]
              2588.00  1.0% update_curr                  [kernel.kallsyms]
              1952.00  0.8% schedule                     [kernel.kallsyms]
              1907.00  0.8% task_rq_lock                 [kernel.kallsyms]
              1467.00  0.6% _spin_lock                   [kernel.kallsyms]
              1384.00  0.5% thread_generic_wrapper       [spl]
              1304.00  0.5% __wake_up_common             [kernel.kallsyms]

Looks to be a locking issue to me.

behlendorf · 2011-11-21T23:34:11Z

Indeed. Now the question is where exactly is this lock being taken. The Linux kernel does have some lock profiling code which could help run this down. However, I have a few educated guesses which might speed up the search.

The offending function here is spin_lock_irqsave() which is only used sparingly in the spl. The only real consumers are the spl taskq and slab implementations because they need to briefly disable interrupts. Of those two options I would first suspect the taskq.

As we were talking about last week the taskq currently funnels all entries through the tq->tq_lock. Contention on this lock would look exactly like what your describing. If the unlink call path dispatches a lot of entries to the taskq for large files this would explain it.

The fix would be to improve the taskq implementation as we discussed to use per-cpu pending and priority lists. Alternately, there may be a way on the zfs side to avoid using taskqs entirely. Here's a link to the open spl issue:

openzfs/spl#32

Anyway, the first thing to do would be to verify that this is in fact the case. It might be easiest just to add some debug code to the spl taskq code to see if this is happening.

prakashsurya · 2011-11-22T00:40:22Z

Here's some output from the console during one of my large file unlink tests:

2011-11-21 09:15:17 INFO: task rm:13304 blocked for more than 120 seconds.
2011-11-21 09:15:17 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
2011-11-21 09:15:17 rm            D 0000000000000004     0 13304   7745 0x00000000
2011-11-21 09:15:17  ffff8801e1305a98 0000000000000086 00000002e1305a28 0000000000000001
2011-11-21 09:15:17  0000000000000002 0000000000000082 0000000000000001 ffff88030f0d9da0
2011-11-21 09:15:17  ffff88031c1070f8 ffff8801e1305fd8 000000000000f598 ffff88031c1070f8
2011-11-21 09:15:17 Call Trace:
2011-11-21 09:15:17  [] ? prepare_to_wait_exclusive+0x4e/0x80
2011-11-21 09:15:17  [] cv_wait_common+0x78/0xe0 [spl]
2011-11-21 09:15:17  [] ? autoremove_wake_function+0x0/0x40
2011-11-21 09:15:17  [] __cv_wait+0x13/0x20 [spl]
2011-11-21 09:15:17  [] txg_wait_open+0x7b/0xa0 [zfs]
2011-11-21 09:15:17  [] dmu_tx_wait+0xed/0xf0 [zfs]
2011-11-21 09:15:17  [] dmu_tx_assign+0x6a/0x410 [zfs]
2011-11-21 09:15:17  [] dmu_free_long_range_impl+0x1a6/0x260 [zfs]
2011-11-21 09:15:17  [] dmu_free_long_range+0x4b/0x70 [zfs]
2011-11-21 09:15:17  [] zfs_rmnode+0x60/0x340 [zfs]
2011-11-21 09:15:17  [] zfs_zinactive+0xa8/0x110 [zfs]
2011-11-21 09:15:17  [] zfs_inactive+0x6d/0x1e0 [zfs]
2011-11-21 09:15:17  [] ? unmap_mapping_range+0x72/0x150
2011-11-21 09:15:17  [] ? zpl_inode_delete+0x0/0x70 [zfs]
2011-11-21 09:15:17  [] zpl_clear_inode+0xe/0x10 [zfs]
2011-11-21 09:15:17  [] clear_inode+0x8f/0x110
2011-11-21 09:15:17  [] zpl_inode_delete+0x62/0x70 [zfs]
2011-11-21 09:15:17  [] generic_delete_inode+0xde/0x1d0
2011-11-21 09:15:17  [] generic_drop_inode+0x65/0x80
2011-11-21 09:15:17  [] iput+0x62/0x70
2011-11-21 09:15:17  [] do_unlinkat+0x112/0x1c0
2011-11-21 09:15:17  [] ? do_page_fault+0x3e/0xa0
2011-11-21 09:15:17  [] sys_unlinkat+0x22/0x40
2011-11-21 09:15:17  [] system_call_fastpath+0x16/0x1b
2011-11-21 09:15:17 Nov 21 09:15:17 zeno1 kernel: [ffffa35b> _vwi+x302 sl

When a single work item is dispatched we only need to wake up one thread to service it. The current taskq implementation uses non-exclusive processes in the work wait queue, so every thread in the queue gets woken up when __taskq_dispatch() calls wake_up(). This overhead can become non-negligible as the number of threads in the queue increases, particularly when a large number of short work items are being dispatched. For example, this scenario appears to have led to poor unlink performance in ZFS as described in Issues openzfs/zfs#458 and openzfs/zfs#258. To optimize this case, use add_wait_queue_exclusive() to add threads to the work queue so only one is woken up at a time.

As described in Issue openzfs#458 and openzfs#258, unlinking large amounts of data can cause the threads in the zio free wait queue to start spinning. Reducing the number of z_fr_iss threads from a fixed value of 100 to 1 per cpu signficantly reduces contention on the taskq spinlock and improves throughput. Instrumenting the taskq code showed that __taskq_dispatch() can spend a long time holding tq->tq_lock if there are a large number of threads in the queue. It turns out the time spent in wake_up() scales linearly with the number of threads in the queue. When a large number of short work items are dispatched, as seems to be the case with unlink, the worker threads drain the queue faster than the dispatcher can fill it. They then all pile into the work wait queue to wait for new work items. So if 100 threads are in the queue, wake_up() takes about 100 times as long, and the woken threads have to spin until the dispatcher releases the lock. Reducing the number of threads helps with the symptoms, but doesn't get to the root of the problem. It would seem that wake_up() shouldn't scale linearly in time with queue depth, particularly if we are only trying to wake up one thread. In that vein, I tried making all of the waiting processes exclusive to prevent the scheduler from iterating over the entire list, but I still saw the linear time scaling. So further investigation is needed, but in the meantime reducing the thread count is an easy workaround.

As described in Issue #458 and #258, unlinking large amounts of data can cause the threads in the zio free wait queue to start spinning. Reducing the number of z_fr_iss threads from a fixed value of 100 to 1 per cpu signficantly reduces contention on the taskq spinlock and improves throughput. Instrumenting the taskq code showed that __taskq_dispatch() can spend a long time holding tq->tq_lock if there are a large number of threads in the queue. It turns out the time spent in wake_up() scales linearly with the number of threads in the queue. When a large number of short work items are dispatched, as seems to be the case with unlink, the worker threads drain the queue faster than the dispatcher can fill it. They then all pile into the work wait queue to wait for new work items. So if 100 threads are in the queue, wake_up() takes about 100 times as long, and the woken threads have to spin until the dispatcher releases the lock. Reducing the number of threads helps with the symptoms, but doesn't get to the root of the problem. It would seem that wake_up() shouldn't scale linearly in time with queue depth, particularly if we are only trying to wake up one thread. In that vein, I tried making all of the waiting processes exclusive to prevent the scheduler from iterating over the entire list, but I still saw the linear time scaling. So further investigation is needed, but in the meantime reducing the thread count is an easy workaround. Signed-off-by: Brian Behlendorf <[email protected]> Issue #258 Issue #458

behlendorf · 2012-01-17T18:39:03Z

Merged in to master as commit 08d08eb , we can track the remaining spl taskq optimization work under openzfs/spl#32

The below excerpt of a backtrace is from a ztest failure when running ZoL's ztest. /openzfs#453 0x00007f03c8060b35 in vdev_queue_io_to_issue (vq=vq@entry=0x99f8a8) at ../../module/zfs/vdev_queue.c:706 /openzfs#454 0x00007f03c806106e in vdev_queue_io (zio=zio@entry=0x7f0350003de0) at ../../module/zfs/vdev_queue.c:747 /openzfs#455 0x00007f03c80818c1 in zio_vdev_io_start (zio=0x7f0350003de0) at ../../module/zfs/zio.c:2659 /openzfs#456 0x00007f03c807f243 in __zio_execute (zio=0x7f0350003de0) at ../../module/zfs/zio.c:1399 /openzfs#457 zio_nowait (zio=0x7f0350003de0) at ../../module/zfs/zio.c:1456 /openzfs#458 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350003a10) at ../../module/zfs/vdev_mirror.c:374 /openzfs#459 0x00007f03c807f243 in __zio_execute (zio=0x7f0350003a10) at ../../module/zfs/zio.c:1399 /openzfs#460 zio_nowait (zio=0x7f0350003a10) at ../../module/zfs/zio.c:1456 /openzfs#461 0x00007f03c806464c in vdev_raidz_io_start (zio=0x7f0350003380) at ../../module/zfs/vdev_raidz.c:1607 /openzfs#462 0x00007f03c807f243 in __zio_execute (zio=0x7f0350003380) at ../../module/zfs/zio.c:1399 /openzfs#463 zio_nowait (zio=0x7f0350003380) at ../../module/zfs/zio.c:1456 /openzfs#464 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350002fb0) at ../../module/zfs/vdev_mirror.c:374 /openzfs#465 0x00007f03c807f243 in __zio_execute (zio=0x7f0350002fb0) at ../../module/zfs/zio.c:1399 /openzfs#466 zio_nowait (zio=0x7f0350002fb0) at ../../module/zfs/zio.c:1456 /openzfs#467 0x00007f03c805ed43 in vdev_mirror_io_done (zio=0x7f033957ebf0) at ../../module/zfs/vdev_mirror.c:499 /openzfs#468 0x00007f03c807a0c0 in zio_vdev_io_done (zio=0x7f033957ebf0) at ../../module/zfs/zio.c:2707 /openzfs#469 0x00007f03c808285b in __zio_execute (zio=0x7f033957ebf0) at ../../module/zfs/zio.c:1399 /openzfs#470 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f0390001330, pio=0x7f033957ebf0) at ../../module/zfs/zio.c:547 /openzfs#471 zio_done (zio=0x7f0390001330) at ../../module/zfs/zio.c:3278 /openzfs#472 0x00007f03c808285b in __zio_execute (zio=0x7f0390001330) at ../../module/zfs/zio.c:1399 /openzfs#473 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03b4013a00, pio=0x7f0390001330) at ../../module/zfs/zio.c:547 /openzfs#474 zio_done (zio=0x7f03b4013a00) at ../../module/zfs/zio.c:3278 /openzfs#475 0x00007f03c808285b in __zio_execute (zio=0x7f03b4013a00) at ../../module/zfs/zio.c:1399 /openzfs#476 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03b4014210, pio=0x7f03b4013a00) at ../../module/zfs/zio.c:547 /openzfs#477 zio_done (zio=0x7f03b4014210) at ../../module/zfs/zio.c:3278 /openzfs#478 0x00007f03c808285b in __zio_execute (zio=0x7f03b4014210) at ../../module/zfs/zio.c:1399 /openzfs#479 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03b4014620, pio=0x7f03b4014210) at ../../module/zfs/zio.c:547 /openzfs#480 zio_done (zio=0x7f03b4014620) at ../../module/zfs/zio.c:3278 /openzfs#481 0x00007f03c807a6d3 in __zio_execute (zio=0x7f03b4014620) at ../../module/zfs/zio.c:1399 /openzfs#482 zio_execute (zio=zio@entry=0x7f03b4014620) at ../../module/zfs/zio.c:1337 /openzfs#483 0x00007f03c8060b35 in vdev_queue_io_to_issue (vq=vq@entry=0x99f8a8) at ../../module/zfs/vdev_queue.c:706 /openzfs#484 0x00007f03c806106e in vdev_queue_io (zio=zio@entry=0x7f0350002be0) at ../../module/zfs/vdev_queue.c:747 /openzfs#485 0x00007f03c80818c1 in zio_vdev_io_start (zio=0x7f0350002be0) at ../../module/zfs/zio.c:2659 /openzfs#486 0x00007f03c807f243 in __zio_execute (zio=0x7f0350002be0) at ../../module/zfs/zio.c:1399 /openzfs#487 zio_nowait (zio=0x7f0350002be0) at ../../module/zfs/zio.c:1456 /openzfs#488 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350002810) at ../../module/zfs/vdev_mirror.c:374 /openzfs#489 0x00007f03c807f243 in __zio_execute (zio=0x7f0350002810) at ../../module/zfs/zio.c:1399 /openzfs#490 zio_nowait (zio=0x7f0350002810) at ../../module/zfs/zio.c:1456 /openzfs#491 0x00007f03c8064593 in vdev_raidz_io_start (zio=0x7f0350001270) at ../../module/zfs/vdev_raidz.c:1591 /openzfs#492 0x00007f03c807f243 in __zio_execute (zio=0x7f0350001270) at ../../module/zfs/zio.c:1399 /openzfs#493 zio_nowait (zio=0x7f0350001270) at ../../module/zfs/zio.c:1456 /openzfs#494 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350001e60) at ../../module/zfs/vdev_mirror.c:374 /openzfs#495 0x00007f03c807f243 in __zio_execute (zio=0x7f0350001e60) at ../../module/zfs/zio.c:1399 /openzfs#496 zio_nowait (zio=0x7f0350001e60) at ../../module/zfs/zio.c:1456 /openzfs#497 0x00007f03c805ed43 in vdev_mirror_io_done (zio=0x7f033a0c39c0) at ../../module/zfs/vdev_mirror.c:499 /openzfs#498 0x00007f03c807a0c0 in zio_vdev_io_done (zio=0x7f033a0c39c0) at ../../module/zfs/zio.c:2707 /openzfs#499 0x00007f03c808285b in __zio_execute (zio=0x7f033a0c39c0) at ../../module/zfs/zio.c:1399 /openzfs#500 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03a8003c00, pio=0x7f033a0c39c0) at ../../module/zfs/zio.c:547 /openzfs#501 zio_done (zio=0x7f03a8003c00) at ../../module/zfs/zio.c:3278 /openzfs#502 0x00007f03c808285b in __zio_execute (zio=0x7f03a8003c00) at ../../module/zfs/zio.c:1399 /openzfs#503 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f038800c400, pio=0x7f03a8003c00) at ../../module/zfs/zio.c:547 /openzfs#504 zio_done (zio=0x7f038800c400) at ../../module/zfs/zio.c:3278 /openzfs#505 0x00007f03c808285b in __zio_execute (zio=0x7f038800c400) at ../../module/zfs/zio.c:1399 /openzfs#506 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f038800da00, pio=0x7f038800c400) at ../../module/zfs/zio.c:547 /openzfs#507 zio_done (zio=0x7f038800da00) at ../../module/zfs/zio.c:3278 /openzfs#508 0x00007f03c808285b in __zio_execute (zio=0x7f038800da00) at ../../module/zfs/zio.c:1399 /openzfs#509 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f038800fd80, pio=0x7f038800da00) at ../../module/zfs/zio.c:547 /openzfs#510 zio_done (zio=0x7f038800fd80) at ../../module/zfs/zio.c:3278 /openzfs#511 0x00007f03c807a6d3 in __zio_execute (zio=0x7f038800fd80) at ../../module/zfs/zio.c:1399 /openzfs#512 zio_execute (zio=zio@entry=0x7f038800fd80) at ../../module/zfs/zio.c:1337 /openzfs#513 0x00007f03c8060b35 in vdev_queue_io_to_issue (vq=vq@entry=0x99f8a8) at ../../module/zfs/vdev_queue.c:706 /openzfs#514 0x00007f03c806119d in vdev_queue_io_done (zio=zio@entry=0x7f03a0010950) at ../../module/zfs/vdev_queue.c:775 /openzfs#515 0x00007f03c807a0e8 in zio_vdev_io_done (zio=0x7f03a0010950) at ../../module/zfs/zio.c:2686 /openzfs#516 0x00007f03c807a6d3 in __zio_execute (zio=0x7f03a0010950) at ../../module/zfs/zio.c:1399 /openzfs#517 zio_execute (zio=0x7f03a0010950) at ../../module/zfs/zio.c:1337 /openzfs#518 0x00007f03c7fcd0c4 in taskq_thread (arg=0x966d50) at ../../lib/libzpool/taskq.c:215 /openzfs#519 0x00007f03c7fc7937 in zk_thread_helper (arg=0x967e90) at ../../lib/libzpool/kernel.c:135 /openzfs#520 0x00007f03c78890a3 in start_thread (arg=0x7f03c2703700) at pthread_create.c:309 /openzfs#521 0x00007f03c75c50fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 The backtrace was an infinite loop of `vdev_queue_io_to_issue()` invoking `zio_execute()` until it overran the stack. vdev_queue_io_to_issue() will ony invoke `zio_execute()` on raidz vdevs when aggregation I/Os are generated to improve aggregation continuity. These I/Os do not trigger any writes. However, it appears that they can be generated in such a way that they recurse infinitely upon return to `vdev_queue_io_to_issue()`. As a consequence, we see the number of parents by 1 each time the recursion returns to `vdev_raidz_io_start()`. Signed-off-by: Richard Yao <[email protected]>

The below excerpt of a backtrace is from a ztest failure when running ZoL's ztest. /openzfs#453 0x00007f03c8060b35 in vdev_queue_io_to_issue (vq=vq@entry=0x99f8a8) at ../../module/zfs/vdev_queue.c:706 /openzfs#454 0x00007f03c806106e in vdev_queue_io (zio=zio@entry=0x7f0350003de0) at ../../module/zfs/vdev_queue.c:747 /openzfs#455 0x00007f03c80818c1 in zio_vdev_io_start (zio=0x7f0350003de0) at ../../module/zfs/zio.c:2659 /openzfs#456 0x00007f03c807f243 in __zio_execute (zio=0x7f0350003de0) at ../../module/zfs/zio.c:1399 /openzfs#457 zio_nowait (zio=0x7f0350003de0) at ../../module/zfs/zio.c:1456 /openzfs#458 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350003a10) at ../../module/zfs/vdev_mirror.c:374 /openzfs#459 0x00007f03c807f243 in __zio_execute (zio=0x7f0350003a10) at ../../module/zfs/zio.c:1399 /openzfs#460 zio_nowait (zio=0x7f0350003a10) at ../../module/zfs/zio.c:1456 /openzfs#461 0x00007f03c806464c in vdev_raidz_io_start (zio=0x7f0350003380) at ../../module/zfs/vdev_raidz.c:1607 /openzfs#462 0x00007f03c807f243 in __zio_execute (zio=0x7f0350003380) at ../../module/zfs/zio.c:1399 /openzfs#463 zio_nowait (zio=0x7f0350003380) at ../../module/zfs/zio.c:1456 /openzfs#464 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350002fb0) at ../../module/zfs/vdev_mirror.c:374 /openzfs#465 0x00007f03c807f243 in __zio_execute (zio=0x7f0350002fb0) at ../../module/zfs/zio.c:1399 /openzfs#466 zio_nowait (zio=0x7f0350002fb0) at ../../module/zfs/zio.c:1456 /openzfs#467 0x00007f03c805ed43 in vdev_mirror_io_done (zio=0x7f033957ebf0) at ../../module/zfs/vdev_mirror.c:499 /openzfs#468 0x00007f03c807a0c0 in zio_vdev_io_done (zio=0x7f033957ebf0) at ../../module/zfs/zio.c:2707 /openzfs#469 0x00007f03c808285b in __zio_execute (zio=0x7f033957ebf0) at ../../module/zfs/zio.c:1399 /openzfs#470 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f0390001330, pio=0x7f033957ebf0) at ../../module/zfs/zio.c:547 /openzfs#471 zio_done (zio=0x7f0390001330) at ../../module/zfs/zio.c:3278 /openzfs#472 0x00007f03c808285b in __zio_execute (zio=0x7f0390001330) at ../../module/zfs/zio.c:1399 /openzfs#473 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03b4013a00, pio=0x7f0390001330) at ../../module/zfs/zio.c:547 /openzfs#474 zio_done (zio=0x7f03b4013a00) at ../../module/zfs/zio.c:3278 /openzfs#475 0x00007f03c808285b in __zio_execute (zio=0x7f03b4013a00) at ../../module/zfs/zio.c:1399 /openzfs#476 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03b4014210, pio=0x7f03b4013a00) at ../../module/zfs/zio.c:547 /openzfs#477 zio_done (zio=0x7f03b4014210) at ../../module/zfs/zio.c:3278 /openzfs#478 0x00007f03c808285b in __zio_execute (zio=0x7f03b4014210) at ../../module/zfs/zio.c:1399 /openzfs#479 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03b4014620, pio=0x7f03b4014210) at ../../module/zfs/zio.c:547 /openzfs#480 zio_done (zio=0x7f03b4014620) at ../../module/zfs/zio.c:3278 /openzfs#481 0x00007f03c807a6d3 in __zio_execute (zio=0x7f03b4014620) at ../../module/zfs/zio.c:1399 /openzfs#482 zio_execute (zio=zio@entry=0x7f03b4014620) at ../../module/zfs/zio.c:1337 /openzfs#483 0x00007f03c8060b35 in vdev_queue_io_to_issue (vq=vq@entry=0x99f8a8) at ../../module/zfs/vdev_queue.c:706 /openzfs#484 0x00007f03c806106e in vdev_queue_io (zio=zio@entry=0x7f0350002be0) at ../../module/zfs/vdev_queue.c:747 /openzfs#485 0x00007f03c80818c1 in zio_vdev_io_start (zio=0x7f0350002be0) at ../../module/zfs/zio.c:2659 /openzfs#486 0x00007f03c807f243 in __zio_execute (zio=0x7f0350002be0) at ../../module/zfs/zio.c:1399 /openzfs#487 zio_nowait (zio=0x7f0350002be0) at ../../module/zfs/zio.c:1456 /openzfs#488 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350002810) at ../../module/zfs/vdev_mirror.c:374 /openzfs#489 0x00007f03c807f243 in __zio_execute (zio=0x7f0350002810) at ../../module/zfs/zio.c:1399 /openzfs#490 zio_nowait (zio=0x7f0350002810) at ../../module/zfs/zio.c:1456 /openzfs#491 0x00007f03c8064593 in vdev_raidz_io_start (zio=0x7f0350001270) at ../../module/zfs/vdev_raidz.c:1591 /openzfs#492 0x00007f03c807f243 in __zio_execute (zio=0x7f0350001270) at ../../module/zfs/zio.c:1399 /openzfs#493 zio_nowait (zio=0x7f0350001270) at ../../module/zfs/zio.c:1456 /openzfs#494 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350001e60) at ../../module/zfs/vdev_mirror.c:374 /openzfs#495 0x00007f03c807f243 in __zio_execute (zio=0x7f0350001e60) at ../../module/zfs/zio.c:1399 /openzfs#496 zio_nowait (zio=0x7f0350001e60) at ../../module/zfs/zio.c:1456 /openzfs#497 0x00007f03c805ed43 in vdev_mirror_io_done (zio=0x7f033a0c39c0) at ../../module/zfs/vdev_mirror.c:499 /openzfs#498 0x00007f03c807a0c0 in zio_vdev_io_done (zio=0x7f033a0c39c0) at ../../module/zfs/zio.c:2707 /openzfs#499 0x00007f03c808285b in __zio_execute (zio=0x7f033a0c39c0) at ../../module/zfs/zio.c:1399 /openzfs#500 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03a8003c00, pio=0x7f033a0c39c0) at ../../module/zfs/zio.c:547 /openzfs#501 zio_done (zio=0x7f03a8003c00) at ../../module/zfs/zio.c:3278 /openzfs#502 0x00007f03c808285b in __zio_execute (zio=0x7f03a8003c00) at ../../module/zfs/zio.c:1399 /openzfs#503 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f038800c400, pio=0x7f03a8003c00) at ../../module/zfs/zio.c:547 /openzfs#504 zio_done (zio=0x7f038800c400) at ../../module/zfs/zio.c:3278 /openzfs#505 0x00007f03c808285b in __zio_execute (zio=0x7f038800c400) at ../../module/zfs/zio.c:1399 /openzfs#506 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f038800da00, pio=0x7f038800c400) at ../../module/zfs/zio.c:547 /openzfs#507 zio_done (zio=0x7f038800da00) at ../../module/zfs/zio.c:3278 /openzfs#508 0x00007f03c808285b in __zio_execute (zio=0x7f038800da00) at ../../module/zfs/zio.c:1399 /openzfs#509 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f038800fd80, pio=0x7f038800da00) at ../../module/zfs/zio.c:547 /openzfs#510 zio_done (zio=0x7f038800fd80) at ../../module/zfs/zio.c:3278 /openzfs#511 0x00007f03c807a6d3 in __zio_execute (zio=0x7f038800fd80) at ../../module/zfs/zio.c:1399 /openzfs#512 zio_execute (zio=zio@entry=0x7f038800fd80) at ../../module/zfs/zio.c:1337 /openzfs#513 0x00007f03c8060b35 in vdev_queue_io_to_issue (vq=vq@entry=0x99f8a8) at ../../module/zfs/vdev_queue.c:706 /openzfs#514 0x00007f03c806119d in vdev_queue_io_done (zio=zio@entry=0x7f03a0010950) at ../../module/zfs/vdev_queue.c:775 /openzfs#515 0x00007f03c807a0e8 in zio_vdev_io_done (zio=0x7f03a0010950) at ../../module/zfs/zio.c:2686 /openzfs#516 0x00007f03c807a6d3 in __zio_execute (zio=0x7f03a0010950) at ../../module/zfs/zio.c:1399 /openzfs#517 zio_execute (zio=0x7f03a0010950) at ../../module/zfs/zio.c:1337 /openzfs#518 0x00007f03c7fcd0c4 in taskq_thread (arg=0x966d50) at ../../lib/libzpool/taskq.c:215 /openzfs#519 0x00007f03c7fc7937 in zk_thread_helper (arg=0x967e90) at ../../lib/libzpool/kernel.c:135 /openzfs#520 0x00007f03c78890a3 in start_thread (arg=0x7f03c2703700) at pthread_create.c:309 /openzfs#521 0x00007f03c75c50fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 The backtrace was an infinite loop of `vdev_queue_io_to_issue()` invoking `zio_execute()` until it overran the stack. vdev_queue_io_to_issue() will ony invoke `zio_execute()` on raidz vdevs when aggregation I/Os are generated to improve aggregation continuity. These I/Os do not trigger any writes. However, it appears that they can be generated in such a way that they recurse infinitely upon return to `vdev_queue_io_to_issue()`. Signed-off-by: Richard Yao <[email protected]>

The below excerpt of a backtrace is from a ztest failure when running ZoL's ztest: /openzfs#453 0x00007f03c8060b35 in vdev_queue_io_to_issue (vq=vq@entry=0x99f8a8) at ../../module/zfs/vdev_queue.c:706 /openzfs#454 0x00007f03c806106e in vdev_queue_io (zio=zio@entry=0x7f0350003de0) at ../../module/zfs/vdev_queue.c:747 /openzfs#455 0x00007f03c80818c1 in zio_vdev_io_start (zio=0x7f0350003de0) at ../../module/zfs/zio.c:2659 /openzfs#456 0x00007f03c807f243 in __zio_execute (zio=0x7f0350003de0) at ../../module/zfs/zio.c:1399 /openzfs#457 zio_nowait (zio=0x7f0350003de0) at ../../module/zfs/zio.c:1456 /openzfs#458 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350003a10) at ../../module/zfs/vdev_mirror.c:374 /openzfs#459 0x00007f03c807f243 in __zio_execute (zio=0x7f0350003a10) at ../../module/zfs/zio.c:1399 /openzfs#460 zio_nowait (zio=0x7f0350003a10) at ../../module/zfs/zio.c:1456 /openzfs#461 0x00007f03c806464c in vdev_raidz_io_start (zio=0x7f0350003380) at ../../module/zfs/vdev_raidz.c:1607 /openzfs#462 0x00007f03c807f243 in __zio_execute (zio=0x7f0350003380) at ../../module/zfs/zio.c:1399 /openzfs#463 zio_nowait (zio=0x7f0350003380) at ../../module/zfs/zio.c:1456 /openzfs#464 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350002fb0) at ../../module/zfs/vdev_mirror.c:374 /openzfs#465 0x00007f03c807f243 in __zio_execute (zio=0x7f0350002fb0) at ../../module/zfs/zio.c:1399 /openzfs#466 zio_nowait (zio=0x7f0350002fb0) at ../../module/zfs/zio.c:1456 /openzfs#467 0x00007f03c805ed43 in vdev_mirror_io_done (zio=0x7f033957ebf0) at ../../module/zfs/vdev_mirror.c:499 /openzfs#468 0x00007f03c807a0c0 in zio_vdev_io_done (zio=0x7f033957ebf0) at ../../module/zfs/zio.c:2707 /openzfs#469 0x00007f03c808285b in __zio_execute (zio=0x7f033957ebf0) at ../../module/zfs/zio.c:1399 /openzfs#470 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f0390001330, pio=0x7f033957ebf0) at ../../module/zfs/zio.c:547 /openzfs#471 zio_done (zio=0x7f0390001330) at ../../module/zfs/zio.c:3278 /openzfs#472 0x00007f03c808285b in __zio_execute (zio=0x7f0390001330) at ../../module/zfs/zio.c:1399 /openzfs#473 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03b4013a00, pio=0x7f0390001330) at ../../module/zfs/zio.c:547 /openzfs#474 zio_done (zio=0x7f03b4013a00) at ../../module/zfs/zio.c:3278 /openzfs#475 0x00007f03c808285b in __zio_execute (zio=0x7f03b4013a00) at ../../module/zfs/zio.c:1399 /openzfs#476 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03b4014210, pio=0x7f03b4013a00) at ../../module/zfs/zio.c:547 /openzfs#477 zio_done (zio=0x7f03b4014210) at ../../module/zfs/zio.c:3278 /openzfs#478 0x00007f03c808285b in __zio_execute (zio=0x7f03b4014210) at ../../module/zfs/zio.c:1399 /openzfs#479 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03b4014620, pio=0x7f03b4014210) at ../../module/zfs/zio.c:547 /openzfs#480 zio_done (zio=0x7f03b4014620) at ../../module/zfs/zio.c:3278 /openzfs#481 0x00007f03c807a6d3 in __zio_execute (zio=0x7f03b4014620) at ../../module/zfs/zio.c:1399 /openzfs#482 zio_execute (zio=zio@entry=0x7f03b4014620) at ../../module/zfs/zio.c:1337 /openzfs#483 0x00007f03c8060b35 in vdev_queue_io_to_issue (vq=vq@entry=0x99f8a8) at ../../module/zfs/vdev_queue.c:706 /openzfs#484 0x00007f03c806106e in vdev_queue_io (zio=zio@entry=0x7f0350002be0) at ../../module/zfs/vdev_queue.c:747 /openzfs#485 0x00007f03c80818c1 in zio_vdev_io_start (zio=0x7f0350002be0) at ../../module/zfs/zio.c:2659 /openzfs#486 0x00007f03c807f243 in __zio_execute (zio=0x7f0350002be0) at ../../module/zfs/zio.c:1399 /openzfs#487 zio_nowait (zio=0x7f0350002be0) at ../../module/zfs/zio.c:1456 /openzfs#488 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350002810) at ../../module/zfs/vdev_mirror.c:374 /openzfs#489 0x00007f03c807f243 in __zio_execute (zio=0x7f0350002810) at ../../module/zfs/zio.c:1399 /openzfs#490 zio_nowait (zio=0x7f0350002810) at ../../module/zfs/zio.c:1456 /openzfs#491 0x00007f03c8064593 in vdev_raidz_io_start (zio=0x7f0350001270) at ../../module/zfs/vdev_raidz.c:1591 /openzfs#492 0x00007f03c807f243 in __zio_execute (zio=0x7f0350001270) at ../../module/zfs/zio.c:1399 /openzfs#493 zio_nowait (zio=0x7f0350001270) at ../../module/zfs/zio.c:1456 /openzfs#494 0x00007f03c805f71b in vdev_mirror_io_start (zio=0x7f0350001e60) at ../../module/zfs/vdev_mirror.c:374 /openzfs#495 0x00007f03c807f243 in __zio_execute (zio=0x7f0350001e60) at ../../module/zfs/zio.c:1399 /openzfs#496 zio_nowait (zio=0x7f0350001e60) at ../../module/zfs/zio.c:1456 /openzfs#497 0x00007f03c805ed43 in vdev_mirror_io_done (zio=0x7f033a0c39c0) at ../../module/zfs/vdev_mirror.c:499 /openzfs#498 0x00007f03c807a0c0 in zio_vdev_io_done (zio=0x7f033a0c39c0) at ../../module/zfs/zio.c:2707 /openzfs#499 0x00007f03c808285b in __zio_execute (zio=0x7f033a0c39c0) at ../../module/zfs/zio.c:1399 /openzfs#500 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f03a8003c00, pio=0x7f033a0c39c0) at ../../module/zfs/zio.c:547 /openzfs#501 zio_done (zio=0x7f03a8003c00) at ../../module/zfs/zio.c:3278 /openzfs#502 0x00007f03c808285b in __zio_execute (zio=0x7f03a8003c00) at ../../module/zfs/zio.c:1399 /openzfs#503 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f038800c400, pio=0x7f03a8003c00) at ../../module/zfs/zio.c:547 /openzfs#504 zio_done (zio=0x7f038800c400) at ../../module/zfs/zio.c:3278 /openzfs#505 0x00007f03c808285b in __zio_execute (zio=0x7f038800c400) at ../../module/zfs/zio.c:1399 /openzfs#506 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f038800da00, pio=0x7f038800c400) at ../../module/zfs/zio.c:547 /openzfs#507 zio_done (zio=0x7f038800da00) at ../../module/zfs/zio.c:3278 /openzfs#508 0x00007f03c808285b in __zio_execute (zio=0x7f038800da00) at ../../module/zfs/zio.c:1399 /openzfs#509 zio_notify_parent (wait=ZIO_WAIT_DONE, zio=0x7f038800fd80, pio=0x7f038800da00) at ../../module/zfs/zio.c:547 /openzfs#510 zio_done (zio=0x7f038800fd80) at ../../module/zfs/zio.c:3278 /openzfs#511 0x00007f03c807a6d3 in __zio_execute (zio=0x7f038800fd80) at ../../module/zfs/zio.c:1399 /openzfs#512 zio_execute (zio=zio@entry=0x7f038800fd80) at ../../module/zfs/zio.c:1337 /openzfs#513 0x00007f03c8060b35 in vdev_queue_io_to_issue (vq=vq@entry=0x99f8a8) at ../../module/zfs/vdev_queue.c:706 /openzfs#514 0x00007f03c806119d in vdev_queue_io_done (zio=zio@entry=0x7f03a0010950) at ../../module/zfs/vdev_queue.c:775 /openzfs#515 0x00007f03c807a0e8 in zio_vdev_io_done (zio=0x7f03a0010950) at ../../module/zfs/zio.c:2686 /openzfs#516 0x00007f03c807a6d3 in __zio_execute (zio=0x7f03a0010950) at ../../module/zfs/zio.c:1399 /openzfs#517 zio_execute (zio=0x7f03a0010950) at ../../module/zfs/zio.c:1337 /openzfs#518 0x00007f03c7fcd0c4 in taskq_thread (arg=0x966d50) at ../../lib/libzpool/taskq.c:215 /openzfs#519 0x00007f03c7fc7937 in zk_thread_helper (arg=0x967e90) at ../../lib/libzpool/kernel.c:135 /openzfs#520 0x00007f03c78890a3 in start_thread (arg=0x7f03c2703700) at pthread_create.c:309 /openzfs#521 0x00007f03c75c50fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 This occurred when ztest was simulating a scrub under heavy I/O load. Under those circumstances, it was possible for a mix of noop I/Os for aggregation continuity and the I/O elevator to generate arbitrarily deep recursion. This patch modifies ZFS to propapage a recursion counter inside the zio_t objects such that IOs will be redispatched upon reaching a given recursion depth. We can detect long call chains and dispatch to another ZIO taskq. We cut in-line when we do this to minimize the potential for taskq exhaustion that can prevent a zio from notifying its parent. Signed-off-by: Richard Yao <[email protected]>

Setting the TASKQ_DYNAMIC flag will create a taskq with dynamic semantics. Initially only a single worker thread will be created to service tasks dispatched to the queue. As additional threads are needed they will be dynamically spawned up to the max number specified by 'nthreads'. When the threads are no longer needed, because the taskq is empty, they will automatically terminate. Due to the low cost of creating and destroying threads under Linux by default new threads and spawned and terminated aggressively. There are two modules options which can be tuned to adjust this behavior if needed. * spl_taskq_thread_sequential - The number of sequential tasks, without interruption, which needed to be handled by a worker thread before a new worker thread is spawned. Default 4. * spl_taskq_thread_dynamic - Provides the ability to completely disable the use of dynamic taskqs on the system. This is provided for the purposes of debugging and troubleshooting. Default 1 (enabled). This behavior is fundamentally consistent with the dynamic taskq implementation found in both illumos and FreeBSD. Signed-off-by: Brian Behlendorf <[email protected]> Signed-off-by: Tim Chase <[email protected]> Closes openzfs#458

Add the TASKQ_DYNAMIC flag to the kmem_cache and system taskqs to reduce the number of idle threads on the system. Additional threads will be created on demand up to the previous maximum thread counts. This should have minimal, if any, impact on performance. This makes the system taskq consistent with illumos which is always created as a dynamic taskq with up to 64 threads. The task limits for the kmem_cache have been increased to avoid any unnessisary throttling and to keep a larger reserve of task_t structures on the free list. Signed-off-by: Brian Behlendorf <[email protected]> Signed-off-by: Tim Chase <[email protected]> Closes openzfs#458

We should not be relying on the NvList to be Sync, as it's incorrectly declared to be so (but thankfully our use happens to be safe).

…aster Merge remote-tracking branch '6.0/stage' into 'master'

ghost assigned prakashsurya Nov 21, 2011

ghost assigned nedbass Jan 11, 2012

nedbass mentioned this issue Jan 13, 2012

Reduce number of zio free threads #534

Closed

behlendorf closed this as completed Jan 17, 2012

ryao mentioned this issue Oct 9, 2014

vdev_raidz_io_start: Ignore empty writes #2778

Closed

ryao mentioned this issue Oct 10, 2014

Redispatch ZIOs in deep call graphs #2786

Closed

behlendorf unassigned nedbass Feb 25, 2020

ahrens added a commit to ahrens/zfs that referenced this issue Sep 23, 2021

NvList is not Sync (openzfs#458)

be7664c

We should not be relying on the NvList to be Sync, as it's incorrectly declared to be so (but thankfully our use happens to be safe).

pcd1193182 pushed a commit to pcd1193182/zfs that referenced this issue Sep 26, 2023

Merge pull request openzfs#458 from delphix/projects/merge-upstream/m…

b9309f7

…aster Merge remote-tracking branch '6.0/stage' into 'master'

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Slow unlink #458

Slow unlink #458

behlendorf commented Nov 21, 2011

behlendorf commented Nov 21, 2011

prakashsurya commented Nov 22, 2011

behlendorf commented Jan 17, 2012

Slow unlink #458

Slow unlink #458

Comments

behlendorf commented Nov 21, 2011

behlendorf commented Nov 21, 2011

prakashsurya commented Nov 22, 2011

behlendorf commented Jan 17, 2012