Object allocation backfilling causes O(n^2) CPU usage

[ahrens]

Using a benchmark which has 32 threads creating 2 million files in the same directory, on a machine with 16 CPU cores, I observed very poor performance (~4000 file creations per second). Most of the time was spent in dmu_object_alloc() waiting for the os_obj_lock:

Using dtrace on illumos, I observed that a few calls to dmu_object_alloc() took much longer than normal, and held the os_obj_lock for much longer than normal, due to making a lot more calls to dnode_next_offset() and dnode_hold_impl:

dtrace \
    -n 'dmu_object_alloc:entry{self->next = 0; self->hold = 0;}' \
    -n 'dnode_next_offset:entry{self->next++}' \
    -n 'dnode_hold_impl:entry{self->hold++}' \
    -n 'dmu_object_alloc:return{@nexts = quantize(self->next); @holds = quantize(self->hold)}' \
    -n 'END{printf("next"); printa(@nexts); printf("holds"); printa(@holds)}' &

calls to dnode_next_offset per call to dmu_object_alloc:
           value  ------------- Distribution ------------- count
              -1 |                                         0
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 974135
               1 |                                         5
               2 |                                         0
               4 |                                         0
               8 |                                         0
              16 |                                         0
              32 |                                         0
              64 |                                         0
             128 |                                         0
             256 |                                         0
             512 |                                         0
            1024 |                                         0
            2048 |                                         0
            4096 |                                         3
            8192 |                                         6
           16384 |                                         11
           32768 |                                         33
           65536 |                                         53
          131072 |                                         97
          262144 |                                         34
          524288 |                                         0

calls to dnode_hold_impl per call to dmu_object_alloc:
           value  ------------- Distribution ------------- count
               0 |                                         0
               1 |                                         13
               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 974127
               4 |                                         0
               8 |                                         0
              16 |                                         0
              32 |                                         0
              64 |                                         0
             128 |                                         0
             256 |                                         0
             512 |                                         0
            1024 |                                         0
            2048 |                                         0
            4096 |                                         3
            8192 |                                         6
           16384 |                                         14
           32768 |                                         33
           65536 |                                         53
          131072 |                                         97
          262144 |                                         31
          524288 |                                         0

Normally, the object allocator simply checks to see if the next object is available. The slow calls happened when dmu_object_alloc() checks to see if it can backfill lower object numbers. This happens every time we move on to a new L1 indirect block (i.e. every 32 * 128 = 4096 objects). When re-checking lower object numbers, we use the on-disk fill count (blkptr_t:blk_fill) to quickly skip over indirect blocks that don’t have enough free dnodes (defined as an L2 with at least 393,216 of 524,288 dnodes free). Therefore, we may find that a block of dnodes has a low (or zero) fill count, and yet we can’t allocate any of its dnodes, because they've been allocated in memory but not yet written to disk. In this case we have to hold each of the dnodes and then notice that it has been allocated in memory.

The end result is that allocating N objects in the same TXG can require CPU usage proportional to N^2. Fixing this problem has the potential to improve performance on this benchmark 15x (to 60,000 creations per second).

@nedbass noticed the same problem and opened #4460 as a workaround, which allows for backfilling to be disabled — i.e. we never try to re-allocate object numbers that have been freed. As discussed in that PR, this is not an appropriate solution for general-purpose workloads.

I propose a solution which limits the number of times we check for lower free objects (“rescans”), while still allowing this to happen when it is useful. Specifically, the objset_t can track how many freed objects have been synced out (i.e. number of calls to dnode_sync_free()) since the last rescan. When dmu_object_alloc() finishes a L1 of dnodes (4096), and the count exceeds a predefined threshold (I would propose this be set to around 4096), then we will rescan, and reset the count to zero. We should arrange for the count to be updated only once per TXG (i.e. once per call to spa_sync(), perhaps in dmu_objset_sync()), so that we will rescan at most once per txg.

The behavior of the solution I’m proposing is not perfect, but it has the following nice properties:

• If no dnodes are being freed, the cost of rescanning is zero, because we will never rescan.
• If dnodes are being freed at a slow rate (e.g. 1000 per txg), the cost of rescanning is also low, because when we rescan, most of the freed dnodes will have been synced, and therefore accounted in the fill counts.
• The worst case is if we have lots of allocations and lots of frees happening all the time. In this worst case, we will rescan once per TXG, which means that allocating N objects is still O(N). In practice the rescan cost would be about 1/450th of what I saw in my test case (with 2 million files created per txg).
• It’s relatively straightforward to implement, and to reason about the resulting performance.

Additionally the comments (and variable names) in dmu_object_allloc() say that we rescan when finishing a L2 of dnodes (524,288 dnodes), but the code actually rescans every L1 (4096 dnodes). We should change the comments. Note that the proposed solution is not especially sensitive to this setting, so leaving it at 4096 should be OK.

In terms of cost/reward, the reward for fixing this is very high, and the cost is medium. On the benchmark described above, performance improved 7.5x, from ~4000 creations per second to ~30,000. (Peak performance of ~60,000 creates/sec was observed with 8 CPUs; adding CPUs past that decreased performance due to lock contention.) Although the implementation described above is relatively straightforward, we would want to evaluate performance under a variety of workloads, including the "worst case" of creating and destroying lots of files in the same txg. We would also want to verify that we are rescanning often enough that the dnode object doesn't get too sparse (or at least isn't much worse than it is today).

[ahrens]

Fixed by 68cbd56