True or False – Wait Events

31 03 2010

March 31, 2010

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

A continuation of the series of true or false quizzes for the week – maybe this one is too easy.  Today’s quiz is on the topic of wait events.   Assuming that the questions apply to a release of Oracle that has been available for up to five years, state why you believe that the answer to the question is true, or why you believe that the answer to the question is false.  Any answers that attempt to utilize logical fallacies will be scored as incorrect.

1. Assume that a database instance is being prepared for 1,500 to 2,000 sessions.  Given an unlimited budget, it is possible to configure the database instance to completely eliminate wait events.

2. Consider two identical Oracle databases with a single session connected to each database instance.  Each of the two sessions submits exactly the same SQL statement, with the first session experiencing no wait events while executing the query, and the second session experiencing nearly continuous I/O wait events.  The lack of wait events implies that the query execution for the first session is optimal, and should be the performance target for the second session.

3. Idle wait events are insignificant in performance tuning exercises, and should be ignored.

4. For every one minute of elapsed time, each CPU in the server is capable of accumulating 60 seconds of CPU wait time.

Did I mention that I dislike true/false type questions?  But then these are not simple true/false questions.





True or False – Improving Performance of SQL Statements

30 03 2010

March 30, 2010

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

A continuation of the concept of yesterday’s true or false quiz – this one is a little easier, with new reading material.  Today’s quiz is on the topic of improving performance of SQL statements.  The reading material:
Article 1
Article 2
Article 3

Article 4
Article 5
Article 6
Article 7
Article 8 (actually a book)
Article 9 (actually a book)
Article 10 (actually a book)
Article 11

Please read the above articles and see if you are able to answer the following true or false questions, assuming that the questions apply to a release of Oracle that has been available for up to five years.  State why you believe that the answer to the question is true, or why you believe that the answer to the question is false.  Any answers that attempt to utilize logical fallacies will be scored as incorrect.  (Most of these questions can be answered with the help of the first couple of links.)

1. Queries containing subqueries should be rewritten as a logical step in improving query performance.

2. Complex queries should be decomposed into multiple queries using global temp tables and/or WITH clauses as a step toward improving query performance.

3. Significant performance improvements, possibly 20 fold, are possible by replacing some or all of a SQL statement with PL/SQL.  If true, provide an example showing a significant performance improvement with such a replacement.  If not true, provide an example that shows that performance did not improve significantly.

4. There are cases were performance improvements are possible by modifying a SQL statement containing a three table equijoin, which accesses primary and foreign keys columns of the tables, into a SQL statement which accesses a single table with two PL/SQL functions (each containing a SELECT) in column positions.





True or False – Oracle Sorting

29 03 2010

March 29, 2010 (Updated April 6, 2010 with a test table)

(Forward to the Next Post in the Series)

I recently encountered a discussion thread (dbaforums.org/oracle/index.php?s=eacd9ff86b358b4a14ecd3fd7653a9fd&showtopic=19407) that pointed to a news article about the internals of Oracle sorting.  The news article (dba-oracle.com/t_oracle_sorting.htm) has a date of October 15, 2007, so it is probably reasonable to assume that the article describes the behavior of Oracle Database 10g R2, and possibly Oracle Database 11g R1.

Please read the news article and see if you are able to answer the following true or false questions.  State why you believe that the question is true, or why you believe that the question is false.  Any answers that attempt to utilize logical fallacies will be scored as incorrect.

1. Sequencing of database output first started in the 1960s.

2. One of the very important components of Oracle tuning is Oracle sorting, yet that process is often overlooked.

3. SSD is a synonym for a super-fast RAM disk.

4. Oracle Database always performs an automatic sorting operation when a GROUP BY clause is used in a SQL statement, when an index is created, and when an ORDER BY clause is used in a SQL statement.

5. The cheapest method is always used by Oracle Database when ordering a resultset.

6. A hinted execution plan involving a single table, with a /*+ index */ hint, will always retrieve the rows in the sorted order of the index.

7. If a SQL statement requires a single sort operation that completes in memory, that SQL statement will not use any space in the TEMP tablespace when the rows are retrieved – with the assumption that a hash join did not spill to disk.

8. The CPU_COST parameter causes Oracle Database to favor the pre-sorted ordering of an index over a discrete sorting operation.

9. The value of the SORT_AREA_SIZE parameter or the PGA_AGGREGATE_TARGET parameter if used, influences Oracle Database’s decision to prefer the pre-sorted ordering of an index over a discrete sorting operation.

10. The clustering factor of an index influences Oracle Database’s decision to prefer the pre-sorted ordering of an index over a discrete sorting operation.

11. The default database block size in use by the database influences Oracle Database’s decision to prefer the pre-sorted ordering of an index over a discrete sorting operation.

12. A sort operation will only spill to disk when RAM is exhausted.

13. “At the time a session is established with Oracle, a private sort area is allocated in memory for use by the session for sorting, based on the value of the sort_area_size initialization parameter.”  Supporting evidence:
http://books.google.com/books?id=gsFC1D1LmvQC&pg=PA306&lpg=PA306#v=onepage&q=&f=false
http://www.articles.freemegazone.com/oracle-sorting.php
oracle-training.cc/oracle_tips_sort_operations.htm

14. For sort intensive tasks it is not possible to adjust the amount of memory allocated to those tasks by adjusting the SORT_AREA_SIZE parameter at the session level.

15. The entire database can be slowed down due to a disk sort in the TEMP tablespace because sorts to disk are I/O intensive.

16. A good general rule is that the SORT_AREA_SIZE parameter should be adjusted to eliminate sorts to disk caused by GROUP BY operations.

17. Buffer pool blocks are allocated to hold or manage the blocks that are in the TEMP tablespace.

18. An optimal workarea execution, completed entirely in memory, is always preferred over a one-pass or multi-pass workarea execution.

19. Free buffer waits can be caused by excessive sorts to disk, which cause data blocks needed by other sessions to be paged out of the buffer.

20. One percent is an acceptable ratio of disk sorts to the total number of sorts.

21. When the PGA_AGGREGATE_TARGET parameter is specified, the total work area size cannot exceed 200MB.

22. No task may use more than 10MB for sorting.

23. A DBA should modify two hidden (underscore) parameters to permit up to 50MB of memory to be used for an in-memory sort operation for a SQL statement.

Have you ever read an article in an attempt to find the answer to a very specific question, only to find that by the time the end of the article is reached, you now have a whole new set of questions?  Try to answer the above questions using something beyond true or false – tell me why in detail it is true or why it is false.  Are there any other questions that could be asked about the article?

——-

Test table for question #10, added April 6, 2010:

CREATE TABLE T1 (
  C1 NUMBER,
  C2 NUMBER,
  C3 VARCHAR2(100),
  PRIMARY KEY (C1));

INSERT INTO T1
SELECT
  ROWNUM,
  DECODE(MOD(ROWNUM,100),0,NULL,ROWNUM),
  RPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

COMMIT;

ALTER TABLE T1 MODIFY (C2 NOT NULL);

CREATE INDEX IND_T1_C2 ON T1(C2);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)




Duplicates when Querying V$TEMPSEG_USAGE?

22 03 2010

March 22, 2010

If you search through the Oracle documentation, you will find the following in the Oracle Database 9.2 documentation:

V$SESSION is basically an information view used for finding the SID or SADDR of a user. However, it has some columns that change dynamically and are useful for examining a user. For example:

SQL_HASH_VALUE, SQL_ADDRESS: These identify the SQL statement currently being executed by the session. If NULL or 0, then the session is not executing any SQL statement. PREV_HASH_VALUE and PREV_ADDRESS identify the previous statement being executed by the session.

The Oracle Database 10.2 documentation includes the following:

Use the following query to determine, at a point in time, which sessions are waiting for I/O:

SELECT SQL_ADDRESS, SQL_HASH_VALUE
  FROM V$SESSION
 WHERE EVENT LIKE ‘db file%read';

Again in the Oracle Database 10.2 documentation:

SQL_ADDRESS: Used with SQL_HASH_VALUE to identify the SQL statement that is currently being executed
SQL_HASH_VALUE: Used with SQL_ADDRESS to identify the SQL statement that is currently being executed

The Oracle Database 11.2 documentation repeats what is found in the 10.2 documentation:

SQL_ADDRESS: Used with SQL_HASH_VALUE to identify the SQL statement that is currently being executed
SQL_HASH_VALUE: Used with SQL_ADDRESS to identify the SQL statement that is currently being executed

Why doesn’t the documentation for 10.2 and 11.2 suggest using the SQL_ID and SQL_CHILD_NUMBER columns to find the SQL statement that is currently being executed?  For that matter, why isn’t there a SQL_CHILD_ADDRESS column in V$SESSION if the documentation suggests using SQL_ADDRESS to find the SQL statement currently being executed?

Recently, an errata was filed for page 188 of the Expert Oracle Practices book by an observant reader named Andreas, who mentioned that the SQL statement found on that page could produce duplicate rows, and offered an improved version of the SQL statement.  The SQL statement from the book follows:

SQL> SELECT /*+ ORDERED */
  2    TU.USERNAME, S.SID, S.SERIAL#, S.SQL_ID, S.SQL_ADDRESS, TU.SEGTYPE, TU.EXTENTS,
  3    TU.BLOCKS, SQL.SQL_TEXT
  4  FROM
  5    V$TEMPSEG_USAGE TU, V$SESSION S, V$SQL SQL
  6  WHERE
  7    TU.SESSION_ADDR=S.SADDR
  8    AND TU.SESSION_NUM=S.SERIAL#
  9    AND S.SQL_ID=SQL.SQL_ID
 10    AND S.SQL_ADDRESS=SQL.ADDRESS;

The sample output included in the book from that SQL statement is this:

USERNAME   SID  SERIAL# SQL_ID        SQL_ADDRESS      SEGTYPE EXTENTS     BLOCKS
-------- ----- -------- ------------- ---------------- ------- ------- ----------
TESTUSER   165     2171 7pqxpw71fkjvj 000000027DB50320 SORT        370      47360

SQL_TEXT
-------------------------------------------------------------------
SELECT * FROM T1,T2 WHERE T1.ID<=100 AND T2.ID<=1000 ORDER BY T1.ID

We also included the execution plan for the SQL statement, but did not show how the execution plan was obtained since that would be discussed later in the chapter:

------------------------------------------------------------------------------------
| Id |Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|  0|SELECT STATEMENT             |        |       |       |   119G(100)|          |
|  1| MERGE JOIN CARTESIAN        |        |  6552G|   643T|   119G  (3)|999:59:59 |
|  2|  TABLE ACCESS BY INDEX ROWID| T1     |  1005K|    50M|  1006K  (1)| 00:07:10 |
|* 3|   INDEX RANGE SCAN          | IND_T1 |  1005K|       |  2293   (9)| 00:00:01 |
|  4|  BUFFER SORT                |        |  6516K|   341M|   119G  (3)|999:59:59 |
|* 5|   TABLE ACCESS FULL         | T2     |  6516K|   341M|   118K  (3)| 00:00:51 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("T1"."ID"<=100)
   5 - filter("T2"."ID"<=1000)

Note
-----
   - dynamic sampling used for this statement

What is wrong with the above SQL statement (no, not the one that generated the Cartesian join – the other one that queried V$TEMPSEG_USAGE)?  We did not write the two chapters in linear order, starting at the beginning of chapter 8 and working to the end of chapter 9.  Instead, we outlined each section that would appear in the chapter, and wrote the contents of those sections in spurts.  At the time that the SQL statement which queried V$TEMPSEG_USAGE was written, we had already written the AdaptiveCursorBindTest.sql sample script that is mentioned later in chapter 8.  When the above SQL statement was written, I recall being internally conflicted – why?

  • Should the SQL statement instead use the HASH_VALUE, rather than SQL_ID, as suggested by the Oracle 10.2 and 11.2 documentation, which would then allow the query to also work on Oracle 9.2?  Would it be sufficient to just add a note stating that if you are running Oracle 9.2 or earlier, substitute the SQL_HASH_VALUE for SQL_ID?
  • Should the SQL statement join to V$SQLAREA to eliminate the problems with multiple child cursors for the same SQL_ID?  But how would we then retrieve the correct execution plan from the server’s memory in the event that the multiple child cursors have different execution plans?
  • Should we also use the SQL_CHILD_NUMBER column to join to V$SQL?  But then what about the users still running Oracle 9.2 or earlier?
  • Should there be a SQL_CHILD_ADDRESS column in V$SESSION since the SQL_ADDRESS column will probably be the same for all child cursors for a given SQL_ID?
  • How do we deal with the output of the AdaptiveCursorBindTest.sql sample script, which showed Oracle 11.1.0.6 producing multiple child cursors with the same CHILD_NUMBER for a give SQL_ID?  That would mean that even if the query included the SQL_CHILD_NUMBER column, there is still a potential for duplicate rows being returned by the query.

The initial plan was to circle back to this section of the chapter and try to describe some of the potential issues with using the SQL statement that queried V$TEMPSEG_USAGE, but that would not be an easy task without the reader first reading the rest of that chapter.  Alas, just days after the final version of the chapters were due to the publisher, and the first drop of ink was spilled on the page of the printed book, we made another pass through the chapter.  When I executed this SQL statement I found that it was listing the same SQL_ID more than once.  But why?  A query of V$SQL_SHARED_CURSOR showed that ROLL_INVALID_MISMATCH was set to Y when a second (or third) child cursor was created.  What does that mean?  Execute a query, collect statistics on the tables or indexes used by the query, wait about 5 hours, re-execute the query, and then check V$SQL_SHARED_CURSOR.  The delay is mentioned here and here, along with a hidden _optimizer_invalidation_period parameter that controls how long after statistics collection is performed, the previously hard parsed cursors that referenced those objects can no longer be used.

In short, we never did circle back to that section of the chapter before the book was printed, so I am happy that Andreas filed the errata report, which allowed us to clarify the situation.  We did join to V$SQL so that with a little more work it would be possible to determine the correct execution plan to pull from memory.  In retrospect, we probably should have just written the SQL statement like the following and provided a quick comment about Oracle Database 9.2.0.8 and earlier, and the potential duplicates in Oracle Database 11.1.0.6 that were demonstrated in the AdaptiveCursorBindTest.sql sample script:

SELECT /*+ ORDERED */
  TU.USERNAME, S.SID, S.SERIAL#, S.SQL_ID, S.SQL_CHILD_NUMBER,
  TU.SEGTYPE, TU.EXTENTS, TU.BLOCKS, SQL.SQL_TEXT
FROM
  V$TEMPSEG_USAGE TU, V$SESSION S, V$SQL SQL
WHERE
  TU.SESSION_ADDR=S.SADDR
  AND TU.SESSION_NUM=S.SERIAL#
  AND S.SQL_ID=SQL.SQL_ID
  AND S.SQL_CHILD_NUMBER=SQL.CHILD_NUMBER
  AND S.SQL_ADDRESS=SQL.ADDRESS;

Without looking at the V$SQL_SHARED_CURSOR view, what are the different reasons for multiple child cursors to be created?  To get you started:

  • Collecting object statistics
  • Changing the data type of bind variables
  • Changing the data length of bind variables
  • Changing the optimizer mode (ALL_ROWS, CHOOSE, RULE, FIRST_ROWS, etc.)
  • Adaptive cursor sharing (starting with Oracle Database 11.1.0.6)
  • Cardinality feedback (starting with Oracle Database 11.2.0.1)

I give my thanks to Andreas for inspiring this blog article.

Related blog articles:
SORT_AREA_SIZE Affecting Sorts to Disk with PGA_AGGREGATE_TARGET Set?
SORT_AREA_SIZE Affecting Sorts to Disk with PGA_AGGREGATE_TARGET Set 2?
SQL PLAN_HASH_VALUE Changes for the Same SQL Statement
V$SESSION_LONGOPS – Where’s My SQL Statement





SQL – Overlapping Transactions, How Many Hours have We Worked?

19 03 2010

March 19, 2010

A couple of years ago I received an email from an ERP mailing list that requested assistance with a task of determining how many hours an employee was in a building.  The ERP software allows employees to log into the computer system that job A was in-process between 8:00 AM and 10:00 AM and job B was in-process from 10:00 AM to noon, so in this case it would be a simple task of subtracting the corresponding starting time from the ending time and summing the results.  But what happens if the employee is responsible for monitoring automated processes, where the employee may monitor several simultaneous in-process jobs?  For example, job A was in-process between 8:00 AM and 10:00 AM and job B was in-process from 8:30 AM to 9:25 AM, job C was in-process from 9:00 AM to 11:00 AM, job D was in-process from 10:30 AM to noon.  In the case of the concurrent in-process jobs it becomes much more difficult to show that the employee worked for 4 hours, just as in the first example.

How could we solve this problem?  Paint a picture – there are 1440 minutes in a day, so we could just lay down each of the transactions on top of each of those minutes to see how many of the minutes are occupied.  If we start with the following, we obtain the number of minutes past midnight of the shift date for the clock in and clock out, rounded to the nearest minute:

SELECT
  EMPLOYEE_ID,
  SHIFT_DATE,
  ROUND((CLOCK_IN-SHIFT_DATE)*1440) CLOCK_IN,
  ROUND((CLOCK_OUT-SHIFT_DATE)*1440) CLOCK_OUT
FROM
  LABOR_TICKET
WHERE
  SHIFT_DATE=TRUNC(SYSDATE-1);

If we had a way of stepping through all of the minutes in the day, and potentially two days in the event that the shift date crosses midnight, we could count the number of minutes in which there was an active labor ticket for each employee.  To do this, we need a counter:

SELECT
  ROWNUM COUNTER
FROM
  DUAL
CONNECT BY
  LEVEL<=2880;

Now, if we combine the two SQL statements together, placing each in an inline view, we can count the number of distinct minutes for which there was a labor ticket:

SELECT
  LT.EMPLOYEE_ID,
  LT.SHIFT_DATE,
  MIN(CLOCK_IN) CLOCK_IN,
  MAX(CLOCK_OUT) CLOCK_OUT,
  COUNT(DISTINCT C.COUNTER)/60 HOURS
FROM
  (SELECT
    EMPLOYEE_ID,
    SHIFT_DATE,
    ROUND((ROUND(CLOCK_IN,'MI')-SHIFT_DATE)*1440) CLOCK_IN,
    ROUND((ROUND(CLOCK_OUT,'MI')-SHIFT_DATE)*1440) CLOCK_OUT
  FROM
    LABOR_TICKET
  WHERE
    SHIFT_DATE=TRUNC(SYSDATE-1)) LT,
  (SELECT
    ROWNUM COUNTER
  FROM
    DUAL
  CONNECT BY
    LEVEL<=2880) C
WHERE
  C.COUNTER>LT.CLOCK_IN
  AND C.COUNTER<=LT.CLOCK_OUT
GROUP BY
  LT.EMPLOYEE_ID,
  LT.SHIFT_DATE;

We have a couple of potential problems with the above:

  1. It could bury/peg the CPU in the database server due to the CONNECT BY.
  2. The CLOCK_IN and CLOCK_OUT times are not in a friendly format.

First, we create a counter table:

CREATE TABLE
  MY_COUNTER
AS
SELECT
  ROWNUM COUNTER
FROM
  DUAL
CONNECT BY
  LEVEL<=2880;

COMMIT;

Now, plugging in the counter table and cleaning up the CLOCK_IN and CLOCK_OUT times:

SELECT
  LT.EMPLOYEE_ID,
  LT.SHIFT_DATE,
  MIN(CLOCK_IN)/1440+SHIFT_DATE CLOCK_IN,
  MAX(CLOCK_OUT)/1440+SHIFT_DATE CLOCK_OUT,
  ROUND(COUNT(DISTINCT C.COUNTER)/60,2) HOURS
FROM
  (SELECT
    EMPLOYEE_ID,
    SHIFT_DATE,
    ROUND((ROUND(CLOCK_IN,'MI')-SHIFT_DATE)*1440) CLOCK_IN,
    ROUND((ROUND(CLOCK_OUT,'MI')-SHIFT_DATE)*1440) CLOCK_OUT
  FROM
    LABOR_TICKET
  WHERE
    SHIFT_DATE=TRUNC(SYSDATE-1)) LT,
  (SELECT
    COUNTER
  FROM
    MY_COUNTER) C
WHERE
  C.COUNTER>LT.CLOCK_IN
  AND C.COUNTER<=LT.CLOCK_OUT
GROUP BY
  LT.EMPLOYEE_ID,
  LT.SHIFT_DATE;

This solution was just as easy as painting by number.  It is just a matter of breaking a complicated task into solvable problems.





Improving Performance by Using a Cartesian Join

18 03 2010

March 18, 2010

(Forward to the Next Post in the Series)

This example is based on a demonstration that I gave during a presentation last year.  I did not go into great detail how the code worked, but I demonstrated that a carefully constructed Cartesian join is helpful and efficient for solutions to certain types of problems.  Assume that you have a table named APPLICATION_LIST that lists all of the modules belonging to an application, another table named USER_LIST that lists each Oracle username that has access to the application, and a third table named USER_PROGRAM_PERMISSION that lists each username that is denied access to one of the application modules.  The table construction may seem a little odd, but this is based on an actual example found in a commercial product.  The goal is to produce a cross-tab style report that shows all users’ permissions to all of the application modules, and have that cross-tab report appear in Excel.  The table definitions for our test tables look like this:

CREATE TABLE APPLICATION_LIST(
  PROGRAM_ID VARCHAR2(30),
  MENU_STRING VARCHAR2(30),
  PRIMARY KEY (PROGRAM_ID));

CREATE TABLE USER_LIST(
  NAME VARCHAR2(30),
  TYPE NUMBER,
  PRIMARY KEY(NAME));

CREATE TABLE USER_PROGRAM_PERMISSION(
  USER_ID VARCHAR2(30),
  PROGRAM_ID VARCHAR2(30),
  PERMISSION CHAR(1),
  PROGRAM_COMPONENT VARCHAR(20),
  PRIMARY KEY(USER_ID,PROGRAM_ID));

We will populate the test tables with the following script:

INSERT INTO
  APPLICATION_LIST
SELECT
  DBMS_RANDOM.STRING('Z',10) PROGRAM_ID,
  DBMS_RANDOM.STRING('A',20) MENU_STRING
FROM
  DUAL
CONNECT BY
  LEVEL<=100;

INSERT INTO
  USER_LIST
SELECT
  'USER'||TO_CHAR(ROWNUM) USER_ID,
  1 TYPE
FROM
  DUAL
CONNECT BY
  LEVEL<=300;

INSERT INTO
  USER_PROGRAM_PERMISSION
SELECT
  USER_ID,
  PROGRAM_COMPONENT,
  PERMISSION,
  'PROGRAM'
FROM
  (SELECT
    UL.NAME USER_ID,
    AL.PROGRAM_ID PROGRAM_COMPONENT,
    'N' PERMISSION
  FROM
    USER_LIST UL,
    APPLICATION_LIST AL
  ORDER BY
    DBMS_RANDOM.VALUE)
WHERE
  ROWNUM<=27000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'APPLICATION_LIST',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'USER_LIST',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'USER_PROGRAM_PERMISSION',CASCADE=>TRUE)

The first VBS script will not use a Cartesian Merge join – instead it will retrieve a list of all users and all application modules, and then probe the USER_PROGRAM_PERMISSION table once for each USER_ID. (IntentionalCartesian1-NoCartesian.VBS – save as IntentionalCartesian1-NoCartesian.VBS)

Const adVarChar = 200
Const adCmdText = 1
Const adCmdStoredProc = 4
Const adParamInput = 1

Dim i
Dim j
Dim strSQL
Dim strLastColumn
Dim strProgramName
Dim strUsername
Dim strPassword
Dim strDatabase
Dim strPermission
Dim snpData
Dim comData
Dim dbDatabase
Dim objExcel

Set dbDatabase = CreateObject("ADODB.Connection")
Set snpData = CreateObject("ADODB.Recordset")
Set comData = CreateObject("ADODB.Command")

On Error Resume Next

strUsername = "MyUsername"
strPassword = "MyPassword"
strDatabase = "MyDB"

dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";"
dbDatabase.Open
'Should verify that the connection attempt was successful, but I will leave that for someone else to code

Set snpData = CreateObject("adodb.recordset")

'Create an Excel connection
Set objExcel = CreateObject("Excel.Application")

With objExcel
    .Workbooks.Add
    .ActiveWorkbook.Sheets.Add
    .ActiveSheet.Name = "Application Permissions"

    'Remove the three default worksheets
    For i = 1 To .ActiveWorkbook.Sheets.Count
        If .ActiveWorkbook.Sheets(i).Name = "Sheet1" Then
            .Sheets("Sheet1").Select
            .ActiveWindow.SelectedSheets.Delete
        End If
        If .ActiveWorkbook.Sheets(i).Name = "Sheet2" Then
            .Sheets("Sheet2").Select
            .ActiveWindow.SelectedSheets.Delete
        End If
        If .ActiveWorkbook.Sheets(i).Name = "Sheet3" Then
            .Sheets("Sheet3").Select
            .ActiveWindow.SelectedSheets.Delete
        End If
    Next

    .Visible = True
End With

strSQL = "SELECT" & vbCrLf
strSQL = strSQL & "  PROGRAM_ID," & vbCrLf
strSQL = strSQL & "  MENU_STRING" & vbCrLf
strSQL = strSQL & "FROM" & vbCrLf
strSQL = strSQL & "  APPLICATION_LIST" & vbCrLf
strSQL = strSQL & "WHERE" & vbCrLf
strSQL = strSQL & "  PROGRAM_ID NOT IN ('.SEPARATOR')" & vbCrLf
strSQL = strSQL & "ORDER BY" & vbCrLf
strSQL = strSQL & "  MENU_STRING"

snpData.Open strSQL, dbDatabase

If snpData.State = 1 Then
    strProgramName = snpData.GetRows(30000)
    snpData.Close
End If

'Set the number of elements in the strPermission array to match the number of application module names
ReDim strPermission(UBound(strProgramName, 2))

'Copy the module names into Excel
For j = 0 To UBound(strPermission)
    strPermission(j) = strProgramName(1, j) ' & " - " & strProgramName(0, j)
Next
With objExcel
    .Application.ScreenUpdating = False
    .ActiveSheet.Range(.ActiveSheet.Cells(1, 2), .ActiveSheet.Cells(1, 1 + UBound(strProgramName, 2))) = strPermission
End With

'Retrieve the list of users
strSQL = "SELECT" & vbCrLf
strSQL = strSQL & "  NAME" & vbCrLf
strSQL = strSQL & "FROM" & vbCrLf
strSQL = strSQL & "  USER_LIST" & vbCrLf
strSQL = strSQL & "WHERE" & vbCrLf
strSQL = strSQL & "  TYPE=1" & vbCrLf
strSQL = strSQL & "  AND NAME NOT LIKE '%#'" & vbCrLf
strSQL = strSQL & "ORDER BY" & vbCrLf
strSQL = strSQL & "  NAME"

snpData.Open strSQL, dbDatabase

If snpData.State = 1 Then
    strUsername = snpData.GetRows(30000)
    snpData.Close
End If

'Set the SQL statement to use to retrieve permissions, ? is a bind variable placeholder
strSQL = "SELECT" & vbCrLf
strSQL = strSQL & "  PROGRAM_ID," & vbCrLf
strSQL = strSQL & "  PERMISSION" & vbCrLf
strSQL = strSQL & "FROM" & vbCrLf
strSQL = strSQL & "  USER_PROGRAM_PERMISSION" & vbCrLf
strSQL = strSQL & "WHERE" & vbCrLf
strSQL = strSQL & "  PROGRAM_COMPONENT='PROGRAM'" & vbCrLf
strSQL = strSQL & "  AND USER_ID= ?" & vbCrLf
strSQL = strSQL & "ORDER BY" & vbCrLf
strSQL = strSQL & "  PROGRAM_ID"

With comData
    'Set up the command properties
    .CommandText = strSQL
    .CommandType = adCmdText
    .CommandTimeout = 30
    .ActiveConnection = dbDatabase

    .Parameters.Append .CreateParameter("user_id", adVarChar, adParamInput, 30, "")
End With

'Loop through each user
For i = 0 To UBound(strUsername, 2)
    'Reset the permissions for the next user
    For j = 0 To UBound(strPermission)
        strPermission(j) = "Y"
    Next

    comData("user_id") = strUsername(0, i)
    Set snpData = comData.Execute

    If snpData.State = 1 Then
        Do While Not (snpData.EOF)
            For j = 0 To UBound(strProgramName, 2)
                If strProgramName(0, j) = snpData("program_id") Then
                    strPermission(j) = snpData("permission")
                    Exit For
                End If
            Next
            snpData.MoveNext
        Loop
        snpData.Close
    End If

    With objExcel
        .ActiveSheet.Cells(i + 2, 1) = strUsername(0, i)
        .ActiveSheet.Range(.ActiveSheet.Cells(i + 2, 2), .ActiveSheet.Cells(i + 2, 1 + UBound(strProgramName, 2))) = strPermission
    End With
Next

'Convert the number of columns into letter notation
strLastColumn = Chr(64 + Int((UBound(strProgramName, 2)) / 26)) & Chr(64 + ((UBound(strProgramName, 2)) Mod 26 + 1))

'Final cleanup
With objExcel
    .ActiveSheet.Range(.ActiveSheet.Cells(1, 2), .ActiveSheet.Cells(1, 1 + UBound(strProgramName, 2))).Orientation = 90
    .ActiveSheet.Columns("A:" & strLastColumn).AutoFit
    .Application.ScreenUpdating = True
    .ActiveSheet.Range("B2").Select
    .ActiveWindow.FreezePanes = True
End With

dbDatabase.Close

Set snpData = Nothing
Set comData = Nothing
Set objExcel = Nothing

If you ignore the fact that the above script redefines the meaning of the strUsername variable, the script works.  The problem with the script is that it repeatedly sends queries to the database, and probably should be optimized to remove the repeated queries (the number of repeated communication to the database server could have been much worse).  Let’s take a look at version 2 of the script (IntentionalCartesian2-NoCartesian.VBS – save as IntentionalCartesian2-NoCartesian.VBS)

Dim i
Dim j
Dim strSQL
Dim strLastColumn
Dim strProgramName
Dim strEmployeename
Dim strUsername
Dim strPassword
Dim strDatabase
Dim strPermission
Dim snpData
Dim dbDatabase
Dim objExcel

Set dbDatabase = CreateObject("ADODB.Connection")
Set snpData = CreateObject("ADODB.Recordset")

On Error Resume Next

strUsername = "MyUsername"
strPassword = "MyPassword"
strDatabase = "MyDB"

dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";"
dbDatabase.Open
'Should verify that the connection attempt was successful, but I will leave that for someone else to code

Set snpData = CreateObject("adodb.recordset")

'Create an Excel connection
Set objExcel = CreateObject("Excel.Application")

With objExcel
    .Workbooks.Add
    .ActiveWorkbook.Sheets.Add
    .ActiveSheet.Name = "Visual Permissions"

    'Remove the three default worksheets
    For i = 1 To .ActiveWorkbook.Sheets.Count
        If .ActiveWorkbook.Sheets(i).Name = "Sheet1" Then
            .Sheets("Sheet1").Select
            .ActiveWindow.SelectedSheets.Delete
        End If
        If .ActiveWorkbook.Sheets(i).Name = "Sheet2" Then
            .Sheets("Sheet2").Select
            .ActiveWindow.SelectedSheets.Delete
        End If
        If .ActiveWorkbook.Sheets(i).Name = "Sheet3" Then
            .Sheets("Sheet3").Select
            .ActiveWindow.SelectedSheets.Delete
        End If
    Next

    .Visible = True
End With

strSQL = "SELECT" & vbCrLf
strSQL = strSQL & "  PROGRAM_ID," & vbCrLf
strSQL = strSQL & "  MENU_STRING" & vbCrLf
strSQL = strSQL & "FROM" & vbCrLf
strSQL = strSQL & "  APPLICATION_LIST" & vbCrLf
strSQL = strSQL & "WHERE" & vbCrLf
strSQL = strSQL & "  PROGRAM_ID NOT IN ('.SEPARATOR')" & vbCrLf
strSQL = strSQL & "ORDER BY" & vbCrLf
strSQL = strSQL & "  MENU_STRING"

snpData.Open strSQL, dbDatabase

If snpData.State = 1 Then
    strProgramName = snpData.GetRows(30000)
    snpData.Close
End If

'Set the number of elements in the strPermission array to match the number of application module names
ReDim strPermission(UBound(strProgramName, 2))

'Copy the module names into Excel
For j = 0 To UBound(strPermission)
    strPermission(j) = strProgramName(1, j) ' & " - " & strProgramName(0, j)
Next
With objExcel
    .Application.ScreenUpdating = False
    .ActiveSheet.Range(.ActiveSheet.Cells(1, 2), .ActiveSheet.Cells(1, 1 + UBound(strProgramName, 2))) = strPermission
End With

'Retrieve the list of users
strSQL = "SELECT" & vbCrLf
strSQL = strSQL & "  NAME" & vbCrLf
strSQL = strSQL & "FROM" & vbCrLf
strSQL = strSQL & "  USER_LIST" & vbCrLf
strSQL = strSQL & "WHERE" & vbCrLf
strSQL = strSQL & "  TYPE=1" & vbCrLf
strSQL = strSQL & "  AND NAME NOT LIKE '%#'" & vbCrLf
strSQL = strSQL & "ORDER BY" & vbCrLf
strSQL = strSQL & "  NAME"

snpData.Open strSQL, dbDatabase

If snpData.State = 1 Then
    strEmployeename = snpData.GetRows(30000)
    snpData.Close
End If

'Set the SQL statement to use to retrieve permissions, ? is a bind variable placeholder
strSQL = "SELECT" & vbCrLf
strSQL = strSQL & "  USER_ID," & vbCrLf
strSQL = strSQL & "  PROGRAM_ID," & vbCrLf
strSQL = strSQL & "  PERMISSION" & vbCrLf
strSQL = strSQL & "FROM" & vbCrLf
strSQL = strSQL & "  USER_PROGRAM_PERMISSION" & vbCrLf
strSQL = strSQL & "WHERE" & vbCrLf
strSQL = strSQL & "  PROGRAM_COMPONENT='PROGRAM'" & vbCrLf
strSQL = strSQL & "ORDER BY" & vbCrLf
strSQL = strSQL & "  USER_ID," & vbCrLf
strSQL = strSQL & "  PROGRAM_ID"

snpData.Open strSQL, dbDatabase

If snpData.State = 1 Then
    strAllPermission = snpData.GetRows(600000)
    snpData.Close
End If

strLastUser = ""
intLastPermission = 0

'Loop through all users
For i = 0 To UBound(strEmployeename, 2)
    'Reset the permissions for the next user
    For j = 0 To UBound(strPermission)
        strPermission(j) = "Y"
    Next

    For j = intLastPermission To UBound(strAllPermission, 2)
        If strAllPermission(0, j) = strEmployeename(0, i) Then
            'Examine the permissions for this user
            For k = 0 To UBound(strProgramName, 2)
                If strProgramName(0, k) = strAllPermission(1, j) Then
                    strPermission(k) = strAllPermission(2, j)
                    Exit For
                End If
            Next

        End If

        'Record the loop position so that we do not start at 0 for the next user
        intLastPermission = j

        If strAllPermission(0, j) > strEmployeename(0, i) Then
            'We have passed the last permission for this user, exit the For loop
            Exit For
        End If
    Next

    With objExcel
        .ActiveSheet.Cells(i + 2, 1) = strEmployeename(0, i)
        .ActiveSheet.Range(.ActiveSheet.Cells(i + 2, 2), .ActiveSheet.Cells(i + 2, 1 + UBound(strProgramName, 2))) = strPermission
    End With
Next

'Convert the number of columns into letter notation
strLastColumn = Chr(64 + Int((UBound(strProgramName, 2)) / 26)) & Chr(64 + ((UBound(strProgramName, 2)) Mod 26 + 1))

'Final cleanup
With objExcel
    .ActiveSheet.Range(.ActiveSheet.Cells(1, 2), .ActiveSheet.Cells(1, 1 + UBound(strProgramName, 2))).Orientation = 90
    .ActiveSheet.Columns("A:" & strLastColumn).AutoFit
    .Application.ScreenUpdating = True
    .ActiveSheet.Range("B2").Select
    .ActiveWindow.FreezePanes = True
End With

dbDatabase.Close

Set snpData = Nothing
Set dbDatabase = Nothing
Set objExcel = Nothing

While the second version of the script is better than the first, we are still sending three SQL statements to the server.  We can improve that with a Cartesian join.  Let’s take a look at version 3 of the script (IntentionalCartesian3-Cartesian.VBS – save as IntentionalCartesian3-Cartesian.VBS)

Dim i
Dim intUserCount
Dim intPermissionCount
Dim strLastColumn
Dim strLastUser
Dim strSQL
Dim strPermission(500)
Dim strModuleName(500)

Dim strUsername
Dim strPassword
Dim strDatabase
Dim snpData
Dim dbDatabase
Dim objExcel

Set dbDatabase = CreateObject("ADODB.Connection")
Set snpData = CreateObject("ADODB.Recordset")

On Error Resume Next

strUsername = "MyUsername"
strPassword = "MyPassword"
strDatabase = "MyDB"

dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";"
dbDatabase.Open
'Should verify that the connection attempt was successful, but I will leave that for someone else to code

Set snpData = CreateObject("adodb.recordset")

'Create an Excel connection
Set objExcel = CreateObject("Excel.Application")

With objExcel
    .Workbooks.Add
    .ActiveWorkbook.Sheets.Add
    .ActiveSheet.Name = "Application Permissions"

    'Remove the three default worksheets
    For i = 1 To .ActiveWorkbook.Sheets.Count
        If .ActiveWorkbook.Sheets(i).Name = "Sheet1" Then
            .Sheets("Sheet1").Select
            .ActiveWindow.SelectedSheets.Delete
        End If
        If .ActiveWorkbook.Sheets(i).Name = "Sheet2" Then
            .Sheets("Sheet2").Select
            .ActiveWindow.SelectedSheets.Delete
        End If
        If .ActiveWorkbook.Sheets(i).Name = "Sheet3" Then
            .Sheets("Sheet3").Select
            .ActiveWindow.SelectedSheets.Delete
        End If
    Next

    .Visible = True
End With

strSQL = "SELECT" & vbCrLf
strSQL = strSQL & "  AUP.NAME USERNAME," & vbCrLf
strSQL = strSQL & "  AUP.MENU_STRING MODULE," & vbCrLf
strSQL = strSQL & "  NVL(UGA.PERMISSION,AUP.DEFAULT_PERMISSION) PERMISSION" & vbCrLf
strSQL = strSQL & "FROM" & vbCrLf
strSQL = strSQL & "  (SELECT" & vbCrLf
strSQL = strSQL & "    UL.NAME NAME," & vbCrLf
strSQL = strSQL & "    A.PROGRAM_ID," & vbCrLf
strSQL = strSQL & "    A.MENU_STRING," & vbCrLf
strSQL = strSQL & "    'Y' DEFAULT_PERMISSION" & vbCrLf
strSQL = strSQL & "  FROM" & vbCrLf
strSQL = strSQL & "    APPLICATION_LIST A," & vbCrLf
strSQL = strSQL & "    USER_LIST UL" & vbCrLf
strSQL = strSQL & "  WHERE" & vbCrLf
strSQL = strSQL & "    A.PROGRAM_ID NOT IN ('.SEPARATOR')" & vbCrLf
strSQL = strSQL & "    AND UL.NAME NOT LIKE '%#') AUP," & vbCrLf
strSQL = strSQL & "  (SELECT" & vbCrLf
strSQL = strSQL & "    USER_ID," & vbCrLf
strSQL = strSQL & "    PROGRAM_ID," & vbCrLf
strSQL = strSQL & "    PERMISSION" & vbCrLf
strSQL = strSQL & "  FROM" & vbCrLf
strSQL = strSQL & "    USER_PROGRAM_PERMISSION" & vbCrLf
strSQL = strSQL & "  WHERE" & vbCrLf
strSQL = strSQL & "    PROGRAM_COMPONENT='PROGRAM') UGA" & vbCrLf
strSQL = strSQL & "WHERE" & vbCrLf
strSQL = strSQL & "  AUP.NAME=UGA.USER_ID(+)" & vbCrLf
strSQL = strSQL & "  AND AUP.PROGRAM_ID=UGA.PROGRAM_ID(+)" & vbCrLf
strSQL = strSQL & "ORDER BY" & vbCrLf
strSQL = strSQL & "  AUP.NAME," & vbCrLf
strSQL = strSQL & "  AUP.MENU_STRING"

snpData.Open strSQL, dbDatabase

If snpData.State = 1 Then
  With objExcel
    .Application.ScreenUpdating = False
    strLastUser = ""
    intUserCount = 0
    Do While Not snpData.EOF
        If strLastUser <> snpData("username") Then
            If strLastUser <> "" Then
                'Write out the permissions for the previous user
                .ActiveSheet.Range(.ActiveSheet.Cells(intUserCount + 1, 1), .ActiveSheet.Cells(intUserCount + 1, 1 + intPermissionCount)) = strPermission
            End If
            If intUserCount = 1 Then
                'Write out the module names
                .ActiveSheet.Range(.ActiveSheet.Cells(1, 1), .ActiveSheet.Cells(1, 1 + intPermissionCount)) = strModuleName
            End If

            strPermission(0) = snpData("username")
            intPermissionCount = 0
            intUserCount = intUserCount + 1
        End If
        intPermissionCount = intPermissionCount + 1
        strPermission(intPermissionCount) = snpData("permission")
        strLastUser = snpData("username")

        If intUserCount = 1 Then
            'Record the module names
            strModuleName(intPermissionCount) = snpData("module")
        End If

        snpData.MoveNext
    Loop
    If strLastUser <> "" Then
        'Write out the permissions for the last user
        .ActiveSheet.Range(.ActiveSheet.Cells(intUserCount + 1, 1), .ActiveSheet.Cells(intUserCount + 1, 1 + intPermissionCount)) = strPermission
    End If

    strLastColumn = Chr(64 + Int((intPermissionCount) / 26)) & Chr(64 + ((intPermissionCount) Mod 26 + 1))
    .ActiveSheet.Range(.ActiveSheet.Cells(1, 2), .ActiveSheet.Cells(1, 1 + intPermissionCount)).Orientation = 90
    .ActiveSheet.Columns("A:" & strLastColumn).AutoFit
    .Application.ScreenUpdating = True
    .ActiveWindow.FreezePanes = False
    .ActiveSheet.Range("B2").Select
    .ActiveWindow.FreezePanes = True

    .Application.ScreenUpdating = True
  End With
End If

snpData.Close
dbDatabase.Close
Set snpData = Nothing
Set dbDatabase = Nothing
Set objExcel = Nothing

Notice in the above that the client-side code is much smaller, and we have collapsed the three SQL statements into a single SQL statement with the help of a Cartesian join between the APPLICATION_LIST and USER_LIST tables.  The end result looks like this:





What is the Impact on the CPU Statistic in a 10046 Trace File in a CPU Constrained Server?

17 03 2010

March 17, 2010

Sometimes I have wondered about the statistics that appear in 10046 trace files – how much are the statistics distorted by other activities happening in the server, or even just the act of enabling a 10046 trace for a session.  Will the CPU statistics in the trace file increase as running processes remain in the CPU run queue longer and longer, or are the CPU statistics immune to longer execution times caused by a process’ “run” time slice expiring?  Does the CPU architecture matter?  Does the operating system matter?  Is it possible that a query could actually complete faster when the competition for CPU resources increases?  Are there other variables that need to be considered?

We will set up the same test table that was used in yesterday’s blog article:

CREATE TABLE T5 (
  C1 VARCHAR2(10),
  C2 VARCHAR2(100),
  PRIMARY KEY (C1));

INSERT INTO T5 NOLOGGING
SELECT
  'A'||TO_CHAR(ROWNUM,'0000000'),
  RPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T5',CASCADE=>TRUE)

From a client computer the following script is executed against Oracle 11.1.0.6 running on 64 bit Linux:  

SET AUTOTRACE TRACEONLY STATISTICS
SET ARRAYSIZE 100
SET TIMING ON
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'NOLOAD';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

SELECT /*+ USE_NL(T51 T52 T53 T54 T55 T56 T57 T58) */
  T51.C1,
  T51.C2,
  T52.C1,
  T52.C2,
  T53.C1,
  T53.C2,
  T54.C1,
  T54.C2,
  T55.C1,
  T55.C2,
  T56.C1,
  T56.C2,
  T57.C1,
  T57.C2,
  T58.C1,
  T58.C2
FROM
  T5 T51,
  T5 T52,
  T5 T53,
  T5 T54,
  T5 T55,
  T5 T56,
  T5 T57,
  T5 T58
WHERE
  T51.C1=T52.C1
  AND T51.C1=T53.C1
  AND T51.C1=T54.C1
  AND T51.C1=T55.C1
  AND T51.C1=T56.C1
  AND T51.C1=T57.C1
  AND T51.C1=T58.C1
  AND T51.C1 BETWEEN 'A 0000000' AND 'A 1000000';

SELECT SYSDATE FROM DUAL;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

The SQL*Plus session displayed the following statistics, which were fairly consistent across multiple executions:

1000000 rows selected.

Elapsed: 00:01:59.85

Statistics
---------------------------------------------------
          0  recursive calls
          0  db block gets
    8696435  consistent gets
          0  physical reads
          0  redo size
   86861789  bytes sent via SQL*Net to client
     110349  bytes received via SQL*Net from client
      10001  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
    1000000  rows processed

TKPROF output for the trace file:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch    10001     35.53      35.83          0    8696435          0     1000000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    10005     35.53      35.83          0    8696435          0     1000000

Misses in library cache during parse: 0
Parsing user id: 80 

Rows     Row Source Operation
-------  ---------------------------------------------------
1000000  NESTED LOOPS  (cr=8696435 pr=0 pw=0 time=294720 us)
1000000   NESTED LOOPS  (cr=7696435 pr=0 pw=0 time=272839 us cost=8008211 size=888000000 card=1000000)
1000000    NESTED LOOPS  (cr=7457834 pr=0 pw=0 time=250538 us cost=7007667 size=777000000 card=1000000)
1000000     NESTED LOOPS  (cr=6219233 pr=0 pw=0 time=210922 us cost=6007124 size=666000000 card=1000000)
1000000      NESTED LOOPS  (cr=4980632 pr=0 pw=0 time=170866 us cost=5006580 size=555000000 card=1000000)
1000000       NESTED LOOPS  (cr=3742031 pr=0 pw=0 time=130944 us cost=4006037 size=444000000 card=1000000)
1000000        NESTED LOOPS  (cr=2503430 pr=0 pw=0 time=90395 us cost=3005494 size=333000000 card=1000000)
1000000         NESTED LOOPS  (cr=1264829 pr=0 pw=0 time=49809 us cost=2004950 size=222000000 card=1000000)
1000000          TABLE ACCESS FULL T5 (cr=26228 pr=0 pw=0 time=4775 us cost=4407 size=111000000 card=1000000)
1000000          TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=2 size=111 card=1)
1000000           INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000         TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000          INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000        TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000         INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000       TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000        INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000      TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000       INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000     TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000      INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000    INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000   TABLE ACCESS BY INDEX ROWID T5 (cr=1000000 pr=0 pw=0 time=0 us cost=1 size=111 card=1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   10001        0.00          0.01
  SQL*Net message from client                 10001        0.01         83.34
  SQL*Net more data to client                 10000        0.00          0.19

The above shows that the 1,000,000 rows from the query were returned to the client in just less that 2 minutes.  8,696,435 consistent gets were performed with 35.53 CPU seconds, 35.83 elapsed seconds, and 83.34 seconds waiting for the next fetch request from the client computer.

For fun, we will start up 40 instances of the CPU load generating bash script found on page 197 of the Expert Oracle Practices book.  That will easily push the 8 processors fairly close to 100% utilization with fairly long CPU run queues.  Repeating the previous test, we receive the following output:

1000000 rows selected.

Elapsed: 00:01:57.01

Statistics
---------------------------------------------------
          0  recursive calls
          0  db block gets
    8696435  consistent gets
          0  physical reads
          0  redo size
   86861789  bytes sent via SQL*Net to client
     110349  bytes received via SQL*Net from client
      10001  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
    1000000  rows processed

TKPROF Output:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch    10001     32.64      32.64          0    8696435          0     1000000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    10005     32.64      32.64          0    8696435          0     1000000

Misses in library cache during parse: 0
Parsing user id: 80 

Rows     Row Source Operation
-------  ---------------------------------------------------
1000000  NESTED LOOPS  (cr=8696435 pr=0 pw=0 time=258421 us)
1000000   NESTED LOOPS  (cr=7696435 pr=0 pw=0 time=239249 us cost=8008211 size=888000000 card=1000000)
1000000    NESTED LOOPS  (cr=7457834 pr=0 pw=0 time=219902 us cost=7007667 size=777000000 card=1000000)
1000000     NESTED LOOPS  (cr=6219233 pr=0 pw=0 time=185868 us cost=6007124 size=666000000 card=1000000)
1000000      NESTED LOOPS  (cr=4980632 pr=0 pw=0 time=151577 us cost=5006580 size=555000000 card=1000000)
1000000       NESTED LOOPS  (cr=3742031 pr=0 pw=0 time=117680 us cost=4006037 size=444000000 card=1000000)
1000000        NESTED LOOPS  (cr=2503430 pr=0 pw=0 time=83916 us cost=3005494 size=333000000 card=1000000)
1000000         NESTED LOOPS  (cr=1264829 pr=0 pw=0 time=49146 us cost=2004950 size=222000000 card=1000000)
1000000          TABLE ACCESS FULL T5 (cr=26228 pr=0 pw=0 time=5678 us cost=4407 size=111000000 card=1000000)
1000000          TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=2 size=111 card=1)
1000000           INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000         TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000          INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000        TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000         INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000       TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000        INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000      TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000       INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000     TABLE ACCESS BY INDEX ROWID T5 (cr=1238601 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000      INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000    INDEX UNIQUE SCAN SYS_C0015042 (cr=238601 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74553)
1000000   TABLE ACCESS BY INDEX ROWID T5 (cr=1000000 pr=0 pw=0 time=0 us cost=1 size=111 card=1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   10001        0.00          0.01
  SQL*Net message from client                 10001        0.01         83.33
  SQL*Net more data to client                 10000        0.00          0.27

From the above we see that the 1,000,000 rows were returned to the client almost 3 seconds faster than before with essentially no change in the SQL*Net message from client wait – the statistics show that the CPU time was reduced by almost 3 seconds.  Great – the next time my SQL statement is burning CPU, I’ll just run 40 other CPU consuming processes to make my SQL statement run faster.  :-)  (Nehalem magic?)

I am sure a couple of people are fans of running Oracle on Windows, so let’s try the test on Oracle 11.1.0.7 running on 64 bit Windows with no other CPU load:

1000000 rows selected.

Elapsed: 00:01:38.40

Statistics
---------------------------------------------------
          1  recursive calls
          0  db block gets
    8695518  consistent gets
          0  physical reads
          0  redo size
   86861789  bytes sent via SQL*Net to client
     110349  bytes received via SQL*Net from client
      10001  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
    1000000  rows processed

TKPROF Output:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.07       0.09          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch    10001     12.23      12.93          0    8695518          0     1000000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    10003     12.30      13.02          0    8695518          0     1000000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 56 

Rows     Row Source Operation
-------  ---------------------------------------------------
1000000  NESTED LOOPS  (cr=8695518 pr=0 pw=0 time=187370 us)
1000000   NESTED LOOPS  (cr=7695518 pr=0 pw=0 time=156136 us cost=8008160 size=888000000 card=1000000)
1000000    NESTED LOOPS  (cr=7457048 pr=0 pw=0 time=156136 us cost=7007623 size=777000000 card=1000000)
1000000     NESTED LOOPS  (cr=6218578 pr=0 pw=0 time=156136 us cost=6007087 size=666000000 card=1000000)
1000000      NESTED LOOPS  (cr=4980108 pr=0 pw=0 time=31242 us cost=5006551 size=555000000 card=1000000)
1000000       NESTED LOOPS  (cr=3741638 pr=0 pw=0 time=31242 us cost=4006015 size=444000000 card=1000000)
1000000        NESTED LOOPS  (cr=2503168 pr=0 pw=0 time=0 us cost=3005479 size=333000000 card=1000000)
1000000         NESTED LOOPS  (cr=1264698 pr=0 pw=0 time=0 us cost=2004943 size=222000000 card=1000000)
1000000          TABLE ACCESS FULL T5 (cr=26228 pr=0 pw=0 time=0 us cost=4407 size=111000000 card=1000000)
1000000          TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=2 size=111 card=1)
1000000           INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000         TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000          INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000        TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000         INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000       TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000        INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000      TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000       INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000     TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000      INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000    INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000   TABLE ACCESS BY INDEX ROWID T5 (cr=1000000 pr=0 pw=0 time=0 us cost=1 size=111 card=1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   10001        0.00          0.00
  SQL*Net message from client                 10001        0.01         84.86
  SQL*Net more data to client                 10000        0.00          0.42

Nice, completed 21.5 seconds faster than the no load test on Linux/Oracle 11.1.0.6 running on the same hardware, even with a hard parse.  The CPU utilization is also 1/3 of the Linux test results. 

Now let’s load up the server with 40 CPU consuming processes using the VBS script found on page 197 of the Expert Oracle Practices book.  The test results follow:

1000000 rows selected.

Elapsed: 00:01:47.39

Statistics
---------------------------------------------------
          0  recursive calls
          0  db block gets
    8695518  consistent gets
          0  physical reads
          0  redo size
   86861789  bytes sent via SQL*Net to client
     110349  bytes received via SQL*Net from client
      10001  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
    1000000  rows processed

TKPROF Output:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch    10001     22.24      22.49          0    8695518          0     1000000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    10003     22.24      22.49          0    8695518          0     1000000

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 56 

Rows     Row Source Operation
-------  ---------------------------------------------------
1000000  NESTED LOOPS  (cr=8695518 pr=0 pw=0 time=280798 us)
1000000   NESTED LOOPS  (cr=7695518 pr=0 pw=0 time=249598 us cost=8008160 size=888000000 card=1000000)
1000000    NESTED LOOPS  (cr=7457048 pr=0 pw=0 time=218398 us cost=7007623 size=777000000 card=1000000)
1000000     NESTED LOOPS  (cr=6218578 pr=0 pw=0 time=218398 us cost=6007087 size=666000000 card=1000000)
1000000      NESTED LOOPS  (cr=4980108 pr=0 pw=0 time=187198 us cost=5006551 size=555000000 card=1000000)
1000000       NESTED LOOPS  (cr=3741638 pr=0 pw=0 time=155998 us cost=4006015 size=444000000 card=1000000)
1000000        NESTED LOOPS  (cr=2503168 pr=0 pw=0 time=124799 us cost=3005479 size=333000000 card=1000000)
1000000         NESTED LOOPS  (cr=1264698 pr=0 pw=0 time=31200 us cost=2004943 size=222000000 card=1000000)
1000000          TABLE ACCESS FULL T5 (cr=26228 pr=0 pw=0 time=0 us cost=4407 size=111000000 card=1000000)
1000000          TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=2 size=111 card=1)
1000000           INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000         TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000          INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000        TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000         INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000       TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000        INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000      TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000       INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000     TABLE ACCESS BY INDEX ROWID T5 (cr=1238470 pr=0 pw=0 time=0 us cost=1 size=111 card=1)
1000000      INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000    INDEX UNIQUE SCAN SYS_C0016378 (cr=238470 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 70312)
1000000   TABLE ACCESS BY INDEX ROWID T5 (cr=1000000 pr=0 pw=0 time=0 us cost=1 size=111 card=1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   10001        0.00          0.00
  SQL*Net message from client                 10001        0.01         83.55
  SQL*Net more data to client                 10000        0.00          0.59

The Windows test required an extra 9 seconds of CPU time when 40 processes were competing for the CPUs.  The CPU time for the fetch calls increased by 10 seconds over the test run with no competing processes.  Interestingly, the SQL*Net message from client wait decreased by a second during the test run with the increased CPU usage; I suppose that this might be expected considering that the next request from the client might have arrived while the Oracle thread was waiting in the CPU run queue.  Even with the additional 10 seconds of CPU time, the CPU  time consumed was still 10.5 seconds lower than that experienced with the Linux and Oracle 11.1.0.6 combination.  So, is the drop in CPU utilization an improvement in Oracle 11.1.0.7 that yielded better CPU times (you probably saw what happened when the same SQL statement was executed during yesterday’s blog article), is 64 bit Windows just that much more efficient than 64 bit Linux, or do you think that it was the 917 consistent get decrease that allowed Windows to complete the SQL statement faster than Linux?

The above test seems to indicate that Oracle on Linux does not include the time the process spent waiting in the CPU run queue when there is a lot of competition for CPU time – the fact that the rows returned to the client faster when the server was under a load probably means that more testing is required.  The above also seems to indicate that Oracle on Windows does inflate the CPU time statistic when competition for CPU time increases, but of course more testing should probably be performed.  So, why the recent increased interest in the CPU statistics in a trace file?  This OTN thread perked my interest.








Follow

Get every new post delivered to your Inbox.

Join 141 other followers