June 8, 2011
I have not had published a “What is Wrong with this Quote” blog article for a couple of months, so I thought that I would publish a few of those types of articles.
The first quote is from the Alpha copy of the book “Oracle 11g Performance Tuning Recipes”, recipe 5-7 Resolving Log File Sync Waits. As always, I try to minimize the amount of text that I post for a quote, but a sufficient amount so that the context of the quote is not completely lost. The quote:
“As the log file sync wait event is caused by contention caused by the LGWR process, see if you can use the NOLOGGING option to get rid of these waits. Of course, in a production system, you can’t use the NOLOGGING option when the database is processing user requests, so this option is of limited use in most cases.”
“Although the database automatically calculates the value of the log_io_size parameter, you can specify a value for it, by issuing a command such as the following:
SQL> alter system set "_log_io_size"=1024000 scope=spfile; System altered. "
What, if anything, is wrong with the above quote?
Hint for the first half of the quote: AskTom, Documentation
Hint for the second half of the quote: The scale for the _log_io_size parameter is NOT bytes. This article may also be helpful.
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.

I see that several people have started working on a response for this article, having visited the AskTom and Documentation link. How about another hint for the second half of the quote, looking at the value of that parameter for Oracle Database 10.2.0.2 and 11.2.0.2:
10.2.0.2:
11.2.0.2:
Without checking your reference, I’d say we have still redo-information. I’d expect all the redo needed for UNDO TS/blocks is not affected by NOLOGGING at all?
For the 2nd part: as you showed this parameter as “redo blocks” (512 or 1024 byte, I guess; depends on OS?) I’d say 1/2 or 1GB is big. I just did not find a reference to the size of _log_io_size in the quote – so why did you ask ?
Now I’m going to read your links
Martin,
I think that there is still more to say about the second half, and the first half for that matter. Thanks for setting the foundation upon which other people will likely add.
I think that I have about half of a page of typed review notes for recipe 5-7 (this is NOT a good sign) – I hope that this section of the book is still a work in process. Regarding the “redo block” size, yes, although I thought that I heard that the “redo block” size was set to change soon to 4096 bytes. Reference to the book “Oracle Wait Interface: a Practical Guide to Performance Diagnostics & Tuning” regarding this parameter:
http://books.google.com/books?id=14OmJzfCfXMC&pg=PA137#v=onepage&q&f=false
True, the book (in this case) did not tell the reader to modify a hidden initialization parameter without warning – it described a non-existent parameter, and then demonstrated why people should not just modify those parameters on a whim.
Using just remnants of what I once (2001) learned from ixora.co.au:
> As the log file sync wait event is caused by contention caused by the LGWR process,
Wrong. This event is caused by either a session issuing a commit, or DBWR wanting to checkpoint a block. LGWR just does the work.
> see if you can use the NOLOGGING option to get rid of these waits.
Wrong. See above – the rate of redo generation has nothing to do with ‘log file sync’ waits. Rate of commits does. Place open your database in read-only mode, and you will get rid of these (and many other) events.
Unclear: what does “use the NOLOGGING option” mean? Is this explained in the surrounding text/chapters?
>Of course, in a production system, you can’t use the NOLOGGING option when the database is processing user requests,
Unclear: why not?
>so this option is of limited use in most cases
That might be true, depending on the value of “most” and the definition of “use”. If “use” is “get rid of log file sync waits”, then “most” should be 0 for this to be correct.
And does it say why one might want to get rid of ‘log file sync’ waits? These are pretty harmless waits in most (>>0) cases, I think.
Am I missing the point of the post again?
Cheers,
Flado
Flado,
Well stated, and combined with the comment provided by Martin probably 90% of the thoughts that ran through my mind when I read these two quotes have been covered. The “NOLOGGING option” was not defined in the book, so I made an assumption that the authors intended the “NOLOGGING” keyword in the CREATE TABLE and INSERT INTO … SELECT statement found in this comment:
http://hoopercharles.wordpress.com/2011/06/07/vsessions-row_wait_obj-column-shows-the-data_object_id-verify-the-documentation-challenge/#comment-3420
It suprised me a bit to see the session waiting on “log buffer space” and “log file switch completion” wait events considering that this particular 11.2.0.2 test database is running with:
Why can’t I use that NOLOGGING keyword when other users are adding or updating data in the same database – a database typically has more than one table, right? Finally, is it the database that processes the user requests, or is a database a set of files on disk?
Why would it surprise you that a NOARCHIVELOG database can experience these two waits? Log buffer operations have nothing to do with log file archiving. “log buffer space” only means that there is currently no space in the buffer, so the session has to wait for LGWR to flush it. “log file switch completion” is a variant of “log buffer space” specifying the reason why there’s no space in the buffer (because LGWR is busy switching the log file). In turn, there are two variants of “log file switch completion”, detailing just why it takes so long to switch the file – “log file switch completion (checkpoint incomplete)” and “log file switch completion (archiving needed)”. Of all these, it’s only the last one I would be surprised to see in a NOARCHIVELOG database. In your test, session 1 was generating redo at an alarming rate, so I would consider it normal for it to hit those two events from time to time.
http://www.ixora.com.au/notes/
This is the best explanation of redo internals I have ever seen. Ten years ago (don’t believe the timestamp on that page – The Wayback Machine has crawled it as early as Jan 2002) these notes made me realize that there is no mystery in how Oracle works and it is just a program built using the same building blocks as the programs I was writing at the time. I’d buy Steve Adams a beer were I to ever meet him
Cheers,
Flado
Flado,
There is always the chance that I am misunderstanding something (or overlooking an important detail).
http://download.oracle.com/docs/cd/E18283_01/server.112/e10578/tdpdw_bandr.htm#BFGIJDAH
So, a NOLOGGING operation should generate minimal redo, and that is why I was surprised to see “log buffer space” and “log file switch completion” waits. Did I by chance incorrectly specify NOLOGGING, this is the SQL statement (did I need an APPEND hint to make the NOLOGGING specication have an effect?):
The AskTom article linked at the start of this blog article includes the following quote:
As I stated, there is always the chance that I am misunderstanding something (or overlooking an important detail).
Yes, I think you need /*+ append */ if you want the absolute minimum of redo generated (that for moving the HWM and associated undo, plus eventual delayed block cleanouts on the dictionary tables). Conventional insert with nologging still generates undo which needs redo.
Or I may have overlooked yet another detail and you did generate just a tiny bit of redo but had the bad luck of filling up the last buffer before the switch :-/
Anyway, if you repeat the test (just Session 1) with autotrace on, it should indeed be easy to see.
Cheers,
Flado
Flado,
Good suggestion. See the script below and the output… “ORA-12838: cannot read/modify an object after modifying it in parallel” triggered by AUTOTRACE.
Duplicate previous script:
SET AUTOTRACE ON SPOOL WATCHREDO.TXT DROP TABLE T1 PURGE; SET LINESIZE 140 SET PAGESIZE 1000 SET ARRAYSIZE 1000 COLUMN EVENT FORMAT A30 SELECT EVENT, TOTAL_WAITS, TIME_WAITED, TOTAL_TIMEOUTS FROM V$SESSION_EVENT WHERE WAIT_CLASS'Idle' AND TOTAL_WAITS>0 AND SID= (SELECT SID FROM V$MYSTAT WHERE ROWNUM=1) ORDER BY EVENT; CREATE TABLE T1 NOLOGGING AS SELECT * FROM DBA_OBJECTS; TRUNCATE TABLE T1; INSERT INTO T1 NOLOGGING SELECT DO.* FROM (SELECT * FROM DBA_OBJECTS) DO, (SELECT ROWNUM RN FROM DUAL CONNECT BY LEVEL <=500) D; SELECT EVENT, TOTAL_WAITS, TIME_WAITED, TOTAL_TIMEOUTS FROM V$SESSION_EVENT WHERE WAIT_CLASS'Idle' AND TOTAL_WAITS>0 AND SID= (SELECT SID FROM V$MYSTAT WHERE ROWNUM=1) ORDER BY EVENT; SELECT EVENT, TOTAL_WAITS, TIME_WAITED, TOTAL_TIMEOUTS FROM V$SESSION_EVENT WHERE WAIT_CLASS'Idle' AND TOTAL_WAITS>0 AND SID= (SELECT SID FROM V$MYSTAT WHERE ROWNUM=1) ORDER BY EVENT; SPOOL OFF EXITDuplicate previous script with APPEND hint:
SET AUTOTRACE ON SPOOL WATCHREDO2.TXT DROP TABLE T1 PURGE; SET LINESIZE 140 SET PAGESIZE 1000 SET ARRAYSIZE 1000 COLUMN EVENT FORMAT A30 SELECT EVENT, TOTAL_WAITS, TIME_WAITED, TOTAL_TIMEOUTS FROM V$SESSION_EVENT WHERE WAIT_CLASS'Idle' AND TOTAL_WAITS>0 AND SID= (SELECT SID FROM V$MYSTAT WHERE ROWNUM=1) ORDER BY EVENT; CREATE TABLE T1 NOLOGGING AS SELECT * FROM DBA_OBJECTS; TRUNCATE TABLE T1; INSERT /*+ APPEND */ INTO T1 NOLOGGING SELECT DO.* FROM (SELECT * FROM DBA_OBJECTS) DO, (SELECT ROWNUM RN FROM DUAL CONNECT BY LEVEL <=500) D; SELECT EVENT, TOTAL_WAITS, TIME_WAITED, TOTAL_TIMEOUTS FROM V$SESSION_EVENT WHERE WAIT_CLASS'Idle' AND TOTAL_WAITS>0 AND SID= (SELECT SID FROM V$MYSTAT WHERE ROWNUM=1) ORDER BY EVENT; SELECT EVENT, TOTAL_WAITS, TIME_WAITED, TOTAL_TIMEOUTS FROM V$SESSION_EVENT WHERE WAIT_CLASS'Idle' AND TOTAL_WAITS>0 AND SID= (SELECT SID FROM V$MYSTAT WHERE ROWNUM=1) ORDER BY EVENT; SPOOL OFF EXITThe output will follow.
Duplicate previous script output:
SQL> SQL> DROP TABLE T1 PURGE; DROP TABLE T1 PURGE * ERROR at line 1: ORA-00942: table or view does not exist SQL> SQL> SET LINESIZE 140 SQL> SET PAGESIZE 1000 SQL> SET ARRAYSIZE 1000 SQL> COLUMN EVENT FORMAT A30 SQL> SQL> SELECT 2 EVENT, 3 TOTAL_WAITS, 4 TIME_WAITED, 5 TOTAL_TIMEOUTS 6 FROM 7 V$SESSION_EVENT 8 WHERE 9 WAIT_CLASS<>'Idle' 10 AND TOTAL_WAITS>0 11 AND SID= 12 (SELECT 13 SID 14 FROM 15 V$MYSTAT 16 WHERE 17 ROWNUM=1) 18 ORDER BY 19 EVENT; EVENT TOTAL_WAITS TIME_WAITED TOTAL_TIMEOUTS ------------------------------ ----------- ----------- -------------- Disk file operations I/O 1 0 0 SQL*Net break/reset to client 2 0 0 SQL*Net message to client 32 0 0 log file sync 1 0 0 Execution Plan ---------------------------------------------------------- Plan hash value: 476136829 --------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 406 | 23548 | 123 (100)| 00:00:01 | | 1 | SORT ORDER BY | | 406 | 23548 | 123 (100)| 00:00:01 | | 2 | NESTED LOOPS | | 406 | 23548 | 122 (100)| 00:00:01 | |* 3 | FIXED TABLE FULL | X$KSLES | 406 | 8120 | 121 (100)| 00:00:01 | |* 4 | COUNT STOPKEY | | | | | | |* 5 | FIXED TABLE FULL | X$KSUMYSTA | 1 | 20 | 0 (0)| 00:00:01 | | 6 | FIXED TABLE FULL | X$KSUSGIF | 1 | 4 | 0 (0)| 00:00:01 | |* 7 | FIXED TABLE FIXED INDEX| X$KSLED (ind:2) | 1 | 38 | 0 (0)| 00:00:01 | --------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 3 - filter("S"."KSLESWTS">0 AND "S"."KSLESWTS"<>0 AND "S"."INST_ID"=USERENV('INSTANCE') AND "S"."KSLESSID"= (SELECT "KSUSENUM" FROM SYS."X$KSUMYSTA" "X$KSUMYSTA" WHERE ROWNUM=1 AND BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF"))) 4 - filter(ROWNUM=1) 5 - filter(BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF")) 7 - filter("D"."KSLEDCLASS"<>'Idle' AND "S"."KSLESENM"="D"."INDX") Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 0 consistent gets 0 physical reads 0 redo size 651 bytes sent via SQL*Net to client 333 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 1 sorts (memory) 0 sorts (disk) 4 rows processed SQL> SQL> CREATE TABLE T1 NOLOGGING AS 2 SELECT 3 * 4 FROM 5 DBA_OBJECTS; Table created. SQL> SQL> TRUNCATE TABLE T1; Table truncated. SQL> SQL> INSERT INTO 2 T1 NOLOGGING 3 SELECT 4 DO.* 5 FROM 6 (SELECT * FROM DBA_OBJECTS) DO, 7 (SELECT ROWNUM RN FROM DUAL CONNECT BY LEVEL <=500) D; 32522500 rows created. Execution Plan ---------------------------------------------------------- Plan hash value: 582314787 ------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ------------------------------------------------------------------------------------------------- | 0 | INSERT STATEMENT | | 61212 | 12M| 108 (13)| 00:00:01 | | 1 | LOAD TABLE CONVENTIONAL | T1 | | | | | | 2 | MERGE JOIN CARTESIAN | | 61212 | 12M| 108 (13)| 00:00:01 | | 3 | VIEW | | 1 | | 2 (0)| 00:00:01 | | 4 | COUNT | | | | | | |* 5 | CONNECT BY WITHOUT FILTERING | | | | | | | 6 | FAST DUAL | | 1 | | 2 (0)| 00:00:01 | | 7 | BUFFER SORT | | 61212 | 12M| 108 (13)| 00:00:01 | | 8 | VIEW | DBA_OBJECTS | 61212 | 12M| 106 (14)| 00:00:01 | | 9 | UNION-ALL | | | | | | |* 10 | TABLE ACCESS BY INDEX ROWID | SUM$ | 1 | 11 | 1 (0)| 00:00:01 | |* 11 | INDEX UNIQUE SCAN | I_SUM$_1 | 1 | | 0 (0)| 00:00:01 | | 12 | TABLE ACCESS BY INDEX ROWID | OBJ$ | 1 | 30 | 3 (0)| 00:00:01 | |* 13 | INDEX RANGE SCAN | I_OBJ1 | 1 | | 2 (0)| 00:00:01 | |* 14 | FILTER | | | | | | |* 15 | HASH JOIN | | 65733 | 7638K| 100 (13)| 00:00:01 | | 16 | TABLE ACCESS FULL | USER$ | 177 | 2478 | 3 (0)| 00:00:01 | |* 17 | HASH JOIN | | 65733 | 6740K| 96 (13)| 00:00:01 | | 18 | INDEX FULL SCAN | I_USER2 | 177 | 3894 | 1 (0)| 00:00:01 | |* 19 | TABLE ACCESS FULL | OBJ$ | 65733 | 5327K| 93 (11)| 00:00:01 | |* 20 | TABLE ACCESS BY INDEX ROWID| IND$ | 1 | 8 | 2 (0)| 00:00:01 | |* 21 | INDEX UNIQUE SCAN | I_IND1 | 1 | | 1 (0)| 00:00:01 | | 22 | NESTED LOOPS | | 1 | 29 | 1 (0)| 00:00:01 | |* 23 | INDEX SKIP SCAN | I_USER2 | 1 | 20 | 1 (0)| 00:00:01 | |* 24 | INDEX RANGE SCAN | I_OBJ4 | 1 | 9 | 0 (0)| 00:00:01 | |* 25 | HASH JOIN | | 8 | 296 | 6 (17)| 00:00:01 | | 26 | TABLE ACCESS FULL | LINK$ | 8 | 184 | 2 (0)| 00:00:01 | | 27 | TABLE ACCESS FULL | USER$ | 177 | 2478 | 3 (0)| 00:00:01 | ------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 5 - filter(LEVEL<=500) 10 - filter(BITAND("S"."XPFLAGS",8388608)=8388608) 11 - access("S"."OBJ#"=:B1) 13 - access("EO"."OBJ#"=:B1) 14 - filter(("O"."TYPE#"<>1 AND "O"."TYPE#"<>10 OR "O"."TYPE#"=1 AND (SELECT 1 FROM "SYS"."IND$" "I" WHERE "I"."OBJ#"=:B1 AND ("I"."TYPE#"=1 OR "I"."TYPE#"=2 OR "I"."TYPE#"=3 OR "I"."TYPE#"=4 OR "I"."TYPE#"=6 OR "I"."TYPE#"=7 OR "I"."TYPE#"=9))=1) AND ("O"."TYPE#"<>4 AND "O"."TYPE#"<>5 AND "O"."TYPE#"<>7 AND "O"."TYPE#"<>8 AND "O"."TYPE#"<>9 AND "O"."TYPE#"<>10 AND "O"."TYPE#"<>11 AND "O"."TYPE#"<>12 AND "O"."TYPE#"<>13 AND "O"."TYPE#"<>14 AND "O"."TYPE#"<>22 AND "O"."TYPE#"<>87 AND "O"."TYPE#"<>88 OR BITAND("U"."SPARE1",16)=0 OR ("O"."TYPE#"=4 OR "O"."TYPE#"=5 OR "O"."TYPE#"=7 OR "O"."TYPE#"=8 OR "O"."TYPE#"=9 OR "O"."TYPE#"=10 OR "O"."TYPE#"=11 OR "O"."TYPE#"=12 OR "O"."TYPE#"=13 OR "O"."TYPE#"=14 OR "O"."TYPE#"=22 OR "O"."TYPE#"=87) AND ("U"."TYPE#"<>2 AND SYS_CONTEXT('userenv','current_edition_name')='ORA$BASE' OR "U"."TYPE#"=2 AND "U"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id')) OR EXISTS (SELECT 0 FROM SYS."USER$" "U2",SYS."OBJ$" "O2" WHERE "O2"."OWNER#"="U2"."USER#" AND "O2"."TYPE#"=88 AND "O2"."DATAOBJ#"=:B2 AND "U2"."TYPE#"=2 AND "U2"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_edition_id')))))) 15 - access("O"."SPARE3"="U"."USER#") 17 - access("O"."OWNER#"="U"."USER#") 19 - filter("O"."NAME"<>'_NEXT_OBJECT' AND "O"."NAME"<>'_default_auditing_options_' AND "O"."LINKNAME" IS NULL AND BITAND("O"."FLAGS",128)=0) 20 - filter("I"."TYPE#"=1 OR "I"."TYPE#"=2 OR "I"."TYPE#"=3 OR "I"."TYPE#"=4 OR "I"."TYPE#"=6 OR "I"."TYPE#"=7 OR "I"."TYPE#"=9) 21 - access("I"."OBJ#"=:B1) 23 - access("U2"."TYPE#"=2 AND "U2"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_e dition_id'))) filter("U2"."TYPE#"=2 AND "U2"."SPARE2"=TO_NUMBER(SYS_CONTEXT('userenv','current_e dition_id'))) 24 - access("O2"."DATAOBJ#"=:B1 AND "O2"."TYPE#"=88 AND "O2"."OWNER#"="U2"."USER#") 25 - access("L"."OWNER#"="U"."USER#") Statistics ---------------------------------------------------------- 2840 recursive calls 4000249 db block gets 904071 consistent gets 3 physical reads 3763502592 redo size 614 bytes sent via SQL*Net to client 584 bytes received via SQL*Net from client 4 SQL*Net roundtrips to/from client 4 sorts (memory) 0 sorts (disk) 32522500 rows processed SQL> SQL> SELECT 2 EVENT, 3 TOTAL_WAITS, 4 TIME_WAITED, 5 TOTAL_TIMEOUTS 6 FROM 7 V$SESSION_EVENT 8 WHERE 9 WAIT_CLASS<>'Idle' 10 AND TOTAL_WAITS>0 11 AND SID= 12 (SELECT 13 SID 14 FROM 15 V$MYSTAT 16 WHERE 17 ROWNUM=1) 18 ORDER BY 19 EVENT; EVENT TOTAL_WAITS TIME_WAITED TOTAL_TIMEOUTS ------------------------------ ----------- ----------- -------------- Disk file operations I/O 4 0 0 SQL*Net break/reset to client 2 0 0 SQL*Net message to client 65 0 0 SQL*Net more data to client 3 0 0 db file sequential read 22 6 0 direct path write 1 0 0 enq: RO - fast object reuse 2 0 0 events in waitclass Other 12 0 2 latch: cache buffers chains 1 0 0 local write wait 3 0 0 log buffer space 3 24 0 log file switch completion 10 80 0 log file sync 2 0 0 13 rows selected. Execution Plan ---------------------------------------------------------- Plan hash value: 476136829 --------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 406 | 23548 | 123 (100)| 00:00:01 | | 1 | SORT ORDER BY | | 406 | 23548 | 123 (100)| 00:00:01 | | 2 | NESTED LOOPS | | 406 | 23548 | 122 (100)| 00:00:01 | |* 3 | FIXED TABLE FULL | X$KSLES | 406 | 8120 | 121 (100)| 00:00:01 | |* 4 | COUNT STOPKEY | | | | | | |* 5 | FIXED TABLE FULL | X$KSUMYSTA | 1 | 20 | 0 (0)| 00:00:01 | | 6 | FIXED TABLE FULL | X$KSUSGIF | 1 | 4 | 0 (0)| 00:00:01 | |* 7 | FIXED TABLE FIXED INDEX| X$KSLED (ind:2) | 1 | 38 | 0 (0)| 00:00:01 | --------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 3 - filter("S"."KSLESWTS">0 AND "S"."KSLESWTS"<>0 AND "S"."INST_ID"=USERENV('INSTANCE') AND "S"."KSLESSID"= (SELECT "KSUSENUM" FROM SYS."X$KSUMYSTA" "X$KSUMYSTA" WHERE ROWNUM=1 AND BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF"))) 4 - filter(ROWNUM=1) 5 - filter(BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF")) 7 - filter("D"."KSLEDCLASS"<>'Idle' AND "S"."KSLESENM"="D"."INDX") Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 0 consistent gets 0 physical reads 0 redo size 951 bytes sent via SQL*Net to client 333 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 1 sorts (memory) 0 sorts (disk) 13 rows processed SQL> SQL> SELECT 2 EVENT, 3 TOTAL_WAITS, 4 TIME_WAITED, 5 TOTAL_TIMEOUTS 6 FROM 7 V$SESSION_EVENT 8 WHERE 9 WAIT_CLASS<>'Idle' 10 AND TOTAL_WAITS>0 11 AND SID= 12 (SELECT 13 SID 14 FROM 15 V$MYSTAT 16 WHERE 17 ROWNUM=1) 18 ORDER BY 19 EVENT; EVENT TOTAL_WAITS TIME_WAITED TOTAL_TIMEOUTS ------------------------------ ----------- ----------- -------------- Disk file operations I/O 4 0 0 SQL*Net break/reset to client 2 0 0 SQL*Net message to client 77 0 0 SQL*Net more data to client 4 0 0 db file sequential read 22 6 0 direct path write 1 0 0 enq: RO - fast object reuse 2 0 0 events in waitclass Other 12 0 2 latch: cache buffers chains 1 0 0 local write wait 3 0 0 log buffer space 3 24 0 log file switch completion 10 80 0 log file sync 2 0 0 13 rows selected. Execution Plan ---------------------------------------------------------- Plan hash value: 476136829 --------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 406 | 23548 | 123 (100)| 00:00:01 | | 1 | SORT ORDER BY | | 406 | 23548 | 123 (100)| 00:00:01 | | 2 | NESTED LOOPS | | 406 | 23548 | 122 (100)| 00:00:01 | |* 3 | FIXED TABLE FULL | X$KSLES | 406 | 8120 | 121 (100)| 00:00:01 | |* 4 | COUNT STOPKEY | | | | | | |* 5 | FIXED TABLE FULL | X$KSUMYSTA | 1 | 20 | 0 (0)| 00:00:01 | | 6 | FIXED TABLE FULL | X$KSUSGIF | 1 | 4 | 0 (0)| 00:00:01 | |* 7 | FIXED TABLE FIXED INDEX| X$KSLED (ind:2) | 1 | 38 | 0 (0)| 00:00:01 | --------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 3 - filter("S"."KSLESWTS">0 AND "S"."KSLESWTS"<>0 AND "S"."INST_ID"=USERENV('INSTANCE') AND "S"."KSLESSID"= (SELECT "KSUSENUM" FROM SYS."X$KSUMYSTA" "X$KSUMYSTA" WHERE ROWNUM=1 AND BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF"))) 4 - filter(ROWNUM=1) 5 - filter(BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF")) 7 - filter("D"."KSLEDCLASS"<>'Idle' AND "S"."KSLESENM"="D"."INDX") Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 0 consistent gets 0 physical reads 0 redo size 951 bytes sent via SQL*Net to client 333 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 1 sorts (memory) 0 sorts (disk) 13 rows processed SQL> SQL> SPOOL OFFDuplicate previous script with APPEND hint output:
SQL> SQL> DROP TABLE T1 PURGE; Table dropped. SQL> SQL> SET LINESIZE 140 SQL> SET PAGESIZE 1000 SQL> SET ARRAYSIZE 1000 SQL> COLUMN EVENT FORMAT A30 SQL> SQL> SELECT 2 EVENT, 3 TOTAL_WAITS, 4 TIME_WAITED, 5 TOTAL_TIMEOUTS 6 FROM 7 V$SESSION_EVENT 8 WHERE 9 WAIT_CLASS<>'Idle' 10 AND TOTAL_WAITS>0 11 AND SID= 12 (SELECT 13 SID 14 FROM 15 V$MYSTAT 16 WHERE 17 ROWNUM=1) 18 ORDER BY 19 EVENT; EVENT TOTAL_WAITS TIME_WAITED TOTAL_TIMEOUTS ------------------------------ ----------- ----------- -------------- Disk file operations I/O 3 0 0 SQL*Net message to client 32 0 0 db file sequential read 20 6 0 enq: RO - fast object reuse 1 12 0 events in waitclass Other 3 0 0 log file sync 1 0 0 6 rows selected. Execution Plan ---------------------------------------------------------- Plan hash value: 476136829 --------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 406 | 23548 | 123 (100)| 00:00:01 | | 1 | SORT ORDER BY | | 406 | 23548 | 123 (100)| 00:00:01 | | 2 | NESTED LOOPS | | 406 | 23548 | 122 (100)| 00:00:01 | |* 3 | FIXED TABLE FULL | X$KSLES | 406 | 8120 | 121 (100)| 00:00:01 | |* 4 | COUNT STOPKEY | | | | | | |* 5 | FIXED TABLE FULL | X$KSUMYSTA | 1 | 20 | 0 (0)| 00:00:01 | | 6 | FIXED TABLE FULL | X$KSUSGIF | 1 | 4 | 0 (0)| 00:00:01 | |* 7 | FIXED TABLE FIXED INDEX| X$KSLED (ind:2) | 1 | 38 | 0 (0)| 00:00:01 | --------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 3 - filter("S"."KSLESWTS">0 AND "S"."KSLESWTS"<>0 AND "S"."INST_ID"=USERENV('INSTANCE') AND "S"."KSLESSID"= (SELECT "KSUSENUM" FROM SYS."X$KSUMYSTA" "X$KSUMYSTA" WHERE ROWNUM=1 AND BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF"))) 4 - filter(ROWNUM=1) 5 - filter(BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF")) 7 - filter("D"."KSLEDCLASS"<>'Idle' AND "S"."KSLESENM"="D"."INDX") Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 0 consistent gets 0 physical reads 0 redo size 723 bytes sent via SQL*Net to client 333 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 1 sorts (memory) 0 sorts (disk) 6 rows processed SQL> SQL> CREATE TABLE T1 NOLOGGING AS 2 SELECT 3 * 4 FROM 5 DBA_OBJECTS; Table created. SQL> SQL> TRUNCATE TABLE T1; Table truncated. SQL> SQL> INSERT /*+ APPEND */ INTO 2 T1 NOLOGGING 3 SELECT 4 DO.* 5 FROM 6 (SELECT * FROM DBA_OBJECTS) DO, 7 (SELECT ROWNUM RN FROM DUAL CONNECT BY LEVEL <=500) D; 32522500 rows created. Execution Plan ---------------------------------------------------------- ERROR: ORA-12838: cannot read/modify an object after modifying it in parallel SP2-0612: Error generating AUTOTRACE EXPLAIN report Statistics ---------------------------------------------------------- 2443 recursive calls 469360 db block gets 3335 consistent gets 2 physical reads 1993800 redo size 601 bytes sent via SQL*Net to client 598 bytes received via SQL*Net from client 4 SQL*Net roundtrips to/from client 4 sorts (memory) 0 sorts (disk) 32522500 rows processed SQL> SQL> SELECT 2 EVENT, 3 TOTAL_WAITS, 4 TIME_WAITED, 5 TOTAL_TIMEOUTS 6 FROM 7 V$SESSION_EVENT 8 WHERE 9 WAIT_CLASS<>'Idle' 10 AND TOTAL_WAITS>0 11 AND SID= 12 (SELECT 13 SID 14 FROM 15 V$MYSTAT 16 WHERE 17 ROWNUM=1) 18 ORDER BY 19 EVENT; EVENT TOTAL_WAITS TIME_WAITED TOTAL_TIMEOUTS ------------------------------ ----------- ----------- -------------- Disk file operations I/O 4 0 0 SQL*Net break/reset to client 2 0 0 SQL*Net message to client 60 0 0 SQL*Net more data to client 1 0 0 db file sequential read 33 8 0 direct path write 9 0 0 enq: RO - fast object reuse 3 12 0 events in waitclass Other 7 0 2 local write wait 3 0 0 log file sync 3 0 0 10 rows selected. Execution Plan ---------------------------------------------------------- Plan hash value: 476136829 --------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 406 | 23548 | 123 (100)| 00:00:01 | | 1 | SORT ORDER BY | | 406 | 23548 | 123 (100)| 00:00:01 | | 2 | NESTED LOOPS | | 406 | 23548 | 122 (100)| 00:00:01 | |* 3 | FIXED TABLE FULL | X$KSLES | 406 | 8120 | 121 (100)| 00:00:01 | |* 4 | COUNT STOPKEY | | | | | | |* 5 | FIXED TABLE FULL | X$KSUMYSTA | 1 | 20 | 0 (0)| 00:00:01 | | 6 | FIXED TABLE FULL | X$KSUSGIF | 1 | 4 | 0 (0)| 00:00:01 | |* 7 | FIXED TABLE FIXED INDEX| X$KSLED (ind:2) | 1 | 38 | 0 (0)| 00:00:01 | --------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 3 - filter("S"."KSLESWTS">0 AND "S"."KSLESWTS"<>0 AND "S"."INST_ID"=USERENV('INSTANCE') AND "S"."KSLESSID"= (SELECT "KSUSENUM" FROM SYS."X$KSUMYSTA" "X$KSUMYSTA" WHERE ROWNUM=1 AND BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF"))) 4 - filter(ROWNUM=1) 5 - filter(BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF")) 7 - filter("D"."KSLEDCLASS"<>'Idle' AND "S"."KSLESENM"="D"."INDX") Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 0 consistent gets 0 physical reads 0 redo size 852 bytes sent via SQL*Net to client 333 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 1 sorts (memory) 0 sorts (disk) 10 rows processed SQL> SQL> SELECT 2 EVENT, 3 TOTAL_WAITS, 4 TIME_WAITED, 5 TOTAL_TIMEOUTS 6 FROM 7 V$SESSION_EVENT 8 WHERE 9 WAIT_CLASS<>'Idle' 10 AND TOTAL_WAITS>0 11 AND SID= 12 (SELECT 13 SID 14 FROM 15 V$MYSTAT 16 WHERE 17 ROWNUM=1) 18 ORDER BY 19 EVENT; EVENT TOTAL_WAITS TIME_WAITED TOTAL_TIMEOUTS ------------------------------ ----------- ----------- -------------- Disk file operations I/O 4 0 0 SQL*Net break/reset to client 2 0 0 SQL*Net message to client 72 0 0 SQL*Net more data to client 2 0 0 db file sequential read 33 8 0 direct path write 9 0 0 enq: RO - fast object reuse 3 12 0 events in waitclass Other 7 0 2 local write wait 3 0 0 log file sync 3 0 0 10 rows selected. Execution Plan ---------------------------------------------------------- Plan hash value: 476136829 --------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 406 | 23548 | 123 (100)| 00:00:01 | | 1 | SORT ORDER BY | | 406 | 23548 | 123 (100)| 00:00:01 | | 2 | NESTED LOOPS | | 406 | 23548 | 122 (100)| 00:00:01 | |* 3 | FIXED TABLE FULL | X$KSLES | 406 | 8120 | 121 (100)| 00:00:01 | |* 4 | COUNT STOPKEY | | | | | | |* 5 | FIXED TABLE FULL | X$KSUMYSTA | 1 | 20 | 0 (0)| 00:00:01 | | 6 | FIXED TABLE FULL | X$KSUSGIF | 1 | 4 | 0 (0)| 00:00:01 | |* 7 | FIXED TABLE FIXED INDEX| X$KSLED (ind:2) | 1 | 38 | 0 (0)| 00:00:01 | --------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 3 - filter("S"."KSLESWTS">0 AND "S"."KSLESWTS"<>0 AND "S"."INST_ID"=USERENV('INSTANCE') AND "S"."KSLESSID"= (SELECT "KSUSENUM" FROM SYS."X$KSUMYSTA" "X$KSUMYSTA" WHERE ROWNUM=1 AND BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF"))) 4 - filter(ROWNUM=1) 5 - filter(BITAND("KSSPAFLG",1)<>0 AND BITAND("KSUSEFLG",1)<>0 AND "INST_ID"=USERENV('INSTANCE') AND "KSUSESTN"< (SELECT "KSUSGSTL" FROM SYS."X$KSUSGIF" "X$KSUSGIF")) 7 - filter("D"."KSLEDCLASS"<>'Idle' AND "S"."KSLESENM"="D"."INDX") Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 0 consistent gets 0 physical reads 0 redo size 852 bytes sent via SQL*Net to client 333 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 1 sorts (memory) 0 sorts (disk) 10 rows processed SQL> SQL> SPOOL OFFYeah – generating redo at an alarming rate (3.7 GB per execution, if I’m counting correctly on the phone)
Or am I missing something again?
I vaguely remember that a nologging operation would generate something called “invalidation redo” in a way that a direct load wouldn’t, but that may be a myth or an obsolete state of affairs. Do you know something about that?
Flado,
Yes, roughly 3.7GB, decreased to roughly 2MB with the APPEND hint.
I do not know enough about “invalidation redo” to answer yes or no, so I did a bit of a Google search.
A quick check of the test table and another table in the database:
One of the first threads that mentioned “invalidation redo”:
http://www.freelists.org/post/oracle-l/Tracking-down-NOLOGGING-objects,9
Riyaj Shamsudeen
How to find objects creating nologging changes?
http://orainternals.wordpress.com/2008/09/11/how-to-find-objects-creating-nologging-changes/
Riyaj Shamsudeen
REDO INTERNALS AND TUNING BY REDO REDUCTION
http://www.orainternals.com/papers/riyaj_redo_internals_and_tuning_by_redo_reduction_doc.pdf
Riyaj Shamsudeen
Debunking the myths about redo, undo, commit & rollback
http://www.orainternals.com/papers/riyaj_debunking_myths_about_redo_ppt.pdf
http://download.oracle.com/docs/cd/E11882_01/server.112/e16541/parallel007.htm