Failed Logon Attempts

4 04 2012

April 4, 2012

A fair number of articles on this blog are Oracle performance related in one respect or another.  I started thinking about how to measure how much more efficient something is when compared to something that is never performed.  Consider a situation where you had a database user account that is a member of the DEFAULT Oracle Database profile that is configured as follows:

ALTER PROFILE DEFAULT LIMIT
  PASSWORD_LIFE_TIME UNLIMITED
  FAILED_LOGIN_ATTEMPTS 5
  PASSWORD_LOCK_TIME 1
  PASSWORD_VERIFY_FUNCTION NULL; 

With the above configuration, passwords do not expire after a specified number of days, there are no password complexity requirements, and after five failed logon attempts, the account is automatically locked for one day.  The above configuration is not ideal from a security standpoint, but that is not the point of this blog article.

Assume that the one database user account is shared by multiple people (or multiple utility programs with an embedded username and password).  Suddenly, you find that your efficient utility program becomes inefficient… to the point that the “utility” portion of the program never has an opportunity to execute.  Well, that was unexpected, the database user account is locked out.  How did that happen?

The following SQL statement is probably quite simplistic for many of the readers of this blog, and probably should have been included in my Neat Tricks article that I published a couple of years ago, but I thought that I would include the SQL statement here to save myself a couple of minutes of typing the next time I need to figure out who-done-it:

SELECT
  TO_CHAR(TIMESTAMP,'MM/DD HH24:MI') TIMESTAMP,
  SUBSTR(OS_USERNAME,1,20) OS_USERNAME,
  SUBSTR(USERNAME,1,20) USERNAME,
  SUBSTR(TERMINAL,1,20) TERMINAL,
  ACTION_NAME,
  RETURNCODE
FROM
  SYS.DBA_AUDIT_SESSION
WHERE
  USERNAME LIKE 'MYUSER%'
  AND TIMESTAMP BETWEEN SYSDATE-1 AND SYSDATE
ORDER BY
  TIMESTAMP DESC;

TIMESTAMP   OS_USERNAME          USERNAME TERMINAL        ACTION_NAME          RETURNCODE
----------- -------------------- -------- --------------- -------------------- ----------
04/03 11:33 USER1                MYUSER   CUSER1          LOGON                         0
04/03 11:33 USER1                MYUSER   CUSER1          LOGOFF                        0
04/03 11:33 USER1                MYUSER   CUSER1          LOGOFF                        0
04/03 11:33 USER1                MYUSER   CUSER1          LOGON                         0
04/03 10:54 USER2                MYUSER   CUSER2          LOGOFF                        0
04/03 10:53 USER2                MYUSER   CUSER2          LOGON                         0
04/03 10:53 USER2                MYUSER   CUSER2          LOGON                         0
04/03 10:53 USER2                MYUSER   CUSER2          LOGON                         0
04/03 09:58 USER3                MYUSER   CUSER3          LOGOFF                        0
04/03 09:56 USER4                MYUSER   CUSER4          LOGON                         0
04/03 09:56 USER4                MYUSER   CUSER4          LOGOFF                        0
04/03 09:51 USER5                MYUSER   CUSER5          LOGON                         0
04/03 09:51 USER5                MYUSER   CUSER5          LOGON                         0
04/03 09:51 USER3                MYUSER   CUSER3          LOGON                         0
04/03 09:51 USER5                MYUSER   CUSER5          LOGOFF                        0
04/03 09:51 USER5                MYUSER   CUSER5          LOGOFF                        0
04/03 09:44 USER4                MYUSER   CUSER4          LOGOFF                        0
04/03 09:29 USER3                MYUSER   CUSER3          LOGOFF                        0
04/03 09:10 USER4                MYUSER   CUSER4          LOGON                         0
04/03 09:09 USER3                MYUSER   CUSER3          LOGON                         0
04/03 09:06 USER3                MYUSER   CUSER3          LOGOFF                        0
04/03 09:06 USER3                MYUSER   CUSER3          LOGOFF                        0
04/03 08:47 USER3                MYUSER   CUSER3          LOGON                         0
04/03 07:50 USER4                MYUSER   CUSER4          LOGON                         0
04/03 07:50 USER4                MYUSER   CUSER4          LOGOFF                        0
04/03 07:50 USER4                MYUSER   CUSER4          LOGOFF BY CLEANUP             0
04/03 07:50 USER4                MYUSER   CUSER4          LOGOFF BY CLEANUP             0
04/03 07:50 USER4                MYUSER   CUSER4          LOGOFF BY CLEANUP             0
04/03 07:50 USER4                MYUSER   CUSER4          LOGON                         0
04/03 07:50 USER4                MYUSER   CUSER4          LOGON                         0
04/03 07:50 USER4                MYUSER   CUSER4          LOGON                         0
04/03 07:12 USER3                MYUSER   CUSER3          LOGON                         0
04/03 07:12 NETWORK SERVICE      MYUSER   SERVER          LOGOFF                        0
04/03 07:11 NETWORK SERVICE      MYUSER   SERVER          LOGON                         0
04/03 07:11 IUSR_WEBSERV         MYUSER   SERVER          LOGON                         0
04/03 06:35 NETWORK SERVICE      MYUSER   SERVER          LOGOFF                        0
04/03 06:35 IUSR_WEBSERV         MYUSER   SERVER          LOGOFF                        0
04/03 06:35 NETWORK SERVICE      MYUSER   SERVER          LOGOFF                        0
04/03 06:34 IUSR_WEBSERV         MYUSER   SERVER          LOGON                         0
04/03 06:34 NETWORK SERVICE      MYUSER   SERVER          LOGON                         0
04/03 06:34 NETWORK SERVICE      MYUSER   SERVER          LOGON                         0
04/03 06:29 USER3                MYUSER   CUSER3          LOGOFF                        0
04/03 06:29 USER3                MYUSER   CUSER3          LOGON                         0
04/03 06:28 NETWORK SERVICE      MYUSER   SERVER          LOGOFF                        0
04/03 06:28 NETWORK SERVICE      MYUSER   SERVER          LOGOFF                        0
04/03 06:27 IUSR_WEBSERV         MYUSER   SERVER          LOGOFF                        0
04/03 06:27 NETWORK SERVICE      MYUSER   SERVER          LOGON                         0
04/03 06:26 IUSR_WEBSERV         MYUSER   SERVER          LOGON                         0
04/03 06:26 USER3                MYUSER   CUSER3          LOGOFF                        0
04/03 06:26 USER3                MYUSER   CUSER3          LOGON                         0
04/03 06:26 NETWORK SERVICE      MYUSER   SERVER          LOGON                         0
04/03 06:23 USER3                MYUSER   CUSER3          LOGON                     28000
04/03 06:23 USER3                MYUSER   CUSER3          LOGON                     28000
04/03 06:22 NETWORK SERVICE      MYUSER   SERVER          LOGON                     28000
04/03 06:22 NETWORK SERVICE      MYUSER   SERVER          LOGON                     28000
04/03 02:30 USER5                MYUSER   SERVER2         LOGON                     28000
04/02 19:53 USER1                MYUSER   CUSER1-LT       LOGON                     28000
04/02 19:53 USER1                MYUSER   CUSER1-LT       LOGON                     28000
04/02 19:11 USER1                MYUSER   CUSER1-LT       LOGON                     28000
04/02 19:11 USER1                MYUSER   CUSER1-LT       LOGON                     28000
04/02 18:37 USER1                MYUSER   CUSER1-LT       LOGON                     28000
04/02 18:37 USER1                MYUSER   CUSER1-LT       LOGON                     28000
04/02 18:37 USER1                MYUSER   CUSER1-LT       LOGON                      1017
04/02 18:37 USER1                MYUSER   CUSER1-LT       LOGON                     28000
04/02 18:32 USER1                MYUSER   CUSER1-LT       LOGON                      1017
04/02 18:32 USER1                MYUSER   CUSER1-LT       LOGON                      1017
04/02 18:31 USER1                MYUSER   CUSER1-LT       LOGON                      1017
04/02 18:31 USER1                MYUSER   CUSER1-LT       LOGON                      1017
04/02 17:08 USER3                MYUSER   CUSER3          LOGOFF                        0
04/02 17:03 USER3                MYUSER   CUSER3          LOGOFF                        0
04/02 17:03 USER3                MYUSER   CUSER3          LOGON                         0
04/02 16:55 USER3                MYUSER   CUSER3          LOGOFF                        0
04/02 16:55 USER3                MYUSER   CUSER3          LOGON                         0
04/02 16:54 USER3                MYUSER   CUSER3          LOGON                         0
04/02 16:52 USER3                MYUSER   CUSER3          LOGOFF                        0
04/02 16:45 NETWORK SERVICE      MYUSER   SERVER          LOGOFF                        0
04/02 16:45 NETWORK SERVICE      MYUSER   SERVER          LOGOFF                        0
04/02 16:45 IUSR_WEBSERV         MYUSER   SERVER          LOGOFF                        0
04/02 16:44 NETWORK SERVICE      MYUSER   SERVER          LOGON                         0
04/02 16:44 NETWORK SERVICE      MYUSER   SERVER          LOGON                         0
04/02 16:44 IUSR_WEBSERV         MYUSER   SERVER          LOGON                         0
04/02 16:43 USER3                MYUSER   CUSER3          LOGOFF                        0
04/02 16:42 USER3                MYUSER   CUSER3          LOGON                         0
04/02 16:42 USER3                MYUSER   CUSER3          LOGON                         0
04/02 16:32 USER6                MYUSER   CUSER6          LOGON                         0
04/02 16:32 USER6                MYUSER   CUSER6          LOGON                         0
04/02 16:32 USER6                MYUSER   CUSER6          LOGOFF                        0
04/02 16:32 USER6                MYUSER   CUSER6          LOGOFF                        0
04/02 16:21 USER3                MYUSER   CUSER3          LOGON                         0
04/02 16:20 USER3                MYUSER   CUSER3          LOGON                         0
04/02 16:20 USER3                MYUSER   CUSER3          LOGOFF                        0
04/02 16:19 USER3                MYUSER   CUSER3          LOGOFF                        0
04/02 16:15 USER3                MYUSER   CUSER3          LOGON                         0
04/02 15:40 USER3                MYUSER   CUSER3          LOGON                         0
04/02 15:40 USER3                MYUSER   CUSER3          LOGOFF                        0
04/02 15:31 USER3                MYUSER   CUSER3          LOGOFF                        0
04/02 15:06 USER1                MYUSER   USER1           LOGON                         0
04/02 15:06 USER1                MYUSER   USER1           LOGOFF                        0
04/02 15:06 USER1                MYUSER   USER1           LOGON                         0 

A couple of the rows in the above output are slightly out of sequence, but the order of the output is close enough for my needs.  The RETURNCODE column is the number associated with the ORA- error code that was returned to the client computer:

  • RETURNCODE=0 indicates success
  • RETURNCODE=1017 indicates bad password
  • RETURNCODE=28000 indicates account is locked out

Reviewing the above output, operating system user USER3 logged on successfully at 5:03 PM and logged off at 5:08 PM.  Operating system user USER1 attempted to log on at 6:31 PM from a computer named CUSER1-LT, but failed due to an invalid password.  By 6:37 PM, that same operating system user and computer combination had entered an incorrect password five times, which resulted in an ORA-28000 account lockout error being returned starting with the sixth logon attempt.

At 2:30 AM, USER5 on a computer named SERVER2 attempted to connect using the same database user account, but was also greeted with an ORA-28000.  The same fate awaited operating system user NETWORK SERVICE (this was a web-based logon attempt) and USER3 at 6:22 AM and 6:23 AM, respectively.  The problem was obviously corrected by 6:26 AM, quite likely through the application of the following SQL statement:

ALTER USER MYUSER ACCOUNT UNLOCK;

If you tried executing the above query, you might have noticed that the query execution required a bit of time.  Enterprise Manager also, apparently, executes a somewhat similar SQL statement every 30 minutes.  You can learn more about the potential performance impact of Enterprise Manager’s use of SYS.DBA_AUDIT_SESSION here.

I again started thinking about how to measure how much more efficient something is when compared to something that is never performed… I suppose that it is important to first determine whether or not the task at hand is important before deciding if not doing something is infinitely more efficient or infinitely less efficient than would be the case if the task at hand were completed.





Monitoring Changes to Table Data

22 03 2012

March 22, 2012

Suppose that you receive a request stating that a particular table in one of your databases must be monitored for changes.  One such table might be the one that lists the ERP system’s suppliers and their addresses – you would not want someone to be able to set up a legitimate supplier, and later have the billing remit to name and address changed without being detected.

What approach would you take to solve the above problem?  A question similar to the above arrived recently in an ERP mailing list email – the original poster (OP) is using a SQL Server RDBMS, so that might change the proposed solution just a bit.

Here is the “How simple is too simple?” suggestion that I offered:

Periodically, create a VENDOR_SAVE table (drop it if it already exists, or delete all rows and re-insert from the original source table):

CREATE TABLE VENDOR_SAVE AS
SELECT
  *
FROM
  VENDOR;

Now, just wait a while.

The question then becomes, how do we detect:

  • A new row (record) added to the original source (VENDOR) table.
  • An old row (record) deleted from the original source (VENDOR) table.
  • A change to any column (program field) in the original source (VENDOR) table since the last time the VENDOR_SAVE table was created/refreshed.

Let’s start with the first two bullet points.  I will write the SQL statements so that the statements should work with Oracle Database 9.0.1 and above, and SQL Server with very few changes, even if I feel a bit ANSI about doing so.  I will use the COALESCE function, rather than the NVL function, and CASE syntax rather than the equivalent DECODE syntax.

To identify cases where a row has appeared in, or disappeared from the original source (VENDOR) table, we can simply perform a full outer join between the original source table and the historical mirror image of the original table (VENDOR_SAVE).  We are only interested in cases where the primary key column (ID) is found in exactly one of the two tables:

SELECT
  COALESCE(V.ID,V2.ID) AS ID,
  COALESCE(V.NAME,V2.NAME) AS NAME,
  COALESCE(V.ADDR_1,V2.ADDR_1) AS ADDR_1,
  CASE WHEN V.ID IS NULL THEN 'VENDOR ADDED' ELSE 'VENDOR DELETED' END AS PROBLEM
FROM
  VENDOR V
FULL OUTER JOIN
  VENDOR_SAVE V2
ON (V.ID=V2.ID)
WHERE
  V.ID IS NULL
  OR V2.ID IS NULL;

So, the above SQL statement satisfies the first two bullet points.  The third bullet point is a little more challenging to accomplish… unless of course we employ UNION labor.  If we have two row sources with identical columns, and UNION the row sources together, the resulting row source will be absent of any entirely duplicated rows from the two original row sources (two rows will be reduced to a single row).  If there were no changes to any of the column values (or if the row was added to or deleted from the original source table), there will be a single row for the primary key column value.  If any columns were changed, there will be two rows containing the primary key column value.

Let’s build a SQL statement that UNIONs the rows from the two tables together, and counts the number of rows for each primary key value:

SELECT
  COUNT(*) OVER (PARTITION BY VL.ID) AS CNT,
  VL.ID,
  VL.NAME,
  VL.ADDR_1
FROM
  (SELECT
    *
  FROM
    VENDOR
  UNION
  SELECT
    *
  FROM
    VENDOR_SAVE) VL;

To complete the requirement for bullet point 3 above, we need to eliminate all rows from the result set where there is a single row for the primary key value:

SELECT DISTINCT
  VL2.ID,
  VL2.NAME,
  VL2.ADDR_1,
  'VALUE CHANGE' PROBLEM
FROM
  (SELECT
    COUNT(*) OVER (PARTITION BY VL.ID) AS CNT,
    VL.ID,
    VL.NAME,
    VL.ADDR_1
  FROM
    (SELECT
      *
    FROM
      VENDOR
    UNION
    SELECT
      *
    FROM
      VENDOR_SAVE) VL) VL2
WHERE
  VL2.CNT>1;

As a final step, we should join the two resultsets into a single resultset using UNION ALL:

SELECT
  COALESCE(V.ID,V2.ID) AS ID,
  COALESCE(V.NAME,V2.NAME) AS NAME,
  COALESCE(V.ADDR_1,V2.ADDR_1) AS ADDR_1,
  CASE WHEN V.ID IS NULL THEN 'VENDOR ADDED' ELSE 'VENDOR DELETED' END AS PROBLEM
FROM
  VENDOR V
FULL OUTER JOIN
  VENDOR_SAVE V2
ON (V.ID=V2.ID)
WHERE
  V.ID IS NULL
  OR V2.ID IS NULL
UNION ALL
SELECT DISTINCT
  VL2.ID,
  VL2.NAME,
  VL2.ADDR_1,
  'VALUE CHANGE' PROBLEM
FROM
  (SELECT
    COUNT(*) OVER (PARTITION BY VL.ID) AS CNT,
    VL.ID,
    VL.NAME,
    VL.ADDR_1
  FROM
    (SELECT
      *
    FROM
      VENDOR
    UNION
    SELECT
      *
    FROM
      VENDOR_SAVE) VL) VL2
WHERE
  VL2.CNT>1
ORDER BY
  ID;

While somewhat limited in usefulness, the above approach will indicate which rows in the original source table should be examined because the column values in those rows changed (or were added or deleted).

Another, potentially more useful approach involves setting up a logging trigger and logging table.  I previously shared a VBS script that helps to automate and standardize the process of creating the logging trigger and logging table.  A very similar feature is built into my Hyper-Extended Oracle Performance Monitor program – but, much like the VBS script, this solution is useless for the OP who uses a SQL Server backend.

What are the other options?  Oracle Database’s built-in auditing capabilities.  Auditing built into the ERP system (this particular ERP system writes all audit/change records to a single table that uses a VARCHAR2 column to capture the before/after images of the values stored in columns).  Any other options?  (The mess that someone can create with a bit of idle time on their hands…)





Tables and Their Indexes Should be Located on Different Disks – What is Wrong with this Quote?

17 02 2012

February 17, 2012

As I mentioned in a previous blog article, I placed an order for the book “Oracle Database 11gR2 Performance Tuning Cookbook“, mostly because I was curious how the book would compare with the “Oracle Database 11g Performance Tuning Recipes” book (my review of that book was a total of about 35 typewritten pages in length), and some of the other Oracle performance related books that I have reviewed.

After placing my order for the book, I took a quick look at a couple of the book’s preview pages on Amazon, downloaded the sample chapter from the book publisher – chapter 10 “Tuning I/O”, and spent a bit of time reading the sample chapter (making comments in the margins of the printed pages).  I circled the following paragraph (sorry for the long quote – I want to make certain that the context of the quote is not lost), found on page 422 of the book (page 17 in the PDF download):

“We can also distribute tables and related indexes on different disks, to obtain performance gain in both read and write operations. If we have tables and indexes on the same disk, we need to read and write in two different places on the same disk. By dividing the work between two disks, we can perform an index range scan faster than when the index and the table are on the same disk.”

What, if anything, is wrong with the above quote from the book?  For some reason, the acronym MASE came to mind when I read the above paragraph. 

The point of blog articles like this one is not to insult authors who have spent thousands of hours carefully constructing an accurate and helpful book, but instead to suggest that readers investigate when something stated does not exactly match what one believes to be true.  It could be that the author “took a long walk down a short pier”, or that the author is revealing accurate information which simply cannot be found through other resources (and may in the process be directly contradicting information sources you have used in the past).  If you do not investigate in such cases, you may lose an important opportunity to learn something that could prove to be extremely valuable.





SESSIONS Derived Value Formula – Doc Bug Explains

8 02 2012

February 8, 2012

Default parameter values are great, as long as it is possible to predict the default values, and the defaults are appropriate for the environment in which the defaults are present.  It is sometimes a challenge to remember all of the rules, and exceptions to those rules, that determine the defaults. I had a vague recollection of how the value of the SESSIONS parameter value is derived from the value of the PROCESSES parameter value.  An Oracle Database 11.2.0.2 question recently arrived in my email box from an ERP mailing list.  The original poster (OP) showed the following output in the email:

SQL> show parameter sessions

NAME                                 TYPE        VALUE
------------------------------------ ----------- -----
sessions                             integer     624

SQL> show parameter processes

NAME                                 TYPE        VALUE
------------------------------------ ----------- -----
processes                            integer     400 

At first glance, I thought that the OP made a mistake with the manual specification of the SESSIONS parameter value when taking into consideration the current value of the PROCESSES parameter value.

A Google search found a couple of helpful discussion threads that seemed to provide a formula that showed how the default value for the SESSIONS parameter is derived.  I decided to also perform a Google search of the Oracle documentation (trying to avoid circular references).   The same formula found in the helpful discussion threads is also included in the documentation, so that lends a bit of credibility to the information.  Let’s take a look at the Oracle Database 11.2 documentation for the SESSIONS parameter:

Default Value: Derived: (1.1 * PROCESSES) + 5

“… You should always set this parameter explicitly to a value equivalent to your estimate of the maximum number of concurrent users, plus the number of background processes, plus approximately 10% for recursive sessions.

Oracle uses the default value of this parameter as its minimum. Values between 1 and the default do not trigger errors, but Oracle ignores them and uses the default instead.”

A second page from the documentation library included additional information about the PROCESSES parameter:

“Oracle uses the default value of this parameter as its minimum. Values between 1 and the default do not trigger errors, but Oracle ignores them and uses the default instead…”

If you plan on running 50 user processes, a good estimate would be to set the PROCESSES initialization parameter to 70.”

So, let’s take another look at the PROCESSES value specified by the OP, keeping in mind the information from the documentation.  The OP has a database instance with a PROCESSES value of 400, and with the insight provided by the first documentation quote, that would suggest that the SESSIONS parameter would have been autoset to a value of (1.1 * 400) + 5 = 445.  That formula result coupled with the first paragraph of the second quote might lead someone to believe that the OP manually set the SESSIONS value to 624 – there could be a good reason for doing so.  The second paragraph in the second quote from the documentation suggests that OP’s PROCESSES value would allow about (400 – (70 – 50)) =  380 user processes  (each session will require 1 dedicated process, so that value would permit about 380 user sessions).

In an earlier blog article we saw that the auto-tuned value of the DB_FILE_MULTIBLOCK_READ_COUNT parameter is dependent, in part, on the value of the SESSIONS parameter and the size of the SGA.  In another blog article we found that the maximum number of blocks read by serial direct path read is the greatest power of 2 that is equal to or less than the value of the DB_FILE_MULTIBLOCK_READ_COUNT parameter.  Various other items are also affected by the SESSIONS parameter value, so setting the value to too high of a value has few rewards.

So, did the OP make a mistake when setting the SESSIONS parameter value?  I took a look at a test 11.2.0.2 database instance where I had set the PROCESSES parameter to a value of 150 and left the SESSIONS parameter unset.  The SESSIONS parameter value in the 11.2.0.2 database instance showed a value of 248 when I opened the database and executed:

SHOW PARAMETER SESSIONS

Something a bit stange is happening.  Oracle Database 10.2 seemed to respect the 11.2 documentation’s formula for the auto-calculation of the SESSIONS parameter, but Oracle Database 11.2.0.2 seems to use a different formula.  It was late at night when I posted my reply, so I guessed that the formula was about (1.52 * PROCESSES) + 20 (it was too late at night for thinking in terms of basic algebra, so I just picked a set of numbers that worked with my test PROCESSES and SESSIONS parameter values).

Since responding to the email, I took a sampling of a couple of 11.2.0.2 database instances, and summarized those findings below, including the actual derived SESSIONS value and the calculated value using the formula from the documentation:

PROCESSES SESSIONS
(Actual Derived)
SESSIONS
(Documentation Derived)
330 520 368
150 248 170
400 624 445
60 112 71
80 144 93

The actual numbers don’t quite match what the documentation suggests.

Time for a little basic algebra.  The formula from the documentation could be represented as:

(x * PROCESSES) + y = SESSIONS

If the structure of the above formula is still correct, just with unknown values for x and y, we will need at least two sets of equations to determine the value of the x and y variables.  To find the x and y variable values, we will use the known PROCESSES and actual derived SESSIONS values from first two rows of the above table:

(x * 330) + y = 520
(x * 150) + y = 248

Solving for y in the first equation:

y = 520 - (x * 330)
y = 520 - 330x

Substituting the above value of y into the second equation to solve for x:

(x * 150) + (520 - 330x) = 248
150x + 520 - 330x = 248
-180x = -272
x = 272/180
x = 1.51111111

Plug the value for x into the above equation for y:

y = 520 - 330x
y = 520 - 330*(1.51111111)
y = 21.3333337

So, based on the values from the first two rows from the above table, in Oracle Database 11.2.0.2:

SESSIONS = (1.51111111 * PROCESSES) + 21.3333337

The above formula works for the first, second, and fourth rows in the above table, but the formula is a bit off for the remaining two rows:

PROCESSES SESSIONS
(Actual Derived)
SESSIONS
(Documentation Derived)
   Formula 1
330 520 368   520
150 248 170   248
400 624 445   625.77778
60 112 71   112
80 144 93   142.22222

Let’s try solving the formula again using the values from the two rows that did not agree with the new formula for the derived SESSIONS parameter value:

(x * 400) + y = 624
(x * 80) + y = 144

Solving for y in the first equation:

y = 624 - (x * 400)
y = 624 - 400x

Substituting the above value of y into the second equation to solve for x:

(x * 80) + (624 - 400x) = 144
80x - 400x + 624 = 144
-320x = -480
x = 480/320
x = 1.5

Plug the value for x into the above equation for y:

y = 624 - 400 * 1.5
y = 624 - 600
y = 24

The above result leads to the following formula:

SESSIONS = (1.5 * PROCESSES) + 24

Let’s take a look at the values generated by the two formulas side-by-side with the actual derived SESSIONS values:

PROCESSES SESSIONS
(Actual Derived)
SESSIONS
(Documentation Derived)
  Formula 1 Formula 2
330 520 368   520 519
150 248 170   248 249
400 624 445   625.77778 624
60 112 71   112 114
80 144 93   142.22222 144

Interesting results… Doc Bug?  Why three formulas (plus the guess that I wrote in the email)?  No wonder it is sometimes difficult to remember the default derived values for parameters.

What about this suggestion from the documentation:

“If you plan on running 50 user processes, a good estimate would be to set the PROCESSES initialization parameter to 70.”

That suggestion might also be out of date.  From a generic test 11.2.0.2 Standard Edition database instance running on Windows:

SELECT
  COUNT(*)
FROM
  V$SESSION
WHERE
  USERNAME IS NULL;

COUNT(*)
--------
      27

SELECT
  PROGRAM
FROM
  V$SESSION
WHERE
  USERNAME IS NULL
ORDER BY
  PROGRAM;

PROGRAM
-----------------
ORACLE.EXE (ARC0)
ORACLE.EXE (ARC1)
ORACLE.EXE (ARC2)
ORACLE.EXE (ARC3)
ORACLE.EXE (CJQ0)
ORACLE.EXE (CKPT)
ORACLE.EXE (DBRM)
ORACLE.EXE (DBW0)
ORACLE.EXE (DIA0)
ORACLE.EXE (DIAG)
ORACLE.EXE (GEN0)
ORACLE.EXE (J000)
ORACLE.EXE (J001)
ORACLE.EXE (LGWR)
ORACLE.EXE (MMAN)
ORACLE.EXE (MMNL)
ORACLE.EXE (MMON)
ORACLE.EXE (PMON)
ORACLE.EXE (PSP0)
ORACLE.EXE (Q001)
ORACLE.EXE (Q002)
ORACLE.EXE (QMNC)
ORACLE.EXE (RECO)
ORACLE.EXE (SMCO)
ORACLE.EXE (SMON)
ORACLE.EXE (VKTM)
ORACLE.EXE (W000) 

Interesting results… Doc Bug?  So this generic Standard Edition database has 27 background processes.  Maybe this page in the documentation needs a little work also?  Ah, Doc Bug explains it.





The Transforming Face of the Oracle Support Site

23 12 2011

December 23, 2011

A day or two ago I saw an announcement that the HTML (non-Flash) version of the Oracle Support site was to be phased out in January 2012.  It seems like the last time I tried to use that site, the search functionality did not quite work for Oracle Database products; I gave up on the HTML version of the site and went back to the Flash-based version of the site. 

The performance of the Flash-based version of Metalink (I usually navigate to the site by entering metalink.oracle.com into the web browser’s address bar) My Oracle Support has improved significantly since the initial launch, and it appears that once the website is loaded, it is a bit more stable now.  I do not own any i products (iPhone, iPad, iToy) which do not support Flash, so the Flash-based version of the Oracle support site works OK on most of my devices (Windows 7 64 bit with IE 9, Windows 7 32 bit with IE 8, Windows XP 32 bit, Motorola Xoom, Amazon BlackBerry Playbook, etc.) as long as Flash is supported in the web browser.  Now the shocker, the Flash-based version of the support site is also planned to be phased out, based on Metalink (MOS) Doc ID 1385682.1.

Turning the other cheek, or doing an about-face?  The support document mentions that ADF Faces will be used – the site will be built using Oracle Application Development Framework.  I hate to say that this is a case of Oracle eating its own dog food – maybe there is a better way to state that the support site will be using their own technology rather than the technology of a third party?  I wonder if the Oracle OTN forums are also being redesigned to use Oracle technology, rather than that of a third party?  On a related note, it appears that the OTN forum site has fixed the Internal Server Error problem.

Anyone found any additional information about the change to the support site?  Any experience with ADF Faces?





What Could Go Wrong? Testing the DB_FILE_MULTIBLOCK_READ_COUNT Parameter

14 10 2011

October 14, 2011 (Modified October 15, 2011)

When reading various Oracle Database books, I often perform mental exercises related to the book’s contents, asking “what could go wrong?”   That is probably why some of my book reviews have extended to record setting lengths… who knew that Amazon imposed a limit on book review lengths…

I recently started re-reading the “Troubleshooting Oracle Performance” book after buying a PDF copy of the book.  As previously mentioned, the ultimate reason for re-reading the book is so that I may compose a detailed book review, just as I have done for most of the Oracle Database related books that I have read in the past couple of years.  So far, I have had few opportunities to ask “what could go wrong” – until of course I made it to page 178 during the second read-through of the book.  That page includes a PL/SQL block that tests the performance effects of modifying the DB_FILE_MULTIBLOCK_READ_COUNT parameter from a value of 1 to 32, increasing the value by 1 for each pass through the loop in the PL/SQL block.  What could go wrong?

Let’s build a sample table with 11,000,000 rows:

DROP TABLE T1 PURGE;

CREATE TABLE T1(
  C1 NUMBER,
  C2 NUMBER,
  C3 NUMBER,
  C4 DATE,
  C5 DATE,
  C6 DATE,
  C7 VARCHAR2(20),
  C8 VARCHAR2(20),
  C9 VARCHAR2(20));

INSERT INTO
  T1
SELECT
  ROWNUM,
  DECODE(MOD(ROWNUM,5),0,NULL,ROWNUM),
  DECODE(MOD(ROWNUM,5),0,NULL,ROWNUM),
  TRUNC(SYSDATE)+TRUNC(ROWNUM/100),
  DECODE(MOD(ROWNUM,5),0,NULL,TRUNC(SYSDATE)+TRUNC(ROWNUM/100)),
  DECODE(MOD(ROWNUM,5),0,NULL,TRUNC(SYSDATE)+TRUNC(ROWNUM/100)),
  RPAD(CHR(MOD(ROWNUM-1,26)+65)||
    CHR(MOD(ROWNUM,26)+65)||
    CHR(MOD(ROWNUM+1,26)+65)||
    CHR(MOD(ROWNUM+2,26)+65),20,'A'),
  DECODE(MOD(ROWNUM,5),0,NULL,
   RPAD(CHR(MOD(ROWNUM-1,26)+65)||
    CHR(MOD(ROWNUM,26)+65)||
    CHR(MOD(ROWNUM+1,26)+65)||
    CHR(MOD(ROWNUM+2,26)+65),20,'A')),
  DECODE(MOD(ROWNUM,5),0,NULL,
   RPAD(CHR(MOD(ROWNUM-1,26)+65)||
    CHR(MOD(ROWNUM,26)+65)||
    CHR(MOD(ROWNUM+1,26)+65)||
    CHR(MOD(ROWNUM+2,26)+65),20,'A'))
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

INSERT INTO
  T1
SELECT
  T1.*
FROM
  T1,
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=10);

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',ESTIMATE_PERCENT=>NULL)

The above script might take a minute or two to complete.  Let’s take a look at the extent sizes for table T1:

SELECT
  SEGMENT_NAME SEGMENT,
  COUNT(*) EXTENTS,
  BYTES/1024 EXT_SIZE_KB,
  (COUNT(*) * BYTES)/1048576 TOTAL_MB
FROM
  DBA_EXTENTS
WHERE
  OWNER=USER
  AND SEGMENT_NAME IN ('T1')
GROUP BY
  SEGMENT_NAME,
  BYTES
ORDER BY
  SEGMENT_NAME,
  BYTES;

SEGMENT    EXTENTS EXT_SIZE_KB   TOTAL_MB
------- ---------- ----------- ----------
T1              16          64          1
T1              63        1024         63
T1             120        8192        960
T1               2       65536        128

Now let’s try a slightly modified version of the script that appears in the book:

SET SERVEROUTPUT ON
SET TIMING ON

DECLARE
  L_COUNT PLS_INTEGER;
  L_TIME PLS_INTEGER;
  L_STARTING_TIME PLS_INTEGER;
  L_ENDING_TIME PLS_INTEGER;
BEGIN
  DBMS_OUTPUT.PUT_LINE('DBFMBRC SECONDS');
  FOR L_DBFMBRC IN 1..128
  LOOP
    EXECUTE IMMEDIATE 'ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT='||L_DBFMBRC;
    L_STARTING_TIME := DBMS_UTILITY.GET_TIME();
    SELECT /*+ FULL(T) */ COUNT(*) INTO L_COUNT FROM T1 T;
    L_ENDING_TIME := DBMS_UTILITY.GET_TIME();
    L_TIME := ROUND((L_ENDING_TIME-L_STARTING_TIME)/100);
    DBMS_OUTPUT.PUT_LINE(L_DBFMBRC||' '||L_TIME);
  END LOOP;
END;
/

The output that I received when tested on Oracle Database 11.2.0.2 follows:

DBFMBRC SECONDS
1 0
2 0
3 0
4 0
5 0
6 0
7 0
8 0
9 0
10 0
11 0
12 0
13 0
14 0
15 0
16 0
17 0
18 0
19 0
20 0
21 0
22 0
23 0
24 0
25 0
26 0
27 0
28 0
29 0
30 0
31 0
32 0
33 0
34 0
35 0
36 0
37 0
38 0
39 0
40 0
41 0
42 0
43 0
44 0
45 0
46 0
47 0
48 0
49 0
50 0
51 0
52 0
53 0
54 0
55 0
56 0
57 0
58 0
59 0
60 0
61 0
62 0
63 0
64 0
65 0
66 0
67 0
68 0
69 0
70 0
71 0
72 0
73 0
74 0
75 0
76 0
77 0
78 0
79 0
80 0
81 0
82 0
83 0
84 0
85 0
86 0
87 0
88 0
89 0
90 0
91 0
92 0
93 0
94 0
95 0
96 0
97 0
98 0
99 0
100 0
101 0
102 0
103 0
104 0
105 0
106 0
107 0
108 0
109 0
110 0
111 0
112 0
113 0
114 0
115 0
116 0
117 0
118 0
119 0
120 0
121 0
122 0
123 0
124 0
125 0
126 0
127 0
128 0

PL/SQL procedure successfully completed.

What Could Go Wrong?  (I had two or three answers for this question as I was reading the script, but I have a couple more after a bit of experimentation.  Think about what might go wrong without looking in the book.)

Added October 15, 2011:

The “Troubleshooting Oracle Performance” book, to my knowledge, was the first performance tuning book to address Oracle Database 11.1, and this book was released shortly after the release of Oracle Database 11.1.0.6.  While it was not widely known at the time (I do not think that it was documented), Oracle Database 11.1.0.6 might employ serial direct path reads (directly into the PGA) rather than db file scattered reads (into the buffer cache) when performing a full table scan.  Based on an experiment, the DB_FILE_MULTIBLOCK_READ_COUNT parameter influences the maximum number of blocks read in a single direct path read request; the maximum number of blocks read by direct path read appears to be the greatest power of two that is equal to or less than the value of the the DB_FILE_MULTIBLOCK_READ_COUNT parameter.  The paragraphs that follow this test case in the book suggest that a parallel full table scan should not be utilized – that implies that the book author is aware that direct path reads might distort the outcome of the test case.  This was the first thought that I had when viewing this test case when re-reading the book.

The effects of the table blocks that are already buffered in the buffer cache is also a potential area where this test case might see distorted results (the paragraphs that follow this test case in the book address this issue).  The test table is roughly 1,152MB in size (minus the blocks that are above the high water mark, of course), so how likely is it that some of the table blocks might be cached in the buffer cache either before the first execution of the SELECT from the table T1, or between executions of the SELECT from T1?  Does the answer depend on what was performed prior to the test case – how full is the buffer cache with unrelated blocks?  What is possibly interesting is that in my test case, all of the blocks belonging to the entire table were buffered in the buffer cache prior to the start of the PL/SQL block in the test case.  Without the timing information displayed by SET TIMING ON, it is difficult to determine if the DBMS_UTILITY.GET_TIME function simply is not supported on the operating system platform used for the test, or if as Timur stated in the comments section, the full table scans were completing so quickly that the timing of the individual runs was being rounded to 0 seconds.  I was careful not to include the output of the SQL*Plus timing during the initial posting of the blog article.  I obtained the following times from repeated PL/SQL executions:

Elapsed: 00:00:39.37

Elapsed: 00:00:37.05

Elapsed: 00:00:37.14

With a 10046 trace enabled, the execution time climbed sharply:

...
125 1
126 1
127 1
128 1

PL/SQL procedure successfully completed.

Elapsed: 00:01:40.16

The potential buffering of some or all of the table blocks was the second thought that I had while reading the test case during the re-read of the book.  The paragraph in the book that followed the test case addressed the potential problems of the table blocks being cached in the buffer cache, the operating system cache, a SAN cache, or a similar cache.  As previously mentioned, Oracle Database 11.1.0.6 and later are able to perform serial direct path reads, where previous Oracle Database versions would have used db file scattered reads, so the Oracle Database version is potentially important.  The book previously mentioned on page 175 three items that might cause fewer blocks to be read than what is specified by the DB_FILE_MULTIBLOCK_READ_COUNT parameter – those items might impact the results of the test, if the test table is not representative of the other objects in the database that might be read by a db file scattered read.

While reading the test case, another thought raced through my mind: why is the author experimenting with the DB_FILE_MULTIBLOCK_READ_COUNT parameter – just leave it unset and make certain that system statistics are collected so that the MBRC system statistic is used (I believe that this is related to Mohamed’s second point in the comments section).  Since the release of Oracle Database 10.2.0.1 it is possible to leave that parameter unset (and a bug was fixed in 10.2.0.4 that then allowed the parameter to be set to 0 which then had the same effect as leaving it unset).  That is the point that Mohamed made in the comments section.  The book author covered the possibility of leaving the DB_FILE_MULTIBLOCK_READ_COUNT parameter unset in the paragraphs that followed the test case, and since this book attempts to help with performance problems in Oracle 9.0.1 and later, it probably is a good idea that the test case was included to benefit those who had not yet transitioned all of the databases to Oracle Database 10.2 or later.

Result caching, mentioned by Steve Catmull in the comments section, is not something that I had considered while reading the test case.  If I remember correctly, when the RESULT_CACHE_MODE parameter is set to FORCE, the result cache could distort the results of the test case.

I thought that I would include a couple of more test cases on 11.2.0.2.
With an unset DB_FILE_MULTIBLOCK_READ_COUNT and the following script:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

A variety of “direct path read” wait events appear in the resulting trace file.  Two typical wait events found in the trace file follow:

WAIT #362523544: nam='direct path read' ela= 2280 file number=4 first dba=3951616 block cnt=128 obj#=71407 tim=366050651386
WAIT #362523544: nam='direct path read' ela= 2323 file number=4 first dba=3951744 block cnt=128 obj#=71407 tim=366050654201

The above shows the types of wait events that I expected to have when I read the PL/SQL block.

Let’s try again with a specified value for DB_FILE_MULTIBLOCK_READ_COUNT:

ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=20;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

A variety of “direct path read” wait events appear in the resulting trace file.  Two typical wait events found in the trace file follow:

WAIT #362523544: nam='direct path read' ela= 272 file number=4 first dba=4061184 block cnt=16 obj#=71407 tim=366357357469
WAIT #362523544: nam='direct path read' ela= 372 file number=4 first dba=4061216 block cnt=16 obj#=71407 tim=366357357889

In the above, note that the direct path read wait did not entirely adhere to the value for the modified DB_FILE_MULTIBLOCK_READ_COUNT, the actual number of blocks was rounded down to the next lower power of 2.

Let’s try again with another value for the DB_FILE_MULTIBLOCK_READ_COUNT parameter:

ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=100;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

A variety of “direct path read” wait events appear in the resulting trace file.  Two typical wait events found in the trace file follow:

WAIT #362523544: nam='direct path read' ela= 1206 file number=4 first dba=4050624 block cnt=64 obj#=71407 tim=366563051144
WAIT #362523544: nam='direct path read' ela= 1144 file number=4 first dba=4050688 block cnt=64 obj#=71407 tim=366563052537

In the above, note that the direct path read wait did not entirely adhere to the value for the modified DB_FILE_MULTIBLOCK_READ_COUNT, the actual number of blocks was rounded down to the next lower power of 2.

Let’s try again with another value for the DB_FILE_MULTIBLOCK_READ_COUNT parameter:

ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=120;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

A variety of “direct path read” wait events appear in the resulting trace file.  Two typical wait events found in the trace file follow:

WAIT #362523544: nam='direct path read' ela= 1183 file number=4 first dba=4047232 block cnt=64 obj#=71407 tim=366628708554
WAIT #362523544: nam='direct path read' ela= 1280 file number=4 first dba=4047296 block cnt=64 obj#=71407 tim=366628710113

Just for verification:

ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=128;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

Wait events:

WAIT #362523544: nam='direct path read' ela= 2505 file number=4 first dba=4050560 block cnt=128 obj#=71407 tim=366681412987
WAIT #362523544: nam='direct path read' ela= 2259 file number=4 first dba=4050688 block cnt=128 obj#=71407 tim=366681415722

The above again shows that the number of blocks read by direct path read are rounded down to the nearest power of two.

OK, let’s try the initial test again:

DISCONNECT ALL;
CONNECT ...

Instead of using a PL/SQL block, let’s use regular SQL statements:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',ESTIMATE_PERCENT=>100)

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

The results, “direct path read” wait events for both of the selects from table T1:

...
WAIT #357271008: nam='direct path read' ela= 2774 file number=4 first dba=3930496 block cnt=128 obj#=71407 tim=371288846837
WAIT #357271008: nam='direct path read' ela= 2353 file number=4 first dba=3930624 block cnt=128 obj#=71407 tim=371288849736
...
WAIT #357239640: nam='direct path read' ela= 2749 file number=4 first dba=3935360 block cnt=128 obj#=71407 tim=371292356287
WAIT #357239640: nam='direct path read' ela= 2580 file number=4 first dba=3935488 block cnt=128 obj#=71407 tim=371292359340
...

Other testing showed that if the buffer cache was flushed after creating and populating the table, but before collecting statistics, Oracle Database 11.2.0.2 performed serial direct path reads to read the table blocks, rather than reading those blocks into the buffer cache using db file scattered reads.





Having Fun with ORA-00600 (qkebCreateConstantOpn1) – What is the Cause of this Error?

28 09 2011

September 28, 2011

A friend brought an interesting Oracle Database 11.2.0.2 problem to my attention. He is in the process of upgrading to a new Oracle Database server (and Oracle Database version) and a new version of an ERP package. He has experienced an ORA-00600 error with both patch 6 and patch 9 for 11.2.0.2 on 64 bit Windows after rolling forward the database table definitions for the new version of the ERP package and then testing the ERP functionality (all in a test environment, of course).

I have not seen the most recent table modification scripts first hand, but upgrade scripts for the earlier ERP versions exercised good habits of declaring column constraints and default column values (as well as triggers to make certain that SQL script writers do not get too carried away).

So, what to do to troubleshoot this problem, call Oracle support because an ORA-00600 error is returned, or poke around a little to see if we can determine what is happening? Since I am not able to touch the database to investigate the problem freely, I asked for a 10046 trace at level 12 to be generated. Below is a portion of that trace file (the portion in bold was actually executed by the client application, while the rest is at dep=1, in this case internal SQL used for query optimization):

PARSING IN CURSOR #386947304 len=42 dep=1 uid=0 oct=3 lid=0 tim=63747639340 hv=844002283 ad='314cbd908' sqlid='ftj9uawt4wwzb'
select condition from cdef$ where rowid=:1
END OF STMT
PARSE #386947304:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63747639340
BINDS #386947304:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1c28c668  bln=16  avl=16  flg=05
  value=0000A680.003D.0001
EXEC #386947304:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63747639412
FETCH #386947304:c=0,e=8,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1884964958,tim=63747639432
STAT #386947304 id=1 cnt=1 pid=0 pos=1 obj=31 op='TABLE ACCESS BY USER ROWID CDEF$ (cr=1 pr=0 pw=0 time=4 us cost=1 size=15 card=1)'
CLOSE #386947304:c=0,e=21,dep=1,type=0,tim=63747639466
...
...
...
PARSING IN CURSOR #386943464 len=58 dep=0 uid=36 oct=6 lid=36 tim=63750497441 hv=1532843717 ad='3144ac3d8' sqlid='9m0sbg1dpupq5' 
update PART set mrp_required = :1     where id = :2       
END OF STMT 
PARSE #386943464:c=0,e=121,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=63750497440 
PARSE #386947304:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750497602
BINDS #386947304:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1edffbd8  bln=16  avl=16  flg=05
  value=0000A7B3.0019.0001
EXEC #386947304:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750497664
FETCH #386947304:c=0,e=9,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1884964958,tim=63750497684
CLOSE #386947304:c=0,e=8,dep=1,type=3,tim=63750497704
=====================
PARSING IN CURSOR #517995552 len=98 dep=1 uid=0 oct=3 lid=0 tim=63750497798 hv=3044436590 ad='2f0e99070' sqlid='dha5nv6urcumf'
select binaryDefVal,           lengthb(binaryDefVal) from ecol$ where tabobj# = :1 and colnum = :2
END OF STMT
PARSE #517995552:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3081038021,tim=63750497797
BINDS #517995552:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=0001 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=1edfe758  bln=22  avl=04  flg=05
  value=18450
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=0001 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=1edfe770  bln=22  avl=03  flg=01
  value=141
EXEC #517995552:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3081038021,tim=63750497891
FETCH #517995552:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3081038021,tim=63750497913
STAT #517995552 id=1 cnt=1 pid=0 pos=1 obj=123 op='TABLE ACCESS BY INDEX ROWID ECOL$ (cr=2 pr=0 pw=0 time=11 us cost=2 size=95 card=1)'
STAT #517995552 id=2 cnt=1 pid=1 pos=1 obj=126 op='INDEX RANGE SCAN ECOL_IX1 (cr=1 pr=0 pw=0 time=8 us cost=1 size=0 card=1)'
CLOSE #517995552:c=0,e=1,dep=1,type=3,tim=63750497955
PARSE #386947304:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750498060
BINDS #386947304:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1edfe360  bln=16  avl=16  flg=05
  value=0000A7B3.0019.0001
EXEC #386947304:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750498120
FETCH #386947304:c=0,e=9,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1884964958,tim=63750498140
CLOSE #386947304:c=0,e=7,dep=1,type=3,tim=63750498159
Symbol file c:\Oracle\product\11.2.0\dbhome_1\BIN\orannzsbb11.SYM does not match binary.
 Symbol TimeStamp=4cea6d1b, Module TimeStamp=4d6f3707 are different
Incident 4193 created, dump file: C:\ORACLE\diag\rdbms\test\test\incident\incdir_4193\test_ora_3796_i4193.trc
ORA-00600: internal error code, arguments: [qkebCreateConstantOpn1], [], [], [], [], [], [], [], [], [], [], []

* BLOCK CHECKING IS NOT DONE-Call Heap not initialized.
* Skip checking block dba=0x2402d02.
* BLOCK CHECKING IS NOT DONE-Call Heap not initialized.
* Skip checking block dba=0x340660f.
WAIT #386943464: nam='SQL*Net break/reset to client' ela= 2 driver id=1413697536 break?=1 p3=0 obj#=17988 tim=63752354884
WAIT #386943464: nam='SQL*Net break/reset to client' ela= 469 driver id=1413697536 break?=0 p3=0 obj#=17988 tim=63752355367
WAIT #386943464: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=17988 tim=63752355385
WAIT #386943464: nam='SQL*Net message from client' ela= 7198 driver id=1413697536 #bytes=1 p3=0 obj#=17988 tim=63752362607
WAIT #0: nam='ADR file lock' ela= 3  =0  =0  =0 obj#=17988 tim=63752362675
WAIT #0: nam='ADR file lock' ela= 67  =0  =0  =0 obj#=17988 tim=63752362763
WAIT #0: nam='ADR block file read' ela= 146  =0  =0  =0 obj#=17988 tim=63752363029
WAIT #0: nam='ADR block file write' ela= 392  =0  =0  =0 obj#=17988 tim=63752363449
XCTEND rlbk=1, rd_only=0, tim=63752364013
WAIT #0: nam='log file sync' ela= 115 buffer#=1552 sync scn=251585418 p3=0 obj#=17988 tim=63752364516
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=17988 tim=63752364548

Interesting, maybe?  I ran a test in an older version of the ERP package, also using Oracle Database 11.2.0.2.  My test did not generate an ORA-00600 error, but I did notice something that was a bit interesting.  There was not a single SQL statement similar to the following in my trace file, while the SQL statement was found in the trace file that was sent to me:

select binaryDefVal, lengthb(binaryDefVal) from ecol$ where tabobj# = :1 and colnum = :2

ECOL$? Anything found by Google?  OK, two articles, I will briefly quote one of the articles for dramatic effect:

“11G introduced a fast=true feature for adding columns with default values. In 11G when you want to add a not null column with a default value, the operation completes in the blink of an eye (if there are no locks on the table of course). Now it does not have to update all the rows, it just keeps the information as meta-data in the dictionary. So adding a new column becomes just a few dictionary operations.”

I suspect that the ERP upgrade script might have added non-NULL columns with default values… so let’s take a tour through Metalink (MOS) to see if anything interesting is found:

  • Doc ID 1301504.1: “ORA-00600: internal error code, arguments: [qkebCreateConstantOpn1] ON UPDATES ON TABLES WITH CONSTRAINTS”
  • Bug 12316092: “ORA-600 [QKEBCREATECONSTANTOPN1] AFTER ADDING NOT NULL COLUMN WITH DEFAULT”
  • Bug 12760255: “ORA-00600 INTERNAL ERROR CODE, ARGUMENTS [QKEBCREATECONSTANTOPN1] ON SELECT STAT”
  • Doc ID 8501439.8, Bug 8501439:” OERI[kghfrh:ds] / [kghfrempty:ds] / [17147] ORA-7445 [memcpy] with ANALYZE in a table with added column”
  • Doc ID 1106553.1: “Wrong Result For Added Column After Table Creation in 11g”
  • Bug 11865621: “MERGE ON TABLE WITH COL ADDED WHEN _ADD_COL_OPTIM_ENABLED=TRUE SPINS ON CPU”
  • Bug 10261680: “QUERY RETURNING WRONG RESULT WITH PARALLEL ENABLED”
  • Doc ID 10080167.8, Bug 10080167: “ORA-600 [15599] / dump [kghalf] from TRIGGER with WHEN clause”

OK, so I located through Metalink a couple of potential problems that might be related to the problem that was brought to my attention, some of which might be fixed in Oracle Database 11.2.0.3 or 11.2 (the first two seem to directly pertain to this issue).  It appears that quite a few of the bugs are triggered by the optimization (the fast=true reference in the above quote) that was introduced in Oracle Database 11.1.

What might be the work-around for this particular problem (mostly rough guesses at this point – pick one):

  • Wait for the release of Oracle Database 11.2.0.3 on the Windows platform… or 12.1.
  • Execute “ALTER SYSTEM SET “_ADD_COL_OPTIM_ENABLED”=FALSE;” before running the scripts that add the additional columns to the tables.
  • After running the ERP upgrade scripts, export the database, drop the database, create a new blank database, and then import the exported file.

Any other options?

If you look at the trace file output above, you might have noticed the following line:

Symbol file c:\Oracle\product\11.2.0\dbhome_1\BIN\orannzsbb11.SYM does not match binary

I wonder if that message has any relevance to the problem? It is slightly interesting to find that Oracle Database 11.2.0.1 with patch 7 installed has a file by that name with a file date of April 8, 2011 (399KB in size) while 11.2.0.2 with patch 6 apparently has an older version with a file date of November 22, 2010 (395KB in size). Probably unrelated to the problem at hand, but still interesting that a more recent release offers an older version of a file. I wonder if that file date problem could be related (requires a My Oracle Support account):

Doc ID 1272490.1: “‘Symbol file oraclsra11.SYM does not match binary’ Reported In Trace File + ORA-600 / ORA-7445”








Follow

Get every new post delivered to your Inbox.

Join 174 other followers