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