一个奇怪的ora-4030错误的诊断过程

前些天我收到一个客户报出的相当奇怪的ora-4030的问题，特和大家分享一下。

根据客户的描述，他是在Solaris 10 Sparc上尝试将一个Oracle 10.2.0.5.6的数据库升级到Oracle 12.1.0.2，
在执行数据字典升级($ORACLE_HOME/perl/bin/perl catctl.pl -n  6 -l $ORACLE_HOME/diagnostics catupgrd.sql)
的时候，报出了ora-4030，而且他尝试重复多次执行升级脚本，总是在第70步左右报出ora-4030。

trace文件内容大概如下:

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:  <<<< 可见这个进程总共只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进程总共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设置为pga_aggregate_target = 4G 

基于以上信息，我们可见Oracle总共allocate了3G不到的PGA，并且发生问题的进程只allocate了42M
的PGA后就报出ora-4030了，这显然不是oracle自身问题，因为PGA使用很少，并未使用完。
接下来，我们很容易想到这可能是ulimit配置不当。
因为如果ulimit的 data 和 stack (尤其是data)配置不当，很容易出现以上现象。

我们让客户再做一次升级,然后在尚未报错的时候，定位执行upgrade的server process进程号。
对这个进程提取了ulimit，对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 

结果让我们大失所望，因为data是unlimited的，而且stack完全满足12c安装最低要求。
接下来我们收集了OSWatcher和OS log，希望从这里面发现一些线索。

ora-4030发生的时间为15:13:30，问题期间的vmstat输出表明此时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

但是排序后发现在某些时间点swap只剩下100多m了，不过与ora-4030时间点对不上。

$ 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的时候，swap只有100~200多m了，此时free memory尚有58g
另外可见的是swap的使用跨度巨大，比如下面的详细信息表明从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  <<< 时隔15秒后

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

观察ps的输出，发现这个host上竟然运行着58个oracle数据库.

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

这样我们可以猜测问题原因可能在swap上，只是因为vmstat采样频率15秒太低了，
发生问题的那一瞬间没有采样，并且由于变化巨大，在相邻的采样也看不到低swap的现象。

接下来我们分析了OS log，发现大量如下信息:

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)

这样进一步证明了我们的猜测，接下来我们检查了OS的swap配置:

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

可见有512G的物理内存，但是swap只配了100G，这显然不符合我们的推荐标准，参见
How to Configure Swap Space (Doc ID 286388.1)

这样我们的solution就是将swap space提高到75%的OS memory大小，设置成512G更佳。

但是问题来了，发生问题时我们还有58G的free memory，为什么oracle不用这些free的memroy而是用swap呢？

这是因为Solaris的设计使之然，如下的文档给出了答案:

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

这位具有深厚技术背景的客户甚至自己写了一个程序来印证以上观点:
该程序会通过malloc分配20G内存:

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

运行以上脚本，观察vmstat，从vmstat看到swap有下降20G，但是free（物理内存）是不变的

# 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

到这里，我们可以完全确认这个ora-4030的问题是由于swap配置不当导致的。

由于客户当前尚没有足够的disk资源来添加swap，并且问题紧急，他们最后的解决办法是停掉了一些应用
释放出了更多的free memory，最后升级成功了，等今后有disk的时候再添加swap。