Сеанс консольной магии: анализ access логов nginx'а.

О том, что где-то рядом живут sed, grep, awk и pipelines, я узнал еще года 4 назад, но использовать (с толком) их не приходилось. Пока не захотелось странного…

Странное заключалось в поиске запросов от парсеров в логе nginx’а, и в поиске “дорогих” страниц.
Оказалось все просто:

  • sed – потоковый редактор текста. Т.е. ты ему поток текста, а он его преобразует по данным тобою правилам.
  • grep- потоковый фильтр. Ты ему критерий, он тебе данные, отфильтрованные по этому критерию.
  • awk – скриптовый язык для обработки потоков. Мощная штука. Очень мощная штука.

А теперь хором

Задача номер один – поиск парсеров. Парсеры отличаются тем, что делают много запросов с одного IP. Понеслась…

Файл group_by_ips.sh:

awk '
{
  requests_count_from_ips[$1]++
}
END
{
  for (ip in requests_count_from_ips)
  {
    print requests_count_from_ips[ip] ": " ip;
  }
}' | \
sort -nr

Создаем массив, в котором в качестве ключей используем IP, а в качестве значений – количество запросов с него. Т.к. IP в access логе у нас стоит первым, то соответственно его значение попадет в скрипт, как $1. По окончанию обработки потока бежим по массиву и выводим первым – количество запросов, а потом IP. Ну и сортируем вывод sort’ом.

#cat ./access.log | ./group_by_ips.sh | head
81015: 66.249.72.83
11740: 69.80.244.163
6527: 82.193.155.236
2456: 88.212.197.90
1833: 195.131.145.226
1770: 67.202.41.3
1584: 195.208.157.26
1544: 89.239.140.106
1235: 89.252.9.34
1208: 72.26.227.114

Мы для кого работаем?

Задача #2 состоит в определении “стоимости” различных url. Стоимостью мы будем считать время работы backend’а. Для того, чтобы он попал в access лог будем использовать переменную “upstream_response_time”. Формат моих логов:

log_format fastcgi_log '$remote_addr $request $status $body_bytes_sent'
' $http_referer $upstream_response_time $request_time $time_local $host [$http_user_agent]';

Файл calc_weights_by_urls.sh:

awk '{
  gsub(/[0-9]+/, "X", $3);
  urls[$2" "$3] += $8;
}
END
{
  for(i in urls)
  {
    print urls[i]":"i;
  }
}' | \
sort -nr
#cat ./access.log | ./calc_weight_by_urls.sh | head
88160.2:GET /users/X/
85643.6:GET /photos/X/
84629.4:GET /photos/category/X/?pager=X
45453.2:GET /photos/X/?from_member
25910:GET /users/X/?pager=X
9275.3:GET /photos/category/X/
8299.5:GET /
8298.21:GET /users/X/photos/?category=X
4309.97:GET /my/favorite_authors_photos/
4304.44:GET /new_on_site/photos/?pager=X

Коль пошла такая пьянка

Раз уж у нас есть данные по стоимости каждого запроса, то можно улучшить решение первой задачи, и считать стоимость IP не по количеству запросов, а как сумму стоимостей запросов с этого IP.
Файл calc_weights_by_ips.sh:

awk '
{
  ips[$1] += $8;
}
END
{
  for(i in ips)
  {
    print ips[i]":"i;
  }
}' | \
sort -nr
cat ./access.log | ./calc_weight_by_ips.sh | head
42533.1:66.249.72.83
12886.8:69.80.244.163
5272.19:82.193.155.236
3892.73:93.189.148.97
1678.77:88.212.197.90
1424.76:67.202.41.3
1327.53:82.207.122.195
1318.4:81.19.66.89
1199.44:67.195.45.213
1114.04:80.72.18.82

В итоге три первых IP сохранились, а дальше уже картина немного другая.

Немного о скорости

Несмотря на то, что я, мягко говоря, не айс в этих утилитах, и скорее всего написал все криво и неоптимально, но скорость все равно радует:

  • размер анализируемого лога – 160Mb (650К строк)
  • время работы подсчета стоимости по IP – 2 секунды
  • время работы подсчета стоимости по урлам – 4 секунды

Несколько комментариев

  1. IlVin пишет:

    awk ‘ { requests_count_from_ips[$1]++ }
    END { for (ip in requests_count_from_ips) { print requests_count_from_ips[ip] “: ” ip;
    } }’ | sort -nr

    Это плохой пример, если нужно пропарсить гигабайты упакованных логов :(
    А гигабайты обрабатывает конструкция:

    sort | uniq -c | awk ‘{ print $1 “: ” $2 }’ | sort -nr

    Т.е.
    awk ‘ { requests_count_from_ips[$1]++ }
    END { for (ip in requests_count_from_ips) { print requests_count_from_ips[ip] “: ” ip;
    } }’
    Эквивалентно
    sort | uniq -c

  2. Цветовое кодирование? Можно пример?

  3. Давно уже вдоль и поперёк изъезженная тема, но всё равно как садишься за консоль, аж волосы дыбом встают от ощущения магии. =)

    Я, кстати, люблю ещё применять цветовое кодирование на основе каких-либо критериев. Awk по сути использует псевдо-C язык, я же предпочитаю писать анализаторы на awk в связке с PHP.

  4. Станислав пишет:

    >idler комментирует…
    > 2 секунды, 4 секунды…
    > Это ни о чем не говорит :) – мощности машины ведь не >указаны :)
    На самом деле это не особо важно. Главное, что это не 3 часа, а секунды.

  5. Arceny пишет:

    Пофиксил ))

  6. Arceny пишет:

    awk: cmd. line:5: END blocks must have an action part

  7. idler пишет:

    2 секунды, 4 секунды…
    Это ни о чем не говорит :) – мощности машины ведь не указаны :)

  8. Lzh пишет:

    а не думаешь что оно уже где-нить реализовано? всетаки задача анализа логов не такая уж и редкая.

  9. Станислав пишет:

    Ну так!

    Одна из безумных идей – реализовать подобие fluent intarface для логов.

    lmbLog('access.log')->filter(1, '192.168.0.1')->count(3)->groupby(8);

  10. Lzh пишет:

    отлично, попробовал у себя тоже.

    правда пришлось доработать скрипт подсчета “стоимости” урлов, чтобы он показывал еще количество запросов и среднее время загрузки страницы (правда я и так его знаю).

    как грится – пишите еще :)

  11. Не эквивалентно, ибо “uniq -c” выдаст количество совпадений строк, а не ip’шников.

Оставить комментарий