This is a case of a client that was processed 1 months ago, which is roughly the first time a certain RAC node instance was restarted, with alert log we can find that the node 2 instance of the RAC cluster has been forcibly terminated, as follows the detailed alert logging information:
Mon Sep 28 02:00:00 2015
Errors in FILE/ORACLE/ADMIN/XXX/BDXXX/XXX2_J000_7604.TRC:
Ora-12012:error on auto execute of Job 171538
Ora-06550:line ora-06550:line 4, column 3:
Pls-00905:object XSQD. E_sp_dl_crm_terminal_manager is invalid
Ora-06550:line 4, Column 3:
Pl/sql:statement ignored
, column:
Mon Sep 28 02:03:18 2015
Errors in FILE/ORACLE/ADMIN/XXX/UDXXX/XXX2_ORA_6810.TRC:
Ora-00600:internal error code, arguments: [KGHLKREM1], [0x679000020], [], [], [], [], [], []
。。。。。
Trace dxxxing is performing id=[cdmp_20150928023925]
Mon Sep 28 02:39:32 2015
Errors in FILE/ORACLE/ADMIN/XXX/BDXXX/XXX2_LMD0_24228.TRC:
Ora-00600:internal error code, arguments: [KGHLKREM1], [0x679000020], [], [], [], [], [], []
Mon Sep 28 02:39:32 2015
Lmd0:terminating instance due to error 482
Mon Sep 28 02:39:33 2015
Shutting down instance (abort)
License High Water mark = 145
Mon Sep 28 02:39:37 2015
Instance terminated by LMD0, PID = 24228
Mon Sep 28 02:39:38 2015
From the above log, at 2:03 in the beginning of the error ORA-00600, continued until 2:39, lmd0 process began to report the same error, and then the LMD0 process forced the database instance terminated. Direct search of Oracle MOS looks a bit like this bug, but it's easy to rule out.
Bug 14193240:lms signaled ora-600[kghlkrem1] DURING beehive LOAD
From the log, 2:03 points on the start of the error, however, until the lmd0 error, the instance was terminated, that is to say lmd0 error is the key to the problem. So let's first analyze the contents of the trace file for the next lmd0 process, as follows:
2015-09-28 02:39:24.291
Internal heap ERROR KGHLKREM1 addr=0x679000020 ds=0x60000058 * * * *
Dxxx of memory around addr 0x679000020:
678fff020 00000000 00000000 00000000 00000000 [...]......
Repeat 255 Times
679000020 60001990 00000000 00000000 00000000 [...]......
679000030 00000000 00000000 00000000 00000000 [...]......
Repeat 254 Times
Recovery state:ds=0x60000058 rtn= (nil) *rtn= (nil) szo=0 u4o=0 hdo=0 off=0
Szo:
UB4O:
Hdo:
OFF:
hla:0
******************************************************
HEAP dxxx HEAP name= "SGA HEAP" desc=0x60000058
Extent sz=0x47c0 alt=216 het=32767 rec=9 flg=-126
Parent= (nil) owner= (nil) nex= Nil (xsz=0x0)
DS for latch 1:0x60042f70 0x600447c8 0x60046020 0x60047878
。。。。。
Ksedmp:internal or fatal error
Ora-00600:internal error code, arguments: [KGHLKREM1], [0x679000020], [], [], [], [], [], []
-----Call Stack Trace-----
Calling call entry argument values in hex
Location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
KSEDST () +31 call Ksedst1 () 000000000? 000000001?
7fff41d71f90? 7fff41d71ff0?
7fff41d71f30? 000000000?
KSEDMP () +610 call KSEDST () 000000000? 000000001?
7fff41d71f90? 7fff41d71ff0?
7fff41d71f30? 000000000?
KSFDMP () +21 call Ksedmp () 000000003? 000000001?
7fff41d71f90? 7fff41d71ff0?
7fff41d71f30? 000000000?
KGERINV () +161 call Ksfdmp () 000000003? 000000001?
7fff41d71f90? 7fff41d71ff0?
7fff41d71f30? 000000000?
KGESINV () +33 call KGERINV () 0068966E0? 2af92650e2c0?
7fff41d71ff0? 7fff41d71f30?
000000000? 000000000?
Kgesin () +143 call KGESINV () 0068966E0? 2af92650e2c0?
7fff41d71ff0? 7fff41d71f30?
000000000? 000000000?
Kghnerror () +342 call Kgesin () 0068966E0? 2af92650e2c0?
7fff41d71ff0? 7fff41d71f30?
000000002? 679000020?
Kghadd_reserved_ext call Kghnerror () 0068966E0? 060000058?
ENT () +1039 005ae1c14? 679000020?
000000002? 679000020?
Kghget_reserved_ext Call Kghadd_reserved_ext 0068966E0? 060000058?
ENT () +250 ent () 060042f70? 060042fb8?
000000000? 000000000?
Kghgex () +1622 call Kghget_reserved_ext 0068966E0? 060003b98?
ENT () 060042f70? 000000b10?
000000000? 000000000?
KGHFND () +660 call Kghgex () 0068966E0? 060003b98?
060042f70? 000002000?
000000ac8? 06000d600?
Kghprmalo () +274 call KGHFND () 0068966E0? 060003b98?
060042f70? 000000ab8?
000000ab8? 06000d600?
Kghalo () +3701 call Kghprmalo () 0068966E0? 060003b98?
060042f70? 000000a98?
000000a98? 7fff41d73128?
Ksmdacnk () +297 call Kghalo () 000000000? 060042f70?
000000a98? 07FFFFFFF?
000000a98? 000000a98?
Ksmdget () +958 call Ksmdacnk () 7df4e4aa0? 7adff43f0?
00533a060? 7d5278548?
2af900000000? 000000a98?
KSSADPM () +366 call Ksmdget () 7df4e4aa0? 000000000?
00533a060? 7d5278518?
7d5278548? 000000a98?
Kjlalc () +900 call KSSADPM () 000000000? 000000000?
7d647db78? 000000000?
7d54df5b8? 000000a98?
KJXNRL () +110 call Kjlalc () 7d5507080? 000000020?
7d54df480? 000000000?
7d54df5b8? 000000a98?
KJXOCDR () +301 call KJXNRL () 000000060? 000000020?
2af926a352b0? 7fff41d736c0?
7fff41d736c8? 7fff41d736d0?
KJMXMPM () +508 call KJXOCDR () 2af926a35280? 000000020?
2af926a352b0? 7fff41d736c0?
7fff41d736c8? 7fff41d736d0?
Kjmpmsgi () +1609 call KJMXMPM () 2af926a35280? 000000000?
06cf6f439? 000000000?
7fff41d736c8? 7fff41d736d0?
KJMDM () +7458 call Kjmpmsgi () 2af926a35280? 000000001?
000000001? 000000000?
000000000? 000000000?
KSBRDP () +794 call KJMDM () 06000d708? 000000001?
000000001? 7d380fcf0?
000000001? 7d380fd00?
Opirip () +616 call KSBRDP () 06000d708? 000000001?
000000001? 06000d708?
000000001? 7d380fd00?
Opidrv () +582 call Opirip () 000000032? 000000004?
7fff41d74f08? 06000d708?
000000001? 7d380fd00?
SOU2O () +114 call Opidrv () 000000032? 000000004?
7fff41d74f08? 06000d708?
000000001? 7d380fd00?
Opimai_real () +317 call SOU2O () 7fff41d74ee0? 000000032?
000000004? 7fff41d74f08?
000000001? 7d380fd00?
Main () +116 call Opimai_real () 000000003? 7fff41d74f70?
000000004? 7fff41d74f08?
000000001? 7d380fd00?
__libc_start_main () call main () 000000003? 7fff41d74f70?
+244 000000004? 7fff41d74f08?
000000001? 7d380fd00?
_start () +41 call __libc_start_main () 000723078? 000000001?
7fff41d750c8? 000000000?
000000001? 000000003?
From the above information, it is true that there are errors in heap. According to the description of the Oracle MOS document ORA-600 [KGHLKREM1] on Linux Using Parameter drop_cache on Hugepages Configuration (1070812.1), this failure and documentation The description is basically consistent as follows:
Internal heap ERROR KGHLKREM1 addr=0x679000020 ds=0x60000058 * * * *
Dxxx of memory around addr 0x679000020:
678fff020 00000000 00000000 00000000 00000000 [...]......
Repeat 255 Times
679000020 60001990 00000000 00000000 00000000 [...]......
679000030 00000000 00000000 00000000 00000000 [...]......
Repeat 254 Times
The content after address [0x679000020] is also 0, as is the document description, and second, the article mentions the use of the Linux memory release mechanism and the simultaneous activation of the hugepage configuration.
This should be a Linux bug, according to the document description. By checking the 2-node configuration, we found that the configuration of Node 2 is really different:
--Node 1
[Oracle@xxx-ds01 ~]$ Cat/proc/sys/vm/drop_caches
0
[Oracle@xxx-ds01 ~]$
--Node 2
[Oracle@xxx-ds02 ~]$
[Oracle@xxx-ds02 ~]$ Cat/proc/sys/vm/drop_caches
When Drop_caches is set to 3, it triggers the Linux memory cleanup recovery mechanism, which may cause memory errors; However, we checked that the configuration discovery did not change:
ORACLE@XXX-DS02 bdxxx]$ cat/etc/sysctl.conf
# Kernel sysctl configuration file for Red Hat Linux
#
# for binary values, 0 are disabled, 1 is enabled. Sysctl (8) and
# sysctl.conf (5) for more details.
# Controls IP Packet forwarding
Net.ipv4.ip_forward = 0
# Controls Source Route Verification
Net.ipv4.conf.default.rp_filter = 1
# does not accept source routing
Net.ipv4.conf.default.accept_source_route = 0
# Controls The System Request debugging functionality of the kernel
KERNEL.SYSRQ = 0
# Controls Whether core Dxxxs'll append the PID to the core filename
# Useful for debugging multi-threaded applications
Kernel.core_uses_pid = 1
# Controls The use of TCP syncookies
Net.ipv4.tcp_syncookies = 1
# Controls The maximum size of a message, in bytes
KERNEL.MSGMNB = 65536
# Controls The default maxmimum size of a mesage queue
Kernel.msgmax = 65536
# Controls The maximum shared segment size, in bytes
Kernel.shmmax = 68719476736
# Controls The maximum number of shared memory segments, in pages
Kernel.shmall = 4294967296
Kernel.shmmni = 4096
Kernel.sem = 250 32000 100 128
Fs.file-max = 65536
Net.ipv4.ip_local_port_range = 1024 65000
Net.core.rmem_default = 1048576
Net.core.rmem_max = 1048576
Net.core.wmem_default = 262144
Net.core.wmem_max = 262144
vm.nr_hugepages=15800
So, I think it was before the Echo 3 >/proc/sys/vm/drop_caches operation was done to force the release of memory. The analysis found that only the actions recorded in the last few minutes are visible, as follows:
[Root@xxx-ds02 ~]# History|grep Echo
2015-09-29 16:12:42 root echo 3 >/proc/sys/vm/drop_caches
2015-09-29 16:12:42 root echo 0 >/proc/sys/vm/drop_caches
2015-09-29 16:12:42 root echo 3 >/proc/sys/vm/drop_caches
2015-09-29 16:12:42 root echo 0 >/proc/sys/vm/drop_caches
311 2015-09-29 16:12:42 root echo 3 >/proc/sys/vm/drop_caches
329 2015-09-29 16:12:42 root echo 0 >/proc/sys/vm/drop_caches
1001 2015-09-29 16:12:49 Root History|grep Echo
1005 2015-09-29 16:14:55 Root history|grep Echo
Look at the operation Records do find the operation, then I check the operating system log also found some clues, as follows:
Sep 00:00:12 xxx-ds02 kernel: <span style= "color: #ff0000;" >bug:soft lockup-cpu#1 stuck for 10s! [Rel_mem.sh:13887</span>]
Sep 00:00:12 xxx-ds02 kernel:cpu 1:
Sep 00:00:12 xxx-ds02 kernel:modules linked In:hangcheck_timer autofs4 HIDP ocfs2 (U) rfcomm l2cap bluetooth OCFS2_DLM FS (U) ocfs2_dlm (u) ocfs2_nodemanager (u) configfs lockd sunrpc bonding dm_round_robin dm_multipath SCSI_DH video backlight SBS Power_meter Hwmon i2c_ec i2c_core dell_wmi WMI button battery asus_acpi acpi_memhotplug ac ipv6 xfrm_nalgo Crypto_api PARPORT_PC LP Parport Joydev sg PCSPKR bnx2 (U) dm_raid45 dm_message dm_region_hash dm_mem_cache dm_snapshot Dm_zero Rror dm_log dm_mod usb_storage lpfc scsi_transport_fc shpchp mpt2sas scsi_transport_sas sd_mod scsi_mod ext3 jbd UHCI_HCD OHCI_HCD EHCI_HCD
Sep 00:00:12 xxx-ds02 kernel:pid:13887, comm:rel_mem.sh tainted:g 2.6.18-194.el5 #1
Sep 00:00:12 xxx-ds02 kernel:rip:0010:[<ffffffff800cb229>] [<ffffffff800cb229>] __invalidate_mapping_ pages+0xf3/0x183
Sep 00:00:12 xxx-ds02 kernel:rsp:0018:ffff8112f5f71da8 eflags:00000207
Sep 00:00:12 xxx-ds02 kernel:rax:00000000ffffff94 rbx:000000000000bc83 rcx:0000000000000024
Sep 00:00:12 xxx-ds02 kernel:RDX:ffff81088008746c rsi:0000000000000002 rdi:ffff81108c8e2df8
Sep 00:00:12 xxx-ds02 kernel:rbp:00000000000000d0 r08:ffff810880087503 r09:ffff811080001600
Sep 00:00:12 xxx-ds02 kernel:r10:000000000000bc83 r11:ffffffff8858ea45 r12:ffff81108c8e2df8
Sep 00:00:12 xxx-ds02 kernel:r13:0000000000000001 r14:ffff811e35bad6b0 r15:ffff811411a641f0
Sep 00:00:12 xxx-ds02 kernel:fs:00002af83adf5dd0 (0000) gs:ffff8108800877c0 0000 (knlgs:0000000000000000)
Sep 00:00:12 xxx-ds02 kernel:cs:0010 ds:0000 es:0000 cr0:000000008005003b
Sep 00:00:12 xxx-ds02 kernel:cr2:00002ad3e3ae1f90 cr3:000000120a831000 cr4:00000000000006e0
Sep 00:00:12 XXX-DS02 Kernel:
Sep 00:00:12 xxx-ds02 kernel:call Trace:
Sep 00:00:12 xxx-ds02 kernel: [<ffffffff800cb21a>] __invalidate_mapping_pages+0xe4/0x183
Sep 00:00:12 xxx-ds02 kernel: [<ffffffff800f642e>] drop_pagecache+0xa5/0x13b
Sep 00:00:12 xxx-ds02 kernel: [<ffffffff80096bc1>] do_proc_dointvec_minmax_conv+0x0/0x56
Sep 00:00:12 xxx-ds02 kernel: [<ffffffff800f64de>] drop_caches_sysctl_handler+0x1a/0x2c
Sep 00:00:12 xxx-ds02 kernel: [<ffffffff80096fea>] do_rw_proc+0xcb/0x126
Sep 00:00:12 xxx-ds02 kernel: [<ffffffff80016a49>] vfs_write+0xce/0x174
Sep 00:00:12 xxx-ds02 kernel: [<ffffffff80017316>] sys_write+0x45/0x6e
Sep 00:00:12 xxx-ds02 kernel: [<ffffffff8005e28d>] Tracesys+0xd5/0xe0
You can see that there are also drop_cache related operations. Look at the red place above, mention the execution of a shell script, and then cause a total CPU stuck, but also can see that the script is performing a recall of the cache action.
I insist that the customer's environment must have been forced memory recycling, but the customer said they did not do any artificial operation, but after my examination found that there is indeed a crontab script.
[Root@xxx-ds02 ~]# Crontab-l
* * * */home/oracle/ht/rel_mem.sh
[Root@xxx-ds02 ~]# cat/home/oracle/ht//rel_mem.sh
#!/bin/bash
#mkdir/var/log/freemem
Time= ' Date +%y%m%d '
Used= ' Free-m | awk ' nr==2 ' | awk ' {print $} '
Free= ' Free-m | awk ' nr==2 ' | awk ' {print $} '
echo "===========================" >>/var/log/freemem/mem$time.log
Date >>/var/log/freemem/mem$time.log
echo "Memory usage | [USE:${USED}MB] [FREE:${FREE}MB] ">>/var/log/freemem/mem$time.log
If [$free-le 71680];then
Sync && echo 3 >/proc/sys/vm/drop_caches
echo "OK" >>/var/log/freemem/mem$time.log
Free >>/var/log/freemem/mem$time.log
Else
echo "Not required" >>/var/log/freemem/mem$time.log
Fi
So why is this script deployed on the host? I suspect that the operating system's memory usage looks very high, and it turns out that this is true by checking:
<pre class= "Brush:plain" >[root@xxx-ds02 ~]# cat/proc/meminfo
memtotal:132072032 KB
memfree:1188372 KB
buffers:251144 KB
cached:90677948 KB---90677948/1024=88552m
swapcached:33476 KB
active:34427132 KB
inactive:59309060 KB
hightotal:0 KB
highfree:0 KB
lowtotal:132072032 KB
lowfree:1188372 KB
swaptotal:16383992 KB
swapfree:16184800 KB
Dirty:32 KB
Writeback:64 KB
anonpages:2774776 KB
mapped:30703840 KB
slab:604080 KB
pagetables:3969892 KB
nfs_unstable:0 KB
bounce:0 KB
commitlimit:66240808 KB
committed_as:39177448 KB
vmalloctotal:34359738367 KB
vmallocused:273448 KB
vmallocchunk:34359464907 KB
hugepages_total:15800
hugepages_free:15800
hugepages_rsvd:5424
hugepagesize:2048 KB
[Root@xxx-ds02 ~]# Free-m
Total used free shared buffers Cached
mem:128976 127808 1168 0 245 88552
-/+ buffers/cache:39010 89966
swap:15999 194 15805</pre>
We can see the 128G of physical memory, the cache occupies a 88G appearance at present. Linux file system cache is divided into 2 kinds: page cache and buffer Cache,page cache is used for files, Inode and other operations of the cache, and buffer cache is used for block device operation. From the data above, the cached 88552 in the free-m command we see is page cache. In fact, the memory allocation of the database instance is 40G, and Linux raw is used.
Sql> Show Parameter SGA
We can see that the entire host physical memory is 128G, and Oracle SGA+PGA only 40g, in addition to nearly 90G of memory is the FS cache consumption. It is possible to adjust the parameters of Linux to release the cache without using echo as a more violent method; The following parameters are recommended, based on the descriptions of several documents of Oracle MOS:
Sysctl-w vm.min_free_kbytes=4096000
Sysctl-w vm.vfs_cache_pressure=200
Sysctl-w vm.swappiness=40 (older Linux is set to Vm.pagecache parameters)