Search

OakieTags

Who's online

There are currently 0 users and 31 guests online.

Recent comments

Affiliations

Oakies Blog Aggregator

AUSOUG conference Perth

The annual two day AUSOUG conference in Perth is well underway, and so far, its been a wonderfully successful event. In particular, we Australians are notorious for not really getting into the networking thing, so conferences often have a lot of ‘awkward silences’ when sessions are not on, and we are meant to be (god forbid) *talking* to each other :-)

But this year has been different. Lots of banter, lots of discussion. Also, the AUSOUG committee got it exactly right this year. The venue is just the right size, the rooms are the right size, the timings of the sessions and transit times were spot on. It is a real credit to them – it shows how much they are listening to the speakers and attendees feedback.

I had a couple of talks, which I’ll slideshare in the next couple of days, and we also had plenty of good talks as part of the OTN tour from Tim Hall, Bjorn Rost, Craig Shallamer. Penny Cookson, Jeff Kemp and Chris Muir rounded off the talks I saw.

So if you’re ever in Perth around conference time – put it on your calendar. Its well worth it. (www.ausoug.org.au)

About Oracle’s Code of Ethics, MOS Confidentiality Clause, and Content Stolen from My Website

I strive to keep the number non-technical posts on this blog to the minimum. However, there are days when a non-technical post has to be written. This is one of such days.

Oracle Corporation, concerned about legal and ethical issues, not only provides to its employees a document entitled Code of Ethics and Business Conduct, but also expects that every employee adheres with the standards that the document sets. For the purpose of this post, I would like to quote part of the “Intellectual Property” section:

It is against Oracle policy to use, copy, display, or distribute third-party copyrighted software, documentation, or other materials without permission or approval from Oracle’s Legal Department. For example, you may not post another entity’s copyrighted content to any internal or external Web site or other electronic forum without first obtaining the necessary approvals.

Having said that, I encourage you to have a look to the My Oracle Support note entitled Implementing Instance Caging (1177593.1). For your convenience (and also because I am fully aware that the current situation will change quickly), even though Oracle Corporation did not give me permission to do so, I provide you this PDF file showing the content of the note as the 5th of November 2014. In this way, you can accesses it from this blog without having access to My Oracle Support.

You might ask why I wrote that Oracle Corporation did not give me permission to publish the note I mentioned. The reason is quite simple… Despite the fact that I have access to My Oracle Support (among other, the company I work for, Trivadis, is a Platinum level partner), My Oracle Support Terms of Use clearly states the following:

You may not use, disclose, reproduce, transmit, or otherwise copy in any form or by any means the information contained in the Materials for any purpose, other than to support your authorized use of the Oracle product and/or cloud services, for which you have a current support contract, without the prior written permission of Oracle.

So, why I did it? Because part of the content of the note was reproduced by Oracle Corporation, or better, by one of its employees, without my permission! In fact, as you can easily see yourself, most of the post entitled Instance Caging that I published in November 2009 was included (i.e. copy/pasted) into the note.

While I might find flattering that people at Oracle are using my blog as a resource for technical information, such a conduct is against not only to common practices, but also to Oracle’s well defined code of ethics.

All the best!



PS: I did not write this post to attack Oracle Corporation, but to draw its attention about the unethical behaviour of some of its employees. Alas, doing that in public is the most effective way I am aware of.



UPDATE 2014-11-06 22:19: less than 4 hours after I published this post the note is no longer visible in My Oracle Support. Hence, the link referencing it is broken.

A simple 12c query with a cool result …

Its not immediately obvious the significance of this query…but trust me…you’ll love it :-)

SQL> select table_name, column_name from dba_tab_cols
  2  where column_name like '%\_VC' escape '\'
  3  and owner = 'SYS'
  4  order by 1,2;

TABLE_NAME                     COLUMN_NAME
------------------------------ ----------------------
ALL_CONSTRAINTS                SEARCH_CONDITION_VC
ALL_VIEWS                      TEXT_VC
CDB_CONSTRAINTS                SEARCH_CONDITION_VC
CDB_VIEWS                      TEXT_VC
DBA_CONSTRAINTS                SEARCH_CONDITION_VC
DBA_VIEWS                      TEXT_VC
INT$DBA_CONSTRAINTS            SEARCH_CONDITION_VC
INT$DBA_VIEWS                  TEXT_VC
INT$INT$DBA_CONSTRAINTS        SEARCH_CONDITION_VC
USER_CONSTRAINTS               SEARCH_CONDITION_VC
USER_VIEWS                     TEXT_VC

What Day Is It If You Only Specify The Time?

What is the date if you only specify the time when you populate an Oracle date column (or variable)?

That was the question that came up a few days ago in the little DBA team I am currently working in. Of course, the question was posed by the “junior” (who is damned smart at this stuff as he keeps asking questions like that) and the answer from us two old hands was… “Ohh!… hang on… errr….”

A little discussion then occurred. One of us suggested it would be “today”. One of us suggested it would be the Julian 1 date (4712BC). Both of us then stated it was an easy thing to test and the PROPER answer was “just try it and then you will know for sure”. We were right {and, of course, wrong} – as in with a simple question like this you don’t need to google the question (so “hello” to anyone googling the question and finding this page!) you just try it:

The junior tried it and…

select sysdate,to_char(to_date('11:23:15','HH24:MI:SS'),'DD-MON-YYYY HH24:MI:SS') time_only
from dual;

SYSDATE              TIME_ONLY
-------------------- --------------------
05-NOV-2014 22:37:23 01-NOV-2014 11:23:15

The above of course shows that us two old hands were wrong in our suggestions of what the default date would be

The answer is that:

If you do not specify the date, it defaults to *the first day of the current month*

How odd. How amusing. What was more amusing was the two of us old hands looked at the answer and we both said “oh yes! I remember learning that before. Maybe a couple of times..”.

Maybe I am wrong and most of you reading this learned what the default date is early in your Oracle experience and never forgot it {or have learned it from here and will not forget it now, so long as you remain in possession of your wits} but both of us tired old sods laughed over the fact we knew we had known that and forgotten it. And when asked, came up with reasonable, but wrong, suggestions to the the answer. But at least we both knew it was one of those “you can answer it almost as quickly as it takes to google it” questions and the proper answer was to do a 1 minute test.

A quick check on a table in one of our applications that holds the date and time of an event in two columns (a slightly mad but common situation) demonstrated it nicely too:

select action_date,action_time
from source_table
where action_time is not null
ACTION_DATE           ACTION_TIME
-------------------- --------------------
09-JUN-2011 00:00:00 01-OCT-2014 11:45:30
09-DEC-2012 00:00:00 01-OCT-2014 11:12:13
09-DEC-2012 00:00:00 01-OCT-2014 17:05:57
13-JUN-2013 00:00:00 01-OCT-2014 16:25:17
17-JUN-2013 00:00:00 01-OCT-2014 16:39:00
20-JUN-2013 00:00:00 01-OCT-2014 13:00:00
25-SEP-2014 00:00:00 01-NOV-2014 08:59:00
03-NOV-2014 00:00:00 01-NOV-2014 09:00:00
03-NOV-2014 00:00:00 01-NOV-2014 00:00:00

So, if you do not specify the date, Oracle substitutes the first day of the current month. It is fully documented in the overview of the date datatype

Of course, if you do not state the time portion of a date, it defaults to the start of the current hour.

Only kidding, it of course defaults to midnight, though given how the date portion defaults my hour suggestion would almost make sense.

select sysdate,to_char(to_date('15-OCT-2013','DD-MON-YYYY'),'DD-MON-YYYY HH24:MI:SS') date_only
from dual;

SYSDATE              DATE_ONLY
-------------------- --------------------
06-NOV-14            15-OCT-2013 00:00:00

I wonder what other basic pieces of Oracle Info have left my head and if it is more or less than the average person who has been doing this for 25 years?

Cardinality Feedback

A fairly important question, and a little surprise, appeared on Oracle-L a couple of days ago. Running 11.2.0.3 a query completed quickly on the first execution then ran very slowly on the second execution because Oracle had used cardinality feedback to change the plan. This shouldn’t really be entirely surprising – if you read all the notes that Oracle has published about cardinality feedback – but it’s certainly a little counter-intuitive.

Of course there are several known bugs related to cardinality feedback that could cause this anomaly to appear – a common complaint seems to relate to views on the right-hand (inner table) side of nested loop joins, and cardinality feedback being used on a table inside the view; but there’s an inherent limitation to cardinality feedback that makes it fairly easy to produce an example of a query doing more work on the second execution.

The limitation is that cardinality feedback generally can’t be used (sensibly) on all the tables where better information is needed. This blog describes the simplest example I can come up with to demonstrate the point. Inevitably it’s a little contrived, but it captures the type of guesswork and mis-estimation that can make the problem appear in real data sets. Here’s the query I’m going to use:


select
	t1.n1, t1.n2, t2.n1, t2.n2
from
	t1, t2
where
	t1.n1 = 0
and	t1.n2 = 1000
and	t2.id = t1.id
and	t2.n1 = 0
and	t2.n2 = 400
;

You’ll notice that I’ve got two predicates on both tables so, in the absence of “column-group” extended stats the optimizer will enable cardinality feedback as the query runs to check whether or not its “independent columns” treatment of the predicates gives a suitably accurate estimate of cardinality and a reasonable execution plan. If the estimates are bad enough the optimizer will use information it has gathered as the query ran as an input to re-optimising the query on the next execution.

So here’s the trick.  I’m going to set up the data so that there seem to be only two sensible plans:  (a) full scan of t1, with nested loop unique index access to t2; (b) full scan of t2, with nested loop unique index access to t1. But I’m going to make sure that the optimizer thinks that (a) is more efficient than (b) by making making the stats look as if (on average) the predicates on t1 should return 100 rows while the predicates on t2 return 200 rows.

On the other hand I’ve set the data up so that (for this specific set of values) t1 returns 1,000 rows which means Oracle will decide that its estimate was so far out that it will re-optimize with 1,000 as the estimated single table access cardinality for t1 – and that means it will decide to do the nested loop from t2 to t1. But what the optimizer doesn’t know (and hasn’t been able to find out by running the first plan) is that with this set of predicates t2 will return 20,000 rows to drive the nested loop into t1 – and the new execution plan will do more buffer gets and use more CPU (and time) than the old plan. Since cardinality feedback is applied only once, the optimizer won’t be able to take advantage of the second execution to change the plan again, or even to switch back to the first plan.

Here’s the setup so you can test the behaviour for yourselves:


create table t1
as
with generator as (
	select	--+ materialize
		rownum id
	from dual
	connect by
		level <= 1e4
)
select
	rownum			id,
	mod(rownum,2)		n1,
	mod(rownum,2000)	n2,	-- 200 rows for each value on average
	rpad('x',100)		padding
from
	generator	v1,
	generator	v2
where
	rownum <= 4e5
;

alter table t1 add constraint t1_pk primary key(id);

create table t2
as
with generator as (
	select	--+ materialize
		rownum id
	from dual
	connect by
		level <= 1e4
)
select
	rownum			id,
	mod(rownum,2)		n1,
	2 * mod(rownum,1000)	n2,	-- 400 rows for each value on average, same range as t1
	rpad('x',100)		padding
from
	generator	v1,
	generator	v2
where
	rownum <= 4e5
;

alter table t2 add constraint t2_pk primary key(id);

begin
	dbms_stats.gather_table_stats(
		ownname		 => user,
		tabname		 =>'T1',
		method_opt	 => 'for all columns size 1'
	);
	dbms_stats.gather_table_stats(
		ownname		 => user,
		tabname		 =>'T2',
		method_opt	 => 'for all columns size 1'
	);
end;
/

--
-- Now update both tables to put the data out of sync with the statistics
-- We need a skewed value in t1 that is out by a factor of at least 8 (triggers use of CF)
-- We need a skewed value in t2 that is so bad that the second plan is more resource intensive than the first
--

update t1 set n2 = 1000 where n2 between 1001 and 1019;
update t2 set n2 =  400 where n2 between 402 and 598;
commit;

Here are the execution plans for the first and second executions (with rowsource execution statistics enabled, and the “allstats last” option used in a call to dbms_xplan.display_cursor()).


----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name  | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers | Reads  |
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |       |      1 |        |  1049 (100)|      0 |00:00:00.36 |   11000 |   6588 |
|   1 |  NESTED LOOPS                |       |      1 |    100 |  1049   (3)|      0 |00:00:00.36 |   11000 |   6588 |
|   2 |   NESTED LOOPS               |       |      1 |    100 |  1049   (3)|   2000 |00:00:00.35 |    9000 |   6552 |
|*  3 |    TABLE ACCESS FULL         | T1    |      1 |    100 |   849   (4)|   2000 |00:00:00.30 |    6554 |   6551 |
|*  4 |    INDEX UNIQUE SCAN         | T2_PK |   2000 |      1 |     1   (0)|   2000 |00:00:00.02 |    2446 |      1 |
|*  5 |   TABLE ACCESS BY INDEX ROWID| T2    |   2000 |      1 |     2   (0)|      0 |00:00:00.01 |    2000 |     36 |
----------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(("T1"."N2"=1000 AND "T1"."N1"=0))
   4 - access("T2"."ID"="T1"."ID")
   5 - filter(("T2"."N2"=400 AND "T2"."N1"=0))

----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name  | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers | Reads  |
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |       |      1 |        |  1249 (100)|      0 |00:00:00.66 |   32268 |   1246 |
|   1 |  NESTED LOOPS                |       |      1 |    200 |  1249   (3)|      0 |00:00:00.66 |   32268 |   1246 |
|   2 |   NESTED LOOPS               |       |      1 |    200 |  1249   (3)|  20000 |00:00:00.56 |   12268 |    687 |
|*  3 |    TABLE ACCESS FULL         | T2    |      1 |    200 |   849   (4)|  20000 |00:00:00.12 |    6559 |    686 |
|*  4 |    INDEX UNIQUE SCAN         | T1_PK |  20000 |      1 |     1   (0)|  20000 |00:00:00.19 |    5709 |      1 |
|*  5 |   TABLE ACCESS BY INDEX ROWID| T1    |  20000 |      1 |     2   (0)|      0 |00:00:00.15 |   20000 |    559 |
----------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(("T2"."N2"=400 AND "T2"."N1"=0))
   4 - access("T2"."ID"="T1"."ID")
   5 - filter(("T1"."N2"=1000 AND "T1"."N1"=0))

Note
-----
   - cardinality feedback used for this statement

The second plan does fewer reads because of the buffering side effects from the first plan – but that’s not what the optimizer is looking at. The key feature is that the first plan predicts 100 rows for t1, with 100 starts for the index probe, but discovers 2,000 rows and does 2,000 probes. Applying cardinality feedback the optimizer decides that fetching 200 rows from t2 and probing t1 200 times will be lower cost than running the join the other way round with the 2,000 rows it now knows it will get – but at runtime Oracle actually gets 20,000 rows, does three times as many buffer gets, and spends twice as much time as it did on the first plan.

Hinting

Oracle hasn’t been able to learn (in time) that t2 will supply 20,000 rows – but if you knew this would happen you could use the cardinality() hint to tell the optimizer the truth about both tables /*+ cardinality(t1 2000) cardinality(t2 20000) */ this is the plan you would get:

--------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |      1 |        |  1698 (100)|      0 |00:00:00.06 |   13109 |  13105 |       |       |          |
|*  1 |  HASH JOIN         |      |      1 |   2000 |  1698   (4)|      0 |00:00:00.06 |   13109 |  13105 |  1696K|  1696K| 1647K (0)|
|*  2 |   TABLE ACCESS FULL| T1   |      1 |   2000 |   849   (4)|   2000 |00:00:00.05 |    6554 |   6552 |       |       |          |
|*  3 |   TABLE ACCESS FULL| T2   |      1 |  20000 |   849   (4)|  20000 |00:00:00.09 |    6555 |   6553 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T2"."ID"="T1"."ID")
   2 - filter(("T1"."N2"=1000 AND "T1"."N1"=0))
   3 - filter(("T2"."N2"=400 AND "T2"."N1"=0))

Unfortunately, unless you have used hints, it doesn’t matter how many times you re-run the query after cardinality feedback has pushed you into the bad plan – it’s not going to change again (unless you mess around flushing the shared pool or using dbms_shared_pool.purge() to kick out the specific statement).

Upgrade

If you upgrade to 12c the optimizer does a much better job of handling this query – it produces an adaptive execution plan (starting with the nested loop join but dynamically switching to the hash join as the query runs). Here’s the full adaptive plan pulled from memory after the first execution – as you can see both the t1/t2 nested loop and hash joins were considered, then the nested loop was discarded in mid-execution. Checking the 10053 trace file I found that Oracle has set the inflexion point (cross-over from NLJ to HJ) at 431 rows.


----------------------------------------------------------------------------------------------------------------------------------------------------
|   Id  | Operation                     | Name  | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------------------
|     0 | SELECT STATEMENT              |       |      1 |        |  1063 (100)|      0 |00:00:00.06 |   13113 |  13107 |       |       |          |
|  *  1 |  HASH JOIN                    |       |      1 |    100 |  1063   (3)|      0 |00:00:00.06 |   13113 |  13107 |  1519K|  1519K| 1349K (0)|
|-    2 |   NESTED LOOPS                |       |      1 |    100 |  1063   (3)|   2000 |00:00:00.11 |    6556 |   6553 |       |       |          |
|-    3 |    NESTED LOOPS               |       |      1 |    100 |  1063   (3)|   2000 |00:00:00.10 |    6556 |   6553 |       |       |          |
|-    4 |     STATISTICS COLLECTOR      |       |      1 |        |            |   2000 |00:00:00.09 |    6556 |   6553 |       |       |          |
|  *  5 |      TABLE ACCESS FULL        | T1    |      1 |    100 |   863   (4)|   2000 |00:00:00.08 |    6556 |   6553 |       |       |          |
|- *  6 |     INDEX UNIQUE SCAN         | T2_PK |      0 |      1 |     1   (0)|      0 |00:00:00.01 |       0 |      0 |       |       |          |
|- *  7 |    TABLE ACCESS BY INDEX ROWID| T2    |      0 |      1 |     2   (0)|      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  *  8 |   TABLE ACCESS FULL           | T2    |      1 |      1 |     2   (0)|  20000 |00:00:00.07 |    6557 |   6554 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T2"."ID"="T1"."ID")
   5 - filter(("T1"."N2"=1000 AND "T1"."N1"=0))
   6 - access("T2"."ID"="T1"."ID")
   7 - filter(("T2"."N2"=400 AND "T2"."N1"=0))
   8 - filter(("T2"."N2"=400 AND "T2"."N1"=0))

Note
-----
   - this is an adaptive plan (rows marked '-' are inactive)

Footnote:

For reference, here are a couple of the bug (or patch)  numbers associated with cardinality feedback:

  • Patch 13454409: BAD CARDINALITY FROM FEEDBACK (CFB) ON VIEW RHS OF NLJ
  • Bug 16837274 (fixed in 12.2): Bad cost estimate for object on RHS of NLJ
  • Bug 12557401: The table that is being incorrectly adjusted is in the right hand side of a nested loops.
  • Bug 8521689: Bad cardinality feedback estimate for view on right-hand side of NLJ

 

#CloneAttack online ! (and in person at #ECO14 & #DOAG14)

I’ll be at #ECO14 today in Raleigh,NC. Catch me in person to get a copy of #CloneAttack. I’ll also be at #DOAG14 in Nuremberg Nov 18-20 running an official #CloneAttack along side of #RacAttack and #RepAttack. Will also be at #BGOUG in Sofia Bulgaria Nov 14-16.

For online #CloneAttack info read on:

#2970a6;" src="http://www.oraclerealworld.com/wp-content/uploads/2014/09/Screen-Shot-2014-09-24-at-9.41.34-AM-1024x658.png" alt="Screen Shot 2014-09-24 at 9.41.34 AM" width="464" height="299" />

We are starting a limited publicly accessible download of a trial version of Delphix and lab.

If interested connect with me on linkedin at  #666666;" title="View public profile" href="http://www.linkedin.com/in/kylehailey/" name="webProfileURL">www.linkedin.com/in/kylehailey/ and I will send you the download info via linkedin messages.

#444444;">
#222222;">Delphix trial version and lab:
#222222;">
#222222;">The lab consists of 3 virtual machines. The virtual machines are available from the download link as OVA files. You can start up the virtual machines by simply clicking on the OVA files after you have VMware fusion installed.
#222222;">
#222222;">Virtual Machines are
#222222;">
  1. Source Linux machine with Oracle database
  2. Target Linux machine with just Oracle binaries. We will create thin clone databases, ie virtual databases here
  3. Delphix machine already linked to the source database on the source Linux virtual machine
#444444;">Because we can not distribute Oracle 11gR2 software, we ask that you download that from Oracle and we provide a script to automate the install of Oracle software on the Source and Target Linux virtual machines.
#444444;">The lab requires 11.2.0.1 of Oracle (other versions will fail automated install using our scripts, but you are free to install them manually yourself on the VMs and then use those versions with Delphix)
#444444;">
#444444;">Steps
#444444;">
#444444;">
    #000000;">
  1. #222222;">Import the OVAs into VMWare (right click on OVA, chose open with VMware Fusion)
  2. #222222;">Note IP Address on the boot screen of each VM (via Console)
  3. #222222;">Download the Oracle 11.2.0.1 install for “Linux x86-64″
    • #2970a6;" href="http://www.google.com/url?q=http://www.oracle.com/technetwork/database/enterprise-edition/downloads/index.html&sa=D&sntz=1&usg=AFrqEzfEsE1zdYLoPWfSB5rRp3fEBM33VA" target="_blank">#222222;">linux.x64_11gR2_database_1of2.zip
    • #2970a6;" href="http://www.google.com/url?q=http://www.oracle.com/technetwork/database/enterprise-edition/downloads/index.html&sa=D&sntz=1&usg=AFrqEzfEsE1zdYLoPWfSB5rRp3fEBM33VA" target="_blank">linux.x64_11gR2_database_2of2.zip
  4. #222222;">execute automated Oracle install script (from directory with Oracle install zip files)
    • On MAC  lsde_install_mac_v1.2.sh
    • On PC lsde_install_v1.2.sh
    • On Linux lsde_install_v1.2.sh
  5. #222222;">Login to the Delphix Admin portal (type in the IP address of Delphix VM in a browser)
  6. #222222;">Go to Manage->Environments
  7. #222222;">Choose the appropriate environment and then change the Host Address to the IP address from step 4
  8. #222222;">Refresh Environment (click on the blue & green double arrow on the Target and then Source)
#222222; font-family: Verdana, 'BitStream vera Sans', Helvetica, sans-serif;"> 
#444444;">

#555555;">Prerequisites

#222222;">
    #767676;">
  • #222222;">Pre-download 11.2.0.1 for “Download Linux x86-64″  from Oracle site
    • #2970a6;" href="http://www.google.com/url?q=http://www.oracle.com/technetwork/database/enterprise-edition/downloads/index.html&sa=D&sntz=1&usg=AFrqEzfEsE1zdYLoPWfSB5rRp3fEBM33VA">linux.x64_11gR2_database_1of2.zip
    • #2970a6;" href="http://www.google.com/url?q=http://www.oracle.com/technetwork/database/enterprise-edition/downloads/index.html&sa=D&sntz=1&usg=AFrqEzfEsE1zdYLoPWfSB5rRp3fEBM33VA">linux.x64_11gR2_database_2of2.zip
  • Mac or Linux: VMware Fusion (free trial version #24890d;" title="download" href="https://www.google.com/url?q=https://www.vmware.com/products/fusion/fusion-evaluation.html&sa=D&sntz=1&usg=AFrqEzeedP_fYzx0peKjyOfLLQklcEOmuA" target="_blank">download)
  • Win: VMware Workstation (free trial version #24890d;" title="download" href="http://www.google.com/url?q=http://www.vmware.com/products/workstation/workstation-evaluation&sa=D&sntz=1&usg=AFrqEzfwURMexoK4vPN1mmmlLXYLY0GCSg" target="_blank">download)
  • Win: Cygwin #2970a6;" href="https://www.google.com/url?q=https://cygwin.com/install.html%2520&sa=D&sntz=1&usg=AFrqEzdmr94_XWJFWCxN7iPDjRYfUSVJTQ">download
  • at least 8 GB RAM
  • at least 50 GB free disk space, but preferably 100 GB free
  • at least 2 Ghz CPU, preferably dual-core or better
#444444;">Here is the download URL and login info. Please let me know your experiences. We are actively improving the lab experience and depend on your  feedback to improve it.
#444444;">
#444444;">
#222222;">#444444;" title="">#1155cc;" href="https://www.google.com/url?q=https://delphixdemokit.signin.aws.amazon.com/console/s3&sa=D&sntz=1&usg=AFrqEzcwZxlBF0LDwP2G2u6ldLCFGuyF2Q" target="_blank">https://delphixdemokit.signin.aws.amazon.com/console/s3
#444444;" title=""> 
#444444;" title="">Account: delphixdemokit
#444444;" title="">Username: lsde_shared
#444444; font-family: 'Helvetica Neue', Roboto, Arial, 'Droid Sans', sans-serif;">Password: contact me via linkedin at #666666;" title="View public profile" href="http://www.linkedin.com/in/kylehailey/" name="webProfileURL">www.linkedin.com/in/kylehailey/
#444444;">
#444444; font-family: 'Helvetica Neue', Roboto, Arial, 'Droid Sans', sans-serif;">Path: #1166bb;">All Buckets /landshark/#1166bb;">DE/#1166bb;">1.5.6
#1166bb;"> 
#444444;">There is an online community for posting and asking questions here:
#444444;">
#444444;">#0033cc;" href="https://www.google.com/url?q=https://community.delphix.com/delphix/categories/delphix_landshark&sa=D&sntz=1&usg=AFrqEzdrVxkJcOpB5pye2fDXg2mfIayQNQ">https://community.delphix.com/delphix/categories/delphix_landshark
#444444;">
#444444;">My previous blog postson the labs with general info is at
#444444;">
#444444;">#0033cc;" href="http://www.google.com/url?q=http://www.oraclerealworld.com/delphix-trial-version-available-for-first-time-cloneattack/&sa=D&sntz=1&usg=AFrqEze-XN-d5T0a3jhHJrDAuHAr9DwY0w">http://www.oraclerealworld.com/delphix-trial-version-available-for-first-time-cloneattack/
#444444;">
#444444;">NOTE: this is a trial version is for functional testing and not for performance testing. The trial version is a version trimmed down for  a laptop install thus its not valid for performance tests. For performance tests Delphix requires a minimum of 32GB of RAM and 8 vCPUs and vmxnet3 network driver. This same trial version can successfully be used for performance tests by  being installed on an ESX machine and configured for performance but high end performance setups should ideally include assistance from Delphix pre-sales. Also the performance of the underlying disk subsystem that Delphix relies on will, obviously, be a major factor in any performance. Finally for performance work, ALL router hops between Delphix and target machines that run the virtual databases should be eliminated.
#444444;">
#444444;">

#555555;">Reference

    #555555;">
  • #2970a6;" href="https://blogs.oracle.com/OTN-DBA-DEV-Watercooler/entry/oow_2014_cloneattack_comes_to" target="_blank">OOW 2014 #CLONEATTACK Comes to OTN Lounge
  • #2970a6;" href="http://evdbt.com/cloneattack/" target="_blank">#CLONEATTACK AT ORACLE OPENWORLD 2014

#555555;">#2970a6;" href="http://www.oraclerealworld.com/wp-content/uploads/2014/09/9009_03.jpg">9009_03

#555555;">Here is a video showing the lab setup. A later video will show some exercises we can do with the lab setup.

#555555;">

#555555;">Here is a video of an exercise to do on the lab VMs after install

#555555;">

#555555;">Linux notes

#555555;">NOTE: 

#222222;">- when booting the source/target VMs, the boot process occasionally hangs at:

#222222;">Bringing up interface eth0:

#222222;">Determining IP information for eth0…init: vmware-tools pre-start process (779) terminated with status 1

#222222;">a simple VM restart solves the problem.

#222222;">NOTE Linux

#222222;">need adobe flash to run Delphix console in a browser

#222222;">installing flash on Fedora

#222222;">$ yum install flash-plugin

#222222;">NOTE Fedora Linux install

#222222;">use Linux lsde_install_v1.2.sh

#222222;">but change “ping -n ” to “ping -c ”  and ” grep TTL ” to “grep rtt”

#222222;">will work on a new linux install script

#222222;">Fedora VMware Workstation install

#555555;">download

#444444;"> VMware-Workstation-Full-10.0.4-1379776.x86_64.bundle

#555555;">Following notes from  from http://www.linux.com/community/forums/cloud-management/how-to-install-vmware-1001-on-fedora-20-x86-64

Install GCC, dev tools and kernel headers

# yum -y install gcc kernel-headers kernel-devel
# ln -s /usr/src/kernels/$(uname -r)/include/generated/uapi/linux/version.h /usr/src/kernels/$(uname -r)/include/linux/version.h[/code]

 

Start the VMWare installation

# chmod -x VMware-Workstation-Full-10.0.1-1379776.x86_64.bundle
# ./VMware-Workstation-Full-10.0.1-1379776.x86_64.bundle

Apply patch for a bug with netfilter

WARNING: see https://wiki.archlinux.org/index.php/VMware#3.17_kernels to get correct version of patch for your kernel
$ curl #e37407;" href="http://pastie.org/pastes/8672356/download">http://pastie.org/pastes/8672356/download -o /tmp/vmware-netfilter.patch
$ cd /usr/lib/vmware/modules/source
# tar -xvf vmnet.tar
# patch -p0 -i /tmp/vmware-netfilter.patch
# tar -cf vmnet.tar vmnet-only
# rm -r vmnet-only
# vmware-modconfig --console --install-all

 

Start VMWare

$ vmware

 

ECO 2014 Slides

Just a quick note that I posted slides for the 2 talks I did at ECO in Raleigh this week:

Keynote: Creative Problem Solving (for Oracle Systems)

In-Memory In Action (slides by Tanel Poder) :)

Great crowd. I really enjoyed myself.

Note: You can also find other presentations on my Whitepapers/Presentations page via the link at the top of the screen.

Little things worth knowing: ORACLE_SID, instance_name and the database names in Clusterware

If you ever wanted to know how Clusterware works with registered database resources, read on! It takes a little while to get your head around the concepts of the ORACLE_SID, the instance_name and the database name as well. And how Clusterware deals with all of them. Although this post has been written on 12.1.0.2.0 on Linux, it should be applicable to 11.2 Clusterware as well. Oh and by Clusterware I mean Grid Infrastructure of course ;)

Why would you want to care?

Most deployments I have seen use the simple formula: ORACLE_SID = instance_name = db_name, especially in single instance deployments. RAC One Node and RAC databases are slightly different as their instances are usually named db_name where is the n-th instance in the cluster. What however, if you want to have separate SID, instance name and database names? I keep things simple for now and don’t throw in a different db_unique_name…

Assume for the first part of the article that you have created a database manually, e.g. not using dbca. In this case you define the database properties using the ORACLE_SID, the init.ora file (for db_name and instance_name) as well as the create database statement. Here is an example for my database, DB:

[oracle@oraclelinux ~]$ grep DB /etc/oratab
DB1:/u01/app/oracle/product/12.1.0.2/dbhome_1:N

And for the most basic init.ora:

[oracle@oraclelinux ~]$ cat /u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/initDB1.ora

db_name = DB
instance_name = DB1

db_create_file_dest = '+data'
compatible = 11.2.0.0.0
undo_management=AUTO
db_block_size = 8192
db_files = 300
processes = 500
sga_target=2G
filesystemio_options=setall
recyclebin = off
audit_file_dest=/u01/app/oracle/admin/DB/adump
control_files='+DATA/DB/CONTROLFILE/current.257.862665191'
diagnostic_dest=/u01/app/oracle

So let’s start with the SID

Question 1: can you easily change the ORACLE_SID? Answer is: yes you can. From the point of view of starting the database, the SID is used to look up configuration. Let’s change the ORACLE_SID to DBN (keeping the correct ORACLE_HOME) instead of DB1. Without changing any of the configuration files you will get this:

[oracle@oraclelinux ~]$ export ORACLE_SID=DBN
[oracle@oraclelinux ~]$ sqlplus / as sysdba

SQL*Plus: Release 12.1.0.2.0 Production on Tue Nov 4 07:34:42 2014

Copyright (c) 1982, 2014, Oracle.  All rights reserved.

Connected to an idle instance.

SQL> startup
ORA-01078: failure in processing system parameters
LRM-00109: could not open parameter file '/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/initDBN.ora'
SQL>

What if we change these?

[oracle@oraclelinux dbs]$ mv initDB1.ora initDBN.ora
[oracle@oraclelinux dbs]$ sqlplus / as sysdba

SQL*Plus: Release 12.1.0.2.0 Production on Tue Nov 4 07:36:17 2014

Copyright (c) 1982, 2014, Oracle.  All rights reserved.

Connected to an idle instance.

SQL> startup
ORACLE instance started.

Total System Global Area 2147483648 bytes
Fixed Size		    2926472 bytes
Variable Size		 1677723768 bytes
Database Buffers	  452984832 bytes
Redo Buffers		   13848576 bytes
Database mounted.
Database opened.
SQL>

Checking the background processes you can see that they are named …DBN:

[oracle@oraclelinux dbs]$ ps -ef | grep smon
oracle    1519     1  0 07:02 ?        00:00:00 asm_smon_+ASM
oracle    5073     1  0 07:36 ?        00:00:00 ora_smon_DBN
oracle    5425  1586  0 07:37 pts/0    00:00:00 grep smon
[oracle@oraclelinux dbs]$

Now in this case we have an instance_name of DB1, and an ORACLE_SID of DBN instead of DB1. The database name is still set to DB.

Registering a resource in Clusterware

Question 2: How can you register such a construct in Clusterware? This is an Oracle Restart configuration so I can’t show you how it works in RAC, but I can show you the registration and management for the single instance deployment. Keeping the above settings, you can use the srvctl add database command to add the database to Clusterware. Here is an example. If you used DBCA to create the database, it would use the same technique. Note that I have updated /etc/oratab, replacing DB1 with DBN to reflect the new ORACLE_SID.

[oracle@oraclelinux ~]$ srvctl add database -h

Adds a database configuration to be managed by Oracle Restart.

Usage: srvctl add database -db  -oraclehome  [-domain ] [-spfile ] [-pwfile ] [-role {PRIMARY | PHYSICAL_STANDBY | LOGICAL_STANDBY | SNAPSHOT_STANDBY | FAR_SYNC}] [-startoption ] [-stopoption ] [-dbname ] [-instance ] [-policy {AUTOMATIC | MANUAL | NORESTART}] [-diskgroup ""]
    -db            Unique name for the database
    -oraclehome              Oracle home path
    -domain                Domain for database. Must be set if database has DB_DOMAIN set.
    -spfile                Server parameter file path
    -pwfile    Password file path
    -role                    Role of the database (PRIMARY, PHYSICAL_STANDBY, LOGICAL_STANDBY, SNAPSHOT_STANDBY, FAR_SYNC)
    -startoption    Startup options for the database. Examples of startup options are OPEN, MOUNT, or "READ ONLY".
    -stopoption      Stop options for the database. Examples of shutdown options are NORMAL, TRANSACTIONAL, IMMEDIATE, or ABORT.
    -dbname               Database name (DB_NAME), if different from the unique name given by the -db option
    -instance           Instance name
    -policy              Management policy for the database (AUTOMATIC, MANUAL, or NORESTART)
    -diskgroup ""  Comma separated list of disk group names
    -verbose                       Verbose output
    -help                          Print usage

[oracle@oraclelinux ~]$ srvctl add database -db DB -oraclehome /u01/app/oracle/product/12.1.0.2/dbhome_1 \
> -pwfile /u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/initDBN.ora -role PRIMARY \
> -instance DBN -policy MANUAL -diskgroup "DATA,RECO"

Now the database is registered and I can query it’s configuration:

[oracle@oraclelinux ~]$ srvctl config database -d DB
Database unique name: DB
Database name:
Oracle home: /u01/app/oracle/product/12.1.0.2/dbhome_1
Oracle user: oracle
Spfile:
Password file: /u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/initDBN.ora
Domain:
Start options: open
Stop options: immediate
Database role: PRIMARY
Management policy: MANUAL
Disk Groups: DATA,RECO
Services:
OSDBA group:
OSOPER group:
Database instance: DBN

How does Clusterware connect to my database?

Question 3: How does Clusterware connect to the database to perform administrative tasks such as shutting it down and starting it up?

The answer to that question is found in the oraagent log file. Its location changed in 12c. In 11.2 you found all relevant logs in $GRID_HOME/log/$(hostname -s). In 12c they moved to the diagnostic_dest. In my case the oracle account “owns” Clusterware and the RDBMS stack so that’ll be in $ORACLE_BASE/diag. The complete path to the agent log in my environment is /u01/app/oracle/diag/crs/oraclelinux/crs/trace, and the file to check is ohasd_oraagent_oracle.trc. In RAC the file locations are different-in Oracle Restart there isn’t a CRSD process.

Since this file gets a little verbose even with the low log levels, it’s a good idea to note down when you were performing your test. In the output to follow I skipped all the bits that aren’t relevant for this discussion, otherwise you probably wouldn’t see the wood for the trees.

2014-11-04 07:49:11.128239 :    AGFW:3548362496: {0:0:1726} Agent received the message: RESOURCE_START[ora.db.db 1 1] ID 4098:4393

2014-11-04 07:49:11.128266 :    AGFW:3548362496: {0:0:1726} ora.db.db 1 1 state changed from: UNKNOWN to: STARTING

2014-11-04 07:49:11.130019 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] clsnUtils::cmdIdIsStart CmdId:257
2014-11-04 07:49:11.130051 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] DbAgent:getOracleSid 13 oracle_sid = DBN
2014-11-04 07:49:11.130059 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] DbAgent:getOracleSid  oracle_sid = DBN
2014-11-04 07:49:11.130121 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] Utils::getOracleHomeAttrib oracle_home:/u01/app/oracle/product/12.1.0.2/dbhome_1
2014-11-04 07:49:11.130213 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] ConnectionPool::ConnectionPool 2 m_oracleHome:/u01/app/oracle/product/12.1.0.2/dbhome_1, m_oracleSid:DBN, m_usrOraEnv:  m_instanceType:1 m_instanceVersion:12.1.0.2.0
2014-11-04 07:49:11.130254 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] DbAgent::setOracleSidAttrib updating GEN_USR_ORA_INST_NAME to DBN
2014-11-04 07:49:11.130267 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] clsnUtils::setResAttrib nonPerX current value GEN_USR_ORA_INST_NAME value 

2014-11-04 07:49:11.132339 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] ConfigFile::parse mmap name:prod nameWithCase:prod value:/u01/app/oracle/product/12.1.0.2/dbhome_1:N comment:line added by Agent StartCompleted

2014-11-04 07:49:11.135691 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] ConfigFile::parse mmap name:dbn nameWithCase:DBN value:/u01/app/oracle/product/12.1.0.2/dbhome_1:N comment:line added by Agent

2014-11-04 07:49:11.166499 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] start dependency = hard(ora.DATA.dg,ora.RECO.dg) weak(type:ora.listener.type,uniform:ora.ons)

2014-11-04 07:49:11.269849 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] DbAgent:getConnection oracleHome:/u01/app/oracle/product/12.1.0.2/dbhome_1 oracleSid:DBN usrOraEnv: resVersion:12.1.0.2.0
2014-11-04 07:49:11.269958 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] InstConnection:InstConnection: init:c80b40b0 oracleHome:/u01/app/oracle/product/12.1.0.2/dbhome_1 oracleSid:DBN instanceType:1 instanceVersion:12.1.0.2.0
2014-11-04 07:49:11.270631 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] clsnInstConnection::makeConnectStr UsrOraEnv ,ORACLE_BASE= m_oracleHome /u01/app/oracle/product/12.1.0.2/dbhome_1 Crshome /u01/app/oracle/product/12.1.0.2/grid
2014-11-04 07:49:11.271977 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] makeConnectStr = (DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/u01/app/oracle/product/12.1.0.2/dbhome_1/bin/oracle)(ARGV0=oracleDBN)(ENVS='ORACLE_HOME=/u01/app/oracle/product/12.1.0.2/dbhome_1,ORACLE_SID=DBN,LD_LIBRARY_PATH=,ORACLE_BASE=')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))')(CONNECT_DATA=(SID=DBN))))
2014-11-04 07:49:11.275192 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] Container:start oracle home /u01/app/oracle/product/12.1.0.2/dbhome_1
2014-11-04 07:49:11.275657 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] InstConnection::connectInt: server not attached
2014-11-04 07:49:12.315345 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] InstConnection:connectInt connected

2014-11-04 07:49:24.231865 :    AGFW:3548362496: {0:0:1726} ora.db.db 1 1 state changed from: STARTING to: ONLINE

This should be enough information to get us started. Now what’s happening here? First of all the Agent Framework (AGFW) receives the command to start the database. Oracle Clusterware manages resources, and the database is one of these. Each resource to be managed has to have a profile in Clusterware. The profile determines what Clusterware does with a resource. The profile for the DB resource is shown here for reference.

[oracle@oraclelinux ~]$ crsctl stat res ora.db.db -p
NAME=ora.db.db
TYPE=ora.database.type
ACL=owner:oracle:rwx,pgrp:asmdba:r-x,other::r--,group:oinstall:r-x,user:oracle:rwx
ACTIONS=startoption,group:"asmdba",user:"oracle",group:"oinstall"
ACTION_SCRIPT=
ACTION_START_OPTION=
ACTION_TIMEOUT=600
ACTIVE_PLACEMENT=0
AGENT_FILENAME=%CRS_HOME%/bin/oraagent%CRS_EXE_SUFFIX%
AUTO_START=never
CARDINALITY=1
CHECK_INTERVAL=1
CHECK_TIMEOUT=30
CLEAN_TIMEOUT=60
CLUSTER_DATABASE=false
DATABASE_TYPE=SINGLE
DB_UNIQUE_NAME=DB
DEGREE=1
DELETE_TIMEOUT=60
DESCRIPTION=Oracle Database resource
ENABLED=1
FAILOVER_DELAY=0
FAILURE_INTERVAL=60
FAILURE_THRESHOLD=1
GEN_AUDIT_FILE_DEST=/u01/app/oracle/admin/DB/adump
GEN_START_OPTIONS=
GEN_USR_ORA_INST_NAME=DBN
HOSTING_MEMBERS=
INSTANCE_FAILOVER=1
INTERMEDIATE_TIMEOUT=0
LOAD=1
LOGGING_LEVEL=1
MANAGEMENT_POLICY=MANUAL
MODIFY_TIMEOUT=60
NLS_LANG=
OFFLINE_CHECK_INTERVAL=0
ONLINE_RELOCATION_TIMEOUT=0
ORACLE_HOME=/u01/app/oracle/product/12.1.0.2/dbhome_1
ORACLE_HOME_OLD=
OS_CRASH_THRESHOLD=0
OS_CRASH_UPTIME=0
PLACEMENT=balanced
PWFILE=/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/initDBN.ora
RANK=0
RELOCATE_ACTION=0
RELOCATE_BY_DEPENDENCY=1
RESTART_ATTEMPTS=1
ROLE=PRIMARY
SCRIPT_TIMEOUT=60
SERVER_CATEGORY=
SERVER_POOLS=
SERVER_POOLS_PQ=
SPFILE=
START_CONCURRENCY=0
START_DEPENDENCIES=hard(ora.DATA.dg,ora.RECO.dg) weak(type:ora.listener.type,uniform:ora.ons)
START_TIMEOUT=600
STOP_CONCURRENCY=0
STOP_DEPENDENCIES=hard(intermediate:ora.asm,shutdown:ora.DATA.dg,shutdown:ora.RECO.dg)
STOP_TIMEOUT=600
TYPE_VERSION=3.3
UPTIME_THRESHOLD=1h
USER_WORKLOAD=yes
USE_STICKINESS=0
USR_ORA_DB_NAME=
USR_ORA_DOMAIN=
USR_ORA_ENV=
USR_ORA_FLAGS=
USR_ORA_INST_NAME=DBN
USR_ORA_OPEN_MODE=open
USR_ORA_OPI=false
USR_ORA_STOP_MODE=immediate

Back to the start sequence. After the start command has been received the configuration is looked up in /etc/oratab. Any start dependencies (disk groups DATA and RECO, the listener and the ONS daemon as shown in the profile) are validated and satisfied if needed. The most interesting information is found in makeConnectStr: using the ORACLE_SID and the associated information (ORACLE_HOME) the connection string is dynamically created:

2014-11-04 07:49:11.271977 :CLSDYNAM:3552564992: [ora.db.db]{0:0:1726} [start] makeConnectStr = (DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/u01/app/oracle/prod
uct/12.1.0.2/dbhome_1/bin/oracle)(ARGV0=oracleDBN)(ENVS='ORACLE_HOME=/u01/app/oracle/product/12.1.0.2/dbhome_1,ORACLE_SID=DBN,LD_LIBRARY_PATH=,ORACLE_BASE=')(ARG
S='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))')(CONNECT_DATA=(SID=DBN))))

This will be used to connect to the database instance and start it up. Oracle isn’t able to magically correct any configuration errors. If you define the instance to be DB1 in the srvctl add database command Clusterware won’t be able to start the instance. Just like you aren’t able to start it with SQL*Plus either. The oraagent_oracle.log file on RAC and the ohasd_oraagent_oracle.trc are good starting point to check for issues. Another useful flag is SRVM_TRACE:

[oracle@oraclelinux ~]$ grep SRVM_TRACE $(which srvctl)
if [ "X${SRVM_TRACE}" != "X" ]
  if [ "${SRVM_TRACE}" != "false" ]  && [ "${SRVM_TRACE}" != "FALSE" ]

Applied, this shows some rather verbose output but can help you in cases the resource won’t start. I’ll close this article with a traced call to get the status of the DB database and leave the interpretation of the output as an exercise to the reader.

[oracle@oraclelinux ~]$ SRVM_TRACE=TRUE srvctl status database -db DB
[main] [ 2014-11-04 08:11:36.482 GMT ] [OPSCTLDriver.setInternalDebugLevel:325]  tracing is true at level 2 to file null
[main] [ 2014-11-04 08:11:36.488 GMT ] [OPSCTLDriver.main:162]  SRVCTL arguments : args[0]=status args[1]=database args[2]=-db args[3]=DB
[main] [ 2014-11-04 08:11:36.490 GMT ] [SRVMContext.init:114]  Performing SRVM Context init. Init Counter=1
[main] [ 2014-11-04 08:11:36.527 GMT ] [Library.load:194]  library.load
[main] [ 2014-11-04 08:11:36.529 GMT ] [sPlatform.isHybrid:66]  osName=Linux osArch=amd64 JVM=64 rc=false
[main] [ 2014-11-04 08:11:36.530 GMT ] [sPlatform.isHybrid:66]  osName=Linux osArch=amd64 JVM=64 rc=false
[main] [ 2014-11-04 08:11:36.531 GMT ] [Library.load:271]  Loading  library /u01/app/oracle/product/12.1.0.2/dbhome_1/lib/libsrvmhas12.so
[main] [ 2014-11-04 08:11:36.546 GMT ] [SRVMContext.init:131]  SRVM Context init-ed
[main] [ 2014-11-04 08:11:36.568 GMT ] [Version.isPre:610]  version to be checked 12.1.0.2.0 major version to check against 10
[main] [ 2014-11-04 08:11:36.574 GMT ] [Version.isPre:621]  isPre.java: Returning FALSE
[main] [ 2014-11-04 08:11:36.580 GMT ] [OCR.loadLibrary:328]
 Inside constructor of OCR
[main] [ 2014-11-04 08:11:36.584 GMT ] [OCR.loadLibrary:336]  Going to load the ocr library
[main] [ 2014-11-04 08:11:36.585 GMT ] [Library.load:194]  library.load
[main] [ 2014-11-04 08:11:36.585 GMT ] [sPlatform.isHybrid:66]  osName=Linux osArch=amd64 JVM=64 rc=false
[main] [ 2014-11-04 08:11:36.587 GMT ] [sPlatform.isHybrid:66]  osName=Linux osArch=amd64 JVM=64 rc=false
[main] [ 2014-11-04 08:11:36.588 GMT ] [Library.load:271]  Loading  library /u01/app/oracle/product/12.1.0.2/dbhome_1/lib/libsrvmocr12.so
[main] [ 2014-11-04 08:11:36.589 GMT ] [OCR.loadLibrary:338]  loaded ocr libraries
[main] [ 2014-11-04 08:11:36.590 GMT ] [SRVMContext.init:114]  Performing SRVM Context init. Init Counter=2
[main] [ 2014-11-04 08:11:36.590 GMT ] [OCR.isCluster:1000]  Calling OCRNative for isCluster()
[main] [ 2014-11-04 08:11:36.592 GMT ] [OCR.isCluster:1004]  OCR Result status = true
[main] [ 2014-11-04 08:11:36.593 GMT ] [OCR.isCluster:1016]  Bolean result = false
[main] [ 2014-11-04 08:11:36.594 GMT ] [CommandLineParser.:488]  Is this a cluster? : false
[main] [ 2014-11-04 08:11:36.599 GMT ] [CommandLineParser.parse:678]  parsing cmdline args
[main] [ 2014-11-04 08:11:36.601 GMT ] [CommandLineParser.antlrParse:500]  parsing cmdline args using antlr
[main] [ 2014-11-04 08:11:36.603 GMT ] [CommandLineParser.antlrParse:558]  input args are status database -db %OPTVAL%DB
[main] [ 2014-11-04 08:11:36.641 GMT ] [SrvExprParser.optverb:826]  antlr: Match verb
[main] [ 2014-11-04 08:11:36.642 GMT ] [SrvExprParser.optnoun:873]  antlr: Match noun
[main] [ 2014-11-04 08:11:36.644 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for output
[main] [ 2014-11-04 08:11:36.644 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.645 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for compatible
[main] [ 2014-11-04 08:11:36.645 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.646 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for HELP
[main] [ 2014-11-04 08:11:36.647 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.648 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for help
[main] [ 2014-11-04 08:11:36.648 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.649 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for file
[main] [ 2014-11-04 08:11:36.649 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.650 GMT ] [SrvExprParser.optval:906]  antlr: Call initOptVals for status database
[main] [ 2014-11-04 08:11:36.650 GMT ] [SrvExprParser.optval:946]  antlr: Getting OPTION VALUE
[main] [ 2014-11-04 08:11:36.651 GMT ] [SrvExprParser.optval:948]  antlr: Set -db value: %OPTVAL%DB
[main] [ 2014-11-04 08:11:36.652 GMT ] [CmdOptVals.checkAndSet:734]  Calling checkAndSet for -db = -db
[main] [ 2014-11-04 08:11:36.653 GMT ] [CmdOptVals.checkAndSet:802]  Calling checkAndSet for OptEnum db = DB
[main] [ 2014-11-04 08:11:36.654 GMT ] [OptVal.check:180]  Value DB for option db will be set.
[main] [ 2014-11-04 08:11:36.655 GMT ] [OptVal.check:221]  db = DB
[main] [ 2014-11-04 08:11:36.655 GMT ] [SrvExprParser.cmdline:529]  antlr: Set verb and noun and options
[main] [ 2014-11-04 08:11:36.656 GMT ] [SrvExprParser.srvrule:219]  antlr: Return optvals
[main] [ 2014-11-04 08:11:36.656 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for file
[main] [ 2014-11-04 08:11:36.657 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.658 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for help
[main] [ 2014-11-04 08:11:36.658 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.659 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for db
[main] [ 2014-11-04 08:11:36.660 GMT ] [OptVal.isSet:150]  m_value is DB
[main] [ 2014-11-04 08:11:36.660 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for database
[main] [ 2014-11-04 08:11:36.661 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.661 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for db
[main] [ 2014-11-04 08:11:36.662 GMT ] [OptVal.isSet:150]  m_value is DB
[main] [ 2014-11-04 08:11:36.663 GMT ] [CommandLineParser.checkOptionalCombOptions:813]  Loop for combList(0)
[main] [ 2014-11-04 08:11:36.663 GMT ] [CommandLineParser.checkOptionalCombOptions:815]  Set isMatched to true
[main] [ 2014-11-04 08:11:36.664 GMT ] [CommandLineParser.checkOptionalCombOptions:829]  Check option -db
[main] [ 2014-11-04 08:11:36.665 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for db
[main] [ 2014-11-04 08:11:36.666 GMT ] [OptVal.isSet:150]  m_value is DB
[main] [ 2014-11-04 08:11:36.666 GMT ] [CommandLineParser.checkOptionalCombOptions:813]  Loop for combList(1)
[main] [ 2014-11-04 08:11:36.667 GMT ] [CommandLineParser.checkOptionalCombOptions:815]  Set isMatched to true
[main] [ 2014-11-04 08:11:36.667 GMT ] [CommandLineParser.checkOptionalCombOptions:829]  Check option -thisversion
[main] [ 2014-11-04 08:11:36.668 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for thisversion
[main] [ 2014-11-04 08:11:36.668 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.669 GMT ] [CommandLineParser.checkOptionalCombOptions:846]  Set isMatched to false
[main] [ 2014-11-04 08:11:36.671 GMT ] [CommandLineParser.checkOptionalCombOptions:813]  Loop for combList(2)
[main] [ 2014-11-04 08:11:36.672 GMT ] [CommandLineParser.checkOptionalCombOptions:815]  Set isMatched to true
[main] [ 2014-11-04 08:11:36.672 GMT ] [CommandLineParser.checkOptionalCombOptions:829]  Check option -thishome
[main] [ 2014-11-04 08:11:36.673 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for thishome
[main] [ 2014-11-04 08:11:36.674 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.675 GMT ] [CommandLineParser.checkOptionalCombOptions:846]  Set isMatched to false
[main] [ 2014-11-04 08:11:36.675 GMT ] [CmdOptVals.checkRefChoices:1066]  in checkRefChoices
[main] [ 2014-11-04 08:11:36.676 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for output
[main] [ 2014-11-04 08:11:36.677 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.678 GMT ] [OPSCTLDriver.main:215]  Attempting to register interrupt handler for OPSCTL driver
[main] [ 2014-11-04 08:11:36.681 GMT ] [InterruptHandler.registerInterruptHandler:60]  Registering shutdown hook.....
[main] [ 2014-11-04 08:11:36.682 GMT ] [InterruptHandler.registerInterruptHandler:62]  Registered shutdown hook.....
[main] [ 2014-11-04 08:11:36.683 GMT ] [SRVCTLHandler.registerInterruptHandler:86]  Registered interrupt handler for OPSCTL driver
[main] [ 2014-11-04 08:11:36.684 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for compatible
[main] [ 2014-11-04 08:11:36.684 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.685 GMT ] [OPSCTLDriver.execute:345]  checking for -H option: print verbose command syntax
[main] [ 2014-11-04 08:11:36.685 GMT ] [CmdOptVals.isOptionSet:917]  Check isOptionSet for HELP
[main] [ 2014-11-04 08:11:36.687 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for help
[main] [ 2014-11-04 08:11:36.687 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.688 GMT ] [CmdOptVals.isOptionSet:917]  Check isOptionSet for HELP_H
[main] [ 2014-11-04 08:11:36.688 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for HELP
[main] [ 2014-11-04 08:11:36.689 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:36.711 GMT ] [CRSCache.:74]  CRSCache: useCache is false
[main] [ 2014-11-04 08:11:36.712 GMT ] [OPSCTLDriver.execute:411]  executing 2-word command verb=6 noun=101
[main] [ 2014-11-04 08:11:36.746 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for db
[main] [ 2014-11-04 08:11:36.748 GMT ] [OptVal.isSet:150]  m_value is DB
[main] [ 2014-11-04 08:11:36.763 GMT ] [DatabaseFactoryImpl.getInstance:320]  s_instance is null
[main] [ 2014-11-04 08:11:36.765 GMT ] [DatabaseFactoryImpl.getInstance:323]  before returning object
[main] [ 2014-11-04 08:11:36.765 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for db
[main] [ 2014-11-04 08:11:36.766 GMT ] [OptVal.isSet:150]  m_value is DB
[main] [ 2014-11-04 08:11:36.767 GMT ] [DatabaseFactoryImpl.getDatabase:995]  Before calling get database with name and version
[main] [ 2014-11-04 08:11:36.815 GMT ] [HASContext.:125]  moduleInit = 67
[main] [ 2014-11-04 08:11:36.816 GMT ] [SRVMContext.init:114]  Performing SRVM Context init. Init Counter=3
[main] [ 2014-11-04 08:11:36.816 GMT ] [HASContext.:136]  Initialised SRVMContext
[main] [ 2014-11-04 08:11:36.882 GMT ] [EntityOperations.isEntityRegisteredCRSD:353]  entity: ora.db.db, type: 1, registered: true
[main] [ 2014-11-04 08:11:36.896 GMT ] [CRSCache.getAttributesFromCache:220]  updated: ora.db.db [, , ]
[main] [ 2014-11-04 08:11:36.898 GMT ] [DatabaseFactoryImpl.internalGetDatabase:1115]  dbVersion4 = 12.1.0.2
[main] [ 2014-11-04 08:11:36.901 GMT ] [DatabaseFactoryImpl.internalGetDatabase:1129]  db type SINGLE
[main] [ 2014-11-04 08:11:36.905 GMT ] [Version.isPre:610]  version to be checked 12.1.0.2.0 major version to check against 11
[main] [ 2014-11-04 08:11:36.906 GMT ] [Version.isPre:621]  isPre.java: Returning FALSE
[main] [ 2014-11-04 08:11:36.907 GMT ] [Version.isPre:642]  version to be checked 12.1.0.2.0 major version to check against 11 minor version to check against 2
[main] [ 2014-11-04 08:11:36.908 GMT ] [Version.isPre:651]  isPre: Returning FALSE for major version check
[main] [ 2014-11-04 08:11:36.908 GMT ] [DatabaseFactoryImpl.getSingleInstanceDatabase:1923]  Getting single instance database for DB
[main] [ 2014-11-04 08:11:36.920 GMT ] [DatabaseAction.:80]  Created Database Action
[main] [ 2014-11-04 08:11:36.932 GMT ] [CRSCache.getAttributesFromCache:220]  updated: ora.db.db []
[main] [ 2014-11-04 08:11:36.933 GMT ] [DatabaseImpl.crsResource:5254]  calling parent's crsResource
[main] [ 2014-11-04 08:11:36.980 GMT ] [EntityOperations.isEntityRegisteredCRSD:353]  entity: ora.db.db, type: 1, registered: true
[main] [ 2014-11-04 08:11:36.987 GMT ] [CRSCache.getAttributesFromCache:229]  CRS cache: ora.db.db []
[main] [ 2014-11-04 08:11:36.990 GMT ] [Version.isPre:610]  version to be checked 12.1.0.2.0 major version to check against 11
[main] [ 2014-11-04 08:11:36.991 GMT ] [Version.isPre:621]  isPre.java: Returning FALSE
[main] [ 2014-11-04 08:11:36.991 GMT ] [Version.isPre:691]  version to be checked 12.1.0.2.0 major version to check against 11 minor version to check against 2 patchset version to check against 2
[main] [ 2014-11-04 08:11:36.992 GMT ] [Version.isPre:701]  isPre: Returning FALSE for major version check
[main] [ 2014-11-04 08:11:36.993 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:36.994 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: all
[main] [ 2014-11-04 08:11:37.031 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: [, , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , ]
[main] [ 2014-11-04 08:11:37.032 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STATE, value=ONLINE
[main] [ 2014-11-04 08:11:37.033 GMT ] [DatabaseImpl.getDBInstances:2356]  name=TARGET, value=ONLINE
[main] [ 2014-11-04 08:11:37.034 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACL, value=owner:oracle:rwx,pgrp:asmdba:r-x,other::r--,group:oinstall:r-x,user:oracle:rwx
[main] [ 2014-11-04 08:11:37.035 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTIONS, value=startoption,group:"asmdba",user:"oracle",group:"oinstall"
[main] [ 2014-11-04 08:11:37.035 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTION_FAILURE_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.036 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTION_SCRIPT, value=
[main] [ 2014-11-04 08:11:37.037 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTION_START_OPTION, value=
[main] [ 2014-11-04 08:11:37.038 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTION_TIMEOUT, value=600
[main] [ 2014-11-04 08:11:37.038 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTIVE_PLACEMENT, value=0
[main] [ 2014-11-04 08:11:37.039 GMT ] [DatabaseImpl.getDBInstances:2356]  name=AGENT_FILENAME, value=%CRS_HOME%/bin/oraagent%CRS_EXE_SUFFIX%
[main] [ 2014-11-04 08:11:37.039 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ALERT_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.041 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ALIAS_NAME, value=
[main] [ 2014-11-04 08:11:37.042 GMT ] [DatabaseImpl.getDBInstances:2356]  name=AUTO_START, value=never
[main] [ 2014-11-04 08:11:37.042 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CARDINALITY, value=1
[main] [ 2014-11-04 08:11:37.043 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CARDINALITY_ID, value=0
[main] [ 2014-11-04 08:11:37.045 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CHECK_INTERVAL, value=1
[main] [ 2014-11-04 08:11:37.047 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CHECK_TIMEOUT, value=30
[main] [ 2014-11-04 08:11:37.047 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CLEAN_TIMEOUT, value=60
[main] [ 2014-11-04 08:11:37.048 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CLUSTER_DATABASE, value=false
[main] [ 2014-11-04 08:11:37.049 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CONFIG_VERSION, value=1
[main] [ 2014-11-04 08:11:37.050 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CREATION_SEED, value=37
[main] [ 2014-11-04 08:11:37.051 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DATABASE_TYPE, value=SINGLE
[main] [ 2014-11-04 08:11:37.053 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DB_UNIQUE_NAME, value=DB
[main] [ 2014-11-04 08:11:37.053 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DEFAULT_TEMPLATE, value=PROPERTY(RESOURCE_CLASS=database) PROPERTY(DB_UNIQUE_NAME= CONCAT(PARSE(%NAME%, ., 2), %USR_ORA_DOMAIN%, .)) ELEMENT(INSTANCE_NAME= %GEN_USR_ORA_INST_NAME%) ELEMENT(DATABASE_TYPE= %DATABASE_TYPE%)
[main] [ 2014-11-04 08:11:37.054 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DEGREE, value=1
[main] [ 2014-11-04 08:11:37.058 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DEGREE_ID, value=0
[main] [ 2014-11-04 08:11:37.059 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DELETE_TIMEOUT, value=60
[main] [ 2014-11-04 08:11:37.060 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DESCRIPTION, value=Oracle Database resource
[main] [ 2014-11-04 08:11:37.061 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ENABLED, value=1
[main] [ 2014-11-04 08:11:37.061 GMT ] [DatabaseImpl.getDBInstances:2356]  name=FAILOVER_DELAY, value=0
[main] [ 2014-11-04 08:11:37.062 GMT ] [DatabaseImpl.getDBInstances:2356]  name=FAILURE_INTERVAL, value=60
[main] [ 2014-11-04 08:11:37.063 GMT ] [DatabaseImpl.getDBInstances:2356]  name=FAILURE_THRESHOLD, value=1
[main] [ 2014-11-04 08:11:37.063 GMT ] [DatabaseImpl.getDBInstances:2356]  name=GEN_AUDIT_FILE_DEST, value=/u01/app/oracle/admin/DB/adump
[main] [ 2014-11-04 08:11:37.064 GMT ] [DatabaseImpl.getDBInstances:2356]  name=GEN_START_OPTIONS, value=
[main] [ 2014-11-04 08:11:37.064 GMT ] [DatabaseImpl.getDBInstances:2356]  name=GEN_USR_ORA_INST_NAME, value=DBN
[main] [ 2014-11-04 08:11:37.066 GMT ] [DatabaseImpl.getDBInstances:2356]  name=HOSTING_MEMBERS, value=
[main] [ 2014-11-04 08:11:37.066 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ID, value=ora.db.db
[main] [ 2014-11-04 08:11:37.067 GMT ] [DatabaseImpl.getDBInstances:2356]  name=INSTANCE_COUNT, value=1
[main] [ 2014-11-04 08:11:37.068 GMT ] [DatabaseImpl.getDBInstances:2356]  name=INSTANCE_FAILOVER, value=1
[main] [ 2014-11-04 08:11:37.068 GMT ] [DatabaseImpl.getDBInstances:2356]  name=INTERMEDIATE_TIMEOUT, value=0
[main] [ 2014-11-04 08:11:37.069 GMT ] [DatabaseImpl.getDBInstances:2356]  name=LOAD, value=1
[main] [ 2014-11-04 08:11:37.069 GMT ] [DatabaseImpl.getDBInstances:2356]  name=LOGGING_LEVEL, value=1
[main] [ 2014-11-04 08:11:37.071 GMT ] [DatabaseImpl.getDBInstances:2356]  name=MANAGEMENT_POLICY, value=MANUAL
[main] [ 2014-11-04 08:11:37.072 GMT ] [DatabaseImpl.getDBInstances:2356]  name=MODIFY_TIMEOUT, value=60
[main] [ 2014-11-04 08:11:37.072 GMT ] [DatabaseImpl.getDBInstances:2356]  name=NAME, value=ora.db.db
[main] [ 2014-11-04 08:11:37.073 GMT ] [DatabaseImpl.getDBInstances:2356]  name=NLS_LANG, value=
[main] [ 2014-11-04 08:11:37.074 GMT ] [DatabaseImpl.getDBInstances:2356]  name=NOT_RESTARTING_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.075 GMT ] [DatabaseImpl.getDBInstances:2356]  name=OFFLINE_CHECK_INTERVAL, value=0
[main] [ 2014-11-04 08:11:37.076 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ONLINE_RELOCATION_TIMEOUT, value=0
[main] [ 2014-11-04 08:11:37.082 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ORACLE_HOME, value=/u01/app/oracle/product/12.1.0.2/dbhome_1
[main] [ 2014-11-04 08:11:37.083 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ORACLE_HOME_OLD, value=
[main] [ 2014-11-04 08:11:37.084 GMT ] [DatabaseImpl.getDBInstances:2356]  name=OS_CRASH_THRESHOLD, value=0
[main] [ 2014-11-04 08:11:37.085 GMT ] [DatabaseImpl.getDBInstances:2356]  name=OS_CRASH_UPTIME, value=0
[main] [ 2014-11-04 08:11:37.086 GMT ] [DatabaseImpl.getDBInstances:2356]  name=PLACEMENT, value=balanced
[main] [ 2014-11-04 08:11:37.086 GMT ] [DatabaseImpl.getDBInstances:2356]  name=PROFILE_CHANGE_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.087 GMT ] [DatabaseImpl.getDBInstances:2356]  name=PWFILE, value=/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/initDBN.ora
[main] [ 2014-11-04 08:11:37.087 GMT ] [DatabaseImpl.getDBInstances:2356]  name=RANK, value=0
[main] [ 2014-11-04 08:11:37.088 GMT ] [DatabaseImpl.getDBInstances:2356]  name=RELOCATE_ACTION, value=0
[main] [ 2014-11-04 08:11:37.089 GMT ] [DatabaseImpl.getDBInstances:2356]  name=RELOCATE_BY_DEPENDENCY, value=1
[main] [ 2014-11-04 08:11:37.090 GMT ] [DatabaseImpl.getDBInstances:2356]  name=RESTART_ATTEMPTS, value=1
[main] [ 2014-11-04 08:11:37.090 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ROLE, value=PRIMARY
[main] [ 2014-11-04 08:11:37.091 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SCRIPT_TIMEOUT, value=60
[main] [ 2014-11-04 08:11:37.095 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SERVER_CATEGORY, value=
[main] [ 2014-11-04 08:11:37.097 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SERVER_POOLS, value=
[main] [ 2014-11-04 08:11:37.098 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SERVER_POOLS_PQ, value=
[main] [ 2014-11-04 08:11:37.098 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SPFILE, value=
[main] [ 2014-11-04 08:11:37.099 GMT ] [DatabaseImpl.getDBInstances:2356]  name=START_CONCURRENCY, value=0
[main] [ 2014-11-04 08:11:37.099 GMT ] [DatabaseImpl.getDBInstances:2356]  name=START_DEPENDENCIES, value=hard(ora.DATA.dg,ora.RECO.dg) weak(type:ora.listener.type,uniform:ora.ons)
[main] [ 2014-11-04 08:11:37.100 GMT ] [DatabaseImpl.getDBInstances:2356]  name=START_TIMEOUT, value=600
[main] [ 2014-11-04 08:11:37.101 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STATE_CHANGE_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.101 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STOP_CONCURRENCY, value=0
[main] [ 2014-11-04 08:11:37.102 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STOP_DEPENDENCIES, value=hard(intermediate:ora.asm,shutdown:ora.DATA.dg,shutdown:ora.RECO.dg)
[main] [ 2014-11-04 08:11:37.103 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STOP_TIMEOUT, value=600
[main] [ 2014-11-04 08:11:37.104 GMT ] [DatabaseImpl.getDBInstances:2356]  name=TYPE, value=ora.database.type
[main] [ 2014-11-04 08:11:37.105 GMT ] [DatabaseImpl.getDBInstances:2356]  name=TYPE_VERSION, value=3.3
[main] [ 2014-11-04 08:11:37.106 GMT ] [DatabaseImpl.getDBInstances:2356]  name=UPTIME_THRESHOLD, value=1h
[main] [ 2014-11-04 08:11:37.107 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USER_WORKLOAD, value=yes
[main] [ 2014-11-04 08:11:37.108 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USE_STICKINESS, value=0
[main] [ 2014-11-04 08:11:37.109 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_DB_NAME, value=
[main] [ 2014-11-04 08:11:37.110 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_DOMAIN, value=
[main] [ 2014-11-04 08:11:37.110 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_ENV, value=
[main] [ 2014-11-04 08:11:37.111 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_FLAGS, value=
[main] [ 2014-11-04 08:11:37.112 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_INST_NAME, value=DBN
[main] [ 2014-11-04 08:11:37.112 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_OPEN_MODE, value=open
[main] [ 2014-11-04 08:11:37.114 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_OPI, value=false
[main] [ 2014-11-04 08:11:37.114 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_STOP_MODE, value=immediate
[main] [ 2014-11-04 08:11:37.115 GMT ] [DatabaseImpl.getDBInstances:2356]  name=VERSION, value=12.1.0.2.0
[main] [ 2014-11-04 08:11:37.126 GMT ] [CRSCache.getAttributesFromCache:229]  CRS cache: ora.db.db []
[main] [ 2014-11-04 08:11:37.130 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.131 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [HOSTING_MEMBERS]
[main] [ 2014-11-04 08:11:37.134 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.136 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.136 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [SERVER_POOLS]
[main] [ 2014-11-04 08:11:37.158 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.169 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.170 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [SERVER_POOLS]
[main] [ 2014-11-04 08:11:37.175 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.176 GMT ] [DatabaseImpl.serverPoolsHelper:5977]  list of server pool names =
[main] [ 2014-11-04 08:11:37.178 GMT ] [DatabaseImpl.crsResource:5254]  calling parent's crsResource
[main] [ 2014-11-04 08:11:37.201 GMT ] [EntityOperations.isEntityRegisteredCRSD:353]  entity: ora.db.db, type: 1, registered: true
[main] [ 2014-11-04 08:11:37.218 GMT ] [CRSNative.searchEntities:658]  found 0 entities
[main] [ 2014-11-04 08:11:37.218 GMT ] [EntityOperations.fetchRunningNodeNames:1161]  Looking for nodes: resource ora.db.db
[main] [ 2014-11-04 08:11:37.242 GMT ] [CRSNative.searchEntities:658]  found 1 entities
[main] [ 2014-11-04 08:11:37.244 GMT ] [EntityOperations.fetchRunningNodeNames:1193]  	riid : ora.db.db 1 1 node: oraclelinux, state ONLINE, istate STABLE
[main] [ 2014-11-04 08:11:37.251 GMT ] [DatabaseImpl.getDBInstances:2411]  Adding running node oraclelinux
[main] [ 2014-11-04 08:11:37.252 GMT ] [DatabaseImpl.getDBInstances:2415]  asList=[oraclelinux]
[main] [ 2014-11-04 08:11:37.252 GMT ] [DatabaseImpl.crsResource:5254]  calling parent's crsResource
[main] [ 2014-11-04 08:11:37.263 GMT ] [EntityOperations.isEntityRegisteredCRSD:353]  entity: ora.db.db, type: 1, registered: true
[main] [ 2014-11-04 08:11:37.286 GMT ] [CRSNative.searchEntities:658]  found 1 entities
[main] [ 2014-11-04 08:11:37.289 GMT ] [DatabaseImpl.getDBInstances:2421]  size of resultData = 1
[main] [ 2014-11-04 08:11:37.290 GMT ] [DatabaseImpl.getDBInstances:2454]  riID=ora.db.db 1 1 result={LAST_SERVER=oraclelinux}
[main] [ 2014-11-04 08:11:37.292 GMT ] [DatabaseImpl.getDBInstances:2481]  not getting any value from GEN
[main] [ 2014-11-04 08:11:37.292 GMT ] [DatabaseImpl.getDBInstances:2485]  both gen and config, instance name = DBN
[main] [ 2014-11-04 08:11:37.293 GMT ] [CRSCache.getAttributesFromCache:229]  CRS cache: ora.db.db []
[main] [ 2014-11-04 08:11:37.294 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.295 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [HOSTING_MEMBERS]
[main] [ 2014-11-04 08:11:37.304 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.304 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.305 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [SERVER_POOLS]
[main] [ 2014-11-04 08:11:37.327 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.340 GMT ] [Util.:103]  Util Instance created.
[main] [ 2014-11-04 08:11:37.342 GMT ] [DatabaseImpl.getDBInstances:2543]  instName=DBN nodeName=oraclelinux
[main] [ 2014-11-04 08:11:37.346 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.347 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [SERVER_POOLS_PQ]
[main] [ 2014-11-04 08:11:37.351 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.352 GMT ] [StatusAction.internalExecuteDatabase:491]  number of instances = 1
[main] [ 2014-11-04 08:11:37.353 GMT ] [StatusAction.internalExecuteDatabase:494]  instance name = DBN
[main] [ 2014-11-04 08:11:37.354 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for thisversion
[main] [ 2014-11-04 08:11:37.354 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:37.355 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for thishome
[main] [ 2014-11-04 08:11:37.356 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:37.357 GMT ] [DatabaseImpl.crsResource:5254]  calling parent's crsResource
[main] [ 2014-11-04 08:11:37.371 GMT ] [EntityOperations.isEntityRegisteredCRSD:353]  entity: ora.db.db, type: 1, registered: true
[main] [ 2014-11-04 08:11:37.398 GMT ] [CRSNative.searchEntities:658]  found 1 entities
[main] [ 2014-11-04 08:11:37.399 GMT ] [CRSNative.fetchStatusByNodesName:594]  	node: oraclelinux, status ONLINE, istate STABLE
[main] [ 2014-11-04 08:11:37.401 GMT ] [StatusAction$StatusDescription.:4977]  StatusOnNode: node oraclelinux, value: RUNNING_ON_NODE
[main] [ 2014-11-04 08:11:37.402 GMT ] [Version.isPre:610]  version to be checked 12.1.0.2.0 major version to check against 11
[main] [ 2014-11-04 08:11:37.402 GMT ] [Version.isPre:621]  isPre.java: Returning FALSE
[main] [ 2014-11-04 08:11:37.403 GMT ] [Version.isPre:691]  version to be checked 12.1.0.2.0 major version to check against 11 minor version to check against 2 patchset version to check against 2
[main] [ 2014-11-04 08:11:37.404 GMT ] [Version.isPre:701]  isPre: Returning FALSE for major version check
[main] [ 2014-11-04 08:11:37.405 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.405 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: all
[main] [ 2014-11-04 08:11:37.424 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: [, , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , , ]
[main] [ 2014-11-04 08:11:37.425 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STATE, value=ONLINE
[main] [ 2014-11-04 08:11:37.426 GMT ] [DatabaseImpl.getDBInstances:2356]  name=TARGET, value=ONLINE
[main] [ 2014-11-04 08:11:37.427 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACL, value=owner:oracle:rwx,pgrp:asmdba:r-x,other::r--,group:oinstall:r-x,user:oracle:rwx
[main] [ 2014-11-04 08:11:37.427 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTIONS, value=startoption,group:"asmdba",user:"oracle",group:"oinstall"
[main] [ 2014-11-04 08:11:37.428 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTION_FAILURE_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.428 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTION_SCRIPT, value=
[main] [ 2014-11-04 08:11:37.429 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTION_START_OPTION, value=
[main] [ 2014-11-04 08:11:37.429 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTION_TIMEOUT, value=600
[main] [ 2014-11-04 08:11:37.430 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ACTIVE_PLACEMENT, value=0
[main] [ 2014-11-04 08:11:37.431 GMT ] [DatabaseImpl.getDBInstances:2356]  name=AGENT_FILENAME, value=%CRS_HOME%/bin/oraagent%CRS_EXE_SUFFIX%
[main] [ 2014-11-04 08:11:37.432 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ALERT_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.432 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ALIAS_NAME, value=
[main] [ 2014-11-04 08:11:37.433 GMT ] [DatabaseImpl.getDBInstances:2356]  name=AUTO_START, value=never
[main] [ 2014-11-04 08:11:37.434 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CARDINALITY, value=1
[main] [ 2014-11-04 08:11:37.435 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CARDINALITY_ID, value=0
[main] [ 2014-11-04 08:11:37.435 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CHECK_INTERVAL, value=1
[main] [ 2014-11-04 08:11:37.436 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CHECK_TIMEOUT, value=30
[main] [ 2014-11-04 08:11:37.436 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CLEAN_TIMEOUT, value=60
[main] [ 2014-11-04 08:11:37.437 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CLUSTER_DATABASE, value=false
[main] [ 2014-11-04 08:11:37.438 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CONFIG_VERSION, value=1
[main] [ 2014-11-04 08:11:37.439 GMT ] [DatabaseImpl.getDBInstances:2356]  name=CREATION_SEED, value=37
[main] [ 2014-11-04 08:11:37.439 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DATABASE_TYPE, value=SINGLE
[main] [ 2014-11-04 08:11:37.440 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DB_UNIQUE_NAME, value=DB
[main] [ 2014-11-04 08:11:37.441 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DEFAULT_TEMPLATE, value=PROPERTY(RESOURCE_CLASS=database) PROPERTY(DB_UNIQUE_NAME= CONCAT(PARSE(%NAME%, ., 2), %USR_ORA_DOMAIN%, .)) ELEMENT(INSTANCE_NAME= %GEN_USR_ORA_INST_NAME%) ELEMENT(DATABASE_TYPE= %DATABASE_TYPE%)
[main] [ 2014-11-04 08:11:37.442 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DEGREE, value=1
[main] [ 2014-11-04 08:11:37.444 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DEGREE_ID, value=0
[main] [ 2014-11-04 08:11:37.444 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DELETE_TIMEOUT, value=60
[main] [ 2014-11-04 08:11:37.445 GMT ] [DatabaseImpl.getDBInstances:2356]  name=DESCRIPTION, value=Oracle Database resource
[main] [ 2014-11-04 08:11:37.446 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ENABLED, value=1
[main] [ 2014-11-04 08:11:37.447 GMT ] [DatabaseImpl.getDBInstances:2356]  name=FAILOVER_DELAY, value=0
[main] [ 2014-11-04 08:11:37.447 GMT ] [DatabaseImpl.getDBInstances:2356]  name=FAILURE_INTERVAL, value=60
[main] [ 2014-11-04 08:11:37.448 GMT ] [DatabaseImpl.getDBInstances:2356]  name=FAILURE_THRESHOLD, value=1
[main] [ 2014-11-04 08:11:37.449 GMT ] [DatabaseImpl.getDBInstances:2356]  name=GEN_AUDIT_FILE_DEST, value=/u01/app/oracle/admin/DB/adump
[main] [ 2014-11-04 08:11:37.450 GMT ] [DatabaseImpl.getDBInstances:2356]  name=GEN_START_OPTIONS, value=
[main] [ 2014-11-04 08:11:37.450 GMT ] [DatabaseImpl.getDBInstances:2356]  name=GEN_USR_ORA_INST_NAME, value=DBN
[main] [ 2014-11-04 08:11:37.451 GMT ] [DatabaseImpl.getDBInstances:2356]  name=HOSTING_MEMBERS, value=
[main] [ 2014-11-04 08:11:37.452 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ID, value=ora.db.db
[main] [ 2014-11-04 08:11:37.452 GMT ] [DatabaseImpl.getDBInstances:2356]  name=INSTANCE_COUNT, value=1
[main] [ 2014-11-04 08:11:37.453 GMT ] [DatabaseImpl.getDBInstances:2356]  name=INSTANCE_FAILOVER, value=1
[main] [ 2014-11-04 08:11:37.454 GMT ] [DatabaseImpl.getDBInstances:2356]  name=INTERMEDIATE_TIMEOUT, value=0
[main] [ 2014-11-04 08:11:37.455 GMT ] [DatabaseImpl.getDBInstances:2356]  name=LOAD, value=1
[main] [ 2014-11-04 08:11:37.455 GMT ] [DatabaseImpl.getDBInstances:2356]  name=LOGGING_LEVEL, value=1
[main] [ 2014-11-04 08:11:37.456 GMT ] [DatabaseImpl.getDBInstances:2356]  name=MANAGEMENT_POLICY, value=MANUAL
[main] [ 2014-11-04 08:11:37.456 GMT ] [DatabaseImpl.getDBInstances:2356]  name=MODIFY_TIMEOUT, value=60
[main] [ 2014-11-04 08:11:37.457 GMT ] [DatabaseImpl.getDBInstances:2356]  name=NAME, value=ora.db.db
[main] [ 2014-11-04 08:11:37.458 GMT ] [DatabaseImpl.getDBInstances:2356]  name=NLS_LANG, value=
[main] [ 2014-11-04 08:11:37.458 GMT ] [DatabaseImpl.getDBInstances:2356]  name=NOT_RESTARTING_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.459 GMT ] [DatabaseImpl.getDBInstances:2356]  name=OFFLINE_CHECK_INTERVAL, value=0
[main] [ 2014-11-04 08:11:37.459 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ONLINE_RELOCATION_TIMEOUT, value=0
[main] [ 2014-11-04 08:11:37.460 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ORACLE_HOME, value=/u01/app/oracle/product/12.1.0.2/dbhome_1
[main] [ 2014-11-04 08:11:37.461 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ORACLE_HOME_OLD, value=
[main] [ 2014-11-04 08:11:37.462 GMT ] [DatabaseImpl.getDBInstances:2356]  name=OS_CRASH_THRESHOLD, value=0
[main] [ 2014-11-04 08:11:37.462 GMT ] [DatabaseImpl.getDBInstances:2356]  name=OS_CRASH_UPTIME, value=0
[main] [ 2014-11-04 08:11:37.463 GMT ] [DatabaseImpl.getDBInstances:2356]  name=PLACEMENT, value=balanced
[main] [ 2014-11-04 08:11:37.463 GMT ] [DatabaseImpl.getDBInstances:2356]  name=PROFILE_CHANGE_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.464 GMT ] [DatabaseImpl.getDBInstances:2356]  name=PWFILE, value=/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/initDBN.ora
[main] [ 2014-11-04 08:11:37.465 GMT ] [DatabaseImpl.getDBInstances:2356]  name=RANK, value=0
[main] [ 2014-11-04 08:11:37.466 GMT ] [DatabaseImpl.getDBInstances:2356]  name=RELOCATE_ACTION, value=0
[main] [ 2014-11-04 08:11:37.466 GMT ] [DatabaseImpl.getDBInstances:2356]  name=RELOCATE_BY_DEPENDENCY, value=1
[main] [ 2014-11-04 08:11:37.467 GMT ] [DatabaseImpl.getDBInstances:2356]  name=RESTART_ATTEMPTS, value=1
[main] [ 2014-11-04 08:11:37.468 GMT ] [DatabaseImpl.getDBInstances:2356]  name=ROLE, value=PRIMARY
[main] [ 2014-11-04 08:11:37.469 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SCRIPT_TIMEOUT, value=60
[main] [ 2014-11-04 08:11:37.469 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SERVER_CATEGORY, value=
[main] [ 2014-11-04 08:11:37.470 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SERVER_POOLS, value=
[main] [ 2014-11-04 08:11:37.471 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SERVER_POOLS_PQ, value=
[main] [ 2014-11-04 08:11:37.472 GMT ] [DatabaseImpl.getDBInstances:2356]  name=SPFILE, value=
[main] [ 2014-11-04 08:11:37.473 GMT ] [DatabaseImpl.getDBInstances:2356]  name=START_CONCURRENCY, value=0
[main] [ 2014-11-04 08:11:37.474 GMT ] [DatabaseImpl.getDBInstances:2356]  name=START_DEPENDENCIES, value=hard(ora.DATA.dg,ora.RECO.dg) weak(type:ora.listener.type,uniform:ora.ons)
[main] [ 2014-11-04 08:11:37.475 GMT ] [DatabaseImpl.getDBInstances:2356]  name=START_TIMEOUT, value=600
[main] [ 2014-11-04 08:11:37.476 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STATE_CHANGE_TEMPLATE, value=
[main] [ 2014-11-04 08:11:37.477 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STOP_CONCURRENCY, value=0
[main] [ 2014-11-04 08:11:37.478 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STOP_DEPENDENCIES, value=hard(intermediate:ora.asm,shutdown:ora.DATA.dg,shutdown:ora.RECO.dg)
[main] [ 2014-11-04 08:11:37.478 GMT ] [DatabaseImpl.getDBInstances:2356]  name=STOP_TIMEOUT, value=600
[main] [ 2014-11-04 08:11:37.480 GMT ] [DatabaseImpl.getDBInstances:2356]  name=TYPE, value=ora.database.type
[main] [ 2014-11-04 08:11:37.480 GMT ] [DatabaseImpl.getDBInstances:2356]  name=TYPE_VERSION, value=3.3
[main] [ 2014-11-04 08:11:37.481 GMT ] [DatabaseImpl.getDBInstances:2356]  name=UPTIME_THRESHOLD, value=1h
[main] [ 2014-11-04 08:11:37.481 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USER_WORKLOAD, value=yes
[main] [ 2014-11-04 08:11:37.483 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USE_STICKINESS, value=0
[main] [ 2014-11-04 08:11:37.483 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_DB_NAME, value=
[main] [ 2014-11-04 08:11:37.484 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_DOMAIN, value=
[main] [ 2014-11-04 08:11:37.485 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_ENV, value=
[main] [ 2014-11-04 08:11:37.486 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_FLAGS, value=
[main] [ 2014-11-04 08:11:37.487 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_INST_NAME, value=DBN
[main] [ 2014-11-04 08:11:37.487 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_OPEN_MODE, value=open
[main] [ 2014-11-04 08:11:37.488 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_OPI, value=false
[main] [ 2014-11-04 08:11:37.488 GMT ] [DatabaseImpl.getDBInstances:2356]  name=USR_ORA_STOP_MODE, value=immediate
[main] [ 2014-11-04 08:11:37.489 GMT ] [DatabaseImpl.getDBInstances:2356]  name=VERSION, value=12.1.0.2.0
[main] [ 2014-11-04 08:11:37.490 GMT ] [CRSCache.getAttributesFromCache:229]  CRS cache: ora.db.db []
[main] [ 2014-11-04 08:11:37.494 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.495 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [HOSTING_MEMBERS]
[main] [ 2014-11-04 08:11:37.498 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.499 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.500 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [SERVER_POOLS]
[main] [ 2014-11-04 08:11:37.524 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.527 GMT ] [DatabaseImpl.crsResource:5254]  calling parent's crsResource
[main] [ 2014-11-04 08:11:37.539 GMT ] [EntityOperations.isEntityRegisteredCRSD:353]  entity: ora.db.db, type: 1, registered: true
[main] [ 2014-11-04 08:11:37.562 GMT ] [CRSNative.searchEntities:658]  found 1 entities
[main] [ 2014-11-04 08:11:37.562 GMT ] [DatabaseImpl.getDBInstances:2421]  size of resultData = 1
[main] [ 2014-11-04 08:11:37.564 GMT ] [DatabaseImpl.getDBInstances:2454]  riID=ora.db.db 1 1 result={LAST_SERVER=oraclelinux}
[main] [ 2014-11-04 08:11:37.565 GMT ] [CRSCache.getAttributesFromCache:229]  CRS cache: ora.db.db []
[main] [ 2014-11-04 08:11:37.566 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.572 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [HOSTING_MEMBERS]
[main] [ 2014-11-04 08:11:37.582 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.583 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.584 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [SERVER_POOLS]
[main] [ 2014-11-04 08:11:37.604 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.606 GMT ] [Util.:103]  Util Instance created.
[main] [ 2014-11-04 08:11:37.608 GMT ] [DatabaseImpl.getDBInstances:2543]  instName=DBN nodeName=oraclelinux
[main] [ 2014-11-04 08:11:37.611 GMT ] [CRSCache.getAttributesFromCRS:155]  CRS: name: ora.db.db, type 1, node: null
[main] [ 2014-11-04 08:11:37.614 GMT ] [CRSCache.getAttributesFromCRS:156]  attrs: [SERVER_POOLS_PQ]
[main] [ 2014-11-04 08:11:37.625 GMT ] [CRSCache.getAttributesFromCRS:163]  CRS: []
[main] [ 2014-11-04 08:11:37.626 GMT ] [Util.:103]  Util Instance created.
[main] [ 2014-11-04 08:11:37.627 GMT ] [CmdOptVals.isOptionSet:917]  Check isOptionSet for VERBOSE
[main] [ 2014-11-04 08:11:37.629 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for verbose
[main] [ 2014-11-04 08:11:37.629 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:37.631 GMT ] [CmdOptVals.isOptionSet:917]  Check isOptionSet for INNER
[main] [ 2014-11-04 08:11:37.632 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for inner
[main] [ 2014-11-04 08:11:37.634 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:37.637 GMT ] [CRSCache.getAttributesFromCache:229]  CRS cache: ora.db.db []
[main] [ 2014-11-04 08:11:37.638 GMT ] [CmdOptVals.isOptionSet:917]  Check isOptionSet for FORCE
[main] [ 2014-11-04 08:11:37.639 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for force
[main] [ 2014-11-04 08:11:37.639 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:37.641 GMT ] [CRSNative.getResourceInstancesID:1070]  Looking for RIs using filter: ((NAME == ora.db.db) AND ((STATE == ONLINE) OR (STATE == INTERMEDIATE)))
[main] [ 2014-11-04 08:11:37.645 GMT ] [CRSNative.getResourceInstancesID:1078]  found 1 RIs
[main] [ 2014-11-04 08:11:37.646 GMT ] [CRSNative.getResourceInstancesID:1080]  	ora.db.db 1 1
[main] [ 2014-11-04 08:11:37.647 GMT ] [CmdOptVals.isOptionSet:917]  Check isOptionSet for VERBOSE
[main] [ 2014-11-04 08:11:37.648 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for verbose
[main] [ 2014-11-04 08:11:37.648 GMT ] [OptVal.isSet:150]  m_value is null
Database is running.
[main] [ 2014-11-04 08:11:37.682 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for thisversion
[main] [ 2014-11-04 08:11:37.683 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:37.683 GMT ] [CmdOptVals.isOptionSet:861]  Calling isOptionSet for thishome
[main] [ 2014-11-04 08:11:37.684 GMT ] [OptVal.isSet:150]  m_value is null
[main] [ 2014-11-04 08:11:37.684 GMT ] [InterruptHandler.unRegisterInterruptHandler:76]  UNRegistering shutdown hook.....
[main] [ 2014-11-04 08:11:37.685 GMT ] [InterruptHandler.unRegisterInterruptHandler:81]  UnRegistered shutdown hook.....
[main] [ 2014-11-04 08:11:37.686 GMT ] [OPSCTLDriver.main:233]  Unregistered OPSCTL driver's interrupt handler
[main] [ 2014-11-04 08:11:37.687 GMT ] [SRVMContext.term:151]  Performing SRVM Context Term. Term counter is 2
[oracle@oraclelinux ~]$

Jonathan Lewis explains Delphix

OOW 2014 was the best so far for me and a whirl wind.  After not having a presentation accepted since I left Oracle 10 years ago, I got not only a presentation accepted but 3 presentations accepted. Woohoo! Two of my presentations are available on youtube at

On top of that with the awesome support of the Oaktable, Delphix, Pythian and Enkitec , I was able to secure a great venue for the 3rd annual Oaktable World at OOW where we had the leading Oracle performance and internals experts speak for 2 solid days. You can see videos of the Oaktable World presentations at

Then with the help of Tim Gorman and Steve Karam also of the Oaktable, along with colleague and mastermind Adam Bowen, we ran a hands on lab where we installed Delphix on peoples laptops at the OTN lounge and called it #CloneAttack. We collaborated the next day with DBvisit and Solarwinds as well to hold hold a full day of hands on labs #RepAttack and #MonitorAttack.

The evenings were packed between events like the fun Oracle Ace dinner and the awesome Pythian party at the W and the bloggers get together at Jillians with customer meetings and dinners scattered in between.

The Delphix booth was exciting as it was huge #222222;">20×40 between Cisco and Cognizant. Its been fun watching Delphix go from a 10×10 slot on the outskirts of the show floor, to 10×20, to 20×20 to 20×40 right in the middle of the industry movers and shakers.

Finally had the honor of having Jonathan Lewis explain how Delphix works better than I can and Jonathan has only worked with Delphix for a few days. Incredible. Here is Jonathan’s presentation at the Delphix booth at Oracle Open World

Screen Shot 2014-11-03 at 3.56.46 PM

Filtering PeopleTools SQL from Performance Monitor Traces

I have been doing some on-line performance tuning on a PeopleSoft Financials system using PeopleSoft Performance Monitor (PPM).  End-users have collect verbose PPM traces. Usually, when I use PPM in a production system, all the components are fully cached by the normal activity of the user (except when the application server caches have recently been cleared).  However, when working in a user test environment it is common to find that the components are not fully cached. This presents two problems.

  • The application servers spend quite a lot of time executing queries on the PeopleTools tables to load the components, pages and PeopleCode into their caches. We can see in the screenshot of the component trace that there is a warning message that component objects are not fully cached, and that these  cache misses skew timings.
  • In verbose mode, the PPM traces collect a lot of additional transactions capturing executions and fetches against PeopleTools tables. The PPM analytic components cannot always manage the resultant volume of transactions.
    Figure 1. Component trace as collected by PPM
    Figure 1. Component trace as collected by PPM

    If I go further down the same page and look in the SQL Summary, I can see SQL operations against PeopleTools tables (they are easily identifiable in that they generally do not have an underscore in the third character). Not only are 5 of the top 8 SQL operations related to PeopleTools tables, we can also see that they also account for over 13000 executions, which means there are at least 13000 rows of additional data to be read from PSPMTRANSHIST.

    Figure 2. SQL Summary of PPM trace with PeopleTools SQL
    Figure 2. SQL Summary of PPM trace with PeopleTools SQL

    When I open the longest running server round trip (this is also referred to as a Performance Monitoring Unit or PMU), I can only load 1001 rows before I get a message warning that the maximum row limit has been reached. The duration summary and the number of executions and fetches cannot be calculated and hence 0 is displayed.

    Figure 3: Details of longest PMU with PeopleTools SQL
    Figure 3: Details of longest PMU with PeopleTools SQL

    Another consequence of the PeopleTools data is that it can take a long time to open the PMU tree. There is no screenshot of the PMU tree here because in this case I had so much data that I couldn't open it before the transaction timed out!

    Solution 

    My solution to this problem is to delete the transactions that relate to PeopleTools SQL and correct the durations, and the number of executions and fetches held in summary transactions. The rationale is that these transactions would not normally occur in significant quantities in a real production system, and there is not much I can do about them when they do.
    The first step is to clone the trace. I could work on the trace directly, but I want to preserve the original data.
    PPM transactions are held in the table PSPMTRANSHIST. They have a unique identifier PM_INSTANCE_ID. A single server round trip, also called a Performance Monitoring Unit (PMU), will consist of many transactions. They can be shown as a tree and each transaction has another field PM_PARENT_INST_ID which holds the instance of the parent. This links the data together and we can use hierarchical queries in Oracle SQL to walk the tree. Another field PM_TOP_INST_ID identifies the root transaction in the tree.
    Cloning a PPM trace is simply a matter of inserting data into PSPMTRANSHIST. However, when I clone a PPM trace I have to make sure that the instance numbers are distinct but still link correctly. In my system I can take a very simple approach. All the instance numbers actually collected by PPM are greater than 1016. So, I will simply use the modulus function to consistently alter the instances to be different. This approach may break down in future, but it will do for now.
    On an Oracle database, PL/SQL is a simple and effective way to write simple procedural processes.  I have written two anonymous blocks of code.
    Note that the cloned trace will be purged from PPM like any other data by the delivered PPM archive process.

    #eeeeee; border: 0px solid rgb(0, 0, 0); overflow: auto; padding-left: 4px; padding-right: 4px; width: 100%;">
    REM xPT.sql
    BEGIN --duplicate PPM traces
    FOR i IN (
    SELECT h.*
    FROM pspmtranshist h
    WHERE pm_perf_trace != ' ' /*rows must have a trace name*/
    -- AND pm_perf_trace = '9b. XXXXXXXXXX' /*I could specify a specific trace by name*/
    AND pm_instance_id > 1E16 /*only look at instance > 1e16 so I do not clone cloned traces*/
    ) LOOP
    INSERT INTO pspmtranshist
    (PM_INSTANCE_ID, PM_TRANS_DEFN_SET, PM_TRANS_DEFN_ID, PM_AGENTID, PM_TRANS_STATUS,
    OPRID, PM_PERF_TRACE, PM_CONTEXT_VALUE1, PM_CONTEXT_VALUE2, PM_CONTEXT_VALUE3,
    PM_CONTEXTID_1, PM_CONTEXTID_2, PM_CONTEXTID_3, PM_PROCESS_ID, PM_AGENT_STRT_DTTM,
    PM_MON_STRT_DTTM, PM_TRANS_DURATION, PM_PARENT_INST_ID, PM_TOP_INST_ID, PM_METRIC_VALUE1,
    PM_METRIC_VALUE2, PM_METRIC_VALUE3, PM_METRIC_VALUE4, PM_METRIC_VALUE5, PM_METRIC_VALUE6,
    PM_METRIC_VALUE7, PM_ADDTNL_DESCR)
    VALUES
    (MOD(i.PM_INSTANCE_ID,1E16) /*apply modulus to instance number*/
    ,i.PM_TRANS_DEFN_SET, i.PM_TRANS_DEFN_ID, i.PM_AGENTID, i.PM_TRANS_STATUS,
    i.OPRID,
    SUBSTR('xPT'||i.PM_PERF_TRACE,1,30) /*adjust trace name*/,
    i.PM_CONTEXT_VALUE1, i.PM_CONTEXT_VALUE2, i.PM_CONTEXT_VALUE3,
    i.PM_CONTEXTID_1, i.PM_CONTEXTID_2, i.PM_CONTEXTID_3, i.PM_PROCESS_ID, i.PM_AGENT_STRT_DTTM,
    i.PM_MON_STRT_DTTM, i.PM_TRANS_DURATION,
    MOD(i.PM_PARENT_INST_ID,1E16), MOD(i.PM_TOP_INST_ID,1E16), /*apply modulus to parent and top instance number*/
    i.PM_METRIC_VALUE1, i.PM_METRIC_VALUE2, i.PM_METRIC_VALUE3, i.PM_METRIC_VALUE4, i.PM_METRIC_VALUE5,
    i.PM_METRIC_VALUE6, i.PM_METRIC_VALUE7, i.PM_ADDTNL_DESCR);
    END LOOP;
    COMMIT;
    END;
    /

    Now I will work on the cloned trace. I want to remove certain transaction.

    • PeopleTools SQL. Metric value 7 reports the SQL operation and SQL table name. So if the first word is SELECT and the second word is a PeopleTools table name then it is a PeopleTools SQL operation. A list of PeopleTools tables can be obtained from the object security table PSOBJGROUP.
    • Implicit Commit transactions. This is easy - it is just transaction type 425. 

    Having deleted the PeopleTools transactions, I must also

    • Correct transaction duration for any parents of transaction. I work up the hierarchy of transactions and deduct the duration of the transaction that I am deleting from all of the parent.
    • Transaction types 400, 427 and 428 all record PeopleTools SQL time (metric 66). When I come to that transaction I also deduct the duration of the deleted transaction from the PeopleTools SQL time metric in an parent transaction.
    • Delete any children of the transactions that I delete. 
    • I must also count each PeopleTools SQL Execution transaction (type 408) and each PeopleTools SQL Fetch transaction (type 414) that I delete. These counts are also deducted from the summaries on the parent transaction 400. 

    The summaries in transaction 400 are used on the 'Round Trip Details' components, and if they are not adjusted you can get misleading results. Without the adjustments, I have encountered PMUs where more than 100% of the total duration is spent in SQL - which is obviously impossible.
    Although this technique of first cloning the whole trace and then deleting the PeopleTools operations can be quite slow, it is not something that you are going to do very often. 

    #eeeeee; border: 0px solid rgb(0, 0, 0); overflow: auto; padding-left: 4px; padding-right: 4px; width: 100%;">
    REM xPT.sql
    REM (c)Go-Faster Consultancy Ltd. 2014
    set serveroutput on echo on
    DECLARE
    l_pm_instance_id_m4 INTEGER;
    l_fetch_count INTEGER;
    l_exec_count INTEGER;
    BEGIN /*now remove PeopleTools SQL transaction and any children and adjust trans durations*/
    FOR i IN (
    WITH x AS ( /*returns PeopleTools tables as defined in Object security*/
    SELECT o.entname recname
    FROM psobjgroup o
    WHERE o.objgroupid = 'PEOPLETOOLS'
    AND o.enttype = 'R'
    )
    SELECT h.pm_instance_id, h.pm_parent_inst_id, h.pm_trans_duration, h.pm_trans_defn_id
    FROM pspmtranshist h
    LEFT OUTER JOIN x
    ON h.pm_metric_value7 LIKE 'SELECT '||x.recname||'%'
    AND x.recname = upper(regexp_substr(pm_metric_value7,'[^ ,]+',8,1)) /*first word after select*/
    WHERE pm_perf_trace like 'xPT%' /*restrict to cloned traces*/
    -- AND pm_perf_trace = 'xPT9b. XXXXXXXXXX' /*work on a specific trace*/
    AND pm_instance_id < 1E16 /*restrict to cloned traces*/
    AND ( x.recname IS NOT NULL
    OR h.pm_trans_defn_id IN(425 /*Implicit Commit*/))
    ORDER BY pm_instance_id DESC
    ) LOOP
    l_pm_instance_id_m4 := TO_NUMBER(NULL);
     
        IF i.pm_parent_inst_id>0 AND i.pm_trans_duration>0 THEN
    FOR j IN(
    SELECT h.pm_instance_id, h.pm_parent_inst_id, h.pm_top_inst_id, h.pm_trans_defn_id
    , d.pm_metricid_3, d.pm_metricid_4
    FROM pspmtranshist h
    INNER JOIN pspmtransdefn d
    ON d.pm_trans_defn_set = h.pm_trans_defn_set
    AND d.pm_trans_defn_id = h.pm_trans_Defn_id
    START WITH h.pm_instance_id = i.pm_parent_inst_id
    CONNECT BY prior h.pm_parent_inst_id = h.pm_instance_id
    ) LOOP
    /*decrement parent transaction times*/
    IF j.pm_metricid_4 = 66 /*PeopleTools SQL Time (ms)*/ THEN --decrement metric 4 on transaction 400
    --dbms_output.put_line('ID:'||i.pm_instance_id||' Type:'||i.pm_trans_defn_id||' decrement metric_value4 by '||i.pm_trans_duration);
    UPDATE pspmtranshist
    SET pm_metric_value4 = pm_metric_value4 - i.pm_trans_duration
    WHERE pm_instance_id = j.pm_instance_id
    AND pm_trans_Defn_id = j.pm_trans_defn_id
    AND pm_metric_value4 >= i.pm_trans_duration
    RETURNING pm_instance_id INTO l_pm_instance_id_m4;
    ELSIF j.pm_metricid_3 = 66 /*PeopleTools SQL Time (ms)*/ THEN --SQL time on serialisation
    --dbms_output.put_line('ID:'||i.pm_instance_id||' Type:'||i.pm_trans_defn_id||' decrement metric_value3 by '||i.pm_trans_duration);
    UPDATE pspmtranshist
    SET pm_metric_value3 = pm_metric_value3 - i.pm_trans_duration
    WHERE pm_instance_id = j.pm_instance_id
    AND pm_trans_Defn_id = j.pm_trans_defn_id
    AND pm_metric_value3 >= i.pm_trans_duration;
    END IF;

    UPDATE pspmtranshist
    SET pm_trans_duration = pm_trans_duration - i.pm_trans_duration
    WHERE pm_instance_id = j.pm_instance_id
    AND pm_trans_duration >= i.pm_trans_duration;
    END LOOP;
    END IF;

    l_fetch_count := 0;
    l_exec_count := 0;
    FOR j IN( /*identify transaction to be deleted and any children*/
    SELECT pm_instance_id, pm_parent_inst_id, pm_top_inst_id, pm_trans_defn_id, pm_metric_value3
    FROM pspmtranshist
    START WITH pm_instance_id = i.pm_instance_id
    CONNECT BY PRIOR pm_instance_id = pm_parent_inst_id
    ) LOOP
    IF j.pm_trans_defn_id = 408 THEN /*if PeopleTools SQL*/
    l_exec_count := l_exec_count + 1;
    ELSIF j.pm_trans_defn_id = 414 THEN /*if PeopleTools SQL Fetch*/
    l_fetch_count := l_fetch_count + j.pm_metric_value3;
    END IF;
    DELETE FROM pspmtranshist h /*delete tools transaction*/
    WHERE h.pm_instance_id = j.pm_instance_id;
    END LOOP;

    IF l_pm_instance_id_m4 > 0 THEN
    --dbms_output.put_line('ID:'||l_pm_instance_id_m4||' Decrement '||l_exec_Count||' executions, '||l_fetch_count||' fetches');
    UPDATE pspmtranshist
    SET pm_metric_value5 = pm_metric_value5 - l_exec_count
    , pm_metric_value6 = pm_metric_value6 - l_fetch_count
    WHERE pm_instance_id = l_pm_instance_id_m4;
    l_fetch_count := 0;
    l_exec_count := 0;
    END IF;

    END LOOP;
    END;
    /

    Now, I have a second PPM trace that I can open in the analytic component.

    Figure 4: Original and Cloned PPM traces
    Figure 4: Original and Cloned PPM traces

    When I open the cloned trace, both timings in the duration summary have reduced as have the number of executions and fetches.  The durations of the individual server round trips have also reduced.

    Figure 5: Component Trace without PeopleTools transactions
    Figure 5: Component Trace without PeopleTools transactions

    All of the PeopleTools SQL operations have disappeared from the SQL summary.

    Figure 6: SQL Summary of PPM trace after removing PeopleTools SQL transactions
    Figure 6: SQL Summary of PPM trace after removing PeopleTools SQL transactions

    The SQL summary now only has 125 rows of data.

    Figure 7: SQL Summary of PMU without PeopleTools SQL

    Now, the PPM tree component opens quickly and without error.

    Figure 8: PMU Tree after removing PeopleTools SQL
    Figure 8: PMU Tree after removing PeopleTools SQL

    There may still be more transactions in a PMU than I can show in a screenshot, but I can now find the statement that took the most time quite quickly.

    Figure 9: Long SQL transaction further down same PMU tree
    Figure 9: Long SQL transaction further down same PMU tree

    Conclusions 

    I think that it is reasonable and useful to remove PeopleTools SQL operations from a PPM trace.
    In normal production operation, components will mostly be cached, and this approach renders traces collected in non-production environments both usable in the PPM analytic components and more realistic for performance tuning. However, it is essential that when deleting some transactions from a PMU, that summary data held in other transactions in the same PMU are also corrected so that the metrics remain consistent.