Hatena::ブログ(Diary)

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

2014-04-13

テキトーーク!!ネタ出し

アジェンダ

  1. オープニング
  2. アイスブレイクのクイズ(5 min)
  3. はじめに(1 min)
    • OSの性能分析はもっと簡単にできると思っている(まだその境地には至っていない)。
    • 魔法ではなくサイエンス
    • 追い求めていたものに近いものを見つけたので紹介 → Brendan Gregg の USE Method
  4. The USE Method(5 min)
    • USE Method とは
    • 全体図
      • USE、U+Sの図、Functional Diagrams、Software stack、Flow Diagrams、Checklist
      • USE Method で問題を見つけ、適切なツールを使ってドリルダウンして問題を特定する
  5. デモ(15 min)
    • Perlワンライナーの実行数を増やして、CPU使用率を上げていく。
    • USE Method の Checklist で問題を見つけられることを確認する(図を参照しながら)。
    • さらに Software stack の図を見ながら、適切なコマンドでドリルダウンしてみる。
    • CPU使用率とランキューを見て、コア数に対してランキューがいくつまで許容できるか考えてみる。
  6. 参考文献紹介(1min)

ねらい

  • 知らない世界に案内し、興味を持ってもらう(時間も短いので網羅性より面白さ重視)

何がわかるようになるか


今後紹介したいもの

  • perf、/proc/meminfo、fio、blktrace。crash、DTrace、oratop、MOTAS など。

2014-04-09

「データベースの限界性能を引き出す技術 ~NoSQLに飛びつく前に知っておきたい原理と最新テクニック」の紹介

同僚が書いた本の紹介です。

パフォーマンスチューニングエキスパートである著者が長年の経験で得たエッセンスを惜しみなく伝授してくれる高速道路のような一冊だと思います。ぶっちゃけ読んでいて「へ〜、知らなかった(^-^;」と思ったところがありました。

よくパフォーマンスチューニングは経験しないと身に着かないと言われ、ある程度その通りだと思いますが、この本はエキスパートのノウハウが凝縮された効率よく学べる一冊だと思います。

NoSQLとRDBMSについての考察、ボトルネック、レスポンス、スループットとは何かという基礎的な概念の説明から始まり、ボトルネックCPUネットワークストレージといったハードウェアリソース排他制御で保護されるメモリ上の共有データといったソフトウェアリソースにおいて発生し、そのボトルネックの分析方法とチューニング方法が紹介されています。

シンプルでわかりやすい概念は鈍器級の本に書かれていることが多い気がしますが、平易に書かれているので効率が良く学べる一冊だと思います。Oracle Database 以外でも通用する普遍的な考え方が書かれていますので、プログラマからインフラエンジニアまで、初心者からベテランまで幅広くオススメです。

例えば、I/OボトルネックについてはAWRレポートの Top N Event で db file sequential read などのI/O関連の待機イベントが上位に来ている場合は平均待機時間(Wait Avg(ms))、ヒストグラム(Wait Event Histogram)での待ち時間の分布の確認から OS レベルで iostat をどう見れば良いかまで具体的に書かれています。同様にCPUボトルネックネットワークボトルネックRDBMS排他制御で発生するボトルネックに関しても書かれています。


目次

以下、目次です。興味を持たれた方は本屋でパラパラっと中身を見てみてください。

第1章 なぜ,今「RDBMSはダメだ」と言われるのか
 1-1 昔はRDBMSがシステムの中心だった
 コラム どこからが「大規模システム」か?
 1-2 DBに求められる役割と問題点とは
 1-3 アーキテクチャのすみわけがベストではない

第2章 RDBMSのボトルネックと基本的なチューニングを知る
 2-1 ボトルネックとは
 2-2 レスポンスとスループットを正しく知る
 2-3 ディスクI/Oボトルネックを解決する
 2-4 CPUボトルネックを解決するには
 コラム SPECintとは
 2-5 ネットワークボトルネックを解決するには
 コラム 光通信が電気通信より速いのは,光が電気より伝送速度が速いからではない
 2-6 共有リソースの競合ボトルネックとは

第3章 大規模システムではI/Oボトルネックが大半を占めている
 3-1 I/Oボトルネックはなぜ発生するのか
 3-2 I/Oボトルネックが発生しにくいデータベースを設計する
 3-3 I/Oボトルネックの分析と対策
 3-4 一歩進んだI/Oボトルネック解消法
 3-5 Oracle Exadataが実装しているI/O高速化機能を知る

第4章 CPUボトルネックは使用率だけでは判断できない
 4-1 CPU待ちはなぜ発生するのか
 4-2 CPU使用率が低すぎる原因とは
 4-3 RDBMSでの並列化のすすめ
 4-4 CPU使用率が高すぎる時には
 コラム 待機イベントだけ見ていてもわからない
 4-5 リソースをマネジメントする
 コラム CPUボトルネックは説明しやすい

第5章 ネットワークボトルネックの傾向と対策
 5-1 ネットワークボトルネックはなぜ発生するのか
 5-2 ネットワークボトルネックを発見するには
 5-3 ネットワークボトルネックを改善する

第6章 リソース不足以外にもボトルネックが存在する
 6-1 手元のリソースを使い切れていますか?
 6-2 ロック待ちを解消するには
 6-3 データベース内部でもロック待ちが起こる
 コラム DBは統合すべきか? 分割すべきか?
 6-4 チューニングが他レイヤに与える影響

Appendix RDBMSのアーキテクチャ超概要
 A-1 Oracle Databaseのアーキテクチャを知る
 A-2 SQLの処理フローを見る

2014-04-07

libaio の aio コンテキスト数を調べる

Linux の libaio による非同期I/Oでは aio コンテキスト数は /proc/sys/fs/aio-nr で確認でき、/proc/sys/fs/aio-max-nr に達すると、io_setup システムコール戻り値に EAGAIN が返される。このことをI/Oベンチマークツール flexible IO tester (fio) で検証してみた。


おさらい

Linux の非同期I/Oは2種類ある。


参考情報

aio-nr & aio-max-nr:

aio-nr is the running total of the number of events specified on the io_setup system call for all currently active aio contexts. If aio-nr reaches aio-max-nr then io_setup will fail with EAGAIN. Note that raising aio-max-nr does not result in the pre-allocation or re-sizing of any kernel data structures.

https://www.kernel.org/doc/Documentation/sysctl/fs.txt

EAGAIN The specified nr_events exceeds the user's limit of available events, as defined in /proc/sys/fs/aio-max-nr.

io_setup(2) - Linux manual page

ユーザーモードプロセスが io_submit() システムコールを利用して非同期I/O操作を開始するためには、あらかじめ非同期I/Oコンテキスト(Asynchronous I/O context、以下 AIOコンテキスト)を生成する必要があります。

(中略)

AIOリングはプロセスのページユーザーモードのアドレスにマッピングされており、アプリケーションは未終了の非同期I/O操作の経過を直接確認できます。AIOリングにより、比較的遅いシステムコールを使わずに確認できます。

(中略)

io_setup()システムコーリは、呼び出したプロセス用に新しいAIOコンテキストを生成します。io_setup()システムコールは2つの引数を受け取ります。1つは、未終了の非同期I/O操作の最大数、つまりAIOリングの大きさを決定します。もう1つは、AIOコンテキストを示すハンドルを格納するための変数へのポインタであり、このハンドルはAIOリングのベースアドレスでもあります。


事前準備

  • 非同期I/Oリクエスト数を上限(aio-max-nr)に到達させるため敢えて小さくする(5に変更)
[root@yazekats-linux ~]# cat /proc/sys/fs/aio-max-nr 
65536
[root@yazekats-linux ~]# sysctl -w fs.aio-max-nr=5
[root@yazekats-linux ~]# cat /proc/sys/fs/aio-max-nr 
5

検証

yazekats% while :
do
echo -n `date '+%Y-%m-%d %H:%M:%S:'`
cat /proc/sys/fs/aio-nr
sleep 1
done

...

2014-04-08 02:41:39:0
2014-04-08 02:41:40:0
2014-04-08 02:41:41:0
2014-04-08 02:41:42:52014-04-08 02:41:43:52014-04-08 02:41:44:52014-04-08 02:41:45:52014-04-08 02:41:46:52014-04-08 02:41:47:52014-04-08 02:41:48:52014-04-08 02:41:49:22014-04-08 02:41:50:0
2014-04-08 02:41:51:0

非同期I/Oコンテキスト数(aio-nr)が最大 5 に達している。

yazekats% strace -fttt -o strace_fio.log fio -rw=randwrite -bs=4k -size=50m -directory=/tmp -direct=1 -numjobs=10 -name=file1 -ioengine=libaio
file1: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=1
...
file1: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=1
fio-2.0.13
Starting 10 processes
fio: check /proc/sys/fs/aio-max-nr ★
fio: check /proc/sys/fs/aio-max-nr ★
fio: check /proc/sys/fs/aio-max-nr ★
fio: pid=4797, err=11/file:engines/libaio.c:271, func=io_queue_init, error=Resource temporarily unavailable ★
fio: pid=4795, err=11/file:engines/libaio.c:271, func=io_queue_init, error=Resource temporarily unavailable ★
fio: pid=4794, err=11/file:engines/libaio.c:271, func=io_queue_init, error=Resource temporarily unavailable ★
fio: check /proc/sys/fs/aio-max-nr ★
fio: pid=4798, err=11/file:engines/libaio.c:271, func=io_queue_init, error=Resource temporarily unavailable ★
fio: check /proc/sys/fs/aio-max-nr ★
fio: pid=4796, err=11/file:engines/libaio.c:271, func=io_queue_init, error=Resource temporarily unavailable ★
Jobs: 2 (f=2): [ww___XXXXX] [100.0% done] [0K/27380K/0K /s] [0 /6845 /0  iops] [eta 00m:00s]
file1: (groupid=0, jobs=1): err= 0: pid=4789: Tue Apr  8 02:41:50 2014
  write: io=51200KB, bw=6385.7KB/s, iops=1596 , runt=  8018msec
    slat (usec): min=34 , max=1404 , avg=196.54, stdev=106.99
    clat (usec): min=62 , max=5817 , avg=424.62, stdev=396.55
     lat (usec): min=193 , max=6001 , avg=622.42, stdev=412.09
    clat percentiles (usec):
     |  1.00th=[   89],  5.00th=[  123], 10.00th=[  177], 20.00th=[  239],
     | 30.00th=[  274], 40.00th=[  298], 50.00th=[  322], 60.00th=[  346],
     | 70.00th=[  378], 80.00th=[  438], 90.00th=[  716], 95.00th=[ 1320],
     | 99.00th=[ 2160], 99.50th=[ 2352], 99.90th=[ 3344], 99.95th=[ 3952],
     | 99.99th=[ 4256]
    bw (KB/s)  : min= 5024, max=10936, per=20.03%, avg=6379.12, stdev=1347.65
    lat (usec) : 100=1.45%, 250=21.31%, 500=61.87%, 750=5.85%, 1000=2.64%
    lat (msec) : 2=5.22%, 4=1.62%, 10=0.05%
  cpu          : usr=1.93%, sys=5.39%, ctx=63665, majf=0, minf=26
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=12800/d=0, short=r=0/w=0/d=0
file1: (groupid=0, jobs=1): err= 0: pid=4790: Tue Apr  8 02:41:50 2014
  write: io=51200KB, bw=6513.2KB/s, iops=1628 , runt=  7861msec
    slat (usec): min=33 , max=1855 , avg=194.53, stdev=98.58
    clat (usec): min=50 , max=4267 , avg=414.18, stdev=371.95
     lat (usec): min=198 , max=4522 , avg=609.93, stdev=380.96
    clat percentiles (usec):
     |  1.00th=[  102],  5.00th=[  155], 10.00th=[  197], 20.00th=[  239],
     | 30.00th=[  270], 40.00th=[  294], 50.00th=[  314], 60.00th=[  338],
     | 70.00th=[  370], 80.00th=[  422], 90.00th=[  676], 95.00th=[ 1272],
     | 99.00th=[ 2096], 99.50th=[ 2288], 99.90th=[ 3024], 99.95th=[ 3536],
     | 99.99th=[ 4192]
    bw (KB/s)  : min= 5288, max= 7400, per=19.94%, avg=6348.80, stdev=528.81
    lat (usec) : 100=0.88%, 250=22.46%, 500=62.45%, 750=5.35%, 1000=2.39%
    lat (msec) : 2=5.18%, 4=1.27%, 10=0.02%
  cpu          : usr=2.19%, sys=5.41%, ctx=64013, majf=0, minf=23
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=12800/d=0, short=r=0/w=0/d=0
file1: (groupid=0, jobs=1): err= 0: pid=4791: Tue Apr  8 02:41:50 2014
  write: io=51200KB, bw=6749.3KB/s, iops=1687 , runt=  7586msec
    slat (usec): min=32 , max=1539 , avg=172.25, stdev=83.40
    clat (usec): min=50 , max=4118 , avg=414.69, stdev=358.46
     lat (usec): min=132 , max=4308 , avg=588.14, stdev=363.63
    clat percentiles (usec):
     |  1.00th=[  125],  5.00th=[  181], 10.00th=[  213], 20.00th=[  251],
     | 30.00th=[  278], 40.00th=[  298], 50.00th=[  318], 60.00th=[  342],
     | 70.00th=[  366], 80.00th=[  414], 90.00th=[  660], 95.00th=[ 1224],
     | 99.00th=[ 2096], 99.50th=[ 2224], 99.90th=[ 2832], 99.95th=[ 3376],
     | 99.99th=[ 3888]
    bw (KB/s)  : min= 5368, max= 8000, per=21.13%, avg=6729.13, stdev=610.57
    lat (usec) : 100=0.36%, 250=19.52%, 500=66.64%, 750=5.02%, 1000=2.19%
    lat (msec) : 2=5.02%, 4=1.25%, 10=0.01%
  cpu          : usr=2.85%, sys=5.27%, ctx=63722, majf=0, minf=26
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=12800/d=0, short=r=0/w=0/d=0
file1: (groupid=0, jobs=1): err= 0: pid=4792: Tue Apr  8 02:41:50 2014
  write: io=50552KB, bw=6780.1KB/s, iops=1695 , runt=  7455msec
    slat (usec): min=32 , max=2269 , avg=157.39, stdev=82.15
    clat (usec): min=45 , max=4407 , avg=426.60, stdev=364.62
     lat (usec): min=129 , max=4699 , avg=585.23, stdev=369.91
    clat percentiles (usec):
     |  1.00th=[  131],  5.00th=[  185], 10.00th=[  217], 20.00th=[  258],
     | 30.00th=[  286], 40.00th=[  310], 50.00th=[  330], 60.00th=[  350],
     | 70.00th=[  382], 80.00th=[  430], 90.00th=[  684], 95.00th=[ 1256],
     | 99.00th=[ 2128], 99.50th=[ 2256], 99.90th=[ 2736], 99.95th=[ 3696],
     | 99.99th=[ 4080]
    bw (KB/s)  : min= 5696, max= 7232, per=21.00%, avg=6686.57, stdev=480.73
    lat (usec) : 50=0.01%, 100=0.30%, 250=17.11%, 500=68.37%, 750=5.37%
    lat (usec) : 1000=2.50%
    lat (msec) : 2=4.90%, 4=1.42%, 10=0.02%
  cpu          : usr=2.49%, sys=5.93%, ctx=63366, majf=0, minf=26
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=12638/d=0, short=r=0/w=0/d=0
file1: (groupid=0, jobs=1): err= 0: pid=4793: Tue Apr  8 02:41:50 2014
  write: io=51200KB, bw=7295.6KB/s, iops=1823 , runt=  7018msec
    slat (usec): min=31 , max=1259 , avg=144.58, stdev=74.88
    clat (usec): min=38 , max=6284 , avg=397.84, stdev=332.23
     lat (usec): min=131 , max=6450 , avg=543.66, stdev=335.38
    clat percentiles (usec):
     |  1.00th=[  129],  5.00th=[  179], 10.00th=[  209], 20.00th=[  253],
     | 30.00th=[  282], 40.00th=[  306], 50.00th=[  326], 60.00th=[  346],
     | 70.00th=[  366], 80.00th=[  398], 90.00th=[  532], 95.00th=[  956],
     | 99.00th=[ 1992], 99.50th=[ 2224], 99.90th=[ 3056], 99.95th=[ 3568],
     | 99.99th=[ 4512]
    bw (KB/s)  : min= 6128, max= 8024, per=22.93%, avg=7301.71, stdev=488.22
    lat (usec) : 50=0.02%, 100=0.26%, 250=18.98%, 500=69.81%, 750=4.13%
    lat (usec) : 1000=1.94%
    lat (msec) : 2=3.86%, 4=0.97%, 10=0.03%
  cpu          : usr=2.59%, sys=6.47%, ctx=64512, majf=0, minf=27
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=12800/d=0, short=r=0/w=0/d=0

Run status group 0 (all jobs):
  WRITE: io=255352KB, aggrb=31847KB/s, minb=6385KB/s, maxb=7295KB/s, mint=7018msec, maxt=8018msec

Disk stats (read/write):
    dm-1: ios=173/62797, merge=0/0, ticks=67/24410, in_queue=24481, util=89.99%, aggrios=173/63898, aggrmerge=0/0, aggrticks=67/24511, aggrin_queue=24583, aggrutil=88.68%
    dm-0: ios=173/63898, merge=0/0, ticks=67/24511, in_queue=24583, util=88.68%, aggrios=173/63898, aggrmerge=0/0, aggrticks=45/22169, aggrin_queue=22190, aggrutil=84.26%
  sda: ios=173/63898, merge=0/0, ticks=45/22169, in_queue=22190, util=84.26%

fio の -numjobs オプションで 10 並行を指定したが、aio-max-nr の上限に達し、5 に変更して実行されている。

yazekats% grep io_setup strace_fio.log
4790  1396892502.061498 io_setup(2147483647,  <unfinished ...>
4790  1396892502.061657 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4789  1396892502.061683 io_setup(2147483647,  <unfinished ...>
4790  1396892502.061780 io_setup(1,  <unfinished ...>
4789  1396892502.061797 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4790  1396892502.061906 <... io_setup resumed> {139825214746624}) = 0
4789  1396892502.061931 io_setup(1,  <unfinished ...>
4789  1396892502.062153 <... io_setup resumed> {139825214746624}) = 0
4791  1396892502.062288 io_setup(2147483647,  <unfinished ...>
4791  1396892502.062426 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4791  1396892502.062557 io_setup(1,  <unfinished ...>
4791  1396892502.062759 <... io_setup resumed> {139825214746624}) = 0
4792  1396892502.063390 io_setup(2147483647,  <unfinished ...>
4792  1396892502.063568 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4792  1396892502.063765 io_setup(1,  <unfinished ...>
4792  1396892502.064023 <... io_setup resumed> {139825214746624}) = 0
4793  1396892502.064344 io_setup(2147483647,  <unfinished ...>
4793  1396892502.064503 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4793  1396892502.064730 io_setup(1,  <unfinished ...>
4793  1396892502.064869 <... io_setup resumed> {139825214746624}) = 0
4794  1396892502.065185 io_setup(2147483647,  <unfinished ...>
4794  1396892502.065373 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4794  1396892502.065580 io_setup(1,  <unfinished ...>
4795  1396892502.066413 io_setup(2147483647,  <unfinished ...>
4795  1396892502.066571 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4796  1396892502.066769 io_setup(2147483647,  <unfinished ...>
4795  1396892502.066789 io_setup(1,  <unfinished ...>
4796  1396892502.066918 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4796  1396892502.067031 io_setup(1,  <unfinished ...>
4797  1396892502.067655 io_setup(2147483647,  <unfinished ...>
4797  1396892502.067767 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4797  1396892502.067907 io_setup(1,  <unfinished ...>
4798  1396892502.071044 io_setup(2147483647,  <unfinished ...>
4798  1396892502.071062 <... io_setup resumed> 0x223e210) = -1 EINVAL (Invalid argument)
4798  1396892502.071082 io_setup(1,  <unfinished ...>
4797  1396892502.073724 <... io_setup resumed> 0x223e210) = -1 EAGAIN (Resource temporarily unavailable)4795  1396892502.073738 <... io_setup resumed> 0x223e210) = -1 EAGAIN (Resource temporarily unavailable)4794  1396892502.073788 <... io_setup resumed> 0x223e210) = -1 EAGAIN (Resource temporarily unavailable)4798  1396892502.080743 <... io_setup resumed> 0x223e210) = -1 EAGAIN (Resource temporarily unavailable)4796  1396892502.081637 <... io_setup resumed> 0x223e210) = -1 EAGAIN (Resource temporarily unavailable)

io_setup システムコール戻り値に "EAGAIN (Resource temporarily unavailable)" が返されている。


補足

fio のソースコードを追ってみる

static int fio_libaio_init(struct thread_data *td)
{
	struct libaio_data *ld = malloc(sizeof(*ld));
	struct libaio_options *o = td->eo;
	int err = 0;

	memset(ld, 0, sizeof(*ld));

	/*
	 * First try passing in 0 for queue depth, since we don't
	 * care about the user ring. If that fails, the kernel is too old
	 * and we need the right depth.
	 */
	if (!o->userspace_reap)
		err = io_queue_init(INT_MAX, &ld->aio_ctx);
	if (o->userspace_reap || err == -EINVAL)
		err = io_queue_init(td->o.iodepth, &ld->aio_ctx);
	if (err) {
		td_verror(td, -err, "io_queue_init");
		log_err("fio: check /proc/sys/fs/aio-max-nr\n"); ★
		free(ld);
		return 1;
	}

	ld->aio_events = malloc(td->o.iodepth * sizeof(struct io_event));
	memset(ld->aio_events, 0, td->o.iodepth * sizeof(struct io_event));
	ld->iocbs = malloc(td->o.iodepth * sizeof(struct iocb *));
	memset(ld->iocbs, 0, sizeof(struct iocb *));
	ld->io_us = malloc(td->o.iodepth * sizeof(struct io_u *));
	memset(ld->io_us, 0, td->o.iodepth * sizeof(struct io_u *));
	ld->iocbs_nr = 0;

	td->io_ops->data = ld;
	return 0;
}

参考


追記(2014/04/13):

dstat のソースを見てたら --aio オプションを指定すると /proc/sys/fs/aio-nr を監視できることに気づいた。

284   --aio                  enable aio stats

...

521 class dstat_aio(dstat):
522     def __init__(self):
523         self.name = 'async'
524         self.type = 'd'
525         self.width = 5;
526         self.open('/proc/sys/fs/aio-nr')
527         self.nick = ('#aio',)
528         self.vars = ('aio',)
529 

実行してみると、

yazekats% dstat -t --aio
----system---- async
  date/time   | #aio
14-04 00:31:55|   0 
14-04 00:31:56|   0 
14-04 00:31:57|  10B
14-04 00:31:58|  10B
14-04 00:31:59|  10B

2014-03-23

Github から Linux PC に clone したメモ

# yum install git
$ mkdir -p /home/yazekats/Documents/github
$ cd /home/yazekats/Documents/github
$ git init
$ git clone git://github.com/yoheia/yoheia.git

2014-03-22

sort するとなぜ consistent gets が減るか?

Tom Kyte の以下の記事を読んで、同じテーブルをフルスキャンする場合にソート有無で consistent gets が変わる理由を調べてみた。

これは大きな変化です。 転送されるデータが8MBから3.4MBに減少しました。この減少はすべて、Oracle*Netの圧縮によるものです。 TIMESTAMPの値には繰り返しが多いため、何度も転送する必要がありません。 さらに、consistent getsが5,794から1,031に減少している点もお気づきでしょう。 これもORDER BYによる副作用のひとつです。 1回目の問合せの実行でデータが表から直接読み取られますが、ソートは実行されないため、データを一時領域に書き込む必要はありません。 したがって、データをフェッチするたびに(SQL*Plusのデフォルト配列フェッチ・サイズは一度に15行)、バッファキャッシュからブロックを取得して、そのブロックから15行取得する必要があります。 この表には1ブロックあたり約73レコードが保存されているため、ORDER BYを使用しない場合、最初のブロックの73行すべてを取得するためには、キャッシュから一度に15行ずつ、5回ほど読取る必要があります。 データをソートする場合は、すべての行を読取り、一時メモリかディスク上の一時領域でそれらをソートする必要があります。 一度に15行取得するときには、バッファキャッシュからではなく、一時領域から読み取る必要があります。

Ask Tom: 履歴、基礎、ネットワーク・パフォーマンスについて

検証結果

ソートなしでは consistent gets(query) が 5977 だが、ソートすると 1093 に減っている。physical reads(disk) の 1046 に近い値になっている。ソートする場合は PGA または一時セグメントへブロックがコピーされ、ブロック単位のアクセスになるが、ソートなしでは fetch size 単位で同一ブロックへのアクセスが発生し consistet gets の回数が増加するのではないかと思われる。

SQL ID: 89km4qj1thh13 Plan Hash: 1601196873

select * 
from
 t


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.96          2        107          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch     4903      0.04      13.65       1046       5870          0       73529
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4905      0.05      14.62       1048       5977★          0       73529

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 111  (YAZEKATS)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
     73529      73529      73529  TABLE ACCESS FULL T (cr=5870 pr=1046 pw=0 time=525624 us cost=294 size=7132313 card=73529)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
  73529   TABLE ACCESS   MODE: ANALYZED (FULL) OF 'T' (TABLE)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  row cache lock                                  3        0.00          0.00
  SQL*Net message to client                    4903        0.00          0.00
  enq: KO - fast object checkpoint                3        0.00          0.00
  reliable message                                1        0.00          0.00
  Disk file operations I/O                        3        0.00          0.00
  direct path read                               17        0.78          4.03
  SQL*Net message from client                  4903       23.62         25.64
********************************************************************************
SQL ID: d0q1ds5kq3jup Plan Hash: 961378228

select * 
from
 t order by timestamp


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0         45          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch     4903      0.08       1.23       1046       1048          0       73529
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4905      0.09       1.24       1046       1093★          0       73529

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 111  (YAZEKATS)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
     73529      73529      73529  SORT ORDER BY (cr=1048 pr=1046 pw=0 time=1180962 us cost=1924 size=7132313 card=73529)
     73529      73529      73529   TABLE ACCESS FULL T (cr=1048 pr=1046 pw=0 time=93773 us cost=294 size=7132313 card=73529)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
  73529   SORT (ORDER BY)
  73529    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'T' (TABLE)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  row cache lock                                 15        0.00          0.00
  SQL*Net message to client                    4903        0.00          0.00
  enq: KO - fast object checkpoint                3        0.00          0.00
  reliable message                                1        0.00          0.00
  Disk file operations I/O                        4        0.00          0.00
  direct path read                               28        0.12          1.04
  SQL*Net message from client                  4903       39.82         41.84
********************************************************************************

理由を探る

  • ソートなし
    • ちょこちょこと fetch のたびにブロックにアクセスしている。
$ less orcl1_ora_18920.trc
select * from t
END OF STMT
PARSE #139981612855152:c=9000,e=969715,p=2,cr=107,cu=0,mis=1,r=0,dep=0,og=1,plh=1601196873,tim=1395440522343785
EXEC #139981612855152:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1601196873,tim=1395440522343873
WAIT #139981612855152: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=13893 tim=1395440522343924
WAIT #139981612855152: nam='enq: KO - fast object checkpoint' ela= 397 name|mode=1263468550 2=65604 0=2 obj#=13893 tim=1395440522344636
WAIT #139981612855152: nam='reliable message' ela= 1429 channel context=2501674352 channel handle=2501486064 broadcast message=2502805696 obj#=13893 tim=1395440522346320
WAIT #139981612855152: nam='enq: KO - fast object checkpoint' ela= 190 name|mode=1263468550 2=65604 0=1 obj#=13893 tim=1395440522346604
WAIT #139981612855152: nam='enq: KO - fast object checkpoint' ela= 179 name|mode=1263468545 2=65604 0=2 obj#=13893 tim=1395440522346844
WAIT #139981612855152: nam='Disk file operations I/O' ela= 8 FileOperation=2 fileno=5 filetype=2 obj#=87192 tim=1395440522347020
WAIT #139981612855152: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=9 filetype=2 obj#=87192 tim=1395440522347356

*** 2014-03-22 07:22:02.786
WAIT #139981612855152: nam='direct path read' ela= 438726 file number=5 first dba=149243 block cnt=5 obj#=87192 tim=1395440522786198
FETCH #139981612855152:c=2000,e=442335,p=13,cr=3★,cu=0,mis=0,r=1,dep=0,og=1,plh=1601196873,tim=1395440522786287
WAIT #139981612855152: nam='SQL*Net message from client' ela= 254 driver id=1650815232 #bytes=1 p3=0 obj#=87192 tim=1395440522786594
WAIT #139981612855152: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=87192 tim=1395440522786647
FETCH #139981612855152:c=0,e=57,p=0,cr=1★,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522786689
WAIT #139981612855152: nam='SQL*Net message from client' ela= 431 driver id=1650815232 #bytes=1 p3=0 obj#=87192 tim=1395440522787145
WAIT #139981612855152: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=87192 tim=1395440522787185
FETCH #139981612855152:c=0,e=38,p=0,cr=1★,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522787207
    • cr が 1 以上の行を抽出してみる。
$ perl -nle '/139981612855152/ and /cr=([0-9]+)/ and $1>0 and print' orcl1_ora_18920.trc|head -20
PARSE #139981612855152:c=9000,e=969715,p=2,cr=107,cu=0,mis=1,r=0,dep=0,og=1,plh=1601196873,tim=1395440522343785
FETCH #139981612855152:c=2000,e=442335,p=13,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=1601196873,tim=1395440522786287
FETCH #139981612855152:c=0,e=57,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522786689
FETCH #139981612855152:c=0,e=38,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522787207
FETCH #139981612855152:c=0,e=76,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522787736
FETCH #139981612855152:c=0,e=108,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522788367
FETCH #139981612855152:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522788923
FETCH #139981612855152:c=0,e=36,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522789468
FETCH #139981612855152:c=0,e=85,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522790241
FETCH #139981612855152:c=0,e=32,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522790723
FETCH #139981612855152:c=0,e=31,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522791192
FETCH #139981612855152:c=0,e=29,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522791649
FETCH #139981612855152:c=0,e=30,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522792124
FETCH #139981612855152:c=0,e=32,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522792627
FETCH #139981612855152:c=0,e=29,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522793115
FETCH #139981612855152:c=0,e=29,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522793574
FETCH #139981612855152:c=0,e=28,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522794040
FETCH #139981612855152:c=0,e=29,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522794491
FETCH #139981612855152:c=0,e=36,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522795311
FETCH #139981612855152:c=0,e=30,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522795825
  • ソートあり
    • はじめのほうの fetch で 1048 ブロックにアクセスしているが、その後はアクセスしていない。
$ less orcl1_ora_18920.trc
select * from t order by timestamp
END OF STMT
PARSE #140214895904000:c=3999,e=6802,p=0,cr=45,cu=0,mis=1,r=0,dep=0,og=1,plh=961378228,tim=1395441478342129
EXEC #140214895904000:c=1000,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=961378228,tim=1395441478342222
WAIT #140214895904000: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=68580 tim=1395441478342273
WAIT #140214895904000: nam='enq: KO - fast object checkpoint' ela= 323 name|mode=1263468550 2=65595 0=1 obj#=68580 tim=1395441478342877
WAIT #140214895904000: nam='reliable message' ela= 1021 channel context=2501674352 channel handle=2501480816 broadcast message=2502805696 obj#=68580 tim=1395441478344157
WAIT #140214895904000: nam='enq: KO - fast object checkpoint' ela= 128 name|mode=1263468550 2=65595 0=1 obj#=68580 tim=1395441478344359
WAIT #140214895904000: nam='enq: KO - fast object checkpoint' ela= 193 name|mode=1263468545 2=65595 0=2 obj#=68580 tim=1395441478344692
WAIT #140214895904000: nam='Disk file operations I/O' ela= 9 FileOperation=2 fileno=5 filetype=2 obj#=87192 tim=1395441478344809
WAIT #140214895904000: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=9 filetype=2 obj#=87192 tim=1395441478344929
WAIT #140214895904000: nam='direct path read' ela= 253 file number=5 first dba=149243 block cnt=5 obj#=87192 tim=1395441478345257
WAIT #140214895904000: nam='direct path read' ela= 331 file number=9 first dba=27776 block cnt=8 obj#=87192 tim=1395441478345799
WAIT #140214895904000: nam='direct path read' ela= 685 file number=9 first dba=27785 block cnt=15 obj#=87192 tim=1395441478346813

...

WAIT #140214895904000: nam='direct path read' ela= 14409 file number=5 first dba=12576 block cnt=32 obj#=87192 tim=1395441479267605
WAIT #140214895904000: nam='direct path read' ela= 120053 file number=5 first dba=12640 block cnt=32 obj#=87192 tim=1395441479389968
WAIT #140214895904000: nam='direct path read' ela= 35217 file number=9 first dba=29600 block cnt=16 obj#=87192 tim=1395441479427196
FETCH #140214895904000:c=48993,e=1095355,p=1046,cr=1048★,cu=0,mis=0,r=1,dep=0,og=1,plh=961378228,tim=1395441479437655
WAIT #140214895904000: nam='SQL*Net message from client' ela= 247 driver id=1650815232 #bytes=1 p3=0 obj#=87192 tim=1395441479437989
WAIT #140214895904000: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=87192 tim=1395441479438030
FETCH #140214895904000:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=961378228,tim=1395441479438055
WAIT #140214895904000: nam='SQL*Net message from client' ela= 418 driver id=1650815232 #bytes=1 p3=0 obj#=87192 tim=1395441479438499
WAIT #140214895904000: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=87192 tim=1395441479438543
FETCH #140214895904000:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=961378228,tim=1395441479438567
    • cr が 1 以上の行を抽出してみる。
$ perl -nle '/140214895904000/ and /cr=([0-9]+)/ and $1>0 and print' orcl1_ora_21418.trc
PARSE #140214895904000:c=3999,e=6802,p=0,cr=45,cu=0,mis=1,r=0,dep=0,og=1,plh=961378228,tim=1395441478342129
FETCH #140214895904000:c=48993,e=1095355,p=1046,cr=1048,cu=0,mis=0,r=1,dep=0,og=1,plh=961378228,tim=1395441479437655
STAT #140214895904000 id=1 cnt=73529 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=1048 pr=1046 pw=0 time=1180962 us cost=1924 size=7132313 card=73529)'
STAT #140214895904000 id=2 cnt=73529 pid=1 pos=1 obj=87192 op='TABLE ACCESS FULL T (cr=1048 pr=1046 pw=0 time=93773 us cost=294 size=7132313 card=73529)'

検証手順

SQL> create table t as select * from all_objects;
SQL> execute dbms_stats.gather_table_stats(user,'T');
  • ソートなし(select * from t)でSQLトレースを取得する。
$ cat t.sql
select * from t;
$ sqlplus yazekats
SQL> select s.sid, s.serial#, p.spid from v$session s, v$process p where p.addr = s.paddr and s.sid = sys_context('USERENV','SID');
       SID    SERIAL# SPID
---------- ---------- ------------------------
	25	  609 18920
SQL> spool nosort.lst
SQL> set termout off
SQL> alter session set events '10046 trace name context forever, level 12';
SQL> @t
SQL> alter session set events '10046 trace name context off';
SQL> exit
$ tkprof orcl1_ora_18920.trc orcl1_ora_18920_tkprof.trc explain=yazekats
  • ソートあり(select * from t order by teimstamp)でSQLトレースを取得する。
$ cat ts.sql
select * from t order by teimstamp;
$ sqlplus yazekats
SQL> select s.sid, s.serial#, p.spid from v$session s, v$process p where p.addr = s.paddr and s.sid = sys_context('USERENV','SID');
       SID    SERIAL# SPID
---------- ---------- ------------------------
       828	  147 21418
SQL> spool sort.lst
SQL> set termout off
SQL> alter session set events '10046 trace name context forever, level 12';
SQL> @ts
SQL> alter session set events '10046 trace name context off';
SQL> exit
$ tkprof orcl1_ora_21418.trc orcl1_ora_21418_tkprof.trc explain=yazekats
  • sqlplus の arraysize は 15。
SQL> show arraysize
arraysize 15

参考


追記:

ソートしてもしなくても fetch での Physical Reads は 1046 ブロックでなぜか同じ。ソートする場合は1回、ソートしない場合は38回 fetchしている。

$ perl -lane '/FETCH #139981612855152:/ and /p=([0-9]+)/ and $1>0 and print qq/$.: $_/' sharedgp1_ora_18920.trc
492: FETCH #139981612855152:c=2000,e=442335,p=13,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=1601196873,tim=1395440522786287
576: FETCH #139981612855152:c=0,e=125,p=15,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522800788
699: FETCH #139981612855152:c=0,e=188,p=15,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522821081
936: FETCH #139981612855152:c=0,e=169,p=15,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522860299
1171: FETCH #139981612855152:c=0,e=87556,p=15,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440522985910
1414: FETCH #139981612855152:c=0,e=135,p=15,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440523024864
1649: FETCH #139981612855152:c=0,e=55469,p=15,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440523118517
1874: FETCH #139981612855152:c=0,e=141,p=15,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440523155641
2102: FETCH #139981612855152:c=0,e=324051,p=30,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440523517882
2327: FETCH #139981612855152:c=0,e=144,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440523555729
2786: FETCH #139981612855152:c=0,e=170,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440523630176
3251: FETCH #139981612855152:c=0,e=167,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440523707697
3683: FETCH #139981612855152:c=0,e=168,p=30,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440523777196
4116: FETCH #139981612855152:c=0,e=130405,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440523980049
4527: FETCH #139981612855152:c=0,e=496,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440524048022
4956: FETCH #139981612855152:c=1000,e=186,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440524120961
5394: FETCH #139981612855152:c=0,e=171,p=30,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440524193915
5841: FETCH #139981612855152:c=0,e=239998,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440524505346
6259: FETCH #139981612855152:c=0,e=363532,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440524938565
6706: FETCH #139981612855152:c=0,e=167,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440525012914
7141: FETCH #139981612855152:c=0,e=154,p=30,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440525084372
7576: FETCH #139981612855152:c=0,e=157,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440525155505
7984: FETCH #139981612855152:c=0,e=175,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440525222534
8417: FETCH #139981612855152:c=0,e=74331,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440525366459
8857: FETCH #139981612855152:c=0,e=176,p=30,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440525437047
9296: FETCH #139981612855152:c=0,e=292973,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440525801625
9707: FETCH #139981612855152:c=0,e=173,p=32,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440525870145
10146: FETCH #139981612855152:c=0,e=4082,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440525944206
10583: FETCH #139981612855152:c=0,e=9914914,p=30,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440535934341
11021: FETCH #139981612855152:c=0,e=159,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440536007378
11435: FETCH #139981612855152:c=0,e=787048,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440536861713
11909: FETCH #139981612855152:c=1000,e=174,p=32,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440536938043
12358: FETCH #139981612855152:c=0,e=264865,p=30,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440537274876
12796: FETCH #139981612855152:c=999,e=118325,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440537464472
13228: FETCH #139981612855152:c=0,e=167,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440537535763
13688: FETCH #139981612855152:c=1000,e=112703,p=32,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440537725988
14147: FETCH #139981612855152:c=0,e=163,p=30,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440537801081
14601: FETCH #139981612855152:c=0,e=75375,p=16,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1601196873,tim=1395440537949671
$ perl -lane '/FETCH #139981612855152:/ and /p=([0-9]+)/ and $1>0 and print qq/$.: $_/' sharedgp1_ora_18920.trc|wc -l
38
$ perl -lane '/FETCH #139981612855152/ and /p=([0-9]+)/ and $sum+=$1;END{print $sum}' sharedgp1_ora_18920.trc
1046