Phantom Activity
Igor Zavgorodny
IDS 9.21.UC2 Solaris x86.
У меня, спасибо Юрику Шестакову, вот уже несколько лет стоит мониторинг
через связку "onstat -p" и MRTG за сервером. Достаточно давно я заметил,
что сервер временами проявляет необъснимую "ночную" активность, хотя
после 21:30 в системе остается только файловый-робот, выполняющий раз в
час reconnect к серверу, согласно логам роботам, ночью роботы у него не
было (и не могло быть) + "ontape -c", регламентные операции к этому
времени все выполненны. Тем не менее:
1. Результат анализа графиков MRTG:
02:30-03:50 - disk write/reads в среднем 3000op/s
03:50-04:00 - System CPU около 18%, той же ночью, но в другие полчаса
04:00-04:20 - lchwaits (порядка 200 в секунду, чего при нормальной работе
практически не наблюдается) + bufwaits в это же время, порядка 20 в секунду
04:20-04:40 - disk write/reads в среднем 3000op/s
В течение всего этого времени, буфферное чтение-запись были близки к
нулю (мне тяжело добраться до точных данных, а на графике минимальное
различимое значение - порядка 800op/s.
ISAM Reads+ISAM Writes аналогично не различимы на графике при минимально
заметных 500op/s. Еле заметны только моменты реконнекта файлового-робота
(он достаточно много в этот момент читает).
Page Reads, Page Writes - такая же картина, т.е. график пуст при
различимых 300 op/s.
2. online.log
21:31:44 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
not flushed.
21:31:44 Checkpoint loguniq 28120, logpos 0x11c1dc
[..мыши..]
01:56:45 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
not flushed.
01:56:45 Checkpoint loguniq 28120, logpos 0x1fb1dc
02:01:45 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
not flushed.
02:01:45 Checkpoint loguniq 28120, logpos 0x1fe1dc
02:02:09 Logical Log 28120 Complete.
02:02:11 Process exited with return code 142: /bin/sh /bin/sh -c
/usr/informix/etc/log_full.sh 2 23 "Logical Log 28120 Complete."
"Logical Log 28120 Complete."
02:02:13 Logical Log 28120 - Backup Started
02:02:13 Logical Log 28120 - Backup Completed
02:06:45 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
not flushed.
02:06:45 Checkpoint loguniq 28121, logpos 0x21dc
02:11:45 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
not flushed.
02:11:45 Checkpoint loguniq 28121, logpos 0x51dc
02:16:45 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
not flushed.
02:16:45 Checkpoint loguniq 28121, logpos 0x91dc
02:21:45 Checkpoint Completed: duration was 0 seconds.
02:21:45 Checkpoint loguniq 28121, logpos 0xc018
02:26:45 Checkpoint Completed: duration was 0 seconds.
02:26:45 Checkpoint loguniq 28121, logpos 0x10018
[..мыши..]
04:41:46 Checkpoint Completed: duration was 0 seconds.
04:41:46 Checkpoint loguniq 28121, logpos 0x76018
и т.д. и т.п. до явления юзеров в системе.
Таким образом, видно, что "свистопляска" началась после того, как Fuzzy
сменились обычными Checkpoint-ами. Но чем занимался сервер в это время,
я понять не могу. Возможно где-то в энциклопедии юных сурков, что-то на
эту тему есть, но я не нашел :-(.
Regards, Igor.
Черный Павел
news:3D92D8D2...@torba.com...
> Hi, All.
>
> У меня, спасибо Юрику Шестакову, вот уже несколько лет стоит мониторинг
> через связку "onstat -p" и MRTG за сервером. Достаточно давно я заметил,
А можно поподробнее, если, конечно, автор не возражает.
P.S. Можно на e-mail
С уважением,
Черный Павел
mail to c...@usb.zp.ua
ICQ: 15881625
Igor Zavgorodny
>>У меня, спасибо Юрику Шестакову, вот уже несколько лет стоит мониторинг
>>через связку "onstat -p" и MRTG за сервером. Достаточно давно я заметил,
>
Ну вообще Google, никто не отменял, но помнит все
(MRTG+ukr.comp.dbms.informix не самый большой запрос :-), другое дело,
что из линков, упомянутых в том треде смысл имеет только этот.
http://ee-staff.ethz.ch/~oetiker/webtools/mrtg/mrtg.html
Под 9-ку вывод "onstat -p" все равно другой. Вкратце, как это делается:
1. 5-минутный cron со скриптом вида.
#!/bin/sh
. /etc/default/informix.sh
onstat -p |head -6 |tail -1|awk '{print $3 "\n" $7}'>count.buf
onstat - |head -2 |tail -1|sed -e 's/^.*Up //; s/--.*$//'>>count.buf
echo $INFORMIXSERVER>>count.buf
ну и д.т. и т.п. дабы получить файлик count.buf типа:
650121446
47950419
109 days 22:24:26
ontelebank
2. Еже 5-минутный запуск MRTG (можно в том же cron-e, настройки его
описывать не буду, они у меня далековато и логина туда нет, а ножками не
дойду).
3. Наслаждаемся через WEB ежедневными, еженедельными, ежемесячными,
ежегодными, ... графиками.
Regards, Igor.
Vasyl Shulzhenko
"Igor Zavgorodny" <dau...@torba.com> wrote in message
news:3D92D8D2...@torba.com...
> Hi, All.
>
> IDS 9.21.UC2 Solaris x86.
>
> У меня, спасибо Юрику Шестакову, вот уже несколько лет стоит мониторинг
> через связку "onstat -p" и MRTG за сервером. Достаточно давно я заметил,
> что сервер временами проявляет необъснимую "ночную" активность, хотя
> после 21:30 в системе остается только файловый-робот, выполняющий раз в
> час reconnect к серверу, согласно логам роботам, ночью роботы у него не
> было (и не могло быть) + "ontape -c", регламентные операции к этому
> времени все выполненны. Тем не менее:
А в своп ничего не сбрасывается ?
И вообще, удалось обнаружить причины ночной активности ?
> 02:01:45 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
> not flushed.
> 02:06:45 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
> not flushed.
.....
> 02:21:45 Checkpoint Completed: duration was 0 seconds.
> 02:21:45 Checkpoint loguniq 28121, logpos 0xc018
>
> Таким образом, видно, что "свистопляска" началась после того, как Fuzzy
> сменились обычными Checkpoint-ами. Но чем занимался сервер в это время,
Как это "после" ? А до этого это не "свистопляска" ?
Может это попытки сбросить одни и те самые 6 буферов ?
Кстати, а почему происходит смена Fuzzy на обычный ?
Igor Zavgorodny
>
> А в своп ничего не сбрасывается ?
активной работе).
> И вообще, удалось обнаружить причины ночной активности ?
Нет. Я 3 недели в разъездах по стране провел.
Впрочем, впоследнее время "активность" стала стабильно наблюдаться в
воскресенье, на следующих выходных по стараюсь по-мониторить.
>
>
>>02:01:45 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
>>not flushed.
>>02:06:45 Fuzzy Checkpoint Completed: duration was 0 seconds, 6 buffers
>>not flushed.
>
> .....
>
>>02:21:45 Checkpoint Completed: duration was 0 seconds.
>>02:21:45 Checkpoint loguniq 28121, logpos 0xc018
>>
>>Таким образом, видно, что "свистопляска" началась после того, как Fuzzy
>>сменились обычными Checkpoint-ами. Но чем занимался сервер в это время,
> Как это "после" ? А до этого это не "свистопляска" ?
До этого нету "ненормальной активности" в дисковом чтении-записи, в
buffer&lchwaits и т.д.
> Может это попытки сбросить одни и те самые 6 буферов ?
> Кстати, а почему происходит смена Fuzzy на обычный ?
Потому как лог.наполняется (минимальная нормальная активность все таки
есть), так как раз в час единственный живой робот-пользователь
осуществляет реконнект к базе.
Впрочем, как мне кажется, смена типа чекпоинта не причем. По крайней
мере оно никак не состыковывается с лог-ами за последнюю субботу
воскресенье.
Сейчас у меня появилась еще одна версия, связанная с тем, что сервер раз
в час синхронизирует время по ntp. Возможно, это как-то может
отрицательно влиять на IDS. Вообщем, прийдется делать суровый мониторинг
в выходные, без этого не обойтись :-(.
Regards, Igor.