Dave Herring's DBA Blog

"ulimit", ASM, and Thinking Things Through

2011-11-03T12:53:00.000-07:00

The other day while reviewing an instance's alert log Ifound an interesting message:

WARNING:Oracle instance running on a system with lowopen file descriptor

limit.Tune your system to increase this limit to avoid

severeperformance degradation.

A quick search of MOS pointed me to bug 5862719. It turns out on our RAC system (10.2.0.2) onRHEL 4, the /etc/init.d/init.crsd file has the command "ulimit -nunlimited" in it, which fails and drops the file descriptor limit to itsdefault, which in our case is 1024.

% ps -ef | grep smon_dchdb

oracle 20720 1 0 Oct31 ? 00:00:16 ora_smon_dchdb1

% grep "open files" /proc/20720/limits

Max open files 1024 1024 files

The system recently crashed (which was why I was checkingthe alert log) and so all auto-started Oracle processes inherited their ulimitsfrom the init processes.

My point of this isn't to re-document an Oracle bug butemphasize the importance of taking a step back periodically and thinking thingsthrough. Is an FD limit of 1024potentially hurting our system, performance-wise? If so, can I duplicate this elsewhere toprove the impact, justifying an emergency fix?

On Linux it's pretty easy to check on open file counts forprocesses running under the same account. As "oracle" I issued the following:

#------------------------------------------------------------------------------------|

# Check all "oracle" processes associatedwith database "dchdb" and ASM, grab the PID

# and current command, then count how many files areopened and display the results.

#------------------------------------------------------------------------------------|

ps -f -u oracle | grep -E '(dchdb1|ASM)' | awk'{print $2" "$8}' | \

while readIN_PID IN_CMD

echo"Files opened for PID $IN_PID $IN_CMD: `ls -1 /proc/${IN_PID}/fd 2>/dev/null| wc -l`"

done | sort-nr -k7,7 | head -6

#-- output --#

Files opened for PID 21810 ora_rbal_dchdb1: 28

Files opened for PID 21790 ora_asmb_dchdb1: 28

Files opened for PID 22080 ora_arc1_dchdb1: 27

Files opened for PID 22174 ora_qmnc_dchdb1: 26

Files opened for PID 22078 ora_arc0_dchdb1: 26

Files opened for PID 20859 ora_lck0_dchdb1: 24

No process has more than 28 files open, so a limit of 1024seems pretty safe. Yet the database hasa few hundred datafiles, so why isn't the number higher? This is where ASM comes in to play. ASM bypasses the file system so database"files" aren't managed by the OS and FD's, so for the most part FDlimits have a different context when dealing with ASM.

Result? While I believeit's not always wise to leave code as is even though 1 or more commands/partsare failing each time, in this case spending a bit of time to think thingsthrough allowed this change to be scheduled on a lower priority.

Generating Extra Rows and the Right Cardinality

2011-10-21T09:37:00.000-07:00

Periodically I find code executed on databases I supportthat is used to generate x number of extra rows, normally to produce a set ofliteral values as a table. For example,recently I found the following embedded as an inline view in a rather large query:

(SELECT LAST_DAY(ADD_MONTHS(:in_date, -1))work_date, -1 rws_back

FROM dual UNION

SELECTLAST_DAY(ADD_MONTHS(:in_date, -2)), -2

FROM dual UNION

SELECTLAST_DAY(ADD_MONTHS(:in_date, -3)), -3

FROMdual UNION

...

SELECTLAST_DAY(ADD_MONTHS(:in_date, -13)), -13

FROM dual) in_dt_view

The idea was to generate a 13-row table, with each rowholding a date counting backwards 1 month from the previous row. Those 26 lines of SQL could have easily beenwritten as:

(SELECT /*+ CARDINALITY(d 13) */ LAST_DAY(ADD_MONTHS(sysdate,(level*-1))) work_date

, (level*-1) rws_back

FROMdual d

CONNECT BY level <= 13) in_dt_view

Using "CONNECT BY level <=" is a handy way ofgenerating x number of rows for any number of purposes, not only in situationslike the above one but also for generating data when conducting tests. This change isn't meant to tune the query (itdoes take a smidge less Shared Pool space) but make it easier to write (imagineif they needed 48 months back in time).

Using "CONNECT BY level <=" isn't something new as there are many examples of this technique on the internet. But for whatever reason it doesn't seem to be used that often in production code, instead mostly in code for generating data and/or presentations.

But why the CARDINALITY hint? Without it the optimizer thinks only 1 rowwill be returned as DUAL has only 1 row and the optimizer doesn't try todetermine the row count generated by "CONNECT BY …". Tom Kyte has a great discussion about this hint at http://tinyurl.com/4x2s7zk.

Connection Total Mismatch between Listener and Database

2011-04-18T15:31:00.000-07:00

Normally I don't spend a lot of time reviewing connectiondetails in my client's listener logs, but I came across a situation recentlywhere failover and connection distribution were being questioned, so I figuredit'd be best to review listener log data just to be safe. What I ended up finding was that connectioncounts as recorded in the listener logs was nearly twice that of what"logons cumulative" statistic was showing, which in my mind wasn'tright.

To perform any type of listener log analysis, I firstneeded some sort of tool, as the system involved is a 4-node OLTP RAC with100,000's of connections happening per day. Fortunately Arup Nanda did most of this work for me, based on his DBAzinearticle on 9/16/08 entitled "Mining Information from the ListenerLog". I used his notes to create anExternal Table for pointing to a given listener log and an Oracle function forproperly parsing out details within lines of the listener log. (See the end of this article for SQL queriesinvolved to help analyze the data.)

As for the hardware and database involved, the followinguses simplified names of targets to help illustrate the problem:

4-node RAC running RHEL 4.8 and Oracle 10.2.0.2.
Nodes are named RAC1, RAC2, RAC3, and RAC4 withone 1 Instance of the database on each, named inst1, inst2, inst3, and inst4
2 Oracle Services are defined to use Inst1 andInst2 as a strictly OLTP set of balanced Instances (service "inst1and2")and use Inst3 and Inst4 as a strictly Batch set of balanced Instances (service"batch1and2").

Back to the problem, I found that Service"inst1and2" was getting 1,000's of connections per hour againstInstances Inst3 and Inst4, which from my understanding couldn't happen. I used "srvctl" as one way tovalidate this Service's definition, just to be sure:

% srvctl config service -d$db_unique_name -a

inst1and2 PREF: inst1 inst2AVAIL: TAF: NONE

batch1and2 PREF: inst3 inst4AVAIL: TAF: NONE

As a last check, I asked the Application team to send methe exact connection string they were using. Sure enough, this pointed out the problem:

(DESCRIPTION = (ADDRESS =(PROTOCOL = TCP)(HOST = RACVIP3)(PORT = 1521)) (ADDRESS = (PROTOCOL = TCP)(HOST= RACVIP4)(PORT = 1521)) (LOAD_BALANCE = yes)(FAILOVER = ON) (CONNECT_DATA =(SERVER = DEDICATED) (SERVICE_NAME = inst1and2)(FAILOVER_MODE = (TYPE = SELECT)(METHOD = BASIC))))

Testing this from my PC using "sqlplususer/pass@'' ", I reproduced theproblem. I found that RAC3 / 4'slistener log recorded a connection:

18-APR-2011 09:52:03 *(CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=inst1and2)(FAILOVER_MODE=(TYPE=SELECT)(METHOD=BASIC))(CID=(PROGRAM=C:\oracle\product\10.2.0\db_1\bin\sqlplus.exe)(HOST=myserver123)(USER=ME)))* (ADDRESS=(PROTOCOL=tcp)(HOST=...)(PORT=1234)) * establish * inst1and2 * 0

… and also RAC1 / 2's listener log recorded a connection:

18-APR-2011 09:52:03 *(CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=inst1and2)(FAILOVER_MODE=(TYPE=SELECT)(METHOD=BASIC))(CID=(PROGRAM=C:\oracle\product\10.2.0\db_1\bin\sqlplus.exe)(HOST=myserver123)(USER=ME))(INSTANCE_NAME=inst1))* (ADDRESS=(PROTOCOL=tcp)(HOST=...)(PORT=2345)) * establish * inst1and2 * 0

Notice the string "…INSTANCE_NAME…" in thelistener log entry for RAC1 / 2. According to MOS document 263599.1, when this is present it represents aredirected connection, which is true in the test case above. Simple enough, except that this stringDOESN'T occur in any of listener log entries in question. Further down in the same MOS document,there's a short blurb about thin jdbc connections and that if these connectionsare redirected, there won't be any mention of this in the listener log, as inthe string INSTANCE_NAME won't be present.

This matches my case, as all application servers involvedare connecting via thin jdbc. MOSdocument 263599.1 also points out that "lsnrctl services" can alsopoint out connect redirects. CheckingRAC4 I see the following:

Service "inst1and2"has 2 instance(s).

Instance "inst1", status READY, has 1 handler(s) for thisservice...

Handler(s):

"DEDICATED" established:658909refused:0 state:ready

REMOTE SERVER

(ADDRESS=(PROTOCOL=TCP)(HOST=RAC1)(PORT=1521))

Instance "inst2", status READY, has 1 handler(s) for thisservice...

Handler(s):

"DEDICATED" established:737610refused:0 state:ready

REMOTE SERVER

(ADDRESS=(PROTOCOL=TCP)(HOST=RAC2)(PORT=1521))

For Service "inst1and2" on RAC4, 659,909connections have been redirected to "inst1" and 737,610 connectionshave been redirected to "inst2", all since the listener was lastrestarted.

Although all of this helps account for any connectioncount discrepancies between the listener log and database statistic"logons cumulative", I'm left with having to check "lsnrctlservices" and connect strings from application servers to help tie it alltogether. It'd sure be a lot easier, atleast to me, for Oracle to have included a message like "redirect"within the listener log entry to point out what happened.

SQL Code

The following is an example of a query I used to analyzelistener log data via an external table. I'm including this as I found a few cases where the data didn't line upas expected and I had to use a bit that knowledge to handle most of thosecases.

SELECT min_log_date,max_log_date,

CASE WHENparse_listener_log_line_fnc(connect_string, 'HOST') IS NOT NULL AND

parse_listener_log_line_fnc(connect_string, 'HOST') NOT IN ('__jdbc__')

THENparse_listener_log_line_fnc(connect_string, 'HOST')

ELSEREGEXP_REPLACE(REGEXP_REPLACE(protocol_info,

'(^.*HOST=)([0-9]+.[0-9]+.[0-9]+.[0-9]+).*\$','\2'),

'(^.*HOST=)(lnx|racvip){1}([0-9]+.us.dnb.com).*\$','\2\3')

END source_machine

,NVL(parse_listener_log_line_fnc(connect_string, 'PROGRAM'),

parse_listener_log_line_fnc(connect_string,'HOST'))

, CASE WHEN connect_string IN ('ping','service_update', 'status') THEN connect_string

WHEN protocol_info IN ('services','status') THEN protocol_info

ELSE action

END operation

, NVL(service_name, protocol_info)service, return_code, COUNT(*)

FROM listener_log_tb

, (SELECT MIN(log_date) min_log_date,MAX(log_date) max_log_date

FROM listener_log_tb)

GROUP BY min_log_date, max_log_date

,CASE WHEN parse_listener_log_line_fnc(connect_string, 'HOST') IS NOT NULL AND

parse_listener_log_line_fnc(connect_string,'HOST') NOT IN ('__jdbc__')

THENparse_listener_log_line_fnc(connect_string, 'HOST')

ELSEREGEXP_REPLACE(REGEXP_REPLACE(protocol_info,

'(^.*HOST=)([0-9]+.[0-9]+.[0-9]+.[0-9]+).*\$','\2'),

'(^.*HOST=)(lnx|racvip){1}([0-9]+.us.dnb.com).*\$','\2\3')

END

,NVL(parse_listener_log_line_fnc(connect_string, 'PROGRAM'),

parse_listener_log_line_fnc(connect_string,'HOST'))

,CASE WHEN connect_string IN ('ping', 'service_update', 'status') THENconnect_string

WHENprotocol_info IN ('services', 'status') THEN protocol_info

ELSE action

END

,NVL(service_name, protocol_info), return_code;

Red Hat 4.x to 5.x fuser "Enhancement"

2010-10-03T13:33:00.000-07:00

I came across an interesting situation related to an upgradeof Red Hat. Due to planned upgrades ofOracle 10g to 11g, we are first performing upgrades of RH from 4.x to 5.x. Normally an OS upgrade would involve sanity checks that nothing breaks, butyou'd expect your basic Unix commands to behave the same.

Yet after running a few DBA maintenance scripts I found aproblem with one script that was using "fuser". Our script checks a list of files to see ifany are currently open and if so, it processes them differently. The problem was that under RH 5.x (5.3,specifically), where "fuser" piped to "cut":

for active_file in `fuser $dir/$sub/* 2>&1 |cut -d\: -f1`

In the snipet of code above under RH 5.3, it appeared thatboth files and the PID from "fuser" were getting returned, as if"cut" didn't work at all. After closer investigation it turned out that "fuser" was theguilty party. I ran a simple test on adatabase server with Oracle running, knowing that "libclntsh*" wouldbe open.

Using the command:

fuser $ORACLE_HOME/lib/libclntsh* | cut -d\: -f1

… under RH 4 you'll get:

/ora01/app/oracle/product/10.2.0/db_1/lib/libclntsh.so

/ora01/app/oracle/product/10.2.0/db_1/lib/libclntsh.so.10.1

… while under RH 5 you'll get:

/ora01/app/oracle/product/10.2.0/db_1/lib/libclntsh.so:m

/ora01/app/oracle/product/10.2.0/db_1/lib/libclntsh.so.10.1:m

7309 7309

I did a crazy thing and checked the "man" pagesfor "fuser" to see if I was missing something and sure enough, I was:a change in RH 5! See the following linelisted right before the OPTIONSsection:

fuser outputs only the PIDs tostdout, everything else is sent to stderr.

That explains the difference in behavior between releases. Fortunately the workaround is easy: redirectstderr to stdout.

Fortunately I caught this, but I wonder what other changesare lurking out there?

SQL*Plus & Command History with Cygwin + rlwrap

2010-03-21T17:58:00.000-07:00

Although nearly all apps today are use some sort ofpoint-click, windowing front end, there are plenty of us who still use thecommand-line when available. It's notthat we're set in our ways, it's that for many repetative tasks, the command-lineprovides us with enough shortcuts that we're just way more efficient with a fewkey strokes.

This brings me to Oracle's SQL*Plus, or more specifically,running "sqlplus" from the command-line. "sqlplus" has long provided theability to edit the previous command in it's buffer, either pulling it up intoan editor or using a few commands to change it in place (such as "CHANGE//"). But obviously this is limited.

In comes "rlwrap". This application is also nothing new, but didyou know it's available from within Cygwin? This issue came up during Tanel Poder's recent Training Day at HotsosSymposium 2010. He gave some greatexamples of "rlwrap"'s power using it from Linux, then laid thegauntlet down by saying it shouldwork under Cygwin, but he hasn't tried it and we should let him know if we canget it working. That was enough for me!

I've used Cygwin for some time as a way to start an XWinserver, in support of other apps that require it (such as Oracle's installer). I reviewed the my installation source (x.cygwin.com)and ran the installation again to see if "rlwrap" is available. Sure enough, if you change the View tobe by Category, then you'll file "rlwrap" under Utils:

In the screenshot above you can see "rlwrap" isalready installed, but this was taken from my current install, so you get theidea.

The installation process dumps "rlwrap" under c:\cygwin\binby default. Now comes the power of thetool!

From your PC, open a Cygwin XWin server to work off of, thenan xterm from this XWin server session. From the xterm session you can fire off your "rlwrap"commands. You can run themfrom the XWin server session, but I prefer to instead use that as a centralsession, firing off separate xterm sessions per connection I plan on making. In my $HOME directory I created a setupscript which defines a series of aliases, one per color-coded xterm screen:

alias black="xterm -fn '-adobe-courier-*-r-*-*-12-*-*-*-*-*-10' -ls -geometry 140x35+50+20 -bg black-fg gainsboro &"

alias brown="xterm -fn '-adobe-courier-*-r-*-*-12-*-*-*-*-*-10'-ls -geometry 140x35+50+20 -bg brown -fg gainsboro &"

alias blue="xterm -fn'-adobe-courier-*-r-*-*-12-*-*-*-*-*-10' -ls -geometry 140x35+50+20 -bgdarkblue -fg gainsboro &"

alias darkred="xterm -fn '-adobe-courier-*-r-*-*-12-*-*-*-*-*-10' -ls -geometry 140x35+50+20 -bg darkred -fg gainsboro &"

alias green="xterm -fn'-adobe-courier-*-r-*-*-12-*-*-*-*-*-10' -ls -geometry 140x35+50+20 -bggreen4 -fg gainsboro &"

alias purple="xterm -fn '-adobe-courier-*-r-*-*-12-*-*-*-*-*-10' -ls -geometry 140x35+50+20 -bg purple4 -fg gainsboro &"

alias teal="xterm -fn'-adobe-courier-*-r-*-*-12-*-*-*-*-*-10' -ls -geometry 140x35+50+20 -bgdarkcyan -fg gainsboro &"

alias white="xterm -fn'-adobe-courier-*-r-*-*-12-*-*-*-*-*-10' -ls -geometry 140x35+50+20 -bg white-fg black &"

This way typing "blue", for example, quicklygives me a new blue background, white foreground xterm.

Back to "rlwrap" power. A simple example of the command is asfollows:

rlwrap -r sqlplus dherri@ORCL1

Within this sqlplus session I now have full command-linehistory using the arrow keys. Plus withthe "-r" argument, "rlwrap" will "remember", soto speak, all text that passes on the screen. What this means is through the TAB key you can now quickly access outputfrom previous queries. For example, supposeyou wanted to query an AWR view but couldn't remember the name. So you enter:

SELECT view_name

FROM dba_views

WHERE view_name LIKE 'DBA_HIST%'

ORDER BY 1;

Now the output list of view names is in rlwrap's buffer,which means the view names are available for command completion. If you enter:

SELECT * FROM DBA_HIST_SQL

… and hit TAB twice, you'll get the following displayed:

DBA_HIST_SQLBIND DBA_HIST_SQLTEXT DBA_HIST_SQL_PLAN DBA_HIST_SQL_WORKAREA_HSTGRM

DBA_HIST_SQLSTAT DBA_HIST_SQL_BIND_METADATA DBA_HIST_SQL_SUMMARY

This is just a small sampling of what "rlwrap"can provide in terms of added efficiency within sqlplus command-line or fornearly any app for that matter (RMAN quickly comes to mind). The main point I'm raising here is Windowsusers need not be excluded from the benefits of command-line completion using "rlwrap".

For more detail on "rlwrap" and excellentexamples of applying its use, see Tanel Poder's blog @ blog.tanelpoder.com or his new tech site @ tech.e2sn.com.

Parallelism "Secretly" Disabled by User Function

2009-08-28T15:41:00.000-07:00

Ever work on a problem where initial observation and past experience says "1 + 1 = 2" yet it keeps coming out "3"? I recently ran into a situation like this, where all past experience told me that the query should run with parallelism and even the xplan showed it would, yet during the execution of the query I could tell it was running serially.

A simplified version of the original query is listed below, involving 3 tables that all had a parallel degree of 8:

SELECT std_function_pkg.domain_group_fnc(dn.domain, dn.domain_suffix)

, MAX(CASE WHEN event_type = 'C' THEN e.event_date ELSE NULL END) latest_type

FROM dn_tb dn LEFT OUTER JOIN vlm_sum_tb vlm

ON (dn.member_id = vlm.member_id)

LEFT OUTER JOIN

event_tb PARTITION (v8) e

ON ( dn.member_id = e.member_id

AND e.vendor_id = 13569

AND e.event_type IN ('O','C'))

GROUP BY std_function_pkg.domain_group_fnc(dn.domain, dn.domain_suffix);

This query yields an xplan as follows:

--------------------------------------------------------------------------------------------------------------------------------------
| Id|Operation                     | Name           | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |  TQ  |IN-OUT| PQ Distrib
--------------------------------------------------------------------------------------------------------------------------------------
|  0|SELECT STATEMENT              |                | 14960 |   613K| 83941   (5)| 00:16:48 |       |       |      |      |
|  1| PX COORDINATOR FORCED SERIAL |                |       |       |            |          |       |       |      |      |
|  2|  PX SEND QC (RANDOM)         | :TQ10003       | 14960 |   613K| 83941   (5)| 00:16:48 |       |       |Q1,03 | P->S |QC (RAND)
|  3|   SORT GROUP BY              |                | 14960 |   613K| 83941   (5)| 00:16:48 |       |       |Q1,03 | PCWP |
|  4|    PX RECEIVE                |                | 14960 |   613K| 83941   (5)| 00:16:48 |       |       |Q1,03 | PCWP |
|  5|     PX SEND HASH             | :TQ10002       | 14960 |   613K| 83941   (5)| 00:16:48 |       |       |Q1,02 | P->P | HASH
|  6|      SORT GROUP BY           |                | 14960 |   613K| 83941   (5)| 00:16:48 |       |       |Q1,02 | PCWP |
|  7|       NESTED LOOPS OUTER     |                |  4568K|   182M| 83713   (4)| 00:16:45 |       |       |Q1,02 | PCWP |
|* 8|        HASH JOIN RIGHT OUTER |                |   253K|  6444K|    54   (6)| 00:00:01 |       |       |Q1,02 | PCWP |
|  9|         PX RECEIVE           |                |   286K|  1676K|     7   (0)| 00:00:01 |       |       |Q1,02 | PCWP |
| 10|          PX SEND HASH        | :TQ10000       |   286K|  1676K|     7   (0)| 00:00:01 |       |       |Q1,00 | P->P | HASH
| 11|           PX BLOCK ITERATOR  |                |   286K|  1676K|     7   (0)| 00:00:01 |     1 |    16 |Q1,00 | PCWC |
| 12|            TABLE ACCESS FULL | VLM_SUM_TB     |   286K|  1676K|     7   (0)| 00:00:01 |     1 |    16 |Q1,00 | PCWP |
| 13|         PX RECEIVE           |                |   253K|  4957K|    46   (5)| 00:00:01 |       |       |Q1,02 | PCWP |
| 14|          PX SEND HASH        | :TQ10001       |   253K|  4957K|    46   (5)| 00:00:01 |       |       |Q1,01 | P->P | HASH
| 15|           PX BLOCK ITERATOR  |                |   253K|  4957K|    46   (5)| 00:00:01 |     1 |    16 |Q1,01 | PCWC |
| 16|            TABLE ACCESS FULL | DN_TB          |   253K|  4957K|    46   (5)| 00:00:01 |     1 |    16 |Q1,01 | PCWP |
| 17|        PARTITION RANGE SINGLE|                |    18 |   288 |            |          |     8 |     8 |Q1,02 | PCWP |
| 18|         PARTITION LIST INLIST|                |    18 |   288 |            |          |KEY(I) |KEY(I) |Q1,02 | PCWP |
| 19|          VIEW                |                |    18 |   288 |            |          |       |       |Q1,02 | PCWP |
|*20|           TABLE ACCESS FULL  | EVENT_TB       |    18 |   324 | 51903   (7)| 00:10:23 |KEY(I) |KEY(I) |Q1,02 | PCWP |
--------------------------------------------------------------------------------------------------------------------------------------

As you can see from the xplan, the query should use parallelism. Yet when monitoring the system while the query was running, I saw that V$PX_SESSION returned 0 rows (meaning no PX slaves were active) and that the only session involved in the query was generating "db file scattered read" waits, which is a non-parallel read wait.

I ended up taking the trial and error approach, finding a basic version of the query that ran properly with parallelism, then added back items from the column list and GROUP BY section until parallelism was removed.

It turns out that the call to the user function DOMAIN_GROUP_FNC was the culprit. From there I found out, by isolating the function from the package, that the function itself wasn't the problem but definitions for the function WITHIN the package was the problem.

Within the package STD_FUNCTION_PKG, the function declaration was followed by the directive: pragma restrict_references(domain_group_fnc, WNPS); I don't know the original intent of the programmers who added this, but for a parallel query, this won't work since the documentation clearly states that all four constraints (RNDS, RNPS, WNDS, WNPS) must be specified when using a parallel query. Plus, the clause PARALLEL_ENABLE needs to be added when the function is contained within a package (for that function to allow the query to run with parallelism).

In the end, it points out that wait events are not only key for resolving performance issues, but an excellent method for determining what the query is really doing.