[時間割:サーバ] ntpのログで”too many recvbufs allocated (40)”
2008/08/21 00:08 posted by kunkichi

ある時からntpサーバのntpログでちょっと気になる出力が。サーバ絡みなので勉強と称して調査。

too many recvbufs allocated (40)

これが延々、とは言わないまでも、バラバラっと出力されてしばら〜くしてからまたバラバラっと、っていうのが繰り返される。でいろいろ調べてみたところ、とあるMLにこんな投稿が。

[time] Increasing recv buffers on FreeBSD

・・・
My logs are routinely filled with things like

Apr 25 11:36:21 n118 ntpd[56093]: too many recvbufs allocated (40)
Apr 25 11:36:21 n118 last message repeated 3 times
Apr 25 14:17:03 n118 ntpd[56093]: too many recvbufs allocated (40)
Apr 25 14:17:03 n118 last message repeated 3 times
・・・

It appears that I am dropping requests that I could otherwise answer.

I’ve got the bandwidth, memory and CPU to handle more than I’m currently taking, so I’m wondering if anyone knows how to increase the udp receive buffers on FreeBSD (6.2-RELEASE p3)

うん、一緒一緒。Load Average、CPU使用率、メモリ、トラフィック、全部余裕あるところも一緒。
で、そのレスが以下。

[time] Increasing recv buffers on FreeBSD

It’s not the kernel; that message comes from /usr/src/contrib/ntp/libntp/recvbuff.c around lines 161 & 225:

                 ・・・
                 /*
                  * Check to see if we're below the low water mark.
                  */
                 if (free_recvbufs <= RECV_LOWAT)
                 {
                         if (total_recvbufs >= RECV_TOOMANY)
                             msyslog(LOG_ERR, "too many recvbufs allocated (%ld)",
                                     total_recvbufs);
                 ・・・

It appears that you can change this definition of RECV_TOOMANY here:

% grep -n RECV_TOOMANY */*
include/recvbuff.h:18:#define RECV_TOOMANY      40      /* this is way too many buffers */

As far as I can tell, this only happens if ntpd gets a whole slew of requests at once before it can generate some replies, and it simply results in ntpd dropping the requests…

ってことで、どうやらntpのソース内で受信バッファが定義されていて、瞬間的に大量のパケットを受信したため、バッファからあふれてしまったということの様子。バッファから溢れてしまったのはもちろん落ちちゃっているので、クライアントからのリクエストに対してレスポンスはなくなっちゃってるってことだよねぇ。

で実はここまでは既にわかっていて、パケットキャプチャすると確かにクライアントのリクエストに対してサーバのレスポンスが少ないんだよね、まあ頻度的にはそれほど多くはないのだけど。

ただ、上の理由は僕のシチュエーションだとちょっと納得できない。なんでかというと

• 突然起きたのなら、クライアントが急に増えたとかっていうような変化があったはず。でも調べてみたところ、そういうことはない。
• クライアントのリクエストに対してサーバのレスポンスが返らないのであれば、サーバ側のトラフィックとしては、INは変わらないけど、OUTが減る、っていうのが考えられるけど、トラフィック自体は両方とも同じぐらい減ってる。

からなんだよねぇ、、、不可解だ。

別の投稿がGoogle Groupsにも上がっててこっちは最新版にバージョンアップしろって書いてあるんだけど、最新版(4.2.4p5)のソース見ても上で指摘されている部分は全く変更ないしなぁ。まあバッファを増やしてビルドし直せばログは出なくなるんだろうけど、なんだかなー。

とりあえず今のところテストで再現できてないのでそれをなんとか、って感じ。NTPの負荷テストなんてやったことないしツールもないみたいだし、ちょっとPerlで書いてみることに。Net::NTPでクライアントからのアクセスをParallel::ForkManager使って並列で多量に実行する感じ。

#!/usr/bin/perl -w
 
use strict;
use warnings;
 
use Net::NTP;
use Parallel::ForkManager;
 
my $pm = new Parallel::ForkManager(1000);
foreach my $i (1..100000){
  $pm->start and next;
  my %response = get_ntp_response("XXX.XXX.XXX.XXX",123);
  foreach my $key (keys %response)
  {
    print "$key --> $response{$keys}¥n";
  }
  $pm->finish;
}
$pm->wait_all_children;

うーん、どうかなぁ。とりあえず明日実機で試してみよう。

Category: Server |