ablog

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

シェルスクリプトから実行しているSQLが遅いので調べてみたときのメモ

結論としては、SQL が遅いようなので、別途SQL単体でチューニングが必要と思われる。
調べたときにやったことをメモっておく。

  • top
$ top
top - 14:40:47 up 52 days,  3:14,  9 users,  load average: 2.30, 2.13, 1.76
Tasks: 182 total,   3 running, 179 sleeping,   0 stopped,   0 zombie
Cpu(s): 57.4%us,  2.3%sy,  0.0%ni,  1.8%id, 37.6%wa,  0.2%hi,  0.7%si,  0.0%st
Mem:   2075600k total,  2023152k used,    52448k free,     5908k buffers
Swap:  2096472k total,   294468k used,  1802004k free,  1760204k cached

 8091 oracle    25   0 2192m 340m 307m R 92.1 16.8   1871:23 oracle
 1867 oracle    16   0 2146m 202m 200m R 16.6 10.0   0:35.72 oracle
 1865 oracle    15   0 24156 9188 5172 S  7.6  0.4   0:16.72 sqlldr
30534 oracle    16   0 2161m  38m  37m S  2.3  1.9 171:07.91 oracle

...
  • vmstat
$ vmstat 5 12
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1  0 294436  58776   5636 1759900    3    2    88   141    3    1 12  2 73 13  0
 1  0 294436  58776   5652 1759968    0    0     2    38 1015   51 50  0 48  2  0
 1  0 294436  58280   5652 1760904    0    0     3   226 1016   61 50  0 46  4  0
 1  1 294436  57908   5668 1761320    0    0     0   125 1016   54 50  0 47  3  0
 1  0 294436  57784   5684 1761384    0    0     3    46 1013   54 50  0 47  2  0
 1  0 294436  56792   5700 1762396    0    0     3   350 1024   74 50  0 39 10  0
 1  0 294436  56296   5720 1762844    0    0     2   118 1017   56 50  0 47  3  0
 1  0 294436  56172   5728 1762904    0    0     2    49 1013   50 50  0 48  2  0
 1  0 294436  55304   5736 1763856    0    0     2   238 1020   61 50  0 46  4  0
 1  0 294436  54808   5752 1764312    0    0     3   127 1014   56 50  0 47  3  0
 1  0 294436  54808   5768 1764328    0    0     3    59 1017   58 50  0 48  2  0
 1  0 294436  53596   5772 1765264    0    0     3   816 1029   81 50  0 38 11  0
  • sar
$ sar -P ALL

...

12:30:01          CPU     %user     %nice   %system   %iowait    %steal     %idle
12:40:01          all     50.04      0.00      0.04      2.40      0.00     47.52
12:40:01            0      0.12      0.00      0.06      4.79      0.00     95.03
12:40:01            1     99.97      0.00      0.03      0.00      0.00      0.00
12:50:01          all     50.02      0.00      0.05      2.39      0.00     47.54
12:50:01            0      0.07      0.00      0.06      4.79      0.00     95.07
12:50:01            1     99.97      0.00      0.03      0.00      0.00      0.00
13:00:01          all     50.02      0.00      0.04      2.27      0.00     47.67
13:00:01            0      0.07      0.00      0.05      4.54      0.00     95.33
13:00:01            1     99.97      0.00      0.03      0.00      0.00      0.00
13:10:01          all     50.19      0.00      0.11      2.61      0.00     47.10
13:10:01            0      0.43      0.00      0.17      5.20      0.00     94.19
13:10:01            1     99.95      0.00      0.04      0.01      0.00      0.00
13:20:01          all     50.03      0.00      0.04      2.11      0.00     47.82
13:20:01            0      0.08      0.00      0.06      4.22      0.00     95.65
13:20:01            1     99.97      0.00      0.03      0.00      0.00      0.00
13:30:01          all     50.04      1.31      0.11      2.26      0.00     46.27
13:30:01            0      0.12      2.63      0.19      4.53      0.00     92.54
13:30:01            1     99.97      0.00      0.03      0.00      0.00      0.00
13:40:01          all     50.03      0.00      0.04      2.16      0.00     47.77
13:40:01            0      0.08      0.00      0.06      4.33      0.00     95.53
13:40:01            1     99.97      0.00      0.03      0.00      0.00      0.00
13:50:01          all     50.05      0.00      0.04      2.13      0.00     47.78
13:50:01            0      0.12      0.00      0.06      4.26      0.00     95.56
13:50:01            1     99.98      0.00      0.02      0.00      0.00      0.00
14:00:01          all     50.11      0.00      0.10      2.70      0.00     47.09
14:00:01            0      0.28      0.00      0.15      5.40      0.00     94.17
14:00:01            1     99.94      0.00      0.04      0.00      0.00      0.02
14:10:02          all     71.79      0.00      2.44     19.12      0.00      6.65
14:10:02            0     70.53      0.00      1.94     15.50      0.00     12.04
14:10:02            1     73.05      0.00      2.94     22.75      0.00      1.26
14:20:01          all     51.30      0.00      0.45      8.17      0.00     40.08
14:20:01            0     95.35      0.00      0.25      2.64      0.00      1.76
14:20:01            1      7.25      0.00      0.65     13.70      0.00     78.40
14:30:01          all     50.06      0.58      0.10      6.14      0.00     43.11
14:30:01            0    100.00      0.00      0.00      0.00      0.00      0.00
14:30:01            1      0.13      1.16      0.20     12.29      0.00     86.22
14:40:01          all     71.14      0.72      2.25     18.22      0.00      7.67
14:40:01            0     83.07      0.00      1.67     14.09      0.00      1.17
14:40:01            1     59.22      1.43      2.83     22.35      0.00     14.17
Average:          all     50.66      0.22      0.22      2.98      0.00     45.92
Average:            0      8.94      0.41      0.28      4.88      0.00     85.49
Average:            1     92.38      0.03      0.17      1.08      0.00      6.34
  • プロセス
$ sqlplus / as sysdba
set pagesize 1000
set linesize 300
col spid for 99999
col sid for 9999
col serial# for 99999
col username for a14
col program for a50
col machine for a50
col osuser for a20

select proc.spid, ses.sid, ses.serial#, ses.username, ses.status, ses.program, ses.machine, ses.osuser, ses.process
from v$session ses, v$process proc
where ses.paddr = proc.addr
order by ses.username, ses.status;

SPID           SID SERIAL# USERNAME       STATUS   PROGRAM                                            MACHINE                                            OSUSER               PROCESS
------------ ----- ------- -------------- -------- -------------------------------------------------- -------------------------------------------------- -------------------- ------------
8091           242   41837 SCOTT           ACTIVE   sqlplus@******************************** (TNS V   *********************************                  oracle               8089
...

30 rows selected.
  • プロセスの親子関係を調べる。
$ pstree -alp

...

  |   |-bash,7762
  |   |   `-****_******.sh,29045 ********
  |   |       `-transaction_dat,29828 ********
  |   |           `-*******_******_,8085 ********
  |   |               `-sqlplus,8089 -s 
  • ロックの状況を調べる
$ sqlplus / as sysdba
set feedback off
set pagesize 9999
set linesize 2000
set trimspool on
set trimout on

col block for 9999
col sid for 9999
col status for a8
col machine for a9
col username for a9
col type for a2
col lmode for 99
col request for 99
col program for a10
col serialno for 999999
col lock_time for a10
col sql for a100

select a.blocking_session block,
        a.sid sid,
        a.status status,
        substr(a.machine, 1,9) machine,
        a.username username,
        b.type type,
        b.lmode lmode,
        b.request request,
        a.program program,
        a.serial# serialno,
        to_char(b.ctime/60, '9990.9') lock_time,
        c.sql_text sql
from v$session a,
        v$lock b,
        v$sqlarea c
where a.sid=b.sid
        and a.sql_address = c.address;

BLOCK   SID STATUS   MACHINE   USERNAME  TY LMODE REQUEST PROGRAM    SERIALNO LOCK_TIME  SQL
----- ----- -------- --------- --------- -- ----- ------- ---------- -------- ---------- -----------------------------
        242 ACTIVE   ********* SCOTT      TM     2       0 sqlplus@**    41837  1930.1    UPDATE ********

        242 ACTIVE   ********* SCOTT      TM     3       0 sqlplus@**    41837   202.6    UPDATE ********

        242 ACTIVE   ********* SCOTT      TM     3       0 sqlplus@**    41837   202.8    UPDATE ********

        242 ACTIVE   ********* SCOTT      TM     3       0 sqlplus@**    41837   202.6    UPDATE ********

        242 ACTIVE   +******** SCOTT      TX     6       0 sqlplus@**    41837  1919.1    UPDATE ********
  • 実行計画を調べる。
SQL> select sql_address, sql_hash_value from v$session where sid=242 and serial#=41837;

SQL_ADDR SQL_HASH_VALUE
-------- --------------
9E2DA380     2857543126

SET LINESIZE 200
COLUMN ID FORMAT 999
COLUMN OPERATION FORMAT A60
COLUMN OBJECT FORMAT A30
COLUMN COST FORMAT 9999
COLUMN BYTES FORMAT 99999

SELECT
  ID,
  DECODE( OPTIMIZER,
    'ANALYZED', LPAD( ' ', DEPTH * 3, ' ' ) || OPERATION || ' ' || NVL2( OPTIONS, OPTIONS, null ),
    NULL, LPAD( ' ', DEPTH * 3, ' ' ) || OPERATION || ' ' || OPTIONS,
    LPAD( ' ', DEPTH * 3, ' ' ) || OPERATION
  ) OPERATION,
  DECODE( OPTIMIZER,
    'ANALYZED', OBJECT_NAME,
    NULL, OBJECT_NAME,
    'Optimizer = ' || OPTIMIZER
  ) OBJECT,
  COST,
  BYTES
  FROM V$SQL_PLAN
  WHERE ADDRESS = '9E2DA380' AND HASH_VALUE = 2857543126 AND CHILD_NUMBER = 0
  ORDER BY ADDRESS, HASH_VALUE, CHILD_NUMBER, ID;

  ID OPERATION                                                    OBJECT                          COST  BYTES
---- ------------------------------------------------------------ ------------------------------ ----- ------
   0 UPDATE STATEMENT                                             Optimizer = ALL_ROWS               3
   1    UPDATE                                                    *******_******_DETAIL
   2       MERGE JOIN SEMI                                                                           3     65
   3          TABLE ACCESS BY INDEX ROWID                         *******_******_DETAIL              0     52
   4             INDEX FULL SCAN                                  *******_******_DETAIL_PK           0
   5          SORT UNIQUE                                                                            3     13
   6             VIEW                                             VW_SQ_1                            2     13
   7                NESTED LOOPS                                                                     2    103
   8                   NESTED LOOPS                                                                  1     95
   9                      MERGE JOIN CARTESIAN                                                       0     87
  10                         TABLE ACCESS BY INDEX ROWID          *******_******_DETAIL              0     61
  11                            INDEX RANGE SCAN                  *******_******_DETAIL_UK           0
  12                         BUFFER SORT                                                             0     26
  13                            INDEX RANGE SCAN                  *******_******_UK1                 0     26
  14                      TABLE ACCESS BY INDEX ROWID             ******_******_LOG                  1      8
  15                         INDEX UNIQUE SCAN                    ******_******_LOG_PK               0
  16                   TABLE ACCESS BY INDEX ROWID                ******_******_LOG                  1      8
  17                      INDEX UNIQUE SCAN                       ******_******_LOG_PK               0
  18       HASH GROUP BY                                                                             2    185
  19          NESTED LOOPS                                                                           2    185
  20             NESTED LOOPS                                                                        1    177
  21                NESTED LOOPS                                                                     1     69
  22                   TABLE ACCESS BY INDEX ROWID                *******_******_DETAIL              0     61
  23                      INDEX RANGE SCAN                        *******_******_DETAIL_UK           0
  24                   TABLE ACCESS BY INDEX ROWID                ******_******_LOG                  1   9320
  25                      INDEX UNIQUE SCAN                       ******_******_LOG_PK               0
  26                TABLE ACCESS BY INDEX ROWID                   *******_******                     0     39
  27                   INDEX FULL SCAN                            *******_******_PK                  0
  28             TABLE ACCESS BY INDEX ROWID                      ******_******_LOG                  1      8
  29                INDEX UNIQUE SCAN                             ******_******_LOG_PK               0
  • SQL のどのあたりを実行中か調べる。
SQL> oradebug setospid 8091
Oracle pid: 17, Unix process pid: 8091, image: oracle@*********
SQL> oradebug short_stack
ksdxfstk()+19<-ksdxcb()+1321<-sspuser()+102<-kdsgrp()+261<-kdsfbr()+162<-qertbFetchByRowID()+683<-qerjotFetch()+232<-qerjotFetch()+232<-qerjotFetch()+232<-qerghFetch()+195<-subsr1()+161<-subsr3()+245<-evaopn2()+3242<-evaopn2()+330<-upderh()+135<-__PGOSF250_upduaw()+107<-kdusru()+439<-kauupd()+323<-updrow()+1362<-__PGOSF286_qerupRowProcedure()+62<-qerupFetch()+510<-updaul()+900<-updThreePhaseExe()+277<-updexe()+283<-opiexe()+4165<-opipls()+1033<-opiodr()+976<-__PGOSF112_rpidrus()+159<-skgmstack()+139<-rpidru()+98<-rpiswu2()+334<-rpidrv()+1199<-psddr0()+392<-psdnal()+308<-pevm_EXECC()+296<-__PGOSF12_pfrinstr_EXECC()+63<-pfrrun_no_tool()+45<-pfrrun()+765<-plsql_run()+736<-peicnt()+242<-kkxexe()+389<-opiexe()+4265<-kpoal8()+2089<-opiodr()+976<-ttcpip()+1085<-opitsk()+1054<-opiino()+821<-opiodr()+976<-opidrv()+466<-sou2o()+91<-opimai_real()+117<-main()+111<-__libc_start_main()+220

う〜ん、

qertbFetchByRowID()+683<- ← TABLE ACCESS BY INDEX ROWID
qerjotFetch()+232<- ← NESTED LOOPS
qerjotFetch()+232<- ← NESTED LOOPS
qerjotFetch()+232<- ← NESTED LOOPS
qerghFetch()+195<-  ← HASH GROUP BY

みたいなことかなぁ