tools/slow-sql.sh - master - pickling/perf-hunt

tools/slow-sql.sh
219 строк12 KB
vvyurlov
Каждое «файл не найден» теперь говорит, чем этот файл создаётся
29 июл 2026, 01:19
29 июл 2026, 01:19ef9a24d
#!/usr/bin/env bash
# slow-sql.sh — канал лога СУБД: какие запросы стоили дороже всего и как они выглядят.
#
# Третий измеритель навыка «доказательное профилирование». Счётный канал отвечает «сколько
# обращений», временной — «сколько миллисекунд», этот — «какой именно запрос».
#
# Измерено, зачем он нужен: на одном прогоне в лог попал один единственный медленный запрос,
# вызванный 98 раз, и он объяснил сразу три разные подписи детекторов, которые до того выглядели
# как три независимые проблемы.
#
# ПОРОГОВ В ИНСТРУМЕНТЕ НЕТ. Что считать медленным, решает сама СУБД настройкой логирования
# (log_min_duration_statement и аналоги) — инструмент лишь агрегирует то, что уже записано.
# Ранжирование относительное: доля в суммарном времени по логу. Ни одного значения
# в миллисекундах в коде не зашито.
#
# Каталога известных дефектов здесь тоже нет. Инструмент печатает текст запроса и структурные
# наблюдения о нём (есть ли условие отбора, ограничение) — это свойства самого текста,
# а не признаки из списка. Вывод о механизме делает шаг 50-explain.
#
#   tools/slow-sql.sh -Log .perf/stand/db.log
#   tools/slow-sql.sh -Log /var/log/mysql/slow.log -Format generic -Top 5
#
# -Format postgres — «duration: N ms  <префикс>: <sql>»; generic — «N ms» в одной строке
# с текстом запроса. Для иного формата задайте -Pattern: ERE с двумя группами — (1) миллисекунды,
# (2) текст запроса; шаблон применяется до конца строки.
#
# Пустой результат — законный исход, а не ошибка: он означает либо что логирование медленных
# запросов не включено, либо что запросов дороже порога СУБД не было. Инструмент говорит, какой
# именно из двух случаев, и не выдаёт второй за первый.
#
# Коды выхода: 0 — есть агрегат; 2 — лог не найден; 3 — записей о длительности нет.

set -o pipefail
. "$(cd "$(dirname "$0")" && pwd)/platform.sh"

LOG=''; FORMAT='postgres'; PATTERN=''; TOP=8; SQLCHARS=160; OUTDIR=''

while [ $# -gt 0 ]; do
    case "$1" in
        -Log)      LOG=$2; shift 2 ;;
        -Format)   FORMAT=$2; shift 2 ;;
        -Pattern)  PATTERN=$2; shift 2 ;;
        -Top)      TOP=$2; shift 2 ;;
        -SqlChars) SQLCHARS=$2; shift 2 ;;
        -OutDir)   OUTDIR=$2; shift 2 ;;
        -*) say "$C_RED" "неизвестный параметр: $1"; exit 2 ;;
        *)  if [ -z "$LOG" ]; then LOG=$1; shift; else say "$C_RED" "лишний аргумент: $1"; exit 2; fi ;;
    esac
done

if [ -z "$LOG" ]; then
    say "$C_RED" 'нужен путь к логу СУБД: tools/slow-sql.sh -Log <файл>'
    exit 2
fi
if [ ! -f "$LOG" ]; then
    echo ''
    say "$C_RED" "Лог СУБД не найден: $LOG"
    echo 'Путь берётся из карты проекта (поле db_log), а сам лог пишет СУБД — не этот инструмент'
    echo 'и не приложение. Обычно её поднимает раздел stand.db карты, и он же включает порог'
    echo 'логирования (log_min_duration_statement у PostgreSQL). Порог задаёт СУБД, а не мы:'
    echo 'это единственный отбор в канале, который не наш.'
    echo 'Лога нет — канал лога СУБД НЕДОСТУПЕН. В отчёте это «не проверялось», а не «чисто»:'
    echo 'первопричины по тексту запроса найдены не будут.'
    exit 2
fi

LOG_ABS=$(cd "$(dirname "$LOG")" && pwd)/$(basename "$LOG")
if [ -z "$OUTDIR" ]; then OUTDIR=$(dirname "$LOG_ABS"); fi
mkdir -p "$OUTDIR"
OUT_FILE="$OUTDIR/slow-sql.json"

TAB=$(printf '\t')

# Форматы записей о длительности → sed-подстановка «мс<TAB>текст запроса».
# ERE не знает (?:...), поэтому альтернативы захватывают лишние группы — номера в замене учтены.
case "$FORMAT" in
    postgres)
        # PostgreSQL: "LOG:  duration: 345.335 ms  execute S_29: select ..." либо "... statement: select ..."
        SED_EXPR="s/.*duration:[[:space:]]*([0-9.,]+)[[:space:]]*ms[[:space:]]+((execute|parse|bind)[^:]*:|statement:)?[[:space:]]*(.+)\$/\\1${TAB}\\4/p"
        EFFECTIVE_PATTERN='duration:\s*([0-9.,]+)\s*ms\s+((execute|parse|bind)[^:]*:|statement:)?\s*(.+)$'
        ;;
    generic)
        # Обобщённый: "... 1234 ms ... <sql>"
        SED_EXPR="s/(.*[^0-9.,])?([0-9.,]+)[[:space:]]*ms[^a-zA-Z]*((select|insert|update|delete|with|call)[[:space:]].+)\$/\\2${TAB}\\3/p"
        EFFECTIVE_PATTERN='([0-9.,]+)\s*ms[^a-zA-Z]*((select|insert|update|delete|with|call)\s.+)$'
        ;;
    *)
        say "$C_RED" "неизвестный -Format: $FORMAT (postgres|generic)"; exit 2 ;;
esac
if [ -n "$PATTERN" ]; then
    SED_EXPR="s/.*${PATTERN}\$/\\1${TAB}\\2/p"
    EFFECTIVE_PATTERN=$PATTERN
fi

TMP=$(mktemp -d "${TMPDIR:-/tmp}/slow-sql.XXXXXX")
trap 'rm -rf "$TMP"' EXIT

LINES=$(awk 'END{print NR}' "$LOG")

# Нормализация: одинаковые по форме запросы должны попасть в одну группу независимо от значений.
# Заменяются только литералы и числа — структура запроса не трогается. Границы слов эмулируются
# вручную: в POSIX awk нет \b, а "S_29" и "col1" числами не являются.
sed -nE "$SED_EXPR" "$LOG" | awk -F'\t' '
function norm_numbers(s,    out, before, after) {
    out = ""
    while (match(s, /[0-9]+(\.[0-9]+)?/)) {
        before = (RSTART > 1) ? substr(s, RSTART - 1, 1) : ""
        after  = substr(s, RSTART + RLENGTH, 1)
        if (before ~ /[0-9A-Za-z_]/ || after ~ /[0-9A-Za-z_]/) {
            out = out substr(s, 1, RSTART + RLENGTH - 1)
        } else {
            out = out substr(s, 1, RSTART - 1) "?"
        }
        s = substr(s, RSTART + RLENGTH)
    }
    return out s
}
{
    ms = $1
    sql = substr($0, index($0, "\t") + 1)
    gsub(",", ".", ms)                      # десятичный разделитель зависит от локали пишущего
    if (ms + 0 <= 0 && ms !~ /^0/) next
    gsub(/\x27([^\x27]|\x27\x27)*\x27/, "\x27?\x27", sql)   # строковые литералы
    gsub(/\$[0-9]+/, "?", sql)                              # позиционные параметры
    sql = norm_numbers(sql)                                 # числа вне слов
    gsub(/[[:space:]]+/, " ", sql)
    sub(/^ +/, "", sql); sub(/ +$/, "", sql); sub(/;+$/, "", sql)
    if (sql == "") next
    calls[sql]++
    total[sql] += ms + 0
    if (ms + 0 > max[sql]) max[sql] = ms + 0
}
END {
    for (s in calls) printf "%.6f\t%.6f\t%d\t%s\n", total[s], max[s], calls[s], s
}
' > "$TMP/agg.tsv"

echo ''
say "$C_CYN" "slow-sql  $LOG"

STATEMENTS=$(awk 'END{print NR}' "$TMP/agg.tsv")
PARSED=$(awk -F'\t' '{n += $3} END{print n + 0}' "$TMP/agg.tsv")

if [ "$PARSED" -eq 0 ]; then
    say "$C_YEL" "строк в логе $LINES, записей о длительности не найдено"
    echo ''
    echo 'Два разных случая, и они не равнозначны:'
    echo '  1) логирование медленных запросов выключено — канал недоступен, включите его в СУБД;'
    echo '  2) логирование включено, но запросов дороже порога СУБД не было — канал пуст, и это результат.'
    echo 'Различить их можно по наличию в логе любых строк от СУБД. Не выдавайте первый случай за второй.'
    jq -n --arg log "$LOG_ABS" --argjson lines "$LINES" \
        '{tool: "slow-sql", log: $log, lines: $lines, parsed: 0, statements: 0, available: false}' \
        > "$OUT_FILE"
    exit 3
fi

sort -t"$TAB" -k1,1 -rn "$TMP/agg.tsv" > "$TMP/ranked.tsv"
TOTAL_MS=$(awk -F'\t' '{s += $1} END{printf "%.6f", s}' "$TMP/ranked.tsv")

printf 'строк %s, записей о длительности %s, различных запросов %s, суммарно %.0f мс\n' \
    "$LINES" "$PARSED" "$STATEMENTS" "$TOTAL_MS"
echo ''
printf '  %6s %10s %9s %6s  %s\n' 'доля%' 'сумма мс' 'макс мс' 'вызов' 'запрос'

# Верхние запросы с долями и структурными наблюдениями считает jq: у него есть настоящие
# границы слов в регулярных выражениях, которых нет ни в awk, ни в POSIX grep.
head -n "$TOP" "$TMP/ranked.tsv" | jq -Rn --argjson totalMs "$TOTAL_MS" '
    [inputs | split("\t") | {
        total: (.[0] | tonumber),
        max:   (.[1] | tonumber),
        calls: (.[2] | tonumber),
        sql:   (.[3:] | join("\t"))
    }] | map(
        (.sql | test("^\\s*select\\b"; "i")) as $isSel |
        {
            sql, calls,
            total_ms: ((.total * 10 | round) / 10),
            max_ms:   ((.max * 10 | round) / 10),
            share_pct: (if $totalMs > 0 then ((1000.0 * .total / $totalMs | round) / 10) else 0 end),
            select_without_where: ($isSel and (.sql | test("\\bwhere\\b"; "i") | not)),
            select_without_limit: ($isSel and (.sql | test("\\b(limit|fetch first|top)\\b"; "i") | not))
        })' > "$TMP/top.json"

jq -r --argjson chars "$SQLCHARS" '.[] |
    (if (.sql | length) > $chars then (.sql[:$chars] + "...") else .sql end) as $shown |
    ([(if .select_without_where then "без условия отбора" else empty end),
      (if .select_without_limit then "без ограничения" else empty end)] | join(", ")) as $marks |
    "\(.share_pct)\t\(.total_ms)\t\(.max_ms)\t\(.calls)\t\($shown)\t\($marks)"' "$TMP/top.json" |
while IFS="$TAB" read -r share total max calls shown marks; do
    printf '  %6.1f %10.0f %9.1f %6d  %s\n' "$share" "$total" "$max" "$calls" "$shown"
    if [ -n "$marks" ]; then
        say "$C_YEL" "         ^ $marks"
    fi
done

echo ''
echo 'Ранжирование по доле в суммарном времени лога — величина относительная.'
echo 'Что попало в лог, решила СУБД своей настройкой порога, а не этот инструмент.'

jq -n \
    --arg log "$LOG_ABS" \
    --arg generated_at "$(now_iso)" \
    --arg format "$FORMAT" \
    --arg pattern "$EFFECTIVE_PATTERN" \
    --argjson lines "$LINES" \
    --argjson parsed "$PARSED" \
    --argjson statements "$STATEMENTS" \
    --argjson total_ms "$TOTAL_MS" \
    --slurpfile top "$TMP/top.json" \
    '{
        tool: "slow-sql", log: $log, generated_at: $generated_at,
        format: $format, pattern: $pattern,
        lines: $lines, parsed: $parsed, statements: $statements,
        total_ms: (($total_ms * 10 | round) / 10),
        available: true, top: $top[0]
    }' > "$OUT_FILE"

echo ''
echo "артефакт: $OUT_FILE"