Weekend Learning: Setting up, monitoring, and tuning parallelism

Do not miss out on the MOS document "Setup, Monitor, And Tune Parallelism In The Database" this weekend via document ID 1549214.1 to get the scoop on what default parallelism is, parameter settings which influence this, best practices, AND a health check script which can help you determine if there is anything off in your system!

Weekend Learning: Whitepaper on validation of Diskgroups and ASM

In our efforts to get more understanding of Oracle technology for our toolbox, I suggest that you read the MOS whitepaper "How to Validate Normal or High Redundancy Diskgroups and ASM Disks Partnership (White Paper)" from article ID 1961372.1 to add to that toolbox!  This really takes us step by step on the validation procedure, and makes me think of ways we can monitor this (if OEM does not take care of it!).

Restarting Windows services and v$transaction

I am sure you are thinking "come on, what do I care about restarting a Windows service" or "I thought this was an Oracle blog" right?  Just hang with me for a minute and it will all make sense!  While we are Oracle technologists foremost, sometimes we need to get additional skills to enhance our primary skills and this is a great example of that.  Today I found myself referencing documentation from Microsoft's Technet because we have a Windows service that keeps a connection open to our database so the software can call our database when needed, and this is keeping a transaction open.  Why is that a problem?  We need to make sure that nothing in v$transaction is older than x days due to our restoration plans, but every x days our monitoring tells us about the old transaction from the Windows service and we have to manually restart the service.  Well, HAD to after using the "net stop" and "net start" commands in a batch file so we can create a scheduled task that bounces this service every night.

Weekend Learning: InfiniBand interfaces

Are you running InfiniBand devices with your Oracle infrastructure?  Do you want to know a bit more about it, and problems that can arise?  Of course you do!  Look no further than My Oracle Support note "InfiniBand IPoIB Interfaces Down and IBSTAT Reports HCA Ports in INITIALIZING State" via document ID 1950483.1 which sounds a LOT like an issue we had with InfiniBand interfaces a few months ago, so I wonder if this is based off of our case!  Have you ever used the ibstat command?  Do you monitor /var/log/messages for potential issues?

Weekend Learning: Troubleshooting Essbase Agent when hanging

Did you know there are some step by step instructions for how to troubleshoot the Essbase Agent when it is hanging?  The note "Troubleshooting Essbase Agent Hangs on UNIX Systems" on My Oracle Support via document ID 1107095.1 gives you the steps using the pstack and netstat commands!  On top of it all, they give you the other information needed to open an SR when you encounter this issue which may clue you in on the application log files you need to be monitoring in the future.

Blog roll update: oradbn

Last week I added a new blog to my list and today I decided to find another new blog that has the kind of articles I'm looking for!  While the oradbn blog from Benedikt Nahlovsky might only have a handful of posts from the last two years they are goldmines for being able to monitor the database in new and interesting ways, finding out more on ORA errors that can be encountered on new database versions, and getting 12c installed and running.  There are some great ideas here that I can use at work to implement some new monitoring but also is an outside perspective with how to handle things in a completely different way.

Using shell scripts to monitor DB files

Since I am sure that you got enough Twitter information from KScope this week, I am going to skip the regular Thursday Twitter to focus on on a tweet from Xavier Picamal about monitoring log files!  Why is this such a good article to read?  Well I am spending some time planning out additional monitoring for our platforms using shell scripts like this, and seeing different examples of what can be done or different ways to do the same thing can only expand our horizons and make our solutions better.

While Xavier is looking through .log files, this makes me think about being able to search through .trc files that get automatically generated.  What does this make you think of?  Have you seen other examples of how to do this, or other things to monitor in this way?

Latency heat mapping

Reading a post from my blog roll, I was looking forward to reading the originating post about how to create a latency heat map/chart but thought it would be clunky and would involve some long and drawn out installation.  Surprisingly, it is neither clunky or involved and I can't wait to run this at work tomorrow!

Of course since the original post, there is a new version of code online after feedback and the rubber meeting the road.

WebLogic alerting

This post seems like a very through process for alerting on the WebLogic platform, and I'll be making sure to snoop around our system to see if we're using something like this!

System Wait Events Part 1

Before I go too much further with the blog, I have to do some housecleaning!  Back in August I had realized that a post went missing, so I put the URL into a draft and saved it to come back to and last week I was looking for that article......but I had never come back to it to re-write the article!  That's bad on me in general, and more specifically this post and the one last week have gone without a true origination and credit which bugs me quite a bit.

After upgrading to Exadata with 11.2.0.2, we started running into sessions hanging in the "inactive transaction branch" which were running statements over a DB link to an instance running on 10.2.0.4.  A quick search lead me to this page which not only suggested a fix (patching didn't actually resolve it), but also a way to look into our systems which is proactive and at a deeper level than we had before.

Journal Import: Suspended!

Off of our wait event alert, there was a session that just sitting in "statement suspended, wait error to be cleared" which was a new wait event I had not seen before.  Doing some research I found it to be a Journal Import report which was in the process of deleting rows per this statement:

delete from GL_INTERFACE
where (user_je_source_name, nvl(group_id, -1)) in (listing of ledgers) and status = 'PROCESSED'
and request_id = user request
and rownum <= 5000
and (user_je_source_name, nvl(group_id, -1)) IN (SELECT src.user_je_source_name, nvl(group_id,-1) FROM gl_interface_control ic, gl_je_sources src WHERE ic.je_source_name = src.je_source_name
AND   ic.interface_run_id = run id
AND   ic.set_of_books_id = set of books id
AND   ic.status = 'I'
AND   nvl(ic.processed_table_code,'D') != 'S')

I can see in the table dba_outstanding_alerts information about this session as such:

Operation on resumable session Session 1579, Instance 1 session id 1579 suspended because of errors in rollback segment _SYSSMU1260_2942144267$. Error message is ORA-01628: max # extents (32765) reached for rollback segment _SYSSMU1260_2942144267$

Now the error message seems to be straightforward, and My Oracle Support notes ID 761848.1 & 788060.1 give some anecdotal evidence for what is going on, but we weren't able to get the root cause addressed in time to allow the report to complete successfully as it timed out internally and resulted in the report completing in Error.  This means I'm not exactly sure how we could have resolved it, yet I have some suspicion that if we could have expanded the maximum number of extents for this segment we would have seen the session resume and move along.  I'll put this down under as a mystery which needs research, because we need to learn more about it for next time when the report in question is something a lot more important and we can't go back to Oracle with an SR to fix.

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!

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.

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/

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.

Proactive monitoring

Reading a post by Jonathan Lewis got me to thinking about something I'd been meaning to write up, and there is no time like the present!

In the past year or so I have been growing ever more curious as to how the system is doing what it's doing, and even more importantly to my niche, what is the system doing and why is it doing it. 

Before going to the wonderful HOTSOS Symposium this year, my boss and I were chewing over a problem plaguing us regularly of the system seeming to be doing a lot of work and churning information over in the v$session_longops table quite a bit.  Since we never had a lot of exposure to this view before, we weren't sure how to react to some of the things we saw in there and then we had a crisis come up, and this was research was shelved for a short time.  After the Symposium, and the Training Day with Jonathan, we came back to the office rejuvenated a bit and dug into this with some ferocity; therefore, it was with some chagrin that we realized we had stumbled upon something we wish had been around for several years at our shop.  We now had a window into the SQL running in our system, so we could determine not only what was running long but more importantly if it should be running long.  Now we had a powerful tool in our toolbox, and were able to wield it as one would a sword through a thick jungle to cut down many of the vines in our path but were starting to run out of vines and wanted to turn our sword into a scalpel.  Our choice was to create an Oracle Alert running the below 10.2.0.4 script every 15 minutes alerting our PROD Support team:

select vs.sid,
vs.serial#,
vs.username,
vs.osuser,
vs.module,
vs.action,
substr(vsa.sql_text, 0, 80) AS SQL_PART,
vs.status,
vsl.opname,
vs.event,
vs.blocking_session_status,
to_char(vsl.start_time, 'DD-MON-YY HH24:MI:SS') AS "START TIME",
vsl.last_update_time,
(round((1 - (vsl.elapsed_seconds / (vsl.elapsed_seconds + vsl.time_remaining) ) ),2)) * 100 AS "% WORK_REMAINING",
round((vsl.elapsed_seconds/60), 2) as "MINUTES ELAPSED",
round((vsl.time_remaining/60), 2) as "MINUTES REMAINING",
vsl.message,
vs.sql_id,
vsa.users_executing
from v$session_longops vsl, v$session vs, v$sqlarea vsa
where vsl.sql_id = vs.sql_id
and vs.sql_id = vsa.sql_id
and vsl.sid = vs.sid
and vsl.sofar != vsl.totalwork

After weeks of running this, we were able to capture several performance issues which never would have come to light unless we went looking in our system and I'll be sharing those over the next weeks!  Going even further, we expanded the alert to read across DB links to other 10.2.0.4 instances:

select 'INSTANCE1' AS "SERVER",
vs.sid,
vs.serial#,
vs.username,
vs.osuser,
vs.module,
vs.action,
substr(vsa.sql_text, 0, 80) AS SQL_PART,
vs.status,
vsl.opname,
vs.event,
vs.blocking_session_status,
to_char(vsl.start_time, 'DD-MON-YY HH24:MI:SS') AS "START TIME",
vsl.last_update_time,
(round((1 - (vsl.elapsed_seconds / (vsl.elapsed_seconds + vsl.time_remaining) ) ),2)) * 100 AS "% WORK_REMAINING",
round((vsl.elapsed_seconds/60), 2) as "MINUTES ELAPSED",
round((vsl.time_remaining/60), 2) as "MINUTES REMAINING",
vsl.message,
vs.sql_id,
vsa.users_executing
from v$session_longops vsl, v$session vs, v$sqlarea vsa
where vsl.sql_id = vs.sql_id
and vs.sql_id = vsa.sql_id
and vsl.sid = vs.sid
and vsl.sofar != vsl.totalwork
union
select 'INSTANCE2' AS "SERVER",
vs.sid,
vs.serial#,
vs.username,
vs.osuser,
vs.module,
vs.action,
substr(vsa.sql_text, 0, 80) AS SQL_PART,
vs.status,
vsl.opname,
vs.event,
vs.blocking_session_status,
to_char(vsl.start_time, 'DD-MON-YY HH24:MI:SS') AS "START TIME",
vsl.last_update_time,
(round((1 - (vsl.elapsed_seconds / (vsl.elapsed_seconds + vsl.time_remaining) ) ),2)) * 100 AS "% WORK_REMAINING",
round((vsl.elapsed_seconds/60), 2) as "MINUTES ELAPSED",
round((vsl.time_remaining/60), 2) as "MINUTES REMAINING",
vsl.message,
vs.sql_id,
vsa.users_executing
from v$session_longops@INSTANCE2 vsl, v$session@INSTANCE2 vs, v$sqlarea@INSTANCE2 vsa
where vsl.sql_id = vs.sql_id
and vs.sql_id = vsa.sql_id
and vsl.sid = vs.sid
and vsl.sofar != vsl.totalwork 
union
select 'INSTANCE3' AS "SERVER",
vs.sid,
vs.serial#,
vs.username,
vs.osuser,
vs.module,
vs.action,
substr(vsa.sql_text, 0, 80) AS SQL_PART,
vs.status,
vsl.opname,
vs.event,
vs.blocking_session_status,
to_char(vsl.start_time, 'DD-MON-YY HH24:MI:SS') AS "START TIME",
vsl.last_update_time,
(round((1 - (vsl.elapsed_seconds / (vsl.elapsed_seconds + vsl.time_remaining) ) ),2)) * 100 AS "% WORK_REMAINING",
round((vsl.elapsed_seconds/60), 2) as "MINUTES ELAPSED",
round((vsl.time_remaining/60), 2) as "MINUTES REMAINING",
vsl.message,
vs.sql_id,
vsa.users_executing
from v$session_longops@INSTANCE3 vsl, v$session@INSTANCE3 vs, v$sqlarea@INSTANCE3 vsa
where vsl.sql_id = vs.sql_id
and vs.sql_id = vsa.sql_id
and vsl.sid = vs.sid
and vsl.sofar != vsl.totalwork
order by "SERVER", "% WORK_REMAINING" desc, module