Человеко понятное логирование cron-заданий?

Question

[gigigi]

Здравствуйте. Появилась одна проблема — раз в сутки на сервере сильно поднимается нагрузка.

Т.к. это повторяется в одно и тоже время — подозрение падает естественно на задачи, запускаемые cron'ом. Задача — отследить что именно создаёт большую нагрузку, дабы это оптимизировать.

Т.к. задач в кроне у нас достаточно много, скрипты запускаются разные, добавлять какую-то свою систему логирования будет достаточно долго, хочется добавить что-то в течение пары часов, чтобы уже сегодня отследить, а завтра начать исправлять.


Возможно есть какая-то система логирования, которая хотябы сможет логировать всё, что запускается по крону и в идеале как-то совмещать это с отображением нагрузки по задачам? Или возможно у кого-то есть другие идеи?


Заранее спасибо.

Answer 1

[sledopit]

Подождите, так вы знаете время, когда это происходит? Почему нельзя просто посмотреть, что именно запускалось в этот момент?
Крон же всё пишет в syslog. grep CRON /var/log/syslog ну и найти нужное время.

Или у вас настолько большой крон, что там по сто заданий в минуту запускается?

Comments

[gigigi]

В одно время может запускаться достаточно много заданий, при этом надо понять какое именно из них создаёт большую нагрузку. Не по 100 конечно, но по syslog'у не понять как долго отработал конкретный крон: за 3 секунды или за полчаса. По графикам я вижу когда _примерно_ нагрузка начинает расти и когда снижаться, но в сислоге нет информации о продолжительности, следовательно мне не отследить какой из кронов создаёт нагрузку.

[joneleth]

Руками запустите и посмотрите топ, и все. Если раз в сутки, то это cron.daily.

Answer 2

[rozhik]

хочется добавить что-то в течение пары часов

Замените в кроне
1 2 3 4 5 /bin/task1
на
1 2 3 4 5 /bin/taskRun.sh
В taskRun.sh

#!/bin/bash
date 2>&1 >> /var/log/task1
time /bin/task1 2>&1 >> /var/log/task1
cat /proc/meminfo >> /var/log/task1
cat /proc/loadavg >> /var/log/task1

Будет выведено много строчек статистики на момент окончания скрипта +
Mon Aug 12 14:21:21 UTC 2013
real 1m8.818s
user 0m35.090s
sys 0m1.332s

Хотя правильнее было бы то-же самое сделать через logger. Но как выше быстрее, не нужно парится с конфигом сислога

Comments

[gigigi]

Мне на самом деле достаточно loadavg и time, да даже просто time, т.к. по сути мне нужно узнать продолжительность каждого крона. Спасибо, буду пробовать как-то так. Только пока не смог заставить time писаться в тот же файл, а не выводиться. Ни так, как у вас в примере, ни так как в нескольких примерах из гугла пока не получилось) только выводится, но не пишется.

Answer 3

[mrstrictly]

1. У процессов запускаемых по крону родительский процесс называется CRON и его ppid соответствует процессу cron. Пример:

root       514     1  0 авг.10 ?    00:00:00 cron
...
root     21227   514  0 17:30 ?        00:00:00 CRON
root     21228 21227  0 17:30 ?        00:00:00 /bin/sh -c sleep 1

2. Нагрузку на CPU конкретным процессом можно получить командой

ps u -p <pid>

Таким образом, ваша задача сводится к тому, чтобы в вашем крон-логгере:
1. Вычислить все процессы, у которых имя родительского процесса — CRON.
2. Для этих процессов собрать нагрузку на CPU.
3. Красиво вывести в файл.

Надеюсь, это поможет.

Comments

[gigigi]

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

[mrstrictly]

Осенило, вдруг, готовым решением: pidstat.

$ cat /dev/urandom > /dev/null & pidstat -u -p $! 1
[1] 18053
Linux 3.8.0-27-generic (...) 12.08.2013 _i686_ (4 CPU)

19:05:39 PID %usr %system %guest %CPU CPU Command
19:05:40 18053 0,00 100,00 0,00 100,00 3 cat
19:05:41 18053 0,00 99,00 0,00 99,00 3 cat
19:05:42 18053 0,00 100,00 0,00 100,00 3 cat
19:05:43 18053 0,00 100,00 0,00 100,00 3 cat
…

То есть, всё, что вам нужно — дописать в кронтаб к каждой таске "& pidstat -u -p $! 1 >> путь к логу"

[gigigi]

Спасибо! Надеюсь сработает :)

[gigigi]

Но время выполнения я всё равно не увижу так похоже)

Answer 4

[1x1]

можно на коленке написать скрипт, вызывающий все команды крона, вроде такого:

#!/bin/sh
/bin/date >> /var/log/smth
"$@"
/bin/date >> /var/log/smth
/usr/bin/uptime >> /var/log/smth
/usr/bin/iostat -x 1 1 >> /var/log/smth

Comments

[gigigi]

А зачем вызывать все команды крона?) Они и так вызываются и даже в syslog пишется информация. Но опять же по времени продолжительности и нагрузке по каждой задаче — никакой информации я не получу.

[1x1]

Все интересные вам команды крона элементарно меняются добавлением префикса к команде:
1 * * * * user /opt/cronstat /do/some/stuff param1 param2 param3
Для этого скрипта в лог пишется время начала задачи, время завершения задачи, uptime/load average плюс загрузка дисков на момент завершения задачи (тоже частая причина повышенной нагрузки). Легко добавить другие интересные вам параметры или мониторинг в фоне в течении всего выполнения скрипта.

Answer 5

[rozhik]

Выбирайте что хотите. Опций много ;)man time
Решениеписаться в тот же файл, а не выводиться: [ -o FILE ] [ --append ] то-есть
time -o /var/log/log --append command

Простите писал по памяти, сейчас отпут тайм выдаёт на консоль а не в стдэр ;)

Answer 6

[Пума Тайланд]

А что мешает зайти в это время на сервер и посмотреть топ?

Comments

[gigigi]

А что вам даст простой просмотр топа во время, когда на рабочем сервере крутится куча рабочих проектов + может запускаться по несколько кронов каждую минуту, а выяснить вам надо какой именно крон больше нагружает систему примерно в определённое время +-полчаса?

[Пума Тайланд]

Обычно топ дает мне полную информацию об узких местах и кто их создает, а больше мне и не надо.
Откуда у вас такой разброс +- полчаса. посмотрите в мониторинге с точностью до минуты.

Answer 7

[bestia]

atop (/usr/ports/sysutils/atop ) умеет работать как демон и писать файлы с состояниями. Потом можно посмотреть сохраненные состояния на любой указанный момент времени

Comments

[gigigi]

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