CPU使用率(system.cpu.util)取得値について

こんにちは。
いつもお世話になっております。

タイトルの内容について質問させていただきます。

【環境】
・Red Hat Enterprise Linux Server release 6.6 (Santiago)
・Zabbix Server 2.2.7
・Zabbix Agent 2.2.7
※Zabbixを導入しているサーバ自体にAgentをインストールしています。

【アイテム】
・「system.cpu.util[all,system,avg5]」

【状況】
上記の環境において、取得した値が貼付した画像「system.cpu_.util(all,system,avg5).png」の通り、
「2015/01/21 22:20:25」で「100」という値を取得しました。
ほぼ同時刻のアイテム「system.cpu.util[all,system,avg1]」(画像「system.cpu_.util(all,system,avg1).png」)では、特に値に異常は見られませんでした。

「avg5」は5分間の平均という認識のため、
前後の値に全く影響なくピンポイントで「100」という値を取得することは考えにくいと思っています。

サーバのログ等も確認しましたが、
現時点では、その時間付近でCPU負荷が大きくなるような処理は確認できていません。
※Zabbix専用のサーバのため、Zabbix、MySQL、postfix、httpd程度しか動作しておりません。

【質問】
この様な現象には、どのような要因が考えられるでしょうか?

以上、宜しく御願い致します。

コメント表示オプション

お好みのコメント表示方法を選び「設定の保存」をクリックすると変更が反映されます。
ユーザー TNK の写真

OSの仮想ファイル(/proc/stat)からカウンタ情報を取得して差分で
計算しているだけなので、OSの仮想ファイルからの読み出し時に問
題が発生したのかもしれません。

例えば、長期間継続して運用した場合に、/proc/statで利用してい
るカウンタがoverflowして0からカウントし直しをしていたりした
ら、一時的に不正な値が取得されてしまう可能性はあると思われま
す。

手元の環境で過去の情報を確認してみましたが、複数台あるZabbix
サーバのうち1台だけで同様の症状と思われる記録が残っていまし
た。
そのサーバはヒストリが7日でトレンドが1年分しか残していないの
で、トレンドにしか残っておらず、どのくらいの頻度で発生するの
かは判断はできません。
ちなみに、systemだけで、user、iowaitなど他の指標では100%にな
ったことは記録されていないようです。

頻繁に発生するようであれば、仮想環境などを利用していて、頻繁
に時計のずれを調整していたりしませんか?
カウンタの状態や時刻の補正などの条件の組み合わせによっては、
正常にカウントできないような状態が発生してしまっていたことも
可能性としては考えられると思います。

TNKさん

御回答ありがとうございます。

原因として考えられるのは、不正な値を取得した結果、
Zabbix側で100と判断してしまった可能性があると理解しました。

補足として、サーバは1月に入ってから一度再起動を実施しており、
現象が発生したときは2週間も継続稼動していない状態でした。
また、ntpによる時刻同期もログを見る限り、
その時間帯での時刻修正は見受けられませんでした。

サーバ自体の運用は5ヶ月程度で、
現象が発生したのは、現状では1度だけであるため、
もう少し長期的に監視を実施していきたいと思います。

因みにのお話になりますが、
これはZabbixのバグという判断になるのでしょうか?

ユーザー KAZ の写真
yoshi-yamaさん

2.2.7のソース読んでみました。
/proc/statを読むのはredhatやCentOS系です。
aixとかsolarisは別の取得方法になります。

/proc/statから値を取得しているのはsrc/zabbix_agent/cpustat.cのupdate_cpustats関数です。

↓/proc/statを表示したものです。
]# cat /proc/stat 
cpu  91326 916 54316 63739815 26719 5 590 0 0
cpu0 91326 916 54316 63739815 26719 5 590 0 0
intr 16053756 2272 470 0 0 0 0 0 0 1 0 0 0 108 0 0 75 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 514602 452874 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
ctxt 33987974
btime 1421771321
processes 287964
procs_running 1
procs_blocked 0
softirq 8223294 0 2994906 127857 797242 503961 0 464 0 28180 3770684

基本的には/proc/statをfopenして、行頭に「cpu」と言うキーワードがある行の数字を
atoiで文字->数値変換して格納するだけです。
	if (NULL == (file = fopen(filename, "r")))
	{
		zbx_error("cannot open [%s]: %s", filename, zbx_strerror(errno));
		ZBX_SET_CPUS_NOTSUPPORTED();
		goto exit;
	}

	cpu_status = zbx_malloc(cpu_status, sizeof(unsigned char) * (pcpus->count + 1));

	for (cpu_num = 0; cpu_num <= pcpus->count; cpu_num++)
		cpu_status[cpu_num] = SYSINFO_RET_FAIL;

	while (NULL != fgets(line, sizeof(line), file))
	{
		if (0 != strncmp(line, "cpu", 3))
			continue;

		if ('0' <= line[3] && line[3] <= '9')
		{
			cpu_num = atoi(line + 3) + 1;
			if (1 > cpu_num || cpu_num > pcpus->count)
				continue;
		}
		else if (' ' == line[3])
			cpu_num = 0;
		else
			continue;

		memset(counter, 0, sizeof(counter));
なので、linuxの問題といえます。
ユーザー zinten の写真

TNKさん、KAZさん

取得時の問題はあるかもしれないですが
avg5で1分間隔で取得している前後の監視結果に影響を与えていないということは別問題じゃないですか?

エージェントのCPU使用率の監視は1秒間隔で取得した結果をキャッシュ上に溜め込んで
それをリクエストがあったときに直近n個のデータを使用して計算してたはずです。
取得結果が1、2回おかしかったからといって全体に大きく影響を及ぼさないと思います。

また、avg1とavg5のときに使用するデータもデータ個数が異なるだけで同じデータを使用しているはずなので
avg5だけに影響を及ぼすのはおかしいかと。

エージェントがリクエストを受けて計算する際に何か起きてる気がします。

ユーザー KAZ の写真
zintenさん

エージェントのCPU使用率の監視は1秒間隔で取得した結果をキャッシュ上に溜め込んで それをリクエストがあったときに直近n個のデータを使用して計算してたはずです。 収集するのはcollectorプロセスですね。
計算するのはlistenerプロセスですね。
また、avg1とavg5のときに使用するデータもデータ個数が異なるだけで同じデータを使用しているはずなので avg5だけに影響を及ぼすのはおかしいかと。 なるほど…
listenerプロセスでavg1、agv5、agv15を判別しているのは下記ですね。
int	get_cpustat(AGENT_RESULT *result, int cpu_num, int state, int mode)
{
	int				i, time, idx_curr, idx_base;
	zbx_uint64_t			counter, total = 0;
	ZBX_SINGLE_CPU_STAT_DATA	*cpu;

	if (0 > state || state >= ZBX_CPU_STATE_COUNT)
		return SYSINFO_RET_FAIL;

	switch (mode)
	{
		case ZBX_AVG1:
			time = SEC_PER_MIN;
			break;
		case ZBX_AVG5:
			time = 5 * SEC_PER_MIN;
			break;
		case ZBX_AVG15:
			time = 15 * SEC_PER_MIN;
			break;
		default:
			return SYSINFO_RET_FAIL;
	}
SEC_PER_MINは60秒 そのtimeの値を使うのは下記です。
	if (1 == cpu->h_count)
	{
		for (i = 0; i < ZBX_CPU_STATE_COUNT; i++)
			total += cpu->h_counter[i][idx_curr];
		counter = cpu->h_counter[state][idx_curr];
	}
	else
	{
		if (0 > (idx_base = idx_curr - MIN(cpu->h_count - 1, time)))
			idx_base += MAX_COLLECTOR_HISTORY;

		while (SYSINFO_RET_OK != cpu->h_status[idx_base])
			if (MAX_COLLECTOR_HISTORY == ++idx_base)
				idx_base -= MAX_COLLECTOR_HISTORY;

		for (i = 0; i < ZBX_CPU_STATE_COUNT; i++)
			total += cpu->h_counter[i][idx_curr] - cpu->h_counter[i][idx_base];
		counter = cpu->h_counter[state][idx_curr] - cpu->h_counter[state][idx_base];
	}

	UNLOCK_CPUSTATS;

	SET_DBL_RESULT(result, 0 == total ? 0 : 100. * (double)counter / (double)total);
データ収集した時間とtimeを比較して、小さい方を期間のfromにしてます。
それ以外はargv1、argv5、argv15の違いはないです。

となると問題があるとしたらエージェントではなく。サーバ側のような気がします。

KAZさん、zintenさん

ソースコードやエージェントの動きについて、
確認して頂き、ありがとうございます。

現状ではZabbixのバグとは言い切れないが、
avg5だけ異常な値となっていることから、
サーバでの処理に問題がある可能性があるという状態ですね。

また現在は、
system.cpu.util[all,system,avg5]とsystem.cpu.util[all,user,avg5]の
合計値が80%を超えた場合、アラートをあげる設定にしていますが、
その値が100を超えた場合は今回の現象が発生したと判断して、
アラートをあげない、以下のような設定に変更することも考えて見ます。
「80<systemとuserの合計値<100」