Thread "Item Poller" does not respond to watchdog thread

Victor Kirhenshtein

@anth0ny said in Thread "Item Poller" does not respond to watchdog thread:

Интерес не праздный: столкнулся вчера со странной проблемой. По неясной мне пока причине вчера на двух серверах наблюдал странную картину, возможно схожую с твоей...

2 одинаковых сервера, опрос одинаковых сервисов ведётся через ServiceCheck.HTTP.

Так вот, в какой-то момент времени я вдруг обнаружил, что опрос приостановился, т.е. в истории полученных результатов начиная со времени "Х" виден перерыв, минут на 40 (интервал опроса- 300 секунд), до следующего полученного результата опроса, "У". Причём что самое странное, одновременно (примерно, учитывая сдвиги между поллами) на обоих серверах. Я не могу пока понять что это. И это не очень приятно, так как именно на этот самый промежуток пришлось падение www-сервиса на одном из этих серверов...

U ob'ekta servera monitoringa dolzen bit' DCI pod nazvaniem "Average length of data collection poller's request queue for last minute" - kak on menjalsja v eto vremja?

Anth0ny

проверил - всё по нулям...
как ДО, так и ВО ВРЕМЯ и уже ПОСЛЕ возникновения инцидента...

нули.

isherim

@victor said in Thread "Item Poller" does not respond to watchdog thread:

Item poller - eto potok, kotorij otvechaet za postanovku DCI v ochered' na sbor dannih. On perestaet otvechat' iz-za vnutrennih blokirovok - t.e. kakoe-to dejstvie s ob'ektom uzla sil'no zatjanulos', i vse ostal'nie, v tom chisle item poller, zdali svoej ocheredi na dostup k etomu ob'ektu. V normal'noj situacii takogo proishodit' ne dolzno.

A mozno vkljuchit' 6 uroven' debug'a dljanetxmsd i prislat' mne log?

Best regards,
Victor

Лог пишется, скину. Возможны блокировки по причине большого количества опрашиваемых объектов?

Victor Kirhenshtein

Само по себе большое количество объектов блокировки вызывать не должно. А вот несколько недоступных узлов могут. Я просматривал код, связанный с этими блокировками - еще одна возможная причина - медленная работа базы данных одновременно с наличием большого количества измененных объектов (напримет после изменений в топологии сети, добавления новых узлов, изменения в шаблонах).

Anth0ny

@victor said in Thread "Item Poller" does not respond to watchdog thread:

@anth0ny said in Thread "Item Poller" does not respond to watchdog thread:

Интерес не праздный: столкнулся вчера со странной проблемой. По неясной мне пока причине вчера на двух серверах наблюдал странную картину, возможно схожую с твоей...

2 одинаковых сервера, опрос одинаковых сервисов ведётся через ServiceCheck.HTTP.

Так вот, в какой-то момент времени я вдруг обнаружил, что опрос приостановился, т.е. в истории полученных результатов начиная со времени "Х" виден перерыв, минут на 40 (интервал опроса- 300 секунд), до следующего полученного результата опроса, "У". Причём что самое странное, одновременно (примерно, учитывая сдвиги между поллами) на обоих серверах. Я не могу пока понять что это. И это не очень приятно, так как именно на этот самый промежуток пришлось падение www-сервиса на одном из этих серверов...

U ob'ekta servera monitoringa dolzen bit' DCI pod nazvaniem "Average length of data collection poller's request queue for last minute" - kak on menjalsja v eto vremja?

хмм... снова те же симптомы.
попробую описать более подробно.

конфиг (немного урезанный) сервера NetXMS (Win2008):

DBSyntax	PGSQL
EnableZoning	0
SyncInterval	60
RoutingTableUpdateInterval	300
ConditionPollingInterval	60
ResolveNodeNames	1
NumberOfEventProcessors	1
ClientListenerPort	4701
NumberOfDiscoveryPollers	1
NumberOfRoutingTablePollers	5
ActiveNetworkDiscovery	0
ActiveDiscoveryInterval	7200
DiscoveryFilterFlags	0
DiscoveryFilter	none
HouseKeepingInterval	3600
EnableSNMPTraps	1
AgentUpgradeWaitTime	600
KeepAliveInterval	60
DefaultEncryptionPolicy	1
AllowedCiphers	15
EnableMultipleDBConnections	1
NumberOfDatabaseWriters	1
IcmpPingSize	46
SyslogListenPort	514
StatusCalculationAlgorithm	1
StatusPropagationAlgorithm	1
FixedStatusValue	0
StatusShift	0
CapabilityExpirationTime	604800
DefaultCommunityString	public
DisableVacuum	0
LockTimeout	60000
InternalCA	0
SNMPRequestTimeout	2000
AgentCommandTimeout	2000
TopologyExpirationTime	900
TopologyDiscoveryRadius	3
EnableAuditLog	1
ThresholdRepeatInterval	0
PollCountForStatusChange	1
AllowDirectSMS	0
EnableEventStormDetection	0
EventStormEventsPerSecond	100
EventStormDuration	15
BeaconTimeout	1000
BeaconPollingInterval	1000
CheckTrustedNodes	1
RunNetworkDiscovery	0
DiscoveryPollingInterval	14400
StatusPollingInterval	60
ConfigurationPollingInterval	3600
EnableAdminInterface	1
DBFormatVersion	83
EnableSyslogDaemon	1
LogAllSNMPTraps	1
SyncNodeNamesWithDNS	1
UseInterfaceAliases	1
SyslogRetentionTime	180
EventLogRetentionTime	90
AuditLogRetentionTime	90
DeleteEmptySubnets	0
NumberOfConditionPollers	10
NumberOfConfigurationPollers	5
NumberOfDataCollectors	15
NumberOfStatusPollers	15
NumberOfUpgradeThreads	5

2 одинаковых сервера (Win2003).

конфиги агентов:

MasterServers = monitoring.test.ru, 127.0.0.1
LogFile = {syslog}
FileStore = C:\Program Files\NetXMS\var
SubAgent = ecs.nsm
SubAgent = winperf.nsm
SubAgent = wmi.nsm
SubAgent = ups.nsm
SubAgent = portcheck.nsm

мониторим сервис "Yandex.server" (http://company.yandex.ru/technology/server/, локальная поисковая машина, поиск в проиндексированном контенте).
сервис откликается на порту 17000, отдаёт web-контент.
интервал опроса = 300 секунд (12 запросов в час).
строка запроса: ServiceCheck.HTTP(10.100.122.133,17000,/IOLib.XBook?text=%F5%E0%EC%E5%EB%E5%EE%ED,localyandex.test.ru,"^HTTP/1\.[01] 200.*<html.*green.*")
(%F5%E0%EC%E5%EB%E5%EE%ED = хамелеон)
DCI находятся на обоих серверах.

в основном всё вроде выглядит хорошо, НО только до какого-то определённого момента.
вот и вчера опять приключилась фигня =(

всё те же симптомы, что я описывал ранее: вдруг обнаруживается, что результаты запросов не попадают в Базу мониторинга. и примерно в это время сервис, который мы мониторим, падает. я сделал экспорт результатов ответа Агента за тот проблемный день (5 окт. с 14 до 21) и вот что получилось (проблемные участки выделены --->

сервер 1

05-Oct-2008	16:56:13	3
05-Oct-2008	16:51:13	3
05-Oct-2008	16:46:12	3
05-Oct-2008	16:41:12	3
05-Oct-2008	16:36:12	3
05-Oct-2008	16:31:12	3
05-Oct-2008	16:26:12	3
05-Oct-2008	16:21:12	3
05-Oct-2008	16:16:12	3
05-Oct-2008	16:11:12	3
05-Oct-2008	16:06:11	3
05-Oct-2008	16:01:11	3
05-Oct-2008	15:56:11	3
05-Oct-2008	15:51:11	3
05-Oct-2008	15:46:11	3
05-Oct-2008	15:41:10	3
05-Oct-2008	15:36:10	3
05-Oct-2008	15:31:10	3
---> 05-Oct-2008	15:26:10	3
---> 05-Oct-2008	14:00:29	0
05-Oct-2008	13:55:29	0
05-Oct-2008	13:50:29	0
05-Oct-2008	13:45:29	0
05-Oct-2008	13:40:29	0
05-Oct-2008	13:35:29	0
05-Oct-2008	13:30:29	0
05-Oct-2008	13:25:29	0
05-Oct-2008	13:20:29	0
05-Oct-2008	13:15:29	0
05-Oct-2008	13:10:29	0
05-Oct-2008	13:05:29	0
05-Oct-2008	13:00:29	0

сервер 2

05-Oct-2008	21:57:00	0
05-Oct-2008	21:52:00	0
05-Oct-2008	21:47:00	0
05-Oct-2008	21:42:00	0
05-Oct-2008	21:37:00	0
05-Oct-2008	21:32:00	0
05-Oct-2008	21:27:00	0
05-Oct-2008	21:22:00	0
05-Oct-2008	21:17:00	0
05-Oct-2008	21:12:00	0
05-Oct-2008	21:07:00	0
05-Oct-2008	21:02:00	0
05-Oct-2008	20:57:00	0
05-Oct-2008	20:52:00	0
05-Oct-2008	20:47:00	0
---> 05-Oct-2008	20:42:00	0
---> 05-Oct-2008	14:19:13	0
05-Oct-2008	14:14:13	0
05-Oct-2008	14:09:13	0
05-Oct-2008	14:04:12	0
05-Oct-2008	13:59:11	0
05-Oct-2008	13:54:11	0
05-Oct-2008	13:49:11	0
05-Oct-2008	13:44:11	0
05-Oct-2008	13:39:11	0
05-Oct-2008	13:34:11	0
05-Oct-2008	13:29:11	0
05-Oct-2008	13:24:11	0
05-Oct-2008	13:19:11	0
05-Oct-2008	13:14:11	0
05-Oct-2008	13:09:11	0
05-Oct-2008	13:04:11	0

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

вот данные за этот подозрительный период:

Average length of configuration poller queue for last minute
все полученные значения - "0.000000".

Average length of data collection poller's request queue for last minute
все полученные значения типа "0.000000" мной удалены для уменьшения текста

...
05-Oct-2008 20:47:30	7.416667
05-Oct-2008 19:30:27	2.166667
05-Oct-2008 18:27:27	3.916667
05-Oct-2008 18:17:22	2.166667
05-Oct-2008 16:37:20	0.666667
05-Oct-2008 15:38:16	4.000000
05-Oct-2008 15:22:14	5.750000
05-Oct-2008 14:32:11	0.166667
...

Average length of database writer's request queue for last minute
почти все полученные значения типа "0.000000" мной удалены для уменьшения текста

...
05-Oct-2008 20:44:28	0.000000
05-Oct-2008 20:43:28	1.750000
05-Oct-2008 20:42:28	1.333333
05-Oct-2008 20:11:28	1.333333
05-Oct-2008 20:10:28	1.000000
05-Oct-2008 20:09:28	4.666667
05-Oct-2008 20:08:28	9.083333
05-Oct-2008 20:05:27	970.583333
05-Oct-2008 20:04:27	1639.750000
05-Oct-2008 20:03:27	1374.416667
05-Oct-2008 20:02:27	1022.916667
05-Oct-2008 20:01:27	725.000000
05-Oct-2008 20:00:27	203.416667
05-Oct-2008 19:30:27	0.250000
05-Oct-2008 19:29:27	6.916667
05-Oct-2008 19:28:27	6.166667
05-Oct-2008 19:27:27	3.416667
05-Oct-2008 19:26:27	5.666667
05-Oct-2008 19:25:27	3.000000
05-Oct-2008 19:23:27	0.666667
05-Oct-2008 19:20:27	4.833333
05-Oct-2008 19:18:27	1.166667
05-Oct-2008 19:10:27	7.250000
05-Oct-2008 19:09:27	2.166667
05-Oct-2008 19:08:27	5.666667
05-Oct-2008 19:05:27	890.916667
05-Oct-2008 19:04:27	1613.583333
05-Oct-2008 19:03:27	1354.250000
05-Oct-2008 19:02:27	1010.083333
05-Oct-2008 19:01:27	706.083333
05-Oct-2008 19:00:27	202.750000
05-Oct-2008 18:18:22	0.083333
05-Oct-2008 18:17:22	0.166667
05-Oct-2008 18:16:22	6.666667
05-Oct-2008 18:15:22	5.416667
05-Oct-2008 18:14:22	4.500000
05-Oct-2008 18:13:22	2.666667
05-Oct-2008 18:12:22	2.500000
05-Oct-2008 18:11:22	5.750000
05-Oct-2008 18:10:22	5.583333
05-Oct-2008 18:09:22	6.583333
05-Oct-2008 18:08:22	6.500000
05-Oct-2008 18:05:22	875.250000
05-Oct-2008 18:04:22	1592.666667
05-Oct-2008 18:03:22	1337.000000
05-Oct-2008 18:02:22	990.583333
05-Oct-2008 18:01:21	696.166667
05-Oct-2008 18:00:21	163.000000
05-Oct-2008 17:55:21	0.416667
05-Oct-2008 17:54:21	5.750000
05-Oct-2008 17:45:21	0.250000
05-Oct-2008 17:44:21	0.583333
05-Oct-2008 17:11:21	9.333333
05-Oct-2008 17:05:21	1331.916667
05-Oct-2008 17:04:21	1642.166667
05-Oct-2008 17:03:21	1358.833333
05-Oct-2008 17:02:21	1004.500000
05-Oct-2008 17:01:21	716.000000
05-Oct-2008 17:00:21	167.166667
05-Oct-2008 16:37:20	0.500000
05-Oct-2008 16:36:20	0.416667
05-Oct-2008 16:11:20	0.916667
05-Oct-2008 16:10:20	0.666667
05-Oct-2008 16:09:20	1.750000
05-Oct-2008 16:08:20	0.500000
05-Oct-2008 16:06:19	8.166667
05-Oct-2008 16:05:19	1003.083333
05-Oct-2008 16:04:19	1608.333333
05-Oct-2008 16:03:19	1344.166667
05-Oct-2008 16:02:19	988.500000
05-Oct-2008 16:01:19	700.000000
05-Oct-2008 16:00:19	124.500000
05-Oct-2008 15:56:19	10.250000
05-Oct-2008 15:38:16	10.250000
05-Oct-2008 15:25:16	0.250000
05-Oct-2008 15:05:11	1326.166667
05-Oct-2008 15:04:11	1654.166667
05-Oct-2008 15:03:11	1387.000000
05-Oct-2008 15:02:11	1023.750000
05-Oct-2008 15:01:11	735.083333
05-Oct-2008 15:00:11	85.500000
05-Oct-2008 14:52:11	5.583333
05-Oct-2008 14:51:11	5.833333
05-Oct-2008 14:50:11	5.750000
05-Oct-2008 14:49:11	3.583333
05-Oct-2008 14:48:11	2.166667
05-Oct-2008 14:46:11	4.666667
05-Oct-2008 14:45:11	3.833333
05-Oct-2008 14:44:11	0.000000
05-Oct-2008 14:43:11	1.666667
05-Oct-2008 14:26:11	0.083333
05-Oct-2008 14:11:11	18.000000
05-Oct-2008 14:10:11	5.583333
05-Oct-2008 14:09:11	4.250000
05-Oct-2008 14:08:11	4.500000
05-Oct-2008 14:07:11	9.166667
05-Oct-2008 14:05:11	1300.333333
05-Oct-2008 14:04:11	1661.916667
05-Oct-2008 14:03:11	1390.750000
05-Oct-2008 14:02:11	1024.833333
05-Oct-2008 14:01:11	735.750000
05-Oct-2008 14:00:11	84.250000
05-Oct-2008 13:59:11	0.000000
...

Average length of status poller queue for last minute
все полученные значения - "0.000000".

Average time to queue DCI for polling for last minute
почти все полученные значения типа "0.000000" мной удалены для уменьшения текста

...
05-Oct-2008 20:45:28	0
05-Oct-2008 20:44:28	1
05-Oct-2008 20:35:28	1
05-Oct-2008 20:34:28	1
05-Oct-2008 20:24:28	1
05-Oct-2008 20:14:28	1
05-Oct-2008 20:07:28	5
05-Oct-2008 19:56:27	1
05-Oct-2008 19:47:27	1
05-Oct-2008 19:46:27	1
05-Oct-2008 19:34:27	1
05-Oct-2008 19:27:27	1
05-Oct-2008 19:25:27	1
05-Oct-2008 19:24:27	1
05-Oct-2008 19:14:27	2
05-Oct-2008 19:07:27	36
05-Oct-2008 18:56:27	1
05-Oct-2008 18:54:27	1
05-Oct-2008 18:44:27	2
05-Oct-2008 18:34:27	1
05-Oct-2008 18:27:27	1
05-Oct-2008 18:14:22	1
05-Oct-2008 18:07:22	27
05-Oct-2008 17:54:21	1
05-Oct-2008 17:34:21	1
05-Oct-2008 17:26:21	1
05-Oct-2008 17:24:21	1
05-Oct-2008 17:14:21	1
05-Oct-2008 17:07:21	3
05-Oct-2008 16:54:21	1
05-Oct-2008 16:46:20	1
05-Oct-2008 16:44:20	1
05-Oct-2008 16:36:20	1
05-Oct-2008 16:34:20	1
05-Oct-2008 16:24:20	1
05-Oct-2008 16:16:20	1
05-Oct-2008 16:14:20	1
05-Oct-2008 16:07:20	40
05-Oct-2008 15:56:19	1
05-Oct-2008 15:54:19	1
05-Oct-2008 15:35:16	1
05-Oct-2008 15:24:14	1
05-Oct-2008 15:07:12	33
05-Oct-2008 14:45:11	1
05-Oct-2008 14:40:11	1
05-Oct-2008 14:38:11	1
05-Oct-2008 14:26:11	1
05-Oct-2008 14:07:11	37
05-Oct-2008 14:00:11	0
...

что не понятно:

почему сервер NetXMS не генерирует никаких системных оповещений в случае, если запрос отправлен, а результат запроса не получен?
если сервисы валятся на обоих серверах в разное время, точно не одновременно, то почему проблема с неполучением данных возникает на обоих серверах приблизительно в одно время?

что сейчас делается:

для проверки на обоих клиентах включён "--debug=7" и складирование выходных данных в локальный лог-файл.
созданы дополнительные 2 DCI, которые вынесены на сам сервер мониторинга (на самих серверах с сервисом Yandex'а DCI тоже оставлены). чтобы посмотреть есть ли зависимость глюка от расположения DCI.

надеюсь, я дал исчерпывающую информацию
готов ответить на наводящие вопросы.

Victor Kirhenshtein

Буду сегодня вечером все это анализировать. Очень жду логи...

Anth0ny

как только обсёр случится, я пришлю логи с агентов...

Anth0ny

Виктор, обнаружил дополнительную информацию, которая возможно объясняет возникновение ранее описанной проблемы с перерывами в получении данных!

Просмотрел системный лог сервера, Агент которого ЯКОБЫ не отвечал. И обнаружил тьму однотипных записей (причём что ОЧЕНЬ интересно: ВСЕ записи представлены по ДВА раза), которые приходятся как раз на этот проблемный период и я так подозреваю что КАЖДАЯ ЗАПИСЬ = 1 ЦИКЛУ ОПРОСА (парные записи иду с одинаковым временем и интервалом ровно в 1 минуту):

Event Type:	Warning
Event Source:	NetXMS Win32 Agent
Event Category:	None
Event ID:	13
Date:		05.10.2008
Time:		20:22:01
User:		N/A
Computer:	MYSERVER1

Description:
Too many communication sessions open - unable to accept new connection

Может быть мы имеем дело со своеобразным переполнением буфера в Агенте?
Если опрашиваемый мной сервис по какой-то причине начинает отвечать с бОльшими задержками, чем может переварить Агент и все последующие запросы (включая ежеминутные запросы о статусе Агента) начинают накапливаться в очереди, возможен такой эффект?

Т.е. не прошедшие запросы создают своего рода "пробку".
При этом Агент считается Сервером вполне работающим.

Anth0ny

получено ещё одно подтверждение: мне сообщили что сервис Яндекса обделался ~20 минут назад, я проверил консоль мониторинга- всё ок. НО в архиве ответов агента серверу образовался провал, который как раз начинается с момента падения сервиса Яндекса и длился он (я специально проверил) до тех пор, пока я вручную не рестартовал этот сервис...

интересно вот что: сервис Яндекса зависает не полностью, а как бы чего-то ждёт... т.е. сразу отлупа при заходе на порт сервиса не происходит, а появляется стандартное Page loading, please wait... но запрошенная страница так и не появляется.

и в таком состоянии он и считается упавшим... но сам-то сервис не остановился.
и запросы на соединение принимает..

=(

т.е. в этом случае, я так думаю, нужно очевидно применить какой-то из вариантов стандартного ServiceCheck.HTTP но ждать не конкретного ответа, а любого ответа и ТОЛЬКО НЕ БОЛЕЕ ЧЕМ за указанный период времени (таймаут).

это возможно реализовать?

Victor Kirhenshtein

Teper' ponjatno. Pohoze chto na connect timeout dovol'no bol'shoj, poetomu soedinenija visjat, t.e. s tochki zrenija agenta zapros na znachenie parametra do konca ne obrabotan. Po umolchaniju agent prinimaet ne bolee 32 odnovremennih zaprosov. Ja k sledujuschemu relizu razberus' s timeout'ami pri proverke servisov, poka chto v kachestve workaround mozno sdelat' dve veschi:

Na agente, gde zagruzen portCheck.nsm, dobavit' parametr MaxSessions = 256 (ili drugoe bol'shoe chislo vplot' do 1024).
Dobavit' esche odin threshold na parametr ServiceCheck.HTTP na oshibku sbora dannih - togda mozno budet uznavat' o takih problemah. Ponjatno chto oshibka sbora DCI ne oznachaet chto service ne rabotaet, mogut bit' i drugie prichini, no po krajnej mere budet vidno chto kakie-to problemi est'.

isherim

За время работы в режиме дебага(сутки) данное сообщение не появлялось. Может поискать что-то конкретное в логе-он очень объемный?

Anth0ny

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

2 - имеется в виду Condition типа "Data collection error"?
т.е. если я выставлю Data collection error = 2 consecutive samples, то при двух ушедших и не вернувших значения запросах я получу срабатывание трешолда?

Victor Kirhenshtein

@anth0ny said in Thread "Item Poller" does not respond to watchdog thread:

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

Не совсем так плохо. Тайм-аут на подключение все-таки есть, просто он большой. Постепенно эти зомби-сессии будут завершаться. Ну и в любом случае это временное решение.

@anth0ny said in Thread "Item Poller" does not respond to watchdog thread:

2 - имеется в виду Condition типа "Data collection error"?
т.е. если я выставлю Data collection error = 2 consecutive samples, то при двух ушедших и не вернувших значения запросах я получу срабатывание трешолда?

Да.

Victor Kirhenshtein

@isherim said in Thread "Item Poller" does not respond to watchdog thread:

За время работы в режиме дебага(сутки) данное сообщение не появлялось. Может поискать что-то конкретное в логе-он очень объемный?

Если таких сообщений не было, то и искать нечего - меня интересуют сообщения за период начиная с 5-10 минут перед появлением сообщений "thread not responding...".
Старые логи можно смело стирать.

Anth0ny

Использование "Data collection error" не помогло... нет никакого эффекта.
Сегодня добавил MaxSessions.

Посмотрим на результат...

NetXMS Forum

Thread "Item Poller" does not respond to watchdog thread