Linux VM: Server crash due to Fatal Machine kernel panic

As our systems become more and more complicated, and we look for more and more ways to consolidate and save money I am sure more technologists will need to learn about bugs associated with the Linux VM platform!  Tonight is one such lesson from MOS note "Server Crashed with Kernel panic - not syncing: Fatal Machine check" via ID 2093734.1 as the vmcore output shows very clearly that the kernel did panic which resulted in the server crashing, but just as important as knowing that information is WHY Oracle indicates this happened!

Exadata: X3 hardware may be damaged during upgrade with FCC enabled

If you have an Exadata X3 server, and have upgraded recently or are planning an upgrade, you NEED to read the My Oracle Support article "Following software upgrade on X3 hardware with Exadata Smart Flash Cache Compression enabled, multiple flash drives may fail, leading to reduced performance or data loss" from document ID 1968234.1 to find out what you have to do.  Were you aware that Oracle is recommending you don't upgrade if you have FCC enabled because of this issue?  Check out the story, and also find out what else is recommended if you HAVE to upgrade.

Firewalls, Damn Firewalls, and Projects

Okay, maybe it is not grammatically what the original phrase was about but I thought it was a good title.  :}

We recently had a project where we were replacing a set of servers, and one of the things that caught us out during the PROD cutover was the firewalls!  Firewalls between databases, firewalls between middle tier applications; some we had caught in QA, others we did not, but it all added up to extra time in our deployment that could have been avoided.

Take our mistake, and learn from it to make your next project that much more successful.  I know the next time we have something like this going in, I am going to grill everybody available about the firewalls!

Batches? We don't need no stinking batches!

The error message of "Unable to create batch" was being presented to our users when they were either trying to manually create receipt batches or when the automated processes would run from their requests.  Digging into the SQL of the package started taking me down a rabbit hole from one custom package to another, until I finally found that even though the error message being returned to the users was custom but it was being raised as a result to a call to ARP_RW_BATCHES_PKG.INSERT_MANUAL_BATCH which is a completely canned Oracle procedure.  Tracing through this started making me suspect the call over to arp_rw_batches_check_pkg.check_unique_batch_name but that didn't make any sense since we're talking about receipt classes as defined in ar_batch_sources which are set to AUTOMATIC for their numbering scheme in the auto_batch_numbering field.  So I wind up taking a look at this piece of code a bit closer because nothing else looked possible if I was in the right spot:

SELECT  COUNT(*)
INTO    l_count
FROM    AR_BATCHES bat
WHERE   bat.batch_source_id = p_batch_source_id
AND     bat.name = p_batch_name
AND     (     p_row_id IS NULL
          OR  bat.rowid <> p_row_id );
IF ( l_count <> 0 ) THEN
     FND_MESSAGE.set_name( 'AR', 'AR_DUP_BATCH_NAME' );
     APP_EXCEPTION.raise_exception;

when I decide to see what the data in ar_batches shows me.  Sure enough, the last_batch_num in ar_batch_sources for the batch_source_id in question was currently 5792097 and we have a sequence of batches with a name defined in ar_batches ranging from 5791705 to 5792958 which is preventing the package from successfully getting an available batch name to use in the creation of the batch as shown in these pieces of ARP_RW_BATCHES_PKG.INSERT_MANUAL_BATCH:

IF ( l_auto_batch_numbering = 'AUTOMATIC' ) THEN
UPDATE ar_batch_sources
SET last_batch_num = NVL( LAST_BATCH_NUM, 0 ) + 1
WHERE batch_source_id = l_batch_rec.batch_source_id;

SELECT NVL( LAST_BATCH_NUM, 0 )
INTO   l_batch_rec.name
FROM   ar_batch_sources
WHERE  batch_source_id = l_batch_rec.batch_source_id;

This meant that the application was continuing to increment the last_batch_num value every time the users were trying to do their work, even though the batch names were already taken and it would continue to do so until it encountered a data value which did not already exist for the name field in ar_batches.  The only option I could see is that we would need to manually push out the last_batch_num to match the last item in the sequence, so that a unique value would be returned the next time it would try to get a batch name (see above UPDATE statement).  I didn't want to change the batch names of the items which were created months ago because then we’re changing historical data, and I can’t be 100% sure that it’s not used for reporting or other audit type functions by the business.  After the appropriate approvals, we ran the below script:

UPDATE ar_batch_sources_all
SET last_batch_num = 5792958
WHERE batch_source_id = &batch_source_id
and last_batch_num = 5792097

Service was restored to the batch source after this update was applied, and all was well with the world!  Then we were asked how we could make sure this doesn't happen in the future.  After thinking through the answer a bit, I've come up with the below script which needs to go into a daily alert for us:

select a.batch_source_id, a.last_batch_num, a.org_id from ar_batch_sources_all a, ar_batches_all b
where (a.status not in ('I') or a.status is null)
and a.end_date_active is null
and a.batch_source_id = b.batch_source_id
and a.org_id = b.org_id
and b.name > a.last_batch_num

This was one of those problems where it's incredibly challenging, but also rewarding when you get to the end of the day having solved a pretty big problem and learning a lot in the process.  Years ago I would've ran a trace and handed it over to development to figure out, but I've gained some seasoning since then and decided that I'd do as much "dirty work" as possible before I had to escalate up so I ended up digging down through 7 layers of code to find the actual root cause!

Using RMAN, but not effectively

Since I've been on a RMAN/DBA kick lately, I figure this article is ripe for sharing!

"This article isn’t going to get into every aspect of backup testing but we will show one example of how an inadequate test of incremental backups can have disastrous results in a database recovery scenario."

Does that sound familiar or scary to anybody else out there?  I know I was scared after reading through the scenario!

Learning more about DBA_ALERT_HISTORY

In a previous post I indicated how I was going to create an alert based on the table DBA_ALERT_HISTORY because it would show us when a database went down and also come back up.  What I found out the other day was that if a node in our RAC instance becomes unreachable, or can't communicate with the Oracle database for another reason such as a server crash, the table DBA_ALERT_HISTORY may not get logged to until the node becomes available again.

This was interesting because even though the other node went through configuration believing it was the only node available, the remaining node isn't configured to log into this table that it lost track of the other node since it is the responsibility of the offending node to write to the table.  After the server was communicative again 10-20 minutes later, I saw a most interesting series of entries logged into the table indicating that the server is coming up, followed by a notification that the server is down just milliseconds later....even though the instance was still coming up!  This second notification was actually the original notification that should have went out when the instance went down, but it couldn't be logged to the table until the server was operational and communicating with the DB.

I still think I need to create an alert based on this table, but I thought it was very interesting to see the table in a real-time fashion while we had a server basically offline and my expectations didn't match up with what happened at all!

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!

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/

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.

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.

Four words that strike terror in the hearts of men (and women)

After having a major system uplift, there are four words I’ve heard over and over again which are stalking my dreams and turning them into nightmares lately.  “We didn’t test that.”  Well, that doesn’t seem too dire really, but the repercussions of this are huge and cross every team that worked on the uplift in the first place.

Who is impacted?

Developers - In some cases, these are the unsung heroes of your uplift and what is their reward after it is completed?  To keep their noses to the grindstone and work a few more weeks off on the fires that keep cropping up.  Doesn’t sound like a real promising job huh?

Projects - Not just the project people, which I'll get back to, but you're now putting off being able to work on your next projects.  It doesn't matter if it is old production fixes or currently pipelined new projects, delays will drain your political capital because you are now missing target deployment dates and the business thinks you are pretty much worthless for not catching all the things you are now responsible for fixing.  Project personnel start feeling burned out just like your developers because they've been on the project forever, and the bigger the project the longer you'll want to keep them around to play clean up for all the new debris coming up.

Support - How many fires do you get on a daily basis?  Multiply that by a factor of 2 or 3 after doing an uplift like this for about a month, and you’ll see what kind of volume you’ll be slowly crushed under when you have people in the new system doing their daily work which they never really replicated in the test environment.

DBAs - During the project and throughout the implementation we've been wearing them thin, and they are now getting no rest by making them look at applying patches and identifying system issues which should’ve been caught months ago so they aren't able to instead be able to focus on things like building new monitoring tools.  Fundamental things like missing critical DB bugs can easily happen because everything in the system is being thrown against the wall without a whole lot of investigation possible for each item.

How can we do better?

We need to be more proactive about showing the business and project teams what has been run in the last 30, 60, 180 days in your system and by whom.  Having these snapshots would be able to show the majority of the daily, monthly and quarterly reporting goals that the project needs to meet.

We can do a better job about documenting out our system flow, so we know what all our parts and pieces are which are required to provide full service to the business.  This way you won't get surprised by a report pushing output to a third party in-house group, to a server you didn't even know was connected to your system.

I'll probably add more as I encounter them, but what would you add to this list?