ablog

不器用で落着きのない技術者のメモ

SQLトレースとstrace

[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#, p.spid from v$session s, v$process p where p.addr = s.paddr and s.sid = sys_context('USERENV','SID');

       SID    SERIAL# SPID
---------- ---------- ------------------------
        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 #5597196: nam='direct path read' ela= 233 file number=4 first dba=3251 block cnt=5 obj#=110119 tim=1350521557206427
WAIT #5597196: nam='direct path read' ela= 211 file number=4 first dba=3264 block cnt=8 obj#=110119 tim=1350521557206820
WAIT #5597196: nam='direct path read' ela= 632 file number=4 first dba=3273 block cnt=15 obj#=110119 tim=1350521557208596
WAIT #5597196: nam='direct path read' ela= 225 file number=4 first dba=22297 block cnt=15 obj#=110119 tim=1350521557210469
WAIT #5597196: nam='direct path read' ela= 203 file number=4 first dba=22313 block cnt=15 obj#=110119 tim=1350521557213599
[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