Блог

Я хочу улучшить время уничтожения интерфейса с помощью FreeBSD. Уничтожение тысяч интерфейсов занимает несколько минут на моей тестовой машине -CURRENT , и хотя, по общему признанию, мой вариант использования может быть необычным, я хотел бы понять, почему система так долго работает.

Из моих первоначальных наблюдений я смог установить, что большая часть времени тратится на ожидание где-то внутри if_detach_internal() . Итак, в попытке профилировать эту функцию я придумал следующий сценарий DTrace:

 #!/usr/sbin/dtrace -s

#pragma D option quiet
#pragma D option dynvarsize=256m

fbt:kernel:if_detach_internal:entry
{
        self->traceme = 1;
        t[probefunc] = timestamp;
}

fbt:kernel:if_detach_internal:return
{
        dt = timestamp - t[probefunc];
        @ft[probefunc] = sum(dt);
        t[probefunc] = 0;
        self->traceme = 0;
}

fbt:kernel::entry
/self->traceme/
{
        t[probefunc] = timestamp;
}

fbt:kernel::return
/self->traceme/
{
        dt = timestamp - t[probefunc];
        @ft[probefunc] = sum(dt);
        t[probefunc] = 0;
}
  

Подключившись к зондам entry и return fbt, я ожидаю получить список имен функций и совокупное время выполнения для каждой функции, вызываемой if_detach_internal() (независимо от глубины стека), и отфильтровать все остальное.

Однако то, что я получаю, выглядит следующим образом (уничтожение 250 интерфейсов):

 callout_when1676 sched_load
1779
 if_rele 1801
[...]
 rt_unlinkrte 10296062843
sched_switch 10408456866
 rt_checkdelroute 11562396547
 rn_walktree 12404143265
 rib_walk_del 12553013469
 if_detach_internal 24335505097
 uma_zfree_arg 25045046322788
intr_event_schedule_thread 58336370701120
 swi_sched 83355263713937
 spinlock_enter 116681093870088
[...]
 spinlock_exit 4492719328120735
 cpu_search_lowest 16750701670277714

Информация о времени, по крайней мере, для некоторых функций, кажется, имеет смысл, но я бы ожидал if_detach_internal() , что это будет последняя запись в списке, и ничто не займет больше времени, поскольку эта функция находится в верхней части дерева вызовов, которое я пытаюсь профилировать.

Очевидно, что это не так, поскольку я также получаю измерения для других функций ( uma_zfree_arg() , swi_sched() , и т.д.) с кажущимся сумасшедшим временем выполнения. Эти результаты полностью уничтожают мое доверие ко всему остальному, что сообщает мне здесь DTrace.

Что я упускаю? Звучит ли этот подход вообще?

Я добавлю в свои комментарии тот факт, что я не использовал DTrace во FreeBSD, только в macOS / OS X. Так что здесь может быть что-то специфичное для платформы, о чем я не знаю. С этим покончено:

• Я немного обеспокоен вашим использованием глобального ассоциативного массива t . Возможно, вы захотите сделать эту функцию thread-local ( self->t ) локальной для потоков, потому что в нынешнем виде ваш код может выдавать нежелательные результаты, если if_detach_internal вызывается из нескольких потоков одновременно.
• Ваше использование глобальной dt переменной также опасно и небезопасно для потоков. Это действительно должно быть this->dt везде (предложение-локальная переменная).
• Еще одна вещь, о которой следует помнить, но которая не должна вызывать проблем в вашем коде в его нынешнем виде, это то, что действие fbt:kernel::entry /self->traceme/ будет вызываться само по if_detach_internal себе. Это связано с тем, что последняя функция, конечно, соответствует шаблону, и действия выполняются в том порядке, в котором они отображаются в скрипте, поэтому к тому времени, когда предикат для действия с шаблоном entry проверяется, действие, не являющееся шаблоном, будет иметь значение self->traceme = 1; Double — установка метки времени, подобная этой, не должна вызвать никаких негативных последствий, но, судя по тому, как написан код, вы, возможно, не знали, что это на самом деле то, что он делает, что может вызвать проблемы, если вы внесете дальнейшие изменения в дальнейшем.

К сожалению, правила определения области видимости DTrace довольно неинтуитивны, поскольку по умолчанию все является глобальным и потокобезопасным. И да, это все еще время от времени меня беспокоит, даже после написания изрядного количества кода скрипта DTrace.

Я не знаю, поможет ли следование приведенным выше советам полностью решить вашу проблему; если нет, пожалуйста, соответствующим образом обновите свой вопрос и напишите мне комментарий ниже, и я посмотрю еще раз.

Это еще один вариант действительно простого, но чрезвычайно полезного скрипта DTrace, который я часто использовал, чтобы выяснить, где какое-либо ядро на самом деле проводит большую часть своего времени:

 #!/usr/sbin/dtrace -s

profile:::profile-1001hz
/arg0/
{
    @[ stack() ] = count();
}
  

Это профилирует трассировки стека ядра, и когда скрипт завершает работу с помощью CTRL-C или каким-либо другим способом, он будет печатать что-то вроде этого:

              .
             .
             .
          unix`z_compress_level 0x9a
          zfs`zfs_gzip_compress 0x4e
          zfs`zfs_compress_data 0x8c
          zfs`zio_compress 0x9f
          zfs`zio_write_bp_init 0x2b4
          zfs`zio_execute 0xc2
          genunix`taskq_thread 0x3ad
          unix`thread_start 0x8
          703

          unix`deflate_slow 0x8a
          unix`z_deflate 0x75a
          unix`z_compress_level 0x9a
          zfs`zfs_gzip_compress 0x4e
          zfs`zfs_compress_data 0x8c
          zfs`zio_compress 0x9f
          zfs`zio_write_bp_init 0x2b4
          zfs`zio_execute 0xc2
          genunix`taskq_thread 0x3ad
          unix`thread_start 0x8
         1708

          unix`i86_mwait 0xd
          unix`cpu_idle_mwait 0x1f3
          unix`idle 0x111
          unix`thread_start 0x8
        86200
  

Это примерный набор трассировок стека и количество раз, когда была выбрана трассировка стека. Обратите внимание, что наиболее частые трассировки стека выводятся последними.

Таким образом, вы можете сразу увидеть трассировки стека, которые выбираются наиболее часто — на которые ядро тратит много времени.

Обратите внимание также, что трассировки стека печатаются в том порядке, который вы можете считать обратным — внешний, самый верхний вызов печатается последним.