it-swarm-ja.com

なぜファイルをメモリに読み込んで2回計算するよりも2倍速く反復するのですか?

私は以下を比較しています

tail -n 1000000 stdout.log | grep -c '"success": true'
tail -n 1000000 stdout.log | grep -c '"success": false'

次の

log=$(tail -n 1000000 stdout.log)
echo "$log" | grep -c '"success": true'
echo "$log" | grep -c '"success": false'

驚いたことに、2番目は最初の3倍近く時間がかかります。もっと速くなるはずですよね?

26
phunehehe

次のテストを実行しましたが、私のシステムでは、2番目のスクリプトの場合、結果の差は約100倍長くなります。

私のファイルはbigfileと呼ばれるstrace出力です

$ wc -l bigfile.log 
1617000 bigfile.log

スクリプト

[email protected]:~/tmp$ cat p1.sh
tail -n 1000000 bigfile.log | grep '"success": true' | wc -l
tail -n 1000000 bigfile.log | grep '"success": false' | wc -l

[email protected]:~/tmp$ cat p2.sh
log=$(tail -n 1000000 bigfile.log)
echo "$log" | grep '"success": true' | wc -l
echo "$log" | grep '"success": true' | wc -l

実際にはgrepに一致するものがないため、wc -lへの最後のパイプには何も書き込まれません。

タイミングは次のとおりです。

[email protected]:~/tmp$ time bash p1.sh
0
0

real    0m0.381s
user    0m0.248s
sys 0m0.280s
[email protected]:~/tmp$ time bash p2.sh
0
0

real    0m46.060s
user    0m43.903s
sys 0m2.176s

したがって、straceコマンドを使用して2つのスクリプトを再度実行しました

strace -cfo p1.strace bash p1.sh
strace -cfo p2.strace bash p2.sh

トレースの結果は次のとおりです。

$ cat p1.strace 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97.24    0.508109       63514         8         2 waitpid
  1.61    0.008388           0     84569           read
  1.08    0.005659           0     42448           write
  0.06    0.000328           0     21233           _llseek
  0.00    0.000024           0       204       146 stat64
  0.00    0.000017           0       137           fstat64
  0.00    0.000000           0       283       149 open
  0.00    0.000000           0       180         8 close
...
  0.00    0.000000           0       162           mmap2
  0.00    0.000000           0        29           getuid32
  0.00    0.000000           0        29           getgid32
  0.00    0.000000           0        29           geteuid32
  0.00    0.000000           0        29           getegid32
  0.00    0.000000           0         3         1 fcntl64
  0.00    0.000000           0         7           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    0.522525                149618       332 total

そしてp2.strace

$ cat p2.strace 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 75.27    1.336886      133689        10         3 waitpid
 13.36    0.237266          11     21231           write
  4.65    0.082527        1115        74           brk
  2.48    0.044000        7333         6           execve
  2.31    0.040998        5857         7           clone
  1.91    0.033965           0    705681           read
  0.02    0.000376           0     10619           _llseek
  0.00    0.000000           0       248       132 open
...
  0.00    0.000000           0       141           mmap2
  0.00    0.000000           0       176       126 stat64
  0.00    0.000000           0       118           fstat64
  0.00    0.000000           0        25           getuid32
  0.00    0.000000           0        25           getgid32
  0.00    0.000000           0        25           geteuid32
  0.00    0.000000           0        25           getegid32
  0.00    0.000000           0         3         1 fcntl64
  0.00    0.000000           0         6           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    1.776018                738827       293 total

分析

当然のことながら、どちらの場合でも、ほとんどの時間はプロセスの完了を待機するために費やされますが、p2はp1の2.63倍待機し、他の人が述べたように、p2.shで遅れて開始しています。

そのため、waitpidを忘れて、%列を無視して、両方のトレースの秒列を確認してください。

最大時間読み取るファイルが大きいため、p1はほとんどの時間を読み取りに費やしていますが、p2はp1の28.82倍の時間を読み取りに費やしています。 -bashは、そのような大きなファイルを変数に読み込むことを想定しておらず、おそらく一度にバッファを読み込んで、行に分割してから別のバッファを取得しています。

読み取りカウント p2は705k対p1の84kですが、読み取りごとにカーネルスペースへのコンテキストスイッチと再度のコンテキストスイッチが必要です。読み取りとコンテキスト切り替えの数のほぼ10倍。

書き込み時間 p2は、p1よりも書き込みに41.93倍長く費やします

書き込み数 p1は、p2よりも多くの書き込みを実行します。ただし、42k対21kですが、はるかに高速です。

おそらく、末尾書き込みバッファとは対照的に、echoへの行のgrepが原因です。

さらに、p2は読み取りよりも書き込みに多くの時間を費やし、p1はその逆です!

その他の要素brkシステムコールの数を確認します。p2は、読み取りよりも2.42倍長いブレークに費やしています! p1で(登録もしません)。 brkは、最初に十分に割り当てられなかったためにプログラムがアドレススペースを拡張する必要がある場合です。これは、おそらくbashがそのファイルを変数に読み込む必要があり、ファイルがそれほど大きくないことを予期していないためです。 @scaiによると、ファイルが大きくなりすぎた場合でも機能しません。

tailはおそらく非常に効率的なファイルリーダーです。これはファイルリーダーが設計されたものであるため、ファイルをmemmapして改行をスキャンし、カーネルがI/Oを最適化できるようにするためです。 bashは、読み取りと書き込みに費やされた時間の両方に関して、それほど良くありません。

p2はcloneexecvに44ミリ秒と41ミリ秒を費やしています。これは、p1の測定可能な量ではありません。おそらく、テールから変数を読み取って作成することをbashします。

最終的には合計 p1は、p2 740k(4.93倍)に対して〜150kシステムコールを実行します。

Waitpidを排除すると、p1はシステムコールの実行に0.014416秒、p2は0.439132秒(30倍)を費やします。

したがって、p2はほとんどの時間をユーザー空間で費やして、システムコールの完了とカーネルがメモリを再編成するのを待つ以外は何もせず、p1はより多くの書き込みを実行しますが、より効率的で、システム負荷が大幅に減少するため、高速です。

結論

Bashスクリプトを作成するときに、メモリを介したコーディングについて心配するつもりはありません。つまり、効率を上げようとしないわけではありません。

tailは、ファイルの機能を実行するように設計されています。おそらく、ファイルをmemory mapsにして、読み取りが効率的になり、カーネルがI/Oを最適化できるようにします。

問題を最適化するためのより良い方法は、最初にgrep for '"success":'行を作成してから、真と偽をカウントすることです。grepには、wc -l、またはさらに良いことに、末尾をawkにパイプし、trueとfalseを同時にカウントします。 p2は時間がかかるだけでなく、メモリがbrksでシャッフルされている間、システムに負荷がかかります。

26
X Tian

実際、最初のソリューションもファイルをメモリに読み込みます!これはcachingと呼ばれ、オペレーティングシステムによって自動的に行われます。

mikeserv ですでに正しく説明されているように、最初の解決策はgrepwhileを除外し、ファイルは読み取られますが、 2番目のソリューションは、ファイルをtailが読み取った後後に実行します

したがって、さまざまな最適化のため、最初のソリューションはより高速です。しかし、これは常に本当である必要はありません。 OSが2番目のソリューションをキャッシュしないと決定した非常に大きなファイルの場合、高速になる可能性があります。ただし、メモリに収まらないさらに大きなファイルの場合、2番目のソリューションはまったく機能しません。

5
scai

主な違いは、echoが遅いということです。このことを考慮:

$ time (tail -n 1000000 foo | grep 'true' | wc -l; 
        tail -n 1000000 foo | grep 'false' | wc -l;)
666666
333333

real    0m0.999s
user    0m1.056s
sys     0m0.136s

$ time (log=$(tail -n 1000000 foo); echo "$log" | grep 'true' | wc -l; 
                                    echo "$log" | grep 'false' | wc -l)
666666
333333

real    0m4.132s
user    0m3.876s
sys     0m0.468s

$ time (tail -n 1000000 foo > bb;  grep 'true' bb | wc -l; 
                                   grep 'false' bb | wc -l)
666666
333333

real    0m0.568s
user    0m0.512s
sys     0m0.092s

上記のように、時間のかかる手順はデータの印刷です。単に新しいファイルにリダイレクトし、それを介してgrepを実行すると、ファイルを1回だけ読み取るときにmuch速くなります。


そして、要求に応じて、ヒア文字列で:

 $ time (log=$(tail -n 1000000 foo); grep 'true' <<< $log | wc -l; 
                                     grep 'false' <<< $log | wc -l  )
1
1

real    0m7.574s
user    0m7.092s
sys     0m0.516s

Here文字列がすべてのデータを1つの長い行に連結していて、grepが遅くなるため、これはさらに遅くなります。

$ tail -n 1000000 foo | (time grep -c 'true')
666666

real    0m0.500s
user    0m0.472s
sys     0m0.000s

$ tail -n 1000000 foo | Perl -pe 's/\n/ /' | (time grep -c 'true')
1

real    0m1.053s
user    0m0.048s
sys     0m0.068s

分割が発生しないように変数が引用されている場合、処理は少し速くなります。

 $ time (log=$(tail -n 1000000 foo); grep 'true' <<< "$log" | wc -l; 
                                     grep 'false' <<< "$log" | wc -l  )
666666
333333

real    0m6.545s
user    0m6.060s
sys     0m0.548s

しかし、速度制限ステップがデータを印刷しているため、まだ低速です。

3
terdon