RAC nodes with unknown code differences

As I said several months ago, while going to Exadata we went to a RAC platform and since that time I have yet to encounter any pitfalls with going to this technology stack....until now!  After applying some Exadata related patches we bounced our system as we've done several times since RAC, and just like we did in our QA mock deployment drills, but when the user community got a chance a few days later to put the system through its paces we received various errors reported in both canned and custom functionality.  Drilling into the issue further, we realized it had something to do with our tax solution with "com.evermind.server.http.HttpIOException: Broken pipe" in our application server logs and this in the error logging table:

ORA-29270: too many open HTTP requests
ORA-29273: HTTP request failed
ORA-06512: at "SYS.UTL_HTTP", line 1130
ORA-29270: too many open HTTP requests

It is important to note that one of the patches applied upgraded us from 11.2.0.2.0 to 11.2.0.3.0 and subsequent red herrings from My Oracle Support of 1301699.1 and 1293056.1 had us all assuming the issue resided in new Access Control Lists functionality that might have been introduced with the patching.  Eventually we were able to find that the code being run to get a URL response passed back would run successfully on one of the RAC nodes but not the other and that had nothing to do with ACLs at all.  With this we continued to research and found that the package being called was actually corrupt on one node, but not the other, and had no outwards sign of being INVALID or otherwise corrupted since when it was compiled as a new object on the "bad" node it would run successfully.

This could be the end to our story, if not for the fact that after we recompiled the object we were still receiving the "too many open HTTP requests" error.  At this point, we dug deeper into the system and one item we encountered in our research on My Oracle Support stuck out to us from 961468.1:

What is the reason of ORA-29270?

The database server has a hardcoded limit of 5 open HTTP connections per session. When you attempt to open a 6th http connection, this error is thrown.

Now we hadn't changed the application, or the other database which we're communicating with in this scenario, over the weekend but in some way the database received (or otherwise caused) corrupted communications and held onto these 5 HTTP connections in such a way as to not release them for further communications.  Running lsof and netstat found that on the node in question there were several hundred connections stuck from the other database, and once a kill was issued for them the natural order was restored to the universe when they died off and allowed connections to work again without issue.

This was quite an interesting problem as it was nebulous in finding where the root cause resided, and added a few tools into my toolbox for the next time we have something like this!

Purging concurrent and Fixed Assets

If you have a realitively large application, you probably purge your concurrent request tables fairly frequently due to space limitations which most of the time is a benefit but I've recently found a reason that this can hurt you as well.  With the Fixed Assets module, the table fa_book_controls keeps track of the depreciation runs that the system or the users run and if many deprecation runs are being with some frequency there doesn't appear to be any issues.  The problem lies with infrequent deprecation runs when the last run happens and ends in error leaving the request_id populated in the table, and is subsequently then purged out of the tables by your regular concurrent purge processes.  By having this mass_request_id in the table, when either the Calculate Gains and Losses or Depreciation Run concurrent reports are run they will error out barking about how they can't find the previous request:

APP-OFA-48392: Unable to get the concurrent request status using procedure FND_CONCURRENT.GET_REQUEST_STATUS.

This doesn't sound too dire, but if your business is in the midde of trying to close their books and this crops up you need to be able to resolve the issue quickly.  Having encountered this situation several times, I've created the alert below to notify us if these conditions exist:

select mass_request_id, book_type_code
into &REQ_ID, &BOOK
from fa_book_controls
where mass_request_id is not null
and last_update_date < sysdate - (2/24)

The reason I am looking for a last_update_date greater than the past 2 hours is because this means the request has errored within the past few hours and while it is potentially a problem a few days from now this alert is giving us some lead time in fixing the issue.

RMAN hanging up

Recently I've had to verify or look into our RMAN process potentially hanging up, so I thought I'd share how I've been finding it in our system.

If you look in the table v$rman_backup_job_details, you can see details such as the status, start time, duration, device type, backup type, and even how large the backup job was; but it also shows the current running session(s) as well (the word backup made me initially think it was a history table).  If this doesn't show the information for some reason, you can also look in gv$session by the program column looking for %rman% to find the active sessions.  (Sometimes the module column will have rman as well, but it will change into something that doesn't have rman at certain points so I find the program column much more reliable for my system since it is rman@system and I assume that's the natural setup for all implementations!)

As you can see the common thread running through a lot of posts recently, we have access to the data behind some of our processes and now we need to come up with ways to monitoring this for when RMAN is thrashing against the DB and taking up critical resources that should be available instead.

A blog's first steps

I checked in tonight before writing a new post, hoping that 2 new visitors had hit the site in the last day or two since that would mean I had 50 hits in the past month which is just insane and awesome and incredible all rolled up into one, yet was astounded to see I had 20 hits from Russia yesterday to push me way over the edge and make this month the largest this blog has seen (so far).  I'll keep going, if you keep visiting!

-The Oracle EMT

v$sesstat - A new tool for the toolbox

While I think I have a handle on some of the techniques Tanel puts into the first of his three steps, I need to gain more understanding about what v$sesstat is and how I can use it the next time I get into a situation where I am out of ideas as to what's going wrong with our systems (and why I found it in the first place, but the problem went away before I could use this too extensively).  This pretty much sums it up:

Only looking into #1 is enough in 90% of problem cases. But for advanced troubleshooting of complex and exotic problems I regularly have to dive into the #2 – V$SESSTAT performance counters (That’s the reason why I wrote Snapper for example).

If you aren't following Tanel, you need to be.

Recycle bin?

You could've knocked me over with a feather when I found out that an Oracle DB has a recycle bin!  So I'm curious about it obviously, and query the table and lo and behold there are items in there which a. aren't being dropped and b. being created every day as a result of our team's automation.  The good news is that there isn't a whole lot of space being taken up by what's in here, but here again is something we aren't monitoring on so now I'm going to be designing a new alert to let us know what's being dumped in here.

http://connormcdonald.wordpress.com/2012/11/23/why-cant-i-resize-my-datafile/

duration not active: A Tale of Two Articles

From time to time I snoop around our DB log files to see if anything is going on with the system, and the other day I found this:

Errors in file <filename>:
ORA-21779: duration not active

Now, I've never seen this before so I go to the Oracle authority MetaLink (or My Oracle Support as it's known now) to find two completely different articles which illustrate probably how many people they have working at Oracle more than anything else.

A helpful article:

What Does Error "ORA-21779 Duration Not Active" Mean? [ID 1084474.1]

Goal
What Does Error "ORA-21779 Duration Not Active" Mean?

Solution
The error "ORA-21779 Duration Not Active" is caused by some process trying to clean up an object from memory.

Duration is the amount of time a object is in memory.  If an object in memory is accessed and its duration is inactive state or not found then the ORA-21779 message is returned.

Each memory chunk is associated with a duration. This allows clients to automatically free all memory associated with a duration (at the end of the duration).  The duration determines the heap that is used to allocate the memory.

The allocation duration is set when an object is created with OCIObjectNew(), and the pin duration is set when an object is pinned with OCIObjectPin().  The datatype of the duration value is OCIDuration.

When an object reaches the end of its allocation duration, it is automatically deleted and its memory can be reused.  The pin duration indicates when an object's memory can be reused, and memory is reused when the cache is full.

There are various predefined types of durations supported on memory and context management calls.

OCI_DURATION_CALL. The duration of this operation is that of a callout.

OCI_DURATION_STATEMENT. The duration of this operation is the external row source.

OCI_DURATION_SESSION. The duration of this operation is the user session.

OCI_DURATION_PROCESS. The duration of this is agent process.

See following docs with regards to durations
Oracle Call Interface Programmer's Guide, 10g Release 2 (10.2), Part Number B14250-02
Oracle Database Data Cartridge Developer's Guide,10g Release 2 (10.2), Part Number B14289-02

A not so helpful article:

OERR: ORA-21779 duration not active [ID 49397.1]
Error: ORA-21779
Text: duration not active
---------------------------------------------------------------------------
Cause: User is trying to use a duration that has been terminated.
Action: User should avoid performing such operation.

Seriously, that's all the second article has for content!  And.......ANNNND.....it was last updated 6 months ago.  So it was.....added to?

Annnnyways, the first article does give me some idea of what was going on but not why or what was happening so I'll need to keep my eyes peeled to try and see this in action next time!

Site changes!

Over the holiday break I've had some time to browse a bunch of blogs hosted by Oracle, and I've added about 20 of them at this time to follow on the sidebar!  I'm sure that I'll eventually weed some of them out over the next few months, but I think I'll also do a random deep dive on an article archive so that's at least 20 blog posts you can look forward to.  :}

-The Oracle EMT

Yet another thanks, and Happy Holidays!

Having taken a short (unintended) break from blogging in November, it was astonishing to see that while it took this blog 5 months to get 100 views it only took another 2 months to get an additional 50 views with only posting twice in that time!!  I can't tell you how much this motivates me to keep this blog going, but also to rededicate myself to the "art of Oracle" so that I can learn things that can be of use to the community as a whole.  So to everybody that follows what I'm doing here, or stumbles upon this site searching for something Oracle related, thank you!!!

Also, I want to wish everybody out there a Happy Holiday no matter which you choose (or not) to celebrate and here's to looking forward to ringing in a Happy New Year with all the challenges and learning we hope to encounter!!

-The Oracle EMT

Timestamp across DB versions

So the other day I decided to write up an alert to let us know when a DB crashes, and nobody hears it, but I was struggling with joining our instances for some unknown reason due to this error message:

ORA-30175: invalid type given for an argument

I shelved it for a day or two until I had a chunk of time to dig into this a bit deeper, and with the help of an Oracle forums post I realized what my problem was.  You see, the source of my confusion resided in the fact that the below script was able to be run individually for each instance and I only had problems when starting to union them together:

select 'INST1' AS "SERVER", process_id, host_id, substr(reason, 0, 40) AS STATUS, creation_time from DBA_ALERT_HISTORY@inst1
where creation_time > sysdate -1
and object_type = 'INSTANCE'
union all
select 'INST2' AS "SERVER", process_id, host_id, substr(reason, 0, 40) AS STATUS, creation_time from DBA_ALERT_HISTORY@inst2
where creation_time > sysdate -1
and object_type = 'INSTANCE'

Looks benign right?  Well I realized that I was joining 11g and 10g DB tables together and that the timestamp object has apparently changed a bit, so that even with the table definitions not changing our system just wouldn't let me join the tables together no matter what I did when I do a value comparison on creation_time!  Finding that post was the key to getting this changed, because when I updated the script to be:

select 'INST1' AS "SERVER", process_id, host_id, substr(reason, 0, 40) AS STATUS, creation_time from DBA_ALERT_HISTORY@inst1
where creation_time > to_timestamp(trunc(systimestamp))
and object_type = 'INSTANCE'
union all
select 'INST2' AS "SERVER", process_id, host_id, substrDBA_ALERT_HISTORY@inst2
where creation_time > to_timestamp(trunc(systimestamp))
and object_type = 'INSTANCE'

everything was right with the world, and no more error messages were returned.  Oddly enough, or not as I've already explained, the same script with creation_time > to_timestamp(trunc(systimestamp)) -1 starts to bomb out again because the timestamp object is again having a comparison done to it.

Troubleshooting latch contention by Tanel

In trying to find out what was holding latches in our new shiny 11.2.0.2 system, I started digging around on the web and lo and behold I ran across a really good article by Tanel Poder a few years ago not only explaining latches, and their contention, but giving us tools to be able to try and catch them in the act!

P.S.  I know I've taken a short break from the blog, but I've got some really good posts coming up over the next few weeks so stay tuned.

Thank you!

I started this blog with some small hope that it would find a place online to grow, and tonight it has hit 100 page views!  To me:

• that is really amazing especially since I've kept it to myself and told nobody in my personal or professional life at this point, let alone share it online at some of the other blogs I've been frequenting
• it means that what I have to say, or share, is relevant or of some value to the general Oracle space
• this gives me some motivation to keep going forward and building this site up more

So again, thanks to everybody out there that's visiting the site!!

-The Oracle EMT

Data (historical and backups)

I had found this post a little while ago on cleaning up historical data, but I wanted to save blogging about it until I had something real to say about it.  This is that time as it has become very apparent that another one of our Main Tenants should be something to do with data, maybe Data Consumption or Data Usage but SOMETHING because data is just piling up in our systems every day.  Audit data, user data, this data, and that data and how much is being purged, how much can be purged, who has a strategy for keeping track of all of this and where does that fit in with a corporate strategy?

Skip several years later, and the database had grown to be huge for that time. Retrievals were taking longer and longer, and talking to some of the sysadmins late at night around the coffee machine, I learned that the backup was getting too large to even back it up within a week. The application was starting to hit pretty much a ‘brick wall’; it started to fall further and further behind, and something really needed to be done.

Does this sound familiar?  How big is your system?  Has it hit 1 TB?  Are you approaching 5, 10, 50, 100, or more TB of space for your footprint?  How do you approach your backup system?  Do the people that manage your backups tell you when you're having a problem, or do you have to figure it out yourself?  Questions like this are going through my head as I re-read that link because lately in the morning I'm seeing something like this in our new event monitoring alert:

  Waits                                                           Wait Time        Server

 

  Backup: MML create a backup piece           79291.40622    X1

  Backup: sbtbackup                                        3937.101761   X2                  

  Backup: sbtbackup                                      17308.812339   X3

 

This sure seems like our systems are suddenly "wasting" a lot of cycles per hour on backups, especially when these events are from backups that run into our morning several hours and sometimes even into the afternoon.  So begins the investigation!

System Wait Events Part 2

For my first follow up post, I thought it would be appropriate to show why ample alerting can help you to save the day.  It just so happens that on the day that we were closing A/R for the year, we started seeing some very odd things in a new alert we have.

Waits                                                           Wait Time

  gc buffer busy acquire                                     17253.907174

  read by other session                                      16173.301272

  cell single block physical read                             4533.532144

  Disk file operations I/O                                    3961.591694

  gc buffer busy release                                       3783.63651

  RMAN backup & recovery I/O                                  2962.854376

  buffer busy waits                                           1803.283808

  gc current block busy                                       1652.088758

At this time, we see in our DB logs a multitude of these entries:

Tue Sep 04 13:15:04 2012

OSPID: 19311: connect: ossnet: connection failed to server x.x.x.x, result=5 (login: sosstcpreadtry failed) (difftime=1953)

Anecdotal evidence of something going wrong is that at this time I observed that closing a form took 20-30 seconds for an individual, and I had another business user indicate that in the last hour or so he's been getting a "circle mouse" indicating waiting on the form when he tries to move between records on a student account.  So knowing that "something is going on" I start drilling in some more to investigate sessions which are making up some of the time in the above alert buckets and this session breakdown of wait times over 2 seconds shows:

WAIT_EVENT	TOT_WAITS	WAIT_PCT	WAIT_SECONDS	WAIT_MINUTES	TIME_PCT
gc buffer busy acquire	1033	0.09	418.49	6.97	0.03
gc cr block 2-way	31312	2.71	3.21	0.05	0
gc cr block busy	6460	0.56	3.24	0.05	0
SQL*Net message from client	532955	46.14	1526240.71	25437.35	99.96
cell single block physical read	1972	0.17	2.8	0.05	0

I don’t know what the session was doing, or if it was successful, but that doesn’t look like a normal session wait time profile on our system.  Later we saw this as well (but it was related to our DBA trying to kill the RMAN jobs):

Tue Sep 04 14:18:52 2012

ARCH: Possible network disconnect with primary database

So, this is all nice and everything but what happened?

Answer:  Our storage engineer started researching the issue and found that our IB switches and other Exadata components had no issues, but when he checked our 7420 storage array out it was a completely different matter all together.  There were no issues with head 1 of the array, but when he went to check on head 2 he was unable to log in through GUI or ssh with also a simple df command hanging on an NFS mount coming from that head.  When he performed a takeover to move NFS control over to head 1, head 2 complained about lacking resources when attempting to fork something and the only way he could force a takeover was to power down head 2.  What I learned by researching for this article can be found here about what a 7420 head configuration could look like in Illustration 20 and Illustration 21 and the following paragraph as well.

Parallel Executions

I mentioned earlier that we implemented Exadata, and I learned something about parallel executions as a result!  Ignoring the fact that too much parallel execution on our system after the first few hours almost brought our system down, one of our developers had found that a simple query of a table with 54 rows in 8 blocks was taking too long to process versus our old environment.

Global Stats

=======================================

| Elapsed |  Other   | Fetch | Buffer |

| Time(s) | Waits(s) | Calls |  Gets  |

=======================================

|    0.00 |     0.00 |     1 |      3 |

=======================================

Global Stats

===============================================================

| Elapsed |   Cpu   | Concurrency |  Other   | Fetch | Buffer |

| Time(s) | Time(s) |  Waits(s)   | Waits(s) | Calls |  Gets  |

===============================================================

|    1.92 |    0.02 |        0.86 |     1.04 |     1 |      5 |

===============================================================

The 0 values in the first example were actually recorded to be 0.000079s and when we were seeing it then taking 2-3 seconds at time for each call, he started drilling down to see why there was such bad for our online performance.  He found that the default INSTANCES setting on the table was causing our Optimizer to compute a parallel execution plan which never caused us a problem because we didn't have an exponential number of potential slaves available for the parallel execution to take up the overhead of our RAC nodes.  The sins of our past, marking tables and indexes for parallel execution without needing to or really utilizing the feature, had caught up with us and Exadata didn't CAUSE the flaws it merely REVEALED them to us.  So we obviously fixed this, as well as limited our parallel executions on our DB nodes, but what else did we do?

We learned from our failure by creating an alert to track the current (and future) items that were running marked as parallel in our application just in case we had other objects running marked similarly (or implemented new objects in the future):

SELECT sql_id,
       substr(sql_text, 0, 200) AS sql_text,
       SUM(px_servers_executions) AS sum_px_exec,
       to_char(MAX(last_active_time), 'DD-MON-YYYY HH24:MI:SS') AS last_active_time
INTO
&SQLID,
&TEXT,
&EXEC,
&TIME
  FROM gv$sqlstats
WHERE px_servers_executions > 0
   AND upper(sql_text) NOT LIKE '%GV$%'
   AND upper(sql_text) NOT LIKE '%ORACLEOEM%'
   AND upper(sql_text) NOT LIKE '%GV%DB%'
   AND upper(sql_text) NOT LIKE '%SYS%DB%'
   AND last_active_time > SYSDATE - 1
GROUP BY
       sql_id,
       sql_text
order by
    sum_px_exec desc

Obviously you can see I "commented" out a lot of the returns from gv$sqlstats since many objects owned by the system are parallel which we really don't care too much about.  Here are a few more scripts you can use to identify the objects in your system which have parallelism activated:

select owner, table_name, degree

from  dba_tables

where TRIM(DEGREE) > TO_CHAR(1);

select owner, table_name, index_name, degree

from  dba_indexes

where TRIM(DEGREE) > TO_CHAR(1);

Edit 10/4/2012:  Re-read this today and realized that I mispoke about what our alert was all about, so I corrected it by changing a few words.