Recently we noticed that imageinfo was displaying the following information at a customers site. Imageinfo was not displaying data i suspected, so a quick little blogpost about what was going on there.

```[root@dm01db01 ~]# dcli -g /opt/oracle.SupportTools/onecommand/dbs_group -l root "imageinfo | grep 'Image version'"
dm01db01: Image version: 11.2.3.2.1.130109
dm01db02: Image version: 11.2.3.2.1.130109
dm01db03: Image version: 11.2.3.2.1.130109
dm01db04: Image version: 11.2.3.2.1.130109
dm01db05: Image version: 11.2.3.2.0.120713
dm01db06: Image version: 11.2.3.2.0.120713
dm01db07: Image version: 11.2.3.2.0.120713
dm01db08: Image version: 11.2.3.2.0.120713
```

So what happened here, did those last four nodes not got updated when installing the latest CellOS QDPFE? Well it turns out that all the correct packages are installed after a quick investigation:

```[root@dm0105 ~]# for i in `yum info | grep Name | grep exadata |cut -d: -f2`; do yum info \$i ; done | grep 'Version\|Name'
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
Version    : 11.2.3.2.1.130109
[root@dm0101 rpm-extraxt]#
```

So according to yum everything is installed here, rpm -qa also confirms this so no miss-match there:

```[root@dm0105 ~]# rpm -qa | grep exadata
[root@dm0101 ~]#
```

It looks like imageinfo is displaying incorrect information here, how come and where does it gets its information from? Well, imageinfo gets its information out of a file called image.id:

```root@dm01db05 ~]# cat /opt/oracle.cellos/image.id
id:1357731445
kernel:2.6.32-400.11.1.el5uek
kernelstock:2.6.32-300.19.1.el5uek
version:11.2.3.2.1.130109
type:production
label:OSS_11.2.3.2.1_LINUX.X64_130109
cellrpmver:OSS_11.2.3.2.1_LINUX.X64_130109
cellswver:OSS_11.2.3.2.1_LINUX.X64_130109
mode:install
created:2013-01-09 03:37:26 -0800
node:COMPUTE
f331a2bfa27cc7371d936009289c23b6 *commonos.tbz
22212b4436b57fba6d53be4d7a6fd975 *dbboot.tbz
c7cf016f2180ab820010a787b77c59fb *dbfw.tbz
fd9d8b4f4a30588ca39f66015d5edc4e *dbrpms.tbz
eaa1a7973efcdcd2fe40b09828ba0e01 *debugos.tbz
290909dec5b3995aed2298f20d345aea *exaos.tbz
cfda22b7599e47bdc686acf41fd5d67c *kernel.tbz
18db43d6e94797710ffa771702be33e8 *ofed.tbz
4831ba742464caaa11c1c0153b823886 *sunutils.tbz
activated:2013-11-24 04:41:03 +0100
status:success
```

you can see that this file contains all the informations about the current version of your Exadata software stack as well as a list of md5 checksums of the .tbz files in /opt/oracle.cellos/iso/cellbits. We checked the md5 checksums of these files as well so now we now 100% that we are on the correct level. Now how does this file gets updated, it seems that it is out-of-date or at least not inline with our system? Well it is being generated when you are patching your compute node to another level and it is being updated by the exadata-sun-computenode rpm. Lets peek a bit into that rpm and what it is deploying, first i am going to mount an ISO file as my yum repository:

```[root@dm0101 ~]# mount -o loop /u01/app/oracle/stage.2288/112_latest_repo_130109.iso /var/www/html/yum/unknown/EXADATA/dbserver/11.2/latest.2288/
```

Next step is to extract the files from the RPM and see what we get:

```[root@dm0101 ~]# mkdir /tmp/exadata-sun-computenode-
./etc/init.d/pciibmap
./etc/init.d/workaround_13083530
./etc/yum/pluginconf.d/installonlyn.conf
./opt/oracle.SupportTools/corecontrol
./opt/oracle.SupportTools/dbserver_backup.sh
./opt/oracle.SupportTools/sundiag.sh
./opt/oracle.cellos/tmpl/image.id.11.2.3.2.1.130302.in
194 blocks
```

Aha! there is a file called ./opt/oracle.cellos/tmpl/image.id.11.2.3.2.1.130302.in in that RPM, but it is not showing everything, it still doesn’t got the md5 checksum information in it:

```[root@dm0101 exadata-sun-computenode-]# cat ./opt/oracle.cellos/tmpl/image.id.11.2.3.2.1.130302.in
id:1362281283
kernel:2.6.32-400.21.1.el5uek
kernelstock:2.6.32-300.19.1.el5uek
version:11.2.3.2.1.130302
type:production
label:OSS_11.2.3.2.1_LINUX.X64_RELEASE
cellrpmver:OSS_11.2.3.2.1_LINUX.X64_130302
cellswver:OSS_11.2.3.2.1_LINUX.X64_130302
mode:install
created:2013-03-02 19:28:04 -0800
node:COMPUTE
```

To find out how that gets filled we need to take a look into the script that gets executed when we install this RPM. The output bellow is a bit truncated for readability:

```[root@dm0101 rpm-extraxt]# rpm --scripts -qp exadata-sun-computenode-11.2.3.2.1.130302-1.x86_64.rpm
.
..
fi
# Don't start post script for the fresh imaging (on zero boot)
# Don't install any files (remove them)
if [ -f /.post.imaging ]; then
rm -f /opt/oracle.cellos/tmpl/image.id.11.2.3.2.1.130302.in
else
fi
..
.
```

So when we install this RPM it does (among other things not shown here) remove my image.id file and a shell script called exadata.computenode.post.sh and it then executes a new version of exadata.computenode.post.sh. Now exadata.computenode.post.sh is quiet a big script and it does setup your compute node properly and then finally it reboots your compute node. In this huge exadata.computenode.post.sh script there is a function that is being called that actually calculates the md5 checksums of my cellbits directory and places that info into a variable:

```md5sum_iso_cellbits ()
{
local imageid_out=\$1

[ "\$imageid_out" == '' ] &amp;&amp; imageid_out=\$IMAGE_ID_DEF
print_log "Please wait. Calculating checksums for \$imageid_out ..." INFO
# Remove any existing md5 sums from the output file
perl -ne '/[a-f\d]\s+\*.+/ or print \$_' -i \$imageid_out
local tmp_lst=/tmp/msd5sum.cellbits.lst
pushd /opt/oracle.cellos/iso/cellbits
md5sum -b * &gt; \$tmp_lst
cat \$tmp_lst &gt;&gt; \$imageid_out
rm -f \$tmp_lst
popd
}
```

Finally the function db_update_imageinfo () in exadata.computenode.post.sh creates a new and up-to-date version of my image.id file and it makes imageinfo happy again. To make a long blogpost short, the solution to our misbehaving image info (and also imagehistory btw.) was to run

```yum --enablerepo=exadata_dbserver_11.2.3.2.1_x86_64_base reinstall exadata-sun-computenode-11.2.3.2.1.130109-1
```

and let the nodes reboot. This solved our problem with the imageinfo command, unfortunately we could not determine the root cause for the image.id problem.

With cellcli you can run the calibrate command, this will measure the performance of your harddisks and flashcards. It will eventually report to you the throughput and amount of IOPS that was measured during the calibrate, it will also report to you which luns are not performing up to par.

Calibrate has a few simple options:

```CellCLI> help calibrate

Usage: CALIBRATE [HARDDISK | FLASHDISK | lun1 [, lun2]] [FORCE]
Purpose: Runs raw performance tests on disks.
CELLSRV must be shutdown.  User id root is required.

Options:
[FLASHDISK]: option to specify that only flash LUNs be calibrated.
[HARDDISK] : option to specify that only hard disk LUNs be calibrated.
lun1 [, lun2] : option to specify list of LUNs by name    [FORCE]    : runs test even while CELLSRV is running.

Examples:
CALIBRATE
CALIBRATE '0_8', '0_10' force

CellCLI>
```

So let’s do a test run of calibrate on one of the harddisks in this cell in this V2 half rack:

```CellCLI> calibrate 0_2 force
Calibration will take a few minutes...
LUN 0_2 on drive [20:2] random read throughput: 168.21 MBPS, and 419 IOPSCALIBRATE results are within an acceptable range.

CellCLI>
```

Now this does tell us something about the throughput and the IOPS that was measured but it does not tells you HOW cellcli did manage to measure this. Let’s have a peek into how cellcli works, in order to set we have to increase the logmode and start cellcli in debugging mode:

```[root@dm01cel01 ~]# cellcli -vvv -d
CellCLI: Release 11.2.3.2.1 - Production on Sun Oct 27 15:19:55 CET 2013

Cell Efficiency Ratio: 236
```

What this does, is dumping a lot of extra information on your screen regarding calls that cellcli does to ossmgmt.jar. Now cellcli is nothing but a perl script that calls to that jar file. With cellcli now running in debug mode and loglevel set to the highest we can now run our calibrate command again:

```CellCLI> calibrate 0_2 force
loop
yyn:0  state:0  yychar:-1
tok: -3 sval: calibrate
yy:calibrate
next yychar:289
reduce
state 0, reducing 0 by rule 2 (\$\$1 :)
...
..
.
state 37, reducing 4 by rule 4 (line : \$\$1 cli \$\$2 EOL)
CLI command: CALIBRATE(289)
SPOOL arg : NONE(0)
CLI verb: CALIBRATE(289)
CLI object: NONE(0) 0_2
attr#1: FORCE(334)
++++Over Value is: 0
ForAll is false
attr#1: FORCE(334)
reduce
After reduction, shifting from state 0 to state 2
tok: -1 sval: null
Getting the state of CELLSRV services...  running
Calibration will take a few minutes...
LUN 0_2 on drive [20:2] random read throughput: 168.33 MBPS, and 420 IOPSCALIBRATE results are within an acceptable range.

CellCLI>
```

I have truncated the output above a little bit to make readable. Now this does not tell us a whole lot more but we can now see some interesting info in the cellcli logfile in /var/log/oracle/deploy/cellcli.lst.0* where the last parts can vary on your system depending the times you have started cellcli. When scrolling through that logfile you will see the output generated by cellcli you will find our cellcli calibrate command:

```Oct 27, 2013 3:21:33 PM oracle.ossmgmt.ms.cli.CellCLI readAndProcessLine
INFO: Executing cellcli command: "calibrate 0_2 force"
Oct 27, 2013 3:21:33 PM oracle.ossmgmt.ms.cli.CellCLI invokeSingleRSCmd
FINE: Executing RS command: 0.0STATE CELLSRV!!!!!!!!!!!!!!.
Oct 27, 2013 3:21:33 PM oracle.ossmgmt.ms.cli.CellCLI invokeSingleRSCmd
FINE: RS comamnd return status: 2.
```

You see that the oracle.ossmgmt.ms.cli.CellCLI class checks wetter or not cellsrv is running or not (i have added the force parameter so i can run calibrate without stopping cellsrv).

```Oct 27, 2013 3:21:33 PM oracle.ossmgmt.ms.cli.Calibrate fetchLuns
INFO: disknames.size: 1 listluncmd - list lun "0_2" attributes name, devicename, physicaldrives, disktype, lunsize
Oct 27, 2013 3:21:33 PM oracle.ossmgmt.ms.cli.Calibrate fetchCliResults
FINER: fetchCli cmd: MOD CALIBRATE :list lun "0_2" attributes name, devicename, physicaldrives, disktype, lunsize
Oct 27, 2013 3:22:14 PM oracle.ossmgmt.ms.cli.Calibrate fetchCliResults
FINER: fetchCli result: .	 0_2	 /dev/sdc	 20:2	 HardDisk	 557.861328125G
```

Next you see that cellcli uses oracle.ossmgmt.ms.cli.Calibrate to translate my lun name 0_2 to a blockdevice name, in my case /dev/sdc. it the goes on the gather names of all the pun:

```Oct 27, 2013 3:22:14 PM oracle.ossmgmt.ms.cli.Calibrate fetchLuns
INFO: listluns: 	 0_2	 /dev/sdc	 20:2	 HardDisk	 557.861328125G

Oct 27, 2013 3:22:14 PM oracle.ossmgmt.ms.cli.Calibrate fetchCliResults
FINER: fetchCli cmd: MOD CALIBRATE :list physicaldisk attributes name, luns, diskMediaGroup
Oct 27, 2013 3:22:20 PM oracle.ossmgmt.ms.cli.Calibrate fetchCliResults
FINER: fetchCli result: .	 20:0	 0_0	 DMG_SYSTEM_HDD1
20:1	 0_1	 DMG_SYSTEM_HDD1
20:2	 0_2	 DMG_DATA_HDD1
20:3	 0_3	 DMG_DATA_HDD1
...
..
.
Oct 27, 2013 3:22:20 PM oracle.ossmgmt.ms.cli.Calibrate fetchLuns
INFO: listpds: 	 20:0	 0_0	 DMG_SYSTEM_HDD1
20:1	 0_1	 DMG_SYSTEM_HDD1
20:2	 0_2	 DMG_DATA_HDD1
20:3	 0_3	 DMG_DATA_HDD1
...
..
.
```

The output above is shortened for readability. Next oracle.ossmgmt.ms.cli.Calibrate runs scripts_common.sh, which is also run during cell deployment. scripts_common.sh tune_block_io /dev/sdc sets nr_request in /sys/block/sdc/queue/nr_requests to 4096:

```Oct 27, 2013 3:22:20 PM oracle.ossmgmt.ms.cli.Calibrate calibrate
```

The nr_requests sets the amount of IO slots 4096 meaning that the deadline IO scheduler has more chance to merge IO requests. This should already been set to 4096 on all of your cells, the calibrate command sets it again anyway.

```Oct 27, 2013 3:22:21 PM oracle.ossmgmt.ms.cli.CalibrateTest executeOrion
INFO: execute: /opt/oracle/cell11.2.3.2.1_LINUX.X64_130109/cellsrv/bin/orion -run advanced -type rand -matrix point  -disk_start_offset 0 -duration 30 -num_disks 1 -testname rand_0 -disk_end_offset 285184m -size_large 8192 -num_small 0 -num_large 10
Oct 27, 2013 3:22:51 PM oracle.ossmgmt.ms.cli.CalibrateTest executeOrion
INFO: execute: /opt/oracle/cell11.2.3.2.1_LINUX.X64_130109/cellsrv/bin/orion -run advanced -type rand -matrix point  -disk_start_offset 0 -duration 30 -num_disks 1 -testname rand_IOPS_0 -disk_end_offset 285184m -size_small 8 -num_large 0 -num_small 20
```

Finally calibrate starts the actual calibrate, it does this by calling Orion which is located in \$OSS_BIN. It runs two separate runs, one doing small 8Kb requests and one doing 8192Kb large IO’s.

# Exadata system stats and MBRC

Last year Oracle added a new functionality to dbms_stats.gather_system_stats, making it more Exadata aware and thus let the optimizer make choices that might result in offloading more often. See this blog post from Kerry Osborne about it, i made a small comment about the MBRC in it and i would like to zoom in on that a bit more on this post.

So what happens during gathering van of the Exadata system statistics, de easiest way to find out is to run an SQL trace along with the system stats:

```SYS@kjj AS SYSDBA> alter session set events 'sql_trace wait=true, bind=true, level=12';

Session altered.

PL/SQL procedure successfully completed.
```

If we look in the trace file we see that Oracle starts with some recursive SQL statements to find out what datafiles there are and the starts doing a lot of IO, these are all recorded with a unique wait event:

```WAIT #139869656707320: nam='Disk file I/O Calibration' ela= 3255 count=1 p2=182669 p3=2 obj#=-1 tim=1379436371918507
```

It looks like Oracle is doing some type of IO to find out what out what this storage can do, lets take a deeper look into these IO’s. You can use the GDB route, described by Frits Hoogland here but for this purpose there is an somewhat easier way. The new trace interface in 11g has an interesting option where we can trace the OSS calls to the storage:

```SYS@kjj AS SYSDBA> oradebug setmypid
Statement processed.
Statement processed.
SYS@kjj AS SYSDBA> alter session set events 'trace[libcell.client_library.*]';

Session altered.

SYS@kjj AS SYSDBA> alter session set events 'sql_trace wait=true, bind=true, level=12';

Session altered.

PL/SQL procedure successfully completed.

/u01/app/oracle/diag/rdbms/kjj/kjj/trace/kjj_ora_13915.trc
Statement processed.
SYS@kjj AS SYSDBA>
```

So what am i doing there, first i want to remove the 5MB tracefile limit for my session because the above steps will generate a huge trace file, next is how we van enable trace of all the communication of my shadow process to the storage layer so this:

```alter session set events 'trace[libcell.client_library.*]';
```

Will trace all of the following

```Components in library LIBCELL:
--------------------------
Client_Library	       Client Library
Disk_Layer		       Disk Layer
Network_Layer	       Network Layer
IPC_Layer		       IPC Layer
```

libcell.client_library.* means that i want to trace all calls to libcell.client_library and all of the 3 child layers. If we now take a look at the trace file and we zoom into to the Disk file I/O Calibration waits we see that is now preceded with trace data containing information about the communication between my shadow process and the storage layer:

```oss_open called for o/192.168.100.11/DATA_CD_09_dm01cel07 with guid 56d7b5d4-12a-0-0
connect: box name -192.168.100.11, port - 5042
TCP-connected to: box name -192.168.100.11, ospid - 14950, port - 5042, my box refid: 5, source id: 2575757666
SKGXP-connecting to the box 192.168.100.11 OSS OS Pid 14950
SKGXP-connected to the appliance number -728063998
Sending message 0xdabf2f0 with frag # 0, msgid 27 to box my_box_refid: 5 (my sourceid in box: 2575757666  box inc: 17)
Command code OPEN, msgid 27, refid 0
Open flags: readwrite - 1, sync - 1, char - 0.
Device name - DATA_CD_09_dm01cel07
Vrpc completion - cmd 0xdabf330, req 0xdabee50, msgid 27, frag # 1
Vrpc reply 0xdabf3e8 with refid 27 for existing message: 0xdabf2f0
Command code REPLY OPEN, msgid 0, refid 27
Returned open file descriptor  0
opening file number 9
oss_read open file: 9, offset: 38498574336, blocks: 128
Sending message 0xdabf2f0 with frag # 0, msgid 28 to box my_box_refid: 5 (my sourceid in box: 2575757666  box inc: 17)
Command code BREAD, msgid 28, refid 0
Block arguments fd 0 offset 38498574336 cnt 128 blksize 512 prefetch 0
oss_wait called for request: 0xdabee50
Vrpc completion - cmd 0xdabf330, req 0xdabee50, msgid 28, frag # 1
Vrpc reply 0xdabf3e8 with refid 28 for existing message: 0xdabf2f0
oss_wait done, request 0xdabee50, result 0x7f35f116bfc8
WAIT #139869656707320: nam='Disk file I/O Calibration' ela= 3255 count=1 p2=182669 p3=2 obj#=-1 tim=1379436371918507
```

So now we know how Exadata handles IO request lets zoom in on our IO’s for our Disk file I/O Calibration wait

```[oracle@dm0101 [kjj] trace]\$ grep 'oss_read open file' /u01/app/oracle/diag/rdbms/kjj/kjj/trace/kjj_ora_13915.trc
...
..
.
oss_read open file: 19, offset: 37603999744, blocks: 128
oss_read open file: 12, offset: 38469820416, blocks: 16
oss_read open file: 16, offset: 38503866368, blocks: 128
oss_read open file: 43, offset: 38536380416, blocks: 16
oss_read open file: 51, offset: 37821882368, blocks: 128
oss_read open file: 78, offset: 37753462784, blocks: 16
oss_read open file: 44, offset: 38539337728, blocks: 128
oss_read open file: 33, offset: 38455091200, blocks: 16
oss_read open file: 49, offset: 37558116352, blocks: 128
oss_read open file: 30, offset: 38454730752, blocks: 16
oss_read open file: 16, offset: 38439862272, blocks: 128
oss_read open file: 67, offset: 37605408768, blocks: 16
...
..
.
[oracle@dm0101 [kjj] trace]\$
```

So when oracle fires the dbms_stats.gather_system_stats(‘EXADATA’) you see that it is switching between requesting 128 blocks and 16 blocks from different celldisks. Apparently oracle uses these IO’s to calculate wetter or not it can set the MBRC to 128 or not (it also takes db_cache_size into account). Then it deletes the results in aux_stats\$:

```DELETE FROM SYS.AUX_STATS\$ WHERE SNAME = 'SYSSTATS_MAIN'
```

and eventually it updates the values of, amongst others, MBRC to 128 in this case:

```PARSING IN CURSOR #139869655553736 len=71 dep=1 uid=0 oct=2 lid=0 tim=1379436419280111 hv=4016519028 ad='db24c118' sqlid='32kbjpmrqfdvn'
INSERT INTO SYS.AUX_STATS\$ VALUES ('SYSSTATS_MAIN', 'MBRC', :B1 , NULL)
END OF STMT
BINDS #139869655553736:
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=7f35f12e4088  bln=22  avl=03  flg=09
value=128
EXEC #139869655553736:c=0,e=267,p=0,cr=0,cu=3,mis=0,r=1,dep=1,og=1,plh=0,tim=1379436419280370
CLOSE #139869655553736:c=0,e=1,dep=1,type=3,tim=1379436419280396
```

# Analyzing page allocation failures on Exadata

I have seen several clients who are struggling to decode page allocation failures on Exadata, in this post i will try to explain how to read the backtrace. The following is an anonymized client case where page allocation failures are leading up to a node reboot.

```Jan 1 11:58:02 dm01db01 kernel: oracle: page allocation failure. order:1, mode:0x20
Jan 1 11:58:02 dm01db01 kernel: Pid: 80047, comm: oracle Tainted: P           2.6.32-400.11.1.el5uek #1
Jan 1 11:58:02 dm01db01 kernel: Call Trace:
Jan 1 11:58:02 dm01db01 kernel:  <IRQ>  [<ffffffff810ddf74>] __alloc_pages_nodemask+0x524/0x595
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff8110da3f>] kmem_getpages+0x4f/0xf4
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff8110dc3c>] fallback_alloc+0x158/0x1ce
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff8110ddd3>] ____cache_alloc_node+0x121/0x134
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff8110e3f3>] kmem_cache_alloc_node_notrace+0x84/0xb9
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff8110e46e>] __kmalloc_node+0x46/0x73
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff813b9aa8>] ? __alloc_skb+0x72/0x13d
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff813b9aa8>] __alloc_skb+0x72/0x13d
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff813b9bdb>] alloc_skb+0x13/0x15
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff813b9f11>] dev_alloc_skb+0x1b/0x38
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa02a3722>] ipoib_cm_alloc_rx_skb+0x31/0x1de [ib_ipoib]
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa02a4d04>] ipoib_cm_handle_rx_wc+0x3a1/0x5b8 [ib_ipoib]
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa0198bdc>] ? mlx4_ib_free_srq_wqe+0x27/0x54 [mlx4_ib]
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa01904d4>] ? mlx4_ib_poll_cq+0x620/0x65e [mlx4_ib]
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa029fe97>] ipoib_poll+0x87/0x128 [ib_ipoib]
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff813c4b69>] net_rx_action+0xc6/0x1cd
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff8105e8cd>] __do_softirq+0xd7/0x19e
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff810aefdc>] ? handle_IRQ_event+0x66/0x120
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff81012eec>] call_softirq+0x1c/0x30
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff81014695>] do_softirq+0x46/0x89
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff8105e752>] irq_exit+0x3b/0x7a
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff8145bea1>] do_IRQ+0x99/0xb0
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffff81012713>] ret_from_intr+0x0/0x11
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa02bc2df>] ? kcalloc+0x35/0x3d [rds]
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa02bc2df>] ? kcalloc+0x35/0x3d [rds]
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa02bc724>] ? __rds_rdma_map+0x16c/0x32c [rds]
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa02bca09>] ? rds_get_mr+0x42/0x4f [rds]
Jan 1 11:58:02 dm01db01 kernel:  [<ffffffffa02b67b2>] ? rds_setsockopt+0xae/0x14f [rds]
Jan 1 11:58:02 dm01db01 kernel:  <EOI>  [<ffffffff81458045>] ? _spin_lock+0x21/0x25
```

Lets take a look at that call trace, in line 1 we see that this regarding the oracle binary that is having the page allocation failures. The way the linux kernel works is that it tries to allocatie pages is in powers of 2, so ‘order:1′ means that linux failed to allocate 2^1 ( $2^1$ ) pages, so 2 pages in total. We can see how much that is if we lookup the pagesize on Exadata:

```[root@dm0101 ~]# getconf PAGESIZE
4096
```

so this means we wanted to allocate: $2^1*4096=8192$

So in this case this system could not allocate 8k of memory, if we walk through the trace we can see where it went wrong. You can see in lines 10,11 en 12 that Linux tries to allocate Socket Kernel Buffers (alloc_skb) and fails. Walking further down the stack we can see it is IP over Infinband that tries to allocate these buffers (ipoib_cm_alloc_rx_skb).

The mode:0×020 line is the GFP (Get Free Pages) flag that is being sent with the request, you can look up what flag it is in gfp.h:

```[root@dm0101 ~]# grep 0x20 /usr/src/kernels/`uname -r`/include/linux/gfp.h
#define __GFP_HIGH	((__force gfp_t)0x20u)	/* Should access emergency pools? */
```

So if we look further down the messages file we can see the following part:

```Jun 14 11:58:02 dm04dbadm02 kernel: Node 0 DMA free:15800kB min:4kB low:4kB high:4kB active_anon:0kB inactive_anon:0kB
active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15252kB mlocked:0kB dirty:0kB
writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB
bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
```

As we can see we have only 4kB of low memory left and absolutely no room left in kernel slabs at all. As you can see rds and ip and thus also ipoib are slab allocated pages (you can monitor slabs using slabinfo):

```[root@dm0101 ~]# cat /proc/slabinfo | grep "^ip\|rds"
rds_ib_frag        23600  23600   8192    1    4 : tunables    8    4    0 : slabdata  23600  23600      0
rds_ib_incoming    23570  23570   8192    1    4 : tunables    8    4    0 : slabdata  23570  23570      0
rds_iw_frag            0      0     40   92    1 : tunables  120   60    8 : slabdata      0      0      0
rds_iw_incoming        0      0    120   32    1 : tunables  120   60    8 : slabdata      0      0      0
rds_connection        18     77    688   11    2 : tunables   54   27    8 : slabdata      7      7      0
ip6_dst_cache         10     24    320   12    1 : tunables   54   27    8 : slabdata      2      2      0
ip6_mrt_cache          0      0    128   30    1 : tunables  120   60    8 : slabdata      0      0      0
ip_mrt_cache           0      0    128   30    1 : tunables  120   60    8 : slabdata      0      0      0
ip_fib_alias           0      0     32  112    1 : tunables  120   60    8 : slabdata      0      0      0
ip_fib_hash           28    106     72   53    1 : tunables  120   60    8 : slabdata      2      2      0
ip_dst_cache         486    530    384   10    1 : tunables   54   27    8 : slabdata     53     53      0
[root@dm0101 ~]#
```

Furthermore, ipoib uses an MTU size 64k so that is at least an order 4 of slab managed pages.

```[root@dm0101 ~]# ifconfig bond0 | grep MTU
UP BROADCAST RUNNING MASTER MULTICAST  MTU:65520  Metric:1
```

With res running on our interconnect this will eventually lead to a node eviction. If rds message can’t be written in the pages then interconnect traffic won’t arrive at this host (remember that infiniband is a lossless fabric).

# Exadata V2 and CPU scaling

A while ago I was doing some bandwith and latency testing of infiniband interfaces on different Exadata configurations and ran into something that might be interesting for Exadata V2 owners out there. You can do some performance test on your IB stack using a set of tools that start with ib_read_*, ib_send_* and ib_write_*. These tools work in a client/server setting where you start a server on side of your path and start a client on the side and start sending and reading data. When running these tests on an Exadata X2 and higher your output will look somewhat like this:

```[root@dm0102 ~]# ib_read_bw dm01db01-priv -a
------------------------------------------------------------------
Connection type : RC
local address:  LID 0x0e, QPN 0x40005f, PSN 0x1f908d RKey 0x30003153 VAddr 0x007f368c713000
remote address: LID 0x0c, QPN 0x28005d, PSN 0x6bbc6e, RKey 0x400428d1 VAddr 0x007f691a135000
Mtu : 2048
------------------------------------------------------------------
#bytes #iterations    BW peak[MB/sec]    BW average[MB/sec]
2        1000               7.22                  2.25
4        1000              14.94                 13.86
8        1000              28.81                 26.53
16        1000              59.03                 54.09
32        1000             113.56                104.37
64        1000             223.18                197.08
128        1000             113.06                112.79
256        1000             226.70                226.16
512        1000             452.23                451.57
1024        1000             902.15                900.82
2048        1000            1805.63               1801.26
4096        1000            2435.64               2434.48
8192        1000            2916.02               2915.82
16384        1000            2937.44               2937.33
32768        1000            2934.50               2931.79
65536        1000            2941.48               2940.98
131072        1000            2941.67               2941.60
262144        1000            2943.20               2941.26
524288        1000            2940.64               2938.26
1048576        1000            2939.29               2939.29
2097152        1000            2942.21               2941.77
4194304        1000            2941.54               2941.00
8388608        1000            2939.31               2938.80
------------------------------------------------------------------
[root@dm0102 ~]#
```

Try running this same test on a Exadata V2 and you will see this:

```Connection type : RC
local address:  LID 0x0e, QPN 0x34004f, PSN 0xc3db36 RKey 0xf8015f71 VAddr 0x007f2a75f2d000
remote address: LID 0x0c, QPN 0x2c0065, PSN 0xdd9285, RKey 0x60003b19 VAddr 0x007f2100646000
Mtu : 2048
------------------------------------------------------------------
#bytes #iterations    BW peak[MB/sec]    BW average[MB/sec]
Conflicting CPU frequency values detected: 1600.000000 != 2534.000000
2        1000               0.00                  0.00
Conflicting CPU frequency values detected: 1600.000000 != 2534.000000
4        1000               0.00                  0.00
Conflicting CPU frequency values detected: 1600.000000 != 2534.000000
8        1000               0.00                  0.00
^C
[root@dm0102 ~]#
```

It looks like this tool is telling me that my CPU’s are running 1.6Mhz but wants to run at 2.53Ghz. Now this tool is right, on this Exadata my CPU’s are running at that speed:

```[root@dm0102 ~]# cat /proc/cpuinfo | grep "cpu MHz" | uniq
cpu MHz		: 1600.000
```

Also, my tool was right at the expected speed, my V2 system uses an Intel Xeon E5440 running at 2.53Ghz:

```[root@dm0102 ~]# cat /proc/cpuinfo | grep "model name" | uniq
model name	: Intel(R) Xeon(R) CPU           E5540  @ 2.53GHz
[root@dm0102 ~]#
```

So your CPU’s are not running at full speed at an Exadata V2. On my test V2 there is nothing running that generates load on the CPU, if you run some load then some of the CPU’s are kicking into full throttle:

```[root@dm0102 ~]# cat /proc/cpuinfo | grep "cpu MHz" | uniq
cpu MHz		: 1600.000
cpu MHz		: 2534.000
cpu MHz		: 1600.000
```

What is causing this behavior, well it is a linux kernel architecture implementation of CPU frequency scaling. The scaling of the CPU speed is done by a process called the CPU Scaling Governor, and you can see it’s status by looking in the /sys filesystem:

```[root@dm0102 ~]# for i in {0..12}; do cat /sys/devices/system/cpu/cpu\$i/cpufreq/scaling_governor; done
ondemand
ondemand
ondemand
ondemand
ondemand
ondemand
ondemand
ondemand
ondemand
ondemand
ondemand
ondemand
ondemand
```

The status of all my CPU cores is ‘ondemand’ which means that Linux will dynamically scale my CPU speed when needed. We can control the behavior with a daemon simply called cpuspeed:

```[root@dm0102 ~]# /etc/init.d/cpuspeed status
Frequency scaling enabled using ondemand governor
```

We can stop this daemon to disable the CPU Scaling Governor:

```[root@dm0102 ~]# /etc/init.d/cpuspeed stop
Disabling ondemand cpu frequency scaling:                  [  OK  ]
[root@dm0102 ~]# for i in {0..12}; do cat /sys/devices/system/cpu/cpu\$i/cpufreq/scaling_governor; done
userspace
userspace
userspace
userspace
userspace
userspace
userspace
userspace
userspace
userspace
userspace
userspace
userspace
```

If we now look at the our CPU speed we can see that they are running at full speed:

```[root@dm0102 ~]# cat /proc/cpuinfo | grep "cpu MHz" | uniq
cpu MHz		: 2534.000
```

Interestingly enough Oracle apparently decided not to use CPU Scaling on their X2 and X3 models.

# Changing the heap size of Enterprise Manager 12c

Enterprise Manager 12c is a product that is being deployed a lot lately, a vast improvement over previews version. For most DBA’s it is a tool they use regularly on a daily basis so performance is key. Fortunately oracle provides us with some documentation on how to size the repository database and heap size of the Oracle Management Service. An excellent white paper on EM12c sizing can be found here on OTN:

http://www.oracle.com/technetwork/oem/framework-infra/em12c-sizing-1590739.pdf

Interestingly enough it states that Oracle considers installation with +1000 targets as a medium sized em12c environment. That limit of +1000 targets is reached quite easily. One of the advisories is that for a medium EM12c environment the minimum heap size should be at least 4G, most default installation run with a heap size of around 1.5G.

So how do we change the heap size of OMS to 4G, meet the startEMServer.sh script, this script can be located Grid Control domain directory of Weblogic:

```[oracle@em12c ~]\$ cd `cat ./bea/beahomelist|cut -d\; -f2`/gc_inst/user_projects/domains/GCDomain/bin
```
```if [ "\${SERVER_NAME}" != "EMGC_ADMINSERVER" ] ; then
if [ "\${JAVA_VENDOR}" = "Sun" ] ; then
if [ "\${PRODUCTION_MODE}" = "" ] ; then
fi
fi
export USER_MEM_ARGS
fi
```

Change the Xms and Xmx parameters on line 2 and 5 the desired values, in this example i choose to set a maximum heapsize of 4G and minimun if 2G. No smart caclculations are done to determine these values, except the upper limit, which came from the earlier mentioned white paper.

```[oracle@ovmem01 bin]\$ . ./setDomainEnv.sh
[oracle@ovmem01 ~]\$ \$OMS_HOME/bin/emctl status oms
Oracle Enterprise Manager Cloud Control 12c Release 2
WebTier is Up
Oracle Management Server is Up
[oracle@ovmem01 ~]\$ \$OMS_HOME/bin/emctl stop oms
Oracle Enterprise Manager Cloud Control 12c Release 2
Stopping WebTier...
WebTier Successfully Stopped
Stopping Oracle Management Server...
Oracle Management Server Successfully Stopped
Oracle Management Server is Down
[oracle@ovmem01 ~]\$ \$OMS_HOME/bin/emctl start oms
Oracle Enterprise Manager Cloud Control 12c Release 2
Starting Oracle Management Server...
Starting WebTier...
WebTier Successfully Started
Oracle Management Server Successfully Started
Oracle Management Server is Up
[oracle@ovmem01 ~]\$
```

Recently one of my customers got a complaint from their DNS administrators, our Exadata’s are doing 40.000 DNS requests per minute. We like our DNS admins so we had a look into these request and what was causing them. I started with just firing up a tcpdump on one of the bonded client interfaces on a random compute node:

```[root@dm01db01 ~]# tcpdump -i bondeth0 -s 0 port 53
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on bondeth0, link-type EN10MB (Ethernet), capture size 65535 bytes
15:41:04.937009 IP dm0101.domain.local.59868 > dnsserver01.domain.local:  53563+ AAAA? dm0101-vip.domain.local. (41)
15:41:04.937287 IP dm0101.domain.local.46672 > dnsserver01.domain.local:  44056+ PTR? 8.18.68.10.in-addr.arpa. (41)
15:41:04.938409 IP dnsserver01.domain.local > dm0101.domain.local.59868:  53563* 0/1/0 (116)
15:41:04.938457 IP dm0101.domain.local.56576 > dnsserver01.domain.local:  45733+ AAAA? dm0101-vip.domain.local.domain.local. (54)
15:41:04.939547 IP dnsserver01.domain.local > dm0101.domain.local.46672:  44056* 1/1/1 PTR dnsserver01.domain.local. (120)
15:41:04.940204 IP dnsserver01.domain.local > dm0101.domain.local.56576:  45733 NXDomain* 0/1/0 (129)
15:41:04.940237 IP dm0101.domain.local.9618 > dnsserver01.domain.local:  64639+ A? dm0101-vip.domain.local. (41)
15:41:04.941912 IP dnsserver01.domain.local > dm0101.domain.local.9618:  64639* 1/1/1 A dm0101-vip.domain.local (114)
```

So what are we seeing here, there are a bunch of AAAA requests to the DNS server and only one A record request. But the weirdest thing is of course the requests with the double domainname extensions. If we zoom in at those AAAA records requests we see the following, here is the request:

```15:41:04.937009 IP dm0101.domain.local.59868 > dnsserver01.domain.local:  53563+ AAAA? dm0101-vip.domain.local. (41)
```

```15:41:04.938409 IP dnsserver01.domain.local > dm0101.domain.local.59868:  53563* 0/1/0 (116)
```

The interesting part is in the answer of the dnsserver, in 0/1/0 the DNS server tells me that for this lookup it found 0 answer resource records, 1 authority resource records, and 0 additional resource records. So it could not resolve my VIP name in DNS. Now if we look at the A records request:

```15:41:04.945697 IP dm0101.domain.local.10401 > dnsserver01.domain.local:  37808+ A? dm0101-vip.domain.local. (41)
```

```15:41:04.947249 IP dnsserver01.domain.local > dm0101.domain.local.10401:  37808* 1/1/1 A dm0101-vip.domain.local (114)
```

Now by looking at the answer: 1/1/1 we can see that i got 1 answer record in return (the first 1), so the DNS server knows the IP for dm0101-vip.domain.local when an A record is requested. What is going on here? Well the answer is simple, AAAA records are IPv6 DNS requests, our DNS servers are not configured for IPv6 name request so it rejects these requests. So what about those weird double domain names like dm0101-vip.domain.local.domain.local? When Linux requests a DNS record the following happens:

1. Linux issues DNS request for dm0101-vip.domain.local, because IPv6 is enabled, it issues an AAAA request.
2. DNS server is not configured for IPv6 requests and discards request.
3. Linux retries the requests, looks into resolv.conf and adds domainame, we now have dm0101-vip.domain.local.domain.local
4. Once again, the DNS server discards this request.
5. Linux once agains retries the AAAA request, adds domain name: dm0101-vip.domain.local.domain.local.domain.local
6. DNS server discards AAAA request
7. Linux now falls back to a DNS IPv4 request and does an A request: dm0101-vip.domain.local
8. DNS servers understands this and replies

This happens because Exadata comes with IPv6 Enabled on both infiniband and ethernet interfaces:

```[root@dm0101 ~]# ifconfig bond0;ifconfig bond1
UP BROADCAST RUNNING MASTER MULTICAST  MTU:65520  Metric:1
RX packets:226096104 errors:0 dropped:0 overruns:0 frame:0
TX packets:217747947 errors:0 dropped:55409 overruns:0 carrier:0
collisions:0 txqueuelen:0
RX bytes:320173078389 (298.1 GiB)  TX bytes:176752381042 (164.6 GiB)

UP BROADCAST RUNNING MASTER MULTICAST  MTU:1500  Metric:1
RX packets:14132063 errors:2 dropped:0 overruns:0 frame:2
TX packets:7334898 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:0
RX bytes:2420637835 (2.2 GiB)  TX bytes:3838537234 (3.5 GiB)

[root@dm0101 ~]#
```

Let’s disable ipv6, my client is not using on ipv6 its internal network anyway (like most companies i assume). You can edit /etc/modprobe.conf to prevent it from being loaded at boot time, add the following 2 lines modprobe.conf:

```alias ipv6 off
install ipv6 /bin/true
```

Then add the below entries to /etc/sysconfig/network

```IPV6INIT=no
```

Reboot the host and lets look at what we see after the host is up again:

```[root@dm0103 ~]# cat /proc/net/if_inet6
00000000000000000000000000000001 01 80 10 80       lo
fe8000000000000002212800013f111f 08 40 20 80    bond0
fe80000000000000022128fffe8e5f6a 02 40 20 80     eth0
fe80000000000000022128fffe8e5f6b 09 40 20 80    bond1
[root@dm0103 ~]# ifconfig bond0;ifconfig bond1
UP BROADCAST RUNNING MASTER MULTICAST  MTU:65520  Metric:1
RX packets:318265 errors:0 dropped:0 overruns:0 frame:0
TX packets:268072 errors:0 dropped:16 overruns:0 carrier:0
collisions:0 txqueuelen:0
RX bytes:433056862 (412.9 MiB)  TX bytes:190905039 (182.0 MiB)

UP BROADCAST RUNNING MASTER MULTICAST  MTU:1500  Metric:1
RX packets:10256 errors:0 dropped:0 overruns:0 frame:0
TX packets:5215 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:0
RX bytes:1559169 (1.4 MiB)  TX bytes:1350653 (1.2 MiB)

[root@dm0103 ~]#
```

So disabling ipv6 modules through modprobe.conf did not do the trick, what did broughgt the ipv6 stack:

```[root@dm0103 ~]# lsmod | grep ipv6
```

The infiniband stack brought up ipv6, we can disable ipv6 at kernel level:

```root@dm0103 ~]# sysctl -a | grep net.ipv6.conf.all.disable_ipv6
net.ipv6.conf.all.disable_ipv6 = 0
[root@dm0103 ~]# echo 1 > /proc/sys/net/ipv6/conf/all/disable_ipv6
[root@dm0103 ~]# sysctl -a | grep net.ipv6.conf.all.disable_ipv6
net.ipv6.conf.all.disable_ipv6 = 1
[root@dm0103 ~]# cat /proc/net/if_inet6
[root@dm0103 ~]#
```

Now we are running this exadata compute node without ipv6, we can now check if we still have infiniband connectivity, on a cell start a ibping server and use ibstat to get the port GUID:

```[root@dm01cel01 ~]# ibstat -p
0x00212800013ea3bf
0x00212800013ea3c0
[root@dm01cel01 ~]# ibping -S
```

On our ipv6 disabled host start the ibping to one of the

```[root@dm0103 ~]# ibping -c 4 -v -G 0x00212800013ea3bf
ibwarn: [14476] ibping: Ping..
Pong from dm01cel01.oracle.vxcompany.local.(none) (Lid 6): time 0.148 ms
ibwarn: [14476] ibping: Ping..
Pong from dm01cel01.oracle.vxcompany.local.(none) (Lid 6): time 0.205 ms
ibwarn: [14476] ibping: Ping..
Pong from dm01cel01.oracle.vxcompany.local.(none) (Lid 6): time 0.247 ms
ibwarn: [14476] ibping: Ping..
Pong from dm01cel01.oracle.vxcompany.local.(none) (Lid 6): time 0.139 ms
ibwarn: [14476] report: out due signal 0

--- dm01cel01.oracle.vxcompany.local.(none) (Lid 6) ibping statistics ---
4 packets transmitted, 4 received, 0% packet loss, time 4001 ms
rtt min/avg/max = 0.139/0.184/0.247 ms
[root@dm0103 ~]#
```

So we have infiniband connectivity, lets see how Oracle reacts:

```[root@dm0103 ~]# crsctl stat res -t
```

And now we play the waiting game… well basically it never comes back, it tries to read from 2 network sockets if we look with strace, it hangs at:

```[pid 15917] poll([{fd=3, events=POLLIN|POLLRDNORM}, {fd=4, events=POLLIN|POLLRDNORM}], 2, -1
```

Which points to 2 file descriptors which it can’t read from:

```[root@dm0103 ~]# ls -altr /proc/15917/fd
total 0
dr-xr-xr-x 7 root root  0 Feb  3 18:37 ..
lrwx------ 1 root root 64 Feb  3 18:37 4 -> socket:[3447070]
lrwx------ 1 root root 64 Feb  3 18:37 3 -> socket:[3447069]
lrwx------ 1 root root 64 Feb  3 18:37 2 -> /dev/pts/0
lrwx------ 1 root root 64 Feb  3 18:37 1 -> /dev/pts/0
lrwx------ 1 root root 64 Feb  3 18:37 0 -> /dev/pts/0
dr-x------ 2 root root  0 Feb  3 18:37 .
[root@dm0103 ~]#
```

There is an dependency between ipv6 and CRS on an Exadata, disabling ipv6 will cripple your clusterware. There is no real solution for this problem because we need ipv6 on an Exadata, we can’t disable it. However we van easily reduce the amount of ipv6 DNS lookups by extending our /etc/hosts file and adding all hostnames, vip names etc. of all our hosts in our cluster in every single hostfile on computenodes. Unfortunately we can’t do this on our Cell servers, because oracle does not want us to go ‘messing’ with them so you have to live with it for now.