Friday Oct 24, 2014

Onion Security

This blog is part of the SPARC T5-4 RAC and WebLogic Cluster series: including:

I was asked why I used so many subnets in the system which is described in my blog entry SPARC T5-4 LDoms for RAC and WebLogic Clusters:
  • Management Subnet
  • HTTP Public Network
  • JDBC subnet
  • Storage subnet
The short answer: I didn't need to. I could have used one public network and one RAC private network.

Longer answer:
  • Better observability
  • Better isolation
  • It enables a better security model


Onion View





LDom View




If Joe Blackhat is able to compromise our HTTP server, that is a bad thing, but hopefully he will only be able access a subset of the data.  To get any additional data, he will need to request the data from the WebLogic server. The HTTP to WebLogic network layer can be monitored, firewalled, and logged. Again, if Joe Blackhat is able to penetrate one layer deeper, into the WebLogic layer, he will only be able to access additional data via JDBC calls to Oracle RAC. Again, the WebLogic to RAC network layer can be monitored, firewalled, and logged. And so forth...

In case it isn't obvious, the management network is intended to be used only infrequently by DBA's and System Administrators. This network should be tightly controlled and only enabled when system administration is required.

Saturday Oct 11, 2014

netperf on Solaris 11


I wanted to use netperf 2.6.0 on Solaris 11. See http://www.netperf.org/netperf/ for details.

I had this error when I tried to build:

$ make
make  all-recursive
Making all in src
Making all in missing
Making all in m4
gcc -DHAVE_CONFIG_H -I. -I..       -MT netlib.o -MD -MP -MF .deps/netlib.Tpo -c -o netlib.o netlib.c
In file included from netlib.c:2245:0:
/usr/include/sys/processor.h: In function ‘bind_to_specific_processor’:
/usr/include/sys/processor.h:128:12: error: ‘processor_affinity’ redeclared as different kind of symbol
netlib.c:2222:32: note: previous definition of ‘processor_affinity’ was here


This was with gcc version 4.5.2.

Made the following changes in src/netlib.c:

$ diff netlib.c.ORIG netlib.c
2222c2222
< bind_to_specific_processor(int processor_affinity, int use_cpu_map)
---
> bind_to_specific_processor(int j_processor_affinity, int use_cpu_map)

2233c2233

<     mapped_affinity = lib_cpu_map[processor_affinity];
---
>     mapped_affinity = lib_cpu_map[j_processor_affinity];

2236c2236

<     mapped_affinity = processor_affinity;
---
>     mapped_affinity = j_processor_affinity;


And all was good.

FYI, I added these settings to increase performance on the 10-Gb network:

/usr/sbin/ndd -set /dev/tcp tcp_conn_req_max_q 16384
/usr/sbin/ndd -set /dev/tcp tcp_conn_req_max_q0 16384
/usr/sbin/ndd -set /dev/tcp tcp_max_buf 2097152
/usr/sbin/ndd -set /dev/tcp tcp_xmit_hiwat 524288
/usr/sbin/ndd -set /dev/tcp tcp_recv_hiwat 524288
/usr/sbin/ndd -set /dev/tcp tcp_cwnd_max 2097152


The performance on the 10-Gb network is about 30% faster with the tunables in place. The 1-Gb networks is not faster than it had been.

See "ndd on Solaris 10" - https://blogs.oracle.com/taylor22/entry/ndd_on_solaris_10

Performance now looks good:

$ / usr/local/bin/netperf -fg -H my-server
MIGRATED TCP STREAM TEST from 0.0.0.0 (0.0.0.0) port 0 AF_INET to my-server () port 0 AF_INET
Recv   Send    Send                         
Socket Socket  Message  Elapsed             
Size   Size    Size     Time     Throughput 
bytes  bytes   bytes    secs.    10^9bits/sec 

524288  65536  65536    10.00       9.90

References:
  1. My blog about ndd settings on Solaris
  2. How to Measure the Network Bandwidth Between Solaris Nodes?
  3. 2009 article about Netperf 2.4.5 on Solaris

Hope this helps.

Monday Sep 08, 2014

emca and ORA-12537: TNS:connection closed

Problem: I couldn't configure Enterprise Manager for a RAC database running on two SPARC T5-4 Servers

$ emca -deconfig dbcontrol db -repos drop  -cluster
$ emca -config dbcontrol db -repos create -cluster

STARTED EMCA at Sep 6, 2014 1:03:42 PM
EM Configuration Assistant, Version 11.2.0.3.0 Production
Copyright (c) 2003, 2011, Oracle.  All rights reserved.

Enter the following information:
Database unique name: orcl2
Service name: orcl2
Listener port number: 1521
Listener ORACLE_HOME [ /u01/app/11.2.0/grid ]:
Password for SYS user: 
Password for DBSNMP user: 
Password for SYSMAN user: 40
Cluster name: ofsaa-scan
Email address for notifications (optional):
Outgoing Mail (SMTP) server for notifications (optional):
-----------------------------------------------------------------

You have specified the following settings

Database ORACLE_HOME ................ /u01/app/oracle/product/11.2.0/dbhome_1

Database instance hostname ................ Listener ORACLE_HOME ................ /u01/app/11.2.0/grid
Listener port number ................ 1521
Cluster name ................ proj-scan
Database unique name ................ orcl2
Email address for notifications ...............
Outgoing Mail (SMTP) server for notifications ...............

-----------------------------------------------------------------
Do you wish to continue? [yes(Y)/no(N)]: y
Sep 6, 2014 1:04:28 PM oracle.sysman.emcp.EMConfig perform
INFO: This operation is being logged at /u01/app/oracle/cfgtoollogs/emca/orcl2/emca_2014_09_06_13_03_41.log.
Sep 6, 2014 1:04:33 PM oracle.sysman.emcp.EMReposConfig createRepository
INFO: Creating the EM repository (this may take a while) ...
Sep 6, 2014 1:09:20 PM oracle.sysman.emcp.EMReposConfig invoke
INFO: Repository successfully created
Sep 6, 2014 1:09:22 PM oracle.sysman.emcp.util.GeneralUtil initSQLEngineRemotely
WARNING: Error during db connection : ORA-12537: TNS:connection closed

Sep 6, 2014 1:09:33 PM oracle.sysman.emcp.EMReposConfig invoke
SEVERE: Failed to unlock all EM-related accounts
Sep 6, 2014 1:09:33 PM oracle.sysman.emcp.EMConfig perform
SEVERE: Failed to unlock all EM-related accounts
Refer to the log file at /u01/app/oracle/cfgtoollogs/emca/orcl2/emca_2014_09_06_13_03_41.log for more details.
Could not complete the configuration. Refer to the log file at /u01/app/oracle/cfgtoollogs/emca/orcl2/emca_2014_09_06_13_03_41.log for more details.


Very strange. Everything else seemed fine.

$ srvctl status scan
$ srvctl status scan_listener
$ srvctl status listener
$ srvctl status database -d orcl2


I spent so many hours digging through log files, listener.ora, tnsnames.ora, running netca and netmgr. Nothing helped.

Two other strange things that I eventually noticed.
- sqlplus connections to the SCAN address had intermittent failures.
- Successful connections where always to one instance, never the other.

All of the failures where ORA-12537: TNS:connection closed

Eventually, I found MOS note 1069517.1, "ORA-12537 / ORA-12547 or TNS-12518 if Listener (including SCAN Listener) and Database are Owned by Different OS User". Sure enough, on one SPARC T5-4 servers, the setgid bit wasn't set on the oracle executable, but it was set on the other server.

# export ORACLE_HOME=/u01/app/oracle/product/11.2.0/dbhome_1
# cd $ORACLE_HOME/bin
# chmod u+s oradism nmo nmhs emtgtctl2 jssu extjob nmb oracle
# chmod g+s emtgtctl2 oracle


Monday Aug 25, 2014

Installing VNC server on Solaris 11

I tend to forget the exact command line for installing VNC on Solaris 11.

VNC isn't installed by default:

# vncserver
-bash: vncserver: command not found


But it is in the repository. (You need to use the --accept option because java/jre-7  requires BCL License acceptance )

# pkg install --accept solaris-desktop
           Packages to install: 463
           Mediators to change:   1
            Services to change:  16
       Create boot environment:  No
Create backup boot environment:  No
DOWNLOAD                                PKGS         FILES    XFER (MB)   SPEED
Completed                            463/463   68277/68277  729.0/729.0  6.2M/s

PHASE                                          ITEMS
Installing new actions                   104012/104012
Updating package state database                 Done
Updating package cache                           0/0
Updating image state                            Done
Creating fast lookup database                   Done
Updating package cache                           2/2
You have new mail in /var/mail/root


Now the VNC server is installed:

$ vncserver

You will require a password to access your desktops.

Password:
Verify:
xauth:  file /home/jeff/.Xauthority does not exist

New 'my-host:1 (root)' desktop is my-host:1

Creating default startup script /home/jeff/.vnc/xstartup
Starting applications specified in /home/jeff/.vnc/xstartup
Log file is /home/jeff/.vnc/my-host:1.log


By default, you get the tiled window manager (twm), but I prefer Gnome.

# vi /home/jeff/.vnc/xstartup

At the bottom of xstartup, change "twm &" -to- "gnome-session &":

Kill the session running twm and restart with Gnome:

$ vncserver -kill :1
Killing Xvnc process ID 2392

$ vncserver

New 'my-host:1 (root)' desktop is my-host:1

Starting applications specified in /home/jeff/.vnc/xstartup
Log file is /home/jeff/.vnc/my-host:1.log


Now you're good to go. Visit the vncserver with a vncclient:

vnc.png

You may also want to review:

Hope this helps.

Wednesday Aug 20, 2014

Quadratic Programming with Oracle R Enterprise

     I wanted to use quadprog with ORE on a server running Oracle Solaris 11.2 on a Oracle SPARC T-4 server

For background, see:


Problem: path to Solaris Studio doesn't match my installation:

$ ORE CMD INSTALL quadprog_1.5-5.tar.gz
* installing to library \u2018/u01/app/oracle/product/12.1.0/dbhome_1/R/library\u2019
* installing *source* package \u2018quadprog\u2019 ...
** package \u2018quadprog\u2019 successfully unpacked and MD5 sums checked
** libs
/opt/SunProd/studio12u3/solarisstudio12.3/bin/f95 -m64   -PIC  -g  -c aind.f -o aind.o
bash: /opt/SunProd/studio12u3/solarisstudio12.3/bin/f95: No such file or directory
*** Error code 1
make: Fatal error: Command failed for target `aind.o'
ERROR: compilation failed for package \u2018quadprog\u2019
* removing \u2018/u01/app/oracle/product/12.1.0/dbhome_1/R/library/quadprog\u2019

$ ls -l /opt/solarisstudio12.3/bin/f95
lrwxrwxrwx   1 root     root          15 Aug 19 17:36 /opt/solarisstudio12.3/bin/f95 -> ../prod/bin/f90

Solution: a symbolic link:

$ sudo mkdir -p /opt/SunProd/studio12u3

$ sudo ln -s /opt/solarisstudio12.3 /opt/SunProd/studio12u3/

Now, it is all good:

$ ORE CMD INSTALL quadprog_1.5-5.tar.gz
* installing to library \u2018/u01/app/oracle/product/12.1.0/dbhome_1/R/library\u2019
* installing *source* package \u2018quadprog\u2019 ...
** package \u2018quadprog\u2019 successfully unpacked and MD5 sums checked
** libs
/opt/SunProd/studio12u3/solarisstudio12.3/bin/f95 -m64   -PIC  -g  -c aind.f -o aind.o
/opt/SunProd/studio12u3/solarisstudio12.3/bin/ cc -xc99 -m64 -I/usr/lib/64/R/include -DNDEBUG -KPIC  -xlibmieee  -c init.c -o init.o
/opt/SunProd/studio12u3/solarisstudio12.3/bin/f95 -m64  -PIC -g  -c -o solve.QP.compact.o solve.QP.compact.f
/opt/SunProd/studio12u3/solarisstudio12.3/bin/f95 -m64  -PIC -g  -c -o solve.QP.o solve.QP.f
/opt/SunProd/studio12u3/solarisstudio12.3/bin/f95 -m64   -PIC  -g  -c util.f -o util.o
/opt/SunProd/studio12u3/solarisstudio12.3/bin/ cc -xc99 -m64 -G -o quadprog.so aind.o init.o solve.QP.compact.o solve.QP.o util.o -xlic_lib=sunperf -lsunmath -lifai -lsunimath -lfai -lfai2 -lfsumai -lfprodai -lfminlai -lfmaxlai -lfminvai -lfmaxvai -lfui -lfsu -lsunmath -lmtsk -lm -lifai -lsunimath -lfai -lfai2 -lfsumai -lfprodai -lfminlai -lfmaxlai -lfminvai -lfmaxvai -lfui -lfsu -lsunmath -lmtsk -lm -L/usr/lib/64/R/lib -lR
installing to /u01/app/oracle/product/12.1.0/dbhome_1/R/library/quadprog/libs
** R
** preparing package for lazy loading
** help
*** installing help indices
  converting help for package \u2018quadprog\u2019
    finding HTML links ... done
    solve.QP                                html 
    solve.QP.compact                        html 
** building package indices
** testing if installed package can be loaded
* DONE (quadprog)

======

Here is an example from http://cran.r-project.org/web/packages/quadprog/quadprog.pdf

> require(quadprog)
> Dmat <- matrix(0,3,3)
> diag(Dmat) <- 1
> dvec <- c(0,5,0)
> Amat <- matrix(c(-4,-3,0,2,1,0,0,-2,1),3,3)
> bvec <- c(-8,2,0)
> solve.QP(Dmat,dvec,Amat,bvec=bvec)
$solution
[1] 0.4761905 1.0476190 2.0952381

$value
[1] -2.380952

$unconstrained.solution
[1] 0 5 0

$iterations
[1] 3 0

$Lagrangian
[1] 0.0000000 0.2380952 2.0952381

$iact
[1] 3 2


Here, the standard example is modified to work with Oracle R Enterprise


require(ORE)
ore.connect("my-name", "my-sid", "my-host", "my-pass", 1521)

ore.doEval(
  function () {
    require(quadprog)
  }
)

ore.doEval(
  function () {
    Dmat <- matrix(0,3,3)
    diag(Dmat) <- 1
    dvec <- c(0,5,0)
    Amat <- matrix(c(-4,-3,0,2,1,0,0,-2,1),3,3)
    bvec <- c(-8,2,0)
    solve.QP(Dmat,dvec,Amat,bvec=bvec)
  }
)

$solution
[1] 0.4761905 1.0476190 2.0952381

$value
[1] -2.380952

$unconstrained.solution
[1] 0 5 0

$iterations
[1] 3 0

$Lagrangian
[1] 0.0000000 0.2380952 2.0952381

$iact
[1] 3 2

Now I can combine the quadprog compute algorithms with the Oracle R Enterprise Database engine functionality:
  • Scale to large datasets
  • Access to tables, views, and external tables in the database, as well as those accessible through database links
  • Use SQL query parallel execution
  • Use in-database statistical and data mining functionality

Monday Aug 18, 2014

SPARC T5-4 LDoms for RAC and WebLogic Clusters

This blog is part of the SPARC T5-4 RAC and WebLogic Cluster series:

I wanted to use two Oracle SPARC T5-4 servers to simultaneously host both Oracle RAC and a WebLogic Server Cluster. I chose to use Oracle VM Server for SPARC to create a cluster like this:


There are plenty of trade offs and decisions that need to be made, for example:


Both Oracle SPARC T5-4 servers were to be configured like this:


Cntl
0.25
 4 
64GB

                    App LDom
                   2.75 CPU's                   
                    44 cores                    
                     704 GB        
     DB LDom
     One CPU    
     16 cores   

      256 GB  


The systems started with everything in the primary domain:

# ldm list
NAME             STATE      FLAGS   CONS    VCPU  MEMORY   UTIL  NORM  UPTIME
primary          active     -n-c--  UART    512   1023G    0.0%  0.0%  11m

# ldm list-spconfig
factory-default [current]
primary

# ldm list -o core,memory,physio
NAME             
primary          

CORE
    CID    CPUSET
    0      (0, 1, 2, 3, 4, 5, 6, 7)
    1      (8, 9, 10, 11, 12, 13, 14, 15)
    2      (16, 17, 18, 19, 20, 21, 22, 23)
-- SNIP
    62     (496, 497, 498, 499, 500, 501, 502, 503)
    63     (504, 505, 506, 507, 508, 509, 510, 511)

MEMORY
    RA               PA               SIZE            
    0x30000000       0x30000000       255G
    0x80000000000    0x80000000000    256G
    0x100000000000   0x100000000000   256G
    0x180000000000  
0x180000000000   256G # Give this memory block to the DB LDom

IO
    DEVICE                           PSEUDONYM        OPTIONS
    pci@300                          pci_0           
    pci@340                          pci_1           
    pci@380                          pci_2           
    pci@3c0                          pci_3           
    pci@400                          pci_4           
    pci@440                          pci_5           
    pci@480                          pci_6           
    pci@4c0                          pci_7           
    pci@300/pci@1/pci@0/pci@6        /SYS/RCSA/PCIE1
    pci@300/pci@1/pci@0/pci@c        /SYS/RCSA/PCIE2
    pci@300/pci@1/pci@0/pci@4/pci@0/pci@c /SYS/MB/SASHBA0
    pci@300/pci@1/pci@0/pci@4/pci@0/pci@8 /SYS/RIO/NET0   
    pci@340/pci@1/pci@0/pci@6        /SYS/RCSA/PCIE3
    pci@340/pci@1/pci@0/pci@c        /SYS/RCSA/PCIE4
    pci@380/pci@1/pci@0/pci@a        /SYS/RCSA/PCIE9
    pci@380/pci@1/pci@0/pci@4        /SYS/RCSA/PCIE10
    pci@3c0/pci@1/pci@0/pci@e        /SYS/RCSA/PCIE11
    pci@3c0/pci@1/pci@0/pci@8        /SYS/RCSA/PCIE12
    pci@400/pci@1/pci@0/pci@e        /SYS/RCSA/PCIE5
    pci@400/pci@1/pci@0/pci@8        /SYS/RCSA/PCIE6
    pci@440/pci@1/pci@0/pci@e        /SYS/RCSA/PCIE7
    pci@440/pci@1/pci@0/pci@8        /SYS/RCSA/PCIE8
    pci@480/pci@1/pci@0/pci@a        /SYS/RCSA/PCIE13
    pci@480/pci@1/pci@0/pci@4        /SYS/RCSA/PCIE14
    pci@4c0/pci@1/pci@0/pci@8        /SYS/RCSA/PCIE15
    pci@4c0/pci@1/pci@0/pci@4        /SYS/RCSA/PCIE16
    pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@c /SYS/MB/SASHBA1
    pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@4 /SYS/RIO/NET2   


Added an additional service processor configuration:

# ldm add-spconfig split

# ldm list-spconfig
factory-default
primary
split [current]


And removed many of the resources from the primary domain:

# ldm start-reconf primary
# ldm set-core 4 primary
# ldm set-memory 32G primary
# ldm rm-io pci@340 primary
# ldm rm-io pci@380 primary
# ldm rm-io pci@3c0 primary
# ldm rm-io pci@400 primary
# ldm rm-io pci@440 primary
# ldm rm-io pci@480 primary
# ldm rm-io pci@4c0 primary
# init 6


Needed to add resources to the guest domains:

# ldm add-domain db

# ldm set-core cid=`seq -s"," 48 63` db

# ldm add-memory mblock=0x180000000000:256G db


# ldm add-io pci@480 db

# ldm add-io pci@4c0 db


# ldm add-domain app

# ldm set-core 44 app
# ldm set-memory 704G  app

# ldm add-io pci@340 app
# ldm add-io pci@380 app
# ldm add-io pci@3c0 app
# ldm add-io pci@400 app
# ldm add-io pci@440 app




Needed to set up services:

# ldm add-vds primary-vds0 primary
# ldm add-vcc port-range=5000-5100 primary-vcc0 primary


Needed to add a virtual network port for the WebLogic application domain:

# ipadm
NAME              CLASS/TYPE STATE        UNDER      ADDR
lo0               loopback   ok           --         --
   lo0/v4         static     ok           --         ...
   lo0/v6         static     ok           --         ...
net0              ip         ok           --         ...
   net0/v4        static     ok           --         xxx.xxx.xxx.xxx/24
   net0/v6        addrconf   ok           --         ....
   net0/v6        addrconf   ok           --         ...
net8              ip         ok           --         --
   net8/v4        static     ok           --         ...

# dladm show-phys
LINK              MEDIA                STATE      SPEED  DUPLEX    DEVICE
net1              Ethernet             unknown    0      unknown   ixgbe1
net0              Ethernet             up         1000   full      ixgbe0
net8              Ethernet             up         10     full      usbecm2

# ldm add-vsw net-dev=net0 primary-vsw0 primary
# ldm add-vnet vnet1 primary-vsw0 app


Needed to add a virtual disk to the WebLogic application domain:

# format
Searching for disks...done


AVAILABLE DISK SELECTIONS:
       0. c0t5000CCA02505F874d0 <HITACHI-H106060SDSUN600G-A2B0-558.91GB>
          /scsi_vhci/disk@g5000cca02505f874
          /dev/chassis/SPARC_T5-4.AK00084038/SYS/SASBP0/HDD0/disk
       1. c0t5000CCA02506C468d0 <HITACHI-H106060SDSUN600G-A2B0-558.91GB>
          /scsi_vhci/disk@g5000cca02506c468
          /dev/chassis/SPARC_T5-4.AK00084038/SYS/SASBP0/HDD1/disk

       2. c0t5000CCA025067E5Cd0 <HITACHI-H106060SDSUN600G-A2B0-558.91GB>
          /scsi_vhci/disk@g5000cca025067e5c
          /dev/chassis/SPARC_T5-4.AK00084038/SYS/SASBP0/HDD2/disk
       3. c0t5000CCA02506C258d0 <HITACHI-H106060SDSUN600G-A2B0-558.91GB>
          /scsi_vhci/disk@g5000cca02506c258
          /dev/chassis/SPARC_T5-4.AK00084038/SYS/SASBP0/HDD3/disk
Specify disk (enter its number): ^C

# ldm add-vdsdev /dev/dsk/c0t5000CCA02506C468d0s2 HDD1@primary-vds0
# ldm add-vdisk HDD1 HDD1@primary-vds0 app



Add some additional spice to the pot:

# ldm set-variable auto-boot\\?=false db
# ldm set-variable auto-boot\\?=false app
# ldm set-var boot-device=HDD1 app


Bind the logical domains:

# ldm bind db
# ldm bind app


At the end of the process, the system is set up like this:

# ldm list -o core,memory,physio
NAME            
primary         

CORE
    CID    CPUSET
    0      (0, 1, 2, 3, 4, 5, 6, 7)
    1      (8, 9, 10, 11, 12, 13, 14, 15)
    2      (16, 17, 18, 19, 20, 21, 22, 23)
    3      (24, 25, 26, 27, 28, 29, 30, 31)

MEMORY
    RA               PA               SIZE           
    0x30000000       0x30000000       32G

IO
    DEVICE                           PSEUDONYM        OPTIONS
    pci@300                          pci_0          
    pci@300/pci@1/pci@0/pci@6        /SYS/RCSA/PCIE1
    pci@300/pci@1/pci@0/pci@c        /SYS/RCSA/PCIE2
    pci@300/pci@1/pci@0/pci@4/pci@0/pci@c /SYS/MB/SASHBA0
    pci@300/pci@1/pci@0/pci@4/pci@0/pci@8 /SYS/RIO/NET0  
------------------------------------------------------------------------------

NAME            
app             

CORE
    CID    CPUSET
    4      (32, 33, 34, 35, 36, 37, 38, 39)
    5      (40, 41, 42, 43, 44, 45, 46, 47)
    6      (48, 49, 50, 51, 52, 53, 54, 55)
    7      (56, 57, 58, 59, 60, 61, 62, 63)
    8      (64, 65, 66, 67, 68, 69, 70, 71)
    9      (72, 73, 74, 75, 76, 77, 78, 79)
    10     (80, 81, 82, 83, 84, 85, 86, 87)
    11     (88, 89, 90, 91, 92, 93, 94, 95)
    12     (96, 97, 98, 99, 100, 101, 102, 103)
    13     (104, 105, 106, 107, 108, 109, 110, 111)
    14     (112, 113, 114, 115, 116, 117, 118, 119)
    15     (120, 121, 122, 123, 124, 125, 126, 127)
    16     (128, 129, 130, 131, 132, 133, 134, 135)
    17     (136, 137, 138, 139, 140, 141, 142, 143)
    18     (144, 145, 146, 147, 148, 149, 150, 151)
    19     (152, 153, 154, 155, 156, 157, 158, 159)
    20     (160, 161, 162, 163, 164, 165, 166, 167)
    21     (168, 169, 170, 171, 172, 173, 174, 175)
    22     (176, 177, 178, 179, 180, 181, 182, 183)
    23     (184, 185, 186, 187, 188, 189, 190, 191)
    24     (192, 193, 194, 195, 196, 197, 198, 199)
    25     (200, 201, 202, 203, 204, 205, 206, 207)
    26     (208, 209, 210, 211, 212, 213, 214, 215)
    27     (216, 217, 218, 219, 220, 221, 222, 223)
    28     (224, 225, 226, 227, 228, 229, 230, 231)
    29     (232, 233, 234, 235, 236, 237, 238, 239)
    30     (240, 241, 242, 243, 244, 245, 246, 247)
    31     (248, 249, 250, 251, 252, 253, 254, 255)
    32     (256, 257, 258, 259, 260, 261, 262, 263)
    33     (264, 265, 266, 267, 268, 269, 270, 271)
    34     (272, 273, 274, 275, 276, 277, 278, 279)
    35     (280, 281, 282, 283, 284, 285, 286, 287)
    36     (288, 289, 290, 291, 292, 293, 294, 295)
    37     (296, 297, 298, 299, 300, 301, 302, 303)
    38     (304, 305, 306, 307, 308, 309, 310, 311)
    39     (312, 313, 314, 315, 316, 317, 318, 319)
    40     (320, 321, 322, 323, 324, 325, 326, 327)
    41     (328, 329, 330, 331, 332, 333, 334, 335)
    42     (336, 337, 338, 339, 340, 341, 342, 343)
    43     (344, 345, 346, 347, 348, 349, 350, 351)
    44     (352, 353, 354, 355, 356, 357, 358, 359)
    45     (360, 361, 362, 363, 364, 365, 366, 367)
    46     (368, 369, 370, 371, 372, 373, 374, 375)
    47     (376, 377, 378, 379, 380, 381, 382, 383)

MEMORY
    RA               PA               SIZE           
    0x30000000       0x830000000      192G
    0x4000000000     0x80000000000    256G
    0x8080000000     0x100000000000   256G

IO
    DEVICE                           PSEUDONYM        OPTIONS
    pci@340                          pci_1          
    pci@380                          pci_2          
    pci@3c0                          pci_3          
    pci@400                          pci_4          
    pci@440                          pci_5          
    pci@340/pci@1/pci@0/pci@6        /SYS/RCSA/PCIE3
    pci@340/pci@1/pci@0/pci@c        /SYS/RCSA/PCIE4
    pci@380/pci@1/pci@0/pci@a        /SYS/RCSA/PCIE9
    pci@380/pci@1/pci@0/pci@4        /SYS/RCSA/PCIE10
    pci@3c0/pci@1/pci@0/pci@e        /SYS/RCSA/PCIE11
    pci@3c0/pci@1/pci@0/pci@8        /SYS/RCSA/PCIE12
    pci@400/pci@1/pci@0/pci@e        /SYS/RCSA/PCIE5
    pci@400/pci@1/pci@0/pci@8        /SYS/RCSA/PCIE6
    pci@440/pci@1/pci@0/pci@e        /SYS/RCSA/PCIE7
    pci@440/pci@1/pci@0/pci@8        /SYS/RCSA/PCIE8
------------------------------------------------------------------------------

NAME            
db              

CORE
    CID    CPUSET
    48     (384, 385, 386, 387, 388, 389, 390, 391)
    49     (392, 393, 394, 395, 396, 397, 398, 399)
    50     (400, 401, 402, 403, 404, 405, 406, 407)
    51     (408, 409, 410, 411, 412, 413, 414, 415)
    52     (416, 417, 418, 419, 420, 421, 422, 423)
    53     (424, 425, 426, 427, 428, 429, 430, 431)
    54     (432, 433, 434, 435, 436, 437, 438, 439)
    55     (440, 441, 442, 443, 444, 445, 446, 447)
    56     (448, 449, 450, 451, 452, 453, 454, 455)
    57     (456, 457, 458, 459, 460, 461, 462, 463)
    58     (464, 465, 466, 467, 468, 469, 470, 471)
    59     (472, 473, 474, 475, 476, 477, 478, 479)
    60     (480, 481, 482, 483, 484, 485, 486, 487)
    61     (488, 489, 490, 491, 492, 493, 494, 495)
    62     (496, 497, 498, 499, 500, 501, 502, 503)
    63     (504, 505, 506, 507, 508, 509, 510, 511)

MEMORY
    RA               PA               SIZE           
    0x80000000       0x180000000000   256G

IO
    DEVICE                           PSEUDONYM        OPTIONS
    pci@480                          pci_6          
    pci@4c0                          pci_7          
    pci@480/pci@1/pci@0/pci@a        /SYS/RCSA/PCIE13
    pci@480/pci@1/pci@0/pci@4        /SYS/RCSA/PCIE14
    pci@4c0/pci@1/pci@0/pci@8        /SYS/RCSA/PCIE15
    pci@4c0/pci@1/pci@0/pci@4        /SYS/RCSA/PCIE16
    pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@c /SYS/MB/SASHBA1
    pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@4 /SYS/RIO/NET2  


Start the domains:

# ldm start app
LDom app started

# ldm start db
LDom db started


Make sure to start the vntsd service that was created, above.

# svcs -a | grep ldo
disabled        8:38:38 svc:/ldoms/vntsd:default
online          8:38:58 svc:/ldoms/agents:default
online          8:39:25 svc:/ldoms/ldmd:default

# svcadm enable vntsd



Now use the MAC address to configure the Solaris 11 Automated Installation.


Database Logical Domain
# telnet localhost 5000
{0} ok devalias
screen                   /pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@7/display@0
disk7                    /pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@c/scsi@0/disk@p3
disk6                    /pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@c/scsi@0/disk@p2
disk5                    /pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@c/scsi@0/disk@p1
disk4                    /pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@c/scsi@0/disk@p0
scsi1                    /pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@c/scsi@0
net3                     /pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@4/network@0,1
net2                     /pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@4/network@0
virtual-console          /virtual-devices/console@1
name                     aliases
{0} ok boot net2
Boot device: /pci@4c0/pci@1/pci@0/pci@c/pci@0/pci@4/network@0  File and args:
1000 Mbps full duplex Link up
Requesting Internet Address for xx:xx:xx:xx:xx:xx

Requesting Internet Address for xx:xx:xx:xx:xx:xx
WLS Logical Domain
# telnet localhost 5001
{0} ok devalias
hdd1                     /virtual-devices@100/channel-devices@200/disk@0
vnet1                    /virtual-devices@100/channel-devices@200/network@0
net                      /virtual-devices@100/channel-devices@200/network@0
disk                     /virtual-devices@100/channel-devices@200/disk@0
virtual-console          /virtual-devices/console@1
name                     aliases
{0} ok boot net
Boot device: /virtual-devices@100/channel-devices@200/network@0  File and args:
Requesting Internet Address for xx:xx:xx:xx:xx:xx

Requesting Internet Address for xx:xx:xx:xx:xx:xx

Repeat the process for the second SPARC T5-4, install Solaris, RAC and WebLogic Cluster, and you are ready to go. Maybe buying a SuperCluster would have been easier.

Tuesday Jul 22, 2014

VNC Cut & Paste on Solaris 10

I love being able to cut & paste between my laptop (e-mail, web browser, etc.) and my VNC session. This functionality is controlled by vncconfig. From the man page:

vncconfig is used to configure and control a running
instance of Xvnc, or any other X server with the VNC exten-
sion. Note that it cannot be used to control VNC servers
prior to version 4.

I hate this message:

$ vncconfig
No VNC extension on display :1.0


When I hit the problem again, I found my way back to one of my old blog entries: Solaris/x64 VNC with Cut & Paste, but this time, the situation was slightly different:
  • On SPARC
  • SFWvnc was not installed
When I re-read my old blog, it didn't seem to apply.

But I found:

$ which Xvnc
/ usr/local/bin/Xvnc

$ pkginfo -L | grep vnc
SUNWvncviewer
SUNWxvnc

$ /usr/sbin/pkgchk -l SUNWxvnc | grep Xvnc
NOTE: Couldn't lock the package database.
Pathname: /usr/X11/bin/Xvnc
Pathname: /usr/X11/share/man/man1/Xvnc.1


Someone had put Xvnc version 3.x in /usr/local. Because /usr/local was near the start of my PATH, I wasn't using the version of Xvnc that is supplied with Solaris 10 Update 10.

Again, the solution is simple.

1) Kill the running Xvnc process

2) Start a new Xvnc process using the Solaris supplied executable

$ export PATH=/usr/X11/bin:$PATH
$ vncviewer


3) Use a VNC viewer to visit the Xvnc server and run vncconfig:

$ vncconfig &

vncconfig.png

4) Now, cut & paste works between my laptop (e-mail, web browser, etc.) and my VNC session.

5) You will want to make sure that vncconfig is started automatically in your .vnc/xstartup file.

Hope this helps!

Tuesday May 27, 2014

Using R to analyze Java G1 garbage collector log files

Introduction

Working in Oracle Platform Integration gives an engineer opportunities to work on a wide array of technologies. My team’s goal is to make Oracle applications run best on the Solaris/SPARC platform. When looking for bottlenecks in a modern application, one needs to be aware of not only how the CPUs and operating system are executing, but also network, storage, and in some cases, the Java Virtual Machine.

I was recently presented with about 1.5 GB of Java Garbage First (G1) Garbage Collector log file data. If you’re not familiar with the subject, you might want to review Garbage First Garbage Collector Tuning by Monica Beckwith. The customer had been running Java HotSpot 1.6.0_31 to host a web application server. The logs are from a very early implementation of the G1 collector, prior to it becoming supported. The G1 collector is supported starting in JDK 7 update 4 and there are substantial performance improvements between the experimental version and the supported version.

I was told that the Solaris/SPARC server was running a Java process launched using a command line that included the following flags: -d64 -Xms9g -Xmx9g -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:InitiatingHeapOccupancyPercent=80 -XX:PermSize=256m -XX:MaxPermSize=256m -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintGCDateStamps -XX:+PrintFlagsFinal -XX:+DisableExplicitGC -XX:+UnlockExperimentalVMOptions -XX:ParallelGCThreads=8

Several sources on the internet indicate that if I were to print out the 1.5 GB of log files, it would require enough paper to fill the bed of a pick up truck. Of course, it would be fruitless to try to scan the log files by hand. Tools will be required to summarize the contents of the log files.

Others have encountered large Java garbage collection log files. There are existing tools to analyze the log files:

  • IBM’s GC toolkit
  • The chewiebug GCViewer
  • gchisto
  • HPjmeter

Instead of using one of the other tools listed, I decide to parse the log files with standard Unix tools, and analyze the data with R. From the R project's home page, "R is a free software environment for statistical computing and graphics. It compiles and runs on a wide variety of UNIX platforms, Windows and MacOS." If you would like to install R, there are many options for downloading R, including:

  • one of the CRAN mirrors listed at http://cran.r-project.org/mirrors.html
  • the Oracle R Distribution from https://oss.oracle.com/ORD/

Data Cleansing

The log files arrived in two different formats. I guess that the difference is that one set of log files was generated using a more verbose option, maybe -XX:+PrintHeapAtGC, and the other set of log files was generated without that option.

Format 1

In some of the log files, the log files with the less verbose format, a single trace, i.e. the report of a singe garbage collection event, looks like this:

{Heap before GC invocations=12280 (full 61):
 garbage-first heap   total 9437184K, used 7499918K [0xfffffffd00000000, 0xffffffff40000000, 0xffffffff40000000)
  region size 4096K, 1 young (4096K), 0 survivors (0K)
 compacting perm gen  total 262144K, used 144077K [0xffffffff40000000, 0xffffffff50000000, 0xffffffff50000000)
   the space 262144K,  54% used [0xffffffff40000000, 0xffffffff48cb3758, 0xffffffff48cb3800, 0xffffffff50000000)
No shared spaces configured.
2014-05-14T07:24:00.988-0700: 60586.353: [GC pause (young) 7324M->7320M(9216M), 0.1567265 secs]
Heap after GC invocations=12281 (full 61):
 garbage-first heap   total 9437184K, used 7496533K [0xfffffffd00000000, 0xffffffff40000000, 0xffffffff40000000)
  region size 4096K, 0 young (0K), 0 survivors (0K)
 compacting perm gen  total 262144K, used 144077K [0xffffffff40000000, 0xffffffff50000000, 0xffffffff50000000)
   the space 262144K,  54% used [0xffffffff40000000, 0xffffffff48cb3758, 0xffffffff48cb3800, 0xffffffff50000000)
No shared spaces configured.
}

A simple grep can be used to extract a summary:

$ grep "\[ GC pause (young"  g1gc.log
2014-05-13T13:24:35.091-0700: 3.109: [GC pause (young) 20M->5029K(9216M), 0.0146328 secs]
2014-05-13T13:24:35.440-0700: 3.459: [GC pause (young) 9125K->6077K(9216M), 0.0086723 secs]
2014-05-13T13:24:37.581-0700: 5.599: [GC pause (young) 25M->8470K(9216M), 0.0203820 secs]
2014-05-13T13:24:42.686-0700: 10.704: [GC pause (young) 44M->15M(9216M), 0.0288848 secs]
2014-05-13T13:24:48.941-0700: 16.958: [GC pause (young) 51M->20M(9216M), 0.0491244 secs]
2014-05-13T13:24:56.049-0700: 24.066: [GC pause (young) 92M->26M(9216M), 0.0525368 secs]
2014-05-13T13:25:34.368-0700: 62.383: [GC pause (young) 602M->68M(9216M), 0.1721173 secs]

But that format wasn't easily read into R, so I needed to be a bit more tricky. I used the following Unix command to create a summary file that was easy for R to read.

$ echo "SecondsSinceLaunch BeforeSize AfterSize TotalSize RealTime" > summary.txt 
$ grep "\[GC pause (young" g1gc.log | grep -v mark | sed -e 's/[A-SU-z\(\),]/ /g' -e 's/->/  /' -e 's/: /  /g' >> summary.txt 
"SecondsSinceLaunch BeforeSize AfterSize TotalSize RealTime
2014-05-13T13:24:35.091-0700  3.109                    20   5029  9216    0.0146328      
2014-05-13T13:24:35.440-0700  3.459                    9125   6077  9216    0.0086723      
2014-05-13T13:24:37.581-0700  5.599                    25   8470  9216    0.0203820      
2014-05-13T13:24:42.686-0700  10.704                    44   15  9216    0.0288848      
2014-05-13T13:24:48.941-0700  16.958                    51   20  9216    0.0491244      
2014-05-13T13:24:56.049-0700  24.066                    92   26  9216    0.0525368      
2014-05-13T13:25:34.368-0700  62.383                    602   68  9216    0.1721173     

Format 2

In some of the log files, the log files with the more verbose format, a single trace, i.e. the report of a singe garbage collection event, was more complicated than Format 1. Here is a text file with an example of a single G1GC trace in the second format. As you can see, it is quite complicated. It is nice that there is so much information available, but the level of detail can be overwhelming.

I wrote this awk script (download) to summarize each trace on a single line.

#!/usr/bin/env awk -f

BEGIN {
    printf("SecondsSinceLaunch IncrementalCount FullCount UserTime SysTime RealTime BeforeSize AfterSize TotalSize\n")
}

######################
# Save count data from lines that are at the start of each G1GC trace.
# Each trace starts out like this:
#   {Heap before GC invocations=14 (full 0):
#    garbage-first heap   total 9437184K, used 325496K [0xfffffffd00000000, 0xffffffff40000000, 0xffffffff40000000)
######################
/{Heap.*full/{
    gsub ( "\\)" , "" );
    nf=split($0,a,"=");
    split(a[2],b," ");
    getline;
    if ( match($0, "first") ) { 
  G1GC=1;
  IncrementalCount=b[1];
	FullCount=substr( b[3], 1, length(b[3])-1 ); 
    } else {
        G1GC=0;
    }
}

######################
# Pull out time stamps that are in lines with this format:
#   2014-05-12T14:02:06.025-0700: 94.312: [GC pause (young), 0.08870154 secs]
######################
/GC pause/ {
    DateTime=$1;
    SecondsSinceLaunch=substr($2, 1, length($2)-1);
}

######################
# Heap sizes are in lines that look like this:
#  [ 4842M->4838M(9216M)] 
######################
/\[ .*]$/ {
    gsub ( "\\[" , "" );
    gsub ( "\ \]" , "" );
    gsub ( "->" , " " );
    gsub ( "\\( " , " " );
    gsub ( "\ \)" , " " );
    split($0,a," ");

    if ( split(a[1],b,"M") > 1 ) {BeforeSize=b[1]*1024;}
    if ( split(a[1],b,"K") > 1 ) {BeforeSize=b[1];}

    if ( split(a[2],b,"M") > 1 ) {AfterSize=b[1]*1024;}
    if ( split(a[2],b,"K") > 1 ) {AfterSize=b[1];}

    if ( split(a[3],b,"M") > 1 ) {TotalSize=b[1]*1024;}
    if ( split(a[3],b,"K") > 1 ) {TotalSize=b[1];}
}

######################
# Emit an output line when you find input that looks like this:
#   [Times: user=1.41 sys=0.08, real=0.24 secs]
######################
/\[Times/ {
    if (G1GC==1) {
    gsub ( "," , "" );
    split($2,a,"=");
    UserTime=a[2];
    split($3,a,"=");
    SysTime=a[2];
    split($4,a,"=");
  RealTime=a[2];
    print DateTime,SecondsSinceLaunch,IncrementalCount,FullCount,UserTime,SysTime,RealTime,BeforeSize,AfterSize,TotalSize;
    G1GC=0;
    }
}

The resulting summary is about 25X smaller than the original file, but still difficult for a human to digest.

SecondsSinceLaunch IncrementalCount FullCount UserTime SysTime RealTime BeforeSize AfterSize TotalSize
...
2014-05-12T18:36:34.669-0700: 3985.744 561 0 0.57 0.06 0.16 1724416 1720320 9437184
2014-05-12T18:36:34.839-0700: 3985.914 562 0 0.51 0.06 0.19 1724416 1720320 9437184
2014-05-12T18:36:35.069-0700: 3986.144 563 0 0.60 0.04 0.27 1724416 1721344 9437184
2014-05-12T18:36:35.354-0700: 3986.429 564 0 0.33 0.04 0.09 1725440 1722368 9437184
2014-05-12T18:36:35.545-0700: 3986.620 565 0 0.58 0.04 0.17 1726464 1722368 9437184
2014-05-12T18:36:35.726-0700: 3986.801 566 0 0.43 0.05 0.12 1726464 1722368 9437184
2014-05-12T18:36:35.856-0700: 3986.930 567 0 0.30 0.04 0.07 1726464 1723392 9437184
2014-05-12T18:36:35.947-0700: 3987.023 568 0 0.61 0.04 0.26 1727488 1723392 9437184
2014-05-12T18:36:36.228-0700: 3987.302 569 0 0.46 0.04 0.16 1731584 1724416 9437184

Reading the Data into R

Once the GC log data had been cleansed, either by processing the first format with the shell script, or by processing the second format with the awk script, it was easy to read the data into R.

g1gc.df = read.csv("summary.txt", row.names = NULL, stringsAsFactors=FALSE,sep="")
str(g1gc.df)
## 'data.frame':    8307 obs. of  10 variables:
##  $ row.names         : chr  "2014-05-12T14:00:32.868-0700:" "2014-05-12T14:00:33.179-0700:" "2014-05-12T14:00:33.677-0700:" "2014-05-12T14:00:35.538-0700:" ...
##  $ SecondsSinceLaunch: num  1.16 1.47 1.97 3.83 6.1 ...
##  $ IncrementalCount  : int  0 1 2 3 4 5 6 7 8 9 ...
##  $ FullCount         : int  0 0 0 0 0 0 0 0 0 0 ...
##  $ UserTime          : num  0.11 0.05 0.04 0.21 0.08 0.26 0.31 0.33 0.34 0.56 ...
##  $ SysTime           : num  0.04 0.01 0.01 0.05 0.01 0.06 0.07 0.06 0.07 0.09 ...
##  $ RealTime          : num  0.02 0.02 0.01 0.04 0.02 0.04 0.05 0.04 0.04 0.06 ...
##  $ BeforeSize        : int  8192 5496 5768 22528 24576 43008 34816 53248 55296 93184 ...
##  $ AfterSize         : int  1400 1672 2557 4907 7072 14336 16384 18432 19456 21504 ...
##  $ TotalSize         : int  9437184 9437184 9437184 9437184 9437184 9437184 9437184 9437184 9437184 9437184 ...
head(g1gc.df)
##                       row.names SecondsSinceLaunch IncrementalCount
## 1 2014-05-12T14:00:32.868-0700:              1.161                0
## 2 2014-05-12T14:00:33.179-0700:              1.472                1
## 3 2014-05-12T14:00:33.677-0700:              1.969                2
## 4 2014-05-12T14:00:35.538-0700:              3.830                3
## 5 2014-05-12T14:00:37.811-0700:              6.103                4
## 6 2014-05-12T14:00:41.428-0700:              9.720                5
##   FullCount UserTime SysTime RealTime BeforeSize AfterSize TotalSize
## 1         0     0.11    0.04     0.02       8192      1400   9437184
## 2         0     0.05    0.01     0.02       5496      1672   9437184
## 3         0     0.04    0.01     0.01       5768      2557   9437184
## 4         0     0.21    0.05     0.04      22528      4907   9437184
## 5         0     0.08    0.01     0.02      24576      7072   9437184
## 6         0     0.26    0.06     0.04      43008     14336   9437184

Basic Statistics

Once the data has been read into R, simple statistics are very easy to generate. All of the numbers from high school statistics are available via simple commands. For example, generate a summary of every column:

summary(g1gc.df)
##   row.names         SecondsSinceLaunch IncrementalCount   FullCount    
##  Length:8307        Min.   :    1      Min.   :   0     Min.   :  0.0  
##  Class :character   1st Qu.: 9977      1st Qu.:2048     1st Qu.:  0.0  
##  Mode  :character   Median :12855      Median :4136     Median : 12.0  
##                     Mean   :12527      Mean   :4156     Mean   : 31.6  
##                     3rd Qu.:15758      3rd Qu.:6262     3rd Qu.: 61.0  
##                     Max.   :55484      Max.   :8391     Max.   :113.0  
##     UserTime        SysTime          RealTime       BeforeSize     
##  Min.   :0.040   Min.   :0.0000   Min.   :  0.0   Min.   :   5476  
##  1st Qu.:0.470   1st Qu.:0.0300   1st Qu.:  0.1   1st Qu.:5137920  
##  Median :0.620   Median :0.0300   Median :  0.1   Median :6574080  
##  Mean   :0.751   Mean   :0.0355   Mean   :  0.3   Mean   :5841855  
##  3rd Qu.:0.920   3rd Qu.:0.0400   3rd Qu.:  0.2   3rd Qu.:7084032  
##  Max.   :3.370   Max.   :1.5600   Max.   :488.1   Max.   :8696832  
##    AfterSize         TotalSize      
##  Min.   :   1380   Min.   :9437184  
##  1st Qu.:5002752   1st Qu.:9437184  
##  Median :6559744   Median :9437184  
##  Mean   :5785454   Mean   :9437184  
##  3rd Qu.:7054336   3rd Qu.:9437184  
##  Max.   :8482816   Max.   :9437184

Q: What is the total amount of User CPU time spent in garbage collection?

sum(g1gc.df$UserTime)
## [1] 6236

As you can see, less than two hours of CPU time was spent in garbage collection. Is that too much? To find the percentage of time spent in garbage collection, divide the number above by total_elapsed_time*CPU_count. In this case, there are a lot of CPU’s and it turns out the the overall amount of CPU time spent in garbage collection isn’t a problem when viewed in isolation.

When calculating rates, i.e. events per unit time, you need to ask yourself if the rate is homogenous across the time period in the log file. Does the log file include spikes of high activity that should be separately analyzed? Averaging in data from nights and weekends with data from business hours may alias problems. If you have a reason to suspect that the garbage collection rates include peaks and valleys that need to be independently analyzed, see the “Time Series” section, below.

Q: How much garbage is collected on each pass?

The amount of heap space that is recovered per GC pass is surprisingly low:

  • At least one collection didn’t recover any data. (“Min.=0”)
  • 25% of the passes recovered 3MB or less. (“1st Qu.=3072”)
  • Half of the GC passes recovered 4MB or less. (“Median=4096”)
  • The average amount recovered was 56MB. (“Mean=56390”)
  • 75% of the passes recovered 36MB or less. (“3rd Qu.=36860”)
  • At least one pass recovered 2GB. (“Max.=2121000”)
g1gc.df$Delta = g1gc.df$BeforeSize - g1gc.df$AfterSize
summary(g1gc.df$Delta)
##    Min. 1st Qu.  Median    Mean 3rd Qu.    Max. 
##       0    3070    4100   56400   36900 2120000

Q: What is the maximum User CPU time for a single collection?

The worst garbage collection (“Max.”) is many standard deviations away from the mean. The data appears to be right skewed.

summary(g1gc.df$UserTime)
##    Min. 1st Qu.  Median    Mean 3rd Qu.    Max. 
##   0.040   0.470   0.620   0.751   0.920   3.370
sd(g1gc.df$UserTime)
## [1] 0.3966

Basic Graphics

Once the data is in R, it is trivial to plot the data with formats including dot plots, line charts, bar charts (simple, stacked, grouped), pie charts, boxplots, scatter plots histograms, and kernel density plots.

Histogram of User CPU Time per Collection

I don't think that this graph requires any explanation.

hist(g1gc.df$UserTime,
     main="User CPU Time per Collection",
     xlab="Seconds", ylab="Frequency")

plot of chunk unnamed-chunk-6

Box plot to identify outliers

When the initial data is viewed with a box plot, you can see the one crazy outlier in the real time per GC. Save this data point for future analysis and drop the outlier so that it’s not throwing off our statistics. Now the box plot shows many outliers, which will be examined later, using times series analysis. Notice that the scale of the x-axis changes drastically once the crazy outlier is removed.

par(mfrow=c(2,1))
boxplot(g1gc.df$UserTime,g1gc.df$SysTime,g1gc.df$RealTime,
        main="Box Plot of Time per GC\n(dominated by a crazy outlier)",
        names=c("usr","sys","elapsed"),
        xlab="Seconds per GC", ylab="Time (Seconds)",
        horizontal = TRUE,
        outcol="red")

crazy.outlier.df=g1gc.df[g1gc.df$RealTime > 400,]
g1gc.df=g1gc.df[g1gc.df$RealTime < 400,]

boxplot(g1gc.df$UserTime,g1gc.df$SysTime,g1gc.df$RealTime,
        main="Box Plot of Time per GC\n(crazy outlier excluded)",
        names=c("usr","sys","elapsed"), 
        xlab="Seconds per GC", ylab="Time (Seconds)",
        horizontal = TRUE,
        outcol="red")
box(which = "outer", lty = "solid")

plot of chunk unnamed-chunk-7

Here is the crazy outlier for future analysis:

crazy.outlier.df
##                          row.names SecondsSinceLaunch IncrementalCount
## 8233 2014-05-12T23:15:43.903-0700:              20741             8316
##      FullCount UserTime SysTime RealTime BeforeSize AfterSize TotalSize
## 8233       112     0.55    0.42    488.1    8381440   8235008   9437184
##       Delta
## 8233 146432

R Time Series Data

To analyze the garbage collection as a time series, I’ll use Z’s Ordered Observations (zoo). “zoo is the creator for an S3 class of indexed totally ordered observations which includes irregular time series.”

require(zoo)
## Loading required package: zoo
## 
## Attaching package: 'zoo'
## 
## The following objects are masked from 'package:base':
## 
##     as.Date, as.Date.numeric
head(g1gc.df[,1])
## [1] "2014-05-12T14:00:32.868-0700:" "2014-05-12T14:00:33.179-0700:"
## [3] "2014-05-12T14:00:33.677-0700:" "2014-05-12T14:00:35.538-0700:"
## [5] "2014-05-12T14:00:37.811-0700:" "2014-05-12T14:00:41.428-0700:"
options("digits.secs"=3)
times=as.POSIXct( g1gc.df[,1], format="%Y-%m-%dT%H:%M:%OS%z:")
g1gc.z = zoo(g1gc.df[,-c(1)], order.by=times)
head(g1gc.z)
##                         SecondsSinceLaunch IncrementalCount FullCount
## 2014-05-12 17:00:32.868              1.161                0         0
## 2014-05-12 17:00:33.178              1.472                1         0
## 2014-05-12 17:00:33.677              1.969                2         0
## 2014-05-12 17:00:35.538              3.830                3         0
## 2014-05-12 17:00:37.811              6.103                4         0
## 2014-05-12 17:00:41.427              9.720                5         0
##                         UserTime SysTime RealTime BeforeSize AfterSize
## 2014-05-12 17:00:32.868     0.11    0.04     0.02       8192      1400
## 2014-05-12 17:00:33.178     0.05    0.01     0.02       5496      1672
## 2014-05-12 17:00:33.677     0.04    0.01     0.01       5768      2557
## 2014-05-12 17:00:35.538     0.21    0.05     0.04      22528      4907
## 2014-05-12 17:00:37.811     0.08    0.01     0.02      24576      7072
## 2014-05-12 17:00:41.427     0.26    0.06     0.04      43008     14336
##                         TotalSize Delta
## 2014-05-12 17:00:32.868   9437184  6792
## 2014-05-12 17:00:33.178   9437184  3824
## 2014-05-12 17:00:33.677   9437184  3211
## 2014-05-12 17:00:35.538   9437184 17621
## 2014-05-12 17:00:37.811   9437184 17504
## 2014-05-12 17:00:41.427   9437184 28672

Example of Two Benchmark Runs in One Log File

The data in the following graph is from a different log file, not the one of primary interest to this article. I’m including this image because it is an example of idle periods followed by busy periods. It would be uninteresting to average the rate of garbage collection over the entire log file period. More interesting would be the rate of garbage collection in the two busy periods. Are they the same or different?

Your production data may be similar, for example, bursts when employees return from lunch and idle times on weekend evenings, etc. Once the data is in an R Time Series, you can analyze isolated time windows.

Log_with_2_runs.png

Clipping the Time Series data

Flashing back to our test case… Viewing the data as a time series is interesting. You can see that the work intensive time period is between 9:00 PM and 3:00 AM. Lets clip the data to the interesting period:

par(mfrow=c(2,1))
plot(g1gc.z$UserTime, type="h",
     main="User Time per GC\nTime: Complete Log File",
     xlab="Time of Day", ylab="CPU Seconds per GC",
     col="#1b9e77")
clipped.g1gc.z=window(g1gc.z, 
                      start=as.POSIXct("2014-05-12 21:00:00"), 
                      end=as.POSIXct("2014-05-13 03:00:00"))
plot(clipped.g1gc.z$UserTime, type="h", 
     main="User Time per GC\nTime: Limited to Benchmark Execution",
     xlab="Time of Day", ylab="CPU Seconds per GC",
     col="#1b9e77")
box(which = "outer", lty = "solid")

plot of chunk unnamed-chunk-10

Cumulative Incremental and Full GC count

Here is the cumulative incremental and full GC count. When the line is very steep, it indicates that the GCs are repeating very quickly. Notice that the scale on the Y axis is different for full vs. incremental.

plot(clipped.g1gc.z[,c(2:3)],
     main="Cumulative Incremental and Full GC count",
     xlab="Time of Day",
     col="#1b9e77")

plot of chunk unnamed-chunk-11

GC Analysis of Benchmark Execution using Time Series data

In the following series of 3 graphs:

  • The “After Size” show the amount of heap space in use after each garbage collection. Many Java objects are still referenced, i.e. alive, during each garbage collection. This may indicate that the application has a memory leak, or may indicate that the application has a very large memory footprint. Typically, an application's memory footprint plateau's in the early stage of execution. One would expect this graph to have a flat top. On the far right side, the steep decline in the heap space may indicate that the application crashed after 2:00.
  • The second graph shows that the outliers in real execution time, discussed above, occur near 2:00. when the Java heap seems to be quite full.
  • The third graph shows that Full GCs are infrequent during the first few hours of execution. The rate of Full GC's, (the slope of the cumulative Full GC line), changes near midnight.
  • plot(clipped.g1gc.z[,c("AfterSize","RealTime","FullCount")],
         xlab="Time of Day",
         col=c("#1b9e77","red","#1b9e77"))
    

    plot of chunk unnamed-chunk-12

    GC Analysis of heap recovered

    Each GC trace includes the amount of heap space in use before and after the individual GC event. During garbage collection, unreferenced objects are identified, the space holding the unreferenced objects is freed, and thus, the difference in before and after usage indicates how much space has been freed.

    The following box plot and bar chart both demonstrate the same point - the amount of heap space freed per garbage collection is surprisingly low.

    par(mfrow=c(2,1))
    boxplot(as.vector(clipped.g1gc.z$Delta),
         main="Amount of Heap Recovered per GC Pass",
         xlab="Size in KB",
         horizontal = TRUE,
         col="red")
    hist(as.vector(clipped.g1gc.z$Delta),
         main="Amount of Heap Recovered per GC Pass",
         xlab="Size in KB",
         breaks=100,
         col="red")
    box(which = "outer", lty = "solid")
    

    plot of chunk unnamed-chunk-13

    This graph is the most interesting. The dark blue area shows how much heap is occupied by referenced Java objects. This represents memory that holds live data. The red fringe at the top shows how much data was recovered after each garbage collection.

    barplot(clipped.g1gc.z[,c("AfterSize","Delta")],
         col=c("#7570b3","#e7298a"),
         xlab="Time of Day",
         border=NA)
    legend("topleft",
           c("Live Objects","Heap Recovered on GC"),
           fill=c("#7570b3","#e7298a"))
    box(which = "outer", lty = "solid")
    

    plot of chunk unnamed-chunk-14

    When I discuss the data in the log files with the customer, I will ask for an explanation for the large amount of referenced data resident in the Java heap. There are two are possibilities:

    • There is a memory leak and the amount of space required to hold referenced objects will continue to grow, limited only by the maximum heap size. After the maximum heap size is reached, the JVM will throw an “Out of Memory” exception every time that the application tries to allocate a new object. If this is the case, the application needs to be debugged to identify why old objects are referenced when they are no longer needed.
    • The application has a legitimate requirement to keep a large amount of data in memory. The customer may want to further increase the maximum heap size. Another possible solution would be to partition the application across multiple cluster nodes, where each node has responsibility for managing a unique subset of the data.

    Conclusion

    In conclusion, R is a very powerful tool for the analysis of Java garbage collection log files. The primary difficulty is data cleansing so that information can be read into an R data frame. Once the data has been read into R, a rich set of tools may be used for thorough evaluation.

    Tuesday Mar 18, 2014

    What compiler options were used to create an executable?


    Not stripped:

    $ cc -O hello.c

    $ file a.out

    a.out: ELF 32-bit MSB executable SPARC32PLUS Version 1, V8+ Required, dynamically linked, not stripped

    $ strings -a a.out | grep cc

    /opt/solarisstudio12.3/prod/bin/cc -O hello.c

    $ dwarfdump -i a.out | grep compile_o

    DW_AT_SUN_compile_options Xa;O;R=Sun C 5.12 SunOS_sparc Patch 148917-07 2013/10/18;backend;raw;cd;

    Stripped:

    $ strip a.out

    $ file a.out

    a.out: ELF 32-bit MSB executable SPARC32PLUS Version 1, V8+ Required, dynamically linked, stripped

    $ strings -a a.out | grep cc

    (none)

    Wednesday Feb 26, 2014

    Quadratic data in Oracle R Enterprise and Oracle Data Mining

    I was working with some data which was stored in an Oracle database on a SPARC T4 server. I thought that the data had a quadratic component and I wanted to analyze the data using SQL Developer and Oracle Data Mining, a component of the Oracle Advanced Analytics Option. When I reviewed the initial analysis, I wasn't getting results that I had expected, and the fit of the model wasn't very good. I decided to feed some simple, synthetic quad data into Oracle Data Miner to ensure that I was using the tool properly.

    Oracle R Enterprise was used as the tool to create and view the synthetic data.

    From an R session that has the Oracle R Enterprise package installed, it is easy to access an Oracle Database:

    require(ORE)
    
    ## Loading required package: ORE
    ## Loading required package: OREbase
    ## 
    ## Attaching package: 'OREbase'
    ## 
    ## The following object(s) are masked from 'package:base':
    ## 
    ##     cbind, data.frame, eval, interaction, order, paste, pmax,
    ##     pmin, rbind, table
    ## 
    ## Loading required package: OREstats
    ## Loading required package: MASS
    ## Loading required package: OREgraphics
    ## Loading required package: OREeda
    ## Loading required package: OREdm
    ## Loading required package: lattice
    ## Loading required package: OREpredict
    ## Loading required package: ORExml
    
    ore.connect("SCOTT", "orcl", "sparc-T4", "TIGER", 1521)
    
    ## Loading required package: ROracle
    ## Loading required package: DBI
    

    The following R function, quad1(), is used to calculate "y=ax^2 + bx + c",

    where:
     - the data frame that is passed in has a column of x values.
     - a is in coefficients[feature, 1]
     - b is in coefficients[feature, 2]
     - c is in coefficients[feature, 3]

    The function will simply calculate points along a parabolic line and is more complicated than it needs to be. I will leave it in this complicated format so that I can extend it to work with more interesting functions, such as a parabolic surface, later.  

    quad1 <- function(df, coefficients) {
        feature <- 1
    
        coefficients[feature, 1] * df[, feature] * df[, feature] +
          coefficients[feature, 2] * df[, feature] +
          coefficients[feature, 3]
    }
    

    The following function, genData(), creates random "x" data points and uses func() to calculate the y values that correspond to the random x values.

    genData <- function(nObservations, func, coefficients, nFeatures, scale) {
        dframe <- data.frame(x1 = rep(1, nObservations))
        
        for (feature in seq(nFeatures)) {
            name <- paste("x", feature, sep = "")
            dframe[name] <- runif(nObservations, -scale[feature], scale[feature])
        }
        dframe["y"] <- func(dframe, coefficients)
        return(dframe)
    }
    

    The following function, quadGraph(), is used for graphing. The points in dframe are displayed in a scatter plot. The coefficients for the known synthetic data is passed in and the corresponding line is sketched in blue. (Obviously, if you aren't working with synthetic data, it is unlikely that you will know the "true" coefficients.) The R model that is the best estimate of the data based on regression is passed in and sketched in blue.

    quadGraph <- function(dframe, coefficients = NULL, model = NULL, ...) {
        with(dframe, plot(x1, y))
        title(main = "Quadratic Fit")
        legend("topright", inset = 0.05, c("True", "Model"), lwd = c(2.5, 2.5), 
            col = c("blue", "red"))
        xRange <- range(dframe[, "x1"])
        smoothX <- seq(xRange[1], xRange[2], length.out = 50)
        trueY <- quad1(data.frame(smoothX), coefficients)
        lines(smoothX, trueY, col = "blue")
        
        new = data.frame(x1 = smoothX)
        y_estimated <- predict(model, new)
        lines(smoothX, y_estimated, col = "red")
    }
    

    Here are the settings that will be used.

    nFeatures <- 1  # one feature can sketch a line, 2 a surface, ...
    nObservations <- 20  # How many rows of data to create for modeling
    degree <- 2  # 2 is quadratic, 3 is cubic, etc
    set.seed(2)  # I'll get the same coefficients every time I run 
    coefficients <- matrix(rnorm(nFeatures * (degree + 1)), nFeatures, degree + 1)
    scale <- (10^rpois(nFeatures, 2)) * rnorm(nFeatures, 3)
    

    Here, synthetic data is created that matches the quadratic function and the random coefficients.

    modelData <- genData(nObservations, quad1, coefficients, nFeatures, scale)
    

    We can make this exercise at least slightly more realistic by adding some irreducible error for the regression algorithm to deal with. Add noise.

    yRange <- range(modelData[, "y"])
    yJitter <- (yRange[2] - yRange[1])/10
    modelData["y"] <- modelData["y"] + rnorm(nObservations, 0, yJitter)
    

    Great. At this point I have good quadratic synthetic data which can be analyzed. Feed the synthetic data to the Oracle Database.

    oreDF <- ore.push(modelData)
    tableName <- paste("QuadraticSample_", nObservations, "_", nFeatures, sep = "")
    ore.drop(table = tableName)
    ore.create(oreDF, table = tableName)
    

    The Oracle R Enterprise function to fit the linear model works as expected.

    m = ore.lm(y ~ x1 + I(x1 * x1), dat = oreDF)
    summary(m)
    
    ## 
    ## Call:
    ## ore.lm(formula = y ~ x1 + I(x1 * x1), data = oreDF)
    ## 
    ## Residuals:
    ##    Min     1Q Median     3Q    Max 
    ## -2.149 -0.911 -0.156  0.888  1.894 
    ## 
    ## Coefficients:
    ##             Estimate Std. Error t value Pr(>|t|)    
    ## (Intercept)   1.3264     0.4308    3.08   0.0068 ** 
    ## x1           -0.0640     0.1354   -0.47   0.6428    
    ## I(x1 * x1)   -0.8392     0.0662  -12.68  4.3e-10 ***
    ## ---
    ## Signif. codes:  0 '***' 0.001 '**' 0.01 '*' 0.05 '.' 0.1 ' ' 1 
    ## 
    ## Residual standard error: 1.28 on 17 degrees of freedom
    ## Multiple R-squared: 0.912,	Adjusted R-squared: 0.901 
    ## F-statistic: 87.7 on 2 and 17 DF,  p-value: 1.1e-09
    
    coefficients
    
    ##         [,1]   [,2]  [,3]
    ## [1,] -0.8969 0.1848 1.588
    

    Notice that the "true" coefficients, that were used to create the synthetic data are close to the values from the regression. For example, the true "a" is stored in coefficients[1,1] = -0.8969 and is close to the model's I(x1 * x1) = -0.8392. Not bad given that the model was created from only 20 data points.

    quadGraph(modelData, coefficients, m)
    

    The 20 data points, which were calculated from the "true" equation, but with noisy irreducible error added, are shown in the graph. The model, estimated by ore.lm() from the 20 noisy data points, is close to true.

    plot of chunk unnamed-chunk-10

    At this point, my job is either complete, or ready to start, depending on your perspective. I'm happy that ore.lm() does a nice job of fitting, so maybe I'm done. But if you remember that my initial goal was to validate that SQL Developer and Oracle Data Miner work with quadratic data, my job has just begun. Now that I have known good quadratic synthetic data in the database, I'll use SQL Developer and the Oracle Data Mining to verify that everything is fine.

    One more step in R. Create a second Oracle Database table that will be used to test the regression model. 

    testData <- genData(nObservations, quad1, coefficients, nFeatures, scale)
    oreTestData <- ore.push(testData)
    tableName <- paste("QuadraticTest_", nObservations, "_", nFeatures, sep = "")
    ore.drop(table = tableName)
    ore.create(oreTestData, table = tableName)  

    Here is the SQL Developer workflow that will be used. The synthetic data is in the Oracle Database table "QuadraticSample_20_1". The "Regress Build" node will run linear regression on the synthetic data. The test data which was generated using R in the previous paragraph, is stored in a Oracle Database table named "QuadraticTest_20_1". The Apply node will use the regression model that has been created and use the "x1" values from the test data, storing the y values in an Oracle Database table named "QUADTESTRESULTS". 

    SQL Developer Data Mining Work Flow

    So how did it work? A PhD in statistics would quickly tell you, "not well", and might look at you like you're an idiot if you don't know that a Model F Value Statistic of 3.25 isn't good. My more pedestrian approach is to plot the results of applying the model to the test data. 

    The predictive confidence of the model that was created is poor:

    Predictive Confidence

    Pull the test result data into R for viewing:

    ore.sync()
    ore.attach()
    testResults <- ore.pull(QUADTESTRESULTS)
    
    ## Warning: ORE object has no unique key - using random order
    
    colnames(testResults)[1] <- "y"
    
    with(testResults, plot(x1, y))
    title(main = "Results of Applying Model to Test Data")
    

     Hmm, that doesn't look parabolic to me:

    Linear fit, not quadratic

    Now that I'm quite sure that SQL Developer and Oracle Data Mining isn't giving an expected fit, check through the advanced settings: 

    Advanced Setting

    There it is!!

    Feature Selection

     Set the feature generation to use quadratic candidates, re-run the model.

    The predictive confidence has improved. 

    Bring the new results back into R:

    Data viewed from R looks parabolic

    Also, your statistician friends will be happy because the new model has a Model F Value Statistic of 124. Exciting, right? 

    Now, off to work on parabolic surfaces...

    Monday Feb 10, 2014

    Finding datasets for South African Heart Disease

    I've been working with R recently and have been looking for interesting data sets, for example:

    http://statweb.stanford.edu/~tibs/ElemStatLearn/data.html

    The following command is documented but fails because R can't track through 2 302 status codes and a "301 Moved Permanently":

    > read.table("http://www-stat.stanford.edu/~tibs/ElemStatLearn/datasets/SAheart.data", sep=",",head=T,row.names=1)
    Error in file(file, "rt") : cannot open the connection


    This worked:

    > read.table("http://statweb.stanford.edu/~tibs/ElemStatLearn/datasets/SAheart.data", sep=",",head=T,row.names=1)

    Even better:

    http://cran.r-project.org/web/packages/ElemStatLearn/ElemStatLearn.pdf

    > install.packages("ElemStatLearn")
    > help(package="ElemStatLearn")
    > library( package = ElemStatLearn )
    > str(SAheart)
    > summary(SAheart)
    > data(SAheart)

    R attributes and regexpr

    I've been working with R recently.

    Here is an example of using the match.length attribute that is returned from regexpr:

    Three strings in a vector, first and third include an embedded string:

    data=c("<a href=\"ch4.html\">Chapter 1</a>",
           "no quoted string is embedded in this string",
           "<a   href=\"appendix.html\">Appendix</a>")

    Use regexpr to locate the embedded strings:

    > locations <- regexpr("\"(.*?)\"", data)

    Matches are in the first string (at 9 with length 10) and third string (at 11 with length 15):

    > locations
    [1]  9 -1 11
    attr(,"match.length")
    [1] 10 -1 15
    attr(,"useBytes")
    [1] TRUE

    Vector from the attribute:

    > attr(locations,"match.length")
    [1] 10 -1 15

    Use substr and the attribute vector to extract the strings:

    > quoted_strings=substr( data, 
                             locations, 
                             locations+attr(locations,"match.length")-1 )    
    > quoted_strings
    [1] "\"ch4.html\""      ""                  "\"appendix.html\""

    Maybe you'd like to remove the embedded quote characters from your strings:

    > gsub("\"", "", quoted_strings)
    [1] "ch4.html"      ""              "appendix.html"

    An alternative is to use regmatches:

    > regmatches(data,locations)
    [1] "\"ch4.html\""      "\"appendix.html\""

    Friday Jan 24, 2014

    Redo Log Switches

    In Gathering Database Statistics in a Test Harness I said that use of the Automatic Workload Repository (AWR) is fundamental to understanding Oracle Database performance.

    When I finished the scripts for the blog and ran the first test run, the AWR report was quite clear: I need to increase the size of the redo logs:

    Report Summary

    Top ADDM Findings by Average Active Sessions

    Finding Name Avg active sessions of the task Percent active sessions of finding Task Name Begin Snap Time End Snap Time
    Top SQL Statements 1.00 80.56 ADDM:1351308822_1_2046 24-Jan-14 11:36 24-Jan-14 11:42
    Log File Switches 1.00 5.38 ADDM:1351308822_1_2046 24-Jan-14 11:36 24-Jan-14 11:42


    Instance Activity Stats - Thread Activity

    • Statistics identified by '(derived)' come from sources other than SYSSTAT
    Statistic Total per Hour
    log switches (derived) 13 126.78

    Finding 2: Log File Switches
    Impact is .05 active sessions, 5.38% of total activity.
    -------------------------------------------------------
    Log file switch operations were consuming significant database time while
    waiting for checkpoint completion.
    This problem can be caused by use of hot backup mode on tablespaces.  DML to
    tablespaces in hot backup mode causes generation of additional redo.
    
    ...
    
       Recommendation 2: Database Configuration
       Estimated benefit is .05 active sessions, 5.38% of total activity.
       ------------------------------------------------------------------
       Action
          Increase the size of the log files to 1552 M to hold at least 20 minutes
          of redo information.

    Original log files and groups:

    SQL> select GROUP#,THREAD#,BYTES from v$log;

        GROUP#    THREAD#      BYTES
    ---------- ---------- ----------
         1         1        52428800
         2         1        52428800
         3         1        52428800

    SQL> select MEMBER from v$logfile;

    MEMBER
    --------------------------------------------------------------------------------
    /u01/app/oracle/oradata/orcl/redo03.log
    /u01/app/oracle/oradata/orcl/redo02.log
    /u01/app/oracle/oradata/orcl/redo01.log

    Create new ones:

    SQL > ALTER DATABASE
      ADD LOGFILE GROUP 4 ('/u01/app/oracle/oradata/orcl/redo04.log')
          SIZE 5G;

    SQL> ALTER DATABASE
      ADD LOGFILE GROUP 5 ('/u01/app/oracle/oradata/orcl/redo05.log')
          SIZE 5G;

    SQL> ALTER DATABASE
      ADD LOGFILE GROUP 6 ('/u01/app/oracle/oradata/orcl/redo06.log')
          SIZE 5G;

    Drop the old one:

    SQL> ALTER SYSTEM SWITCH LOGFILE;
    SQL> ALTER SYSTEM SWITCH LOGFILE;
    SQL> ALTER DATABASE DROP LOGFILE GROUP 1;
    SQL> ALTER DATABASE DROP LOGFILE GROUP 2;
    ERROR at line 1:
    ORA-01624: log 2 needed for crash recovery of instance orcl (thread 1)
    ORA-00312: online log 2 thread 1: '/u01/app/oracle/oradata/orcl/redo02.log'

    SQL> ALTER DATABASE DROP LOGFILE GROUP 3;

    SQL> alter system checkpoint;
    SQL> ALTER DATABASE DROP LOGFILE GROUP 2;

    (Dropping group 2 is OK after checkpoint)


    Done:

    SQL> select GROUP#,THREAD#,BYTES from v$log;

        GROUP#    THREAD#       BYTES
    ---------- ---------- ----------
         4          1     5368709120
         5          1     5368709120
         6          1     5368709120

    Gathering Database Statistics in a Test Harness

    Use of the Automatic Workload Repository (AWR) is fundamental to understanding Oracle Database performance. By default, Oracle Database automatically generates snapshots of the performance data once every hour and retains the statistics in the workload repository for 8 days. You can also manually create snapshots, but this is usually not necessary.

    When benchmarking, it is helpful to be able to create an AWR report that covers the exact interval of benchmark execution. Since my benchmarks don't begin or end at the top of the hour, I take an AWR snapshot immediately before and after benchmark execution. At benchmark completion, an AWR report is generated that exactly covers the benchmark execution interval.

    Here is a simple shell script "snap.sh" that takes a new snapshot and returns the ID of the snapshot. I call this script before and after benchmark execution.

    #!/bin/bash

    result=$(sqlplus -S sys/SysPass as sysdba << EOF

    set head off
    set term off
    set echo off
    set trim on
    set trimspool on
    set feedback off
    set pagesize 0
    exec sys.dbms_workload_repository.create_snapshot;
    select max(snap_id) from dba_hist_snapshot;
    EOF
    )

    echo $result


    Here is a script "gen_awr.sh". I call this script after benchmark execution with my preferred name for the report, and the before and after snap IDs.

    sqlplus / as sysdba << @EOF
    @$ORACLE_HOME/rdbms/admin/awrrpt
    html
    1
    $2
    $3
    $1
    exit
    @EOF

    Here is a script "run.sh" that controls the gathering of data for the benchmark execution environment:

    Comments:
    run.sh

    #!/usr/bin/env bash

    ###
    # Usage
    ###
    [ $# -eq 0 ] && { echo "Usage: $0 <TestSize>"; exit 1; }

    ###
    # Set up
    ###
    size=$1
    export DateStamp=`date +%y%m%d_%H%M%S`
    export DIR=/STATS/`hostname`_${size}_$DateStamp
    mkdir -p $DIR

    ###
    # Start gathering statistics
    ###
    vmstat 1 > $DIR/vmstat.out &
    vmstat_pid=$!
    Take an AWR snapshot before execution
    first=`./snap.sh`

    ###
    # Run the benchmark
    ###
    time sqlplus User/UserPass @RunAll $size > $DIR/std.out 2> $DIR/std.err

    ###
    # Stop gathering statistics
    ###
    Take an AWR snapshot after execution last=`./snap.sh`

    kill $vmstat_pid

    ###
    # Generate the report
    ###
    Generate the AWR report
    ./gen_awr.sh $size $first $last > /dev/null
    mv $size.lst $DIR/awr_$size.html


    ###
    # View the AWR report
    ###
    firefox $DIR/awr_$size.html

    After many benchmark runs, I have one directory per benchmark execution, named <nodename>_<size>_<date>_<time>, and each directory contains one AWR report that exactly covers the benchmark interval.


    Friday Sep 06, 2013

    Hadoop on an Oracle SPARC T4-2 Server

    I recently configured a Oracle SPARC T4-2 server to store and process a combination of 2 types of data:
    1. Critical and sensitive data. ACID transactions are required. Security is critical. This data needs to be stored in an Oracle Database.
    2. High-volume/low-risk data that needs to be processed using Apache Hadoop. This data is stored in HDFS.

    Based on the requirements, I configured the server using a combination of:

    1. Oracle VM Server for SPARC, used for hard partitioning of system resources such as CPU, memory, PCIe buses and devices.
    2. Oracle Solaris Zones to host a Hadoop cluster as shown in Orgad Kimchi's How to Set Up a Hadoop Cluster Using Oracle Solaris Zones

    The configuration is shown in the following diagram:

    Oracle SPARC T4 Configuration

    Hadoop Low CPU utilization:

    As you can see in the diagram, a T4 CPU is allocated for Hadoop map/reduce processing. The T4 CPU has 8 cores and 64 virtual processors, enabling it to simultaneously run up to 64 software threads:

    # psrinfo -pv
    The physical processor has 8 cores and 64 virtual processors (0-63)
      The core has 8 virtual processors (0-7)
      The core has 8 virtual processors (8-15)
      The core has 8 virtual processors (16-23)
      The core has 8 virtual processors (24-31)
      The core has 8 virtual processors (32-39)
      The core has 8 virtual processors (40-47)
      The core has 8 virtual processors (48-55)
      The core has 8 virtual processors (56-63)
        SPARC-T4 (chipid 0, clock 2848 MHz)

    To test the Hadoop configuration, I created a large Hive table and launched Hadoop map/reduce processes using Hive:

    INSERT into table Table2
      SELECT ColumnA, SUM(ColumnB)
      FROM Table1
      GROUP BY ColumnA;

    Out-of-the-box Hadoop performance was not well tuned. Simple Hive functions were not able to take advantage of the T4's CPU resources.

    While the HIve job was running, I ran iostat in the Global Zone, I could see that:

    1. The CPU was not very busy
    2. The 3 data-node disks would spike, but were not stressed. 

    # iostat -MmxPznc 60
    ...
         cpu
     us sy wt id
     12  1  0 88
                        extended device statistics             
        r/s    w/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
        2.2   19.1    0.0    0.1  0.0  0.0    0.0    1.8   0   1 (Primary LDOM root)
       23.4    2.9    3.0    0.0  0.0  0.0    0.0    1.3   0   2
    (data-node1)
      105.5    5.5   11.7    0.0  0.0  0.4    0.0    3.2   0  10 (data-node2)
        0.0   23.7    0.0    0.3  0.0  0.0    0.0    1.9   0   1 
    (Guest LDOM root)
       24.2    2.9    1.9    0.0  0.0  0.0    0.0    1.2   0   2
    (data-node3)
        7.2   22.9    0.4    0.3  0.0  0.1    0.0    5.0   0   6 (/ZONES)

         cpu
     us sy wt id
     12  1  0 87
                        extended device statistics             
        r/s    w/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
        2.3   19.2    0.0    0.1  0.0  0.0    0.0    1.8   0   1
    (Primary LDOM root)
        3.8    4.0    0.4    0.0  0.0  0.0    0.0    1.4   0   1
    (data-node1)
       47.9    5.4    4.1    0.0  0.0  0.1    0.0    1.6   0   3 
    (data-node2)
        0.0   25.6    0.0    0.3  0.0  0.0    0.0    1.5   0   1
    (Guest LDOM root)
       38.2    3.9    3.2    0.0  0.0  0.1    0.0    1.4   0   3
    (data-node3)
        9.5   21.9    0.6    0.3  0.0  0.1    0.0    4.4   0   6
    (/ZONES)

         cpu
     us sy wt id
     11  1  0 88
                        extended device statistics             
        r/s    w/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
        5.3   18.6    0.1    0.1  0.0  0.1    0.0    4.4   0   4
    (Primary LDOM root)
        0.5    3.6    0.0    0.0  0.0  0.0    0.0    1.1   0   0 
    (data-node1)
        0.4    3.6    0.0    0.0  0.0  0.0    0.0    0.8   0   0
    (data-node2)
        0.0   23.5    0.0    0.3  0.0  0.0    0.0    1.3   0   1
    (Guest LDOM root)
      124.9    7.2   10.3    0.0  0.0  0.2    0.0    1.8   0  10 (data-node3)
        8.5   24.4    0.6    0.4  0.0  0.2    0.0    4.6   0   6
    (/ZONES)

    To understand the low CPU activity, I looked at active software threads on the Hadoop cluster from the Global Zone.  Six (6) threads were active, one thread per process from map/reduce processes.


    $ prstat -mL
       PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID 

     27529 hadoop    98 0.5 0.0 0.0 0.0 1.0 0.0 0.0  14  46  3K   0 java/2
     27534 hadoop    98 0.5 0.0 0.0 0.0 1.1 0.0 0.0  13  46  3K   0 java/2
     27575 hadoop    98 0.5 0.0 0.0 0.0 1.1 0.0 0.0  15  53  3K   0 java/2
     27577 hadoop    98 0.6 0.0 0.0 0.0 1.2 0.0 0.0  14  53  3K   0 java/2
     27576 hadoop    98 0.6 0.0 0.0 0.0 1.1 0.8 0.0  46  57  3K   0 java/2
     27578 hadoop    97 0.6 0.0 0.0 0.0 1.1 1.0 0.0  53  53  4K   0 java/2
     27575 hadoop   5.8 0.0 0.0 0.0 0.0  94 0.0 0.0  19   4  26   0 java/32
     27578 hadoop   5.6 0.0 0.0 0.0 0.0  94 0.0 0.0  19   5  35   0 java/33
     27529 hadoop   5.6 0.0 0.0 0.0 0.0  94 0.0 0.0   2   8   2   0 java/32
     27576 hadoop   5.5 0.0 0.0 0.0 0.0  95 0.0 0.0  21   6  36   0 java/33
     27028 hadoop   1.2 1.3 0.0 0.0 0.0 0.0  97 0.1 254   5  2K   0 java/87
     27028 hadoop   1.2 1.2 0.0 0.0 0.0 0.0  97 0.1 251   2  2K   0 java/86
       958 root     1.9 0.1 0.0 0.0 0.0  98 0.4 0.0   9   4  27   0 fmd/36
     27005 hadoop   1.2 0.8 0.0 0.0 0.0 0.0  98 0.0  99   2  2K   0 java/86
     27005 hadoop   1.1 0.8 0.0 0.0 0.0 0.0  98 0.0  98   3  2K   0 java/87
     11956 root     1.8 0.1 0.0 0.0 0.0 0.0  98 0.0  44   3 882   0 Xvnc/1
     27016 hadoop   1.0 0.8 0.0 0.0 0.0 0.0  98 0.0  95   2  2K   0 java/86
     27577 hadoop   1.7 0.0 0.0 0.0 0.0  98 0.0 0.0  18   1  28   0 java/32
     27016 hadoop   1.0 0.7 0.0 0.0 0.0 0.0  98 0.0  93   2  2K   0 java/85
     27576 hadoop   1.7 0.0 0.0 0.0 0.0  98 0.0 0.0  20   1  33   0 java/32
     27577 hadoop   1.6 0.0 0.0 0.0 0.0  98 0.0 0.0  18   0  31   0 java/33
    Total: 619 processes, 4548 lwps, load averages: 3.46, 8.63, 27.90


    From the Hadoop JobTracker UI, it could be seen that Hadoop was only scheduling a few of the tasks.

    SixMapProcesses.jpg

    This was because there were only 6 Map and 6 Reduce job slots. (See the "Map Task Capacity" and "Reduce Task Capacity"columns): 

    SixJobSlots.jpg

    Increasing the number of Job Slots:

    The T4 CPU is able to run 64 software threads simultaneously, and over-subscribing the Hadoop CPU's is recommended. I enabled 25 Job Slots per node, for a total of 75, by adding these properties to mapred-site.xml:


      <property>
        <name>mapred.tasktracker.map.tasks.maximum</name>
        <value>25</value>
      </property>

      <property>
        <name>mapred.tasktracker.reduce.tasks.maximum</name>
        <value>25</value>
      </property>

    Improved Hadoop CPU utilization:

    After add Job slots, while running iostat in the Global Zone, I could see that:

    1. The CPU was very busy
    2. The 3 data-node disk were active (but not stressed)

    # iostat -MmxPznc 30
    ...
     us sy wt id

     98  2  0  0
                        extended device statistics             
        r/s    w/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
        1.2   20.6    0.0    0.1  0.0  0.0    0.0    1.5   0   1 c0t5000CCA025261B74d0s0
        0.9   12.9    0.0    0.1  0.0  0.0    0.0    3.2   0   2 c0t5000CCA025311930d0s0
        1.0    9.7    0.0    0.0  0.0  0.0    0.0    1.2   0   1 c0t5000CCA02530B058d0s0
        0.0   22.4    0.0    0.2  0.0  0.0    0.0    1.0   0   1 c0t5000CCA0250CB198d0s0
        1.3   15.7    0.0    0.1  0.0  0.0    0.0    1.1   0   1 c0t5000CCA025324D98d0s0
        2.8   28.3    0.1    0.4  0.0  0.1    0.0    3.5   0   4 c0t5000CCA0253C11B0d0s0
         cpu
     us sy wt id
     98  2  0  0
                        extended device statistics             
        r/s    w/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
        1.3   21.1    0.0    0.1  0.0  0.1    0.0    3.0   0   3 c0t5000CCA025261B74d0s0
        0.6    7.2    0.0    0.0  0.0  0.0    0.0    1.3   0   0 c0t5000CCA025311930d0s0
        0.8    5.7    0.0    0.0  0.0  0.0    0.0    1.5   0   0 c0t5000CCA02530B058d0s0
        0.0   22.6    0.0    0.3  0.0  0.0    0.0    1.1   0   1 c0t5000CCA0250CB198d0s0
        0.5    7.7    0.0    0.1  0.0  0.0    0.0    1.1   0   0 c0t5000CCA025324D98d0s0
        2.2   24.7    0.1    0.3  0.0  0.1    0.0    2.4   0   2 c0t5000CCA0253C11B0d0s0
         cpu
     us sy wt id
     98  2  0  0
                        extended device statistics             
        r/s    w/s   Mr/s   Mw/s wait actv wsvc_t asvc_t  %w  %b device
        0.9   20.6    0.0    0.1  0.0  0.1    0.0    2.6   0   2 c0t5000CCA025261B74d0s0
        0.5    7.1    0.0    0.0  0.0  0.0    0.0    0.9   0   0 c0t5000CCA025311930d0s0
        4.8   10.3    0.4    0.0  0.0  0.0    0.0    1.2   0   1 c0t5000CCA02530B058d0s0
        0.0   21.7    0.0    0.2  0.0  0.0    0.0    1.1   0   1 c0t5000CCA0250CB198d0s0
        2.4   15.1    0.2    0.1  0.0  0.0    0.0    1.2   0   1 c0t5000CCA025324D98d0s0
        4.8   25.3    0.5    0.4  0.0  0.2    0.0    5.4   0   5 c0t5000CCA0253C11B0d0s0

    Now all 69 maps jobs can run in parallel:

    69JobsRunning.jpg

    Because there are 75 map job slots: (See the "Map Task Capacity" and "Reduce Task Capacity"columns)

    75slots.jpg

    Hadoop Memory Usage:

    For this simple case, I found that allocating additional memory to the Java map/reduce processes did not help, but for reference, this is how I increased the memory available to the Hive map/reduce processes:

    $ hive --hiveconf mapred.map.child.java.opts="-Xmx1000m -Xms500m"




    About

    Jeff Taylor-Oracle

    Search

    Archives
    « July 2015
    SunMonTueWedThuFriSat
       
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
     
           
    Today