ORA-29770: global enqueue process LMS0 (OSID 11912) is hung for more than 70 seconds (Doc ID 2217764.1)

Incremental checkpoint up to RBA [0xd5e.e130a.0], current log tail at RBA [0xd5e.119c55.0]
Wed Dec 21 17:09:47 2016
Incremental checkpoint up to RBA [0xd5e.12372b.0], current log tail at RBA [0xd5e.124630.0]
Wed Dec 21 17:13:33 2016
LMS0 (ospid: 11912) has not called a wait for 11 secs.
LMS1 (ospid: 11915) has not called a wait for sub 0 secs.
LMS2 (ospid: 11918) has not called a wait for sub 0 secs.
Errors in file /oracle/ORCL/saptrace/diag/rdbms/orcl/ORCL1/trace/ORCL1_lmhb_11922.trc (incident=115345):
ORA-29770: global enqueue process LMS0 (OSID 11912) is hung for more than 70 seconds
Incident details in: /oracle/ORCL/saptrace/diag/rdbms/orcl/ORCL1/incident/incdir_115345/ORCL1_lmhb_11922_i115345.trc
Wed Dec 21 17:13:44 2016
Errors in file /oracle/ORCL/saptrace/diag/rdbms/orcl/ORCL1/trace/ORCL1_lmhb_11922.trc (incident=115346):
ORA-29770: global enqueue process LMS1 (OSID 11915) is hung for more than 70 seconds
Incident details in: /oracle/ORCL/saptrace/diag/rdbms/orcl/ORCL1/incident/incdir_115346/ORCL1_lmhb_11922_i115346.trc
Wed Dec 21 17:13:46 2016
Sweep [inc][115346]: completed
Sweep [inc][115345]: completed
Sweep [inc2][115345]: completed
Errors in file /oracle/ORCL/saptrace/diag/rdbms/orcl/ORCL1/trace/ORCL1_lmhb_11922.trc (incident=115347):
ORA-29770: global enqueue process LMS2 (OSID 11918) is hung for more than 70 seconds
Incident details in: /oracle/ORCL/saptrace/diag/rdbms/orcl/ORCL1/incident/incdir_115347/ORCL1_lmhb_11922_i115347.trc
ERROR: Some process(s) is not making progress.
LMHB (ospid: 11922) is terminating the instance.
Please check LMHB trace file for more details.
Please also check the CPU load, I/O load and other system properties for anomalous behavior
ERROR: Some process(s) is not making progress.
LMHB (ospid: 11922): terminating the instance due to error 29770

*** 2016-12-21 17:12:37.997
MP normal (0x380013268): type 0x1 bufsz 1240
MP: #mbuf outstanding from sharedpool 156871 initq 3130
MP: #mbuf cur 160001 init 3130 max 160001
outq : 0:2 7:5 8:22 12:35 16:12 25:1 32:45 34:159819
outq : 36:16 44:2 56:1 73:41

*** 2016-12-21 17:13:34.479
Received ORADEBUG command (#12) 'dump KSTDUMPCURPROC 1' from process 'Unix process pid: 11922, image: <none>'

Begin DRM(2837) (swin 1)
READMOSTLY object id 427944007.0, objscan 1.1, dissolve affinity from instance 1
Total pkey count in this drm 1
* drm quiesce

*** 2016-12-21 17:11:58.917
* kjbrdrmcvtq: time limit 3000 exceeded (429769873->429772873), rhtbucket = 1586250, idx 1586250, rescount 4794052

*** 2016-12-21 17:12:02.000
* kjbrdrmcvtq: time limit 3000 exceeded (429772884->429775884), rhtbucket = 3161282, idx 3161282, rescount 4761214

*** 2016-12-21 17:12:04.014
2016-12-21 17:12:04.014117 : DRM(2837) resources quiesced [0-4194303], rescount 3124804
2016-12-21 17:12:04.014527 : DRM(2837) local converts quiesced [0-4194303], lockcount 1, bucket 171
* kjbrdrmcvtq: lms 0 not yet quiesced
* kjbrdrmcvtq: lms 1 not yet quiesced
* kjbrdrmcvtq: lms 2 not yet quiesced

....

*** 2016-12-21 17:13:34.087
* kjbrdrmcvtq: lms 0 not yet quiesced
* kjbrdrmcvtq: lms 1 not yet quiesced
* kjbrdrmcvtq: lms 2 not yet quiesced

*** 2016-12-21 17:12:31.165
==============================
LMS0 (ospid: 11912) has not moved for 36 sec (1482315150.1482315114)
kjfmGCR_HBCheckAll: LMS0 (ospid: 11912) has status 2
: Not in wait; last wait ended 0 secs ago.
: last wait_id 531815021 at 'latch free'.
==============================
Dumping PROCESS LMS0 (ospid: 11912) States
==============================
===[ Callstack ]===

*** 2016-12-21 17:12:31.165
Process diagnostic dump for oracle@ptm-dbcln0201 (LMS0), OS id=11912,
pid: 14, proc_ser: 1, sid: 799, sess_ser: 1
-------------------------------------------------------------------------------
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 17:12:30 ]
NOTE: scheduling delay has not been sampled for 0.306420 secs 0.000000 secs from [ 17:12:26 - 17:12:31 ], 5 sec avg
0.000000 secs from [ 17:11:31 - 17:12:31 ], 1 min avg
0.000000 secs from [ 17:07:31 - 17:12:31 ], 5 min avg

*** 2016-12-21 17:12:32.200
loadavg : 3.23 2.56 2.46
swap info: free_mem = 288727.60M rsv = 324706.37M
alloc = 323772.84M avail = 365385.22M swap_free = 366318.74M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
0 O oracle 11912 11890 2 39 0 ? 40193507 Oct 16 ? 975:20 ora_lms0_ORCL1
Short stack dump:
ksedsts()+380<-ksdxfstk()+52<-ksdxcb()+3592<-sspuser()+140<-__sighndlr()+12<-call_user_handler()+868<-sigacthandler()+92<-kclclose()+6460<-kclcontext()+456<-kclobj()+12084<-kclaoliter()+184<-kjblpkeydrmqscchk()+2496<-kjmdrmchk()+2596<-kjmsm()+3436<-ksbrdp()+1720<-opirip()+1680<-opidrv()+748<-sou2o()+88<-opimai_real()+512<-ssthrdmain()+324<-main()+316<-_start()+380

-------------------------------------------------------------------------------
Process diagnostic dump actual duration=1.040000 sec
(max dump time=5.000000 sec)

*** 2016-12-21 17:12:32.205

*** 2016-12-21 17:12:32.205
==============================
LMS1 (ospid: 11915) has not moved for 37 sec (1482315151.1482315114)
kjfmGCR_HBCheckAll: LMS1 (ospid: 11915) has status 2
: Not in wait; last wait ended 0 secs ago.
: last wait_id 647523037 at 'latch free'.
==============================
Dumping PROCESS LMS1 (ospid: 11915) States
==============================
===[ Callstack ]===

*** 2016-12-21 17:12:32.206
Process diagnostic dump for oracle@ptm-dbcln0201 (LMS1), OS id=11915,
pid: 15, proc_ser: 1, sid: 857, sess_ser: 1
-------------------------------------------------------------------------------
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 17:12:31 ]
NOTE: scheduling delay has not been sampled for 0.342900 secs 0.000000 secs from [ 17:12:27 - 17:12:32 ], 5 sec avg
0.000000 secs from [ 17:11:32 - 17:12:32 ], 1 min avg
0.000000 secs from [ 17:07:32 - 17:12:32 ], 5 min avg

*** 2016-12-21 17:12:33.811
loadavg : 3.24 2.56 2.46
swap info: free_mem = 288727.67M rsv = 324706.37M
alloc = 323756.34M avail = 365385.22M swap_free = 366335.24M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
0 O oracle 11915 11890 2 39 0 ? 40192483 Oct 16 ? 1198:56 ora_lms1_ORCL1
11915: ora_lms1_ORCL1
ffffffff7d54e50c yield (10dbd4000, 4ea1cf92b0, 0, 10d800, 4e9c5f7d10, 4ea1cf9280) + 8
000000010400a6b0 kclzcli (2bfff581c8, 4e9c5f7d10, 7000, 1, 21, 380012) + 150
0000000103f6dd54 kclclose (1, 1981e847, 0, 10dbd4d60, 0, 1) + e34
0000000103f6f048 kclcontext (38001f, 960, 0, 380000, 4b000, 960) + 1c8
0000000103f73f74 kclobj (0, ffffff, 380018098, 4ebdf888e8, 41, 100000001) + 2f34
0000000103f78678 kclaoliter (0, 1981e847, 5002eacf04, 1, 1, 0) + b8
0000000103ae0b80 kjblpkeydrmqscchk (1, 2199dc491, 5002ead720, 5002eae768, 0, 0) + 9c0
00000001038d9c44 kjmdrmchk (380014, ffffffff7fffcf74, ffffffff7fffcf70, 380000, 57a13b, 5002ead728) + a24
00000001038d43ac kjmsm (380013, 0, 0, 0, 866771247df, ffffffff7c0226b8) + d6c
0000000108890d78 ksbrdp (1, 1768, 380017000, 380014ec8, 100fdb9a8, 380000) + 6b8
0000000109233e70 opirip (4d28, 10dbd09e0, 1020b2, 38000a2e8, 10dbf7000, 10dbf7000) + 690
0000000105f78e2c opidrv (10dbd4000, 0, 10dbf2c78, 32, 0, ffffffff7fffe4e0) + 2ec
00000001071fad38 sou2o (ffffffff7fffe4b8, 32, 4, ffffffff7fffe4e0, 10dbf77e0, 10d800) + 58
0000000102580640 opimai_real (ffffffff7fffec70, ffffffff7fffec19, ffffffff7dc01070, ffffffff7dc01070, 0, ffffffff7fffe458) + 200
00000001072148c4 ssthrdmain (10dc00, 10dc03, 10dc03000, 3, 10dc03, 10ddbbd60) + 144
000000010258041c main (3, 2, 0, ffffffff7fffe770, ffffffff7fffe880, 2800) + 13c
00000001025802bc _start (0, 0, 0, 0, 0, 0) + 17c
Short stack dump:
ksedsts()+380<-ksdxfstk()+52<-ksdxcb()+3592<-sspuser()+140<-__sighndlr()+12<-call_user_handler()+868<-sigacthandler()+92<-kclclose()+6460<-kclcontext()+456<-kclobj()+12084<-kclaoliter()+184<-kjblpkeydrmqscchk()+2496<-kjmdrmchk()+2596<-kjmsm()+3436<-ksbrdp()+1720<-opirip()+1680<-opidrv()+748<-sou2o()+88<-opimai_real()+512<-ssthrdmain()+324<-main()+316<-_start()+380

-------------------------------------------------------------------------------
Process diagnostic dump actual duration=1.611000 sec
(max dump time=5.000000 sec)

*** 2016-12-21 17:12:33.817

*** 2016-12-21 17:12:33.817
==============================
LMS2 (ospid: 11918) has not moved for 39 sec (1482315153.1482315114)
kjfmGCR_HBCheckAll: LMS2 (ospid: 11918) has status 2
: Not in wait; last wait ended 0 secs ago.
: last wait_id 545791842 at 'latch free'.
==============================
Dumping PROCESS LMS2 (ospid: 11918) States
==============================
===[ Callstack ]===

*** 2016-12-21 17:12:33.817
Process diagnostic dump for oracle@ptm-dbcln0201 (LMS2), OS id=11918,
pid: 16, proc_ser: 1, sid: 913, sess_ser: 1
-------------------------------------------------------------------------------
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 17:12:32 ]
NOTE: scheduling delay has not been sampled for 0.949924 secs 0.000000 secs from [ 17:12:28 - 17:12:33 ], 5 sec avg
0.000000 secs from [ 17:11:34 - 17:12:33 ], 1 min avg
0.000000 secs from [ 17:07:34 - 17:12:33 ], 5 min avg

*** 2016-12-21 17:12:35.728
loadavg : 3.26 2.57 2.46
swap info: free_mem = 288719.77M rsv = 324706.37M
alloc = 323756.34M avail = 365385.22M swap_free = 366335.24M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
0 O oracle 11918 11890 2 39 0 ? 40192555 Oct 16 ? 1006:11 ora_lms2_ORCL1
11918: ora_lms2_ORCL1
ffffffff7d54e9f0 _syscall6 (ffffffff7fffb878, 10dbd4de8, 4ea1cf9600, 0, 3800ffaa8, 200003f) + 20
000000010268c500 ksl_check_lwaiter (4ea1cf9128, 1, 1, 4ea1cf9128, 3800132a0, 4ea1cf9280) + a0
0000000102692090 kslfre (0, 38000b000, 4ea1cf9128, 585a5593, 3800132a0, 4e81d2ef18) + 3d0
00000001038013a8 kjcsmpav (1, 380013268, 4e62446840, 380013290, 4e62446828, 4e62446868) + 1a48
0000000103805918 kjcsmba (1, 4e62446828, 380013268, 1, 0, c8) + 578
00000001037f4f00 kjccgmb (1, 10dbde, 101843, 10dbde000, 10dbd04d0, 380013268) + 120
00000001039bfd1c kjbclose (4e624463c8, 10dbde000, 0, 1c1fd7faa0, 80, 10dbd09e0) + a9c
000000010400a8b4 kclzcli (1c1fd7fa28, 4e9c5f8a50, f, 0, 0, 0) + 354
0000000103f6dd54 kclclose (1, 1981e847, 0, 10dbd4d60, 0, 1) + e34
0000000103f6f048 kclcontext (38001f, 960, 0, 380000, 4b000, 960) + 1c8
0000000103f73f74 kclobj (0, ffffff, 380018098, 4ebdf888e8, 42, 100000001) + 2f34
0000000103f78678 kclaoliter (0, 1981e847, 4ee27bb1a4, 1, 1, 0) + b8
0000000103ae0b80 kjblpkeydrmqscchk (1, 2199dc491, 4ee27bb9c0, 4ee27bca08, 0, 0) + 9c0
00000001038d9c44 kjmdrmchk (380014, ffffffff7fffd144, ffffffff7fffd140, 380000, 57a13b, 4ee27bb9c8) + a24
00000001038d43ac kjmsm (380013, 0, 0, 0, 866771247df, ffffffff7c0226b8) + d6c
0000000108890d78 ksbrdp (1, 1768, 380017000, 380014f20, 100fdb9d0, 380000) + 6b8
0000000109233e70 opirip (4d28, 10dbd09e0, 1020b2, 38000a2e8, 10dbf7000, 10dbf7000) + 690
0000000105f78e2c opidrv (10dbd4000, 0, 10dbf2c78, 32, 0, ffffffff7fffe6b0) + 2ec
00000001071fad38 sou2o (ffffffff7fffe688, 32, 4, ffffffff7fffe6b0, 10dbf77e0, 10d800) + 58
0000000102580640 opimai_real (ffffffff7fffee33, ffffffff7fffeddb, ffffffff7dc01070, ffffffff7dc01070, 0, ffffffff7fffe628) + 200
00000001072148c4 ssthrdmain (10dc00, 10dc03, 10dc03000, 3, 10dc03, 10ddbbd60) + 144
000000010258041c main (3, 2, 0, ffffffff7fffe940, ffffffff7fffea50, 2800) + 13c
00000001025802bc _start (0, 0, 0, 0, 0, 0) + 17c
Short stack dump:
ksedsts()+380<-ksdxfstk()+52<-ksdxcb()+3592<-sspuser()+140<-__sighndlr()+12<-call_user_handler()+868<-sigacthandler()+92<-kclclose()+6460<-kclcontext()+456<-kclobj()+12084<-kclaoliter()+184<-kjblpkeydrmqscchk()+2496<-kjmdrmchk()+2596<-kjmsm()+3436<-ksbrdp()+1720<-opirip()+1680<-opidrv()+748<-sou2o()+88<-opimai_real()+512<-ssthrdmain()+324<-main()+316<-_start()+380

-------------------------------------------------------------------------------
Process diagnostic dump actual duration=1.917000 sec
(max dump time=5.000000 sec)

*** 2016-12-21 17:12:35.734
kjgcr_SlaveReqBegin: message queued to slave
kjgcr_Main: KJGCR_ACTION - id 3
CPU is high. Top oracle users listed below:
Session Serial CPU
865 38067 0
1211 56827 0
1091 31527 0
1544 21611 0
744 48721 0

*** 2016-12-21 17:12:40.815
kjgcr_Main: Reset called for action high cpu, identify users, count 0

*** 2016-12-21 17:12:40.815
kjgcr_Main: Reset called for action high cpu, kill users, count 0

*** 2016-12-21 17:12:40.816
kjgcr_Main: Reset called for action high cpu, activate RM plan, count 0

*** 2016-12-21 17:12:40.816
kjgcr_Main: Reset called for action high cpu, set BG into RT, count 0

*** 2016-12-21 17:12:50.816
==============================
LMS0 (ospid: 11912) has not moved for 56 sec (1482315170.1482315114)
kjfmGCR_HBCheckAll: LMS0 (ospid: 11912) has status 2
: Not in wait; last wait ended 0 secs ago.
: last wait_id 531815474 at 'latch free'.
==============================
Dumping PROCESS LMS0 (ospid: 11912) States
==============================
===[ Callstack ]===

*** 2016-12-21 17:12:50.817
Process diagnostic dump for oracle@<hostname> (LMS0), OS id=11912,
pid: 14, proc_ser: 1, sid: 799, sess_ser: 1
-------------------------------------------------------------------------------
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 17:12:49 ]
NOTE: scheduling delay has not been sampled for 0.880220 secs 0.000000 secs from [ 17:12:45 - 17:12:50 ], 5 sec avg
0.000000 secs from [ 17:11:51 - 17:12:50 ], 1 min avg
0.000000 secs from [ 17:07:51 - 17:12:50 ], 5 min avg

*** 2016-12-21 17:12:52.517
loadavg : 3.47 2.66 2.50
swap info: free_mem = 288703.91M rsv = 324738.99M
alloc = 323785.22M avail = 365352.59M swap_free = 366306.37M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
0 O oracle 11912 11890 2 39 0 ? 40193507 Oct 16 ? 975:39 ora_lms0_ORCL1
11912: ora_lms0_ORCL1
ffffffff7d54e9f0 _syscall6 (ffffffff7fffb6c8, 10dbd4de8, 4e81d2f298, 0, 3800ffaa8, 200003f) + 20
000000010268c500 ksl_check_lwaiter (4e81d2edc0, 1, 1, 4e81d2edc0, 3800132a0, 4e81d2ef18) + a0
0000000102692090 kslfre (0, 38000b000, 4e81d2edc0, 585a55a4, 3800132a0, 4ec1cfbe38) + 3d0
00000001038013a8 kjcsmpav (1, 380013268, 4e62445c60, 380013290, 4e62445c48, 4e62445c88) + 1a48
0000000103805918 kjcsmba (1, 4e62445c48, 380013268, 1, 0, c8) + 578
00000001037f4f00 kjccgmb (1, 10dbde, 101843, 10dbde000, 10dbd04d0, 380013268) + 120
00000001039bfd1c kjbclose (4e624457e8, 10dbde000, 0, 2fbf1fd670, 80, 10dbd09e0) + a9c
000000010400a8b4 kclzcli (2fbf1fd5f8, 4e9c5f7178, 2, 0, 0, 0) + 354
0000000103f6dd54 kclclose (1, 1981e847, 0, 10dbd4d60, 0, 1) + e34
0000000103f6f048 kclcontext (38001f, 960, 0, 380000, 4b000, 960) + 1c8
0000000103f73f74 kclobj (0, ffffff, 380018098, 380018090, 40, 100000001) + 2f34
0000000103f78678 kclaoliter (0, 1981e847, 4f02a1331c, 1, 1, 0) + b8
0000000103ae0b80 kjblpkeydrmqscchk (1, 2199dc491, 4f02a13b38, 4f02a14b80, 0, 0) + 9c0
00000001038d9c44 kjmdrmchk (380014, ffffffff7fffcf94, ffffffff7fffcf90, 380000, 57a13b, 4f02a13b40) + a24
00000001038d43ac kjmsm (380013, 0, 0, 0, 866771247df, ffffffff7c0226b8) + d6c
0000000108890d78 ksbrdp (1, 1768, 380017000, 380014e70, 100fdb980, 380000) + 6b8
0000000109233e70 opirip (4d28, 10dbd09e0, 1020b2, 38000a2e8, 10dbf7000, 10dbf7000) + 690
0000000105f78e2c opidrv (10dbd4000, 0, 10dbf2c78, 32, 0, ffffffff7fffe500) + 2ec
00000001071fad38 sou2o (ffffffff7fffe4d8, 32, 4, ffffffff7fffe500, 10dbf77e0, 10d800) + 58
0000000102580640 opimai_real (ffffffff7fffec90, ffffffff7fffec39, ffffffff7dc01070, ffffffff7dc01070, 0, ffffffff7fffe478) + 200
00000001072148c4 ssthrdmain (10dc00, 10dc03, 10dc03000, 3, 10dc03, 10ddbbd60) + 144
000000010258041c main (3, 2, 0, ffffffff7fffe790, ffffffff7fffe8a0, 2800) + 13c
00000001025802bc _start (0, 0, 0, 0, 0, 0) + 17c
Short stack dump:
ksedsts()+380<-ksdxfstk()+52<-ksdxcb()+3592<-sspuser()+140<-__sighndlr()+12<-call_user_handler()+868<-sigacthandler()+92<-kjutot()+12<-kclclose()+3484<-kclcontext()+456<-kclobj()+12084<-kclaoliter()+184<-kjblpkeydrmqscchk()+2496<-kjmdrmchk()+2596<-kjmsm()+3436<-ksbrdp()+1720<-opirip()+1680<-opidrv()+748<-sou2o()+88<-opimai_real()+512<-ssthrdmain()+324<-main()+316<-_start()+380

-------------------------------------------------------------------------------
Process diagnostic dump actual duration=1.706000 sec
(max dump time=5.000000 sec)