txg.xd

#!/usr/sbin/dtrace -Cs

#pragma D option quiet
#pragma D option aggrate=5hz
#pragma D option switchrate=5hz
#pragma D option dynvarsize=5m
#pragma D option experimental

BEGIN
{
        self->start = 0;
        self->stop = 0;
        @bytes_read2 = sum(0);
        @reads = count();
        lastprint = 0;
}

spa_sync:entry
/stringof(args[0]->spa_name) == $$1/
{
        printf("%5ums ",
            (timestamp - self->stop)/1000000);

        spa = args[0];

#if 0
        normalize(@bytes_read2,
            1024*1024 * (timestamp - self->stop)/1000000000);
        normalize(@reads,
            (timestamp - self->stop)/1000000000);
        printa("%3@uMB/s ", @bytes_read2);
        printa("%4@uop/s read", @reads);
        clear(@bytes_read2);
        clear(@reads);
#endif

        self->start = timestamp;
}

dsl_pool_sync:return
/entry->args[0]->dp_spa == spa && spa->spa_sync_pass == 1/
{
        pass1_ms = entry->elapsed_ms;
}

vdev_queue_pending_remove:entry
{
        this->io = (zfs`zio_t*)args[1];
        if (this->io->io_spa == spa) {
#if 0
                if (this->io->io_type == ZIO_TYPE_READ) {
                        @reads = count();
                        @bytes_read2 = sum(this->io->io_size);
                }
#endif
                if (this->io->io_type == ZIO_TYPE_WRITE &&
                    this->io->io_bookmark.zb_level != 2) {
                        @bytes_written = sum(this->io->io_size);
                        @bytes_written2 = sum(this->io->io_size);
                }
        }
}

dmu_tx_delay:delay-mintime
{
        this->tx = (dmu_tx_t *)arg0;
        if (this->tx->tx_pool->dp_spa == spa)
                @throttle_us = max((arg2 + 999) / 1000);
}

dmu_tx_delay:return
{
        if (entry->args[0]->tx_pool->dp_spa == spa) {
                @delay_us = max(entry->elapsed_us + 1);
                @delay_us_avg = avg(entry->elapsed_us + 1);
        }
}

#if 0
set-error
/arg0 == 91/
{
        printf("returning ERESTART from:\n");
        stack();
}
#endif

arc_tempreserve_space:return
/arg1 == 91/
{
        printf("reserve=%uKB arc_tempreserve=%uKB arc_c=%uKB\n",
            entry->arg0 / 1024,
            `arc_tempreserve / 1024,
            `arc_stats.arcstat_c.value.ui64 / 1024);

}

zfs-dprintf
/stringof(arg1) == "arc_tempreserve_space"/
{
        printf("%s: %s\n", stringof(arg1), stringof(arg3));
}

/*
zfsdev_ioctl:entry
/this->vec = zfs`zfs_ioc_vec[args[1] - ('Z'<<8)], this->vec.zvec_allow_log && this->vec.zvec_name/
{
        iocname = stringof(this->vec.zvec_name);
}
*/

tick-10hz
/spa != 0/
{
        @dirty_mb = max(spa->spa_dsl_pool->dp_dirty_total / 1024 / 1024);
        @dirty_b = max(spa->spa_dsl_pool->dp_dirty_total);
}

spa_sync:return
/self->start/
{
        normalize(@bytes_written, 1024*1024);
        normalize(@bytes_written2, 1024*1024 * (timestamp - self->start)/1000000000);
        printa(" %4@uMB", @bytes_written);
        printf(" in %5ums", entry->elapsed_ms);
        printf(" (%2u%% p1)", pass1_ms * 100 / (entry->elapsed_ms + 1));
        printa(" %3@uMB/s", @bytes_written2);
#if 0
        normalize(@bytes_read2, 1024*1024 * (timestamp - self->start)/1000000000);
        normalize(@reads, (timestamp - self->stop)/1000000000);
        printa(" + %3@uMB/s", @bytes_read2);
        printa(" %4@uop/s read", @reads);
#endif
        printa(" %@4uMB", @dirty_mb);
        normalize(@dirty_b, `zfs_dirty_data_max / 100);
        printa(" (%@2u%%)", @dirty_b);
        normalize(@delay_us, 1000);
        normalize(@delay_us_avg, 1000);
        printa(" %@4dus %@5dms %@5dms",
            @throttle_us, @delay_us, @delay_us_avg);

        printf("\n");
        clear(@bytes_read2);
        clear(@reads);
        clear(@bytes_written);
        clear(@bytes_written2);
        clear(@bytes_read2);
        clear(@reads);
        trunc(@throttle_us);
        trunc(@delay_us);
        trunc(@delay_us_avg);
        clear(@dirty_mb);
        clear(@dirty_b);

        self->stop = timestamp;

#if 0
        if (stalled) {
                stalled = 0;
                printa("%@u ops stalled due to lack of open txg\n", @stalls);
                normalize(@stalltime, 1000 * 1000);
                printa(" (%@ums/stall)\n", @stalltime);
                clear(@stalls);
                clear(@stalltime);
        }
#endif
}

BEGIN
{
        printed = 100000;
}

spa_sync:return
/self->start && printed++ > 30/
{
        printf("\n");
        printf("%Y txg %u is next\n", walltimestamp, entry->args[1] + 1);
        printf("time since last sync\n");
        printf("     |  written by sync\n");
        printf("     |      | syncing time (%% pass 1)\n");
        printf("     |      |         |        |     write rate while syncing\n");
        printf("     |      |         |        |       |   highest dirty (%% of limit) \n");
        printf("     |      |         |        |       |        | highest throttle delay\n");
        printf("     |      |         |        |       |        |            |      |  avg delay\n");
        printf("     v      v         v        v       v        v            v      v       v\n");
#if 0
        printf("    0ms   145MB in  1342ms (60% p1) 108MB/s  208MB (10%)    0us    57us
#endif
        printed = 0;
}