BashTex | Linux on Telegram: “Профилирование скрипта: time, PS4, set -x

Профилирование скрипта: time, PS4, set -x - лог с таймингом каждой строки

🔎 Скрипт тормозит, но где? Чтобы найти бутылочное горлышко в скрипте, нужно понять, какая строка выполняется долго, а не просто смотреть на общее time.

✅ Решение: профилирование через связку:

time - сколько длился весь скрипт
set -x - трассировка всех команд
PS4 + date - лог с таймингом каждой строки

▪️ Пример: логирование с таймингом


#!/bin/bash

LOGFILE=trace.log

# Префикс трассировки: время и строка
export PS4='+ $(date "+%H:%M:%S.%3N") [${BASH_SOURCE##*/}:${LINENO}] '

# Включаем трассировку и направляем в лог
exec 3>&1 4>&2
exec > >(tee "$LOGFILE") 2>&1
set -x

# Тестовые команды
sleep 1
echo "Шаг 1"
sleep 2
echo "Шаг 2"

▪️ Вывод лога trace.log:


+ 12:34:56.001 [script.sh:12] sleep 1
+ 12:34:57.003 [script.sh:13] echo 'Шаг 1'
Шаг 1
+ 12:34:57.004 [script.sh:14] sleep 2
+ 12:34:59.006 [script.sh:15] echo 'Шаг 2'
Шаг 2

Теперь видно, какая команда занимает больше всего времени. Не нужно гадать.

▪️ Добавим time: Если обернуть скрипт:


time ./script.sh

В конце получим:


real    0m3.006s
user    0m0.002s
sys     0m0.004s

🛠 Скрипт: поиск "медленных" команд в логе


#!/bin/bash

LOG=trace.log
THRESHOLD=1.0  # секунды

awk '
  /^\+ / {
    ts=$2                      # + 12:34:56.001
    split(ts, a, ":")
    split(a[3], b, ".")
    sec = a[1]*3600 + a[2]*60 + b[1] + b[2]/1000
    cmd = substr($0, index($0, $4))
    
    if (last_sec > 0) {
      delta = sec - last_sec
      if (delta >= threshold) {
        printf "%6.3fs  | %s\n", delta, last_cmd
      }
    }

    last_sec = sec
    last_cmd = cmd
  }
' threshold="$THRESHOLD" "$LOG"

▪️ Пример вывода:


1.002s  | sleep 1
2.002s  | sleep 2

Теперь ты в автомате видишь: какие строки тормозят, а не листаешь лог на глаз.

BashTex 📱 #bash #utils