I/O性能とファイルの使用状況
読取り量と呼出し時間を、fdの参照先に対応させて調べます。
説明
I/Oの遅さを調べるときは、処理した量、待った時間、アクセス先を合わせて確認します。readのバイト数と装置からの読込み量は同じとは限らず、装置全体の統計は一つのプロセスだけの値でもありません。
2秒間のI/Oカウンターと、同時点のfd表・呼出し記録を使います。差分を求め、長い呼出しを参照先へ結び付け、デバイス全体の値と比べながら分かる範囲を確かめます。
1読込み量の二つの記録
PID700の/proc/PID/io形式から、2秒間隔の開始と終了を読みます。固定した教材記録で、この区間には子プロセスの回収はありません。
cat io-before.txt区間開始; cat io-after.txt2秒後rcharはread等が返したバイト数、read_bytesはストレージ層から取得した量です。キャッシュや読取り対象の種類により一致しません。どちらも累積値なので、区間の差分を取ります。
2ストレージから取得した量
同名項目の差分を計算し、rcharとread_bytesをMiBへ換算します。
awk 'NR==FNR {a[$1]=$2; next} $1=="rchar:" || $1=="read_bytes:" {printf "%s %.1f MiB\n",$1,($2-a[$1])/1048576}'読み出した量とストレージ量 io-before.txt io-after.txt同じ区間の二点rcharは8MiB、read_bytesは2MiBです。残る6MiBをこの表だけで「特定のファイルのキャッシュ」と断定せず、何を読んだかも調べます。2秒間のストレージ読込みは平均1MiB/秒です。
3ファイル記述子と対象
fds.csvは同じ時点でPID700が開いていた資源の対応表です。
cat fds.csvfdと参照先fd4は入力ファイル、fd5は出力ファイル、fd3はソケットです。readという呼出し名だけではディスクから読んでいるとは判断できません。fdの対応と取得時点を合わせて確認します。
4時間のかかった呼出し
trace.csvは同じ処理から4呼出しを抽出した記録です。所要時間の長い順へ並べます。
head -n 1 trace.csv列名; tail -n +2 trace.csvデータ行 | sort -t, -k6,6nr所要時間の降順最長はfd5のfsyncで0.400秒、次はfd4のreadで0.250秒です。fsyncは0を返して成功していますが、完了まで待っています。成功した呼出しでも遅延の主因になる場合があります。
5呼出しとパスを結び付ける
同じPID・fdをキーに、呼出しの記録へ参照先を付けます。
awk -F, 'NR==FNR {if(FNR>1) target[$1,$2]=$4; next} FNR>1 {printf "%s fd=%s target=%s seconds=%s\n",$3,$4,target[$2,$4],$6}'PIDとfdで対応を結合 fds.csv trace.csv同時点の資源表と呼出し待ったfsyncはreport.csv、長いreadはinput.binです。ソケットのreadも別に存在します。この表ではfdの開閉・再利用が区間内にない条件です。実調査では同じ番号が別の資源へ割り当て直されていないかも確認します。
6デバイスの待ち時間を別に確認
device.csvは同じ2秒区間にデバイスで完了した200要求の統計です。全要求の遅延合計は8000msです。
awk -F, 'NR==2 {printf "completed_per_sec=%.1f average_ms=%.1f\n",1000*$2/$1,$3/$2}'処理量と平均遅延 device.csvデバイス全体の記録平均100要求/秒、要求当たり40msです。各要求は並行し得るので、合計遅延8000msが測定区間2000msを超えても矛盾しません。このデバイス値には他プロセスの要求も含み得るため、PID700の待ちへ全量を割り当てません。
7抽出した呼出しの時間を集計
抽出した4呼出しの所要時間を合計し、fsyncの比率を求めます。
awk -F, 'NR>1 {total+=$6; if($3=="fsync") sync+=$6} END {printf "selected_seconds=%.3f fsync_share=%.1f%%\n",total,100*sync/total}'抽出範囲内の時間配分 trace.csv4呼出しの記録抽出分は0.656秒で、その約61%がfsyncです。2秒間の全処理を収録した記録ではないため、残り時間の原因はこの表だけでは決まりません。全体の経過時間、抽出範囲、資源別の待ちをそろえて次の調査を決めます。
まとめ
I/Oの累積値は差分にし、ストレージ量とread等の返却量を分けます。
同じPID・fd・時刻で、待った呼出しと参照先を結び付けます。
抽出した呼出しの合計や装置全体の統計を、プロセスの全経過時間と混同しません。
操作履歴と解説を振り返れます。
Bash / Linuxの記録
cat io-before.txt; cat io-after.txtrchar: 1048576 wchar: 4096 syscr: 100 syscw: 4 read_bytes: 0 write_bytes: 4096 cancelled_write_bytes: 0 rchar: 9437184 wchar: 8192 syscr: 1124 syscw: 8 read_bytes: 2097152 write_bytes: 8192 cancelled_write_bytes: 0
awk 'NR==FNR {a[$1]=$2; next} $1=="rchar:" || $1=="read_bytes:" {printf "%s %.1f MiB\n",$1,($2-a[$1])/1048576}' io-before.txt io-after.txtrchar: 8.0 MiB read_bytes: 2.0 MiB
cat fds.csvPID,FD,TYPE,TARGET 700,3,socket,socket:[8100] 700,4,file,/data/input.bin 700,5,file,/data/report.csv
head -n 1 trace.csv; tail -n +2 trace.csv | sort -t, -k6,6nrTIME,PID,CALL,FD,RESULT,DURATION_SEC 10:00:00.251,700,fsync,5,0,0.400 10:00:00.000,700,read,4,8192,0.250 10:00:00.651,700,read,3,64,0.005 10:00:00.250,700,write,5,128,0.001
awk -F, 'NR==FNR {if(FNR>1) target[$1,$2]=$4; next} FNR>1 {printf "%s fd=%s target=%s seconds=%s\n",$3,$4,target[$2,$4],$6}' fds.csv trace.csvread fd=4 target=/data/input.bin seconds=0.250 write fd=5 target=/data/report.csv seconds=0.001 fsync fd=5 target=/data/report.csv seconds=0.400 read fd=3 target=socket:[8100] seconds=0.005
awk -F, 'NR==2 {printf "completed_per_sec=%.1f average_ms=%.1f\n",1000*$2/$1,$3/$2}' device.csvcompleted_per_sec=100.0 average_ms=40.0
awk -F, 'NR>1 {total+=$6; if($3=="fsync") sync+=$6} END {printf "selected_seconds=%.3f fsync_share=%.1f%%\n",total,100*sync/total}' trace.csvselected_seconds=0.656 fsync_share=61.0%
演習完了