8.2.2. 処理時間の測り方¶

　コマンドの処理時間は、timeコマンドで測ります。 ファイルを全部解凍してファイルに出力する時間を測ってみましょう。

$ time zcat *.gz > hoge

   
real 0m0.957s user 0m0.588s sys 0m0.156s 

realが実際（我々の世界）でかかった時間、 userとsysはそれぞれ、CPU時間（CPUが働いた時間）のうち、 ユーザモードだった（カーネル以外のプログラムが動いた）時間、 カーネルモードだった時間です。 普通は何らかの原因でプログラムが待たされ、 CPU時間よりもrealの時間が長くなります。

　計測の際、ハードディスクへの出力の遅延を気にしたくない場合は、 次のように /dev/null というところに出力をリダイレクトします。 この例の場合は、ほぼ read = user + sys になっています。

$ time zcat *.gz > /dev/null

   
real 0m0.563s user 0m0.560s sys 0m0.004s 

　 /dev/null （ビットバケツ）はなんでも吸い込んで消してしまう特殊なファイルです。 コマンドの出力をここにリダイレクトしておくと、 消えてなくなります。 コマンドは接続先が /dev/null でも律儀に出力を行うので、 この時間は計測されます。 ちなみに、筆者は /dev/null を「デブヌル」と呼んでいます。

　もう一つ、パイプでつながっていないコマンドの処理時間を端末で計測したいときには、 以下のようにコマンドをセミコロンで区切って括弧で囲む方法があります。 あるいはシェルスクリプトにして、 $ time ./hoge.sh のように呼び出してもよいでしょう。

$ time ( sleep 1 ; sleep 2 )

   
real 0m3.003s user 0m0.000s sys 0m0.000s 

8.2.3. パイプラインの並列処理¶

　では、まずパイプを使うと何が起こるか見てみましょう。

リスト2：パイプを使う

 1 2 3 4 5 6 7 8 9 10

$ time sed 's/a/b/g' < log1G > /dev/null

   
real 0m12.439s user 0m10.505s sys 0m0.876s $ time sed 's/a/b/g' < log1G | sed 's/b/a/g' > /dev/null
   
real 0m14.938s user 0m24.338s sys 0m1.900s 

リスト2の上の処理は log1G ファイルをsedコマンドで読み込み、 aをすべてbに置換しています。 下の処理では、さらにパイプの後ろにsedコマンドをつなげ、 bをaに置換しています。 下の処理の方が2.5[s]遅いですが、注目すべきはuserの値がrealの値を上回っていることです。 実際にかかった時間よりもCPU時間が長いということは、 平均してCPUが1個以上使われているということになり、 並列化されているということになります。 リスト3は、処理中にtopコマンドを打ってみたものです。 sedのCPU使用率が92%と82%で、足すとsedだけで1.7個CPUを使用していることになります。

リスト3: sedをパイプでつないだ処理中のtop

1 2 3 4 5 6

$ top -n 1 -b | sed -n '/PID/,$p' | head -n 5 PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 13108 ueda 20 0 16644 832 704 R 92 0.0 0:04.37 sed 13107 ueda 20 0 16644 828 704 R 82 0.0 0:03.82 sed 1089 root 20 0 198m 25m 6480 S 2 1.4 5:40.79 Xorg 2023 ueda 20 0 1261m 64m 10m S 2 3.4 4:06.40 compiz 

　ちなみに、この処理をパイプを使わずに行うとこうなります。

$ sed 's/a/b/g' < log1G > hoge ; sed 's/b/a/g' < hoge > /dev/null ; rm hoge

   
real 0m43.570s user 0m23.893s sys 0m4.480s 

当然、途中でファイルに書き出す手間がかかるので、時間を食うことになります。 また、中間ファイルは消さないといけません。 書き方もゴテゴテしています。面倒です。

8.2.4. もっとつなぐとどうなるか？¶

　パイプで並列処理ができるとなると、 どこまでパイプでつないでよいのかという疑問が生じます。 普通、この手のテクニックは度が過ぎるとパフォーマンスが落ちるものです。

　実験をしてみます。 sedで1GBのファイルのアルファベットを一文字ずつ変換してみます。 下のコマンドラインのように、aをb、cをd・・・ と変換するsedコマンドをパイプで数珠つなぎにして処理時間を計測します。 sedの数は1～13まで変化させます。 処理の総量はsedの数に比例して大きくなります。

#2個連結 $ time sed 's/a/b/g' < log1G | sed 's/c/d/g' > /dev/null #13個連結 $ time sed 's/a/b/g' < log1G | sed 's/c/d/g' | (略) | sed 's/w/x/g' | sed 's/y/z/g' > /dev/null 

　計測は、これまで使ってきたノートPCの他に、 CPUを8コア持っているサーバ機でもやってみました。 スペックは書きませんが、CPUを8個全部使えることができれば、 高い並列化の効果を観測できるかもしれません。

　図1に、計時結果をグラフを示します。 （脚注：これもシェルスクリプトで描いています。4月号・5月号参考のこと。 細かくデザインしやすいからで、別に意固地になっているわけではありません。）

↓図1：処理時間

ほぼ線形で時間が増えており、 処理量に比例して時間が増えているように見えます。 この図ではあまり傾向がつかめないので、 計測時間をsedの数で割ってみたものを図2に示します。 この図は、同じ処理量で計算能力を比較したものになります。 （ただし、ファイルを読み出す時間を考慮するとsedの数が多い方が若干有利な値になります。）

↓図2：sed一個あたりの処理時間

こちらの図は並列化の効果がよくわかります。 どちらのマシンでも、sedが1個のときよりも2個のときの方が、 時間あたりにたくさんの処理をこなしています。 8CPUのサーバの場合は、7個あたりまで時間が短くなっています。

　また、パイプでつながったsedの数がCPUの数を上回っても、 この範囲のsedの数では性能が落ちないことも分かります。 つまり、思いつく限りずらずらコマンドをパイプで並べていってもパイプが詰まる心配は小さいと言えます。

8.2.5. 負荷にばらつきがある場合¶

　sedの実験では、それぞれのsedの負荷にあまり違いがないようにしていましたが、 そうでないときはどうなるでしょうか？

　例えば、同じ置換のコマンドであっても、trコマンドはsedに比べてかなり高速です。 そのため、sedとtrをパイプでつなげると、順序はどっちでも、 リスト4の例のようにtrの方が遊んでしまいます。

リスト4：sedとtrをつなげるとtrが遊ぶ

 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18

$ sed 's/a/b/g' < log1G | tr 'c' 'd' > /dev/null #別のターミナルでtopを打ったときの出力の抜粋 #sedの出力をtrが待ってしまう %CPU %MEM TIME+ COMMAND 96 0.0 0:07.82 sed 23 0.0 0:01.89 tr 10 14.4 12:03.30 chromium-browse 2 0.0 0:03.36 kswapd0

   
#trを先にしてみる $ tr 'c' 'd' < log1G | sed 's/a/b/g' > /dev/null #別のターミナルでtopを打ってみる #sedが入力を受け付けるまでtrが待ってしまう %CPU %MEM TIME+ COMMAND 86 0.0 0:03.25 sed 29 0.0 0:01.04 tr 2 0.0 0:04.23 kswapd0 2 1.1 8:51.42 Xorg 

　また、grepで検索した結果を後続のコマンドで処理するというのはよくあることですが、 このときは後のコマンドで扱うデータ量が少ないので、これも負荷に違いが出ます。 例えば次のワンライナーでは、grepとawkで扱うレコード数が数倍違うので、 負荷もそれくらいの違いが出ます。

1 2 3 4 5 6

#「Chrome」という単語のある #レコードからIPと時刻を抜き出す $ grep Chrome log1G | awk '{print $1,$4,$5}' 114.182.aaa.xxx [05/Feb/2012:16:24:46 +0900] 114.182.aaa.xxx [05/Feb/2012:16:24:46 +0900] ・・・ 

　これら場合は、一番負荷の高いコマンドの処理時間以上に処理が早く終わることはありません。 これはパイプの並列化の限界で、 もしもっと早い処理が必要ならば、別の方法をとる必要があります。

　ただし、負荷の高いコマンドを待っている間にCPUを効率的に使うことは可能です。 下の例のように、sedがほぼ1個分のCPUを占領していても、 他のコマンドの負荷が軽ければそちらで勝手に処理が分散されます。

$ time sed 's/a/b/g' < log1G | tr 'c' 'd' | tr 'e' 'f' | tr 'g' 'h' | tr 'i' 'j' | tr 'k' 'l' > /dev/null

   
#topの抜粋。sedで82%、あとのtrで91% %CPU %MEM TIME+ COMMAND 82 0.0 0:04.95 sed 19 0.0 0:01.28 tr 16 0.0 0:00.92 tr 14 0.0 0:00.90 tr 14 0.0 0:00.86 tr 14 0.0 0:00.90 tr 14 0.0 0:00.82 tr 

　冒頭で、 「たとえCPUが1個であっても、細かい時間間隔で各コマンドが入り乱れて動く」 と言ったように、コマンドを二つつなげたらそれぞれがCPUを一個ずつ占領するわけではありません。 パイプにコマンドが3個以上あっても、 CPUが遊ばないように負荷分散されます。 パイプが何段必要かは処理によって違うので、 無理にパイプをつなげて処理することはありませんが、 ちょっと頭の隅に置いておくとよいでしょう。

　もう一つ、特にawkやsedを使って重たい処理をする場合に実践的な方法ですが、 処理を分割すると早くなるという例を下に示します。

 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19

#このような、日付と時刻を加工する処理 #入力 114.182.aaa.xxx - - [05/Feb/2012:16:24:46 +0900] "GET （略） #出力 114.182.aaa.xxx - - [ 05 Feb 2012 162446 +0900] "GET （略）

   
#一個のsedで処理 #sedで置換ルールを二つ以上指定するときは-eというオプションを使う $ time sed -e 's@\(..\)/\(...\)/\(....\)@ \1 \2 \3@' -e 's/:\(..\):\(..\):\(..\)/ \1\2\3/' < log1G > /dev/null
   
real 0m29.488s user 0m28.994s sys 0m0.492s #日付の処理と時刻の処理を分割 $ time sed -e 's@\(..\)/\(...\)/\(....\)@ \1 \2 \3@' < log1G | sed -e 's/:\(..\):\(..\):\(..\)/ \1\2\3/' > /dev/null
   
real 0m22.807s user 0m32.382s sys 0m2.064s 

ハードディスクの読み出しよりも処理がボトルネックになる場合は、 このように処理を分割した方が処理が早く終わる場合が多いです。 また、シェルスクリプトの場合は分けて書いた方が読みやすくなります。

　これの処理については、先ほどパイプをたくさんつなげる実験をした8CPUのサーバでもやってみました。 たくさんコマンドをつなげることに抵抗がなければ、CPUが多い環境だとこれだけ速くなるという例です。 ちょっといい加減なコードですが・・・。

 1 2 3 4 5 6 7 8 9 10 11

$ time sed -e 's@\(..\)/\(...\)/\(....\)@ \1 \2 \3@' -e 's/:\(..\):\(..\):\(..\)/ \1\2\3/' < log1G > /dev/null

   
real 0m17.551s user 0m17.209s sys 0m0.303s
   
$ time sed 's/\[/& /' < log1G | sed 's@/@ @' | sed 's@/@ @' | sed 's/:/ /' | sed 's/://' | sed 's/://' > /dev/null
   
real 0m5.773s user 0m17.252s sys 0m10.959s 

8.2.6. データをブロックするコマンドがある場合¶

　sortのように全部データを読み込まないと出力をしないコマンドも、 ボトルネックになります。 次の場合、sortが終わるまで、awk以後の処理は開始しません。

1

$ time zcat .gz | sort | awk '{print $1}' | uniq c-

これも無理に回避する必要はありませんが、 早く処理を終わらせるテクニックはあります。

　上の例の場合は、単純にgrepとawkの順序を変えるだけでかなり処理時間が違ってきます。

 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16

$ time zcat .gz | sort | awk '{print $1}' | uniq -c | head -n 3 10 1.112.aaa.xxx 37 1.112.bbb.yyy 10 1.112.ccc.zzz

   
real 0m5.561s user 0m4.544s sys 0m0.384s $ time zcat *.gz | awk '{print $1}' | sort | uniq -c | head -n 3 10 1.112.aaa.xxx 37 1.112.bbb.yyy 10 1.112.ccc.zzz
   
real 0m1.991s user 0m2.452s sys 0m0.144s 

この例では単にsortに入れるデータ量を減らすということが効率の改善になっていますが、 例えば後者の並び次の二つのグループが同時に実行されることが分かっていることも大事です。

• zcat、awk、sortのデータ読み込み
• sortの出力、uniq、head

実際、後者のreal値とuser値が逆転しているように、 並列化の効果はsortが間にあってもちゃんと出ています。