[oracle@localhost ~]$ sqlplus neo/zion
SQL*Plus: Release 11.2.0.2.0 Production on Wed Oct 17 17:50:41 2012
Copyright (c) 1982, 2010, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> set escape on
SQL> select s.sid, s.serial
SID SERIAL
---------- ---------- ------------------------
39 85 3331
SQL> !sudo /usr/bin/strace -tt -o strace.log -p 3331 \&
SQL> Process 3331 attached - interrupt to quit
SQL> set autotrace on
SQL> alter session set events '10046 trace name context forever, level 12';
Session altered.
SQL> select count(1) from agent;
COUNT(1)
----------
1000000
Execution Plan
----------------------------------------------------------
Plan hash value: 2571700340
--------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
--------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 789 (1)| 00:00:10 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| AGENT | 873K| 789 (1)| 00:00:10 |
--------------------------------------------------------------------
Note
-----
- dynamic sampling used for this statement (level=2)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
2893 consistent gets
2890 physical reads
0 redo size
489 bytes sent via SQL*Net to client
437 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> alter session set events '10046 trace name context off';
Session altered.
SQL> ! ls -l /proc/3331/fd
total 0
lr-x------ 1 oracle oracle 64 Oct 17 17:53 0 -> /dev/null
l-wx------ 1 oracle oracle 64 Oct 17 17:53 1 -> /dev/null
lr-x------ 1 oracle oracle 64 Oct 17 17:53 10 -> /home/oracle/app/oracle/product/11.2.0/dbhome_2/rdbms/mesg/oraus.msb
l-wx------ 1 oracle oracle 64 Oct 17 17:53 11 -> /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3331.trm
l-wx------ 1 oracle oracle 64 Oct 17 17:53 12 -> pipe:[10374]
lr-x------ 1 oracle oracle 64 Oct 17 17:53 14 -> /home/oracle/app/oracle/product/11.2.0/dbhome_2/rdbms/mesg/oraus.msb
l-wx------ 1 oracle oracle 64 Oct 17 17:53 2 -> /dev/null
lrwx------ 1 oracle oracle 64 Oct 17 17:53 256 -> /home/oracle/app/oracle/oradata/orcl/system01.dbf
lrwx------ 1 oracle oracle 64 Oct 17 17:53 257 -> /home/oracle/app/oracle/oradata/orcl/users01.dbf
lrwx------ 1 oracle oracle 64 Oct 17 17:53 258 -> /home/oracle/app/oracle/oradata/orcl/temp01.dbf
lrwx------ 1 oracle oracle 64 Oct 17 17:53 259 -> /home/oracle/app/oracle/oradata/orcl/undotbs01.dbf
lr-x------ 1 oracle oracle 64 Oct 17 17:53 3 -> /dev/null
lr-x------ 1 oracle oracle 64 Oct 17 17:53 4 -> /dev/null
lr-x------ 1 oracle oracle 64 Oct 17 17:53 5 -> /home/oracle/app/oracle/product/11.2.0/dbhome_2/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oracle 64 Oct 17 17:53 6 -> /proc/3331/fd
lr-x------ 1 oracle oracle 64 Oct 17 17:53 7 -> /dev/zero
l-wx------ 1 oracle oracle 64 Oct 17 17:53 8 -> /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3331.trc
lr-x------ 1 oracle oracle 64 Oct 17 17:53 9 -> pipe:[10373]
SQL> show parameters user_dump_dest
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest string /home/oracle/app/oracle/diag/r
dbms/orcl/orcl/trace
SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@localhost ~]$ Process 3331 detached
[oracle@localhost ~]$ tkprof /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3331.trc orcl_ora_3331_tkprof.txt
TKPROF: Release 11.2.0.2.0 - Development on Wed Oct 17 18:01:37 2012
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
[oracle@localhost ~]$ less orcl_ora_3331_tkprof.txt
...
SQL ID: guxtdnm3w68gr Plan Hash: 2571700340
select count(1)
from
agent
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 2 0.21 0.80 2890 2893 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.21 0.80 2890 2893 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 346
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=2893 pr=2890 pw=0 time=807284 us)
1000000 1000000 1000000 TABLE ACCESS FULL AGENT (cr=2893 pr=2890 pw=0 time=38613843 us cost=789 size=0 card=873743)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
Disk file operations I/O 1 0.00 0.00
asynch descriptor resize 2 0.00 0.00
direct path read 97 0.00 0.03
SQL*Net message from client 2 0.00 0.00
********************************************************************************
[oracle@localhost ~]$ grep 'pread64(257' strace.log|head -5
17:52:37.206294 pread64(257, "\6\242\0\0\263\f\0\1\303\364\356\0\0\0\1\6\306\313\0\0\1\0\0\0'\256\1\0j\350\356\0"..., 40960, 26632192) = 40960
17:52:37.206677 pread64(257, "\6\242\0\0\300\f\0\1\303\364\356\0\0\0\1\6\324\305\0\0\1\0\0\0'\256\1\0r\350\356\0"..., 65536, 26738688) = 65536
17:52:37.208032 pread64(257, "\6\242\0\0\311\f\0\1\303\364\356\0\0\0\1\6\25\224\0\0\1\0\0\0'\256\1\0|\350\356\0"..., 122880, 26812416) = 122880
17:52:37.210311 pread64(257, "\6\242\0\0\31W\0\1\377\364\356\0\0\0\1\4\16'\0\0\1\0!\0'\256\1\0\377\364\356\0"..., 122880, 182657024) = 122880
17:52:37.213464 pread64(257, "\6\242\0\0)W\0\1\377\364\356\0\0\0\1\4\n\5\0\0\1\0\26\0'\256\1\0\377\364\356\0"..., 122880, 182788096) = 122880
[oracle@localhost ~]$ grep 'direct path read' /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3331.trc|head -5
WAIT
WAIT
WAIT
WAIT
WAIT
[oracle@localhost ~]$ grep 'pread64(257' strace.log|wc -l
97
[oracle@localhost ~]$ grep 'direct path read' /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3331.trc|wc -l
97