Windows Server 2008R2 のProcesser Time監視が非常に不安定です。
Windows Server 2008R2のパフォーマンスカウンタ Processer Timeを監視しているのですが、
不定期で値の収集ができなくなったり、再び収集できるようになったり、
動作が非常に不安定です。
収集できなくなる時間は不定で、30分程度の時もあれば、
1時間以上値が収集できなくなる時もあります。
また収集できなくなる間隔も不定期で、
3時間収集可能なときもあれば、15分で収集不能になる場合もあります。
2台監視しているのですが2台とも同じ状況です。
仮想環境のWindows Server 2008R2を監視している際には、
このような現象は起きなかったのですが…。
設定に問題があるのでしょうか…。
Agentのログ設定をDebugにして稼働していますが、
エラーは見受けられませんでした。
何か情報をお持ちでしたらアドバイスをお願いいたします。
環境:
○Zabbixサーバー
OS:CentOS 5.9
Zabbix Server:1.8.16
○監視対象
OS:Windows Server 2008 R2
Zabbix Agent:1.8.15
○収集アイテム
タイプ:Zabbixエージェント
キー:perf_counter[\Processor(_Total)\% Processor Time]
データ型:数値(浮動小数)
単位:%
乗数を使用:OFF
更新間隔:15秒
例外の更新間隔:無し
ヒストリの保存期間:7日
トレンドの保存期間:365日
ステータス:有効
値のマッピングの使用:なし
アプリケーションの作成:なし
アプリケーション:Performance、CPU
KAZ - 投稿数: 1085
Makoto Fusegiさん
そのマシンで他の監視(ping監視等)は問題なく取れていますか?
Makoto Fusegi - 投稿数: 19
Ping監視は実施していないのですが、
下記のキーは欠ける事無く取得できています。
perf_counter[\PhysicalDisk(_Total)\Avg. Disk Read Queue Length]
perf_counter[\PhysicalDisk(_Total)\Avg. Disk Write Queue Length]
perf_counter[ Read Queue Length]
perf_counter[\PhysicalDisk(_Total)\Avg. Disk Write Queue Length]
perf_counter[\Syst Queue Length]
perf_counter[\PhysicalDisk(_Total)\Avg. Disk Write Queue Length]
perf_counter[\System\File Read Bytes/sec]
perf_counter[\System\File Write Bytes/sec]
vfs.fs.size[c:,free]
vm.memory.size[free]
system.swap.size[,free]
system.cpu.util[,system,avg1]
vm.memory.size[bytes]
KAZ - 投稿数: 1085
Makoto Fusegiさん
サーバ側のログにもエラー等は出ていませんか?
KAZ - 投稿数: 1085
Makoto Fusegiさん
サーバ側のログにもエラー等は出ていませんか?
Makoto Fusegi - 投稿数: 19
KAZさん
サーバー側のログに下記のようなエラー?が出ていました。
ログファイル:
/var/log/zabbix/zabbix_server.log
内容:
item [サーバー名:perf_counter[\Processor(_Total)\% Processor Time]] became not supported: Not supported by Zabbix Agent
item [サーバー名:perf_counter[\Processor(_Total)\% Processor Time]] became supported
Not supportedとsupportedの状態を繰り返している。
Windows Server 2008R2の仮想環境を作成し、
テスト監視を行っているのですが、その際にはこのようなエラーは出ていませんでした。
ハードウェアが変われば監視できなくなるような事があるのでしょうか?
KAZ - 投稿数: 1085
Makoto Fusegiさん
仮想環境のOSは32bitですか?64bitですか?
また、今回障害が出ているOSは32bitですか?64bitですか?
Makoto Fusegi - 投稿数: 19
KAZさん
仮想環境、障害環境共に64bitです。
Agentも64bit用の物を使用しています。
KAZ - 投稿数: 1085
Makoto Fusegiさん
下記の2件が事象が似ているように見えます。
https://www.zabbix.com/forum/showthread.php?t=40793
https://www.zabbix.com/forum/showthread.php?t=14297
DOSプロンプトで下記のコマンドを実行し、結果を取得していただけますか?
typeperf -qx > perfcounter.txt
Makoto Fusegi - 投稿数: 19
KAZさん
コマンドの結果下記のカウンターは存在していました。
\Processor(_Total)\% Processor Time
一点、気になったのですが、
こちらのリンクでは、
https://www.zabbix.com/forum/showthread.php?t=14297
アイテムの設定で、
タイプをZabbixエージェント(アクティブ)にしていました。
現在監視を実施している環境では、
監視対象サーバーからZabbixサーバーに対して、
10051ポートをオープンにする事がルール上出来ない環境です。
したがって、
アイテムのタイプはZabbixエージェントにしていますし、
zabbix_agent.confのDisableActiveの値も1にして無効化しています。
これが悪さを働いている可能性はあるのでしょうか?
KAZ - 投稿数: 1085
Makoto Fusegiさん
DisableActiveは1でOKなはずと思ったのですが、マニュアル見るとZabbixエージェントのUnix/LinuxとWindowsで設定項目が違うようです。
※:Windows用のエージェントにDisableActiveはないようです。
https://www.zabbix.com/documentation/jp/1.8/manual/processes/zabbix_agen...
zabbix_agent.confを見直して頂けますでしょうか?
後、MaxCollectorProcessingTimeはの値が気になります。
値はデフォルトでしょうか?
デフォルトでしたら値を500位に変えてみて頂けますか?
Makoto Fusegi - 投稿数: 19
KAZさん
MaxCollectorProcessingTimeは省略していました。
500を設定したところ、起動しなくなりました。
エージェントの設定に問題があるのでしょうか?
KAZ - 投稿数: 1085
Makoto Fusegiさん
> MaxCollectorProcessingTimeは省略していました。
> 500を設定したところ、起動しなくなりました。
説明がデータを収集する許容時間っぽい内容なので値を大きくしたら良いかと思ったのですが…
すいません、MaxCollectorProcessingTimeはデフォルトに戻して頂けますでしょうか?
> エージェントの設定に問題があるのでしょうか?
エージェントの設定の問題ではないように思えます。
zabbix_agent.confから「DisableActive」を外した状態で、事象は変わらない状態でしょうか?
Makoto Fusegi - 投稿数: 19
KAZさん
いつも返信ありがとうございます。
MaxCollectorProcessingTimeをデフォルトである100に設定しても起動しません。
省略すれば起動しますが・・・。
エージェント自体に異常があるのでしょうか?
DisableActiveを省略しても状況は変わりませんでした。
KAZ - 投稿数: 1085
Makoto Fusegiさん
MaxCollectorProcessingTimeについて↓ここで確認したのですが、既知の問題としては載ってないようです。
https://support.zabbix.com/secure/Dashboard.jspa
エージェントのログレベルを4にして、起動しなかった時のログでエラーが出ているかご確認いただけませんか?
また、perf_counterについても検索しているのですが、こちらは量が多く英語なので読むのに手間取っています。
これからZabbix Server:1.8.16/Zabbix Agent:1.8.15のソースゲットして読んでみます。
Makoto Fusegi - 投稿数: 19
KAZさん
MaxCollectorProcessingTime=100
DebugLevel=4
にてZabbix Agentdサービスを起動した所、
ローカル コンピューターのZabbix Agent サービスを開始できません。
エラー 1053: そのサービスは指定時間内に開始要求または制御要求に応答しませんでした。
とWindowsのエラーメッセージが表示されます。
Zabbix Agentのログは出力すらされません。
KAZ - 投稿数: 1085
Makoto Fusegiさん
Zabbix Agent:1.8.15のソース読みました。
MaxCollectorProcessingTimeなんて項目ありませんでした。
マニュアルが間違っているようです。
報告しておきます。
色々とすませんでした。
これからZabbix Server:1.8.16のソース読みます。
以下、Zabbix Agent:1.8.15のソースの該当の箇所です。
/******************************************************************************
* *
* Function: zbx_load_config *
* *
* Purpose: load configuration from config file *
* *
* Parameters: requirement - produce error if config file missing or not *
* *
******************************************************************************/
static void zbx_load_config(int requirement)
{
char *p, *active_hosts = NULL;
struct cfg_line cfg[] =
{
/* PARAMETER, VAR, TYPE,
MANDATORY, MIN, MAX */
{"Server", &CONFIG_HOSTS_ALLOWED, TYPE_STRING,
PARM_MAND, 0, 0},
{"ServerActive", &active_hosts, TYPE_STRING,
PARM_OPT, 0, 0},
{"Hostname", &CONFIG_HOSTNAME, TYPE_STRING,
PARM_OPT, 0, 0},
{"HostnameItem", &CONFIG_HOSTNAME_ITEM, TYPE_STRING,
PARM_OPT, 0, 0},
{"BufferSize", &CONFIG_BUFFER_SIZE, TYPE_INT,
PARM_OPT, 2, 65535},
{"BufferSend", &CONFIG_BUFFER_SEND, TYPE_INT,
PARM_OPT, 1, SEC_PER_HOUR},
#ifdef USE_PID_FILE
{"PidFile", &CONFIG_PID_FILE, TYPE_STRING,
PARM_OPT, 0, 0},
#endif
{"LogFile", &CONFIG_LOG_FILE, TYPE_STRING,
PARM_OPT, 0, 0},
{"LogFileSize", &CONFIG_LOG_FILE_SIZE, TYPE_INT,
PARM_OPT, 0, 1024},
{"DisableActive", &CONFIG_ACTIVE_DISABLE, TYPE_INT,
PARM_OPT, 0, 1},
{"DisablePassive", &CONFIG_PASSIVE_DISABLE, TYPE_INT,
PARM_OPT, 0, 1},
{"Timeout", &CONFIG_TIMEOUT, TYPE_INT,
PARM_OPT, 1, 30},
{"ListenPort", &CONFIG_LISTEN_PORT, TYPE_INT,
PARM_OPT, 1024, 32767},
{"ServerPort", &CONFIG_SERVER_PORT, TYPE_INT,
PARM_OPT, 1024, 32767},
{"ListenIP", &CONFIG_LISTEN_IP, TYPE_STRING,
PARM_OPT, 0, 0},
{"SourceIP", &CONFIG_SOURCE_IP, TYPE_STRING,
PARM_OPT, 0, 0},
{"DebugLevel", &CONFIG_LOG_LEVEL, TYPE_INT,
PARM_OPT, 0, 4},
{"StartAgents", &CONFIG_PASSIVE_FORKS, TYPE_INT,
PARM_OPT, 1, 100},
{"RefreshActiveChecks", &CONFIG_REFRESH_ACTIVE_CHECKS, TYPE_INT,
PARM_OPT, SEC_PER_MIN, SEC_PER_HOUR},
{"MaxLinesPerSecond", &CONFIG_MAX_LINES_PER_SECOND, TYPE_INT,
PARM_OPT, 1, 1000},
{"AllowRoot", &CONFIG_ALLOW_ROOT, TYPE_INT,
PARM_OPT, 0, 1},
{"EnableRemoteCommands", &CONFIG_ENABLE_REMOTE_COMMANDS, TYPE_INT,
PARM_OPT, 0, 1},
{"LogRemoteCommands", &CONFIG_LOG_REMOTE_COMMANDS, TYPE_INT,
PARM_OPT, 0, 1},
{"UnsafeUserParameters", &CONFIG_UNSAFE_USER_PARAMETERS, TYPE_INT,
PARM_OPT, 0, 1},
{"Alias", &CONFIG_ALIASES, TYPE_MULTISTRING,
PARM_OPT, 0, 0},
{"UserParameter", &CONFIG_USER_PARAMETERS, TYPE_MULTISTRING,
PARM_OPT, 0, 0},
#ifdef _WINDOWS
{"PerfCounter", &CONFIG_PERF_COUNTERS, TYPE_MULTISTRING,
PARM_OPT, 0, 0},
#endif
{NULL}
};
/* initialize multistrings */
zbx_strarr_init(&CONFIG_ALIASES);
zbx_strarr_init(&CONFIG_USER_PARAMETERS);
#ifdef _WINDOWS
zbx_strarr_init(&CONFIG_PERF_COUNTERS);
#endif
parse_cfg_file(CONFIG_FILE, cfg, requirement, ZBX_CFG_STRICT);
set_defaults();
if (ZBX_CFG_FILE_REQUIRED == requirement)
zbx_validate_config();
if (0 != CONFIG_PASSIVE_DISABLE)
CONFIG_PASSIVE_FORKS = 0; /* listeners are not needed for passive checks */
if (0 == CONFIG_ACTIVE_DISABLE && ZBX_CFG_FILE_REQUIRED == requirement)
{
if (NULL == active_hosts || '\0' == *active_hosts)
{
if (NULL != (p = strchr(CONFIG_HOSTS_ALLOWED, ',')))
*p = '\0';
add_activechk_host(CONFIG_HOSTS_ALLOWED, (unsigned short)CONFIG_SERVER_PORT);
if (NULL != p)
*p = ',';
}
else
parse_active_hosts(active_hosts);
}
zbx_free(active_hosts);
}
kodai - 投稿数: 1341
日本語版のマニュアルが古かったです。MaxCollectorProcessingTimeを含め、1.8では使えないパラメータは削除しました。
https://www.zabbix.com/documentation/jp/1.8/manual/processes/zabbix_agen...
KAZ - 投稿数: 1085
Makoto Fusegiさん
MaxCollectorProcessingTimeはZabbixエージェントのログから抜いてください。
すません。
Zabbixサーバのログレベルを4にして「became not supported: Not supported by Zabbix Agent~became supported」がでたらその部分を取得して頂けますか?
※:できれば前後のログも少々欲しいです。
Makoto Fusegi - 投稿数: 19
KAZさん
logを添付します。
IPアドレスやホスト名は置き換えています。
お手数ですがご確認よろしくお願いいたします。
KAZ - 投稿数: 1085
Makoto Fusegiさん
すいません、ログもうちょっと上下付けて頂けませんか?
前後、2~30行追加願いたく。
KAZ - 投稿数: 1085
Makoto Fusegiさん
週末用事があってソース追うのは来週になりそうです。
すいません。
ちなみにzabbix_get でperf_counter取れますか?
これで値が取れないと、そもそも監視できないのですが…A(^^;
現在の処分かっていろ事
①ZabbixエージェントからNot Supportedが返却される
②その後、DCsync_historyでbecame supportedになる。
DCsync_history関数の↓ここら辺まで追ってみました。
if (0 != (daemon_type & ZBX_DAEMON_TYPE_SERVER))
{
DCmass_update_items(history, history_num); <-- ここら辺でbecame supportedが出てるっぽいのですが、おいきれてません
DCmass_add_history(history, history_num);
DCmass_update_triggers(history, history_num);
DCmass_update_trends(history, history_num);
}
else
{
DCmass_proxy_add_history(history, history_num);
DCmass_proxy_update_items(history, history_num);
}
DBcommit();
Makoto Fusegi - 投稿数: 19
KAZさん
前後20行程度追加したものをUPします。
zabbix_getですが対象のパフォーマンスカウンターの取得を確認しています。
KAZ - 投稿数: 1085
Makoto Fusegiさん
>zabbix_getですが対象のパフォーマンスカウンターの取得を確認しています。
了解しました。
ログですが、この下2~30行ほど欲しいのですが…
24617:20130726:100346.887 item [監視対象1:perf_counter[\Processor(_Total)\% Processor Time]] became supported
このログの後、こんな感じで取得した値がログに出るはずなんです。
そこが見たいんです。
↓これはエラーのログで「itemid=23024」が取得できなくNot Supportedになってます。
正常なときは値が取得できているはずで、それが本当に取得できているのか確認したいのです。
24617:20130726:100146.595 In DCadd_nextcheck()
24617:20130726:100146.595 End of DCadd_nextcheck()
24617:20130726:100146.595 query [txnlev:1] [update items set lastclock=1374800505,prevvalue=lastvalue,lastvalue='1' where itemid=18435;
update items set lastclock=1374800506,prevorgvalue='4047768693.000000',prevvalue=lastvalue,lastvalue='510.333333' where itemid=18440;
update items set lastclock=1374800502,prevorgvalue='6630885.000000',prevvalue=lastvalue,lastvalue='2080.200000' where itemid=18442;
update items set lastclock=1374800503,prevorgvalue='2083708548.000000',prevvalue=lastvalue,lastvalue='1058.000000' where itemid=18443;
update items set lastclock=1374800506,prevorgvalue='6638065.000000',prevvalue=lastvalue,lastvalue='1871.000000' where itemid=18445;
update items set lastclock=1374800501,prevvalue=lastvalue,lastvalue='268' where itemid=18461;
update items set lastclock=1374800503,prevvalue=lastvalue,lastvalue='0.360000' where itemid=18468;
update items set lastclock=1374800501,prevvalue=lastvalue,lastvalue='0.000000' where itemid=18471;
update items set lastclock=1374800502,prevvalue=lastvalue,lastvalue='0.251797' where itemid=18472;
update items set lastclock=1374800503,prevvalue=lastvalue,lastvalue='1.921046' where itemid=18473;
update items set lastclock=1374800505,prevvalue=lastvalue,lastvalue='0.004061' where itemid=18474;
update items set lastclock=1374800504,prevvalue=lastvalue,lastvalue='99.530063' where itemid=18493;
update items set lastclock=1374800506,prevvalue=lastvalue,lastvalue='99.530063' where itemid=18496;
update items set lastclock=1374800502,prevvalue=lastvalue,lastvalue='5350064128' where itemid=18522;
update items set lastclock=1374800503,prevvalue=lastvalue,lastvalue='118816862208' where itemid=18523;
update items set lastclock=1374800505,prevvalue=lastvalue,lastvalue='95.691223' where itemid=18524;
update items set lastclock=1374800506,prevvalue=lastvalue,lastvalue='4.308781' where itemid=18525;
update items set lastclock=1374800504,prevvalue=lastvalue,lastvalue='24' where itemid=22993;
update items set lastclock=1374800506,prevvalue=lastvalue,lastvalue='80334823424' where itemid=22995;
update items set lastclock=1374800506,prevvalue=lastvalue,lastvalue='22.089283' where itemid=22996;
update items set lastclock=1374800501,prevorgvalue='1450009370',prevvalue=lastvalue,lastvalue='670386' where itemid=23016;
update items set lastclock=1374800502,prevorgvalue='1199377002',prevvalue=lastvalue,lastvalue='343785' where itemid=23017;
update items set lastclock=1374800503,prevorgvalue='2560793725',prevvalue=lastvalue,lastvalue='65164' where itemid=23018;
update items set lastclock=1374800505,prevorgvalue='1622724946',prevvalue=lastvalue,lastvalue='647487' where itemid=23019;
update items set lastclock=1374800505,status=3,error='Not supported by Zabbix Agent' where itemid=23024;
update items set lastclock=1374800506,prevvalue=lastvalue,lastvalue='27.179153' where itemid=23025;
update items set lastclock=1374800502,prevvalue=lastvalue,lastvalue='575262720' where itemid=23052;
]
Makoto Fusegi - 投稿数: 19
KAZさん
以下のようにログ出力されています。
取得はできているように思えます。
24617:20130726:100346.887 item [監視対象1:perf_counter[\Processor(_Total)\% Processor Time]] became supported
24617:20130726:100346.887 query [txnlev:1] [update items set lastclock=1374800625,prevvalue=lastvalue,lastvalue='1' where itemid=18435;
update items set lastclock=1374800625,prevorgvalue='4047931121.000000',prevvalue=lastvalue,lastvalue='317.000000' where itemid=18440;
update items set lastclock=1374800622,prevorgvalue='6867758.000000',prevvalue=lastvalue,lastvalue='2334.800000' where itemid=18442;
update items set lastclock=1374800623,prevorgvalue='2084626916.000000',prevvalue=lastvalue,lastvalue='309.600000' where itemid=18443;
update items set lastclock=1374800625,prevorgvalue='6873000.000000',prevvalue=lastvalue,lastvalue='1743.200000' where itemid=18445;
update items set lastclock=1374800623,prevvalue=lastvalue,lastvalue='0.650000' where itemid=18468;
update items set lastclock=1374800622,prevvalue=lastvalue,lastvalue='0.324123' where itemid=18472;
update items set lastclock=1374800623,prevvalue=lastvalue,lastvalue='4.185575' where itemid=18473;
update items set lastclock=1374800624,prevvalue=lastvalue,lastvalue='0.012158' where itemid=18474;
update items set lastclock=1374800623,prevvalue=lastvalue,lastvalue='99.530066' where itemid=18493;
update items set lastclock=1374800622,prevvalue=lastvalue,lastvalue='5351424000' where itemid=18522;
update items set lastclock=1374800623,prevvalue=lastvalue,lastvalue='118815490048' where itemid=18523;
update items set lastclock=1374800624,prevvalue=lastvalue,lastvalue='95.690127' where itemid=18524;
update items set lastclock=1374800623,prevvalue=lastvalue,lastvalue='24' where itemid=22993;
update items set lastclock=1374800625,prevvalue=lastvalue,lastvalue='80329383936' where itemid=22995;
update items set lastclock=1374800622,prevorgvalue='1202675073',prevvalue=lastvalue,lastvalue='52792' where itemid=23017;
update items set lastclock=1374800623,prevorgvalue='2561857938',prevvalue=lastvalue,lastvalue='13365' where itemid=23018;
update items set lastclock=1374800624,prevorgvalue='1624446474',prevvalue=lastvalue,lastvalue='1163' where itemid=23019;
update items set lastclock=1374800625,prevvalue=lastvalue,lastvalue='56.922877',status=0,error='' where itemid=23024;
update items set lastclock=1374800622,prevvalue=lastvalue,lastvalue='575262720' where itemid=23052;
]
KAZ - 投稿数: 1085
今までの情報をまとめると…
1)Zabbixエージェントではエラーログが出ていない
2)ZabbixサーバではNot supported ~ supportedを繰り返す。
3)zabbix_getで値が取得できている
上記からネットワークの問題の可能性があります。
DOS窓で以下のコマンドを実行してみてください。
netsh interface tcp show global
下記はWindows7ですが、オフロードとかアドオン輻輳制御プロバイダーはWindows2008も同じ設定で良いはずです。
Makoto Fusegi - 投稿数: 19
KAZさん
NICのオフロード設定は無効にしてあります。
他の収集アイテムが収集できている事を考えると、
ネットワークに原因があるのか不明ですね・・・。
TCP グローバル パラメーター
----------------------------------------------
Receive-Side Scaling 状態 : disabled
Chimney オフロード状態 : disabled
NetDMA 状態 : disabled
Direct Cache Acess (DCA) : disabled
受信ウィンドウ自動チューニング レベル : normal
アドオン輻輳制御プロバイダー : ctcp
ECN 機能 : disabled
RFC 1323 タイムスタンプ : disabled
KAZ - 投稿数: 1085
Makoto Fusegiさん
他の収集アイテムが収集できている事を考えると、
ネットワークに原因があるのか不明ですね・・・。
となると、Zabbixエージェントの問題っぽいですね…
エラーログは出てないということですが、ZabbixサーバログでNot supportedが出ている時間帯のZabbixエージェントのログは収集できますでしょうか?
Makoto Fusegi - 投稿数: 19
KAZさん
すみません。
それらしきログが見つかりました。
カウンターにマイナスの値が返っているようです…。
マイナスの値などありえるのですかね?
############ NOTSUPPORTED ############
1676:20130730:160640.115 In collect_perfstat()
1684:20130730:160640.770 Processing request.
1684:20130730:160640.770 Requested [perf_counter[\Processor(_Total)\% Processor Time]]
1684:20130730:160640.770 In PERF_COUNTER()
1684:20130730:160640.770 PERF_COUNTER(): PerfCounter '\Processor(_Total)\% Processor Time' successfully added
1700:20130730:160641.082 In send_buffer() host:'IPアドレス' port:10051 values:0/100
1700:20130730:160641.082 End of send_buffer():SUCCEED
1676:20130730:160641.129 In collect_perfstat()
1684:20130730:160641.784 P In collect_perfstat()
1684:20130730:160641.784 PERF_COUNTER(): cannot calculate counter value '\Processor(_Total)\% Processor Time': [0x800007D6] 分母の値が負のカウンターが検出されました。
1684:20130730:160641.784 End of PERF_COUNTER()
1684:20130730:160641.784 Sending back [ZBX_NOTSUPPORTED]
1700:20130730:160642.096 In send_buffer() host:'IPアドレス' port:10051 values:0/100
1700:20130730:160642.096 E send_buffer() host:'IPアドレス' port:10051 values:0/100
1700:20130730:160642.096 End of send_buffer():SUCCEED
############ SUPPORTED ############
1676:20130730:161309.492 In collect_perfstat()
1692:20130730:161310.256 P In collect_perfstat()
1692:20130730:161310.256 Processing request.
1692:20130730:161310.256 Requested [perf_counter[\Processor(_Total)\% Processor Time]]
1692:20130730:161310.256 In PERF_COUNTER()
1692:20130730:161310.256 PERF_COUNTER(): PerfCounter '\Processor(_Total)\% Processor Time' successfully added
1700:20130730:161310.459 In send_buffer() host:'IPアドレス' port:10051 values:0/100
1700:20130730:161310.459 End of send_buffer():SUCCEED
1700:20130730:161310.459 Sleeping for 1 second(s)
1676:20130730:161310.506 In collect_perfstat()
1692:20130730:161311.270 End of PERF_COUNTER()
1692:20130730:161311.270 Sending back [58.910073]
1700:20130730:161311.473 In send_buffer() host:'IPアドレス' port:10051 values:0/100
1700:20130730:161311.473 End of send_buffer():SUCCEED
17 1700:20130730:161311.473 End of send_buffer():SUCCEED
1700:20130730:161311.473 Sleeping for 1 second(s)
KAZ - 投稿数: 1085
Makoto Fusegiさん
■確認です。
質問1)
perf_counter[\Processor(_Total)\% Processor Time]は監視対象1、監視対象2の2アイテムありますね?
質問2)
Not supportedがでるのは監視対象1のみ?
■事象のまとめ
1)Zabbixサーバ側の受信時の不具合
→Zabbixサーバの不具合と思われます。
2)Zabbixエージェントとの通信が上手く出来ていない
→ネットワークの問題かもしれません。
■Zabbixサーバのログ検証
下記、'監視対象1と監視対象2に対してのkey:'perf_counter[\Processor(_Total)\% Processor Time]'のログです。
※:途中関係ないと思われるログはカットしてます。
--------zabbix_server.txt抜粋-------------------------
24617:20130726:100146.595 item [監視対象1:perf_counter[\Processor(_Total)\% Processor Time]] became not supported: Not supported by Zabbix Agent
24595:20130726:100344.904 In get_value() key:'perf_counter[\Processor(_Total)\% Processor Time]'
24595:20130726:100344.904 In get_value_agent() host:'監視対象1' addr:'IPアドレス' key:'perf_counter[\Processor(_Total)\% Processor Time]'
24595:20130726:100344.905 Sending [perf_counter[\Processor(_Total)\% Processor Time]]
24592:20130726:100345.898 In get_value() key:'perf_counter[\Processor(_Total)\% Processor Time]'
24592:20130726:100345.898 In get_value_agent() host:'監視対象2' addr:'IPアドレス' key:'perf_counter[\Processor(_Total)\% Processor Time]'
24592:20130726:100345.898 Sending [perf_counter[\Processor(_Total)\% Processor Time]]
24595:20130726:100345.913 get value from agent result: '56.922877'
24595:20130726:100345.913 End of get_value():SUCCEED
24617:20130726:100346.887 item [監視対象1:perf_counter[\Processor(_Total)\% Processor Time]] became supported
--------zabbix_server.txt抜粋-------------------------
見ると分かりますが、監視対象1の「get value from agent result」がないです。
※:「End of get_value()」もないです。
推測になりますが、下記ソースのzbx_tcp_recv_extで処理が止まったか、プロセスが落ちたかしてます。
-------zabbix-1.8.16\src\zabbix_server\poller\checks_agent.cの61行目(get_value_agent関数)---------
/* send requests using old protocol */
if (SUCCEED == (ret = zbx_tcp_send_raw(&s, buffer)))
ret = zbx_tcp_recv_ext(&s, &buf, ZBX_TCP_READ_UNTIL_CLOSE, 0);
-------zabbix-1.8.16\src\zabbix_server\poller\checks_agent.cの61行目(get_value_agent関数)---------
これは通信問題なのかZabbixサーバ/エージェントの問題なのか、現状不明です。
上記を考慮したうえで、後で頂いたログを見ると…
--------追加のログ抜粋-------------------------
update items set lastclock=1374800625,prevvalue=lastvalue,lastvalue='56.922877',status=0,error='' where itemid=23024;
値は監視対象2の値です。
つまり、監視対象2が値取得できたので、監視対象1のステータスがサポートになってます。
※:これはバグですね。
tsuzuki - 投稿数: 78
Makoto Fusegiさん、KAZさん
Makoto Fusegiさんの書かれた内容を見たところ、複数スレッドで同時にパフォーマンスカウンタを使ってますね。
Windows用のZabbixAgentは複数スレッドで動作しているのですが、パフォーマンスカウンタは
複数スレッドで同時にアクセスすることは、Windowsの仕様としてサポートされていません。
↓
http://msdn.microsoft.com/ja-jp/library/48eh73h4(v=vs.71).aspx
「パフォーマンス カウンタは共有メモリに存在するため、カウンタへのアクセスは常にスレッドセーフな方法で行われる必要があります。」
なので、ZabbixAgentは本来ならば同時アクセスにならないようにロックを取って複数スレッドでアクセス
しないようにする必要があります。
複数スレッドで同時に使っているZabbixAgentのバグだと思いました。
tsuzuki - 投稿数: 78
「NOTSUPPORTED」として貼ってもらったログのうち、↓があやしいところです。
複数スレッドでパフォーマンスカウンタまわりの操作をして、変な値が出ている。
--------------------------------------------------
1676:20130730:160641.129 In collect_perfstat()
1684:20130730:160641.784 P In collect_perfstat()
--------------------------------------------------
傍証にしかなりませんが、監視間隔を広げると発生しにくくなるようならば、複数スレッドでの同時アクセスが原因の可能性が高いと思います。
あとは、同様なNOTSUPPORTEDのケースで上記のようなログが出ていないか、いくつか見てみると、原因の箇所が絞れると思います。
他に、いくつかNOTSUPPORTEDのケースのログがあれば貼ってもらえないでしょうか。
よろしくお願いします。
tsuzuki - 投稿数: 78
もう一点、気になる点を見つけました。
通常、collect_perfstat() を実行するスレッドは1つだけなので、複数のスレッドが『In collect_perfstat()』を出力していることは、
複数のZabbixAgentを動作させていたり、複数のZabbixServerから監視してたりするのかもしれないと思ったのですが、そのあたりの
環境がどうなっているか教えてもらってもよろしいでしょうか。
もしくは、ZabbixAgentのログが何らかの原因でおかしくなっている気がします。『P In collect_perfstat()』に『P 』がなぜか入ってるので。
fripper - 投稿数: 495
http://www.zabbix.jp/node/1150
と同じ事象のように見えますね。
しかし、同スレッドでも、明快な解決策は見いだせていないようですが‥
KAZ - 投稿数: 1085
Makoto Fusegiさん
ログありがとうございます。
fripperさんが指摘されている様に同件ぽいですね。
明確な回答がないわけですが…
tsuzukiさん
ありがとうございます!m(__)m
私も引き続き追ってみます。
Makoto Fusegi - 投稿数: 19
KAZさん
返信が遅くなりました。
質問1)
perf_counter[\Processor(_Total)\% Processor Time]は監視対象1、監視対象2の2アイテムありますね?
⇒ 2台のサーバーの対象カウンタを監視しています
質問2)
Not supportedがでるのは監視対象1のみ?
⇒ 当初は2台で発生していたのですが、今現在片側はカウンターの取得はできています。
設定は変えてはいないのですが、気がついたら取れている状態です。
※二台ともOSは一緒です。
Makoto Fusegi - 投稿数: 19
tsuzukiさん
マルチスレッドが原因となるならば、
zabbix_agentd.confの、
StartAgentsの値を1に変更すれば1スレッドによる動作に切り替えられるのでしょうか?
Zabbix Agendはサービスとして登録した1つのみの起動です。
監視サーバーも一つのみです。
Makoto Fusegi - 投稿数: 19
StartAgentsの値を1にしても状況に変化はありませんでした。
KAZ - 投稿数: 1085
Makoto Fusegiさん
検証ありがとうございます。
確証はないのですが、Zabbixサーバ側もおかしな動作をしているように見えます。
引き続きソースを追ってみます。
何か新情報がありましたら書き込み頂けると助かります。
KAZ - 投稿数: 1085
Makoto Fusegiさん
↓この件ですが、WindowsXPやWindows2000でも出ているようです。
[0x800007D6] 分母の値が負のカウンターが検出されました。
また、Zabbix以外のアプリでも同様の問題が出ているようです。
これはWindows自体の問題ですね…
その他…
1)ログが崩れている件(Zabbixエージェント)
2)監視対象2のデータが取得されると監視対象1がサポート状態になる件(Zabbixサーバ)
上記2件を引き続き、追ってみます。
KAZ - 投稿数: 1085
Makoto Fusegiさん
↓この件ですが、Windowsの修復セットアップ等の話が出てます。
[0x800007D6] 分母の値が負のカウンターが検出されました。
http://construweb.net/0x800007d6.php
http://www.nonabyte.net/0x800007d6/
Makoto Fusegi - 投稿数: 19
KAZさん
色々調査いただいてありがとうございます。
Windows自体のバグである可能性が高いとの事ですね。
Microsoftからパッチが出ていればいいのですが、
OS修復用のパッチがMicrosoft製以外となると、
中々許可が下りないかもしれません・・・。
これはProcesser Timeだけで起きる障害なのでしょうかね?
KAZ - 投稿数: 1085
Makoto Fusegiさん
>Windows自体のバグである可能性が高いとの事ですね。
バグというよりOSが破損している可能性があるので、修復セットアップを進めているサイトがありました。
>これはProcesser Timeだけで起きる障害なのでしょうかね?
今週の頭から同じ監視設定を入れて再現試験をしているのですが、私のところでは発生していないので断言ができない状況です。
私の推測ではこの問題には3つの問題が複合して起きているように見えます。
1)WindowsのOS破損
2)Zabbixエージェントでメモリ破壊
3)Zabbixサーバで取得データのとり違い
提供して頂いたZabbixエージェントのログをみると、active_checkプロセスとListenプロセスでメモリ破壊しているように見えるのですが、どの時点でおかしくなっているのか見当がつきません。
できれば、起動からNot supported~supportedがでるまでのログすべてを見たいのですが…
Makoto Fusegi - 投稿数: 19
KAZさん
返答が遅くなりました。
起動からNot supported ~ supportedのログをUPします。
よろしくお願いいたします。
KAZ - 投稿数: 1085
Makoto Fusegiさん
頂いたログはZabbixエージェントの物でしょうか?
Zabbixサーバのログの様な気がしますが…A(^^;
また、Zabbixエージェントを起動すると以下の様なログが出て、どのプロセスが何の処理か分かるので、「起動」からNot supported~supportedがでるまでのログすべてを見たいのですが…
9944:20130815:111046.129 Starting Zabbix Agent [xxxxxxxx]. Zabbix 2.0.6 (revision 35155). <--Zabbixエージェント2.0.6
9944:20130815:111046.157 In init_collector_data()
9944:20130815:111046.157 End of init_collector_data()
9944:20130815:111046.157 In init_perf_collector()
9944:20130815:111046.157 End of init_perf_collector():SUCCEED
9952:20130815:111046.158 agent #0 started [collector] <-- 9952はcollector
9956:20130815:111046.158 agent #1 started [listener] <-- 9956はlistener
9960:20130815:111046.158 agent #2 started [listener] <-- 9960はlistener
9964:20130815:111046.159 agent #3 started [listener] <-- 9964はlistener
9968:20130815:111046.159 agent #4 started [active checks] <-- 9968はactivechecks
■追記
Not supported ~ supportedのログではなく、supported ~ Not supportedのログに見えますが…
Makoto Fusegi - 投稿数: 19
KAZさん
エージェント側ではsupportedログは出ていません。
Not supported~supportedが出ているのはサーバー側です。
エージェント側ではNot supportedが定期的に出ているだけです。
とりあえず取得してみます。
KAZ - 投稿数: 1085
Makoto Fusegiさん
書き方が悪かったですね、すいません。
欲しいのはZabbixエージェントのログで、範囲は起動してからサーバ側でNot supported~supportedが発生している時の時間帯のログです。
できれば、同じ時間帯のZabbixサーバのログも欲しいです。