listen()のbacklogの設定値、キューの数値を確認する

Apacheのポートベースのバーチャルホストで特定のホストだけ死活監視が失敗する事がありました。 ssコマンドで表示されるRecv-Qがbacklogのキューの数値だと思っていたのですが ss(8) - Linux manual pageを見ても不確かだったのでソースを確認したいと思います。

以下、対象サーバーの5秒間隔のss -intlコマンドの出力結果になります。

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     38     128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     127    128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     129    128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     129    128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     126    128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

10443ポートでListenしているRecv-Qが最大で(Send-Q)+1まで増加しています。
このRecv-QとSend-Qの値が何を指しているのか確認します。
ss.cのsock_state_print()が出力しています。

  • iproute2-4.11.0/misc/ss.c
 793 static void sock_state_print(struct sockstat *s)
 794 {
 795   const char *sock_name;
 796   static const char * const sstate_name[] = {
 797     "UNKNOWN",
 798     [SS_ESTABLISHED] = "ESTAB",
 799     [SS_SYN_SENT] = "SYN-SENT",
 800     [SS_SYN_RECV] = "SYN-RECV",
 801     [SS_FIN_WAIT1] = "FIN-WAIT-1",
 802     [SS_FIN_WAIT2] = "FIN-WAIT-2",
 803     [SS_TIME_WAIT] = "TIME-WAIT",
 804     [SS_CLOSE] = "UNCONN",
 805     [SS_CLOSE_WAIT] = "CLOSE-WAIT",
 806     [SS_LAST_ACK] = "LAST-ACK",
 807     [SS_LISTEN] = "LISTEN",
 808     [SS_CLOSING] = "CLOSING",
 809   };
 810
 811   switch (s->local.family) {
 812   case AF_UNIX:
 813     sock_name = unix_netid_name(s->type);
 814     break;
 815   case AF_INET:
 816   case AF_INET6:
 817     sock_name = proto_name(s->type);
 818     break;
 819   case AF_PACKET:
 820     sock_name = s->type == SOCK_RAW ? "p_raw" : "p_dgr";
 821     break;
 822   case AF_NETLINK:
 823     sock_name = "nl";
 824     break;
 825   default:
 826     sock_name = "unknown";
 827   }
 828
 829   if (netid_width)
 830     printf("%-*s ", netid_width,
 831            is_sctp_assoc(s, sock_name) ? "" : sock_name);
 832   if (state_width) {
 833     if (is_sctp_assoc(s, sock_name))
 834       printf("`- %-*s ", state_width - 3,
 835              sctp_sstate_name[s->state]);
 836     else
 837       printf("%-*s ", state_width, sstate_name[s->state]);
 838   }
 839
 840   printf("%-6d %-6d ", s->rq, s->wq);
 841 }

s->rqとs->wqには、parse_diag_msg()によってidiag_rqueueとidiag_wqueueの値がそれぞれ入ります。

2343 static void parse_diag_msg(struct nlmsghdr *nlh, struct sockstat *s)
2344 {
2345   struct rtattr *tb[INET_DIAG_MAX+1];
2346   struct inet_diag_msg *r = NLMSG_DATA(nlh);
2347
2348   parse_rtattr(tb, INET_DIAG_MAX, (struct rtattr *)(r+1),
2349          nlh->nlmsg_len - NLMSG_LENGTH(sizeof(*r)));
2350
2351   s->state  = r->idiag_state;
2352   s->local.family = s->remote.family = r->idiag_family;
2353   s->lport  = ntohs(r->id.idiag_sport);
2354   s->rport  = ntohs(r->id.idiag_dport);
2355   s->wq   = r->idiag_wqueue;
2356   s->rq   = r->idiag_rqueue;
2357   s->ino    = r->idiag_inode;
2358   s->uid    = r->idiag_uid;
2359   s->iface  = r->id.idiag_if;
2360   s->sk   = cookie_sk_get(&r->id.idiag_cookie[0]);
2361
2362   s->mark = 0;
2363   if (tb[INET_DIAG_MARK])
2364     s->mark = rta_getattr_u32(tb[INET_DIAG_MARK]);
2365   if (tb[INET_DIAG_PROTOCOL])
2366     s->raw_prot = rta_getattr_u8(tb[INET_DIAG_PROTOCOL]);
2367   else
2368     s->raw_prot = 0;
2369
2370   if (s->local.family == AF_INET)
2371     s->local.bytelen = s->remote.bytelen = 4;
2372   else
2373     s->local.bytelen = s->remote.bytelen = 16;
2374
2375   memcpy(s->local.data, r->id.idiag_src, s->local.bytelen);
2376   memcpy(s->remote.data, r->id.idiag_dst, s->local.bytelen);
2377 }

それぞれの値の意味はman(7)sock_diagによると
http://man7.org/linux/man-pages/man7/sock_diag.7.html  

idiag_rqueue
For listening sockets: the number of pending connections.
For other sockets: the amount of data in the incoming queue.

idiag_wqueue
For listening sockets: the backlog length.
For other sockets: the amount of memory available for sending.

idiag_rqueue (Recv-Q)は、accept()を待っているキューの数
idiag_wqueue (Send-Q)は、backlogのサイズ
という事なので期待していた数値で間違いなさそうです。

backlogが溢れた時の動作については、How TCP backlog works in Linuxに詳しく解説されてますが
1. LINUX_MIB_LISTENOVERFLOWS, LINUX_MIB_LISTENDROPSのカウンタをインクリメントしtcp_abort_on_overflow = 0だった場合何もしない。
2. ACK, SYNをdropする
となります。

カウンタの値は以下のコマンドで確認できます。

$ nstat -s |grep -i listen
TcpExtListenOverflows           32449              0.0
TcpExtListenDrops               32449              0.0
$ nstat -s TcpExtListenOverflows
#kernel
TcpExtListenOverflows           32449              0.0
[mnishikizawa@web01 ~ RADIAN-MUSASHI]$ nstat -s TcpExtListenDrops
#kernel
TcpExtListenDrops               32449              0.0
[mnishikizawa@web01 ~ RADIAN-MUSASHI]$

死活監視の失敗原因は、backlog溢れによるtimeoutで間違いなさそうなので今回はsomaxconnを増やして対応することにしました。

linuxのtcp_rmemの変更は何に影響するのか調べたのでメモっておく

大容量なファイル送信にかかる時間を短縮する為に色々調べていたら sysctlで送受信用ウィンドウ・サイズの最大値を変更するようアドバイスするサイトが多かったので 変更によって何が影響するのか調べてみた。

tcp_select_initial_window()のif (wscale_ok)の辺りが関係しそう。

#define TCP_MAX_WSCALE          14U
 191 void tcp_select_initial_window(const struct sock *sk, int __space, __u32 mss,
 192              __u32 *rcv_wnd, __u32 *window_clamp,
 193              int wscale_ok, __u8 *rcv_wscale,
 194              __u32 init_rcv_wnd)
 195 {
 196   unsigned int space = (__space < 0 ? 0 : __space);
 197
 198   /* If no clamp set the clamp to the max possible scaled window */
 199   if (*window_clamp == 0)
 200     (*window_clamp) = (U16_MAX << TCP_MAX_WSCALE);
 201   space = min(*window_clamp, space);
 202
 203   /* Quantize space offering to a multiple of mss if possible. */
 204   if (space > mss)
 205     space = rounddown(space, mss);
 206
 207   /* NOTE: offering an initial window larger than 32767
 208    * will break some buggy TCP stacks. If the admin tells us
 209    * it is likely we could be speaking with such a buggy stack
 210    * we will truncate our initial window offering to 32K-1
 211    * unless the remote has sent us a window scaling option,
 212    * which we interpret as a sign the remote TCP is not
 213    * misinterpreting the window field as a signed quantity.
 214    */
 215   if (sock_net(sk)->ipv4.sysctl_tcp_workaround_signed_windows)
 216     (*rcv_wnd) = min(space, MAX_TCP_WINDOW);
 217   else
 218     (*rcv_wnd) = space;
 219
 220   (*rcv_wscale) = 0;
 221   if (wscale_ok) {
 222     /* Set window scaling on max possible window */
 223     space = max_t(u32, space, sock_net(sk)->ipv4.sysctl_tcp_rmem[2]);
 224     space = max_t(u32, space, sysctl_rmem_max);
 225     space = min_t(u32, space, *window_clamp);
 226     while (space > U16_MAX && (*rcv_wscale) < TCP_MAX_WSCALE) {
 227       space >>= 1;
 228       (*rcv_wscale)++;
 229     }
 230   }
 231
 232   if (mss > (1 << *rcv_wscale)) {
 233     if (!init_rcv_wnd) /* Use default unless specified otherwise */
 234       init_rcv_wnd = tcp_default_init_rwnd(mss);
 235     *rcv_wnd = min(*rcv_wnd, init_rcv_wnd * mss);
 236   }
 237
 238   /* Set the clamp no higher than max representable value */
 239   (*window_clamp) = min_t(__u32, U16_MAX << (*rcv_wscale), *window_clamp);
 240 }
 241 EXPORT_SYMBOL(tcp_select_initial_window);

TCP window scale オプションが有効だった場合、tcp_rmemの設定値に応じて 最大値14のTCP window scale の値が変更になる。

TCP window scale 値は3 Way ハンドシェイク時に通知され、Wireshark等で確認できる。
この画像ではWindow scale: 6
tcp_rmemの値を増やすと、このWindow scaleが最大14まで上昇する。 f:id:nishitki:20180921112833p:plain

ssコマンドなんかでも確認できて、下の画像の wscale:5,6がそれ。
tcp_rmemが3839488だった場合のWindow scale値は6で、通信相手のWindow scale値が5。 f:id:nishitki:20180921123328p:plain

tcp_rmemを増やすことによって、レイテンシーに影響する場合もあるようなので注意が必要ですね。 The story of one latency spike

dbus-daemonのCPU使用率が高いので調べました

dbus-daemonのCPU使用率が高いので調査依頼を受けました。
何はともあれトレースして見ます。
straceの出番です。

$ sudo strace -o dbus.log -ttf -s 512 -p `pidof dbus-daemon`
712   10:58:37.914418 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.914546 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.914623 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.914693 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.914751 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.914812 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.914871 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.914928 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.914987 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.915046 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.915096 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.915156 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.915217 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.915276 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.915338 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.915399 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.915457 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.915518 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.915578 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)

結果はこれ。ディスクリプタリークっぽいような気がします。
ググったら以下がヒット。
[https://bugzilla.redhat.com/show_bug.cgi?id=1325870]
もうすでに修正が入っているみたいでバージョンを上げれば直りそうです。
修正内容を確認してみます。

dbus/dbus - a lightweight ipc mechanism

diff --git a/dbus/dbus-sysdeps-util-unix.c b/dbus/dbus-sysdeps-util-unix.c
index 6cff3fe..bbc3f34 100644
--- a/dbus/dbus-sysdeps-util-unix.c
+++ b/dbus/dbus-sysdeps-util-unix.c
@@ -1144,6 +1144,7 @@ _dbus_command_for_pid (unsigned long  pid,
                       "Failed to read from \"%s\": %s",
                       _dbus_string_get_const_data (&path),
                       _dbus_strerror (errno));      
+      _dbus_close (fd, NULL);
       goto fail;
     }

定期的にアップデートはしないといけませんね。
気をつけます。

kworkerのCPU使用率が高すぎるのでなんとかした

題名の通りkworkerのCPU使用率が高いのをなんとかした記録。OSはCentOS 7.2

ぐぐってみたところ

Linuxで一つのコアのCPU利用率が異様に高いのを何とかする - Qiita

ubuntuでkworkerのcpu使用率がやたら高い - Qiita

ヒットするが、こちらの環境とはマッチしないみたい。

覚えたてのperfを使ってみます。

Samples: 44K of event 'cycles', Event count (approx.): 40358935514
  Children      Self  Command         Shared Object             Symbol
+   70.47%     0.00%  kworker/2:2     [kernel.kallsyms]         [k] kthread
+   70.47%     0.00%  kworker/2:2     [kernel.kallsyms]         [k] ret_from_fork
+   70.47%     0.00%  kworker/2:2     [kernel.kallsyms]         [k] worker_thread
+   70.44%     0.07%  kworker/2:2     [kernel.kallsyms]         [k] process_one_work
+   69.37%     0.05%  kworker/2:2     [kernel.kallsyms]         [k] rpm_idle
+   69.09%     0.08%  kworker/2:2     [kernel.kallsyms]         [k] rpm_suspend
+   68.98%     0.03%  kworker/2:2     [kernel.kallsyms]         [k] pm_runtime_work
+   68.83%     0.04%  kworker/2:2     [kernel.kallsyms]         [k] __rpm_callback
+   68.78%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] usb_runtime_idle
+   68.74%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] __pm_runtime_suspend
+   68.54%     0.00%  kworker/2:2     [kernel.kallsyms]         [k] rpm_callback
+   68.49%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] usb_runtime_suspend
+   68.46%     0.03%  kworker/2:2     [kernel.kallsyms]         [k] usb_suspend_both
+   66.53%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] usb_resume_interface.isra.5
+   66.53%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] hub_resume
+   66.49%     0.42%  kworker/2:2     [kernel.kallsyms]         [k] hub_activate
+   65.50%     0.28%  kworker/2:2     [kernel.kallsyms]         [k] hub_port_status
+   64.32%     0.28%  kworker/2:2     [kernel.kallsyms]         [k] usb_control_msg
+   61.81%     0.22%  kworker/2:2     [kernel.kallsyms]         [k] usb_start_wait_urb
+   56.04%     0.07%  kworker/2:2     [kernel.kallsyms]         [k] usb_submit_urb
+   55.97%     0.54%  kworker/2:2     [kernel.kallsyms]         [k] usb_submit_urb.part.5
+   54.46%     1.71%  kworker/2:2     [kernel.kallsyms]         [k] usb_hcd_submit_urb
+   40.82%    39.99%  kworker/2:2     [kernel.kallsyms]         [k] xhci_hub_control
+   16.33%     0.00%  ksoftirqd/2     [kernel.kallsyms]         [k] kthread
+   16.33%     0.00%  ksoftirqd/2     [kernel.kallsyms]         [k] ret_from_fork
+   15.88%     1.32%  ksoftirqd/2     [kernel.kallsyms]         [k] smpboot_thread_fn

xHCIが悪さをしているようです。

USBをリセットしてみます。

[Reset USB 2.0 (ehci) & USB 3.0 (xhci) Without Reboot in Linux Kernel] (http://www.ubuntubuzz.com/2016/06/reset-usb-20-ehci-usb-30-xhci-without-reboot-linux.html)

使用率が低くなりました。よかったね。

標準入力からの入力に対応していないコマンドを何とかしたいんだ

  • 例えばssh-keygen -lf ~/.ssh/authorized_keysでフィンガープリントを確認したいんだけど ssh-keygen -lfは、標準入力からの入力に対応してない。 /dev/stdinを使えば何とかなるらしい。

  • Serverspecでこんなことしたかったけど/dev/stdin使ったらできた。

describe command(%|ssh-keygen -lf /dev/stdin <<<"$(grep hogehoge /home/hogehoge/.ssh/authorized_keys)"|) do
  its(:stdout) { should contain('1a:2b:3c:4d:5e:6f:7g:8h:9i:10:11:12:13:14:15:16').after(/2048/) }
end

LVSの Hash Table Sizeを大きくします。

OSは、CentOS7です。 kernelを再構築する必要があります。

# yum groupinstall -y "development tools"
# yum install xmlto asciidoc hmaccalc python-devel newt-devel perl-ExtUtils-Embed pesign  elfutils-devel zlib-devel  binutils-devel audit-libs-devel numactl-devel pciutils-devel  ncurses-devel

kernelのSRPMをダウンロードします。

yumdownloader --source kernel

SRPMを展開します。

# yum install kernel-3.10.0-327.13.1.el7.src.rpm

RedHatのkernelパッケージには必要です。

# yum install rng-tools
# rngd -r /dev/urandom

RPMパッケージ名を変更しておきます。

sed -i -e 's/^# % define buildid .local/%define buildid .local/' /root/rpmbuild/SPECS/kernel.spec

Hash Table Sizeを12 -> 20に変更します。

sed -i -e 's/^CONFIG_IP_VS_TAB_BITS=12/CONFIG_IP_VS_TAB_BITS=20' /root/rpmbuild/SOURCES/kernel-3.10.0-x86_64.config

kernelのrpmを作ります。

rpmbuild -ba --target=$(uname -m) --with baseonly --without debug --without debuginfo kernel.spec

確認しておきます。サイズ大きくなりました。

[root@server ~]# ipvsadm -Ln
IP Virtual Server version 1.2.1 (size=1048576)
Prot LocalAddress:Port Scheduler Flags
  -> RemoteAddress:Port           Forward Weight ActiveConn InActConn
TCP  210.152.0.52:80 wlc persistent 60
  -> 10.21.0.4:80                 Route   0      0          0         
  -> 10.21.0.7:80                 Route   0      0          0         
  -> 10.21.0.31:80                Route   0      0          0         
  -> 10.21.0.97:80                Route   0      0          0         
  -> 10.21.0.120:80               Route   0      0          0         
  -> 10.21.0.151:80               Route   0      0          0         
  -> 10.21.0.172:80               Route   0      0          0         
  -> 10.21.0.226:80               Route   0      0          0         
[root@server ~]# 

keepalivedの1.1.20と1.2.2はvrrpが通らないんだね

CVE-2015-7547の対応で1台目のlibc6をupgradeしたら/var/log/messagesにエラーがで始めた。

Keepalived_vrrp: VRRP_Instance(image1:192.168.201.1) ignoring received advertisment...
Keepalived_vrrp: receive an invalid passwd!
Keepalived_vrrp: bogus VRRP packet received on bond0 !!!

keepalivedの設定は変更してないしと思ってググったらイカがヒット

blog.remibergsma.com

パスワードを短くしてkeepalivedを再起動したら今度はイカのようなエラーが。。

Keepalived_vrrp: VRRP_Instance(image1:192.168.201.1) ignoring received advertisment...
Keepalived_vrrp: receive a 0 auth, expecting 1!
Keepalived_vrrp: bogus VRRP packet received on bond0 !!!

結局、バージョンを合わせて直りました。