Linux system forced free cache causes database system crashes crash instance

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)