Oracle Scratchpad

January 6, 2014

LOB changes

Filed under: Infrastructure,LOBs,Oracle,Troubleshooting — Jonathan Lewis @ 7:10 pm BST Jan 6,2014

It’s always useful to collect baseline information – especially when it helps you notice that the baseline has moved in a way that might explain the next performance problem you see. Here’s an example demonstrating the benefit.

I have a table with a LOB column that is stored out of line. Many years ago I decided that I wanted to compare how the redo generation varied as I change the LOB from cached to nocache (with nologging). So here was one of my simplest test scripts (stripped to a minimum):


create table t1 (
	id		number,
	cached_lob	clob
)
lob (cached_lob) store as text_lob_cache(
	disable storage in row
	cache
--	nocache logging
)
;

insert into t1
select
	rownum,
	rpad('x',4000)
from
	all_objects
where
	rownum <= 1000
;

When I first ran this test (twice, one for each option) I noticed that cached LOBs recorded just the redo needed to describe the data that had been written into them (so at 1,000 rows of 4KB each that would be in the ballpark of 4MB with some overheads), but the nocache option created redo for the entire block (so nearer 8MB, plus overheads). There were, of course, all sorts of other side effects of the change – some of them very nasty – but this was one of the more important differences to note.

A little while ago I was prompted to repeat the test – so I ran the whole thing three times on 10.2.0.5, 11.2.0.4, and 12.1.0.1; it’s fascinating to see the way the key redo stats change:


10.2.0.5
========
CACHE
Name                                                                     Value
----                                                                     -----
redo entries                                                             5,588
redo size                                                            5,288,836

NOCACHE
redo entries                                                             5,578
redo size                                                            9,407,824

11.2.0.1
========
CACHE
redo entries                                                             5,223
redo size                                                            5,277,520

NOCACHE
redo entries                                                             5,220
redo size                                                            1,212,992
redo size for direct writes                                             52,000

12.1.0.1
========
CACHE
redo entries                                                             5,231
redo size                                                            9,343,444

NOCACHE
redo entries                                                             5,291
redo size                                                            1,301,700
redo size for direct writes                                             60,000

As you can see the 10.2.0.5 results mirror the first results I got – the redo size is consistent with the volume of data when the LOBs are cached, and matches whole block dumps when they’re not cached – but something very clever seems to appear in the 11.2.0.5 results – the redo for the lob component of nocache LOBs seems to have disappeared – there’s a drop of (roughly) 8,192,000 bytes from the 10g figures: is this a clever trick (filesystem-like logging ?) or is it a reporting error. Then 12c is even stranger – the redo for the cached LOBs now matches block logging (8MB + overheads) instead of data logging – and the redo for the nocache LOBs is still “missing”.

To be investigated further – possibly by dumping redo log files, but initially simply by watching when log file switches take place – to see if the changes are reporting errors or genuine changes.

8 Comments »

  1. For your further investigation I wonder whether the slender redo NOCACHE might employ some pre-redo generation compression whereas perhaps CACHE does not (completely untested wondering, buy hey, you mentioned further investigation.)

    Comment by rsiz — January 6, 2014 @ 7:38 pm BST Jan 6,2014 | Reply

    • One significant difference between 12c and prior to 12c is that 12c uses SECURFILE by default and previous versions BASICFILE. I guess your tests are in NOARCHIVELOG mode, right? Because in ARCHIVELOG mode there was no difference between CACHE and NOCACHE.

      Comment by Husqvik — January 6, 2014 @ 8:22 pm BST Jan 6,2014 | Reply

      • Husqvik,

        Thanks for that. You’re right about archiving – all three databases were in noarchivelog mode, which would explain the missing 8MB. Was your comment only about the 12c results, or does 11g do the same ? (I would guess that this might be true, since the same elimination of redo appeared for index create and rebuild in 11gR2 http://jonathanlewis.wordpress.com/2012/05/28/ch-ch-ch-ch-changes/ )

        In my case the tablespace I happened to be using was using freelist management rather than ASSM, so the LOBs were BASICFILE (ASSM being a requirement for SECUREFILE). Interestingly, when I switched to an ASSM tablespace in 12c I got 2,000 TX enqueue gets and releases, and 2.5GB of “logical bytes read from cache” for the nocache example – so that’s a whole new anomaly to investigate. It’s possible the scale may be associated with the extent management mechanism and extent sizes.

        The only outstanding anomaly, then, is why cached LOBs in 12c BASICFILES no longer follow the 11g “data only” optimization.

        Comment by Jonathan Lewis — January 6, 2014 @ 9:14 pm BST Jan 6,2014 | Reply

        • Here are measurements (hope I didn’t make any mistake):

          Common settings: ASSM, AUTO EXTENT ALLOCATION, ARCHIVELOG

          I use ASSM since almost everywhere I came they use it, because it’s default.
          I created both the table and lob segment as NOLOGGING. Combination of BASIC CACHE NOLOGGING is invalid and therefore cannot be included.

          ORA 12.1.0.1

          SECURFILE NOCACHE
          logical read bytes from cache 24 125 440
          redo entries 3252
          redo size 1 034 668

          BASICFILE NOCACHE
          logical read bytes from cache 132 947 968
          redo entries 5218
          redo size 1 246 648

          SECURFILE CACHE
          logical read bytes from cache 9 824 911 360
          redo entries 5695
          redo size 1 365 568

          ORA 11.2.0.3

          SECURFILE NOCACHE
          logical read bytes from cache 23 142 400
          redo entries 6266
          redo size 1 085 364

          BASICFILE NOCACHE
          logical read bytes from cache 132 308 992
          redo entries 8276
          redo size 1 634 788

          SECURFILE CACHE
          logical read bytes from cache 4 479 393 792
          redo entries 9363
          redo size 10 089 464

          I don’t have so precisely set environment like you so there are several differences between 11g and 12c on my computer but hopefully nothing significant. After first test I realized that I have flashback enabled on 11g so I retested it with disabled flashback as well and I had not impact on the results.

          Btw. I have several questions in my list that you could have answers perhaps. As we are within LOB topics right now:
          1. I have a table with LOB columns with ENABLED STORAGE IN ROW and all with NULL values. When I select these columns from the table in SQL Plus, it makes one additional roundtrip to the database for each row from the returned row set. Do you know what is the reason for that? If I execute the same query using OCI (via ADO.NET as I’m C# developer) I’m able to fetch all the rows at once.
          2. I noticed a dramatic performance drop when doing CTAS PARALLEL x with LOB columns. It’s big in 11g and even bigger in 12c, basically the serial CTAS is faster. I don’t have concrete example right now but I just want to check if you noticed and/or have any explanation for this behavior?

          Thanks.

          And maybe just ot mention one apparent bug I noticed in 12c related to LOBs, you probably know, but for others. When a MATERIALIZE hint is used in a sub query which contains lob columns, the table is materialized but the not the lob segment therefore the resulting columns are null. In Oracle 11, the MATERIALIZE hint is ignored when subquery contains LOBs.

          Comment by Husqvik — January 7, 2014 @ 7:02 am BST Jan 7,2014

        • Husqvik,

          Thanks for the folllow-up. Good idea to think about the flashback logging, nice to know it doesn’t seem to make a difference. Of course, there’s always change tracking to consider now – if you enabled it could concurrent activity of this type result in waits for the CT buffer ? (There are always more questions;)

          If nothing else your comments will have reminded people to look carefully at the conditions they’re testing under to make sure they’re doing the right tests.

          Thanks, too, for the Materialized bug – I hadn’t come across that.

          Answers to your questions:

          1) I have a documented script (dated 2009, referencing 11.2.0.2) that says SQL*Plus uses single row fetches if you’re fetching from a cursor that holds a LOB, even if the “arraysize” is set to something larger. The notes indicate that this shows up clearly in the trace file, with a further comment about seeing LOBREAD: as an event in the trace (especially if “longchunksize” is set to something less than “long”).

          2) I haven’t done this test, so can’t give an answer. Assuming you’re using securefiles then I would guess that the lost time relates to contention during the parallel maintenance of the securefile metadata. It’s also possible that when running serially Oracle has an optimisation that does some sort of array-based metadata maintence, but has to use row at a time maintenance when running parallel.

          Comment by Jonathan Lewis — January 7, 2014 @ 10:01 am BST Jan 7,2014

        • Actually I was wrong regarding the bug. After I post the comment, I wanted to be sure again so I tried to retest it and I found the bug exists in 11g as well. I worked on one task few months ago and I was pretty sure that I had a statement that worked on 11g but didn’t on 12c. But now I’m not able to proof it. But I can post at least what I did today:

          
          WITH T1 AS
          (
              SELECT /*+ materialize */ LEVEL ID, TO_CLOB('x') || 'y' LOB FROM DUAL CONNECT BY LEVEL <= 5
          )
          SELECT ID, LOB FROM T1;
          
          WITH T1 AS
          (
              SELECT LEVEL ID, NVL(TO_CLOB('x'), 'Cannot occur') LOB FROM DUAL CONNECT BY LEVEL <= 2
          )
          SELECT T.ID, T.LOB FROM T1 T CROSS JOIN T1;
          
          WITH T1 AS
          (
              SELECT /*+ materialize */ LEVEL ID, XMLTYPE('<x>1</x>').GETCLOBVAL() LOB FROM DUAL CONNECT BY LEVEL <= 5
          )
          SELECT * FROM T1;
          
          

          These statements behave the same on both versions. Apparently the bug occurs when there is an expression resulting in LOB datatype, referencing just pure columns or TO_CLOB() works correctly and the hint is ignored. The bug is not related to the hint itself, it occurs anytime when a sub-query is materialized, so usually when the sub-query is referenced more than once.

          Thanks for 1), good to know. I noticed that when I worked on remote DB over VPN where the ping was hundreds of milliseconds, so returning just dozens of rows took quite long.

          Ad 2) I tested it with both SECUREFILE and BASICFILE, there was a difference but not big. I think I will make this testcase again.

          I don’t want to bother you with more questions but I have few unanswered questions regarding Oracle DB that I really looking for the answers. So if there is a chance that you could look at them then I would get ex-post Christmas present.

          Comment by Husqvik — January 7, 2014 @ 10:33 am BST Jan 7,2014

        • Here are the CTAS LOB results.

          DROP TABLE SRC PURGE;
          
          CREATE TABLE SRC AS SELECT LEVEL ID FROM DUAL CONNECT BY LEVEL <= 10000; 
          
          DROP TABLE PARALLEL_LOB_TEST PURGE;
          
          CREATE TABLE PARALLEL_LOB_TEST
          (
              ID,
              VAL1,
              VAL2
          )
          LOB(VAL1) STORE AS BASICFILE/*SECUREFILE*/ VAL1_CLOB(NOCACHE)
          LOB(VAL2) STORE AS BASICFILE/*SECUREFILE*/ VAL2_CLOB(NOCACHE)
          PARALLEL 8
          NOLOGGING
          AS
          SELECT ID, TO_CLOB(RPAD('*', 2000, '*')) VAL1, TO_CLOB(RPAD('*', 2000, '*')) VAL2 FROM SRC;
          

          Here it comes again: when you start to dig in into a issue you experienced already something new is observed. There is a big difference in behavior of SECUREFILE when there is more than one LOB column. I made few samples on sessions during the longer executions and put the most common wait event.

          single CLOB column
          serial
          BASICFILE CACHE 0:17 control file sequential read
          BASICFILE NOCACHE 0:03
          SECUREFILE CACHE 0:02
          SECUREFILE NOCACHE 0:02

          parallel 8
          BASICFILE CACHE 0:28 control file sequential read
          BASICFILE NOCACHE 0:04
          SECUREFILE CACHE 0:01
          SECUREFILE NOCACHE 0:01

          two CLOB columns
          serial
          BASICFILE CACHE 0:35 control file sequential read
          BASICFILE NOCACHE 0:07 direct path write
          SECUREFILE CACHE 1:08 db file sequential read + local write wait
          SECUREFILE NOCACHE 1:13 db file sequential read + local write wait

          parallel 8
          BASICFILE CACHE 0:39 control file sequential read
          BASICFILE NOCACHE 0:07 direct path write
          SECUREFILE CACHE 0:41 enq: TX – contention
          SECUREFILE NOCACHE 0:34 enq: TX – contention + buffer busy waits

          Comment by Husqvik — January 7, 2014 @ 1:25 pm BST Jan 7,2014

  2. Hi Jonathan,

    > the redo for the lob component of nocache LOBs seems to have disappeared – there’s a drop of (roughly) 8,192,000 bytes from the 10g figures: is this a clever trick (filesystem-like logging ?) or is it a reporting error.

    I have written a blog post about a similar case (redo generation of no cache lobs in noarchivelog and archivelog mode) with redo dumps. The drop in case of nocache and noarchivelog mode is caused by a “direct loader invalidate block range redo entry” optimization. This makes sense in case of noarchivelog mode and nocache as the LOB content is directly written to the data file and no PIT recovery is possible. (and for crash recovery it is not needed at all as it is already flushed)

    Blog post with block dumps can be found here: http://tinyurl.com/no28vgc

    Regards
    Stefan

    Comment by Stefan Koehler — January 7, 2014 @ 1:36 pm BST Jan 7,2014 | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Theme: Rubric. Get a free blog at WordPress.com

Follow

Get every new post delivered to your Inbox.

Join 4,258 other followers