프린트 하기

내맘대로긍정이 알려주는

Oracle 23ai 신기능
무료 세미나 발표자료

다운로드 trending_flat
2024
10.12
14:00

OS환경 : Oracle Linux 7.6 (64bit)

 

DB 환경 : Oracle Database 19.15.0.0

 

방법 : 오라클 19c insert 쿼리 logical read 확인

19c 환경에서 단일 insert 쿼리 실행시에도 write(쓰기) 관련 wait 이벤트가 아닌
logical read나 physical read wait 이벤트와 같은 read(읽기) 이벤트가 발생하는것을 보고

테스트 환경에서도 재현되는지 테스트 해봄

 

샘플 테이블 및 인덱스 생성

1
2
3
4
5
6
7
SQL> 
drop table intest purge;
create table intest (col1 number, col2 number);
create unique index pk_intest on intest (col1);
alter table intest add constraint pk_intest primary key (col1);
create index ix_intest_01 on intest (col2, col1);
create index ix_intest_02 on intest (col1, col2);

 

 

샘플 데이터 삽입

1
2
SQL> insert into intest select object_id, 100||object_id from dba_objects where object_id is not null;
commit;

 

 

buffer cache 플러쉬

1
2
3
SQL> alter system flush buffer_cache;
 
System altered.

 

 

sql trace 설정

1
2
3
4
5
SQL>
alter session set tracefile_identifier='insert_test1';
alter session set events '10046 trace name context forever, level 8';
 
Session altered.

 

 

단일 insert 쿼리 실행 후 commit

1
2
3
SQL>
insert into intest values (999999888888);
commit;

 

 

sql trace 해제

1
2
3
SQL> alter session set events '10046 trace name context off';
 
Session altered.

 

 

tkprof 후 trace 확인

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
$ tkprof TEST_ora_3827873_insert_test1.trc intest1.trc
$ cat intest1.trc
 
TKPROF: Release 19.0.0.0.0 - Development on Sat Jun 3 10:52:52 2023
 
Copyright (c) 19822019, Oracle and/or its affiliates.  All rights reserved.
 
Trace file: TEST_ora_3827873_insert_test1.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: 3tb9w9637wnq6 Plan Hash: 0
 
insert into intest
values
 (999999888888)
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00         16          3         22           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00         16          3         22           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
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  INTEST (cr=3 pr=16 pw=0 time=777 us starts=1)
 
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                        16        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************
 
SQL ID: 23wm3kz7rps5y Plan Hash: 0
 
commit
 
 
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          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0
 
Misses in library cache during parse: 0
Parsing user id: SYS
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file sync                                   1        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************
 
SQL ID: 06nvwn223659v Plan Hash: 0
 
alter session set events '10046 trace name context off'
 
 
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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0
 
Misses in library cache during parse: 0
Parsing user id: SYS
 
 
 
********************************************************************************
 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00         16          3         23           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00         16          3         23           1
 
Misses in library cache during parse: 1
 
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
  db file sequential read                        16        0.00          0.00
  log file sync                                   1        0.00          0.00
 
 
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          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        0      0.00       0.00          0          0          0           0
 
Misses in library cache during parse: 0
 
    3  user  SQL statements in session.
    0  internal SQL statements in session.
    3  SQL statements in session.
********************************************************************************
Trace file: TEST_ora_3827873_insert_test1.trc
Trace file compatibility: 12.2.0.0
Sort options: default
 
       1  session in tracefile.
       3  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       3  SQL statements in trace file.
       3  unique SQL statements in trace file.
      70  lines in trace file.
       0  elapsed seconds in trace file.

insert 쿼리인데도 db file sequential read 이벤트가 발생함

 

 

trace raw 파일 확인

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
$ cat TEST_ora_3827873_insert_test1.trc
Trace file /oracle/app/oracle/diag/rdbms/test/TEST/trace/TEST_ora_3827873_insert_test1.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.15.0.0.0
Build label:    RDBMS_19.15.0.0.0DBRU_LINUX.X64_220330
ORACLE_HOME:    /oracle/app/oracle/product/19c
System name:    Linux
Node name:      TESTMH
Release:        4.18.0-372.9.1.el8.x86_64
Version:        #1 SMP Fri Apr 15 22:12:19 EDT 2022
Machine:        x86_64
Instance name: TEST
Redo thread mounted by this instance: 1
Oracle process number: 113
Unix process pid: 3827873, image: oracle@TESTMH (TNS V1-V3)
 
 
*** 2023-06-03T10:52:41.808763+02:00
*** SESSION ID:(71.322492023-06-03T10:52:41.808779+02:00
*** CLIENT ID:() 2023-06-03T10:52:41.808784+02:00
*** SERVICE NAME:(SYS$USERS) 2023-06-03T10:52:41.808787+02:00
*** MODULE NAME:(sqlplus@TESTMH (TNS V1-V3)) 2023-06-03T10:52:41.808791+02:00
*** ACTION NAME:() 2023-06-03T10:52:41.808794+02:00
*** CLIENT DRIVER:(SQL*PLUS) 2023-06-03T10:52:41.808797+02:00
 
WAIT #140617850679696: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=24087641677915
WAIT #140617850679696: nam='SQL*Net message from client' ela= 178 driver id=1650815232 #bytes=1 p3=0 obj#=18 tim=24087641678468
CLOSE #140617850679696:c=9,e=9,dep=0,type=1,tim=24087641678494
=====================
PARSING IN CURSOR #140617849481336 len=42 dep=0 uid=0 oct=2 lid=0 tim=24087641679250 hv=2256425670 ad='743d0fc0' sqlid='3tb9w9637wnq6'
insert into intest values (999999888888)
END OF STMT
PARSE #140617849481336:c=741,e=741,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=24087641679250
WAIT #140617849481336: nam='db file sequential read' ela= 7 file#=1 block#=90800 blocks=1 obj#=69145 tim=24087641679367
WAIT #140617849481336: nam='db file sequential read' ela= 3 file#=1 block#=91929 blocks=1 obj#=69145 tim=24087641679398
WAIT #140617849481336: nam='db file sequential read' ela= 4 file#=3 block#=208 blocks=1 obj#=0 tim=24087641679428
WAIT #140617849481336: nam='db file sequential read' ela= 3 file#=3 block#=39156 blocks=1 obj#=0 tim=24087641679450
WAIT #140617849481336: nam='db file sequential read' ela= 3 file#=1 block#=90809 blocks=1 obj#=69146 tim=24087641679503
WAIT #140617849481336: nam='db file sequential read' ela= 2 file#=1 block#=92040 blocks=1 obj#=69146 tim=24087641679522
WAIT #140617849481336: nam='db file sequential read' ela= 3 file#=3 block#=272 blocks=1 obj#=0 tim=24087641679542
WAIT #140617849481336: nam='db file sequential read' ela= 3 file#=1 block#=90817 blocks=1 obj#=69147 tim=24087641679600
WAIT #140617849481336: nam='db file sequential read' ela= 3 file#=1 block#=90820 blocks=1 obj#=69147 tim=24087641679618
WAIT #140617849481336: nam='db file sequential read' ela= 4 file#=3 block#=38001 blocks=1 obj#=0 tim=24087641679694
WAIT #140617849481336: nam='db file sequential read' ela= 4 file#=1 block#=90816 blocks=1 obj#=69147 tim=24087641679799
WAIT #140617849481336: nam='db file sequential read' ela= 3 file#=1 block#=91681 blocks=1 obj#=69147 tim=24087641679818
WAIT #140617849481336: nam='db file sequential read' ela= 3 file#=1 block#=91682 blocks=1 obj#=69147 tim=24087641679857
WAIT #140617849481336: nam='db file sequential read' ela= 4 file#=1 block#=90821 blocks=1 obj#=69147 tim=24087641679902
WAIT #140617849481336: nam='db file sequential read' ela= 4 file#=1 block#=90825 blocks=1 obj#=69148 tim=24087641680061
WAIT #140617849481336: nam='db file sequential read' ela= 3 file#=1 block#=91451 blocks=1 obj#=69148 tim=24087641680091
EXEC #140617849481336:c=701,e=805,p=16,cr=3,cu=22,mis=0,r=1,dep=0,og=1,plh=0,tim=24087641680121
STAT #140617849481336 id=1 cnt=0 pid=0 pos=1 obj=69145 op='LOAD TABLE CONVENTIONAL  INTEST (cr=3 pr=16 pw=0 str=1 time=777 us)'
WAIT #140617849481336: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=69148 tim=24087641680174
WAIT #140617849481336: nam='SQL*Net message from client' ela= 148 driver id=1650815232 #bytes=1 p3=0 obj#=69148 tim=24087641680333
CLOSE #140617849481336:c=2,e=3,dep=0,type=0,tim=24087641680350
=====================
PARSING IN CURSOR #140617858162208 len=6 dep=0 uid=0 oct=44 lid=0 tim=24087641680368 hv=3480936638 ad='0' sqlid='23wm3kz7rps5y'
commit
END OF STMT
PARSE #140617858162208:c=2,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=24087641680368
XCTEND rlbk=0, rd_only=0, tim=24087641680414
EXEC #140617858162208:c=73,e=72,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,plh=0,tim=24087641680481
WAIT #140617858162208: nam='log file sync' ela= 82 buffer#=559 sync scn=8648968 p3=0 obj#=69148 tim=24087641680577
WAIT #140617858162208: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=69148 tim=24087641680609
WAIT #140617858162208: nam='SQL*Net message from client' ela= 147 driver id=1650815232 #bytes=1 p3=0 obj#=69148 tim=24087641680765
CLOSE #140617858162208:c=2,e=1,dep=0,type=3,tim=24087641680777
=====================
PARSING IN CURSOR #140617849481336 len=55 dep=0 uid=0 oct=42 lid=0 tim=24087641680823 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140617849481336:c=22,e=22,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=24087641680823
EXEC #140617849481336:c=178,e=178,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=24087641681043

35번째 줄부터 보면 obj#이 69145, 69146, 69147, 69148 인 오브젝트들에 대한 db file sequential read가 발생했음

 

 

원본 trace 파일에 나온 오브젝트(obj#) 확인

1
2
3
4
5
6
7
8
9
10
11
12
13
SQL>
set lines 200 pages 1000
col owner for a10
col object_name for a20
select owner, object_id, object_name, object_type from dba_objects
where object_id in (69145691466914769148);
 
OWNER       OBJECT_ID OBJECT_NAME          OBJECT_TYPE
---------- ---------- -------------------- -----------------------
SYS             69145 INTEST               TABLE
SYS             69146 PK_INTEST            INDEX
SYS             69147 IX_INTEST_01         INDEX
SYS             69148 IX_INTEST_02         INDEX

각각 테이블과 인덱스들임

 

 

원본 trace 파일에 나온 데이터 파일(file#) 확인

1
2
3
4
5
6
7
8
9
10
11
12
SQL>
set lines 200 pages 1000
col file_name for a50
col tablespace_name for a10 
select tablespace_name, file_id, file_name
from dba_data_files
where file_id in (13);
 
TABLESPACE    FILE_ID FILE_NAME
---------- ---------- --------------------------------------------------
SYSTEM              1 /oracle/app/oracle/oradata/TEST/system01.dbf
UNDOTBS1            3 /oracle/app/oracle/oradata/TEST/undotbs01.dbf

system(intest 테이블이 system ts에 만들어짐)과 undotbs임

 

 

버퍼캐쉬 작게한뒤 테스트

버퍼 캐쉬를 최소 크기로 만들기 위해 파라미터 적용 후 재기동

1
2
3
4
5
6
SQL> alter system set db_cache_size=256m scope=spfile;
 
System altered.
 
SQL> shutdown immediate
SQL> startup

 

 

버퍼 캐시 파라미터 확인

1
2
3
4
5
SQL> show parameter db_cache_size
 
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_cache_size                        big integer 256M

256mb로 작아짐

 

 

대량 샘플 데이터 삽입 및 count 확인

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
SQL>
DECLARE
TYPE tbl_ins IS TABLE OF intest%ROWTYPE INDEX BY BINARY_INTEGER;
w_ins tbl_ins;
BEGIN
FOR d IN 1..100 LOOP
FOR i IN 1..100000 LOOP 
   w_ins(i).col1   := i||ceil(dbms_random.value(11000000000000000000));
   w_ins(i).col2   := i;
END LOOP;
FORALL i in 1..100000 INSERT INTO intest VALUES w_ins(i);
   COMMIT;
END LOOP;
END;
/
(원하는만큼 실행)
 
SQL> 
select count(*from intest;
 
  COUNT(*)
----------
  14300001

 

 

용량 확인

1
2
3
4
5
6
7
8
SQL> 
select bytes/1024/1024 mb 
from dba_segments 
where segment_name = 'INTEST';
 
        MB
----------
       368

 

 

세션1에서 nl조인 사용해서 buffer cache 를 많이 사용하게 하는 쿼리 실행

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
SQL> 
create table tmp1 (col1 number) nologging;
DECLARE
TYPE tbl_ins IS TABLE OF tmp1%ROWTYPE INDEX BY BINARY_INTEGER;
w_ins tbl_ins;
BEGIN
FOR d IN 1..100 LOOP
FOR i IN 1..100000 LOOP 
   w_ins(i).col1   := i;
END LOOP;
FORALL i in 1..100000 INSERT INTO tmp1 VALUES w_ins(i);
   COMMIT;
END LOOP;
END;
/
(원하는만큼 실행)
 
SQL>
select count(*from tmp1;
 
  COUNT(*)
----------
  88200000
 
SQL> 
select /*+ leading(a) use_nl(b) index(b ix_intest_02) */ * 
from sys.tmp1 a, sys.intest b
where a.col1 = b.col2;

 

 

세션 2 실행

sql trace 설정

1
2
3
4
5
SQL> 
alter session set tracefile_identifier='insert_test2';
alter session set events '10046 trace name context forever, level 8';
 
Session altered.

 

 

단일 insert 쿼리 실행 후 commit

1
2
3
SQL> 
insert into tmp1 values (99999999999999999999);
commit;

 

 

sql trace 해제

1
2
3
SQL> alter session set events '10046 trace name context off';
 
Session altered.

 

 

tkprof 후 trace 확인

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
$ tkprof TEST_ora_2064495_insert_test2.trc intest2.trc
$ cat intest2.trc
 
TKPROF: Release 19.0.0.0.0 - Development on Sat Jun 3 11:52:52 2023
 
Copyright (c) 19822019, Oracle and/or its affiliates.  All rights reserved.
 
Trace file: TEST_ora_2064495_insert_test2.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: 6fakz566336w7 Plan Hash: 0
 
insert into tmp1
values
 (99999999999999999999)
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.03          2          1          3           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.03          2          1          3           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
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  TMP1 (cr=1 pr=2 pw=0 time=29925 us starts=1)
 
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                            3        0.00          0.00
  db file sequential read                         2        0.02          0.02
  Disk file operations I/O                        1        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.06          0.06
********************************************************************************
 
SQL ID: 23wm3kz7rps5y Plan Hash: 0
 
commit
 
 
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          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0
 
Misses in library cache during parse: 0
Parsing user id: SYS
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file sync                                   1        0.12          0.12
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        4.01          4.01
********************************************************************************
 
SQL ID: 06nvwn223659v Plan Hash: 0
 
alter session set events '10046 trace name context off'
 
 
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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0
 
Misses in library cache during parse: 0
Parsing user id: SYS
 
 
 
********************************************************************************
 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      3      0.00       0.03          2          1          4           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.03          2          1          4           1
 
Misses in library cache during parse: 1
 
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       29.94         34.03
  PGA memory operation                            3        0.00          0.00
  db file sequential read                         2        0.02          0.02
  Disk file operations I/O                        1        0.00          0.00
  log file sync                                   1        0.12          0.12
 
 
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          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        0      0.00       0.00          0          0          0           0
 
Misses in library cache during parse: 0
 
    3  user  SQL statements in session.
    0  internal SQL statements in session.
    3  SQL statements in session.
********************************************************************************
Trace file: TEST_ora_2064495_insert_test2.trc
Trace file compatibility: 12.2.0.0
Sort options: default
 
       1  session in tracefile.
       3  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       3  SQL statements in trace file.
       3  unique SQL statements in trace file.
      64  lines in trace file.
       4  elapsed seconds in trace file.

db file sequential read, Disk file operations I/O 이벤트가 발생함

 

 

trace raw 파일 확인

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
$ cat TEST_ora_2064495_insert_test2.trc
Trace file /oracle/app/oracle/diag/rdbms/test/TEST/trace/TEST_ora_2064495_insert_test2.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.15.0.0.0
Build label:    RDBMS_19.15.0.0.0DBRU_LINUX.X64_220330
ORACLE_HOME:    /oracle/app/oracle/product/19c
System name:    Linux
Node name:      TESTMH
Release:        4.18.0-372.9.1.el8.x86_64
Version:        #1 SMP Fri Apr 15 22:12:19 EDT 2022
Machine:        x86_64
Instance name: TEST
Redo thread mounted by this instance: 1
Oracle process number: 93
Unix process pid: 2064495, image: oracle@TESTMH (TNS V1-V3)
 
 
*** 2023-06-03T11:52:41.808763+02:00
*** SESSION ID:(71.322492023-06-03T11:52:41.808779+02:00
*** CLIENT ID:() 2023-06-03T11:52:41.808784+02:00
*** SERVICE NAME:(SYS$USERS) 2023-06-03T11:52:41.808787+02:00
*** MODULE NAME:(sqlplus@TESTMH (TNS V1-V3)) 2023-06-03T11:52:41.808791+02:00
*** ACTION NAME:() 2023-06-03T11:52:41.808794+02:00
*** CLIENT DRIVER:(SQL*PLUS) 2023-06-03T11:52:41.808797+02:00
 
WAIT #140403722953864: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=27916397691262
 
*** 2023-06-03T11:52:41.766608+02:00
WAIT #140403722953864: nam='SQL*Net message from client' ela= 29944353 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=27916427635982
CLOSE #140403722953864:c=9,e=9,dep=0,type=1,tim=27916427636117
WAIT #140403722947976: nam='PGA memory operation' ela= 19 p1=65536 p2=1 p3=0 obj#=-1 tim=27916427637290
WAIT #140403722947976: nam='PGA memory operation' ela= 7 p1=65536 p2=1 p3=0 obj#=-1 tim=27916427637789
WAIT #140403722947976: nam='PGA memory operation' ela= 10 p1=65536 p2=2 p3=0 obj#=-1 tim=27916427637947
=====================
PARSING IN CURSOR #140403722947976 len=46 dep=0 uid=0 oct=2 lid=0 tim=27916427638073 hv=2352061319 ad='61ac9fb0' sqlid='6fakz566336w7'
insert into tmp1 values (99999999999999999999)
END OF STMT
PARSE #140403722947976:c=1964,e=1898,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=27916427638072
WAIT #140403722947976: nam='db file sequential read' ela= 25 file#=1 block#=525958 blocks=1 obj#=69188 tim=27916427638359
WAIT #140403722947976: nam='Disk file operations I/O' ela= 30 FileOperation=2 fileno=3 filetype=2 obj#=0 tim=27916427638775
WAIT #140403722947976: nam='db file sequential read' ela= 29245 file#=3 block#=172099 blocks=1 obj#=0 tim=27916427668039
EXEC #140403722947976:c=735,e=30022,p=2,cr=1,cu=3,mis=0,r=1,dep=0,og=1,plh=0,tim=27916427668164
STAT #140403722947976 id=1 cnt=0 pid=0 pos=1 obj=69188 op='LOAD TABLE CONVENTIONAL  TMP1 (cr=1 pr=2 pw=0 str=1 time=29925 us)'
WAIT #140403722947976: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=27916427668309
WAIT #140403722947976: nam='SQL*Net message from client' ela= 69341 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=27916427737682
CLOSE #140403722947976:c=9,e=9,dep=0,type=0,tim=27916427737793
=====================
PARSING IN CURSOR #140403722947976 len=6 dep=0 uid=0 oct=44 lid=0 tim=27916427737893 hv=3480936638 ad='0' sqlid='23wm3kz7rps5y'
commit
END OF STMT
PARSE #140403722947976:c=27,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=27916427737892
XCTEND rlbk=0, rd_only=0, tim=27916427737972
EXEC #140403722947976:c=233,e=233,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,plh=0,tim=27916427738194
WAIT #140403722947976: nam='log file sync' ela= 126627 buffer#=5524 sync scn=9362211 p3=0 obj#=0 tim=27916427864853
WAIT #140403722947976: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=27916427864958
 
*** 2023-06-03T11:52:42.766608+02:00
WAIT #140403722947976: nam='SQL*Net message from client' ela= 4017645 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=27916431882626
CLOSE #140403722947976:c=8,e=8,dep=0,type=1,tim=27916431882749
=====================
PARSING IN CURSOR #140403722946304 len=55 dep=0 uid=0 oct=42 lid=0 tim=27916431882838 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140403722946304:c=33,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=27916431882838
EXEC #140403722946304:c=403,e=403,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=27916431883307

오브젝트 id 69188, 0에 대해 read 이벤트가 발생함

 

 

원본 trace 파일에 나온 오브젝트(obj#) 확인

1
2
3
4
5
6
7
8
9
10
SQL>
set lines 200 pages 1000
col owner for a10
col object_name for a20
select owner, object_id, object_name, object_type from dba_objects
where object_id in (691880);
 
OWNER       OBJECT_ID OBJECT_NAME          OBJECT_TYPE
---------- ---------- -------------------- -----------------------
SYS             69188 TMP1                 TABLE

0은 없고, 69188은 TMP1 테이블임

 

 

원본 trace 파일에 나온 데이터 파일(file#) 확인

1
2
3
4
5
6
7
8
9
10
11
12
SQL>
set lines 200 pages 1000
col file_name for a50
col tablespace_name for a10 
select tablespace_name, file_id, file_name
from dba_data_files
where file_id in (13);
 
TABLESPACE    FILE_ID FILE_NAME
---------- ---------- --------------------------------------------------
SYSTEM              1 /oracle/app/oracle/oradata/TEST/system01.dbf
UNDOTBS1            3 /oracle/app/oracle/oradata/TEST/undotbs01.dbf

system(tmp1 테이블이 system ts에 만들어짐)과 undotbs임

 

 

*추가 insert에 함수 써서 테스트

buffer cache 플러쉬

1
2
3
SQL> alter system flush buffer_cache;
 
System altered.

 

 

sql trace 설정

1
2
3
4
5
SQL>
alter session set tracefile_identifier='insert_test3';
alter session set events '10046 trace name context forever, level 8';
 
Session altered.

 

 

함수를 사용한 단일 insert 쿼리 실행 후 commit

1
2
3
SQL>
insert into intest values (substr(99999999999299992999999929999992999978999919999,3,20), nvl(88884888818888888,9999954999999789999999));
commit;

 

 

sql trace 해제

1
2
3
SQL> alter session set events '10046 trace name context off';
 
Session altered.

 

 

tkprof 후 trace 확인

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
$ tkprof TEST_ora_2178495_insert_test3.trc intest3.trc
$ cat intest3.trc
TKPROF: Release 19.0.0.0.0 - Development on Sat Jun 3 11:54:52 2023
 
Copyright (c) 19822019, Oracle and/or its affiliates.  All rights reserved.
 
Trace file: TEST_ora_2178495_insert_test3.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: 28m9zgfg6j607 Plan Hash: 0
 
insert into intest
values
 (substr(99999999999299992999999929999992999978999919999,3,20),
  nvl(88884888818888888,9999954999999789999999))
 
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00         13          1         12           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00         13          1         12           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
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  INTEST (cr=1 pr=13 pw=0 time=1082 us starts=1)
 
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                            3        0.00          0.00
  asynch descriptor resize                        1        0.00          0.00
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                        13        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.38          0.38
********************************************************************************
 
SQL ID: 23wm3kz7rps5y Plan Hash: 0
 
commit
 
 
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          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0
 
Misses in library cache during parse: 0
Parsing user id: SYS
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file sync                                   1        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        3.02          3.02
********************************************************************************
 
SQL ID: 06nvwn223659v Plan Hash: 0
 
alter session set events '10046 trace name context off'
 
 
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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0
 
Misses in library cache during parse: 0
Parsing user id: SYS
 
 
 
********************************************************************************
 
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00         13          1         13           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00         13          1         13           1
 
Misses in library cache during parse: 1
 
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       12.90         16.32
  PGA memory operation                            3        0.00          0.00
  asynch descriptor resize                        1        0.00          0.00
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                        13        0.00          0.00
  log file sync                                   1        0.00          0.00
 
 
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          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        0      0.00       0.00          0          0          0           0
 
Misses in library cache during parse: 0
 
    3  user  SQL statements in session.
    0  internal SQL statements in session.
    3  SQL statements in session.
********************************************************************************
Trace file: TEST_ora_2178495_insert_test3.trc
Trace file compatibility: 12.2.0.0
Sort options: default
 
       1  session in tracefile.
       3  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       3  SQL statements in trace file.
       3  unique SQL statements in trace file.
      77  lines in trace file.
       3  elapsed seconds in trace file.

db file sequential read, Disk file operations I/O 이벤트가 발생함

 

 

trace raw 파일 확인

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
$ cat TEST_ora_2178495_insert_test3.trc
Trace file /oracle/app/oracle/diag/rdbms/test/TEST/trace/TEST_ora_2178495_insert_test3.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.15.0.0.0
Build label:    RDBMS_19.15.0.0.0DBRU_LINUX.X64_220330
ORACLE_HOME:    /oracle/app/oracle/product/19c
System name:    Linux
Node name:      TESTMH
Release:        4.18.0-372.9.1.el8.x86_64
Version:        #1 SMP Fri Apr 15 22:12:19 EDT 2022
Machine:        x86_64
Instance name: TEST
Redo thread mounted by this instance: 1
Oracle process number: 78
Unix process pid: 2178495, image: oracle@TESTMH (TNS V1-V3)
 
 
*** 2023-06-03T11:54:41.808763+02:00
*** SESSION ID:(71.322492023-06-03T11:54:41.808779+02:00
*** CLIENT ID:() 2023-06-03T11:54:41.808784+02:00
*** SERVICE NAME:(SYS$USERS) 2023-06-03T11:54:41.808787+02:00
*** MODULE NAME:(sqlplus@TESTMH (TNS V1-V3)) 2023-06-03T11:54:41.808791+02:00
*** ACTION NAME:() 2023-06-03T11:54:41.808794+02:00
*** CLIENT DRIVER:(SQL*PLUS) 2023-06-03T11:54:41.808797+02:00
 
WAIT #140597931241304: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=27919210987415
 
*** 2023-06-03T11:54:41.808763+02:00
WAIT #140597931241304: nam='SQL*Net message from client' ela= 12909747 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=27919223897483
CLOSE #140597931241304:c=5,e=5,dep=0,type=1,tim=27919223897582
WAIT #140597931235136: nam='PGA memory operation' ela= 8 p1=65536 p2=1 p3=0 obj#=-1 tim=27919223898571
WAIT #140597931235136: nam='PGA memory operation' ela= 10 p1=65536 p2=2 p3=0 obj#=-1 tim=27919223899035
WAIT #140597931235136: nam='PGA memory operation' ela= 18 p1=65536 p2=1 p3=0 obj#=-1 tim=27919223899277
=====================
PARSING IN CURSOR #140597931235136 len=135 dep=0 uid=0 oct=2 lid=0 tim=27919223899411 hv=2657654791 ad='62e4a090' sqlid='28m9zgfg6j607'
insert into intest values (substr(99999999999299992999999929999992999978999919999,3,20), nvl(88884888818888888,9999954999999789999999))
END OF STMT
PARSE #140597931235136:c=1548,e=1805,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=27919223899410
WAIT #140597931235136: nam='asynch descriptor resize' ela= 5 outstanding #aio=0 current aio limit=0 new aio limit=128 obj#=69145 tim=27919223899604
WAIT #140597931235136: nam='Disk file operations I/O' ela= 54 FileOperation=2 fileno=1 filetype=2 obj#=69145 tim=27919223899654
WAIT #140597931235136: nam='db file sequential read' ela= 11 file#=1 block#=90800 blocks=1 obj#=69145 tim=27919223899681
WAIT #140597931235136: nam='db file sequential read' ela= 7 file#=1 block#=387787 blocks=1 obj#=69145 tim=27919223899761
WAIT #140597931235136: nam='Disk file operations I/O' ela= 10 FileOperation=2 fileno=3 filetype=2 obj#=0 tim=27919223899844
WAIT #140597931235136: nam='db file sequential read' ela= 9 file#=3 block#=272 blocks=1 obj#=0 tim=27919223899864
WAIT #140597931235136: nam='db file sequential read' ela= 6 file#=3 block#=25620 blocks=1 obj#=0 tim=27919223899921
WAIT #140597931235136: nam='db file sequential read' ela= 8 file#=1 block#=90809 blocks=1 obj#=69146 tim=27919223900031
WAIT #140597931235136: nam='db file sequential read' ela= 6 file#=1 block#=94446 blocks=1 obj#=69146 tim=27919223900098
WAIT #140597931235136: nam='db file sequential read' ela= 8 file#=1 block#=252426 blocks=1 obj#=69146 tim=27919223900149
WAIT #140597931235136: nam='db file sequential read' ela= 8 file#=1 block#=90817 blocks=1 obj#=69147 tim=27919223900250
WAIT #140597931235136: nam='db file sequential read' ela= 6 file#=1 block#=368296 blocks=1 obj#=69147 tim=27919223900329
WAIT #140597931235136: nam='db file sequential read' ela= 6 file#=1 block#=247582 blocks=1 obj#=69147 tim=27919223900368
WAIT #140597931235136: nam='db file sequential read' ela= 6 file#=1 block#=90825 blocks=1 obj#=69148 tim=27919223900430
WAIT #140597931235136: nam='db file sequential read' ela= 6 file#=1 block#=93872 blocks=1 obj#=69148 tim=27919223900473
WAIT #140597931235136: nam='db file sequential read' ela= 17 file#=1 block#=168139 blocks=1 obj#=69148 tim=27919223900530
EXEC #140597931235136:c=902,e=1152,p=13,cr=1,cu=12,mis=0,r=1,dep=0,og=1,plh=0,tim=27919223900600
STAT #140597931235136 id=1 cnt=0 pid=0 pos=1 obj=69145 op='LOAD TABLE CONVENTIONAL  INTEST (cr=1 pr=13 pw=0 str=1 time=1082 us)'
WAIT #140597931235136: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=69148 tim=27919223900664
WAIT #140597931235136: nam='SQL*Net message from client' ela= 389227 driver id=1650815232 #bytes=1 p3=0 obj#=69148 tim=27919224289901
CLOSE #140597931235136:c=4,e=4,dep=0,type=0,tim=27919224289954
=====================
PARSING IN CURSOR #140597931235136 len=6 dep=0 uid=0 oct=44 lid=0 tim=27919224289999 hv=3480936638 ad='0' sqlid='23wm3kz7rps5y'
commit
END OF STMT
PARSE #140597931235136:c=13,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=27919224289999
XCTEND rlbk=0, rd_only=0, tim=27919224290051
EXEC #140597931235136:c=133,e=133,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,plh=0,tim=27919224290179
WAIT #140597931235136: nam='log file sync' ela= 107 buffer#=398 sync scn=9365106 p3=0 obj#=69148 tim=27919224290305
WAIT #140597931235136: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=69148 tim=27919224290339
 
*** 2023-06-03T11:54:41.808763+02:00
WAIT #140597931235136: nam='SQL*Net message from client' ela= 3029040 driver id=1650815232 #bytes=1 p3=0 obj#=69148 tim=27919227319389
CLOSE #140597931235136:c=0,e=4,dep=0,type=1,tim=27919227319467
=====================
PARSING IN CURSOR #140597931485928 len=55 dep=0 uid=0 oct=42 lid=0 tim=27919227319508 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140597931485928:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=27919227319508
EXEC #140597931485928:c=0,e=214,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=27919227319768

40번째 줄부터 보면 obj#이 69145, 69146, 69147, 69148 인 오브젝트들에 대한 Disk file operations I/O, db file sequential read가 발생했음

 

 

원본 trace 파일에 나온 오브젝트(obj#) 확인

1
2
3
4
5
6
7
8
9
10
11
12
13
SQL>
set lines 200 pages 1000
col owner for a10
col object_name for a20
select owner, object_id, object_name, object_type from dba_objects
where object_id in (69145691466914769148);
 
OWNER       OBJECT_ID OBJECT_NAME          OBJECT_TYPE
---------- ---------- -------------------- -----------------------
SYS             69145 INTEST               TABLE
SYS             69146 PK_INTEST            INDEX
SYS             69147 IX_INTEST_01         INDEX
SYS             69148 IX_INTEST_02         INDEX

각각 테이블과 인덱스들임

 

 

결론 : 단일 insert 구문을 수행하더라도 logical read wait이 발생함

버퍼캐시 공간이 적거나 버퍼캐시에 freelist 에서 할당받은 블록이 없는 경우

데이터파일에서 읽어 버퍼캐시에 적재하기 때문에 physical read wait이 발생할수도 있음

 

친절한 sql 튜닝 438p(6.2.2 Direct Path Insert) 내용 중 아래와 같이 나와있음

-------------------------------------

일반적인 INSERT가 느린 이유는 다음과 같다.

1. 데이터를 입력할 수 있는 블록을 Freelist에서 찾는다.

테이블 HWM(High Water Mark) 아래쪽에 있는 블록 중 데이터 입력이 가능한(여유 공간이 있는) 블록을 목록으로 관리하는데, 이를 ‘Free list’라고 한다.

2. Freelist에서 할당받은 블록을 버퍼캐시에서 찾는다.

3. 버퍼캐시에 없으면, 데이터파일에서 읽어 버퍼캐시에 적재한다.

4. INSERT 내용을 Undo 세그먼트에 기록한다.

5. INSERT 내용을 Redo 로그에 기록한다.

-------------------------------------

 

 

참조 : 

참조 친절한 sql 튜닝 438p(6.2.2 Direct Path Insert)

2546382.1, 1081977.1