Project

General

Profile

Bug #3581

spa_zio_taskq[ZIO_TYPE_FREE][ZIO_TASKQ_ISSUE]->tq_lock is piping hot

Added by Christopher Siden over 6 years ago. Updated over 6 years ago.

Status:
Closed
Priority:
Normal
Category:
zfs - Zettabyte File System
Start date:
2013-02-19
Due date:
% Done:

100%

Estimated time:
Difficulty:
Medium
Tags:
needs-triage

Description

From Adam Leventhal's original bug report at Delphix:

On a system I collected lockstat data that featured
spa_zio_taskq[ZIO_TYPE_FREE][ZIO_TASKQ_ISSUE]->tq_lock prominently:

> ffffff0d2b686ac0::print spa_t spa_zio_taskq
spa_zio_taskq = [
    [ 0xffffff0d49cb5a20, 0, 0xffffff0d49cb5b38, 0 ]
    [ 0xffffff0d4abffa28, 0, 0xffffff0d4abff910, 0 ]
    [ 0xffffff0d4abff7f8, 0xffffff0d4abff6e0, 0xffffff0d4abff5c8,
0xffffff0d4abff4b0 ]
    [ 0xffffff0d4abff398, 0, 0xffffff0d4abff280, 0 ]
    [ 0xffffff0d4abff168, 0, 0xffffff0d4abff050, 0 ]
    [ 0xffffff0d4cb3be90, 0, 0xffffff0d4cb3bd78, 0 ]
]
> 0xffffff0d4abff398::print -at taskq_t tq_lock
ffffff0d4abff3b8 kmutex_t tq_lock = {
    ffffff0d4abff3b8 void *[1] tq_lock._opaque = [ 0 ]
}

-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Lock                   Caller
126959  10%  10% 0.00    75181 0xffffff0d4abff3b8     taskq_thread+0x2a8

      nsec ------ Time Distribution ------ count     Stack
       512 |                               892       thread_start+0x8
      1024 |                               2601
      2048 |@@                             8900
      4096 |@@@@@@                         29035
      8192 |@@@@@@@@@@@@                   52341
     16384 |@@                             11731
     32768 |@                              4311
     65536 |                               2937
    131072 |                               2203
    262144 |                               3200
    524288 |                               3637
   1048576 |                               3106
   2097152 |                               1598
   4194304 |                               386
   8388608 |                               45
  16777216 |                               21
  33554432 |                               10
  67108864 |                               5
-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Lock                   Caller
113743   9%  28% 0.00   139391 0xffffff0d4abff3b8     cv_wait+0x69

      nsec ------ Time Distribution ------ count     Stack
       512 |                               3354      taskq_thread_wait+0x84
      1024 |@                              5147      taskq_thread+0x308
      2048 |@@@                            11967     thread_start+0x8
      4096 |@@@@                           18832
      8192 |@@@@@@@                        28091
     16384 |@@                             9912
     32768 |@                              4573
     65536 |@                              5445
    131072 |@                              4359
    262144 |@                              6240
    524288 |@                              6736
   1048576 |@                              5684
   2097152 |                               2719
   4194304 |                               567
   8388608 |                               60
  16777216 |                               35
  33554432 |                               13
  67108864 |                               9
-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Lock                   Caller
92798   7%  42% 0.00    33367 0xffffff0d4abff3b8     taskq_dispatch_ent+0x4a

      nsec ------ Time Distribution ------ count     Stack
       512 |                               1773      zio_taskq_dispatch+0xb5
      1024 |                               1119      zio_issue_async+0x19
      2048 |                               871       zio_execute+0x8d
      4096 |@                              6055      zio_nowait+0x42
      8192 |@@@@@@@@@@@@@                  43007     spa_free_sync_cb+0x4d
     16384 |@@@                            9832      bplist_iterate+0x70
     32768 |@@@                            10499     spa_sync+0x40b
     65536 |@@@                            10190     txg_sync_thread+0x247
    131072 |@                              4492      thread_start+0x8
    262144 |@                              3447
    524288 |                               1249
   1048576 |                               219
   2097152 |                               8
   4194304 |                               0
   8388608 |                               28
  16777216 |                               5
  33554432 |                               3
  67108864 |                               1
-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Lock                   Caller
 1752  15%  15% 0.00    95610 0xffffff0d4abff3b8     cv_wait+0x69

      nsec ------ Time Distribution ------ count     Stack
      4096 |                               3         taskq_thread_wait+0x84
      8192 |@@                             142       taskq_thread+0x308
     16384 |@@@@@@@@@@@@                   720       thread_start+0x8
     32768 |@@@@@@@                        461
     65536 |@@@                            199
    131072 |@                              69
    262144 |                               39
    524288 |                               33
   1048576 |                               57
   2097152 |                               15
   4194304 |                               11
   8388608 |                               3
-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Lock                   Caller
 1255  11%  26% 0.00    74830 0xffffff0d4abff3b8     taskq_thread+0x2a8

      nsec ------ Time Distribution ------ count     Stack
      8192 |@                              72        thread_start+0x8
     16384 |@@@@@@@@@@@@                   507
     32768 |@@@@@@@@@                      379
     65536 |@@@                            146
    131072 |@                              54
    262144 |                               33
    524288 |                               26
   1048576 |                               16
   2097152 |                               17
   4194304 |                               4
   8388608 |                               1
-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Lock                   Caller
  641   6%  31% 0.00    41828 0xffffff0d4abff3b8     taskq_dispatch_ent+0x4a

      nsec ------ Time Distribution ------ count     Stack
      8192 |@@                             49        zio_taskq_dispatch+0xb5
     16384 |@@@@@@@@@@@@                   267       zio_issue_async+0x19
     32768 |@@@@@@@@                       180       zio_execute+0x8d
     65536 |@@@@                           93        zio_nowait+0x42
    131072 |@                              25        spa_free_sync_cb+0x4d
    262144 |                               14        bplist_iterate+0x70
    524288 |                               7         spa_sync+0x40b
   1048576 |                               2         txg_sync_thread+0x247
   2097152 |                               3         thread_start+0x8
   4194304 |                               1

It seems likely that we could fan out the number of taskqs -- perhaps we could
have one per-CPU.

The taskq's are defined here:
const zio_taskq_info_t zio_taskqs[ZIO_TYPES][ZIO_TASKQ_TYPES] = {
        /* ISSUE        ISSUE_HIGH      INTR            INTR_HIGH */
        { ZTI_ONE,      ZTI_NULL,       ZTI_ONE,        ZTI_NULL },
        { ZTI_FIX(8),   ZTI_NULL,       ZTI_BATCH,      ZTI_NULL },
        { ZTI_BATCH,    ZTI_FIX(5),     ZTI_FIX(8),     ZTI_FIX(5) },
        { ZTI_FIX(100), ZTI_NULL,       ZTI_ONE,        ZTI_NULL },
        { ZTI_ONE,      ZTI_NULL,       ZTI_ONE,        ZTI_NULL },
        { ZTI_ONE,      ZTI_NULL,       ZTI_ONE,        ZTI_NULL },
};

I imagine it should not be ZTI_FIX(100). It seems more likely that it should be
ZTI_BATCH or ZTI_PCT(100)... or maybe ZTI_PCT(200). Or perhaps we should have a
taskq per CPU and have a fixed number of threads per CPU.

This contention was introduced by a recent push, it was not a regression, we just moved a performance bottleneck by parallelizing some work that was done while freeing blocks:

commit 16a4a80
Author: George Wilson <george.wilson@delphix.com>
Date:   Tue Feb 19 14:15:41 2013

    3552 condensing one space map burns 3 seconds of CPU in spa_sync() thread
    3564 spa_sync() spends 5-10% of its time in metaslab_sync() (when not condensing)
    3566 recursive mutex panic in specfs
    Reviewed by: Adam Leventhal <ahl@delphix.com>
    Reviewed by: Dan Kimmel <dan.kimmel@delphix.com>
    Reviewed by: Matthew Ahrens <mahrens@delphix.com>
    Approved by: Richard Lowe <richlowe@richlowe.net>

History

#1

Updated by Christopher Siden over 6 years ago

  • Status changed from In Progress to Closed
commit ec94d32
Author: Adam Leventhal <ahl@delphix.com>
Date:   Mon Feb 25 21:41:47 2013

    3581 spa_zio_taskq[ZIO_TYPE_FREE][ZIO_TASKQ_ISSUE]->tq_lock is piping hot
    Reviewed by: Matthew Ahrens <mahrens@delphix.com>
    Reviewed by: George Wilson <george.wilson@delphix.com>
    Reviewed by: Christopher Siden <christopher.siden@delphix.com>
    Reviewed by: Gordon Ross <gordon.ross@nexenta.com>
    Approved by: Richard Lowe <richlowe@richlowe.net>

Also available in: Atom PDF