Лидером, конечно же остается Linux.
А сегодня на повестке дня, снова твой любимый strace и замечательная опция -T, которая позволяет находить ботлнэк (узкое место).
В посте будут встречаться лютые «франкенштейны», но ты сразу не уходи, я кратенько всё разжую и ты проникнешься. Бля буду!
Опция -T выводит разницу во времени между запуском и завершением системного вызова. Применяется для того, чтобы увидеть момент, когда конкретный вызов начал тормозить (встал раком) на фоне предыдущих.
Запускаем «франкенштейна»
strace -s0 -o'|nl >&2' -Tyqqqfe write dd if=/dev/random bs=4096 count=23 status=none | while read -rn1;do : ;done
✔️ Для начала давай разберем эту кишку:
s0 = размер буфера, строки не обрезаются
o/nl/&2 = вывод в стандартную ошибку на утилиту nl
nl = утилита нумерует строки
T = затраченное время на системный вызов
y = показывать симлинки для файловых дескрипторов
qqq = отключаем лешний шлак
f = трассируем дочерние процессы
e = трассировка только write
dd = читает из random блоками 4096 и пишем по 23 блока
дальше скармливаем это while
while = читает данные побайтно (-n1) без обработки символов конца строки (-r)
Вывод сокращаю, чтобы не так погано смотрелось:
01 write() = 4096 <0.004691>
02 write() = 4096 <0.000010>
03 write() = 4096 <0.000009>
04 write() = 4096 <0.000009>
05 write() = 4096 <0.000009>
06 write() = 4096 <0.000009>
07 write() = 4096 <0.000009>
08 write() = 4096 <0.000009>
09 write() = 4096 <0.000009>
10 write() = 4096 <0.000009>
11 write() = 4096 <0.000009>
12 write() = 4096 <0.000009>
13 write() = 4096 <0.000009>
14 write() = 4096 <0.000009>
15 write() = 4096 <0.000009>
16 write() = 4096 <0.000009>
17 write() = 4096 <0.014406>
18 write() = 4096 <0.023782>
19 write() = 4096 <0.023870>
20 write() = 4096 <0.023944>
21 write() = 4096 <0.023815>
22 write() = 4096 <0.024032>
23 write() = 4096 <0.024088>
Смотрим на последний столбик, видим аномалию после 16 строки, время выполнения существенно увеличилось. Поздравляю мы нашли bottleneck (узкое место).
Теперь давай разберемся с этим узким местом. Что произошло, почему все стало тормозить?
Умножаем блок 4096 на номер строки 16, получаем = 65536. Знакомая цифра? Знакомая!
65536 это ёмкость пайпа (канала), по достижению предела пишущий процесс заблокировался, пока не было прочитано и освобождено достаточно места.
Подробнее можешь почитать в мане:
man 7 pipe (раздел Pipe capacity).Бонусом команда, которая протестирует ёмкость пайпа:
sh -c '( dd if=/dev/zero obs=1 oflag=nonblock || pkill -P $$ -x "sleep" ) | sleep 300'
Если dd сообщает о недоступности стандартного вывода, значит тест удался. У меня получилось так:
dd: writing to 'standard output': Resource temporarily unavailable
129+0 records in
65536+0 records out
65536 bytes (66 kB, 64 KiB) copied, 0.0195754 s, 3.3 MB/s
Terminated
Вот так находясь на границе между кодом приложения и кодом ядра можно увидеть тонкие моменты. Изучай!
tags: #linux #debug
—
🔔 @bashdays