Hatena::ブログ(Diary)

ablog このページをアンテナに追加 RSSフィード Twitter

2015-08-30

Oracle RAC の投票ディスクについて

オラクルマスター教科書 ORACLE MASTER Expert 【RAC】編(試験番号:1Z0-048)

P.460

投票ディスクの機能

CSSD(Cluster Syncronization Service デーモン)は、インターコネクトを介してほかのノード通信し、通信状況を投票ディスクに格納します。インターコネクトに障害が発生した場合、共有ディスクに対するI/Oの同期が取れなくなるため、クラスタが分断された状態になります。クラスタ孤立するとほかのノードが使用可能か判断できなくなり、同じデータベースに対して非同期アクセスすることでデータベースの不整合が発生する可能性があります。このような状況は「スプリットブレイン」と呼ばれ、投票ディスクはスプリットブレインを解決するために使用されます。

スプリットブレインが発生すると、孤立したノードを削除する必要があります。その際には、通信できるノード数の多いノード群を残存ノードにし、少ないノード群を削除にします。ノード数が等しい場合は、小さいノード番号が割り当てられているノードを残存ノードにし、大きいノード番号が割り当てられているノードを削除します。削除されることになったノードは、全ての書き込みI/Oを停止するためにノード再起動します。ノード数が変化したときのノードリストの再構成を「クラスタ再構成」と呼びます。

P.461

投票ディスクの動作に影響を与えるパラメータ

インターコネクトを使用したネットワークのハートビートと投票ディスクへのI/Oは、1秒間隔で実行されます。ハートビートが識別できなかったり投票ディスクへのI/Oタイムアウトすると、該当するノード再起動します。タイムアウトの設定には、MISSCOUNTとDISKTIMEOUTの2つのパラメータが関係します。

  • MISSCOUNT
  • DISKTIMEOUT
    • 投票ディスクへのディスクI/Oが実行できないと判定されるまえでの最大許容時間(秒単位)です。この時間を経過するとノードを削除するためにクラスタ再構成が行われます。デフォルトは200秒です。

DISKTIMEOUTを使用して投票ディスクへのI/Oタイムアウトが設定されるのは、10.2.0.2以降です。10.2.0.1の場合は、MISSCOUNT-3秒がディスクタイムアウトのしきい値になります。


サポートエンジニアが語る!RAC 環境のトラブルシューティング

P.15-19

f:id:yohei-a:20150830140631p:image:w640

f:id:yohei-a:20150830140628p:image:w640

f:id:yohei-a:20150830140626p:image:w640

f:id:yohei-a:20150830141126p:image:w640

f:id:yohei-a:20150830141124p:image:w640


Oracle Database 11g Oracle Real Application Clusters Handbook, 2nd Edition (Oracle Press)

  • CHAPTER 14 Oracle RAC Troubleshooting
    • Debugging Node Eviction Issues

One of the most common and complex issues in Oracle RAC is performing the root cause analysis (RCA) of the node eviction issues. Oracle evicts a node from the cluster mainly due to one of the following three reasons:

Oracle Grid Infrastructureインストレーション・ガイド 11gリリース2 (11.2) for Linux B56271-12

  • 2.13 Intelligent Platform Management Interface(IPMI)の有効化

Intelligent Platform Management Interface(IPMI)は、コンピュータハードウェアおよびファームウェアへの共通インタフェースを提供し、システム管理者はそのインタフェースを使用して、システム状態の監視およびシステムの管理を実行できます。Oracle 11g リリース2では、Oracle ClusterwareにIPMIを統合して、障害分離をサポートしたりクラスタの整合性を確保することができます。

インストール中にノード・ターミネーション・プロトコル(IPMIなど)を選択することで、IPMIでノード・ターミネーションを構成できます。また、IPMIは、crsctlコマンドを使用してインストール後に構成することもできます。


http://www.oracle.com/technetwork/jp/database/enterprise-edition/db11gr2-10-134833-ja.pdf

P.36

IPMI: ハードウェアファームウェア に共通インターフェースを提供することによってシステムを監視します。

OUI では、IPMI を利用して障害が発生したリモート・ノードの停止を実施する仕組みを構成可能です。OUI でのインストール実行後に手動で構成することも可能です。

IPMI の使用

Oracle Clusterware で IPMI を使用する場合には、OUI にて Grid Infrastructure のインストール時に IPMI の構成(ADMIN 権限を持 ザ名やパ ドの入力)が可能です あるい 権限を持つユーザ名やパスワードの入力)が可能です。あるいはインストール終了後に手動で設定が可能です。

また、IPMI を設定する際には事前に OS 側で IPMI を構成し使用可能な状態にしておく必要があります。


絵で見てわかるシステム構築のためのOracle設計 (DB Selection)

絵で見てわかるシステム構築のためのOracle設計 (DB Selection)

2015-08-08

pgrep で子プロセスの PID を調べる

プロセスの PID を取得したい場合、人間が見るには pstree が便利だけど、

$ pstree -alp $$  
zsh,13840
  ├─pstree,14216 -alp 13840
  ├─zsh,13940
  │   └─sleep,14213 10
  └─zsh,13992
      └─sleep,14215 10

シェルスクリプトで子プロセスの PID を取得して何か自動処理したいときには pgrep が便利そう。

  • P: 親プロセスの PID を指定
  • d: デリミタを指定
$ pgrep -d: -P $$ 
13940:13992

参考

2015-08-06

プロセスのランキュー待ち時間とI/O待ち時間を調べる

cat file|awk では実行時間 < CPU時間となっていますが、cat が I/O wait していないとは限りません。実行時間は単純に終了時間 - 開始時間で算出しますが、CPU時間はプロセスCPU時間を getrusage システムコールで取得します。catのプロセスawkプロセスが並列実行されている期間があるため、実行時間 < CPU時間となっています。例えば、CPUバウンドな2プロセスがほぼ完全に並列実行されると、実行時間 * 2 ≒ CPU時間 となったりします。

(中略)

f:id:yohei-a:20150807083842p:image:w640

大きなテキストファイルをawkで処理するときにcatで投げ込むと速い理由 - ablog

と書きましたが、プロセス

  • ランキュー待ち時間は /proc/<pid>/sched の2列目(sched_info.run_delay)
  • I/O待ち時間は /proc/<pid>/schedstat の se.statistics.iowait_sum

で調べることができます(たぶん)。


Brendan Gregg の USE Method: Linux Performance Checklist にも書かれていました。

Physical Resources

componenttypemetric
CPUsaturationsystem-wide: vmstat 1, "r" > CPU count [2]; sar -q, "runq-sz" > CPU count; dstat -p, "run" > CPU count; per-process: /proc/PID/schedstat 2nd field (sched_info.run_delay); perf sched latency (shows "Average" and "Maximum" delay per-schedule); dynamic tracing, eg, SystemTap schedtimes.stp "queued(us)" [3]
Storage device I/Outilizationsystem-wide: iostat -xz 1, "%util"; sar -d, "%util"; per-process: iotop; pidstat -d; /proc/PID/sched "se.statistics.iowait_sum"
USE Method: Linux Performance Checklist

プロセスのランキュー待ち時間を調べる

分析結果

/proc/<pid>/sched の2列目(sched_info.run_delay) を1秒間隔でサンプリングしたもののデルタ値をグラフ化したものです。秒間で最大30ミリ秒程度ランキュー待ちしていることがわかります。

f:id:yohei-a:20150807083100p:image:w640


手順
$ time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; } &
[2] 7125
$ pstree -alp $$
bash,4227
  ├─bash,6906
  ├─bash,7125
  │   ├─awk,7127 $5\040~\040/00$/\040{print}
  │   └─cat,7126 sample.txt
  └─pstree,7128 -alp 4227
$ while :; do cat /proc/7126/schedstat|awk '{print strftime("%y-%m-%d %H:%M:%S"), $0}'; sleep 1; done
15-08-06 21:36:45 383345672 191046611 110195
15-08-06 21:36:46 423034353 219229112 123027
15-08-06 21:36:47 462241056 244457968 136128
15-08-06 21:36:48 500990500 256206129 149262
15-08-06 21:36:49 539925919 274300181 162458
15-08-06 21:36:50 578372401 299073669 175502
15-08-06 21:36:51 616229970 321905887 188106
15-08-06 21:36:52 657995074 344450537 199886
15-08-06 21:36:53 695856409 360521384 213114
15-08-06 21:36:54 733568047 379649740 225926
15-08-06 21:36:55 772121747 410237735 238805
15-08-06 21:36:56 811170984 439155374 251822
15-08-06 21:36:57 850370696 465749478 264767
15-08-06 21:36:58 890058031 484898263 278059
15-08-06 21:36:59 929623665 502559894 291335
15-08-06 21:37:00 967534110 521142065 304264
15-08-06 21:37:01 1005369475 548146247 317000
15-08-06 21:37:02 1045520743 570541563 330048
15-08-06 21:37:03 1084174346 595538881 342781
15-08-06 21:37:04 1122857147 624379948 355558
15-08-06 21:37:05 1161376812 644308940 368760
15-08-06 21:37:06 1199607045 662688976 381716
15-08-06 21:37:07 1238034816 684981820 394697
15-08-06 21:37:08 1276644529 700901178 407911
15-08-06 21:37:09 1314893392 725301702 420697
15-08-06 21:37:10 1353172176 751330360 433661
15-08-06 21:37:11 1391506701 781730973 446465
15-08-06 21:37:12 1430111400 808695732 459453
15-08-06 21:37:13 1467890931 824451306 472343
15-08-06 21:37:14 1506399258 843147547 485447
15-08-06 21:37:15 1544417093 873616546 498517
15-08-06 21:37:16 1583421820 894680563 509600
15-08-06 21:37:17 1622831983 919412658 522427
15-08-06 21:37:18 1661565247 943010058 535545
15-08-06 21:37:19 1699449046 965567060 548420
15-08-06 21:37:20 1737512755 990405342 561547
15-08-06 21:37:21 1775750584 1009670772 574741
15-08-06 21:37:22 1813066160 1031995672 587582
15-08-06 21:37:23 1851382288 1058140829 600612
15-08-06 21:37:24 1890265617 1082606489 613648
15-08-06 21:37:25 1927966940 1101233300 626576
15-08-06 21:37:26 1965556572 1122902677 639485
15-08-06 21:37:27 2004574469 1135810609 652729
15-08-06 21:37:28 2043342617 1154135252 665729

real	0m52.387s
user	0m51.237s
sys	0m2.828s
[2]-  Done                    time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; }
cat: /proc/7126/schedstat: No such file or directory

プロセスI/O待ち時間を調べる

分析結果

/proc/<pid>/schedstat の se.statistics.iowait_sum を1秒間隔でサンプリングしたもののデルタ値をグラフ化したものです。単位はナノ秒のようです。

f:id:yohei-a:20150807083059p:image:w640

手順
$ time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; } &
$ pstree -alp $$
bash,4227
  ├─bash,6906
  ├─bash,8290
  │   ├─awk,8292 $5\040~\040/00$/\040{print}
  │   └─cat,8291 sample.txt
  └─pstree,8296 -alp 4227
$ while :; do cat /proc/8291/sched|awk '{print strftime("%y-%m-%d %H:%M:%S"), $0}'; sleep 1; done
15-08-06 22:11:45 cat (8291, #threads: 1)
15-08-06 22:11:45 ---------------------------------------------------------
15-08-06 22:11:45 se.exec_start                      :       5789181.672512
15-08-06 22:11:45 se.vruntime                        :      17852208.688334
15-08-06 22:11:45 se.sum_exec_runtime                :           898.581661
15-08-06 22:11:45 se.statistics.wait_start           :       5789181.856209
15-08-06 22:11:45 se.statistics.sleep_start          :             0.000000
15-08-06 22:11:45 se.statistics.block_start          :             0.000000
15-08-06 22:11:45 se.statistics.sleep_max            :            19.405457
15-08-06 22:11:45 se.statistics.block_max            :             8.517829
15-08-06 22:11:45 se.statistics.exec_max             :             0.315179
15-08-06 22:11:45 se.statistics.slice_max            :             0.303532
15-08-06 22:11:45 se.statistics.wait_max             :             3.450454
15-08-06 22:11:45 se.statistics.wait_sum             :           176.897778
15-08-06 22:11:45 se.statistics.wait_count           :               220924
15-08-06 22:11:45 se.statistics.iowait_sum           :            79.213880
15-08-06 22:11:45 se.statistics.iowait_count         :                   31
15-08-06 22:11:45 se.nr_migrations                   :                14756
15-08-06 22:11:45 se.statistics.nr_migrations_cold   :                    0
15-08-06 22:11:45 se.statistics.nr_failed_migrations_affine:                    0
15-08-06 22:11:45 se.statistics.nr_failed_migrations_running:                  100
15-08-06 22:11:45 se.statistics.nr_failed_migrations_hot:                  169
15-08-06 22:11:45 se.statistics.nr_forced_migrations :                    1
15-08-06 22:11:45 se.statistics.nr_wakeups           :               220832
15-08-06 22:11:45 se.statistics.nr_wakeups_sync      :               213774
15-08-06 22:11:45 se.statistics.nr_wakeups_migrate   :                14730
15-08-06 22:11:45 se.statistics.nr_wakeups_local     :                29500
15-08-06 22:11:45 se.statistics.nr_wakeups_remote    :               191332
15-08-06 22:11:45 se.statistics.nr_wakeups_affine    :                  538
15-08-06 22:11:45 se.statistics.nr_wakeups_affine_attempts:                  855
15-08-06 22:11:45 se.statistics.nr_wakeups_passive   :                    0
15-08-06 22:11:45 se.statistics.nr_wakeups_idle      :                    0
15-08-06 22:11:45 avg_atom                           :             0.004067
15-08-06 22:11:45 avg_per_cpu                        :             0.060896
15-08-06 22:11:45 nr_switches                        :               220898
15-08-06 22:11:45 nr_voluntary_switches              :               220833
15-08-06 22:11:45 nr_involuntary_switches            :                   66
15-08-06 22:11:45 se.load.weight                     :                 1024
15-08-06 22:11:45 policy                             :                    0
15-08-06 22:11:45 prio                               :                  120
15-08-06 22:11:45 clock-delta                        :                   56
15-08-06 22:11:46 cat (8291, #threads: 1)
15-08-06 22:11:46 ---------------------------------------------------------
15-08-06 22:11:46 se.exec_start                      :       5790193.560503
15-08-06 22:11:46 se.vruntime                        :      17853207.587196
15-08-06 22:11:46 se.sum_exec_runtime                :           946.724633
15-08-06 22:11:46 se.statistics.wait_start           :             0.000000
15-08-06 22:11:46 se.statistics.sleep_start          :       5790193.560503
15-08-06 22:11:46 se.statistics.block_start          :             0.000000
15-08-06 22:11:46 se.statistics.sleep_max            :            19.405457
15-08-06 22:11:46 se.statistics.block_max            :             8.517829
15-08-06 22:11:46 se.statistics.exec_max             :             0.315179
15-08-06 22:11:46 se.statistics.slice_max            :             0.303532
15-08-06 22:11:46 se.statistics.wait_max             :             3.450454
15-08-06 22:11:46 se.statistics.wait_sum             :           178.163357
15-08-06 22:11:46 se.statistics.wait_count           :               232283
15-08-06 22:11:46 se.statistics.iowait_sum           :            89.090687
15-08-06 22:11:46 se.statistics.iowait_count         :                   33
15-08-06 22:11:46 se.nr_migrations                   :                15553
15-08-06 22:11:46 se.statistics.nr_migrations_cold   :                    0
15-08-06 22:11:46 se.statistics.nr_failed_migrations_affine:                    0
15-08-06 22:11:46 se.statistics.nr_failed_migrations_running:                  104
15-08-06 22:11:46 se.statistics.nr_failed_migrations_hot:                  169
15-08-06 22:11:46 se.statistics.nr_forced_migrations :                    1
15-08-06 22:11:46 se.statistics.nr_wakeups           :               232190
15-08-06 22:11:46 se.statistics.nr_wakeups_sync      :               224776
15-08-06 22:11:46 se.statistics.nr_wakeups_migrate   :                15526
15-08-06 22:11:46 se.statistics.nr_wakeups_local     :                31523
15-08-06 22:11:46 se.statistics.nr_wakeups_remote    :               200667
15-08-06 22:11:46 se.statistics.nr_wakeups_affine    :                  538
15-08-06 22:11:46 se.statistics.nr_wakeups_affine_attempts:                  863
15-08-06 22:11:46 se.statistics.nr_wakeups_passive   :                    0
15-08-06 22:11:46 se.statistics.nr_wakeups_idle      :                    0
15-08-06 22:11:46 avg_atom                           :             0.004076
15-08-06 22:11:46 avg_per_cpu                        :             0.060870
15-08-06 22:11:46 nr_switches                        :               232257
15-08-06 22:11:46 nr_voluntary_switches              :               232190
15-08-06 22:11:46 nr_involuntary_switches            :                   67
15-08-06 22:11:46 se.load.weight                     :                 1024
15-08-06 22:11:46 policy                             :                    0
15-08-06 22:11:46 prio                               :                  120
15-08-06 22:11:46 clock-delta                        :                   52
15-08-06 22:12:23 se.load.weight                     :                 1024
15-08-06 22:12:23 policy                             :                    0
15-08-06 22:12:23 prio                               :                  120
15-08-06 22:12:23 clock-delta                        :                   60

...

real	0m57.677s
user	0m55.928s
sys	0m3.728s
[2]-  Done                    time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; }
cat: /proc/8291/sched: No such file or directory

補足

we have how long we wait. we do not have how long we iowait afaik... at least not in nanosecond granularity. (We do have the sampled data, but that is milisecond sampled data, not very useful for making charts based on time to show the sequence of events)

Linux Kernel - [PATCH] sched: Provide iowait counters
#ifdef CONFIG_SCHEDSTATS
/*
 * Provides /proc/PID/schedstat
 */
static int proc_pid_schedstat(struct task_struct *task, char *buffer)
{
        return sprintf(buffer, "%llu %llu %lu\n",
                        (unsigned long long)task->se.sum_exec_runtime,
                        (unsigned long long)task->sched_info.run_delay,
                        task->sched_info.pcount);
}
#endif
static void enqueue_sleeper(struct cfs_rq *cfs_rq, struct sched_entity *se)
{
#ifdef CONFIG_SCHEDSTATS
        struct task_struct *tsk = NULL;

        if (entity_is_task(se))
                tsk = task_of(se);

        if (se->statistics.sleep_start) {
                u64 delta = rq_of(cfs_rq)->clock - se->statistics.sleep_start;

                if ((s64)delta < 0)
                        delta = 0;

                if (unlikely(delta > se->statistics.sleep_max))
                        se->statistics.sleep_max = delta;

                se->statistics.sleep_start = 0;
                se->statistics.sum_sleep_runtime += delta;

                if (tsk) {
                        account_scheduler_latency(tsk, delta >> 10, 1);
                        trace_sched_stat_sleep(tsk, delta);
                }
        }
        if (se->statistics.block_start) {
                u64 delta = rq_of(cfs_rq)->clock - se->statistics.block_start;

                if ((s64)delta < 0)
                        delta = 0;
                if (unlikely(delta > se->statistics.block_max))
                        se->statistics.block_max = delta;

                se->statistics.block_start = 0;
                se->statistics.sum_sleep_runtime += delta;

                if (tsk) {
                        if (tsk->in_iowait) {
                                se->statistics.iowait_sum += delta;
                                se->statistics.iowait_count++;
                                trace_sched_stat_iowait(tsk, delta);
                        }

                        /*
                         * Blocking time is in units of nanosecs, so shift by
                         * 20 to get a milliseconds-range estimation of the
                         * amount of time that the task spent sleeping:
                         */
                        if (unlikely(prof_on == SLEEP_PROFILING)) {
                                profile_hits(SLEEP_PROFILING,
                                                (void *)get_wchan(tsk),
                                                delta >> 20);
                        }
                        account_scheduler_latency(tsk, delta >> 10, 0);
                }
        }
#end

参考

2015-08-03

”私の環境で”大きなテキストファイルをawkで処理するときにcatで投げ込むと速い理由

大きなテキストファイルをawkで処理するときにcatで投げ込むと速い理由 - ablog を書きましたが、awk file > file より cat file|awk > file が速い環境は稀なようなので、私の環境でなぜ cat file|awk > file のほうが速いのか調べてみました。プロセススケジューラが関係しているようです。

f:id:yohei-a:20150802105256p:image:w640

↑はPerf + Flame Graphs で、awk file > file 実行時のコールスタックと所要時間を可視化したものです。


結論(たぶん)


分析結果

awk file > file

awk file > file では暗号化データを復号するカーネルスレッドawkプロセスプロセススケジューラがなぜか同じ CPUスケジューリングし、並列処理できていない。

  • awk file > file を実行する
$ time awk '$5 ~ /00$/ {print}' sample.txt > result1.txt
real	1m12.940s
user	0m59.059s
sys	0m1.477s
$ top -c 
# f を押して、j(Last used cpu (SMP))、l(CPU Time)、y(Sleeping in Function) を押して、return
top - 01:34:00 up  2:06,  8 users,  load average: 1.17, 0.90, 0.74
Tasks: 227 total,   3 running, 224 sleeping,   0 stopped,   0 zombie
Cpu(s): 20.6%us,  4.2%sy,  0.0%ni, 75.1%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:  16158544k total,  2895472k used, 13263072k free,     3176k buffers
Swap:  8085500k total,        0k used,  8085500k free,  2148524k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P★CPU番号   TIME WCHAN     COMMAND
 9577 yazekats  20   0  103m  780  644 R 83.4  0.0   0:37.65 0   0:37 -         awk $5 ~ /00$/ {print} sample.txt ★カーネルスレッドと同じ CPU0 を使っている
 6230 root      20   0     0    0    0 S  8.6  0.0   0:09.30 0   0:09 worker_th [kworker/0:2] ★カーネルスレッドは CPU0 を使用
 9349 root      20   0     0    0    0 S  7.3  0.0   0:03.82 0   0:03 worker_th [kworker/0:1] ★カーネルスレッドは CPU0 を使用
 9303 yazekats  20   0 15204 1248  860 R  0.7  0.0   0:00.83 1   0:00 -         top -c
 6240 root      20   0     0    0    0 R  0.3  0.0   0:00.93 1   0:00 ?         [kworker/1:0]

top で表示されるCPU番号は正確には最後に使ったCPU番号です。


cat file|awk > file

cat file|awk > file では cat、awk、復号するカーネルスレッドが別々のCPUスケジューリングされ、並列処理できている。

  • cat file|awk > file を実行する。
$  time { cat sample.txt|awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m52.097s
user	0m50.920s
sys	0m2.846s
top - 01:45:59 up  2:18,  8 users,  load average: 1.37, 1.04, 0.83
Tasks: 228 total,   3 running, 225 sleeping,   0 stopped,   0 zombie
Cpu(s): 25.0%us,  6.2%sy,  0.0%ni, 68.7%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:  16158544k total,  2358376k used, 13800168k free,     5712k buffers
Swap:  8085500k total,        0k used,  8085500k free,  1604420k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P★CPU番号   TIME WCHAN     COMMAND
 9721 yazekats  20   0  103m  780  644 R 99.7  0.0   0:23.06 3★   0:23 -         awk $5 ~ /00$/ {print} ★1CPUをほぼ使い切っている
 9672 root      20   0     0    0    0 S 20.3  0.0   0:19.08 0★   0:19 worker_th [kworker/0:1]
 9720 yazekats  20   0 98.6m  484  416 S  4.0  0.0   0:00.91 2★   0:00 pipe_wait★ cat sample.txt ★cat はこの瞬間はパイプへの書込み待ちでスリープ

検証

  • taskset コマンドで awk file > file 実行時に使うCPU番号を明示的に指定すると、awk と復号するカーネルスレッドが別のCPUを使って並列処理され、速くなりました。
$ time taskset -c 3 awk '$5 ~ /00$/ {print}' sample.txt > result1.txt
real	0m54.180s ★ cat file|awk > file に近い実行時間になっています
user	0m51.277s
sys	0m1.151s
Tasks: 226 total,   2 running, 224 sleeping,   0 stopped,   0 zombie
Cpu(s): 24.0%us,  5.5%sy,  0.0%ni, 70.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  16158544k total,  3458788k used, 12699756k free,     6656k buffers
Swap:  8085500k total,        0k used,  8085500k free,  2698136k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P★CPU番号   TIME WCHAN     COMMAND
 9783 yazekats  20   0  103m  780  644 R 97.6★  0.0   0:43.60 3★   0:43 -         awk $5 ~ /00$/ {print} sample.txt
 9784 root      20   0     0    0    0 S 18.6  0.0   0:05.79 0★   0:05 worker_th [kworker/0:2]
 4431 yazekats  20   0 15196 1236  856 S  0.7  0.0   0:24.78 1   0:24 poll_sche top -c

補足

  • 検証の前には都度ページキャッシュを解放しています。
# echo 3 > /proc/sys/vm/drop_caches
  • ベースライン
$ time { awk '$5 ~ /00$/ {print}' sample.txt > result1.txt; }
real	1m9.755s
user	0m56.078s
sys	0m1.593s
$ time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m59.299s
user	0m56.994s
sys	0m4.005s
  • "> file" しなくても実行時間はほぼ同じため、write はボトルネックになっていない。
$ time { awk '$5 ~ /00$/ {print}' sample.txt > /dev/null; }
real	1m11.339s
user	0m57.730s
sys	0m1.304s
$ time { awk '$5 ~ /00$/ {}' sample.txt; }
real	1m8.525s
user	0m55.022s
sys	0m1.420s
$ time { cat sample.txt|awk '$5 ~ /00$/ {print}' > /dev/null; }
real	0m55.854s
user	0m54.418s
sys	0m3.293s
$  time { cat sample.txt|awk '$5 ~ /00$/ {}'; }
real	0m58.242s
user	0m56.425s
sys	0m3.540s
  • awk に posix_fadivse(SEQUENTIAL) を入れても速くならない。
$ pwd
/usr/src/gnu/gawk-3.1.7
$ diff io.c io.c.org 
27d26
< #include "fadvise.h"
1679d1677
< 	posix_fadvise(openfd, 0, 0, POSIX_FADV_SEQUENTIAL);
$ ./configure
$ make
$ strace /usr/src/gnu/gawk-3.1.7/gawk '{print}' sample.txt 2>&1|grep -C2 fadvise
open("sample.txt", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=2800000000, ...}) = 0
fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffa7cb3930) = -1 ENOTTY (Inappropriate ioctl for device)
fstat(3, {st_mode=S_IFREG|0664, st_size=2800000000, ...}) = 0
$ time { /usr/src/gnu/gawk-3.1.7/gawk '$5 ~ /00$/ {print}' sample.txt > result1.txt; }
real 1m9.574s
user 0m56.812s
sys 0m1.408s

参考


関連