Log file sync caused by more commit

Today, our db changes slow suddenly.

And i do a hanganalyze as following:

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. 

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 

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.

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值