一個(gè)奇怪的ora-4030錯(cuò)誤的診斷過程

前些天我收到一個(gè)客戶報(bào)出的相當(dāng)奇怪的ora-4030的問題，特和大家分享一下。

根據(jù)客戶的描述，他是在Solaris 10 Sparc上嘗試將一個(gè)Oracle 10.2.0.5.6的數(shù)據(jù)庫升級(jí)到Oracle 12.1.0.2，
在執(zhí)行數(shù)據(jù)字典升級(jí)($ORACLE_HOME/perl/bin/perl catctl.pl -n  6 -l $ORACLE_HOME/diagnostics catupgrd.sql)
的時(shí)候，報(bào)出了ora-4030，而且他嘗試重復(fù)多次執(zhí)行升級(jí)腳本，總是在第70步左右報(bào)出ora-4030。

trace文件內(nèi)容大概如下:

ORA-04030: out of process memory when trying to allocate 616 bytes (SQLA^b20dbe57,frodef:qcpitnm)

=======================================
PRIVATE MEMORY SUMMARY FOR THIS PROCESS
---------------------------------------
******************************************************
PRIVATE HEAP SUMMARY DUMP
42 MB total:  <<<< 可見這個(gè)進(jìn)程總共只allocate了42M的PGA
    42 MB commented, 270 KB permanent
    86 KB free (0 KB in empty extents),
      37 MB,   2 heaps:   "callheap       "            44 KB free held
    4990 KB,   1 heap:    "session heap   "           


Private memory usage per Oracle process

-------------------------
Top 10 processes:
-------------------------
(percentage is of 3108 MB total allocated memory)
 <<<< 所有Oracle進(jìn)程總共allocate了3108M的PGA >>>>
 1% pid 43: 42 MB used of 42 MB allocated  <= CURRENT PROC
 1% pid 11: 7558 KB used of 20 MB allocated (12 MB freeable)
......

swap info: free_mem = 55412.04M rsv = 406039.34M 
           alloc = 364360.94M avail = 93020.98M swap_free = 134699.38M
==> 可見OS有55G的free memory, swap有134G的free

客戶的PGA設(shè)置為pga_aggregate_target = 4G 

基于以上信息，我們可見Oracle總共allocate了3G不到的PGA，并且發(fā)生問題的進(jìn)程只allocate了42M
的PGA后就報(bào)出ora-4030了，這顯然不是oracle自身問題，因?yàn)镻GA使用很少，并未使用完。
接下來，我們很容易想到這可能是ulimit配置不當(dāng)。
因?yàn)槿绻鹵limit的 data 和 stack (尤其是data)配置不當(dāng)，很容易出現(xiàn)以上現(xiàn)象。

我們讓客戶再做一次升級(jí),然后在尚未報(bào)錯(cuò)的時(shí)候，定位執(zhí)行upgrade的server process進(jìn)程號(hào)。
對(duì)這個(gè)進(jìn)程提取了ulimit，對(duì)Solaris來說，plimit命令就能做到。

# plimit 16497

16497:  oraclexxxxxx (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
  resource              current         maximum
 time(seconds)         unlimited       unlimited
 file(blocks)          unlimited       unlimited
 data(kbytes)          unlimited       unlimited
 stack(kbytes)         32768           unlimited
 coredump(blocks)      unlimited       unlimited
 nofiles(descriptors)  65536           65536
 vmemory(kbytes)       unlimited       unlimited 

結(jié)果讓我們大失所望，因?yàn)閐ata是unlimited的，而且stack完全滿足12c安裝最低要求。
接下來我們收集了OSWatcher和OS log，希望從這里面發(fā)現(xiàn)一些線索。

ora-4030發(fā)生的時(shí)間為15:13:30，問題期間的vmstat輸出表明此時(shí)OS有充分的memory及swap資源

zzz ***Mon Oct 31 15:13:23 CST 2016
 kthr      memory
 r b w   swap  free
 3 38 0 142269152 95078552
 0 30 0 102388240 58454584
 0 29 0 102382384 58453432  <<< 58G free memory

但是排序后發(fā)現(xiàn)在某些時(shí)間點(diǎn)swap只剩下100多m了，不過與ora-4030時(shí)間點(diǎn)對(duì)不上。

$ awk '/^zzz/{t=$5;next}/^\s*[0-9]/{print t,$4,$5}' xxxxxx_vmstat_16.10.31.1500.dat | sort -k2,2rn

time     swap   free
15:22:42 231952 58769488
15:06:04 136480 58555416
15:27:14 133456 58835728
15:22:42 131288 58799792

可見在15:06/15:22/15:27的時(shí)候，swap只有100~200多m了，此時(shí)free memory尚有58g
另外可見的是swap的使用跨度巨大，比如下面的詳細(xì)信息表明從15:22:42到15:22:57之間15秒，swap跨度為100多G，

zzz ***Mon Oct 31 15:22:42 CST 2016

r b w   swap  free
3 38 0 142267000 95076616
1 18 0 231952 58769488
2 24 0 131288 58799792  <<<<  131m swap

zzz ***Mon Oct 31 15:22:57 CST 2016  <<< 時(shí)隔15秒后

r b w   swap  free
3 38 0 142266920 95076568
0 16 0 103208360 58855448  <<<< 100g swap
1 29 0 103214056 58860848

觀察ps的輸出，發(fā)現(xiàn)這個(gè)host上竟然運(yùn)行著58個(gè)oracle數(shù)據(jù)庫.

$ grep -oE "[^ ]+_lgwr_.+" xxxxxx_ps_16.10.31.1500.dat | sort -u | wc -l
58

這樣我們可以猜測(cè)問題原因可能在swap上，只是因?yàn)関mstat采樣頻率15秒太低了，
發(fā)生問題的那一瞬間沒有采樣，并且由于變化巨大，在相鄰的采樣也看不到低swap的現(xiàn)象。

接下來我們分析了OS log，發(fā)現(xiàn)大量如下信息:

Oct 31 11:03:58 xxxx genunix: [ID 470503 kern.warning] WARNING: Sorry, no swap space to grow stack for pid 24989 (oracle)
Oct 31 15:37:21 xxxx tmpfs: [ID 518458 kern.warning] WARNING: /tmp: File system full, swap space limit exceeded
Oct 31 17:11:28 xxxx genunix: [ID 470503 kern.warning] WARNING: Sorry, no swap space to grow stack for pid 23708 (oracle)

這樣進(jìn)一步證明了我們的猜測(cè)，接下來我們檢查了OS的swap配置:

# top
Memory: 512G phys mem, 62G free mem, 100G swap, 100G free swap

可見有512G的物理內(nèi)存，但是swap只配了100G，這顯然不符合我們的推薦標(biāo)準(zhǔn)，參見
How to Configure Swap Space (Doc ID 286388.1)

這樣我們的solution就是將swap space提高到75%的OS memory大小，設(shè)置成512G更佳。

但是問題來了，發(fā)生問題時(shí)我們還有58G的free memory，為什么oracle不用這些free的memroy而是用swap呢？

這是因?yàn)镾olaris的設(shè)計(jì)使之然，如下的文檔給出了答案:

How does the Solaris Operating System Calculate Available Swap? (Doc ID 1010585.1)

When a process calls the malloc()/sbrk() commands, only virtual swap is allocated.
The operating system allocates the memory from physical disk-based swap first.
If disk-based swap is exhausted or unconfigured, the reservation is allocated from physical memory.
If both resources are exhausted then the malloc() call fails.
To ensure malloc() won't fail due to lack of virtual swap, configure a large physical disk-based swap
facility in the form of a device or swapfile.  You can monitor swap reservation via "swap -s" and "vmstat:swap",
as described above.

Follow the guidelines below to calculate amount of virtual swap usage:
Virtual swap = Physical Memory + Fixed Disk swap

這位具有深厚技術(shù)背景的客戶甚至自己寫了一個(gè)程序來印證以上觀點(diǎn):
該程序會(huì)通過malloc分配20G內(nèi)存:

#include <stdlib.h>
#include <unistd.h>
int main() {
  int i;
  for (i=1; i<(20 * 1024); i++) {
    int * mem = (int *) malloc(262144 * sizeof(int)); /* allocate 1M memory */
  }
  sleep(3600);
} 

運(yùn)行以上腳本，觀察vmstat，從vmstat看到swap有下降20G，但是free（物理內(nèi)存）是不變的

# vmstat 5
kthr      memory
r b w   swap  free
3 38 0 142014200 94739000
0 25 0 149185672 101854776
0 26 0 149206240 101858144
1 30 0 146200840 101672840
0 38 0 128054088 101455256 <<< 這里swap減少了18G
1 30 0 127985768 101463136
0 31 0 128119312 101556752

到這里，我們可以完全確認(rèn)這個(gè)ora-4030的問題是由于swap配置不當(dāng)導(dǎo)致的。

由于客戶當(dāng)前尚沒有足夠的disk資源來添加swap，并且問題緊急，他們最后的解決辦法是停掉了一些應(yīng)用
釋放出了更多的free memory，最后升級(jí)成功了，等今后有disk的時(shí)候再添加swap。