Я не могу назвать себя большим специалистом в использовании DTrace, но время от времени я использую возможности этой технологии для отладки на живой системе. Особенно, когда систему нельзя перезагрузить, чтобы добавить в ядро дополнительные отладочные сообщения. В этой заметке я опишу некоторые способы и скрипты для dtrace. Возможно, кому-то они будут полезны, да и самому мне частенько приходится подглядывать в старые скрипты, когда срочно нужно что-то сделать, а уже не помнишь как :)
Всё что необходимо сделать на работающей системе для запуска dtrace:
- # kldload dtraceall
- # vim script.d
- # chmod +x script.d
- # ./script.d
Начну с последней задачи, которая ещё свежа в памяти. На маршрутизаторе с нагрузкой примерно 1Mpps на приём и на отдачу в логах время от времени появлялись сообщения от
named о невозможности отправки ответа клиенту "
error sending response: not enough free resources". При этом счётчик "
output packets dropped due to no bufs, etc." в выводе
netstat -sp ip растёт со скоростью примерно 100 пакетов в секунду.
% while true; do i=$j; j=`netstat -sp ip | awk '/no bufs/ {print $1}'`; echo $((j-i)); sleep 1; done
99499853
81
86
99
104
79
96
86
94
95
86
Если посмотреть в исходный код named'а, то можно увидеть, что такое сообщение возможно только при возвращении системным вызовом кода ошибки ENOBUFS. В сетевом стеке есть несколько мест, которые могут являться источником такого кода ошибки:
% grep -l ENOBUFS netinet/* net/* | column -c 80
netinet/in_gif.c netinet/sctputil.c net/if_fwsubr.c
netinet/in_mcast.c netinet/tcp_output.c net/if_gre.c
netinet/in_pcb.c netinet/tcp_syncache.c net/if_iso88025subr.c
netinet/ip_divert.c netinet/tcp_timewait.c net/if_spppsubr.c
netinet/ip_input.c netinet/tcp_usrreq.c net/if_stf.c
netinet/ip_mroute.c netinet/udp_usrreq.c net/if_tap.c
netinet/ip_output.c net/if_arcsubr.c net/if_tun.c
netinet/raw_ip.c net/if_atmsubr.c net/ifq.h
netinet/sctp_output.c net/if_bridge.c net/netisr.c
netinet/sctp_pcb.c net/if_ethersubr.c net/route.c
netinet/sctp_usrreq.c net/if_fddisubr.c net/rtsock.c
Так как речь идёт о протоколе UDP и IPv4 (IPv4 адреса отображаются в сообщении об ошибке), то начиная с верхнего уровня будем спускаться вниз по стеку. Открываем netinet/udp_usrreq.c и смотрим, где может возвращаться ENOBUFS. Параллельно с этим, создаём скрипт для dtrace, чтобы в реальном времени найти функцию, возвращающую этот код ошибки. Одна из функций, которая может вернуть ENOBUFS - udp_output. Но если посмотреть в вывод dtrace -l, то мы не увидим там возможности трассировать эту функцию. Вероятно компилятор оптимизировал её... Придётся смотреть функцию, которая вызывает udp_output, а это - udp_send.
% sudo dtrace -l | grep udp_output
% sudo dtrace -l | grep udp_send
20109 fbt kernel udp_send entry
20110 fbt kernel udp_send return
Функция
udp_send имеет такой код:
1756 static int
1757 udp_send(struct socket *so, int flags, struct mbuf *m, struct sockaddr *addr,
1758 struct mbuf *control, struct thread *td)
1759 {
1760 struct inpcb *inp;
1761
1762 inp = sotoinpcb(so);
1763 KASSERT(inp != NULL, ("udp_send: inp == NULL"));
1764 return (udp_output(inp, m, addr, control, td));
1765 }
Здесь четвёртый аргумент (arg3 - в dtrace нумерация аргументов идёт с нуля) представляет из себя структуру
sockadd_in, в которой содержится адрес и порт назначения отправляемой датаграммы. Его можно использовать в нашем скрипте:
% vim script.d
#!/usr/sbin/dtrace -s
fbt::udp_send:entry
{
self->addr = (struct sockaddr_in *)arg3;
}
fbt::udp_send:return
/arg1 == 55/
{
printf("%s:%d", inet_ntoa(&self->addr->sin_addr.s_addr), htons(self->addr->sin_port));
}
При запуске скрипта подсистема dtrace будет вызывать функцию fbt::udp_send:entry каждый раз, когда ядро вызывает udp_send. Всё что будет делать наша функция - сохранять указатель на адрес назначения. А обработчик fbt::udp_send:return будет вызываться при завершении функции udp_send, но наличие предиката /arg1 == 55/ ограничит количество вызовов только теми, когда код ошибки, возвращаемый udp_send, будет равен 55 (это числовое значение ENOBUFS). При этом будет напечатан адрес и порт назначения для датаграммы, которую система не смогла отправить (мы сохранили эти данные при входе в функцию). Наблюдая одновременно за логом системы и за выводом этого скрипта можно сделать вывод, что мы идём верным направлением. Адреса совпадают.
Теперь можно спуститься на уровень ниже - в IP, чтобы убедиться что ошибка происходит не в самой udp_output, а в функции, которую она вызывает - ip_output. Добавляем в script.d такую функцию:
fbt::ip_output:return
/arg1 == 55/
{
stack(5);
}
И снова запускаем скрипт. Функция fbt::ip_output:return будет вызываться при выходе из ip_output, когда возвращаемое ею значение будет ENOBUFS. При этом будет печататься набор вызовов функций, который привёл в ip_output:
% sudo ./script.d
dtrace: script './script.d' matched 3 probes
CPU ID FUNCTION:NAME
30 49706 ip_output:return
kernel`udp_send+0x519
kernel`sosend_dgram+0x2d2
kernel`kern_sendit+0x1a3
kernel`sendit+0xdc
kernel`sys_sendto+0x4d
30 20110 udp_send:return XX.88.58.YY:67
30 49706 ip_output:return
kernel`udp_send+0x519
kernel`sosend_dgram+0x2d2
kernel`kern_sendit+0x1a3
kernel`sendit+0xdc
kernel`sys_sendmsg+0x87
30 20110 udp_send:return XX.8.YY.55:51283
Как видим, udp_send не виновата. ENOBUFS, который возвращает udp_send приходит к ней из ip_output. ip_output может возвращать эту ошибку сама, а может получать от нижнего уровня - Ethernet. Таким образом, опускаясь всё ниже и ниже я добрался до драйвера сетевой карты ixgbe(4). В скрипте dtrace у меня из значимого остался вот такой код:
fbt::lagg_transmit:entry
{
self->ifp = (struct ifnet *)arg0;
self->sc = (struct lagg_softc *)self->ifp->if_softc;
}
fbt::lagg_enqueue:entry
{
self->lp = (struct ifnet *)arg0;
}
fbt::lagg_transmit:return
/arg1 == 55/
{
printf("ENOBUFS from %s / %d / %s", self->ifp->if_xname,
self->sc->sc_proto, self->lp->if_xname);
stack(10);
}
Вывод которого показал:
CPU ID FUNCTION:NAME
30 56590 lagg_transmit:return ENOBUFS from lagg0 / 4 / ix1
kernel`vlan_transmit+0xcf
kernel`ether_output_frame+0x33
kernel`ether_output+0x4a2
kernel`ip_output+0xdc0
kernel`udp_send+0x519
kernel`sosend_dgram+0x2d2
kernel`kern_sendit+0x1a3
kernel`sendit+0xdc
kernel`sys_sendmsg+0x87
kernel`amd64_syscall+0x5ea
30 56590 lagg_transmit:return ENOBUFS from lagg0 / 4 / ix0
kernel`vlan_transmit+0xcf
kernel`ether_output_frame+0x33
kernel`ether_output+0x4a2
kernel`ip_output+0xdc0
kernel`udp_send+0x519
kernel`sosend_dgram+0x2d2
kernel`kern_sendit+0x1a3
kernel`sendit+0xdc
kernel`sys_sendmsg+0x87
kernel`amd64_syscall+0x5ea
Здесь немного поясню. Когда приложение делает системный вызов sendmsg для отправки датаграммы, мы попадаем в udp_send, затем вызываем ip_output, от туда мы попадаем в ether_output и ether_output_frame, далее в код vlan'а - vlan_transmit, от туда в код lagg(4), на котором создан vlan - lagg_transmit. lagg(4) создан на двух 10G карточках ixgbe(4). И внутри lagg(4) мы получаем ENOBUFS уже от самого драйвера ixgbe. Внутри кода драйвера ENOBUFS без отображения в статистике мы можем получить только при переполнении кольцевых буферов:
848 err = drbr_enqueue(ifp, txr->br, m);
849 if (err)
850 return (err);
Но и в этом случае ведётся статистика, только доступа к ней нет. Хотя, есть же отладчик! Запускаем kgdb, находим там нужную структуру
ifnet, её
softc, заглядываем внутрь каждой структуры
buf_ring и смотрим на показания счётчика
br_drops. Как-то так:
# kgdb
...
(kgdb) set $ifs=ifindex_table
(kgdb) set $i=1
(kgdb) while ($ifs[$i]->ife_ifnet != 0)
>printf "%i -> %s\n", $i, $ifs[$i++]->ife_ifnet->if_xname
>end
1 -> igb0
2 -> igb1
3 -> ix0
4 -> ix1
...
(kgdb) set $s=(struct adapter *)ifindex_table[3]->ife_ifnet->if_softc
(kgdb) set $i=0
(kgdb) while ($i < $s->num_queues)
>printf "%d -> %d\n", $i, $s->tx_rings[$i++]->br->br_drops
>end
0 -> 24
1 -> 4
2 -> 18
3 -> 7
4 -> 2
5 -> 9
6 -> 9
7 -> 22
8 -> 2
9 -> 1
10 -> 3
11 -> 2
12 -> 2
13 -> 2
14 -> 1046
15 -> 507
В первом цикле мы находим нужную нам структуру ifnet внутри массива ifindex_table. Это структуры с индексами 3 и 4. Ориентируясь на количество очередей внутри драйвера ixgbe(4), выводим на печать содержимое счётчика дропов кольцевых буферов. Как видим, у каждой очереди он не нулевой.
На второй карте было нечто похожее. И это никак не укладывалось в 100 дропов в секунду (в выводе netstat -sp ip). Так как здесь не более 2 тысяч дропов с момента включения сервера.
Что ж, продолжаем искать. В выводе netstat нужный нам счётчик имеет имя ips_odropped (это можно узнать из кода netstat(8), например). Ищем, где этот счётчик изменяется:
% grep -l ips_odropped * | column -c 80
igmp.c ip_fastfwd.c ip_output.c ip_var.h
igmp.c отбрасываем, т.к. в выводе netstat -sp igmp количество пакетов составляло всего пару десятков. Остаются два кандидата ip_output и ip_fastforward. Для первого мы уже делали dtrace скрипты, и частых срабатываний там не было. А вот ip_fastforward ещё не проверяли. В этой функции счётчик ips_odropped может увеличиваться при любой ошибке полученной от Ethernet уровня:
583 if (error != 0)
584 IPSTAT_INC(ips_odropped);
Раз ошибка может быть любой, то посмотрим - а какие вообще ошибки возвращает Ethernet уровень?
fbt::ether_output:return
{
@err[arg1] = count();
}
# ./script.d
dtrace: script './script.d' matched 1 probe
^C
55 2
64 4043
0 34401844
В этом dtrace скрипте я использовал функцию аггреагирования count(). Она сохраняет число вызовов в массив err, где ключём является код возвращаемой ошибки. Теперь смотрим в man errno: 55 код - это ENOBUFS, а 64 - EHOSTDOWN. И тут мы вспоминаем, что когда роутер не может определить L2 адрес хоста назначения, он возвращает эту ошибку из функции arpresolv. Кстати, в коде той же функции ведётся статистика для протокола ARP, которую можно увидеть в выводе netstat -sp arp:
$ while true; do i=$j; j=`netstat -sp arp | awk '/dropped/ {print $1}'`; echo $((j-i)); sleep 1; done
101807936
93
101
106
79
93
78
104
100
89
^C
Примерно вот так знание кода системы, некоторые навыки работы в отладчике и использование dtrace помогают убить время :)
