[20181129]大量的control file sequential read.txt

--//昨天看一個生產系統的awr報表,發現奇怪的現象,出現大量控制檔案讀取情況.

1.問題提出:

SYS@baaad1> @ ver1

PORT_STRING VERSION BANNER

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

x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

--//摘要awr報表如下:

Top 10 Foreground Events by Total Wait Time

Event Waits Total Wait Time (sec) Wait Avg(ms) % DB time Wait Class

DB CPU 708 89.0

log file sync 20,868 110.3 5 13.9 Commit

control file sequential read 38,851 16.9 0 2.1 System I/O

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

gc cr block 2-way 16,066 7.3 0 .9 Cluster

gc current block 2-way 13,385 5.7 0 .7 Cluster

SQL*Net more data to client 559,046 4.6 0 .6 Network

log file switch completion 4 3 757 .4 Configuration

gc current grant busy 7,577 2.9 0 .4 Cluster

db file sequential read 413 2.2 5 .3 User I/O

gc cr multi block request 2,417 1.8 1 .2 Cluster

--//control file sequential read佔17秒根本不算什麼.

...

IOStat by Filetype summary

'Data' columns suffixed with M,G,T,P are in multiples of 1024 other columns suffixed with K,M,G,T,P are in multiples of 1000

Small Read and Large Read are average service times, in milliseconds

Ordered by (Data Read + Write) desc

Filetype Name Reads: Data Reqs per sec Data per sec Writes: Data Reqs per sec Data per sec Small Read Large Read

Control File 7.6G 18.19 2.151M 239M 3.77 .066M 0.08 0.75

Log File 281M 0.08 .078M 291M 9.54 .081M 0.60 5.74

Data File 19M 0.70 .005M 280M 4.75 .078M 1.52

Archive Log 0M 0.10 0M 280M 0.08 .078M 0.05

TOTAL: 7.9G 19.08 2.235M 1.1G 18.14 .303M 0.14 0.90

--//真心說一下,資料庫本身沒有什麼大問題,典型的大馬拉小車(rac環境,記憶體充足,使用者很少).但是奇怪的是為什麼控制檔案讀如此之高(取樣1個小時)

--//我看了其它時間段的awr報表,也是一樣.為什麼?做一些簡單探究.

2.探究:

SYS@baaad1> @ ev_name 'control file sequential read'

EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS

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

81 3213517201 control file sequential read file# block# blocks 4108307767 9 System I/O

# iostat 1 100

Linux 2.6.32-431.el6.x86_64 (baaad1) 11/29/2018 _x86_64_ (32 CPU)

avg-cpu: %user %nice %system %iowait %steal %idle

0.75 0.00 0.99 0.03 0.00 98.23

Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn

....

sdz 3.46 4.70 3.52 274297736 205429406

...

sdac 15.46 1635.83 37.78 95396336257 2203177194

sdad 12.17 1356.83 58.67 79125895811 3421575617

sdae 15.25 1803.30 58.63 105162260680 3419328124

...

--//可以發現主要集中在sda[cde]磁碟上.

# dstat -t -r -d -D sdac,sdad,sdae,total 1 100

----system---- --io/sdac-----io/sdad-----io/sdae-----io/total- --dsk/sdac----dsk/sdad----dsk/sdae---dsk/total-

date/time | read writ: read writ: read writ: read writ| read writ: read writ: read writ: read writ

29-11 09:23:21|13.4 2.08 :9.64 2.53 :12.7 2.58 :37.9 21.4 | 818k 19k: 678k 29k: 902k 29k:2402k 230k

29-11 09:23:22|4.00 9.00 :2.00 3.00 :3.00 4.00 :11.0 18.0 | 64k 25k: 32k 32k: 48k 40k: 145k 101k

29-11 09:23:23| 0 9.00 : 0 3.00 :1.00 1.00 :3.00 18.0 | 0 32k: 0 32k: 16k 16k: 17k 96k

29-11 09:23:24| 114 3.00 :74.0 1.00 :82.0 1.00 : 272 14.0 |7808k 3072B:6769k 16k:8416k 16k: 22M 412k

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

29-11 09:23:25|6.00 7.00 :4.00 3.00 :4.00 3.00 :16.0 19.0 | 96k 46k: 64k 48k: 64k 48k: 225k 163k

29-11 09:23:26|60.0 15.0 :50.0 1.00 :64.0 1.00 : 176 44.0 |4400k 21k:4097k 16k:5128k 16k: 13M 393k

29-11 09:23:27| 0 9.00 : 0 1.00 :2.00 1.00 :4.00 13.0 | 0 10k: 0 16k: 32k 16k: 33k 47k

29-11 09:23:28|12.0 9.00 :6.00 3.00 :7.00 3.00 :27.0 20.0 | 192k 71k: 96k 48k: 112k 48k: 401k 183k

29-11 09:23:29| 0 6.00 : 0 1.00 :2.00 1.00 :4.00 18.0 | 0 3584B: 0 16k: 32k 16k: 33k 140k

29-11 09:23:30| 0 2.00 :1.00 1.00 :2.00 1.00 :5.00 8.00 | 0 1536B: 16k 16k: 32k 16k: 49k 46k

29-11 09:23:31|6.00 8.00 :3.00 3.00 :3.00 3.00 :14.0 23.0 | 96k 47k: 48k 48k: 48k 48k: 193k 179k

29-11 09:23:32| 0 2.00 : 0 1.00 :2.00 1.00 :4.00 16.0 | 0 1536B: 0 16k: 32k 16k: 33k 302k

29-11 09:23:33|6.00 5.00 :3.00 1.00 :4.00 1.00 :15.0 9.00 | 96k 3072B: 48k 16k: 64k 16k: 209k 40k

29-11 09:23:34|10.0 15.0 :5.00 1.00 :6.00 1.00 :23.0 33.0 | 160k 53k: 80k 16k: 96k 16k: 337k 221k

29-11 09:23:35| 0 8.00 :1.00 2.00 :2.00 1.00 :5.00 13.0 | 0 5632B: 16k 24k: 32k 16k: 49k 50k

29-11 09:23:36| 0 6.00 : 0 1.00 :1.00 1.00 :3.00 15.0 | 0 11k: 0 16k: 16k 16k: 17k 68k

29-11 09:23:37|35.0 11.0 :11.0 4.00 :6.00 6.00 :54.0 32.0 | 560k 48k: 176k 56k: 96k 192k: 833k 573k

29-11 09:23:38|1.00 9.00 :1.00 4.00 :4.00 3.00 :8.00 20.0 | 16k 98k: 16k 48k: 80k 40k: 113k 199k

29-11 09:23:39| 0 6.00 : 0 1.00 :2.00 2.00 :4.00 18.0 | 0 28k: 0 16k: 16k 24k: 17k 129k

29-11 09:23:40|5.00 10.0 :3.00 1.00 :2.00 2.00 :12.0 18.0 | 80k 17k: 48k 16k: 32k 24k: 161k 74k

29-11 09:23:41| 114 5.00 :74.0 1.00 :81.0 1.00 : 271 27.0 |7808k 3072B:6769k 16k:8400k 16k: 22M 368k

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

29-11 09:23:42| 0 10.0 : 0 4.00 :2.00 1.00 :4.00 28.0 | 0 74k: 0 40k: 32k 16k: 33k 398k

29-11 09:23:43|66.0 21.0 :53.0 7.00 :66.0 8.00 : 187 42.0 |4496k 101k:4145k 80k:5168k 112k: 13M 314k

29-11 09:23:44|2.00 15.0 :1.00 4.00 :2.00 6.00 :7.00 238 | 32k 59k: 16k 40k: 32k 56k: 81k 1663k

29-11 09:23:45| 0 7.00 :1.00 1.00 :2.00 1.00 :5.00 14.0 | 0 5632B: 16k 16k: 32k 16k: 49k 54k

29-11 09:23:46|4.00 7.00 :2.00 1.00 :2.00 2.00 :10.0 90.0 | 64k 10k: 32k 16k: 32k 32k: 129k 539k

29-11 09:23:47| 0 2.00 : 0 1.00 :2.00 3.00 :4.00 18.0 | 0 1536B: 0 16k: 32k 24k: 33k 286k

29-11 09:23:48|2.00 7.00 :1.00 4.00 :4.00 3.00 :9.00 15.0 | 32k 66k: 16k 56k: 64k 48k: 113k 171k

29-11 09:23:49|5.00 10.0 :3.00 2.00 :4.00 2.00 :14.0 33.0 | 80k 72k: 48k 32k: 64k 32k: 193k 340k

29-11 09:23:50| 0 3.00 :1.00 1.00 :2.00 2.00 :5.00 7.00 | 0 2048B: 16k 16k: 32k 24k: 49k 43k

29-11 09:23:51| 0 6.00 : 0 1.00 :2.00 1.00 :4.00 16.0 | 0 3584B: 0 16k: 32k 16k: 33k 68k

29-11 09:23:52|4.00 8.00 :2.00 1.00 :2.00 1.00 :10.0 21.0 | 64k 8192B: 32k 16k: 32k 16k: 129k 337k

29-11 09:23:53| 0 8.00 : 0 1.00 :2.00 1.00 :4.00 15.0 | 0 8192B: 0 16k: 32k 16k: 33k 57k

29-11 09:23:54| 0 5.00 : 0 1.00 :1.00 2.00 :3.00 16.0 | 0 3072B: 0 16k: 16k 24k: 17k 116k

29-11 09:23:55|6.00 12.0 :4.00 7.00 :4.00 4.00 :16.0 29.0 | 96k 72k: 64k 80k: 64k 56k: 225k 228k

29-11 09:23:56| 0 9.00 : 0 5.00 :2.00 1.00 :4.00 18.0 | 0 22k: 0 48k: 32k 16k: 33k 122k

29-11 09:23:57| 0 9.00 : 0 1.00 :1.00 2.00 :3.00 23.0 | 0 5632B: 0 16k: 16k 24k: 17k 294k

29-11 09:23:58| 104 8.00 :77.0 3.00 : 101 3.00 : 284 19.0 |7648k 78k:6817k 48k:8720k 48k: 23M 190k

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

29-11 09:23:59| 0 4.00 : 0 2.00 :2.00 1.00 :4.00 9.00 | 0 2560B: 0 32k: 32k 16k: 33k 55k

29-11 09:24:00|60.0 7.00 :51.0 1.00 :63.0 1.00 : 176 24.0 |4400k 28k:4113k 16k:5120k 16k: 13M 184k

29-11 09:24:01|7.00 11.0 :3.00 3.00 :3.00 3.00 :15.0 31.0 | 112k 48k: 48k 48k: 48k 48k: 209k 273k

29-11 09:24:02| 0 6.00 : 0 1.00 :1.00 1.00 :3.00 16.0 | 0 3584B: 0 16k: 16k 16k: 17k 272k

29-11 09:24:03| 0 10.0 : 0 3.00 :2.00 5.00 :4.00 26.0 | 0 66k: 0 32k: 32k 48k: 33k 250k

29-11 09:24:04|5.00 9.00 :2.00 8.00 :2.00 4.00 :11.0 26.0 | 80k 46k: 32k 80k: 32k 40k: 145k 183k

29-11 09:24:05| 0 17.0 :1.00 8.00 :1.00 1.00 :4.00 35.0 | 0 64k: 16k 72k: 16k 16k: 33k 252k

29-11 09:24:06| 0 9.00 : 0 1.00 :2.00 1.00 :4.00 21.0 | 0 8704B: 0 16k: 32k 16k: 33k 133k

29-11 09:24:07|7.00 11.0 :3.00 8.00 :2.00 4.00 :14.0 35.0 | 112k 56k: 48k 88k: 32k 56k: 193k 457k

29-11 09:24:08|5.00 13.0 :2.00 5.00 :6.00 5.00 :15.0 27.0 | 80k 131k: 32k 80k: 96k 80k: 209k 304k

29-11 09:24:09| 0 7.00 : 0 1.00 :2.00 2.00 :4.00 12.0 | 0 12k: 0 16k: 32k 32k: 33k 64k

29-11 09:24:10|5.00 10.0 :3.00 2.00 :1.00 2.00 :11.0 23.0 | 80k 9216B: 48k 24k: 16k 24k: 145k 134k

29-11 09:24:11| 0 6.00 : 0 3.00 :2.00 1.00 :4.00 37.0 | 0 11k: 0 32k: 32k 16k: 33k 340k

29-11 09:24:12| 0 15.0 : 0 1.00 :2.00 1.00 :4.00 21.0 | 0 18k: 0 16k: 32k 16k: 33k 215k

29-11 09:24:13|7.00 6.00 :3.00 4.00 :2.00 3.00 :14.0 24.0 | 112k 38k: 48k 56k: 32k 48k: 193k 239k

29-11 09:24:14|2.00 8.00 :1.00 1.00 :3.00 1.00 :8.00 21.0 | 32k 30k: 16k 16k: 48k 16k: 97k 386k

29-11 09:24:15| 111 5.00 :75.0 1.00 :84.0 1.00 : 272 13.0 |7760k 3072B:6785k 16k:8448k 16k: 22M 56k

29-11 09:24:16|5.00 5.00 :2.00 1.00 :2.00 1.00 :11.0 11.0 | 80k 6656B: 32k 16k: 32k 16k: 145k 51k

29-11 09:24:17|68.0 6.00 :50.0 1.00 :56.0 1.00 : 176 22.0 |4528k 3584B:4097k 16k:5008k 16k: 13M 372k

29-11 09:24:18|3.00 8.00 :1.00 4.00 :2.00 4.00 :8.00 17.0 | 48k 36k: 16k 64k: 32k 64k: 97k 164k^C

--//可以看出大約17-18秒存在大量的讀操作.22M之後,停頓1秒,又有13M的讀操作.

--//awr報表1個小時3600秒,3600/18*(23+13) = 7623M,接近上面報表看到的情況.

--//使用iotop -a 排序磁碟讀,結果如下:

Total DISK READ: 2.22 K/s | Total DISK WRITE: 28.89 K/s

TID PRIO USER DISK READ> DISK WRITE SWAPIN IO COMMAND

28909 be/4 oracle 5.34 M 0.00 B 0.00 % 0.04 % ora_lmon_baaad1

28946 be/4 oracle 4.48 M 6.22 M 0.00 % 0.06 % ora_ckpt_baaad1

28944 be/4 oracle 4.47 M 5.66 M 0.00 % 0.32 % ora_lgwr_baaad1

29476 be/4 oracle 1872.00 K 0.00 B 0.00 % 0.01 % ora_arc2_baaad1

29474 be/4 oracle 768.00 K 0.00 B 0.00 % 0.00 % ora_arc1_baaad1

6018 rt/4 grid 476.00 K 0.00 B 0.00 % 0.05 % ocssd.bin

--//感覺不對,不大可能這麼少.我監測時間至少1分鐘.

--//看另外的生產系統:

SYS@good1> select session_type,count(*),min(sample_time),max(sample_time) from V$ACTIVE_SESSION_HISTORY where event = 'control file sequential read' group by session_type;

SESSION_TY COUNT(*) MIN(SAMPLE_TIME) MAX(SAMPLE_TIME)

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

BACKGROUND 278 2018-11-28 07:33:13.367 2018-11-29 09:31:41.357

--//基本都是後臺操作.

--//有問題系統:

SYS@baaad1> select session_type,count(*),min(sample_time),max(sample_time) from V$ACTIVE_SESSION_HISTORY where event = 'control file sequential read' group by session_type;

SESSION_TY COUNT(*) MIN(SAMPLE_TIME) MAX(SAMPLE_TIME)

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

FOREGROUND 8547 2018-11-07 20:14:45.402 2018-11-29 09:32:46.703

BACKGROUND 3048 2018-11-07 20:18:18.712 2018-11-29 09:24:23.885

--//奇怪為什麼存在前臺的control file sequential read等待事件.

SELECT machine, COUNT (*)

FROM V$ACTIVE_SESSION_HISTORY

WHERE event = 'control file sequential read' AND session_type = 'FOREGROUND'

GROUP BY machine

5 ORDER BY 2 DESC;

MACHINE COUNT(*)

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

dbra 8272

baaad1 267

--//主要來自主機dbra的機器.噢這時我才想起來,我們這套系統引入一個變態的dg系統.一定是這臺機器不停的發出一些sql語句,需要大量的讀取控制檔案資訊,

--//而導致的情況.真心的無語....國內一個公司打著所謂高科技專利的東西,做出來的東西真tmd的垃圾!!!

SELECT *

FROM ( SELECT sql_id, session_type, COUNT (*)

FROM V$ACTIVE_SESSION_HISTORY

WHERE event = 'control file sequential read' AND machine = 'dbra'

GROUP BY sql_id, session_type

ORDER BY 3 DESC)

WHERE ROWNUM <= 10;

SQL_ID SESSION_TY COUNT(*)

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

6kkfgfjybkpfk FOREGROUND 3219

cwtrxyuuj3g9f FOREGROUND 12

4r17sm64wjavh FOREGROUND 11

9cqy7104jtqv8 FOREGROUND 10

gb34cg8jky3zv FOREGROUND 10

82tkft36vtcmy FOREGROUND 10

4661q3grpwg82 FOREGROUND 10

4fghushmxbv20 FOREGROUND 10

dtd4kmuz6bf80 FOREGROUND 10

bkgd2n3hyp7f5 FOREGROUND 10

10 rows selected.

--//主要集中在sql_id=6kkfgfjybkpfk.

SYS@baaad1> @ sql_id 6kkfgfjybkpfk

old 1: select sql_id,sql_fulltext sqltext from gv$sqlarea where sql_id='&1'

new 1: select sql_id,sql_fulltext sqltext from gv$sqlarea where sql_id='6kkfgfjybkpfk'

SQL_ID SQLTEXT

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

6kkfgfjybkpfk select 'flashpct;'||trim(ceil(percent_space_used)) from V$FLASH_RECOVERY_AREA_USAGE where file_type='FLASHBACK LOG'

union all

select 'flashtime;'||to_char(OLDEST_FLASHBACK_TIME,'yyyy-mm-dd hh24:mi:ss') from V$FLASHBACK_DATABASE_LOG

SYS@baaad1> @ viewsess 'physical read total bytes'

NAME STATISTIC# VALUE SID

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

physical read total bytes optimized 53 0 412

physical read total bytes 55 0 412

select 'flashpct;'||trim(ceil(percent_space_used)) from V$FLASH_RECOVERY_AREA_USAGE where file_type='FLASHBACK LOG'

union all

select 'flashtime;'||to_char(OLDEST_FLASHBACK_TIME,'yyyy-mm-dd hh24:mi:ss') from V$FLASHBACK_DATABASE_LOG

;

'FLASHPCT;'||TRIM(CEIL(PERCENT_SPACE_USED))

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

flashpct;0

SYS@baaad1> @ viewsess 'physical read total bytes'

NAME STATISTIC# VALUE SID

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

physical read total bytes optimized 53 0 412

physical read total bytes 55 13926400 412

--//看看一次訪問導致的物理讀,13926400/1024/1024 = 13.28M

--//當我查詢如下,sample_time時間按照前面dstat確定:

SELECT sample_time

,sql_id

,machine

,event

FROM V$ACTIVE_SESSION_HISTORY

WHERE sample_time BETWEEN '2018-11-29 09:23:38' AND '2018-11-29 09:23:42';

SAMPLE_TIME SQL_ID MACHINE EVENT

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

2018-11-29 09:23:40.825 6kzu9bz2qf6vc dbra

--//運氣好,抓到1個.不一定每次都能抓到.

SYS@baaad1> @ sql_id 6kzu9bz2qf6vc

SQL_ID SQLTEXT

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

6kzu9bz2qf6vc select 'archinfo;'||name||';'||dest_id||';'||thread#||';'||sequence#||';'||to_char(FIRST_CHANGE#)||';'||to_char(NEXT_CHANGE#)||';'||status||';'||to_char(completion_time,'yyyy-mm-dd hh24:mi:ss')||';'||

DELETED from v$archived_Log where next_change#>26408430794 and RESETLOGS_CHANGE# in (select resetlogs_change# from v$database) and deleted='NO' and STANDBY_DEST='NO' and status='A'

union all

select 'scninfo;'||to_char(current_scn) from v$database

union all

select 'dbidinfo;'||to_char(dbid)||';'||to_char(resetlogs_change#) from v$database

union all

select 'loginfo;'||group#||';'||thread#||';'||sequence#||';'||to_char(bytes)||';'||members||';'||archived||';'||status||';'||to_char(first_change#)||';'||to_char(first_time,'yyyymmdd hh24:mi:ss')||';'

||to_char(sysdate,'yyyy-mm-dd hh24:mi:ss') from v$Log

union all

select 'tpsinfo;'||ts#||';'||name||';'||included_in_database_backup from v$tablespace

union all

select 'userinfo;'||username||';'||user_id||';'||account_status||';'||to_char(lock_date,'yyyy-mm-dd hh24:mi:ss')||';'||to_char(expiry_date,'yyyy-mm-dd hh24:mi:ss')||';'||default_tablespace||';'||

temporary_tablespace from dba_users

union all

select 'controlinfo;'||NAME from v$controlfile

union all

select 'delarchinfo;'||to_char(min(next_change#)) from v$archived_Log where RESETLOGS_CHANGE# in (select resetlogs_change# from v$database) and deleted='NO' and STANDBY_DEST='NO' and status='A'

--//查詢到sql_id=6kzu9bz2qf6vc.問題在於這些語句還沒有使用繫結變數.當你查詢如下.

SELECT distinct plan_hash_value

FROM DBA_HIST_SQL_PLAN

WHERE sql_id IN ('cwtrxyuuj3g9f'

,'4r17sm64wjavh'

,'9cqy7104jtqv8'

,'gb34cg8jky3zv'

,'82tkft36vtcmy'

,'4661q3grpwg82'

,'4fghushmxbv20'

,'dtd4kmuz6bf80'

,'bkgd2n3hyp7f5')

PLAN_HASH_VALUE

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

3729576189

--//執行計劃都是一樣的實際上執行都是類似sql_id=6kzu9bz2qf6vc一樣的語句.僅僅next_change#>26408430794不同罷了.可以透過如下語句確定:

select * from DBA_HIST_SQLTEXT

WHERE sql_id IN ('cwtrxyuuj3g9f'

,'4r17sm64wjavh'

,'9cqy7104jtqv8'

,'gb34cg8jky3zv'

,'82tkft36vtcmy'

,'4661q3grpwg82'

,'4fghushmxbv20'

,'dtd4kmuz6bf80'

,'bkgd2n3hyp7f5');

--//結果不再貼出了.

--//我自己手工執行:

SYS@baaad1> @ viewsess 'physical read total bytes'

NAME STATISTIC# VALUE SID

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

physical read total bytes optimized 53 0 412

physical read total bytes 55 0 412

--//執行sql_id=6kzu9bz2qf6vc.語句....

SYS@baaad1> @ viewsess 'physical read total bytes'

NAME STATISTIC# VALUE SID

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

physical read total bytes optimized 53 0 412

physical read total bytes 55 23625728 412

--//物理讀比前面的還高.23625728/1024/1024 = 22.53M.

--//不知道大家看出規律來沒有,1個22.52M,1個13.28M.就是這2個sql語句不斷執行,間隔大約17-18秒.正好與我前面使用dstat看到的結果

--//相符合,頻繁呼叫讀取控制檔案導致的.

--//這也看出asm一些"弊端"(純粹個人的看法)^_^.

--//使用asm,由於沒有檔案系統的快取，基本是直接讀取磁碟裝置，控制檔案資訊不會進入資料快取,這樣導致大量的物理讀控制檔案.

--//頻繁呼叫,導致awr報表看到的情況.

--//補充1個使用檔案系統的例子:

SYS@zzz430> select * from v$version where rownum=1;

BANNER

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

Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

SYS@zzz430> show parameter filesystem

NAME TYPE VALUE

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

filesystemio_options string ASYNCH

--//反覆呼叫如下語句:

select 'flashpct;'||trim(ceil(percent_space_used)) from V$FLASH_RECOVERY_AREA_USAGE where file_type='FLASHBACK LOG'

union all

select 'flashtime;'||to_char(OLDEST_FLASHBACK_TIME,'yyyy-mm-dd hh24:mi:ss') from V$FLASHBACK_DATABASE_LOG

;

# dstat -t -d -D sda1,sda3,total

-----time----- --dsk/sda1----dsk/sda3---dsk/total-

date/time | read writ: read writ: read writ

29-11 11:07:22| 490B 5793B: 23k 52k: 47k 116k

29-11 11:07:23| 0 0 : 40k 88k: 80k 176k

29-11 11:07:24| 0 0 : 0 36k: 0 72k

29-11 11:07:25| 0 0 : 0 156k: 0 312k

29-11 11:07:26| 0 0 : 0 8192B: 0 16k

29-11 11:07:27| 0 160k: 0 52k: 0 424k

29-11 11:07:28| 0 0 :8192B 112k: 16k 224k

29-11 11:07:29| 0 0 : 0 100k: 0 200k

29-11 11:07:30| 0 0 : 0 44k: 0 88k

29-11 11:07:31| 0 0 :8192B 92k: 16k 184k

29-11 11:07:32| 0 0 : 0 92k: 0 184k

29-11 11:07:33| 0 0 : 0 44k: 0 88k

29-11 11:07:34| 0 0 : 0 52k: 0 104k

29-11 11:07:35| 0 0 : 0 44k: 0 88k

29-11 11:07:36| 0 0 : 0 56k: 0 112k

29-11 11:07:37| 0 0 : 0 184k: 0 368k

29-11 11:07:38| 0 0 : 0 40k: 0 80k

29-11 11:07:39| 0 12k: 16k 64k: 32k 152k

29-11 11:07:40| 0 0 : 0 32k: 0 64k

--// 資料庫在sda3磁碟上你可以發現根本沒有讀操作.

# ls -1 /u01/app/oracle/oradata/zzz430/control0*.ctl | xargs -I {} cachestats {}

/u01/app/oracle/oradata/zzz430/control01.ctl pages in cache: 2876/2884 (99.7%) [filesize=11536.0K, pagesize=4K]

/u01/app/oracle/oradata/zzz430/control02.ctl pages in cache: 260/2884 (9.0%) [filesize=11536.0K, pagesize=4K]

--//你可以發現檔案系統已經快取了控制檔案control01.ctl.反覆呼叫不再存在物理讀.

--//實際上如果你修改oracle引數filesystemio_options=setall,directio,就會看到物理讀.再做一個測試:

--//在測試系統進行,因為改引數filesystemio_options要重啟資料庫.

SYS@book> @ ver1

PORT_STRING VERSION BANNER

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

x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

SYS@book> show parameter filesystem

NAME TYPE VALUE

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

filesystemio_options string directio

$ cat c.txt

select 'flashpct;'||trim(ceil(percent_space_used)) from V$FLASH_RECOVERY_AREA_USAGE where file_type='FLASHBACK LOG'

union all

select 'flashtime;'||to_char(OLDEST_FLASHBACK_TIME,'yyyy-mm-dd hh24:mi:ss') from V$FLASHBACK_DATABASE_LOG

;

host sleep 0.99

--//執行如下:

sqlplus / as sysdba <<EOF

$(seq 1 100 | xargs -I {} cat c.txt)

EOF

# dstat -t -d -D cciss/c0d0p6,total

-----time----- dsk/cciss/c--dsk/total-

date/time | read writ: read writ

29-11 11:55:26| 784k 33k:1568k 65k

29-11 11:55:27| 784k 33k:1568k 65k

29-11 11:55:28| 848k 33k:1696k 65k

29-11 11:55:29| 784k 85k:1568k 169k

29-11 11:55:30| 784k 33k:1568k 65k

29-11 11:55:31| 848k 33k:1696k 185k

29-11 11:55:32| 784k 33k:1568k 65k

29-11 11:55:33| 784k 33k:1568k 65k

29-11 11:55:34| 848k 45k:1696k 89k

29-11 11:55:35| 784k 65k:1568k 129k

29-11 11:55:36| 784k 33k:1568k 65k

29-11 11:55:37| 848k 33k:1696k 113k

29-11 11:55:38| 784k 33k:1568k 65k

29-11 11:55:39| 848k 45k:1696k 89k

--//1秒呼叫一次.基本每秒讀取784K.

--//??這個版本的dstat可能有bug,看到total加倍了.

SYS@book> @ viewsess 'physical read total bytes'

NAME STATISTIC# VALUE SID

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

physical read total bytes optimized 53 0 28

physical read total bytes 55 0 28

SYS@book> @ b.txt

'FLASHPCT;'||TRIM(CEIL(PERCENT_SPACE_USED))

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

flashpct;0

SYS@book> @ viewsess 'physical read total bytes'

NAME STATISTIC# VALUE SID

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

physical read total bytes optimized 53 0 28

physical read total bytes 55 802816 28

--//802816/1024 = 784k,基本符合測試結果.

--//換成filesystemio_options=setall也一樣.貼出dstat的輸出.

SYS@book> show parameter filesystem

NAME TYPE VALUE

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

filesystemio_options string setall

--//執行如下:

sqlplus / as sysdba <<EOF

$(seq 1 30 | xargs -I {} cat c.txt)

EOF

# dstat -t -d -D cciss/c0d0p6,total

-----time----- dsk/cciss/c--dsk/total-

date/time | read writ: read writ

29-11 15:45:05| 784k 33k:1568k 65k

29-11 15:45:06| 848k 33k:1696k 193k

29-11 15:45:07| 784k 45k:1568k 89k

29-11 15:45:08| 784k 33k:1568k 65k

29-11 15:45:09| 848k 33k:1696k 65k

29-11 15:45:10| 784k 33k:1568k 65k

29-11 15:45:11| 784k 33k:1568k 121k

29-11 15:45:12| 848k 45k:1696k 89k

29-11 15:45:13| 784k 33k:1568k 65k

29-11 15:45:14| 784k 33k:1568k 65k

29-11 15:45:15| 848k 33k:1696k 65k

29-11 15:45:16| 784k 33k:1568k 65k

29-11 15:45:17| 848k 45k:1696k 89k

29-11 15:45:18| 848k 33k:1696k 65k

29-11 15:45:19| 784k 33k:1568k 65k

29-11 15:45:20| 784k 33k:1568k 65k

29-11 15:45:21| 848k 33k:1696k 89k

29-11 15:45:22| 784k 45k:1568k 89k

29-11 15:45:23| 784k 33k:1568k 65k

29-11 15:45:24| 848k 33k:1696k 65k

29-11 15:45:25| 784k 33k:1568k 65k^C

總結:

--//實際上對於國內所謂的公司真心無語,打著高科技的幌子騙人.

--//如果要是N年以前的硬體裝置,這樣的應用可能已經"不堪重負"了.

--//再回頭看awr報表發現:

Elapsed Time (s) Executions Elapsed Time per Exec (s) %Total %CPU %IO SQL Id SQL Module SQL Text

...

13.72 211 0.07 1.72 57.15 2.68 6kkfgfjybkpfk SQL*Plus select 'flashpct;'||trim(ceil(...

11.66 102 0.11 1.46 56.38 1.74 bf2j0w3avts8g SQL*Plus select 'archinfo;'||name||';'|...

10.23 97 0.11 1.28 61.88 0.93 6v7rcfxb9mftr SQL*Plus select 'archinfo;'||name||';'|...

--//執行sql_id=6kkfgfjybkpfk,211次.因為對方的dg是日誌傳輸完後在應用日誌,為了避免長時間日誌不應用.設定log_checkpoint_timeout=1800,

--//也就是30分鐘切換1次.這樣 102+97 = 199,我估計還漏掉1個類似的sql語句.

SYS@baaad1> show parameter log_checkpoint_timeout

NAME TYPE VALUE

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

log_checkpoint_timeout integer 1800

--//3600/211 = 17.06161137440758293838 基本17秒迴圈執行1次.

--//這樣前面的計算做一些簡單修正:

--//3600/17.06*(22.53+13.28) = 7556.62M,這樣就非常接近awr報表的統計數量了.

--//在SQL ordered by Physical Reads (UnOptimized)

UnOptimized Read Reqs Physical Read Reqs Executions UnOptimized Reqs per Exec %Opt %Total SQL Id SQL Module SQL Text

15,724 15,724 211 74.52 0.00 662.06 6kkfgfjybkpfk SQL*Plus select 'flashpct;'||trim(ceil(...

10,307 10,307 102 101.05 0.00 433.98 bf2j0w3avts8g SQL*Plus select 'archinfo;'||name||';'|...

9,603 9,603 97 99.00 0.00 404.34 6v7rcfxb9mftr SQL*Plus select 'archinfo;'||name||';'|...

--//awr報表時間段是2018-11-26 10:00 到 2018-11-26 11:00,看看alert.log檔案:

Mon Nov 26 10:01:15 2018

LGWR: Standby redo logfile selected for thread 1 sequence 38454 for destination LOG_ARCHIVE_DEST_2

Thread 1 advanced to log sequence 38454 (LGWR switch)

Current log# 1 seq# 38454 mem# 0: +DATA/baaad/onlinelog/redo01.redo

Mon Nov 26 10:01:16 2018

LNS: Standby redo logfile selected for thread 1 sequence 38454 for destination LOG_ARCHIVE_DEST_3

Mon Nov 26 10:01:16 2018

Archived Log entry 151141 added for thread 1 sequence 38453 ID 0x3647f882 dest 1:

Mon Nov 26 10:31:17 2018

LGWR: Standby redo logfile selected for thread 1 sequence 38455 for destination LOG_ARCHIVE_DEST_2

Thread 1 advanced to log sequence 38455 (LGWR switch)

Current log# 2 seq# 38455 mem# 0: +DATA/baaad/onlinelog/redo02.redo

Mon Nov 26 10:31:18 2018

Archived Log entry 151149 added for thread 1 sequence 38454 ID 0x3647f882 dest 1:

Mon Nov 26 10:31:18 2018

LNS: Standby redo logfile selected for thread 1 sequence 38455 for destination LOG_ARCHIVE_DEST_3

Mon Nov 26 11:01:16 2018

LGWR: Standby redo logfile selected for thread 1 sequence 38456 for destination LOG_ARCHIVE_DEST_2

--//發生了2次切換.時間並沒有對齊整點.這樣類似sql_id=bf2j0w3avts8g,6v7rcfxb9mftr漏掉幾次.

--//10:01:16, 漏掉76秒,76/17.06 = 4.45.有點差距.不探究了.

SELECT *

FROM V$ACTIVE_SESSION_HISTORY

WHERE sql_id IN ('6kkfgfjybkpfk', 'bf2j0w3avts8g', '6v7rcfxb9mftr')

AND sample_time BETWEEN '2018-11-26 10:00:00'

AND '2018-11-26 11:00:00'

order by 2 ;

--//看到session_id,session_serial#不一樣的,好像是分開執行的.不再探究這些細節了.這也是為什麼前面使用iotop看不到的原因,因

--//為很快執行完成退出了.

[20181129]大量的control file sequential read.txt

相關文章