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 ブロックでなぜか同じ。ソートする場合は１回、ソートしない場合は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
