关于ASM的限制，请参见 ASM – Scalability and Limits (Doc ID 370921.1)
ASM imposes the following limits: 63 disk groups in a storage system 10,000 ASM disks in a storage system 2 terabyte maximum storage for each ASM disk (the Bug 6453944 allowed larger sizes, but that led to problems, see Note 736891.1 "ORA-15196 WITH ASM DISKS LARGER THAN 2TB") 40 exabyte maximum storage for each storage system 1 million files for each disk group 2.4 terabyte maximum storage for each file
有朋友说12.1上已经可以创建2T的文件，事实上，在很多时候，我们还是不建议这样使用，bug依然存在，维护还是问题。。。。。
例如：
Bug 14181123 ROOT.SH HANGS ON OHASD.BIN REBOOT
Bug 16565325 ASM FILE CREATION PERFORMANCE REGRESSION
当你碰到ASM的一些报错或者bug，怎么去检查问题呢？
前面已经说过使用DBI_TRACE去trace asm的过程，这里再说下，结合event 10046去诊断问题。
比如一个场景，客户反映在ASM上创建表空间很慢，或者cp很慢，或者其他。。。。。很慢的问题，那么首先我们先设置 DBI_TRACE=1 来跟踪ASM的内部操作：
[grid@RAC1 ~]$ export DBI_TRACE=1
[grid@RAC1 ~]$ asmcmd
DBI 1.602-ithread default trace level set to 0x0/1 (pid 4739) at DBI.pm line 273 via asmcmdshare.pm line 204
-> DBI->connect(dbi:Oracle:, , ****, HASH(0x16b8c38))
-> DBI->install_driver(Oracle) for linux perl=5.010000 pid=4739 ruid=1100 euid=1100
install_driver: DBD::Oracle version 1.20 loaded from /u01/11.2.0/grid/perl/lib/site_perl/5.10.0/x86_64-linux-thread-multi/DBD/Oracle.pm
<- STORE('ShowErrorStatement', 1)= 1 at Oracle.pm line 62
<- install_driver= DBI::dr=HASH(0x1b763c0)
<- default_user(undef, undef, ...)= ( undef undef ) [2 items] at DBI.pm line 625
<- DESTROY(DBI::st=HASH(1b12030))= undef at Oracle.pm line 234
<- connect('', undef, ...)= DBI::db=HASH(0x1b11f10) at DBI.pm line 637
<- STORE('PrintError', 0)= 1 at DBI.pm line 689
<- STORE('AutoCommit', 1)= 1 at DBI.pm line 689
<- STORE('Username', undef)= 1 at DBI.pm line 692
<> FETCH('Username')= undef ('Username' from cache) at DBI.pm line 692
$h->{'ora_session_mode'}=32768 ignored for invalid driver-specific attribute
<- STORE('ora_session_mode', 32768)= '' at DBI.pm line 692
<- FETCH('ora_session_mode')= undef at DBI.pm line 692
<- connected('dbi:Oracle:', undef, ...)= undef at DBI.pm line 698
<- connect= DBI::db=HASH(0x1b11f10)
<- STORE('dbi_connect_closure', CODE(0x1b7e3b8))= 1 at DBI.pm line 707
<- prepare('/* ASMCMD */ select version from v$instance')= DBI::st=HASH(0xde9f58) at asmcmdshare.pm line 2678
<- execute= '0E0' at asmcmdshare.pm line 2697
<- fetchrow_hashref= HASH(0x1b12570)1keys row1 at asmcmdshare.pm line 2723
<- finish= 1 at asmcmdshare.pm line 2744
<- DESTROY(DBI::st=HASH(1b11f40))= undef at asmcmdcore line 414
ASMCMD>
这里你可以看到ASM的每一个操作的详细的执行情况
然后，我们设置event 10046来跟踪该进程的执行情况
SQL> oradebug setospid 4742 Oracle pid: 27, Unix process pid: 4742, image: oracle@RAC1 (TNS V1-V3) SQL> oradebug event 10046 trace name context forever, level 12 Statement processed. SQL> oradebug dump errorstack 3 Statement processed. SQL> oradebug tracefile_name /u01/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_4742.trc SQL>
例如，我们将 +ASMDATA/RACDB/datafile/USERS.259.814462681 复制到/home/grid/asmfile
ASMCMD> cp +ASMDATA/RACDB/datafile/USERS.259.814462681 /home/grid/asmfile 看下，文件已经复制成功： [grid@RAC1 asmfile]$ ls -lrt total 5156 -rw-r--r-- 1 grid oinstall 10955 May 18 13:44 core_asmfile.pl -rw-r--r-- 1 grid oinstall 643 May 18 13:44 asmfile -rw-r----- 1 grid oinstall 5251072 Nov 1 11:41 USERS.259.814462681 [grid@RAC1 asmfile]$
现在我们使用tkprof进行格式化：
[grid@RAC1 trace]$ tkprof /u01/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_4742.trc /u01/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_4742.trc.out TKPROF: Release 11.2.0.3.0 - Development on Fri Nov 1 11:48:08 2013 Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved. [grid@RAC1 trace]$
可以看到，trace中显示了每一步我所执行的操作映射成ASM内部操作的过程和执行计划，时间等等详细信息，根据这个，不难找出瓶颈或者问题了吧，O(∩_∩)O哈哈~
TKPROF: Release 11.2.0.3.0 - Development on Fri Nov 1 11:48:08 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: /u01/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_4742.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
SQL ID: acnhubu2pzw1k Plan Hash: 486334127
select *
from
v$asm_diskgroup_stat
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.07 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.02 0.43 0 0 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.03 0.51 0 0 0 2
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
2 2 2 FIXED TABLE FULL X$KFGRP_STAT (cr=0 pr=0 pw=0 time=434753 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 5.01 5.01
GCS lock cvt S 2 0.02 0.02
GCS lock open S 8 0.03 0.05
Disk file operations I/O 3 0.00 0.00
kfk: async disk IO 12 0.00 0.01
********************************************************************************
SQL ID: 9gzq03ud5hkc4 Plan Hash: 486334127
select group_number, state
from
v$asm_diskgroup_stat where name='DATA'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.01 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 0 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.01 0 0 0 2
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FIXED TABLE FULL X$KFGRP_STAT (cr=0 pr=0 pw=0 time=68 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 6 0.00 0.00
SQL*Net message from client 6 1.19 1.19
********************************************************************************
SQL ID: 75uwbs5dk1u8s Plan Hash: 3937404369
select to_char(current_date, 'J') "JULIAN_DATE"
from
dual
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.02 0.50 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 0 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.02 0.52 0 0 0 3
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 3
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FIXED TABLE FULL X$DUAL (cr=0 pr=0 pw=0 time=47 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 9 0.00 0.00
SQL*Net message from client 10 387.59 387.59
library cache lock 1 0.03 0.03
library cache pin 1 0.00 0.00
********************************************************************************
SQL ID: 4zsbm8qz3sfw8 Plan Hash: 0
select inst_id, name_kfals, group_kfals, number_kfals, incarn_kfals,
entnum_kfals, entinc_kfals, parent_kfals, refer_kfals,
decode(bitand(entflg_kfals, 12), 4, 'Y', 8, 'Y', 'N'),
decode(bitand(entflg_kfals, 15), 1, 'N', 2, 'Y', 4, 'Y', 8, 'N')
from
x$kfals where decode(bitand(entflg_kfals, 12), 4, 'Y', 8, 'Y', 'N') = 'Y'
OR decode(bitand(entflg_kfals, 16), 16, 'Y', 'N') = 'Y'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.03 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.03 0 0 0 0
Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
********************************************************************************
SQL ID: fx7ssvgfs8vpv Plan Hash: 0
select name, group_number, file_number, file_incarnation, alias_index,
alias_incarnation, parent_index, reference_index, alias_directory,
system_created
from
gv$asm_alias where inst_id = USERENV('Instance')
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.09 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.09 0 0 0 0
Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
********************************************************************************
/* ASMCMD */ select name,
group_number,
file_number,
reference_index,
parent_index,
alias_directory,
system_created
from v$asm_alias where group_number=2 and parent_index=33554432
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.03 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.02 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.06 0 0 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FIXED TABLE FIXED INDEX X$KFALS (ind:4) (cr=0 pr=0 pw=0 time=20100 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 158.03 158.03
GCS lock open S 2 0.00 0.00
kfk: async disk IO 2 0.00 0.00
Disk file operations I/O 1 0.00 0.00
********************************************************************************
SQL ID: dykkcht6fux3m Plan Hash: 486334127
select group_number, state
from
v$asm_diskgroup_stat where name='ASMDATA'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 0 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.00 0.00 0 0 0 3
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 3
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FIXED TABLE FULL X$KFGRP_STAT (cr=0 pr=0 pw=0 time=126 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 9 0.00 0.00
SQL*Net message from client 9 0.00 0.00
********************************************************************************
SQL ID: ctvfwrrhcwx0v Plan Hash: 2683990587
select reference_index
from
v$asm_alias where group_number=1 and parent_index=16777216 and upper(name)=
'RACDB'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 0 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.00 0.00 0 0 0 3
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 3
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FIXED TABLE FIXED INDEX X$KFALS (ind:4) (cr=0 pr=0 pw=0 time=147 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 9 0.00 0.00
SQL*Net message from client 9 0.00 0.00
********************************************************************************
SQL ID: 5463x46jn1c70 Plan Hash: 2683990587
select reference_index
from
v$asm_alias where group_number=1 and parent_index=16777269 and upper(name)=
'DATAFILE'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 0 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.00 0.00 0 0 0 3
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 3
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FIXED TABLE FIXED INDEX X$KFALS (ind:4) (cr=0 pr=0 pw=0 time=205 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 9 0.00 0.00
SQL*Net message from client 9 15.96 15.97
********************************************************************************
/* ASMCMD */ select name,
group_number,
file_number,
reference_index,
parent_index,
alias_directory,
system_created
from v$asm_alias where group_number=1 and upper(name) like 'DATAFILE' and reference_index=16777322 and parent_index=16777269
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 0 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FIXED TABLE FIXED INDEX X$KFALS (ind:4) (cr=0 pr=0 pw=0 time=565 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.00 0.00
********************************************************************************
/* ASMCMD */ select name,
group_number,
file_number,
reference_index,
parent_index,
alias_directory,
system_created
from v$asm_alias where group_number=1 and parent_index=16777322
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 0 0 6
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 0 0 6
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
6 6 6 FIXED TABLE FIXED INDEX X$KFALS (ind:4) (cr=0 pr=0 pw=0 time=221 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 101.84 101.84
********************************************************************************
SQL ID: 8jn71z38r6h5z Plan Hash: 2683990587
select reference_index
from
v$asm_alias where group_number=1 and parent_index=16777322 and upper(name)=
'USERS.259.814462681'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 0 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FIXED TABLE FIXED INDEX X$KFALS (ind:4) (cr=0 pr=0 pw=0 time=204 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.00 0.00
********************************************************************************
begin
dbms_diskgroup.getfileattr(:filename, :filetype, :filesz, :blksz);
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.14 0 0 0 0
Execute 1 0.01 0.42 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.02 0.56 0 0 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
os thread startup 1 0.08 0.08
KSV master wait 6 0.13 0.15
ASM file metadata operation 2 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
begin
dbms_diskgroup.copy('', '', '', :src_path, :src_ftyp, :src_blksz,
:src_fsiz, '','','', :dst_path, 1);
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.01 0 0 0 0
Execute 1 0.03 0.48 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.03 0.50 0 0 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
KSV master wait 6 0.03 0.04
ASM file metadata operation 3 0.00 0.00
Disk file operations I/O 4 0.03 0.06
dbms_file_transfer I/O 15 0.18 0.30
CSS initialization 1 0.01 0.01
CSS operation: action 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.19 0.19
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 21 0.06 0.81 0 0 0 0
Execute 21 0.05 0.91 0 0 0 2
Fetch 19 0.03 0.46 0 0 0 25
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 61 0.14 2.20 0 0 0 27
Misses in library cache during parse: 12
Misses in library cache during execute: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message from client 60 387.59 669.86
SQL*Net message to client 59 0.00 0.00
GCS lock cvt S 2 0.02 0.02
GCS lock open S 10 0.03 0.05
Disk file operations I/O 8 0.03 0.07
kfk: async disk IO 14 0.00 0.01
library cache lock 1 0.03 0.03
library cache pin 1 0.00 0.00
os thread startup 1 0.08 0.08
KSV master wait 12 0.13 0.20
ASM file metadata operation 5 0.00 0.00
dbms_file_transfer I/O 15 0.18 0.30
CSS initialization 1 0.01 0.01
CSS operation: action 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.12 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.12 0 0 0 0
Misses in library cache during parse: 2
21 user SQL statements in session.
2 internal SQL statements in session.
23 SQL statements in session.
********************************************************************************
Trace file: /u01/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_4742.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
21 user SQL statements in trace file.
2 internal SQL statements in trace file.
23 SQL statements in trace file.
14 unique SQL statements in trace file.
41120 lines in trace file.
284 elapsed seconds in trace file.
