Почему Cacti продолжает ждать мертвых процессов опроса?
В настоящее время я настраиваю новый сервер Debian (6.0.5). Вчера я положил на него Cacti (0,8,7 г) и с тех пор борюсь с ним.
Первоначальный выпуск
Первоначальная проблема, которую я наблюдал, заключалась в том, что мои графики не обновлялись. Итак, я проверил свой cacti.log и нашел это сообщение:
POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
Это не может быть хорошо, правда? Я пошел проверять и начал poller.php я (через sudo -u www-data php poller.php --force). Он выдаст много сообщений (которые выглядят так, как я ожидал), а затем зависнет на минуту. По истечении этой 1 минуты он будет повторять следующее сообщение:
Waiting on 1 of 1 pollers.
Это продолжается еще 4 минуты, пока процесс не будет принудительно завершен на время, превышающее 298 с.
Все идет нормально
Я продолжал добрый час, пытаясь определить, какой опросчик все еще может работать, пока не пришел к выводу, что просто не работает опрос.
Отладка
Я проверил poller.php чтобы узнать, как и почему выдается это предупреждение. В строке 368 Cacti извлекает количество завершенных процессов из базы данных и использует это значение для вычисления количества выполняемых процессов. Итак, давайте посмотрим на это значение!
Я добавил следующий код отладки в poller.php:
$finished_processes = db_fetch_cell("SELECT count(*) FROM cacti.poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'");
print "Finished: " . $finished_processes . " - Started: " . $started_processes . "\n";
Результат
Это напечатает следующее в течение секунды после запуска poller.php:
Finished: 0 - Started: 1
Waiting on 1 of 1 pollers.
Finished: 1 - Started: 1
Значения считываются и действительны. До того как мы переходим к той части, где продолжается цикл:
Finished: - Started: 1
Waiting on 1 of 1 pollers.
Внезапно ценность исчезает. Зачем? Положив var_dump() там подтверждает проблему:
NULL
Finished: - Started: 1
Waiting on 1 of 1 pollers.
Возвращаемое значение - NULL. Как такое может быть при запросе SELECT COUNT()...? (SELECT COUNT() всегда должен возвращать одну строку результата, не так ли?)
Больше отладки
Итак, я вошел в lib\database.php и посмотрел на это db_fetch_cell(). Небольшое тестирование подтвердило, что набор результатов фактически пуст.
Поэтому я добавил туда свой собственный код запроса к базе данных, чтобы посмотреть, что он сделает:
$finished_processes = db_fetch_cell("SELECT count(*) FROM poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'");
print "Finished: " . $finished_processes . " - Started: " . $started_processes . "\n";
$mysqli = new mysqli("localhost","cacti","cacti","cacti");
$result = $mysqli->query("SELECT COUNT(*) FROM poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00';");
$row = $result->fetch_assoc();
var_dump( $row );
Это выведет
Finished: - Started: 1
array(1) {
["COUNT(*)"]=>
string(1) "2"
}
Waiting on 1 of 1 pollers.
Итак, данные есть, и к ним можно получить доступ без каких-либо проблем, только не с помощью метода, который использует Cacti?
Еще раз проверьте это!
Я включил ведение журнала MySQL, чтобы убедиться, что я ничего не воображаю. Разумеется, когда сообщение об ошибке зацикливается, cacti.log читается так, как будто это безумный запрос:
06/29/2012 08:44:00 PM - CMDPHP: Poller[0] DEVEL: SQL Cell: "SELECT count(*) FROM cacti.poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'"
06/29/2012 08:44:01 PM - CMDPHP: Poller[0] DEVEL: SQL Cell: "SELECT count(*) FROM cacti.poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'"
06/29/2012 08:44:02 PM - CMDPHP: Poller[0] DEVEL: SQL Cell: "SELECT count(*) FROM cacti.poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'"
Но никто из этих запросов регистрируется MySQL. Тем не менее, когда я добавляю свой собственный код запроса к базе данных, он отображается нормально.
Что, черт возьми, здесь происходит?
Копать глубже...
Я пришел к выводу, что соединение с базой данных должно быть потеряно где-то в процессе, а adodb это просто не волнует.
Итак, немного покопавшись, я наконец поместил отладочное сообщение в drivers/adodb-mysql.inc.php, строка 529, в _close функция. Хотел посмотреть, когда закрывается соединение.
Я действительно (наконец) включил отладку PHP и понял mysql_query() был вызван с логическим идентификатором соединения (индикатор намеренно закрытого соединения).
// returns true or false
function _close()
{
@mysql_close($this->_connectionID);
echo "!!!! CLOSED !!!!\n";
debug_print_backtrace();
$this->_connectionID = false;
}
Что это за печать?
oliver@j27773:/etc/php5/conf.d$ sudo -u www-data php /usr/share/cacti/site/poller.php --force
06/30/2012 01:33:49 AM - POLLER: Poller[0] NOTE: Poller Int: '60', Cron Int: '300', Time Since Last: '61', Max Runtime '298', Poller Runs: '5'
06/30/2012 01:33:49 AM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/bin/php, ARGS: -q "/usr/share/cacti/site/cmd.php" 0 3]
Finished: 0 - Started: 1
Waiting on 1 of 1 pollers.
Finished: 1 - Started: 1
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_apache_sb_keepalive_100.rrd --template apache_sb_keepalive 1341012829:0
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_apache_reqpersec_95.rrd --template apache_reqpersec 1341012829:.0228409
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_apache_bytesperreq_90.rrd --template apache_bytesperreq 1341012829:13925.7
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_cpu_85.rrd --template cpu 1341012829:1
OK u:0.00 s:0.00 r:1.00
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_hdd_used_80.rrd --template hdd_used:hdd_total 1341012829:924741632:2677886976
OK u:0.00 s:0.00 r:1.00
OK u:0.00 s:0.01 r:1.00
OK u:0.00 s:0.01 r:1.00
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_apache_sb_wait_105.rrd --template apache_sb_wait 1341012829:9
OK u:0.00 s:0.01 r:1.00
OK u:0.00 s:0.01 r:1.00
06/30/2012 01:33:50 AM - SYSTEM STATS: Time:1.1261 Method:cmd.php Processes:1 Threads:N/A Hosts:2 HostsPerProcess:2 DataSources:7 RRDsProcessed:6
Loop Time is: 1.1291718482971
Sleep Time is: 58.867464065552
Total Time is: 1.1325359344482
!!!! CLOSED !!!!
#0 ADODB_mysql->_close() called at [/usr/share/php/adodb/adodb.inc.php:2141]
#1 ADOConnection->Close() called at [/usr/share/cacti/site/lib/database.php:68]
#2 db_close() called at [/usr/share/cacti/site/poller.php:455]
^C06/30/2012 01:33:55 AM - CMDPHP: Poller[0] WARNING: Cacti Master Poller process terminated by user
А теперь я слишком устал, чтобы разбираться в этом ...
Я немного изучил ситуацию и понял, что закрытие соединения с базой данных намеренно. Для следующего опроса необходимо восстановить соединение. Но это не так.
Вот отрывок из poller.php:
if ($poller_runs_completed < $poller_runs) {
db_close();
// Debug message by myself
echo "RECONNECTING IN " . $sleep_time . "\n";
usleep($sleep_time * 1000000);
db_connect_real($database_hostname, $database_username, $database_password, $database_default, $database_type, $database_port);
}
Я также проверил db_connect_real и на самом деле он называется после usleep завершает. Вот где я буду копать дальше.
А пока я изменил раздел следующим образом:
if ($poller_runs_completed < $poller_runs) {
//db_close();
// Debug message by myself
echo "RECONNECTING IN " . $sleep_time . "\n";
usleep($sleep_time * 1000000);
//db_connect_real($database_hostname, $database_username, $database_password, $database_default, $database_type, $database_port);
}
Теперь опросчик работает без предупреждений, и мои графики рисуются. Тем не менее, проблема все еще существует. Не все мои графики рисуются правильно, как видно из следующего изображения:
Я предположил, что это связано с тем, что опросчик работает слишком редко для определенных источников данных. Чтобы решить эту проблему, я переключился на позвоночник (что я все равно хотел сделать) и установил для него 4 потока.
Все идет нормально...
Обновить
Я углубился в эту проблему и подумал, что исправил ее. Я предположил, что соединение не сохраняется должным образом после попытки повторного подключения опросчика.
Моя попытка решить эту проблему сначала выглядела многообещающей, но полученные графики все еще были ошибочными. Так что проблема глубже.
Обходной путь, который я разработал ранее и представленный в этом ответе, по-прежнему работает отлично. Я решил больше не тратить время на эту проблему и остановился на обходном пути. Сожалею.