Bash Days | Linux | DevOps: “Ищем баги с помощью strace Предположим, крутится у тебя в проде какое-…”

Ищем баги с помощью strace

Предположим, крутится у тебя в проде какое-то приложение, это приложение было разработано криворукими обезьянами — на отъебись.
ㅤ
По итогу продакшен начинает троить и выжирать процессорное время. Хуита!

Явно требуется профилирование, но мыж с тобой не обезьяны, поэтому изучать код не будем. А сразу вооружимся strace и посмотрим где-же узкое горлышко.

Запускаем:

strace -c python3 app.py

Через несколько секунд жмём Ctrl-C и получаем статистику:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ------
99.82    0.413251           8     49431            write
 0.07    0.000291          32         9            mmap
 0.05    0.000207          25         8            mprotect
 0.03    0.000129          21         6            openat
 0.02    0.000090          30         3            close
......

Хм… эта падла активно пользуется системным вызовом write().

time — процент процессорного времени, потраченного на вызов.
usecs/call — среднее время на один вызов (в микросекундах).
calls — сколько раз вызов был сделан.

Виновника определили. То есть приложение постоянно что-то куда-то пишет, тем самым забивая 99% процессорного времени.

Важно понимать: strace показывает только то время, которое ядро тратит на обработку системных вызовов. Поэтому значения могут отличаться от того, что покажет команда time:

$ time python3 app.py

real    0m7.412s
user    0m1.102s
sys     0m6.184s

Здесь sys совпадёт с тем, что мы видели через strace -c.

Ну и теперь даже без доступа к исходникам можно быстро понять, где «утекают» ресурсы.

Исходники у нас есть, давай посмотрим:

with open("tmp.txt", "w") as f:
    while True:
        f.write("Привет супчики! Привет от BashDays!")
        f.flush()

Что тут не так:

Из-за flush() Python гонит строку сразу в файловую систему, без буферизации.

Как пофиксить:

# fixed.py
with open("tmp.txt", "w", buffering=1024*1024) as f:
    while True:
        f.write("Привет супчики! Привет от BashDays!\n")

Теперь данные будут сбрасывать пачками, так как мы указали буферизацию, которая равна 1MB.

Проверяем до фикса:

$ strace -c python3 app.py
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ------
99.8      0.413251           8     49431           write

Проверяем после фикса:

$ strace -c python3 app-fixed.py
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ------
98.9     0.072111         450        160           write

Количество вызовов write() резко сократилось, нагрузка на ядро упала.

Как костыль и быстрофикс — сойдёт! Повторюсь — мы с тобой не обезьяны, чтобы вникать в код разработчиков и что-то в нем «правильно» править.

В большинстве случаев, ты просто находишь проблемы и уже с этими данными создаешь задачу на разработчика. Сам в код не лезь, целее будешь.

Ну и на закуску фикс, который сделали разработчики:

import io

buffer = io.StringIO()

with open("tmp.txt", "w") as f:
    while True:
        buffer.write("Привет супчики! Привет от BashDays\n")
        if buffer.tell() > 1024 * 1024:
            f.write(buffer.getvalue())
            f.flush()
            buffer.seek(0)
            buffer.truncate(0)

Как это работает:

1. StringIO хранит текст в оперативной памяти.
2. Цикл гонит туда строки.
3. Когда накопится, например, 1 MB, содержимое сбрасывается в файл одной большой порцией (write + flush).
4. Буфер очищается и цикл продолжается.

Хуй знает на сколько это всё правильно, ну раз сделали через внутреннию буферизацию StringIO, значит так правильно.

Такие дела. Изучай.

🛠 #debug
—
✅ @bashdays ✅ @linuxfactory ✅ @blog