labunix's blog

labunixのラボUnix

ftpの負荷テスト方法を検討する。

■ftpの負荷テスト方法を検討する。

$ lsb_release -d
Description:	Debian GNU/Linux 8.3 (jessie)

■ユーザ名、パスワードをlabunixとした場合の
 「ls *.sh」だけを実行する読み込みファイルを作成

$ cat my.ftp 
user labunix labunix
bin
prompt
ls *.sh
quit

■単独で実行すると、以下のようになる。

$ ftp -n 127.0.0.1 < my.ftp 
Interactive mode off.
-rwxr-xr-x    1 1000     1000          264 Feb 26  2015 FGT_disable_syslog.sh
-rwxr-xr-x    1 1000     1000          632 Jun 18  2015 spamtestmail.sh
-rwxr-xr-x    1 1000     1000          734 Jun 22  2015 spamtestmail2.sh
-rwxr-xr-x    1 1000     1000         1767 Mar 23  2015 web_mail_proxy.sh

■ところで、きちんと終了してもセッションがTIME_WAITで残る。

$ netstat -an | grep 127.0.0.1:21
tcp        0      0 127.0.0.1:59549         127.0.0.1:21            TIME_WAIT  

■どのくらいTIME_WAITで残るのかというとデフォルトで60秒

$ sudo sysctl -n net.ipv4.tcp_fin_timeout
60

■実際に60秒間残る。

$ ftp -n 127.0.0.1 < my.ftp > /dev/null 2>&1 & \
    echo "$(date '+%Y/%m/%d %H:%M:%S'),"; \
    netstat -an | grep 127.0.0.1:21; \
    sleep 50; \
    while true;do echo -n "$(date '+%Y/%m/%d %H:%M:%S'),";netstat -an | grep 127.0.0.1:21;sleep 1;done
[1] 27840
2016/04/03 02:35:24,
tcp        0      0 127.0.0.1:59608         127.0.0.1:21            ESTABLISHED
tcp        0      0 127.0.0.1:21            127.0.0.1:59608         ESTABLISHED
[1]+  終了                  ftp -n 127.0.0.1 < my.ftp > /dev/null 2>&1
2016/04/03 02:36:14,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:15,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:16,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:17,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:18,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:19,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:20,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:21,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:22,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:23,tcp        0      0 127.0.0.1:59608         127.0.0.1:21            TIME_WAIT  
2016/04/03 02:36:24,2016/04/03 02:36:25,2016/04/03 02:36:26,^C

■誰も繋ぎに来ない環境であれば、上記を前提にはじめ60秒待てば確実に並列実行による結果を見れる。
 なお、ESTABLISHEDの数から、最初の2秒ほどで50件のftp処理は終わって、TIME_WAITの60秒後に綺麗になる。
 ちなみに0.5秒のsleepは改行が表示されしまうから。

 オプションについては以下。
 「-L」は1回の実行に最大でいくつの引数を与えるか
 「-P」は最大でいくつのプロセスを実行するか

$ netstat -an | grep ":21.*WAIT" >/dev/null 2>&1 && sleep 60; \
  echo "ftp -n 127.0.0.1 < my.ftp" | awk '{for(n=0;n<50;n++){print $0}}' | sh >/dev/null 2>&1 | xargs -L 50 -P 50 & \
  sleep 0.5; \
  for n in `seq 1 5`;do \
    echo -n "$(date '+%Y/%m/%d %H:%M:%S'),"; \
    echo -ne $(netstat -an | grep "127.0.0.1:21.*EST" | wc -l),$(netstat -an | grep "127.0.0.1:21.*WAIT" | wc -l);echo; \
    sleep 1; \
  done; \
  sleep 50; \
  for n in `seq 1 15`;do \
    echo -n "$(date '+%Y/%m/%d %H:%M:%S'),"; \
    echo -ne $(netstat -an | grep "127.0.0.1:21.*EST" | wc -l),$(netstat -an | grep "127.0.0.1:21.*WAIT" | wc -l);echo; \
    sleep 1; \
  done
[1] 4545

2016/04/03 03:21:38,2,9
2016/04/03 03:21:39,2,28
2016/04/03 03:21:40,2,49
[1]+  終了    echo "ftp -n 127.0.0.1 < my.ftp" | awk '{for(n=0;n<50;n++){print $0}}' | sh > /dev/null 2>&1 | xargs -L 50 -P 50
2016/04/03 03:21:41,0,50
2016/04/03 03:21:42,0,50
2016/04/03 03:22:34,0,50
2016/04/03 03:22:35,0,50
2016/04/03 03:22:36,0,50
2016/04/03 03:22:37,0,50
2016/04/03 03:22:38,0,50
2016/04/03 03:22:39,0,0
2016/04/03 03:22:40,0,0
2016/04/03 03:22:41,0,0
2016/04/03 03:22:42,0,0
2016/04/03 03:22:43,0,0
2016/04/03 03:22:44,0,0
2016/04/03 03:22:45,0,0
2016/04/03 03:22:46,0,0
2016/04/03 03:22:47,0,0
2016/04/03 03:22:48,0,0

■きちんと50回接続に来ていることも確認出来ます。

$ sudo awk '/03:2[12]/&&/CONNECT/{sum+=1};END{print sum}' /var/log/vsftpd.log
50

■負荷が目的なので、2万件ほど試してみる。
 さすがに最初の2秒どころか1分では終了しない。
 秒間20処理程度なので、およそ17分かかる。

$ echo "20000 20" | awk '{print $1/$2/60}'
16.6667

$ netstat -an | grep ":21.*WAIT" >/dev/null 2>&1 && sleep 60; \
  echo "ftp -n 127.0.0.1 < my.ftp" | awk '{for(n=0;n<20000;n++){print $0}}' | sh >/dev/null 2>&1 | xargs -L 20000 -P 20000 & \
  sleep 0.5; \
  for n in `seq 1 5`;do \
    echo -n "$(date '+%Y/%m/%d %H:%M:%S'),"; \
    echo -ne $(netstat -an | grep "127.0.0.1:21.*EST" | wc -l),$(netstat -an | grep "127.0.0.1:21.*WAIT" | wc -l);echo; \
    sleep 1; \
  done; \
  sleep 50; \
  for n in `seq 1 15`;do \
    echo -n "$(date '+%Y/%m/%d %H:%M:%S'),"; \
    echo -ne $(netstat -an | grep "127.0.0.1:21.*EST" | wc -l),$(netstat -an | grep "127.0.0.1:21.*WAIT" | wc -l);echo; \
    sleep 1; \
  done
[1] 5009

2016/04/03 03:27:54,2,10
2016/04/03 03:27:55,2,30
2016/04/03 03:27:56,2,49
2016/04/03 03:27:57,2,69
2016/04/03 03:27:58,2,89
2016/04/03 03:28:49,2,1191
2016/04/03 03:28:50,2,1213
2016/04/03 03:28:51,2,1236
2016/04/03 03:28:52,3,1257
2016/04/03 03:28:54,3,1130
2016/04/03 03:28:55,2,1155
2016/04/03 03:28:56,0,1179
2016/04/03 03:28:57,2,1201
2016/04/03 03:28:58,2,1224
2016/04/03 03:28:59,3,1244
2016/04/03 03:29:00,3,1262
2016/04/03 03:29:02,2,1286
2016/04/03 03:29:03,2,1309
2016/04/03 03:29:04,2,1334
2016/04/03 03:29:05,2,13561分あたり約1200件の処理なので、以降の継続は次のように確認出来る。
 適当に1分過ぎたら確認して、最後は何となくのsleep時間で待って確認。

$ echo "20 60" | awk '{print $1*$2}'
1200

$ sudo awk '(/03:2[789]/) && /CONNECT/{sum+=1}END{print sum}' /var/log/vsftpd.log
2536

$ sudo awk '(/03:3/) && /CONNECT/{sum+=1}END{print sum}' /var/log/vsftpd.log
10902

$ sleep 10; \
  while true ;do \
    echo -n "$(date '+%Y/%m/%d %H:%M:%S'),"; \
    sudo awk '(/03:2[789]/ || /03:3[0-9]/ || /03:4[0-9]/) && /CONNECT/{sum+=1}END{print sum}' /var/log/vsftpd.log; \
    sleep 1; \
  done
2016/04/03 03:45:58,19906
2016/04/03 03:45:59,19928
2016/04/03 03:46:00,19948
2016/04/03 03:46:02,19969
2016/04/03 03:46:03,19991
2016/04/03 03:46:04,20000
2016/04/03 03:46:05,20000
2016/04/03 03:46:07,20000
^C

■5千件程度なら、せいぜい5分で終わるはず。

$ echo "5000 50 20" | awk '{print $1/$2/60,$1/$3/60}'
1.66667 4.16667

■もう一度xargsに渡すパラメータを戻して5000件を実行してみる。
 やはり秒間20件程度。

$ netstat -an | grep ":21.*WAIT" >/dev/null 2>&1 && sleep 60; \
  echo "ftp -n 127.0.0.1 < my.ftp" | awk '{for(n=0;n<5000;n++){print $0}}' | sh >/dev/null 2>&1 | xargs -L 50 -P 50 & \
  sleep 0.5; \
  for n in `seq 1 5`;do \
    echo -n "$(date '+%Y/%m/%d %H:%M:%S'),"; \
    echo -ne $(netstat -an | grep "127.0.0.1:21.*EST" | wc -l),$(netstat -an | grep "127.0.0.1:21.*WAIT" | wc -l);echo; \
    sleep 1; \
  done; \
  sleep 50; \
  for n in `seq 1 15`;do \
    echo -n "$(date '+%Y/%m/%d %H:%M:%S'),"; \
    echo -ne $(netstat -an | grep "127.0.0.1:21.*EST" | wc -l),$(netstat -an | grep "127.0.0.1:21.*WAIT" | wc -l);echo; \
    sleep 1; \
  done
[1] 23324

2016/04/03 03:50:12,2,11
2016/04/03 03:50:13,2,32
2016/04/03 03:50:14,0,53
2016/04/03 03:50:15,2,71
2016/04/03 03:50:16,2,92
2016/04/03 03:51:07,2,1208
2016/04/03 03:51:09,2,1228
2016/04/03 03:51:10,2,1249
2016/04/03 03:51:11,2,1270
2016/04/03 03:51:12,2,1149
2016/04/03 03:51:13,0,1172
2016/04/03 03:51:14,2,1201
2016/04/03 03:51:15,2,1223
2016/04/03 03:51:17,4,1247
2016/04/03 03:51:18,2,1272
2016/04/03 03:51:19,2,1290
2016/04/03 03:51:20,2,1317
2016/04/03 03:51:21,2,1339
2016/04/03 03:51:22,2,1360
2016/04/03 03:51:23,0,1381

$ sleep 10; \
  while true ;do \
    echo -n "$(date '+%Y/%m/%d %H:%M:%S'),"; \
    sudo awk '/03:5[01234]/ && /CONNECT/{sum+=1}END{print sum}' /var/log/vsftpd.log; \
    sleep 1; \
  done
[1]+  終了   echo "ftp -n 127.0.0.1 < my.ftp" | awk '{for(n=0;n<5000;n++){print $0}}' | sh > /dev/null 2>&1 | xargs -L 50 -P 50
2016/04/03 03:54:37,5000
2016/04/03 03:54:38,5000
2016/04/03 03:54:39,5000
^C

■厳密には5000件の処理には平均19件/秒の処理がされるので263秒かかる。
 逆に言うとこの方法では、19件/秒程度しか負荷はかけられない。

$ echo "$((5000/19))"
263

$ sudo awk '/03:5[01234]/ && /CONNECT/{a[$4]+=1}END{for (n in a){print a[n],n}}' /var/log/vsftpd.log | \
    awk '{sum+=$1;if(NR==1||NR>260)print NR,$0}END{print sum,sum/NR}'
1 16 03:53:11
261 16 03:54:33
262 19 03:54:34
263 21 03:53:10
5000 19.0114