Log file sync caused by more commit
Log file sync caused by more commit
Today, our db changes slow suddenly.
And i do a hanganalyze as following:
[sql]
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1
System name: Linux
Node name: db42
Release: 2.6.18-164.el5
Version: #1 SMP Thu Sep 3 04:15:13 EDT 2009
Machine: x86_64
Instance name: cedb2
Redo thread mounted by this instance: 2
Oracle process number: 205
Unix process pid: 11618, image: oracle@db42 (TNS V1-V3)
*** 2013-08-28 15:53:14.460
*** SESSION ID:(773.44301) 2013-08-28 15:53:14.460
*** CLIENT ID:() 2013-08-28 15:53:14.460
*** SERVICE NAME:(SYS$USERS) 2013-08-28 15:53:14.460
*** MODULE NAME:(sqlplus@db42 (TNS V1-V3)) 2013-08-28 15:53:14.460
*** ACTION NAME:() 2013-08-28 15:53:14.460
Processing Oradebug command 'hanganalyze 3'
*** 2013-08-28 15:53:15.164
===============================================================================
HANG ANALYSIS:
instances (db_name.oracle_sid): cedb.cedb2
oradebug_node_dump_level: 3
analysis initiated by oradebug
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 15:53:14 ]
NOTE: scheduling delay has not been sampled for 0.294437 secs 0.000000 secs from [ 15:53:10 - 15:53:15 ], 5 sec avg
0.000000 secs from [ 15:52:15 - 15:53:15 ], 1 min avg
0.000000 secs from [ 15:48:15 - 15:53:15 ], 5 min avg
===============================================================================
Chains most likely to have caused the hang:
[a] Chain 1 Signature: 'log file parallel write'<='log file sync'
Chain 1 Signature Hash: 0x9a625f43
[b] Chain 2 Signature: 'log file parallel write'<='log file sync'
Chain 2 Signature Hash: 0x9a625f43
[c] Chain 3 Signature: 'log file parallel write'<='log file sync'
Chain 3 Signature Hash: 0x9a625f43
===============================================================================
Non-intersecting chains:
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 2 (cedb.cedb2)
os id: 10456
process id: 202, oracle@db42
session id: 595
session serial #: 44879
}
is waiting for 'log file sync' with wait info:
{
p1: 'buffer#'=0x6fa9
p2: 'sync scn'=0x6f01c17c
time in wait: 1.268483 sec
timeout after: never
wait id: 1777
blocking: 0 sessions
current sql: <none>
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwai
tctx()+163<-kcrf_commit_force()+972<-kcbdsy()+44<-ksupop()+1090<-opiodr()+1008<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o(
)+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+244<-_start()+36
wait history:
* time between current wait and wait #1: 0.000143 sec
1. event: 'SQL*Net message from client'
time waited: 0.001444 sec
wait id: 1776 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #1 and #2: 0.000012 sec
2. event: 'SQL*Net message to client'
time waited: 0.000002 sec
wait id: 1775 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000646 sec
3. event: 'SQL*Net message from client'
time waited: 0.000828 sec
wait id: 1774 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
}
and is blocked by
=> Oracle session identified by:
{
instance: 2 (cedb.cedb2)
os id: 11611
process id: 28, oracle@db42 (LGWR)
session id: 1653
session serial #: 1
}
which is waiting for 'log file parallel write' with wait info:
{
p1: 'files'=0x2
p2: 'blocks'=0x18
p3: 'requests'=0x2
time in wait: 2.999912 sec
timeout after: never
wait id: 309360511
blocking: 6 sessions
current sql: <none>
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-read()+16<-kfk_block()+940<-kfk_transit_waitIO()+188<-kf
k_transitIO()+1739<-kfioWaitIO()+721<-kfioRequestPriv()+351<-kfioRequest()+706<-ksfd_kfioRequest()+649<-ksfd_osmbio()+438<-ksfdbio()+1487<-kcrfw_do_write()+98
8<-kcrfw_redo_write()+3449<-ksbabs()+771<-ksbrdp()+971<-opirip()+623<-opidrv()+603<-sou2o()+103<-opimai_real()+266<-ssthrdmain()+252<-main()+201<-__libc_start
_main()+244<-_start()+36
wait history:
* time between current wait and wait #1: 0.000098 sec
1. event: 'LGWR wait for redo copy'
time waited: 0.000023 sec
wait id: 309360510 p1: 'copy latch #'=0x5
* time between wait #1 and #2: 0.000009 sec
2. event: 'rdbms ipc message'
time waited: 0.001294 sec
wait id: 309360509 p1: 'timeout'=0x13
* time between wait #2 and #3: 0.000040 sec
3. event: 'log file parallel write'
time waited: 0.000293 sec
wait id: 309360508 p1: 'files'=0x2
p2: 'blocks'=0x2
p3: 'requests'=0x2
}
Chain 1 Signature: 'log file parallel write'<='log file sync'
Chain 1 Signature Hash: 0x9a625f43
-------------------------------------------------------------------------------
===============================================================================
Intersecting chains:
-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 2 (cedb.cedb2)
os id: 12760
process id: 102, oracle@db42
session id: 2245
session serial #: 1577
}
is waiting for 'log file sync' with wait info:
{
p1: 'buffer#'=0x6f9d
p2: 'sync scn'=0x6f01b311
time in wait: 2.999925 sec
timeout after: never
wait id: 52573
blocking: 0 sessions
current sql: <none>
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwai
tctx()+163<-kcrf_commit_force()+972<-kcbdsy()+44<-ksupop()+1090<-opiodr()+1008<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o(
)+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+244<-_start()+36
wait history:
* time between current wait and wait #1: 0.000240 sec
1. event: 'SQL*Net message from client'
time waited: 0.000985 sec
wait id: 52572 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #1 and #2: 0.000014 sec
2. event: 'SQL*Net message to client'
time waited: 0.000002 sec
wait id: 52571 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000820 sec
3. event: 'SQL*Net message from client'
time waited: 0.000716 sec
wait id: 52570 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
}
and is blocked by 'instance: 2, os id: 11611, session id: 1653',
which is a member of 'Chain 1'.
Chain 2 Signature: 'log file parallel write'<='log file sync'
Chain 2 Signature Hash: 0x9a625f43
-------------------------------------------------------------------------------
-------------------------------------------------------------------------------
Chain 3:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 2 (cedb.cedb2)
os id: 12762
process id: 103, oracle@db42
session id: 2304
session serial #: 1077
}
is waiting for 'log file sync' with wait info:
{
p1: 'buffer#'=0x6fa9
p2: 'sync scn'=0x6f01b313
time in wait: 2.999726 sec
timeout after: never
wait id: 54709
blocking: 0 sessions
current sql: <none>
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwai
tctx()+163<-kcrf_commit_force()+972<-kcbdsy()+44<-ksupop()+1090<-opiodr()+1008<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o(
)+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+244<-_start()+36
wait history:
* time between current wait and wait #1: 0.000175 sec
1. event: 'SQL*Net message from client'
time waited: 0.000301 sec
wait id: 54708 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #1 and #2: 0.000033 sec
2. event: 'SQL*Net message to client'
time waited: 0.000003 sec
wait id: 54707 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000850 sec
3. event: 'SQL*Net message from client'
time waited: 0.001152 sec
wait id: 54706 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
}
and is blocked by 'instance: 2, os id: 11611, session id: 1653',
which is a member of 'Chain 1'.
Chain 3 Signature: 'log file parallel write'<='log file sync'
Chain 3 Signature Hash: 0x9a625f43
-------------------------------------------------------------------------------
-------------------------------------------------------------------------------
Chain 4:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 2 (cedb.cedb2)
os id: 12764
process id: 104, oracle@db42
session id: 2364
session serial #: 44511
}
is waiting for 'log file sync' with wait info:
{
p1: 'buffer#'=0x6fa9
p2: 'sync scn'=0x6f01b314
time in wait: 2.999371 sec
timeout after: never
wait id: 52571
blocking: 0 sessions
current sql: <none>
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwai
tctx()+163<-kcrf_commit_force()+972<-kcbdsy()+44<-ksupop()+1090<-opiodr()+1008<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o(
)+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+244<-_start()+36
wait history:
* time between current wait and wait #1: 0.000135 sec
1. event: 'SQL*Net message from client'
time waited: 0.000313 sec
wait id: 52570 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #1 and #2: 0.000017 sec
2. event: 'SQL*Net message to client'
time waited: 0.000002 sec
wait id: 52569 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000906 sec
3. event: 'SQL*Net message from client'
time waited: 0.000614 sec
wait id: 52568 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
}
and is blocked by 'instance: 2, os id: 11611, session id: 1653',
which is a member of 'Chain 1'.
Chain 4 Signature: 'log file parallel write'<='log file sync'
Chain 4 Signature Hash: 0x9a625f43
-------------------------------------------------------------------------------
-------------------------------------------------------------------------------
Chain 5:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 2 (cedb.cedb2)
os id: 12766
process id: 105, oracle@db42
session id: 2425
session serial #: 16133
}
is waiting for 'log file sync' with wait info:
{
p1: 'buffer#'=0x6fa9
p2: 'sync scn'=0x6f01b315
time in wait: 2.998936 sec
timeout after: never
wait id: 55819
blocking: 0 sessions
current sql: <none>
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwai
tctx()+163<-kcrf_commit_force()+972<-kcbdsy()+44<-ksupop()+1090<-opiodr()+1008<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o(
)+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+244<-_start()+36
wait history:
* time between current wait and wait #1: 0.000141 sec
1. event: 'SQL*Net message from client'
time waited: 0.000252 sec
wait id: 55818 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #1 and #2: 0.000013 sec
2. event: 'SQL*Net message to client'
time waited: 0.000002 sec
wait id: 55817 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000596 sec
3. event: 'SQL*Net message from client'
time waited: 0.000944 sec
wait id: 55816 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
}
and is blocked by 'instance: 2, os id: 11611, session id: 1653',
which is a member of 'Chain 1'.
Chain 5 Signature: 'log file parallel write'<='log file sync'
Chain 5 Signature Hash: 0x9a625f43
-------------------------------------------------------------------------------
-------------------------------------------------------------------------------
Chain 6:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 2 (cedb.cedb2)
os id: 22034
process id: 63, oracle@db42
session id: 3720
session serial #: 1513
}
is waiting for 'log file sync' with wait info:
{
p1: 'buffer#'=0x6fa9
p2: 'sync scn'=0x6f01b3c4
time in wait: 2.779358 sec
timeout after: never
wait id: 32770
blocking: 0 sessions
current sql: <none>
short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwai
tctx()+163<-kcrf_commit_force()+972<-kcbdsy()+44<-ksupop()+1090<-opiodr()+1008<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o(
)+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+244<-_start()+36
wait history:
* time between current wait and wait #1: 0.000208 sec
1. event: 'SQL*Net message from client'
time waited: 0.001506 sec
wait id: 32769 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #1 and #2: 0.000011 sec
2. event: 'SQL*Net message to client'
time waited: 0.000002 sec
wait id: 32768 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
* time between wait #2 and #3: 0.000845 sec
3. event: 'SQL*Net message from client'
time waited: 0.001030 sec
wait id: 32767 p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
}
and is blocked by 'instance: 2, os id: 11611, session id: 1653',
which is a member of 'Chain 1'.
Chain 6 Signature: 'log file parallel write'<='log file sync'
Chain 6 Signature Hash: 0x9a625f43
Combine the ash report that there are more tan 20000 commit operations.
[sql]
Call Type Count % Activity Avg Active
---------------------------------------- ---------- ---------- ----------
COMMIT 22,124 55.99 12.29
V8 Bundled Exec 10,652 26.96 5.92
OAUTH 2,249 5.69 1.25
LOGOFF 584 1.48 0.32
-------------------------------------------------------------
With the awr report top 5 event
[sql]
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
log file sync 269,309 33,931 126 75.7 Commit
log buffer space 104 5,424 52157 12.1 Configurat
buffer busy waits 2,593 3,580 1381 8.0 Concurrenc
log file switch completion 24 892 37155 2.0 Configurat
DB CPU 888 2.0
^LHost CPU (CPUs: 64 Cores: 32 Sockets: 4)
The log file sync wait event which average wait time is 126ms is percent 75.7 of DB time. In order to reduce this wait event, it should modify the application software to reduce commit operation.
本站文章为和通数据库网友分享或者投稿，欢迎任何形式的转载，但请务必注明出处.
同时文章内容如有侵犯了您的权益，请联系QQ：970679559，我们会在尽快处理。