SQLDeveloper’s “mystats.sql” equivalent

It just occurred to me that I haven’t blogged about SQLDeveloper yet, something I really need to change ;) This post covers SQLDeveloper 19.4, and although I don’t know exactly when the feature you are reading about was added I doubt it was in the latest release.

A little bit of background first

Sometimes the wait interface isn’t enough, so you need to dig a little deeper into the performance issue. In my opinion there are two layers inside Oracle when it comes to performance troubleshooting:

• The Wait Interface provides valuable insights about session activity, especially when off-CPU and waiting
• Session counters provide insights into ongoing operations at a lower level, and finer granularity

Tanel Poder’s post I linked to (yes, it’s from 2010, time flies!) provides an excellent introduction to the topic. His (session) snapper.sql script is one of my favourite and most heavily-used tools, especially when investigating an ongoing issue. Have a look at the Snapper landing page to get some more details and ideas about its many capabilities, it can do a LOT.

Adrian Billington’s mystats.sql tracks sessions counters as well, but it takes a different approach. The mystats.sql script works particularly well when you can sandwich a piece of (PL/)SQL between calls to mystats start and mystasts stop. I have been using it extensively for research and even managed to sneak a little improvement in ;)

Here is an example of mystat use. It captures session counters before and after the execution of a SQL statement and prints the delta. Have a look at the GitHub repository for more details about this very useful utility as I’m not going into the details…

SQL> @mystats start s=s

PL/SQL procedure successfully completed.

SELECT /*+ noparallel gather_plan_statistics  */
  2      oi.order_id,
    SUM(oi.unit_price * oi.quantity)
  4  FROM
  5      soe.orders         o,
  6      soe.order_items    oi
  7  WHERE
  8          o.order_id = oi.order_id
  9      AND o.delivery_type = 'Express'
 10  GROUP BY
 11      oi.order_id
 12  HAVING
    SUM(oi.unit_price * oi.quantity) > 45000
 14  ORDER BY
 15      2 DESC;

  ORDER_ID SUM(OI.UNIT_PRICE*OI.QUANTITY)
---------- ------------------------------
   1449606                          49324
    577982                          48606
    468019                          47970
   1977685                          46786
   1891120                          45347
   2310221                          45209

6 rows selected.

SQL> @mystats stop t=1

==========================================================================================
MyStats report : 26-MAY-2020 18:44:51
==========================================================================================


------------------------------------------------------------------------------------------
1. Summary Timings
------------------------------------------------------------------------------------------

Type    Statistic Name                                                               Value
------  ----------------------------------------------------------------  ----------------
TIMER   snapshot interval (seconds)                                                  14.76
TIMER   CPU time used (seconds)                                                       2.38


------------------------------------------------------------------------------------------
2. Statistics Report
------------------------------------------------------------------------------------------

Type    Statistic Name                                                               Value
------  ----------------------------------------------------------------  ----------------
STAT    CPU used by this session                                                       239
STAT    CPU used when call started                                                     238
STAT    CR blocks created                                                               13
STAT    DB time                                                                        692
STAT    Effective IO time                                                        4,415,766
STAT    Number of read IOs issued                                                    1,336
STAT    Requests to/from client                                                         20
STAT    SQL*Net roundtrips to/from client                                               20
STAT    application wait time                                                            9
STAT    buffer is not pinned count                                                       7
STAT    bytes received via SQL*Net from client                                      20,586
STAT    bytes sent via SQL*Net to client                                            10,594
STAT    calls to get snapshot scn: kcmgss                                              791
STAT    calls to kcmgcs                                                                 47
STAT    cell physical IO interconnect bytes                                  1,370,603,520
STAT    consistent changes                                                             944
STAT    consistent gets                                                            278,437
STAT    consistent gets direct                                                     167,309
STAT    consistent gets examination                                                    251
STAT    consistent gets examination (fastpath)                                         251
STAT    consistent gets from cache                                                 111,128
STAT    consistent gets pin                                                        110,877
STAT    consistent gets pin (fastpath)                                             110,876
STAT    data blocks consistent reads - undo records applied                            247
STAT    db block changes                                                               838
STAT    db block gets                                                                2,415
STAT    db block gets from cache                                                     2,415
STAT    db block gets from cache (fastpath)                                          1,970
STAT    dirty buffers inspected                                                         33
STAT    enqueue conversions                                                              4
STAT    enqueue releases                                                                 8
STAT    enqueue requests                                                                 8
STAT    enqueue waits                                                                    1
STAT    execute count                                                                   17
STAT    execute count                                                                   17
STAT    file io wait time                                                       10,452,219
STAT    free buffer inspected                                                          105
STAT    free buffer requested                                                           69
STAT    heap block compress                                                              2
STAT    hot buffers moved to head of LRU                                               193
STAT    index fetch by key                                                               2
STAT    lob writes                                                                     391
STAT    lob writes unaligned                                                           391
STAT    logical read bytes from cache                                          930,144,256
STAT    no work - consistent read gets                                             277,738
STAT    non-idle wait count                                                          1,153
STAT    non-idle wait time                                                             452
STAT    opened cursors cumulative                                                       21
STAT    parse count (hard)                                                               1
STAT    parse count (total)                                                             17
STAT    physical read IO requests                                                    1,337
STAT    physical read bytes                                                  1,370,603,520
STAT    physical read total IO requests                                              1,337
STAT    physical read total bytes                                            1,370,603,520
STAT    physical read total multi block requests                                     1,336
STAT    physical reads                                                             167,310
STAT    physical reads cache                                                             1
STAT    physical reads direct                                                      167,309
STAT    process last non-idle time                                                      15
STAT    recursive calls                                                              2,022
STAT    recursive cpu usage                                                              3
STAT    rollbacks only - consistent read gets                                           26
STAT    rows fetched via callback                                                        1
STAT    session cursor cache count                                                       7
STAT    session cursor cache hits                                                       10
STAT    session logical reads                                                      280,852
STAT    session pga memory                                                       2,276,704
STAT    session pga memory max                                                  65,518,944
STAT    session uga memory                                                         261,952
STAT    session uga memory max                                                  63,036,496
STAT    sorts (memory)                                                                   1
STAT    sorts (rows)                                                                     6
STAT    table fetch by rowid                                                             1
STAT    table scan blocks gotten                                                   277,764
STAT    table scan disk non-IMC rows gotten                                     31,341,195
STAT    table scan rows gotten                                                  31,341,195
STAT    table scans (direct read)                                                        1
STAT    table scans (long tables)                                                        2
STAT    temp space allocated (bytes)                                             1,048,576
STAT    user I/O wait time                                                             442
STAT    user calls                                                                      28
STAT    workarea executions - optimal                                                    6
STAT    workarea memory allocated                                                       12


------------------------------------------------------------------------------------------
3. Options Used
------------------------------------------------------------------------------------------
- Statistics types : s=s
- Reporting filter : t=1


------------------------------------------------------------------------------------------
4. About
------------------------------------------------------------------------------------------
- MyStats v3.0 by Adrian Billington (http://www.oracle-developer.net)
- Original version based on the SNAP_MY_STATS utility by Jonathan Lewis


==========================================================================================
End of report
==========================================================================================

PL/SQL procedure successfully completed.

I have modified mystats slightly so as to sort output by statistic name, rather than the change in value. I find it easier to read that way, but your mileage may vary.

Each time I look at performance instrumentation in the Oracle database I am pleasantly surprised about the level of detail available. I haven’t blogged about it lately, but going back a bit to 12.2 shows the progress made. And Oracle didn’t stop there, either. Using mystats’s output I can derive all sorts of interesting facts, none of which are of importance for this post as I’m purely interesting in reporting the change in session stats ;) When researching how Oracle works, this is quite a wealth of information, and you can find further examples on this blog.

SQLDeveloper can do this, too

If you are using SQLDeveloper and don’t want/need to use the command line, you can get something quite similar as well. Just enter your query into the text window, then hit F6 for “Autotrace”. In the lower part of your Autotrace results, you can see the change in session counters. If not, you may have to swipe the statistics pane into view using the mouse. Figure 1 shows an example:

Figure 1: SQLDeveloper’s Autotrace function displaying change in session statistics for this query

Summary

Session counters are super useful for understanding what Oracle does at a more granular level than the wait interface. For the most part, using the wait interface is enough, yet there is the occasional case where more details are needed. I often consider changes in session statistics when researching a particular problem, and thankfully I don’t have to come up with ways to do so as the community has already lent a helping hand!

Advertisement

Little things worth knowing: keeping enq: TM enqueue at bay during direct path inserts

Direct path inserts are commonly found in processing where data are shifted from one source to another. There are many permutations of the theme, this post details the way SQL Loader (sqlldr) behaves.

I have previously written about sqlldr and concurrent direct path inserts. The behaviour for releases <= 12.1 is described in the first post, the most welcome changes in 12.2 went into the second post. Since the fastest way of doing something is not to do it at all, I thought it might be worth demonstrating a useful technique to keep the dreaded TM enqueue at bay. Please note that these do not only apply to sqlldr, inserts with the append hint for example behave the same way in my experience.

I used Oracle 19.4.0 on Oracle Linux 7 for this post, the content should apply to older database releases, too. The data model is once more provided by Swingbench, I’m using the SH benchmark this time. As I said on twitter yesterday, @TanelPoder scripts are simply too good to afford writing my own, so I’m using them in this post where possible.

Please note that I’m using partitioning in this post, which is a cost option on top of Enterprise Edition. Always ensure your system is properly licensed for features you use.

Preparations

Let’s assume for a moment that you would like to load another batch of records into the (Swingbench) sh.sales table. The table is range partitioned on time_id, and split into quarterly partitions – at least for the later ones. On my system I count 68 partitions, with the latest containing records up to January 1st 2014. I added a couple of partitions for the next 2 quarters to allow for the new data load.

SQL> select partition_name, partition_position,high_value 
  2  from user_tab_partitions where table_name = 'SALES' 
  3   and partition_position >= 68;

PARTITION_NAME     PARTITION_POSITION HIGH_VALUE
----------------- ------------------- -----------------------------------------------------------------------------------
SALES_Q4_2013                      68 TO_DATE(' 2014-01-01 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')   
SALES_Q1_2014                      69 TO_DATE(' 2014-04-01 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')   
SALES_Q2_2014                      70 TO_DATE(' 2014-07-01 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')   

I created CSV files of the data to be loaded by simply adding 3 and 6 months to the last populated partition.

spool /u01/app/oracle/admin/ORCL/sqlldr/sales_q1_2014.csv
select /*csv*/ 
 prod_id,
 cust_id,
 add_months(time_id,3) time_id,
 channel_id,
 promo_id,
 quantity_sold,
 seller,
 fulfillment_center,
 courier_org,
 tax_country,
 tax_region,
 amount_sold 
from sales partition (sales_q4_2013);

spool off
spool  /u01/app/oracle/admin/ORCL/sqlldr/sales_q2_2014.csv

select /*csv*/ 
 prod_id,
 cust_id,
 add_months(time_id,6) time_id,
 channel_id,
 promo_id,
 quantity_sold,
 seller,
 fulfillment_center,
 courier_org,
 tax_country,
 tax_region,
 amount_sold 
from sales partition (sales_q4_2013);

spool off
exit

Using the csv “hint” and executing this little script in sqlcl allows me to spool the files into the desired format (I made sure I have plenty of space available in /u01/app/oracle/admin). Now let’s try loading the data. As always, I use a control file although there might be better ways of doing this. It contains the following instructions:

options (direct=true,skip=1)
load data
append into table sales
fields terminated by ',' optionally enclosed by '"'
date format "dd-mon-yy"
trailing nullcols
(
  PROD_ID,                                                                        
  CUST_ID,                                                                        
  TIME_ID,                                                                        
  CHANNEL_ID,                                                                     
  PROMO_ID,                                                                       
  QUANTITY_SOLD,                                                                  
  SELLER,                                                                         
  FULFILLMENT_CENTER,                                                             
  COURIER_ORG,                                                                    
  TAX_COUNTRY,                                                                    
  TAX_REGION,                                                                     
  AMOUNT_SOLD
)

Test #1

Now let’s load the data! Since I’m not the most patient person I launched 2 sessions in parallel using a screen (1) session

$ sqlldr /@sh control=load_sales.ctl data=sales_q1_2014.csv log=load_q1.log bad=load_q1.bad direct_path_lock_wait=true

$ sqlldr /@sh control=load_sales.ctl data=sales_q2_2014.csv log=load_q2.log bad=load_q2.bad direct_path_lock_wait=true

While monitoring the load process I was surprised to see session 2 waiting:

SQL> select sid,seq#,event,state from v$session where program like '%sqlldr%';

       SID       SEQ# EVENT                                                            STATE
---------- ---------- ---------------------------------------------------------------- -------------------
      1228        578 SQL*Net more data from client                                    WAITED SHORT TIME
      1470         97 enq: TM - contention                                             WAITING

2 rows selected.

Each process should insert data into separate partitions, so why is there a wait? Maybe there is a clue in v$session_wait:

SQL> @sw 1470

    SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1                  P2                  P3                  P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------- ------------------- ------------------- ------------------------------------------
   1470 WAITING enq: TM - contention                             98           6 name|mode=          object #= 78758     table/partition= 0  0x544D0006: TM mode 6
                                                                                0x00000000544D0006


1 row selected.

I noticed that p3 mentions a table or partition flag, which triggered my interest. After a little bit of research I found this section in the documentation: 12.3.2 Direct Path Load of a Partitioned or Subpartitioned Table which provides some clues. Object# 78758 is the table in my database:

SQL> @oid 78758

owner                     object_name                    object_type        SUBOBJECT_NAME                 CREATED             LAST_DDL_TIME       status    DATA_OBJECT_ID
------------------------- ------------------------------ ------------------ ------------------------------ ------------------- ------------------- --------- --------------
SH                        SALES                          TABLE                                             2019-08-29 15:14:53 2019-08-29 23:06:27 VALID

What if I tried to insert into a partition straight away?

Test #2

Let’s try that with the following 2 control files. The main differences are a) referencing the input file directly and b) the specification of the target partition in the append clause:

$ cat load_sales_q1_2014.ctl
options (skip=1,direct=true)
load data
infile  /u01/app/oracle/admin/ORCL/sqlldr/sales_q1_2014.csv
append into table sales partition (sales_q1_2014)
fields terminated by ',' optionally enclosed by '"'
date format "dd-mon-yy"
trailing nullcols
( 
  PROD_ID,
  CUST_ID,
  TIME_ID,
  CHANNEL_ID,
  PROMO_ID,
  QUANTITY_SOLD,
  SELLER,
  FULFILLMENT_CENTER,
  COURIER_ORG,
  TAX_COUNTRY,
  TAX_REGION,
  AMOUNT_SOLD
)

$ cat load_sales_q2_2014.ctl
options (skip=1,direct=true)
load data
infile  /u01/app/oracle/admin/ORCL/sqlldr/sales_q2_2014.csv
append into table sales partition (sales_q2_2014)
fields terminated by ',' optionally enclosed by '"'
date format "dd-mon-yy"
trailing nullcols
( 
  PROD_ID,
  CUST_ID,
  TIME_ID,
  CHANNEL_ID,
  PROMO_ID,
  QUANTITY_SOLD,
  SELLER,
  FULFILLMENT_CENTER,
  COURIER_ORG,
  TAX_COUNTRY,
  TAX_REGION,
  AMOUNT_SOLD
)

The slightly adjusted commands for sqlldr are as follows:

$ sqlldr /@sh control=load_sales_q1_2014.ctl log=load_q1.log bad=load_q1.bad direct_path_lock_wait=true

$ sqlldr /@sh control=load_sales_q2_2014.ctl log=load_q2.log bad=load_q2.bad direct_path_lock_wait=true

With the change in place I couldn’t notice any TM enqueues when running these in parallel:

SQL> select sid,seq#,event,state from v$session where program like '%sqlldr%';

no rows selected

SQL>
SQL> r
  1* select sid,seq#,event,state from v$session where program like '%sqlldr%'

       SID       SEQ# EVENT                                                            STATE
---------- ---------- ---------------------------------------------------------------- -------------------
      1251        627 direct path write temp                                           WAITED KNOWN TIME
      1488        475 PGA memory operation                                             WAITED SHORT TIME

SQL> r
  1* select sid,seq#,event,state from v$session where program like '%sqlldr%'

       SID       SEQ# EVENT                                                            STATE
---------- ---------- ---------------------------------------------------------------- -------------------
      1251        819 direct path write temp                                           WAITING
      1488        664 direct path write temp                                           WAITING

SQL> r
  1* select sid,seq#,event,state from v$session where program like '%sqlldr%'

       SID       SEQ# EVENT                                                            STATE
---------- ---------- ---------------------------------------------------------------- -------------------
      1251       1070 SQL*Net more data from client                                    WAITED SHORT TIME
      1488        906 direct path write temp                                           WAITED KNOWN TIME

SQL> r
  1* select sid,seq#,event,state from v$session where program like '%sqlldr%'

       SID       SEQ# EVENT                                                            STATE
---------- ---------- ---------------------------------------------------------------- -------------------
      1251       1332 db file sequential read                                          WAITED SHORT TIME
      1488       1143 library cache lock                                               WAITING

SQL> r
  1* select sid,seq#,event,state from v$session where program like '%sqlldr

       SID       SEQ# EVENT                                                            STATE
---------- ---------- ---------------------------------------------------------------- -------------------
      1251       1824 db file sequential read                                          WAITED SHORT TIME
      1488       1372 db file sequential read                                          WAITING

That looks ok, and switching back through both screen sessions I can see both invocations of sqlldr completed ok:

$ sqlldr /@sh control=load_sales_q1_2014.ctl log=load_q1.log bad=load_q1.bad direct_path_lock_wait=true

SQL*Loader: Release 19.0.0.0.0 - Production on Thu Aug 29 22:44:53 2019
Version 19.4.0.0.0

Copyright (c) 1982, 2019, Oracle and/or its affiliates.  All rights reserved.

Path used:      Direct

Load completed - logical record count 652437.

Table SALES, partition SALES_Q1_2014:
  652437 Rows successfully loaded.

Check the log file:
  load_q1.log
for more information about the load.

$ sqlldr /@sh control=load_sales_q2_2014.ctl log=load_q2.log bad=load_q2.bad direct_path_lock_wait=true

SQL*Loader: Release 19.0.0.0.0 - Production on Thu Aug 29 22:44:54 2019
Version 19.4.0.0.0

Copyright (c) 1982, 2019, Oracle and/or its affiliates.  All rights reserved.

Path used:      Direct

Load completed - logical record count 652437.

Table SALES, partition SALES_Q2_2014:
  652437 Rows successfully loaded.

Check the log file:
  load_q2.log
for more information about the load.

Summary

When you are trying to load data into a table concurrently using direct path inserts, you will have to wait on a TM enqueue unless your table is partitioned and you are specifying different partitions as the target in each process. More generally speaking, Oracle will hold a TM enqueue on the segment you are loading into, so 2 processes attempting a direct path insert into a (sub) partition will equally have to serialise.

NB: if you are using direct path mode for sqlldr and your target segment is indexed, make sure to read chapter 12 in the Database Utilities Guide to learn about the implications of direct path load and index maintenance.

Making some more sense of direct path reads during primary key lookups

After having published my first article of 2019 I have received feedback I felt like including. With a nod to @fritshoogland, @ChrisAntognini and @FranckPachot.

In the previous post I showed you output of Tanel Poder’s ashtop.sql as proof that direct path reads can occur even if all you do is look up data by primary key. This script touches v$active_session_history, and I’m not getting tired of mentioning that you need to license the system in scope for Enterprise Edition and the Diagnostics Pack to do so.

What I haven’t shown you in more detail in the previous article is what causes these direct path reads. This is what I’ll try to do next. I have started by repeating my test case but added the gather_plan_statistics hint to the statement, resulting in a different SQL ID. Yesterday I noticed that Safari doesn’t show the scroll bar at the bottom of this code snippet other browsers show, I hope output isn’t garbled. I’m using the universal excuse here “it works on my laptop”.

SQL> @xia a66axyw2g6yjb
Display Execution plan in advanced format for sqlid a66axyw2g6yjb

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  a66axyw2g6yjb, child number 0
-------------------------------------
select /*+ gather_plan_statistics CLOB standalone */ *  from
martin.orders_clob  where order_id = :1

Plan hash value: 3284193906

----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name           | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                |      1 |        |       |     3 (100)|          |      0 |00:00:00.01 |       3 |
|   1 |  TABLE ACCESS BY INDEX ROWID| ORDERS_CLOB    |      1 |      1 |   137 |     3   (0)| 00:00:01 |      0 |00:00:00.01 |       3 |
|*  2 |   INDEX UNIQUE SCAN         | PK_ORDERS_CLOB |      1 |      1 |       |     2   (0)| 00:00:01 |      0 |00:00:00.01 |       3 |
----------------------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$1 / ORDERS_CLOB@SEL$1
   2 - SEL$1 / ORDERS_CLOB@SEL$1

Outline Data
-------------

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('18.1.0')
      DB_VERSION('18.1.0')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "ORDERS_CLOB"@"SEL$1" ("ORDERS_CLOB"."ORDER_ID"))
      END_OUTLINE_DATA
  */

Peeked Binds (identified by position):
--------------------------------------

   1 - :1 (NUMBER): 519990

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("ORDER_ID"=:1)

Column Projection Information (identified by operation id):
-----------------------------------------------------------

   1 - "ORDER_ID"[NUMBER,22], "ORDERS_CLOB"."ORDER_CLOB"[LOB,4000], "ORDERS_CLOB"."ORDER_DATE"[TIMESTAMP WITH LOCAL TIME
       ZONE,11], "ORDERS_CLOB"."ORDER_MODE"[VARCHAR2,8], "ORDERS_CLOB"."CUSTOMER_ID"[NUMBER,22],
       "ORDERS_CLOB"."ORDER_STATUS"[NUMBER,22], "ORDERS_CLOB"."ORDER_TOTAL"[NUMBER,22], "ORDERS_CLOB"."SALES_REP_ID"[NUMBER,22],
       "ORDERS_CLOB"."PROMOTION_ID"[NUMBER,22], "ORDERS_CLOB"."WAREHOUSE_ID"[NUMBER,22], "ORDERS_CLOB"."DELIVERY_TYPE"[VARCHAR2,15],
       "ORDERS_CLOB"."COST_OF_DELIVERY"[NUMBER,22], "ORDERS_CLOB"."WAIT_TILL_ALL_AVAILABLE"[VARCHAR2,15],
       "ORDERS_CLOB"."DELIVERY_ADDRESS_ID"[NUMBER,22], "ORDERS_CLOB"."CUSTOMER_CLASS"[VARCHAR2,30],
       "ORDERS_CLOB"."CARD_ID"[NUMBER,22], "ORDERS_CLOB"."INVOICE_ADDRESS_ID"[NUMBER,22]
   2 - "ORDERS_CLOB".ROWID[ROWID,10], "ORDER_ID"[NUMBER,22]


57 rows selected.

After a few minutes of executing the statement repeatedly, direct path reads are clearly visible again

SELECT
    COUNT(*),
    event,
    session_state
FROM
    v$active_session_history ash
WHERE
    sql_id = 'a66axyw2g6yjb'
    AND sample_time > SYSDATE - 15 / 1440
GROUP BY
    event,
    session_state
ORDER BY
    1 DESC;

  COUNT(*) EVENT                                    SESSION
---------- ---------------------------------------- -------
      1592                                          ON CPU
        24 direct path read                         WAITING
         6 cursor: pin S                            WAITING
         4 SQL*Net more data to client              WAITING

So far so good. Getting back to the original question: what’s causing these? ASH provides the answer to that question as well.

SELECT
    COUNT(*),
    event,
    session_state,
    sql_plan_operation
    || ' '
    || sql_plan_options AS what,
    CASE
        WHEN wait_class IN(
            'Application',
            'Cluster',
            'Concurrency',
            'User I/O'
        )THEN object_name
        ELSE 'undef'
    END AS obj
FROM
    v$active_session_history ash,
    dba_objects o
WHERE
    ash.current_obj# = o.object_id
    AND sql_id = 'a66axyw2g6yjb'
GROUP BY
    event,
    session_state,
    sql_plan_operation
    || ' '
    || sql_plan_options,
    CASE
        WHEN wait_class IN(
            'Application',
            'Cluster',
            'Concurrency',
            'User I/O'
        )THEN object_name
        ELSE 'undef'
    END
ORDER BY 1 desc;

  COUNT(*) EVENT                                    SESSION WHAT                           OBJ
---------- ---------------------------------------- ------- ------------------------------ ------------------------------
      3006                                          ON CPU  SELECT STATEMENT               undef
       223                                          ON CPU  INDEX UNIQUE SCAN              undef
       126                                          ON CPU  TABLE ACCESS BY INDEX ROWID    undef
        50 direct path read                         WAITING SELECT STATEMENT               SYS_LOB0000081921C00002$$
         8 cursor: pin S                            WAITING SELECT STATEMENT               SYS_LOB0000081921C00002$$
         8 SQL*Net more data to client              WAITING SELECT STATEMENT               undef
         1                                          ON CPU                                 undef

7 rows selected.

I think you might be getting the idea by now … I can link the segment back to DBA_LOBS, and … it’s the LOB column of ORDERS_CLOB.

SELECT
    table_name,
    column_name,
    segment_name,
    cache,
    securefile
FROM
    dba_lobs
WHERE
    segment_name = 'SYS_LOB0000081921C00002$$';

TABLE_NAME      COLUMN_NAME     SEGMENT_NAME                   CACHE      SEC
--------------- --------------- ------------------------------ ---------- ---
ORDERS_CLOB     ORDER_CLOB      SYS_LOB0000081921C00002$$      NO         YES

QED.

Another option is to query session statistics. I looked at one of the sessions using snapper4.sql but the output was too wide to paste it as text. I’ll resort to the traditional way of doing this:

SELECT
     name,
     value
 FROM
     v$sesstat st
     NATURAL JOIN v$statname sn
 WHERE
     st.sid = 128
     AND st.value <> 0
     AND REGEXP_LIKE(name, '(physical|securefile).*read.*')
 ORDER BY
     sn.name;

NAME                                          VALUE
----------------------------------------- ---------- 
 physical read IO requests                    106836
 physical read bytes                       875200512
 physical read total IO requests              106836
 physical read total bytes                 875200512
 physical reads                               106836
 physical reads direct                        106836
 physical reads direct (lob)                  106836
 securefile direct read bytes              875200512
 securefile direct read ops                   106836
 9 rows selected.

I admit this was a rather manual way of extracting this piece of information, you might be able to get the same data with an ASH report (provided the number of I/O samples against that segment is significant enough to show up). In this context I’d like to recommend planx.sql you can find on Carlos Sierra’s and Mauro Pagano’s github repository. It’s small, lightweight, and incredibly useful.

Using colplot to visualise performance data

Back in 2011 I wrote a blog post about colplot but at that time focused on running the plot engine backed by a web server. However some people might not want to take this approach, and thinking about security it might not be the best idea in the world anyway. A port that isn’t opened can’t be scanned for vulnerabilities…

So what is colplot anyway? And why this follow-up to a 7 year old post?

Some background

Back in the day I learned about collectl: a small, light-weight performance monitoring tool that’s easily portable to many platforms. Collectl is very versatile and has capabilities to record a lot of detail, especially on Linux. Collectl comes with a companion, colplot, which I introduced in said post in 2011.

A typical use case – at least for me – is to start collectl recording, do some work, stop recording, and plotting the results. This can be handy if you don’t get permission to install TFA (think “OSWatcher”) at short notice, and still need performance data!

In this blog post I’d like to share how you could go about doing this. I am using Debian as my workstation O/S and Oracle Linux to capture data.

The workload

I wanted a really simple workload, so for lack of ingenuity I came up with the idea of running fio to drive storage and a tiny bit of CPU.

I am running a very basic random read I/O test and record it with collectl. It is important to understand that it’s your responsibility to define what you want to capture with regards to the plots you want to generate. I’ll explain this in a bit, but for now it’ll have to suffice that I need detail data for CPU and disk.

Before kicking off the load generator I start collectl to record data in (P)lot mode, saving data to my data subdirectory:

[oracle@server1 ~]$ collectl -sCD -f /home/oracle/data -P

(Another, probably cleverer option is to record the data without the -P switch, then replay the recording and writing the output to a file in plot format. That way you can have a lot more control over the process and as an added advantage have the raw data)

Once the workload has completed, I can transfer the data captured to my workstation for analysis with colplot. For each detail switch you select (C and D in the example) you’ll get a (compressed) file:

$ ls -l data
total 84
-rw-r--r-- 1 oracle oinstall 21790 Oct 30 08:26 server1-20181030.cpu
-rw-r--r-- 1 oracle oinstall 59357 Oct 30 08:26 server1-20181030.dsk

Plotting details

I imagine most people use the web-frontend to colplot, but that doesn’t mean there aren’t other ways of generating visualisations of your performance data. But first of all, what plots can you create? This depends on the version of colplot in use, for me it’s this:

$ colplot --version
colplot: V5.1.0, gnuplot: V:5.0[png,x11]

Copyright 2004-2014 Hewlett-Packard Development Company, L.P.
colplot may be copied only under the terms of either the Artistic License
or the GNU General Public License, which may be found in the source kit

Getting back to the list of plots supported in my version, it’s super impressive!

$ colplot -showplots
cpu         cpu     s  Cpu Utilization. Other
cpu20       cpu     s  Cpu Utilization, 0-20%
cpu80       cpu     s  Cpu Utilization, 80-100%
cpudold     cpu     s  Old format ony reports individual fields
cpumid      cpu     s  Cpu Utilization, 40-60%
cpumore     cpu     s  Additional types of use
cpuold      cpu     s  Old format ony reports individual fields
loadavg     cpu     s  Load Averages for 1,5,15 min
disk        disk    s  Disk Summary
diskio      disk    s  Disk I/O
disksize    disk    s  Bandwidth and transfer sizes
elan        elan    s  Quadrics ELAN Bandwidth
elanio      elan    s  Quadrics ELAN Packet Rates
ib          ib      s  Infiniband Bandwidth
ibio        ib      s  Infiniband Packet Rates
ibsize      ib      s  Bandwidth and transfer sizes
nvidia      import  s  nvidia GPU stats
inode       inode   s  Inode Summary
luscltio    lustre  s  Lustre Client Summary, I/O only
cltmeta     lustre  s  Lustre Client Meta Summary
cltreada    lustre  s  Lustre Client Read-Ahead Summary
lusmds      lustre  s  lustre Lustre MDS Summary
lusoss      lustre  s  Lustre OSS Data Rates
ossio       lustre  s  Lustre OSS I/Os
faults      mem     s  Page Faults
mem         mem     s  Memory
memanon     mem     s  Anon Memory
membuf      mem     s  Buffered Memory
memcache    mem     s  Cached Memory
memdirty    mem     s  Dirty Memory
memmap      mem     s  Mapped Memory
memslab     mem     s  Slab Memory
paging      mem     s  Paging
swap        mem     s  Swap Utilization
misc1       misc    s  Miscellaneous ctrs from '--import misc'
misc2       misc    s  CPU Frequency from '--import misc'
net         net     s  Network Summary
netpkt      net     s  Network packets
netsize     net     s  Bandwidth and transfer sizes
nfsV2c      nfs     s  older NFS V2 Client Summary
nfsV2s      nfs     s  older NFS V2 Server Summary
nfsV3c      nfs     s  older NFS V3 Client Summary
nfsV3s      nfs     s  older NFS V3 Server Summary
nfsV4c      nfs     s  older NFS V4 Client Summary
nfsV4s      nfs     s  older NFS V4 Server Summary
nfsmeta     nfs     s   NFS Metadata and Commits
nfsrpc      nfs     s  NFS RPC Summary
nfssum      nfs     s   NFS Aggregate Summary Data
ctxint      proc    s  Context and Interruputs
proc        proc    s  Processes
sock        sock    s  Socket Usage
accaudt     swift   s  Account Auditor
accreap     swift   s  Account Reaper
accrepl     swift   s  Account Replicator
accsrvr     swift   s  Account Server
conaudt     swift   s  Container Auditor
conrepl     swift   s  Container Replicator
consrvr     swift   s  Container Server
consync     swift   s  Container Sync
conupdt     swift   s  Container Updater
objaudt     swift   s  Object Auditor
objexpr     swift   s  Object Expirer
objrepl     swift   s  Object Replicator
objsrv2     swift   s  Object Server2
objsrvr     swift   s  Object Server
objupdt     swift   s  Object Updater
prxyacc     swift   s  Proxy Account
prxycon     swift   s  Proxy Container
prxyobj     swift   s  Proxy Object
tcp         tcp     s  TCP errors count summary
tcpold      tcp     s  old TCP acks & packet failures
cpudet      cpu     d  Cpu Details, Other
cpuint      cpu     d  Interrupts by Cpu
cpumored    cpu     d  Additional types of use
diskdet     disk    d  Disk Details
diskdsize   disk    d  Disk I/O Size Details
diskque     disk    d  Disk request queue depth
disktimes   disk    d  Disk wait/service times
diskutil    disk    d  Disk utilization
fans        env     d  Fan Speeds
power       env     d  Power Sensor
temps       env     d  Temperature Sensors
ibdet       inter   d  IB interconnect detail data
ibdsize     inter   d  IB packet size detail
elandio     inter   d  Elan interconnect IOs (get/put/comp)
elandmb     inter   d  Elan interconnect MBs (get/put/comp)
cltdet      lustre  d  Lustre Client FS I/O Detail
cltdetL     lustre  d  Lustre Client OST I/O Detail
ossdet      lustre  d  Lustre OSS Detail
netdet      net     d  Network Details
netdsize    net     d  Network Packet Size Details
nfsV2cd     nfs     d  NFS Version 2 Client Detail
nfsV2sd     nfs     d  NFS Version 2 Server Detail
nfsV3cd     nfs     d  NFS Version 3 Client Detail
nfsV3sd     nfs     d  NFS Version 3 Server Detail
nfsV4cd     nfs     d  NFS Version 4 Client Detail
nfsV4sd     nfs     d  NFS Version 4 Server Detail
cltbrw      macro      Lustre Client BRW stats
cltbrwD     macro      Lustre Client BRW detail stats
detall      macro      All detail plots except nfs and lustre
detlus      macro      Lustre detail plots (there can be a LOT of these!)
detnfs      macro      NFS detail plots, colplot only
inter       macro      Interconnect summary plots
interdet    macro      Interconnect detail plots
lusblkDR    macro      Lustre Block I/O read detail stats (there can be LOTS of these!)
lusblkDW    macro      Lustre Block I/O write detail stats (there can be LOTS of these!)
lusblkR     macro      Lustre Block I/O read summary stats
lusblkW     macro      Lustre Block I/O write summary stats
misc        macro      All misc counters from '--import misc'
ossbrw      macro      Lustre OSS BRW stats
ossbrwD     macro      Lustre OSS BRW detail stats
sumall      macro      All summary plots, except nfs client/server stats
sumlus      macro      Lustre summary plots for clients, mds and oss
summin      macro      Minimal set of summary plots (cpu, disk, mem and disk
sumnfs      macro      NFS summary plots, colplot only

I don’t think I promised too much!

One thing to keep in mind though: you cannot plot charts for which you don’t have data. For example, if I wanted to plot CPU summary data, colplot would tell that it can’t:

$ colplot -dir /home/vagrant/data -plots cpu
No plottable files match your selection criteria.
Are your dir, selection dates and/or file protections right?

I am certain I have set the permissions correctly, but I also know that I didn’t capture CPU summary information (this would be lower-case “c”, as opposed to upper case “C” for the detailed recording). I suggest you run a few tests until you are comfortable with collectl’s command line switches to avoid later disappointment when trying to plot :)

With the collected performance data transferred to ~/data and now can plot some CPU and disk details:

$ colplot -dir /home/vagrant/data -plots cpudet,diskdet \
> -filedir /home/vagrant/data --time 08:15:00-08:25:00
Your Plot(s) have been written to /home/vagrant/data/5376-colplot.pdf

The resulting file created by this particular command is a PDF. I like this format simply because it’s easy to store it for later reference. I also wanted to limit the plots to a specific time, otherwise my little 5m test would have been hardly noticeable.

This is what it looks like, please don’t try to read anything from the charts, they are included for illustration purposes only, taken from a lab VM without any resemblance to a real-world system.

It’s also possible to plot interactively by omitting the -filedir switch in colplot. Output is generated in your X-session and you can export it in different formats.

There is of course more to colplot than I could show in a single post, but I hope I have managed to give you a first impression.

Happy benchmarking!

New Events for Data Guard and Synchronous Redo Transport in 12c (2)

After the baseline has been established in the first part of this series it’s time to measure the effect of the network in this part. The second test will introduce an interesting feature: Using Linux’s own Traffic Shaper/Quality of Services module I will add a delay of 100ms to the Data Guard network interface card (NIC) to slow things down a little.

WARNING: this is of course a lab or VM-only situation. I can’t exert control over wire quality in my (own) switches, hence some software magic is needed on my virtual ones. This post is intended to be merely for educational purposes, not for use at work.

I am continuing to use the 2 node RAC 12.1.0.2.170117 primary database on Oracle Linux 7 with UEK 4 and an identical RAC to host my standby database.

All database traffic still uses eth0 – my public network (192.168.100.0/24). In order not to affect my SSH session with the planned network changes I created a new out-of-band management interface (eth2) on the Data Guard standby database servers. I love KVM and virtio drivers for the NICs: a few commands in virsh later and every RAC node has a new NIC, and of course without rebooting. Adding some nmcli magic and I can configure all interfaces in 1 line!

Here’s what it looks like from connection manager (the system is Oracle Linux 7.3)

[root@rac12sec1 ~]# nmcli c show
NAME  UUID                                  TYPE            DEVICE 
eth0  3e8915f1-10ce-4da7-99b8-d2a6947f9ff7  802-3-ethernet  eth0   
eth1  0ebe1279-40e1-4faf-a0be-49588d347fcf  802-3-ethernet  eth1   
mgmt  51054729-19ae-49e7-ba18-c6b41475ec1b  802-3-ethernet  eth2   

My eth0 device maps to the public networks, e.g. all database traffic including Data Guard. The private interconnect uses eth1 with eth2 as the management interface. I have deliberately kept this simple, usually I’d request a dedicated set of interfaces to route Data Guard traffic (I blogged about that earlier in the context of RAC) here:

• RAC 12c enhancements: adding an additional SCAN-part 1
• RAC 12c enhancements: adding an additional SCAN-part 2
• RAC 12c enhancements: adding an additional SCAN-part 3

Please read past part I of the Adding an additional SCAN-series to get the full story.

Change protection mode

Following the scenario I outlined in part I I first have to change the protection mode to Maximum Availability. Again, please see part I of this series for an explanation about Protection Levels, my choice of protection level, and why “Maximum Availability” might or might not work for you.

Since I’m using the Data Guard Broker, I need to head over and change the mode in dgmgrl.

DGMGRL> show configuration

Configuration - ractest

  Protection Mode: MaxPerformance
  Members:
  NCDBA - Primary database
    NCDBB - Physical standby database

Fast-Start Failover: DISABLED

Configuration Status:
SUCCESS   (status updated 40 seconds ago)

As with many other maintenance tasks, you use the edit command to change the configuration.

DGMGRL> EDIT CONFIGURATION SET PROTECTION MODE AS MaxAvailability;
Error: ORA-16627: operation disallowed since no standby databases would 
remain to support protection mode

Failed.

I seem to have gotten a bit ahead of myself – changing to the more serious protection modes requires changing the transport mode from async to sync. Let’s do that, and then change the protection mode:

DGMGRL> edit database 'NCDBA' set property LogXptMode = 'SYNC';
Property "logxptmode" updated
DGMGRL> edit database 'NCDBB' set property LogXptMode = 'SYNC';
Property "logxptmode" updated
DGMGRL> EDIT CONFIGURATION SET PROTECTION MODE AS MaxAvailability;
Succeeded.
DGMGRL> show configuration

Configuration - ractest

  Protection Mode: MaxAvailability
  Members:
  NCDBA - Primary database
    NCDBB - Physical standby database 

Fast-Start Failover: DISABLED

Configuration Status:
SUCCESS   (status updated 19 seconds ago)

DGMGRL> 

That looks better now, the first half of the job is done. The second half of this article details how to make the network look a lot worse.

Net Emulator

Using the Linux netem kernel module I can simulate many complex network situations – I found https://wiki.linuxfoundation.org/networking/netem to be a good reference.

I should probably say at this point that no one would use a link that has 100 ms delay between sites for (sync) redo transport. That simply doesn’t make sense. I used 100ms to have a large enough factor so that I can actually be sure that a deviation of performance figures is actually a result of my fiddling with the network latency. Large numbers make spotting outliers easier.

How do you mess with the network? That is simple when you are on Linux! On my standby cluster I use the tc command, part of the iproute package. This is the “normal” state:

[root@rac12sec1 ~]# tc qdisc
qdisc pfifo_fast 0: dev eth0 root refcnt 2 bands 3 priomap  1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
qdisc pfifo_fast 0: dev eth1 root refcnt 2 bands 3 priomap  1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
qdisc pfifo_fast 0: dev eth2 root refcnt 2 bands 3 priomap  1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
[root@rac12sec1 ~]# 

I am merely using these tools, if you want to understand them, have a look at the Linux Advanced Routing & Traffic Control HOWTO chapter 9, and refer to the link to the Linux Foundation wiki I mentioned earlier. Then take it from there.

The syntax of tc qdisc is complex at first sight:

[root@rac12sec1 ~]# tc qdisc help
Usage: tc qdisc [ add | del | replace | change | show ] dev STRING
       [ handle QHANDLE ] [ root | ingress | parent CLASSID ]
       [ estimator INTERVAL TIME_CONSTANT ]
       [ stab [ help | STAB_OPTIONS] ]
       [ [ QDISC_KIND ] [ help | OPTIONS ] ]

       tc qdisc show [ dev STRING ] [ingress]
Where:
QDISC_KIND := { [p|b]fifo | tbf | prio | cbq | red | etc. }
OPTIONS := ... try tc qdisc add <desired QDISC_KIND> help
STAB_OPTIONS := ... try tc qdisc add stab help

The above allows us to introduce NetEM to the mix. On my Linux 7.3/UEK4 system it offers the following options:

[root@rac12sec1 ~]# tc qdisc add netem help
Usage: ... netem [ limit PACKETS ] 
                 [ delay TIME [ JITTER [CORRELATION]]]
                 [ distribution {uniform|normal|pareto|paretonormal} ]
                 [ corrupt PERCENT [CORRELATION]] 
                 [ duplicate PERCENT [CORRELATION]]
                 [ loss random PERCENT [CORRELATION]]
                 [ loss state P13 [P31 [P32 [P23 P14]]]
                 [ loss gemodel PERCENT [R [1-H [1-K]]]
                 [ ecn ]
                 [ reorder PRECENT [CORRELATION] [ gap DISTANCE ]]
                 [ rate RATE [PACKETOVERHEAD] [CELLSIZE] [CELLOVERHEAD]]

That’s a wealth of options. I can simulate somewhat unreliable WAN links, even with variations in delay! Refer to the Linux Foundation wiki for more details on how to simulate networks more realistically.

Introducing Delay

I prefer to keep it simple for this post, so I’ll stick with the most basic setting for network delay. I am introducing this to the Data Guard network on both of my standby nodes while connected to the management interface eth2:

[root@rac12sec1 ~]# tc qdisc add dev eth0 root netem delay 100ms

[root@rac12sec1 ~]# tc qdisc
qdisc netem 8001: dev eth0 root refcnt 2 limit 1000 delay 100.0ms
qdisc pfifo_fast 0: dev eth1 root refcnt 2 bands 3 priomap  1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
qdisc pfifo_fast 0: dev eth2 root refcnt 2 bands 3 priomap  1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1

[root@rac12sec2 ~]# tc qdisc
qdisc netem 8001: dev eth0 root refcnt 2 limit 1000 delay 100.0ms
qdisc pfifo_fast 0: dev eth1 root refcnt 2 bands 3 priomap  1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1
qdisc pfifo_fast 0: dev eth2 root refcnt 2 bands 3 priomap  1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1

[root@rac12sec2 ~]# tc qdisc show dev eth0 
qdisc netem 8001: root refcnt 2 limit 1000 delay 100.0ms

The effect can be seen immediately by pinging one of the standby nodes:

[oracle@rac12pri1 ~]$ ping rac12sec1
PING rac12sec1.example.com (192.168.100.20) 56(84) bytes of data.
64 bytes from rac12sec1.example.com (192.168.100.20): icmp_seq=1 ttl=64 time=100 ms
64 bytes from rac12sec1.example.com (192.168.100.20): icmp_seq=2 ttl=64 time=100 ms
64 bytes from rac12sec1.example.com (192.168.100.20): icmp_seq=3 ttl=64 time=100 ms
64 bytes from rac12sec1.example.com (192.168.100.20): icmp_seq=4 ttl=64 time=100 ms
^C
--- rac12sec1.example.com ping statistics ---
4 packets transmitted, 4 received, 0% packet loss, time 3003ms
rtt min/avg/max/mdev = 100.368/100.415/100.478/0.229 ms
[oracle@rac12pri1 ~]$ 

So 100ms delay it is!

Starting the Benchmark

With the scene set, it’s time to start the benchmark. The command to start it resembles the one I used for part I, except for the name of the results file.

[oracle@loadgen1 bin]$ ./charbench -cs //rac12pri-scan/swingbench_both \
> -uc 20 -r results_20_maxavail_netem.xml -rt 00:10
Author  :	 Dominic Giles
Version :	 2.5.0.971

Results will be written to results_20_maxavail_netem.xml.
Hit Return to Terminate Run...

Time		Users	TPM	TPS

1:08:56 PM      20      5188    94          

What effect does this have on the database? Let’s check the Data Guard broker first:

DGMGRL> show database 'NCDBB'

Database - NCDBB

  Role:               PHYSICAL STANDBY
  Intended State:     APPLY-ON
  Transport Lag:      0 seconds (computed 0 seconds ago)
  Apply Lag:          10 seconds (computed 0 seconds ago)
  Average Apply Rate: 207.00 KByte/s
  Real Time Query:    OFF
  Instance(s):
    NCDBB1
    NCDBB2 (apply instance)

Database Status:
SUCCESS

DGMGRL> show database 'NCDBB'

Database - NCDBB

  Role:               PHYSICAL STANDBY
  Intended State:     APPLY-ON
  Transport Lag:      0 seconds (computed 0 seconds ago)
  Apply Lag:          0 seconds (computed 0 seconds ago)
  Average Apply Rate: 211.00 KByte/s
  Real Time Query:    OFF
  Instance(s):
    NCDBB1
    NCDBB2 (apply instance)

Database Status:
SUCCESS

So it looks like there isn’t any lag visible with the benchmark underway, however it took a little while for it to start as visible in the first example. Here is the output from Tanel Poder’s ASHTOP script again (using Tanel Poder’s ashtop again – which requires you to have the Diagnostic Pack license as it access v$active_session_history):

SQL> @ashtop program,event,wait_class,session_state session_type='BACKGROUND' "to_date('17.02.2017 08:10','dd.mm.yyyy hh24:mi')" "to_date('17.02.2017 08:15','dd.mm.yyyy hh24:mi')"

    Total
  Seconds     AAS %This   PROGRAM                                          EVENT                                    WAIT_CLASS      SESSION FIRST_SEEN          LAST_SEEN           DIST_SQLEXEC_SEEN
--------- ------- ------- ------------------------------------------------ ---------------------------------------- --------------- ------- ------------------- ------------------- -----------------
      298     1.0   24% | oracle@rac12pri1 (LGWR)                          SYNC Remote Write                        Other           WAITING 2017-02-17 08:10:00 2017-02-17 08:14:59                 1
      298     1.0   24% | oracle@rac12pri1 (NSS2)                          Redo Transport MISC                      Other           WAITING 2017-02-17 08:10:00 2017-02-17 08:14:59                 1
      276      .9   23% | oracle@rac12pri2 (LGWR)                          SYNC Remote Write                        Other           WAITING 2017-02-17 08:10:00 2017-02-17 08:14:59                 1
      274      .9   23% | oracle@rac12pri2 (NSS2)                          Redo Transport MISC                      Other           WAITING 2017-02-17 08:10:00 2017-02-17 08:14:59                 1
        8      .0    1% | oracle@rac12pri2 (LMS1)                                                                                   ON CPU  2017-02-17 08:10:16 2017-02-17 08:14:59                 1
        7      .0    1% | oracle@rac12pri2 (LMS0)                          gcs log flush sync                       Other           WAITING 2017-02-17 08:10:43 2017-02-17 08:14:51                 1
        5      .0    0% | oracle@rac12pri1 (LMS0)                          gcs log flush sync                       Other           WAITING 2017-02-17 08:10:23 2017-02-17 08:13:48                 1
        5      .0    0% | oracle@rac12pri2 (LMS0)                                                                                   ON CPU  2017-02-17 08:10:00 2017-02-17 08:13:24                 1
        5      .0    0% | oracle@rac12pri2 (NSV1)                                                                                   ON CPU  2017-02-17 08:12:43 2017-02-17 08:14:44                 1
        4      .0    0% | oracle@rac12pri1 (DBW0)                                                                                   ON CPU  2017-02-17 08:11:16 2017-02-17 08:13:35                 1
        3      .0    0% | oracle@rac12pri2 (CJQ0)                                                                                   ON CPU  2017-02-17 08:12:39 2017-02-17 08:12:51                 2
        3      .0    0% | oracle@rac12pri2 (RSM0)                                                                                   ON CPU  2017-02-17 08:11:44 2017-02-17 08:14:44                 3
        2      .0    0% | oracle@rac12pri1 (LMON)                          control file sequential read             System I/O      WAITING 2017-02-17 08:11:51 2017-02-17 08:14:01                 1
        2      .0    0% | oracle@rac12pri1 (LMS1)                          gcs log flush sync                       Other           WAITING 2017-02-17 08:11:14 2017-02-17 08:11:44                 1
        2      .0    0% | oracle@rac12pri2 (DBW0)                          db file parallel write                   System I/O      WAITING 2017-02-17 08:12:14 2017-02-17 08:14:24                 1
        2      .0    0% | oracle@rac12pri2 (LGWR)                          log file parallel write                  System I/O      WAITING 2017-02-17 08:12:59 2017-02-17 08:14:42                 1
        1      .0    0% | oracle@rac12pri1 (CKPT)                          control file sequential read             System I/O      WAITING 2017-02-17 08:13:46 2017-02-17 08:13:46                 1
        1      .0    0% | oracle@rac12pri1 (DBW0)                          db file parallel write                   System I/O      WAITING 2017-02-17 08:10:28 2017-02-17 08:10:28                 1
        1      .0    0% | oracle@rac12pri1 (LGWR)                          Redo Transport Close                     Other           WAITING 2017-02-17 08:12:22 2017-02-17 08:12:22                 1
        1      .0    0% | oracle@rac12pri1 (LGWR)                          log file sequential read                 System I/O      WAITING 2017-02-17 08:14:16 2017-02-17 08:14:16                 1

20 rows selected.

As you can see the top waits are in wait class “other”: “SYNC Remote Write” and “Redo Transport MISC”. I have pulled an AWR diff report that shows an interesting picture. The first snapshot set represents the full network performance, while the second one shows the effect of the 100ms network delay. Only relevant information is shown.

WORKLOAD REPOSITORY RAC Compare Period Report for

Database Summary
~~~~~~~~~~~~~~~~
                            Database                   Snapshot Ids     Number of Instances    Number of Hosts    Report Total (minutes)
               ----------------------------------   -----------------   -----------------   -----------------   ---------------------
Snapshot Set            Id Name      RAC Block Si      Begin      End   In Repor    Total   In Repor    Total      DB time Elapsed ti
------------   ----------- --------- --- --------   -------- --------   -------- --------   -------- --------   ---------- ----------
First (1st)      481582958 NCDBA     YES     8192        303      304          2        2          2        2         22.1       10.2
Second (2nd)     481582958 NCDBA     YES     8192        301      302          2        2          2        2        141.9       10.6
Database Instances Included In Report
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                                                                             Elapsed              Instance Avg Activ
Set       DB Id Inst Instance  Release         Host       Startup         Begin Snap Time End Snap Time   Time (min) DB time (m Up Time (h  Sessions Platform
--- ----------- ---- --------- --------------- ---------- --------------- --------------- --------------- ---------- ---------- ---------- --------- ---------------
1st   481582958    1 NCDBA1    12.1.0.2.0      rac12pri1  17-Feb-17 04:00 17-Feb-17 08:59 17-Feb-17 09:09       10.0        2.0        5.2       0.2 Linux x86 64-bi
                   2 NCDBA2    12.1.0.2.0      rac12pri2  17-Feb-17 04:00 17-Feb-17 08:59 17-Feb-17 09:09       10.0       20.1        5.2       2.0 Linux x86 64-bi

2nd   481582958    1 NCDBA1    12.1.0.2.0      rac12pri1  17-Feb-17 04:00 17-Feb-17 08:06 17-Feb-17 08:17       10.5      134.0        4.3      12.8 Linux x86 64-bi
                   2 NCDBA2    12.1.0.2.0      rac12pri2  17-Feb-17 04:00 17-Feb-17 08:07 17-Feb-17 08:17       10.5        7.9        4.3       0.8 Linux x86 64-bi

...

Workload Comparison
~~~~~~~~~~~~~~~~~~~                      1st Per Sec          2nd Per Sec      %Diff              1st Per Txn          2nd Per Txn      %Diff
                                     ---------------      ---------------     ------          ---------------      ---------------     ------
                       DB time:                  2.2                 13.3      514.3                      0.0                  0.2    1,600.0
                      CPU time:                  1.5                  0.5      -66.0                      0.0                  0.0        0.0
           Background CPU time:                  0.5                  0.2      -56.9                      0.0                  0.0        0.0
             Redo size (bytes):            983,488.1            322,026.1      -67.3                  4,164.1              4,192.4        0.7
         Logical read (blocks):             30,773.7              8,299.3      -73.0                    130.3                108.0      -17.1
                 Block changes:              5,665.8              1,886.0      -66.7                     24.0                 24.6        2.3
        Physical read (blocks):                 10.5                 18.3       74.4                      0.0                  0.2      500.0
       Physical write (blocks):                654.9                196.8      -69.9                      2.8                  2.6       -7.6
              Read IO requests:                 10.1                 12.9       27.3                      0.0                  0.2      325.0
             Write IO requests:                503.8                110.4      -78.1                      2.1                  1.4      -32.4
                  Read IO (MB):                  0.1                  0.1       75.0                      0.0                  0.0        0.0
                 Write IO (MB):                  5.1                  1.5      -69.9                      0.0                  0.0        0.0
                  IM scan rows:                  0.0                  0.0        0.0                      0.0                  0.0        0.0
       Session Logical Read IM:
                    User calls:                515.8                188.2      -63.5                      2.2                  2.5       12.4
                  Parses (SQL):                 24.9                 17.7      -28.8                      0.1                  0.2      109.1
             Hard parses (SQL):                  0.1                  0.2       45.5                      0.0                  0.0        0.0
            SQL Work Area (MB):                  0.1                  0.5      253.8                      0.0                  0.0      253.8
                        Logons:                  1.3                  3.9      191.7                      0.0                  0.1      400.0
                Executes (SQL):              2,587.7                853.0      -67.0                     11.0                 11.1        1.4
                  Transactions:                236.2                 76.8      -67.5

...

Top Timed Events   First DB/Inst: NCDBA/NCDBA1 Snaps: 303-304 (Elapsed time: 612.266 sec  DB time: 1326.09 sec),  Second DB/Inst: NCDBA/NCDBA1 Snaps: 301-302 (Elapsed time: 638.691 sec  DB time: 8514.42 sec)
-> Events with a "-" did not make the Top list in this set of snapshots, but are displayed for comparison purposes
-> Summary for all instances

                                               1st                                                                                                2nd
------------------------------------------------------------------------------------------------   ------------------------------------------------------------------------------------------------
Event                          Wait Class           Waits      Time(s)  Avg Time(ms)    %DB time   Event                          Wait Class           Waits      Time(s)  Avg Time(ms)    %DB time
------------------------------ ------------- ------------ ------------ ------------- -----------   ------------------------------ ------------- ------------ ------------ ------------- -----------
 CPU time                                             N/A        919.5           N/A        69.3    log file sync                 Commit              49,010      7,976.7         162.8        93.7
 log file sync                 Commit             144,284        270.4           1.9        20.4    Redo Transport MISC           Other               11,392      1,192.0         104.6        14.0
 log file parallel write       System I/O         141,581        156.6           1.1        11.8    SYNC Remote Write             Other               11,392      1,179.1         103.5        13.8
 gc current block 2-way        Cluster             98,483         71.9           0.7         5.4    CPU time                                             N/A        328.7           N/A         3.9
 gc cr block 2-way             Cluster             71,469         47.9           0.7         3.6    gcs log flush sync            Other                4,480         56.0          12.5         0.7
 target log write size         Other               22,284         26.5           1.2         2.0    gc current block 2-way        Cluster             62,843         43.3           0.7         0.5
 gc current grant busy         Cluster             22,561         16.8           0.7         1.3    gc current block busy         Cluster                284         39.3         138.4         0.5
 control file sequential read  System I/O           8,497          6.0           0.7         0.5    log file switch (checkpoint i Configuration           75         37.1         495.1         0.4
 db file sequential read       User I/O             5,862          5.4           0.9         0.4    rdbms ipc reply               Other                   32         27.1         845.4         0.3
 log file sequential read      System I/O          14,895          4.8           0.3         0.4    gc cr block 2-way             Cluster             39,015         26.0           0.7         0.3
-log file switch (checkpoint i Configuration          212          3.6          17.2         0.3   -log file parallel write       System I/O          11,267         20.3           1.8         0.2
-gcs log flush sync            Other                  461          0.4           0.9         0.0   -gc current grant busy         Cluster             12,427          8.2           0.7         0.1
-gc current block busy         Cluster                126          0.3           2.7         0.0   -control file sequential read  System I/O           7,326          5.0           0.7         0.1
-                                                     N/A          N/A           N/A         N/A   -db file sequential read       User I/O             6,615          4.7           0.7         0.1
-                                                     N/A          N/A           N/A         N/A   -log file sequential read      System I/O             174          0.4           2.4         0.0
                          --------------------------------------------------------------------------------------------------------------------

This doesn’t look too good, does it? The throughput is down substantially, which is visible in Swingbench itself: in the first example I managed to achieve 255 TPS while I’m averaging 90-95 in the synch + delay example. The numbers from the AWR excerpt shown above confirm this, and allows you to work out where the problem is.

Here is a print screen taken from OEM (that’s a different benchmark execution), showing the same situation. Make sure you are licensed appropriately to use this view.

Summary Part II

So yes, there is a very noticeable affect of the network delay, and the AWR report shows the relevant wait events in 12c indicating where time is spent.

In my opinion it’s a bit unfortunate to have the new waits in the “Other” wait class, but that’s how it is.

References

http://www.oracle.com/technetwork/database/availability/sync-2437177.pdf

New Events for Data Guard and Synchronous Redo Transport in 12c (1)

I may have said it before but I consider presenting and teaching a great way to expand one’s knowledge: first of all it requires me to really understand a subject. Secondly, when presenting, you get lots of interesting questions that can turn into blog posts like this one.

Lately I have been asked about the impact of synchronous log shipping to a physical standby database. I was sure there was an effect to be observed, depending most likely on the network latency between systems but I didn’t have any evidence I could pull out of the hat to back up my thoughts. So what better than trying! I also read that some of the events have changed in 12c, and wanted to make them visible. My environment is based on the 2 node RAC primary/2 node RAC standby configuration I wrote about in my previous posts.

Since their initial setup I upgraded the cluster to 12.1.0.2.170117 for Clusterware and RDBMS.

I am planning to share my findings in two posts: the first one (the one you are reading) will present the baseline, the second one to follow shows how performance can be impacted by poor network performance. I guess the second one will be a bit longer …

Background

Data Guard allows the administrator to define the databases in a Data Guard configuration to be in one of three possible modes. The first one is Maximum Performance, the second Maximum Availability and finally Maximum Protection. All three modes are covered in the official documentation set and MOS. Without saying it very scientifically:

• Maximum Performance uses asynchronous log shipping and is the default. The performance of the standby database (or rather lack thereof) should not impact the performance of the primary. At a cost: it is not guaranteed that redo is actually written to the standby when the commit command returns.
• Maximum Protection allows you to enforce a Zero Data Loss (ZDL) strategy but also at a cost: The primary will shut down if it can’t transmit redo information to the standby. That is how you prevent data loss!
• Maximum Availability is the middle ground and I’ll focus on that protection mode here.

Make sure to read the documentation and understand the implications of each protection mode when assessing the most suitable mode for your environment!

Background: New Events

Before going into details I should probably point out that there are some new Data Guard events. Hurray! More events and more meaningful names, great. Just one caveat-have a look at the output from my 12c database:

select name, wait_class from v$event_name
where name in (
'ARCH Remote Write','ASYNC Remote Write','Redo Transport Attach',
'Redo Transport Close','Redo Transport Detach','Redo Transport Open',
'Redo Transport Ping','Redo Transport Slave Shutdown','Redo Transport Slave Startup',
'Redo Writer Remote Sync Complete', 'Redo Writer Remote Sync Notify',
'Remote SYNC Ping','SYNC Remote Write');

NAME                                               WAIT_CLASS
-------------------------------------------------- ----------------------------------------
ASYNC Remote Write                                 Other
SYNC Remote Write                                  Other
ARCH Remote Write                                  Other
Redo Transport Attach                              Other
Redo Transport Detach                              Other
Redo Transport Open                                Other
Redo Transport Close                               Other
Redo Transport Ping                                Other
Remote SYNC Ping                                   Other
Redo Transport Slave Startup                       Other
Redo Transport Slave Shutdown                      Other
Redo Writer Remote Sync Notify                     Other
Redo Writer Remote Sync Complete                   Other

13 rows selected.

Compare this to the pre 12c events (taken from an 11.2.0.3 database since they are mostly gone in 12c)

select name, wait_class from v$event_name
where name in (
'ARCH wait on ATTACH','ARCH wait on SENDREQ','ARCH wait on DETACH',
'LNS wait on ATTACH', 'LNS wait on SENDREQ','LNS wait on DETACH',
'LGWR wait on LNS','LNS wait on LGWR','LGWR-LNS wait on channel');

NAME                                               WAIT_CLASS
-------------------------------------------------- --------------------
ARCH wait on ATTACH                                Network
LNS wait on ATTACH                                 Network
LNS wait on SENDREQ                                Network
LNS wait on DETACH                                 Network
ARCH wait on SENDREQ                               Network
ARCH wait on DETACH                                Network
LNS wait on LGWR                                   Network
LGWR wait on LNS                                   Network
LGWR-LNS wait on channel                           Other

9 rows selected.

For the sake of completeness here are those events that remained in 12c:

select name, wait_class from v$event_name
where name in (
'ARCH wait on ATTACH','ARCH wait on SENDREQ','ARCH wait on DETACH',
'LNS wait on ATTACH', 'LNS wait on SENDREQ','LNS wait on DETACH',
'LGWR wait on LNS','LNS wait on LGWR','LGWR-LNS wait on channel');

NAME                           WAIT_CLASS
------------------------------ ------------------------------
LNS wait on LGWR               Network
LGWR wait on LNS               Network
LGWR-LNS wait on channel       Other

Bugger. The new events are all in the “Other” wait class. My initial attempts at filtering information from v$event_histogram based on events with the “Network” class had little success. I guess friends of the OEM performance pages might also find that interesting. If you wonder from where I pulled these events – I used a white paper named “Best Practices for Synchronous Redo Transport” as reference.

Testing: The Environment

As you read in the introduction, this environment is based on a two node RAC primary -> two node RAC standby configuration:

DGMGRL> show configuration verbose

Configuration - ractest

  Protection Mode: MaxPerformance
  Members:
  NCDBA - Primary database
    NCDBB - Physical standby database

  Properties:
    FastStartFailoverThreshold      = '30'
    OperationTimeout                = '30'
    TraceLevel                      = 'USER'
    FastStartFailoverLagLimit       = '30'
    CommunicationTimeout            = '180'
    ObserverReconnect               = '0'
    FastStartFailoverAutoReinstate  = 'TRUE'
    FastStartFailoverPmyShutdown    = 'TRUE'
    BystandersFollowRoleChange      = 'ALL'
    ObserverOverride                = 'FALSE'
    ExternalDestination1            = ''
    ExternalDestination2            = ''
    PrimaryLostWriteAction          = 'CONTINUE'

Fast-Start Failover: DISABLED

Configuration Status:
SUCCESS
DGMGRL> show database 'NCDBA';

Database - NCDBA

  Role:               PRIMARY
  Intended State:     TRANSPORT-ON
  Instance(s):
    NCDBA1
    NCDBA2

Database Status:
SUCCESS

DGMGRL> show database 'NCDBB'

Database - NCDBB

  Role:               PHYSICAL STANDBY
  Intended State:     APPLY-ON
  Transport Lag:      0 seconds (computed 0 seconds ago)
  Apply Lag:          0 seconds (computed 0 seconds ago)
  Average Apply Rate: 177.00 KByte/s
  Real Time Query:    OFF
  Instance(s):
    NCDBB1
    NCDBB2 (apply instance)

Database Status:
SUCCESS

DGMGRL> show database 'NCDBA' LogXptMode
  LogXptMode = 'async'
DGMGRL> show database 'NCDBB' LogXptMode
  LogXptMode = 'async'

The configuration is currently set to “Maximum Performance”, databases ship redo asynchronously.

All systems are patched to the January 2017 Proactive Bundle Patch:

[oracle@rac12pri1 ~]$ $ORACLE_HOME/OPatch/opatch lspatches
24917972;Database PSU 12.1.0.2.170117, Oracle JavaVM Component (JAN2017)
24732082;Database Patch Set Update : 12.1.0.2.170117 (24732082)
24828633;OCW Patch Set Update : 12.1.0.2.170117 (24828633)

OPatch succeeded.

Testing part I: The Baseline

I am using Swingbench’s Order Entry benchmark to generate a little bit of load. For the avoidance of doubt: I am not interested in a comparison between asynchronous and synchronous log shipping. I would like to see the effect caused by the difference in latency in the form of hugely increased waits. In my first test I am running with the defaults of my VM (the NIC uses virtio drivers), no change to SDU or send/receive buffers.

$ date
Fri Feb 17 13:58:58 UTC 2017
$ ./charbench -cs //rac12pri-scan/swingbench_both \
> -uc 20 -r results_20_maxperf.xml -rt 00:10
Author  :        Dominic Giles
Version :        2.5.0.971

Results will be written to results_20_maxperf.xml.
Hit Return to Terminate Run...

Time            Users   TPM     TPS

1:59:55 PM      20      3852    255

On the apply side this translates to the following figures (the average apply rate is misleading and should be ignored; it captures all apply since MRP0 was started)

DGMGRL> show database 'NCDBB'

Database - NCDBB

  Role:               PHYSICAL STANDBY
  Intended State:     APPLY-ON
  Transport Lag:      0 seconds (computed 0 seconds ago)
  Apply Lag:          0 seconds (computed 0 seconds ago)
  Average Apply Rate: 713.00 KByte/s
  Real Time Query:    OFF
  Instance(s):
    NCDBB1
    NCDBB2 (apply instance)

Database Status:
SUCCESS

There is no transport lag, and no apply lag either. When checking for waits on background processes (using Tanel Poder’s ashtop – which requires you to have the Diagnostic Pack license as it access v$active_session_history) I noticed the following:

SQL> @ashtop program,event,wait_class,session_state session_type='BACKGROUND' "to_date('17.02.2017 09:02','dd.mm.yyyy hh24:mi')" "to_date('17.02.2017 09:07','dd.mm.yyyy hh24:mi')"

    Total
  Seconds     AAS %This   PROGRAM                                          EVENT                                    WAIT_CLASS      SESSION FIRST_SEEN          LAST_SEEN           DIST_SQLEXEC_SEEN
--------- ------- ------- ------------------------------------------------ ---------------------------------------- --------------- ------- ------------------- ------------------- -----------------
       53      .2   29% | oracle@rac12pri2 (LGWR)                          log file parallel write                  System I/O      WAITING 2017-02-17 09:03:42 2017-02-17 09:06:53                 1
       23      .1   13% | oracle@rac12pri2 (LG00)                          log file parallel write                  System I/O      WAITING 2017-02-17 09:02:03 2017-02-17 09:03:26                 1
       19      .1   10% | oracle@rac12pri2 (DBW0)                                                                                   ON CPU  2017-02-17 09:02:07 2017-02-17 09:06:39                 1
       12      .0    7% | oracle@rac12pri2 (LGWR)                          target log write size                    Other           WAITING 2017-02-17 09:02:03 2017-02-17 09:03:27                 1
        9      .0    5% | oracle@rac12pri1 (LMS1)                                                                                   ON CPU  2017-02-17 09:04:37 2017-02-17 09:06:58                 1
        8      .0    4% | oracle@rac12pri2 (TT00)                                                                                   ON CPU  2017-02-17 09:02:15 2017-02-17 09:06:56                 1
        6      .0    3% | oracle@rac12pri1 (LG00)                          log file parallel write                  System I/O      WAITING 2017-02-17 09:03:08 2017-02-17 09:06:44                 1
        6      .0    3% | oracle@rac12pri2 (LGWR)                                                                                   ON CPU  2017-02-17 09:04:05 2017-02-17 09:06:41                 1
        5      .0    3% | oracle@rac12pri2 (LG00)                                                                                   ON CPU  2017-02-17 09:02:02 2017-02-17 09:03:27                 1
        5      .0    3% | oracle@rac12pri2 (LMS0)                                                                                   ON CPU  2017-02-17 09:02:07 2017-02-17 09:06:14                 1
        5      .0    3% | oracle@rac12pri2 (LMS1)                                                                                   ON CPU  2017-02-17 09:02:24 2017-02-17 09:06:28                 1
        4      .0    2% | oracle@rac12pri1 (LMS0)                                                                                   ON CPU  2017-02-17 09:04:21 2017-02-17 09:06:05                 1
        3      .0    2% | oracle@rac12pri1 (LGWR)                          LGWR all worker groups                   Other           WAITING 2017-02-17 09:03:08 2017-02-17 09:06:13                 1
        2      .0    1% | oracle@rac12pri1 (DBW0)                          db file parallel write                   System I/O      WAITING 2017-02-17 09:03:08 2017-02-17 09:03:42                 1
        2      .0    1% | oracle@rac12pri2 (CKPT)                                                                                   ON CPU  2017-02-17 09:05:10 2017-02-17 09:05:13                 1
        2      .0    1% | oracle@rac12pri2 (TT00)                          log file sequential read                 System I/O      WAITING 2017-02-17 09:03:17 2017-02-17 09:03:46                 1
        1      .0    1% | oracle@rac12pri1 (CJQ0)                                                                                   ON CPU  2017-02-17 09:04:44 2017-02-17 09:04:44                 1
        1      .0    1% | oracle@rac12pri1 (DBW0)                                                                                   ON CPU  2017-02-17 09:03:05 2017-02-17 09:03:05                 1
        1      .0    1% | oracle@rac12pri1 (LG00)                                                                                   ON CPU  2017-02-17 09:02:02 2017-02-17 09:02:02                 1
        1      .0    1% | oracle@rac12pri1 (LGWR)                          target log write size                    Other           WAITING 2017-02-17 09:05:47 2017-02-17 09:05:47                 1

The time difference between charbench and the database can be explained by time zones: my load generator is set to use UTC whereas the database is on EST; the result is a 6 hour time difference. This is a minor oversight on my part and has nothing to do with the location of the machines. In fact, they are all virtualised.

Summary Part I

In this part I tried to lay the foundation for the next one where I’m using my lab environment to simulate an artificially high network latency. I have to admit again that my setup is somewhat over-simplified-using Data Guard with asynchronous log shipping and Maximum Performance mode is not something I’d like to support for anything more important than my toy databases in the lab.

References

http://www.oracle.com/technetwork/database/availability/sync-2437177.pdf

TABLE ACCESS INMEMORY FULL – but there may be more

While preparing to teach a class this week I have had the time to look into the In Memory (cost) option a bit closer. I noticed a few interesting things along the way and would like to share one of these here.

Background

One of the questions I was asking myself was:

“What happens if I scan segments that are within the IM area, and some are not?”

I was primarily thinking of joins in a DWH environment, but in order to keep the test case simple enough and reproducible I decided to go with a partitioned table where the current partition is assigned to the IMCS, and the rest is not. For this test I’m relying on the Swingbench SH schema. All of this runs on my laptop in a VM so I had to be selective when it comes to indexes. I also chose to NOT partition the tables at this stage, I wanted to chose my own partitioning scheme. For reference, here is the command that created the SH schema:

[oracle@oraclelinux7 bin]$ ./shwizard -cl -create -cs //localhost/sh_pdb \
> -dba system -dbap somePassword -nopart -pkindexes -scale 1 -tc 2 -u sh -p sh
...
============================================
|           Datagenerator Run Stats        |
============================================
Connection Time                        0:00:00.005
Data Generation Time                   0:04:35.890
DDL Creation Time                      0:00:14.063
Total Run Time                         0:04:49.962
Rows Inserted per sec                       64,707
Data Generated (MB) per sec                    5.3
Actual Rows Generated                   17,848,007

...

I wanted to create a range partitioned version of the sales table. After the SH-wizard completed the data distribution is as shown:

SQL> select count(*), trunc(time_id,'yy') year from sales group by trunc(time_id,'yy') order by year;

  COUNT(*) YEAR
---------- ---------
    130653 01-JAN-95
    149319 01-JAN-96
    251974 01-JAN-97
    326632 01-JAN-98
    365547 01-JAN-99
    388318 01-JAN-00
    393919 01-JAN-01
    406703 01-JAN-02
    483605 01-JAN-03
    566384 01-JAN-04
    422289 01-JAN-05
    619858 01-JAN-06
    782244 01-JAN-07
   1099551 01-JAN-08
   1249340 01-JAN-09
   1346025 01-JAN-10
   1690302 01-JAN-11
   2028048 01-JAN-12
   2028048 01-JAN-13

19 rows selected.

So based on this information I can create a table that has data from 2013 in the IMCS and everything else will be excluded from it. For the sake of the following discussion 2013 is considered the “current” partition. Here is the partitioned sales table’s DDL with my changes to enable my partitioning scheme.

CREATE TABLE SALES_PART
  (
    PROD_ID            NUMBER NOT NULL ENABLE,
    CUST_ID            NUMBER NOT NULL ENABLE,
    TIME_ID            DATE NOT NULL ENABLE,
    CHANNEL_ID         NUMBER NOT NULL ENABLE,
    PROMO_ID           NUMBER NOT NULL ENABLE,
    QUANTITY_SOLD      NUMBER(10,2) NOT NULL ENABLE,
    SELLER             NUMBER(6,0) NOT NULL ENABLE,
    FULFILLMENT_CENTER NUMBER(6,0) NOT NULL ENABLE,
    COURIER_ORG        NUMBER(6,0) NOT NULL ENABLE,
    TAX_COUNTRY        VARCHAR2(3) NOT NULL ENABLE,
    TAX_REGION         VARCHAR2(3),
    AMOUNT_SOLD        NUMBER(10,2) NOT NULL ENABLE
  )
  partition BY range (time_id)
  (
    partition p_old VALUES less than       (DATE '2001-01-01'),
    partition p_2000_2010 VALUES less than (DATE '2011-01-01'),
    partition p_2011 VALUES less than      (DATE '2012-01-01'),
    partition p_2012 VALUES less than      (DATE '2013-01-01'),
    partition p_2013 VALUES less than      (DATE '2014-01-01') inmemory
  )
  TABLESPACE SH;

SQL> alter session enable parallel dml;

Session altered.

SQL> insert /*+ parallel append */ into sales_part select /*+ parallel */ * from sales
  2  /

14728759 rows created.

SQL> commit;

Commit complete.

SQL> exec dbms_stats.gather_table_stats(user,'SALES_PART')

PL/SQL procedure successfully completed.

SQL> select partition_name, num_rows, inmemory
  2  from user_tab_partitions
  3  where table_name = 'SALES_PART'
  4  order by partition_position;

PARTITION_NAME                   NUM_ROWS INMEMORY
------------------------------ ---------- --------
P_OLD                             1612443 DISABLED
P_2000_2010                       7369918 DISABLED
P_2011                            1690302 DISABLED
P_2012                            2028048 DISABLED
P_2013                            2028048 ENABLED

So that should give me what I needed. The IMCS was now populated with the segment as well:

SQL> select segment_name, partition_name, bytes_not_populated, populate_status from v$im_user_segments;

SEGMENT_NAME         PARTITION_NAME                 BYTES_NOT_POPULATED POPULATE_
-------------------- ------------------------------ ------------------- ---------
SALES_PART           P_2013                                           0 COMPLETED

Test

With the setup work complete I am ready to test. First of all, a simple SQL trace should show me what is happening. Note that I am specifically targeting the “current” partition.

SQL> sho user
USER is "SH"
SQL> alter session set events 'sql_trace level 8';

Session altered.

SQL> select /* current_partition */ count(*) from sales_part
  2  where time_id > DATE '2013-01-02'
  3  and promo_id = 316;

  COUNT(*)
----------
      3947

SQL> alter session set events 'sql_trace off';

Session altered.

SQL> select value from v$diag_info where name like 'Def%';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/cdb/CDB/trace/CDB_ora_14034.trc

The tkprof’d trace shows this result:

********************************************************************************

select /* current_partition */ count(*) from sales_part
where time_id > DATE '2013-01-02'
and promo_id = 316

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          3          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.01          0          5          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 117  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=3 pr=0 pw=0 time=8441 us)
      3947       3947       3947   PARTITION RANGE SINGLE PARTITION: 5 5 (cr=3 pr=0 pw=0 time=7583 us cost=214 size=48252 card=4021)
      3947       3947       3947    TABLE ACCESS INMEMORY FULL SALES_PART PARTITION: 5 5 (cr=3 pr=0 pw=0 time=6972 us cost=214 size=48252 card=4021)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        6.79          6.79
********************************************************************************

As you can see, my partitioning strategy paid off-only the 5th partition is accessed (that’s p_2013 or the “current” partition based on the data). This partition is the one entirely found in the IMCS.

A result like the one above is what I’d expect and the access path “TABLE ACCESS INMEMORY FULL” does it justice. But now the actual reason for the blog post: mixing scans against segments in memory and on disk. Logging on again I ran the same query but without the restriction to 2013.

SQL> alter session set events 'sql_trace level 8';

Session altered.

SQL> select /* every_partition */ count(*) from sales_part
  2  where promo_id = 316;

  COUNT(*)
----------
     28993

SQL> alter session set events 'sql_trace off';

Session altered.

SQL> select value from v$diag_info where name like 'Def%';

VALUE
----------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/cdb/CDB/trace/CDB_ora_14437.trc

The tkprof’d result is shown here:

select /* every_partition */ count(*) from sales_part
where promo_id = 316

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        2      3.15       3.84      94878      94901          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      3.15       3.84      94878      94901          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 117  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=94901 pr=94878 pw=0 time=3848392 us)
     28993      28993      28993   PARTITION RANGE ALL PARTITION: 1 5 (cr=94901 pr=94878 pw=0 time=4503583 us cost=26217 size=117128 card=29282)
     28993      28993      28993    TABLE ACCESS INMEMORY FULL SALES_PART PARTITION: 1 5 (cr=94901 pr=94878 pw=0 time=4254867 us cost=26217 size=117128 card=29282)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  Disk file operations I/O                        4        0.00          0.00
  db file sequential read                         6        0.00          0.01
  direct path read                               42        0.01          0.18
  SQL*Net message from client                     2        7.63          7.63
********************************************************************************

Again the access path is clearly indicated as “TABLE ACCESS INMEMORY FULL SALES_PART”. This time it references all 5 partitions (which is expected since I didn’t have a date in my predicate list). And I can see direct path reads plus some other I/O related information! Direct Path Reads are quite likely going to be Smart Scans on Exadata by the way…

Of course “TABLE ACCESS INMEMORY FULL” is correct (because one partition is accessed that way), but I guess that you cannot see the disk-based I/O against the other segments from the regular execution plan as shown in SQLPlus for example .

Is there any other instrumentation I could use?

The tkprof output shows that data retrieval is possible for segments that are not (entirely) found in the IMCS. Where else could I learn about this fact? Session statistics (V$STATNAME, V$SESSTAT, etc) are another useful source of information. I am a great fan of session snapper (who isn’t?). Snapper can be used to display the change in the session counters while the session you are monitoring is running. Another option is Adrian Billington’s mystats script. It can help you capture the changes in session statistics during the execution of a SQL command. I executed the same query again, sandwiched into calls to mystats. Note that the statistics shown next do not match those of to the execution of the query above. I also tried to limit the output only to the relevant ones, output is sorted by statistic name.

------------------------------------------------------------------------------------------
2. Statistics Report
------------------------------------------------------------------------------------------
Type    Statistic Name                                                               Value
------  ----------------------------------------------------------------  ----------------

STAT    IM scan CUs columns accessed                                                     4
STAT    IM scan CUs columns theoretical max                                             48
STAT    IM scan CUs memcompress for query low                                            4
STAT    IM scan CUs predicates applied                                                   4
STAT    IM scan CUs predicates received                                                  4
STAT    IM scan CUs split pieces                                                         4
STAT    IM scan bytes in-memory                                                 47,683,308
STAT    IM scan bytes uncompressed                                              99,118,124
STAT    IM scan rows                                                             2,028,048
STAT    IM scan rows projected                                                       3,963
STAT    IM scan rows valid                                                       2,028,048
STAT    IM scan segments minmax eligible                                                 4

STAT    consistent gets                                                             95,093
STAT    consistent gets direct                                                      94,872
STAT    consistent gets examination                                                      4
STAT    consistent gets examination (fastpath)                                           4
STAT    consistent gets from cache                                                     221
STAT    consistent gets pin                                                            217
STAT    consistent gets pin (fastpath)                                                 217

STAT    logical read bytes from cache                                            9,666,560
STAT    no work - consistent read gets                                              94,871

STAT    physical read IO requests                                                      749
STAT    physical read bytes                                                    777,191,424
STAT    physical read total IO requests                                                749
STAT    physical read total bytes                                              777,191,424
STAT    physical read total multi block requests                                       749
STAT    physical reads                                                              94,872
STAT    physical reads direct                                                       94,872

STAT    session logical reads                                                      111,201
STAT    session logical reads - IM                                                  15,149

STAT    table scan blocks gotten                                                    94,872
STAT    table scan disk non-IMC rows gotten                                     12,700,711
STAT    table scan rows gotten                                                  14,728,759
STAT    table scans (IM)                                                                 1
STAT    table scans (direct read)                                                        4
STAT    table scans (long tables)                                                        5

STAT    temp space allocated (bytes)                                             1,048,576

STAT    workarea executions - optimal                                                    1
STAT    workarea memory allocated                                                        5
------------------------------------------------------------------------------------------
3. About
------------------------------------------------------------------------------------------
- MyStats v2.01 by Adrian Billington (http://www.oracle-developer.net)
- Based on the SNAP_MY_STATS utility by Jonathan Lewis
==========================================================================================
End of report
==========================================================================================

The highlights are:

• You can see the compression ratio of the data in the IMCS (IM scan bytes in-memory and IM scan bytes uncompressed)
• All rows in the partition were valid (the number of IM Scan rows equals the number of rows in the partition)
• One segment was scanned using IM, and 4 were scanned as direct (path) reads. A total of 5 segments were scanned

Hope this helps!

Little things worth knowing: automatic generation of extended statistics in 12c Part II

In my last post I demonstrated an example how to use a PL/SQL package to monitor a workload in order to identify correlated columns. Such columns are good candidates for the creation of extended statistics since the optimiser does not assume that information stored in different columns may be related. Before starting my tests I invoked DBMS_STATS.SEED_COL_USAGE, which in turn increased Oracle’s attention level trying to find correlated columns. Eventually these have been identified (as shown in the output of DBMS_STATS.REPORT_COL_USAGE) and a subsequent call to DBMS_STATS.GATHER_TABLE_STATS caused extended statistics to be created, including histograms. This is one way you can get extended statistics automatically, but it requires you to enable monitoring of a workload by invoking a PL/SQL API. In other words, it is a conscious effort.

More Ways to Extended Statistics

The other way of ending up with extended statistics is more subtle as it does not require user intervention. As described in the documentation (Database SQL Tuning Guide, chapter 13 “Managing Optimizer Statistics: Advanced Topics”) there is another way to gather extended statistics automatically. It is based on statistics feedback and SQL Plan Directives, both new to 12c (actually statistics feedback is not quite so new, it seems to be an evolution of cardinality feedback).

Demo

To start with a clean sheet I dropped the table I had used previously, which got rid of all the extended stats and SQL Plan Directives (SPD) from the previous example. To be really thorough I also flushed the shared pool.

SQL> drop table martin.customers purge;

Table dropped.

SQL> select * from dba_stat_extensions where owner = user;

no rows selected

SQL> select count(*) from DBA_SQL_PLAN_DIR_OBJECTS where owner = user;

  COUNT(*)
----------
         0

SQL> alter system flush shared_pool;

System altered.

BTW I have switched environments to an Oracle Restart 12.1.0.2 database with the JUL 2015 PSU applied. The second patch you see here is the OJVM patch.

SQL> select patch_id, version, action from dba_registry_sqlpatch;

  PATCH_ID VERSION              ACTION
---------- -------------------- ---------------
  20831110 12.1.0.2             APPLY
  21068507 12.1.0.2             APPLY

Back to creating the table… I am using the same technique as before, but this time without the call to DBMS_STATS.SEED_COL_USAGE:

SQL> create table martin.customers as select * from sh.customers;

Table created.

SQL> select num_rows, last_analyzed from user_tables where table_name = 'CUSTOMERS';

  NUM_ROWS LAST_ANALYZED
---------- -------------------
     55500 15.10.2015 16:57:42

I love the 12c feature where stats are gathered during a CTAS operation …

And now a few queries to tickle the optimiser. Apologies for the wide output but that makes it so much easier to use RLWRAP and command line history. Credit again to
the blog post by Maria Colgan for the query examples.

SQL> select /*+ gather_plan_statistics */ count(*) from customers where cust_city = 'Los Angeles' and cust_state_province = 'CA' and country_id = 52790;

  COUNT(*)
----------
       932

SQL>
SQL> select * from table(dbms_xplan.display_cursor(format => 'allstats last'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------
SQL_ID  34zmr3acgz06g, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from customers where
cust_city = 'Los Angeles' and cust_state_province = 'CA' and country_id
= 52790

Plan hash value: 296924608

---------------------------------------------------------------------------------------------------
| Id  | Operation          | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |           |      1 |        |      1 |00:00:00.03 |    1521 |   1516 |
|   1 |  SORT AGGREGATE    |           |      1 |      1 |      1 |00:00:00.03 |    1521 |   1516 |
|*  2 |   TABLE ACCESS FULL| CUSTOMERS |      1 |      1 |    932 |00:00:00.04 |    1521 |   1516 |
---------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))


22 rows selected.

There is nothing too new here-the optimiser’s cardinality estimate is not great. Following the example from the SQL Tuning Guide-chapter 13 (btw country_id is a number, not a varchar2 field) we can now check if there is anything fancy going to happen next. And sure enough there is:

SQL> select sql_id, child_number, is_obsolete, is_reoptimizable, is_resolved_adaptive_plan from v$sql where sql_id = '34zmr3acgz06g';

SQL_ID        CHILD_NUMBER I I I
------------- ------------ - - -
34zmr3acgz06g            0 N Y

The second flag, is_reoptimisable, is interesting. It indicates the optimiser’s intention to apply information found at run-time to the next execution of the cursor. Let’s run the original query again.

SQL> select /*+ gather_plan_statistics */ count(*) from customers where cust_city = 'Los Angeles' and cust_state_province = 'CA' and country_id = 52790;

  COUNT(*)
----------
       932

So what did that do? Let’s have a look at the diagnostics:

SQL> select sql_id, child_number, is_obsolete, is_reoptimizable, is_resolved_adaptive_plan from v$sql where sql_id = '34zmr3acgz06g';

SQL_ID        CHILD_NUMBER I I I
------------- ------------ - - -
34zmr3acgz06g            0 N Y
34zmr3acgz06g            1 N N

SQL> select * from table(dbms_xplan.display_cursor(sql_id=>'34zmr3acgz06g',cursor_child_no=>1,format => 'allstats last'));

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  34zmr3acgz06g, child number 1
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from customers where
cust_city = 'Los Angeles' and cust_state_province = 'CA' and country_id
= 52790

Plan hash value: 296924608

------------------------------------------------------------------------------------------
| Id  | Operation          | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |           |      1 |        |      1 |00:00:00.01 |    1521 |
|   1 |  SORT AGGREGATE    |           |      1 |      1 |      1 |00:00:00.01 |    1521 |
|*  2 |   TABLE ACCESS FULL| CUSTOMERS |      1 |    932 |    932 |00:00:00.01 |    1521 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))

Note
-----
   - statistics feedback used for this statement


26 rows selected.

As you can see another child cursor has been created. Why?

SQL> select xmltype(reason) from v$sql_shared_cursor where dbms_lob.getlength(reason) > 1 and sql_id = '34zmr3acgz06g';

XMLTYPE(REASON)
-----------------------------------------------------------------------------------------------------------------------------
<ChildNode>
  <ChildNumber>0</ChildNumber>
  <ID>49</ID>
  <reason>Auto Reoptimization Mismatch(1)</reason>
  <size>3x4</size>
  <kxscflg>32</kxscflg>
  <kxscfl4>4194560</kxscfl4>
  <dnum_kksfcxe>262144</dnum_kksfcxe>
</ChildNode>

Ah – the cursor was created because of a reoptimisation mismatch. Checking against v$sql you can see that the optimiser is now happy with the cardinality estimate (not anticipating further reoptimisation for this statement). Note that depending on the query’s complexity many more child cursors can be created as part of the reoptimisation. Also note that for child cursor 1 the A and E rows are perfect matches. Our work here is done. But wait- what about that column usage?

SQL> select dbms_stats.report_col_usage(user, 'CUSTOMERS') from dual;

DBMS_STATS.REPORT_COL_USAGE(USER,'CUSTOMERS')
--------------------------------------------------------------------------------
LEGEND:
.......

EQ         : Used in single table EQuality predicate
RANGE      : Used in single table RANGE predicate
LIKE       : Used in single table LIKE predicate
NULL       : Used in single table is (not) NULL predicate
EQ_JOIN    : Used in EQuality JOIN predicate
NONEQ_JOIN : Used in NON EQuality JOIN predicate
FILTER     : Used in single table FILTER predicate
JOIN       : Used in JOIN predicate
GROUP_BY   : Used in GROUP BY expression
...............................................................................

###############################################################################

COLUMN USAGE REPORT FOR MARTIN.CUSTOMERS
........................................

1. COUNTRY_ID                          : EQ
2. CUST_CITY                           : EQ
3. CUST_STATE_PROVINCE                 : EQ
###############################################################################

SQL> select * from dba_stat_extensions where owner = user;

no rows selected

Nothing here except some equality predicates! This is the big difference to part I of this article where the filter on the 3 columns was detected thanks to the call to DBMS_STATS.SEED_COL_USAGE.

It took me a while to connect the dots and understand what needed to be done next. In the meantime, hidden from view, and in the background, Oracle created a SQL Plan Directive for that table which I failed to notice for a while. SQL Plan Directives are not persisted immediately, the documentation states they are written to SYSAUX every 15 minutes. I must have thought about this for more than 15 minutes, as you will see shortly. If you are a bit more impatient then force the write of the SPD to disk using DBMS_SPD.FLUSH_SQL_PLAN_DIRECTIVE now.

To verify if there were any SPDs I used a query taken more or less literally from the documentation, and yes, there are:

SQL> SELECT TO_CHAR(d.DIRECTIVE_ID) dir_id, o.OBJECT_NAME,
  2         o.SUBOBJECT_NAME col_name, o.OBJECT_TYPE, d.TYPE, d.STATE, d.REASON
  3  FROM   DBA_SQL_PLAN_DIRECTIVES d, DBA_SQL_PLAN_DIR_OBJECTS o
  4  WHERE  d.DIRECTIVE_ID=o.DIRECTIVE_ID
  5  AND    o.OWNER = user
  6  ORDER BY 1,2,3,4,5;

DIR_ID                         OBJECT_NAME          COL_NAME             OBJECT TYPE             STATE    REASON
------------------------------ -------------------- -------------------- ------ ---------------- -------- ------------------------------------
15273172249382976180           CUSTOMERS            COUNTRY_ID           COLUMN DYNAMIC_SAMPLING USABLE   SINGLE TABLE CARDINALITY MISESTIMATE
15273172249382976180           CUSTOMERS            CUST_CITY            COLUMN DYNAMIC_SAMPLING USABLE   SINGLE TABLE CARDINALITY MISESTIMATE
15273172249382976180           CUSTOMERS            CUST_STATE_PROVINCE  COLUMN DYNAMIC_SAMPLING USABLE   SINGLE TABLE CARDINALITY MISESTIMATE
15273172249382976180           CUSTOMERS                                 TABLE  DYNAMIC_SAMPLING USABLE   SINGLE TABLE CARDINALITY MISESTIMATE

Once you can see the SPD in the dictionary, you can also see them in action when you run a statement with the same predicates but different SQL_ID, as in this example.

SQL> select /*+ gather_plan_statistics new_parse_please */ count(*) from customers where cust_city = 'Los Angeles' and cust_state_province = 'CA' and country_id = 52790;

  COUNT(*)
----------
       932

SQL> select * from table(dbms_xplan.display_cursor(format => 'allstats last'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  85qvryzgzj57q, child number 0
-------------------------------------
select /*+ gather_plan_statistics new_parse_please */ count(*) from
customers where cust_city = 'Los Angeles' and cust_state_province =
'CA' and country_id = 52790

Plan hash value: 296924608

------------------------------------------------------------------------------------------
| Id  | Operation          | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |           |      1 |        |      1 |00:00:00.01 |    1521 |
|   1 |  SORT AGGREGATE    |           |      1 |      1 |      1 |00:00:00.01 |    1521 |
|*  2 |   TABLE ACCESS FULL| CUSTOMERS |      1 |    829 |    932 |00:00:00.01 |    1521 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))

Note
-----
   - dynamic statistics used: dynamic sampling (level=2)
   - 1 Sql Plan Directive used for this statement


27 rows selected.

The SQL Plan directive stays even if you flush the cursor with SQL ID 34zmr3acgz06g from the cursor cache or supply a different set of predicates. I used Kerry Osborne’s flush_sql.sql script for this.

SQL> @flush_sql 
Enter value for sql_id: 34zmr3acgz06g
old  14:   where sql_id like '&sql_id';
new  14:   where sql_id like '34zmr3acgz06g';

PL/SQL procedure successfully completed.

SQL> select sql_id, child_number, is_obsolete, is_reoptimizable, is_resolved_adaptive_plan from v$sql where sql_id = '34zmr3acgz06g';

no rows selected

SQL> select /*+ gather_plan_statistics */ count(*) from customers where cust_city = 'Los Angeles' and cust_state_province = 'CA' and country_id = 52790;

  COUNT(*)
----------
       932

SQL> select * from table(dbms_xplan.display_cursor(format=>'allstats last'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  34zmr3acgz06g, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from customers where
cust_city = 'Los Angeles' and cust_state_province = 'CA' and country_id
= 52790

Plan hash value: 296924608

------------------------------------------------------------------------------------------
| Id  | Operation          | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |           |      1 |        |      1 |00:00:00.01 |    1521 |
|   1 |  SORT AGGREGATE    |           |      1 |      1 |      1 |00:00:00.01 |    1521 |
|*  2 |   TABLE ACCESS FULL| CUSTOMERS |      1 |    953 |    932 |00:00:00.01 |    1521 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))

Note
-----
   - dynamic statistics used: dynamic sampling (level=2)
   - 1 Sql Plan Directive used for this statement


27 rows selected.


SQL> select /*+ gather_plan_statistics */ count(*) from customers where cust_city = 'Palmdale' and cust_state_province = 'FL' and country_id = 52790;

  COUNT(*)
----------
       250

SQL> select * from table(dbms_xplan.display_cursor(format=>'allstats last'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  dbkfpchpfwap3, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from customers where
cust_city = 'Palmdale' and cust_state_province = 'FL' and country_id =
52790

Plan hash value: 296924608

------------------------------------------------------------------------------------------
| Id  | Operation          | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |           |      1 |        |      1 |00:00:00.01 |    1521 |
|   1 |  SORT AGGREGATE    |           |      1 |      1 |      1 |00:00:00.01 |    1521 |
|*  2 |   TABLE ACCESS FULL| CUSTOMERS |      1 |    287 |    250 |00:00:00.02 |    1521 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(("CUST_CITY"='Palmdale' AND "CUST_STATE_PROVINCE"='FL' AND
              "COUNTRY_ID"=52790))

Note
-----
   - dynamic statistics used: dynamic sampling (level=2)
   - 1 Sql Plan Directive used for this statement


27 rows selected.

And NOW you get the update to REPORT_COL_USAGE:

SQL> select dbms_stats.report_col_usage(user, 'CUSTOMERS') from dual;

DBMS_STATS.REPORT_COL_USAGE(USER,'CUSTOMERS')
--------------------------------------------------------------------------------
LEGEND:
.......

EQ         : Used in single table EQuality predicate
RANGE      : Used in single table RANGE predicate
LIKE       : Used in single table LIKE predicate
NULL       : Used in single table is (not) NULL predicate
EQ_JOIN    : Used in EQuality JOIN predicate
NONEQ_JOIN : Used in NON EQuality JOIN predicate
FILTER     : Used in single table FILTER predicate
JOIN       : Used in JOIN predicate
GROUP_BY   : Used in GROUP BY expression
...............................................................................

###############################################################################

COLUMN USAGE REPORT FOR MARTIN.CUSTOMERS
........................................

1. COUNTRY_ID                          : EQ
2. CUST_CITY                           : EQ
3. CUST_STATE_PROVINCE                 : EQ
4. (CUST_CITY, CUST_STATE_PROVINCE,
    COUNTRY_ID)                        : FILTER
###############################################################################

From here on it’s the same as in part 1 of this article. You gather stats, either manually like me or automatically like Oracle would, and the end result are extended statistics on the “filter” shown in line 4.

SQL> exec dbms_stats.gather_table_stats(user, 'CUSTOMERS')

PL/SQL procedure successfully completed.

SQL> select table_name, extension_name, extension from dba_stat_extensions where owner = user;

TABLE_NAME                     EXTENSION_NAME                           EXTENSION
------------------------------ ---------------------------------------- --------------------------------------------------------------------------------
CUSTOMERS                      SYS_STSMZ$C3AIHLPBROI#SKA58H_N           ("CUST_CITY","CUST_STATE_PROVINCE","COUNTRY_ID")

Voila! Extended statistics.

There are many more interesting implications to this whole concept, which is something I’ll write about in another post. It’s incredibly interesting, I can’t believe I’m writing optimiser posts …

PS: thanks to @Mautro for casting an eye over this article!

Little things worth knowing: automatic generation of extended statistics in 12c

When you are migrating to Oracle 12c I hope you might this post useful. I came across this feature when researching what’s new with Oracle 12c (and yes I still find lots of new ones I haven’t noticed before). This one is a bit hidden away in section 2.2.4.3 Automatic Column Group Detection of the 12c New Features Guide. And it’s a lot more complex than I first thought! In this first post I’ll try and show the generation of extended statistics in 12c. I am planning on another post to explain how the rest of the adaptive optimisations that are new with 12c fit into the picture.

What is the motivation?

Previously, in Oracle versions up to 12c you needed to be on the lookout for candidates for correlated columns. Extended statistics on groups of columns allow the optimiser to come up with better cardinality estimates if columns in a table are correlated. Instead of me trying to explain the concept in depth I’d like to link to a post written by Maria Colgan. I strongly recommend you have a look at this post if you haven’t used extended statistics a lot.

When putting my post together I referred to the same SH.CUSTOMERS table as Maria. The queries I am using are based on another excellent post by Maria Colgan that builds on the foundations of the one I just referenced. In fact I really needed a data set that had correlated columns but I couldn’t come up with an example that was easy-to-follow until I found that blog entry. I suggest you have a look at this post first as it explains a nifty tool for helping you finding candidates for extended statistics in 11.2. Oracle 12c takes this concept a step further as you will see.

My test case

My test environment is 12.1.0.2.3 on Exadata (but that shouldn’t matter), and this is how it goes. First I create a table in my schema which is an exact replica of the table in the SH schema.

SQL> create table martin.customers as select * from sh.customers;

Table created.

The next step is to tell Oracle to monitor column usage. I have to accelerate this a bit, Oracle does this over the cause of the day anyway.

SQL> exec dbms_stats.seed_col_usage(null,null,300)

PL/SQL procedure successfully completed.

By calling seed_col_usage() without a SQLSET and OWNER I can report column usage. The PL/SQL API documentation reads:

This procedure also records group of columns. Extensions for the recorded group of columns can be created using the CREATE_EXTENDED_STATS Function procedure. If sqlset_name and owner_name are NULL, it records the column (group) usage information for the statements executed in the system in next time_limit seconds.

That sounds like what is needed. To start with a level playing field I gather statistics again using dbms_stats.gather_table_stats(user, ‘customers’).

Let there be queries

The next step is to run a few queries. Cardinality estimates are not correct-the optimiser does not “know” that L.A. can only be in California in this example. Pay attention to the number of rows returned and the cardinality estimates:

SQL> select count(*) from customers
  2  where cust_city = 'Los Angeles'
  3  and cust_state_province = 'CA'
  4  and country_id = 52790;

  COUNT(*)
----------
       932

Elapsed: 00:00:00.03
SQL> select * from table(dbms_xplan.display_cursor);

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
SQL_ID  ap71092cqnj1y, child number 0
-------------------------------------
select count(*) from customers where cust_city = 'Los Angeles' and
cust_state_province = 'CA' and country_id = 52790

Plan hash value: 296924608

----------------------------------------------------------------------------------------
| Id  | Operation                  | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |           |       |       |   423 (100)|          |
|   1 |  SORT AGGREGATE            |           |     1 |    26 |            |          |
|*  2 |   TABLE ACCESS STORAGE FULL| CUSTOMERS |     1 |    26 |   423   (1)| 00:00:01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - storage(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))
       filter(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))

Note
-----
   - automatic DOP: Computed Degree of Parallelism is 1 because of parallel threshold

27 rows selected.

Following advice I have been given by people who know a lot more about SQL tuning than I will ever comprehend, I gather execution statistics and then display actual and expected rows:

SQL> select /*+ gather_plan_statistics */ count(*) from customers
  2  where cust_city = 'Los Angeles'
  3  and cust_state_province = 'CA'
  4  and country_id = 52790;

  COUNT(*)
----------
       932

SQL> select * from table(dbms_xplan.display_cursor(format=>'allstats last'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
SQL_ID  0qmjk7qm3zwkw, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from customers  where
cust_city = 'Los Angeles'  and cust_state_province = 'CA'  and
country_id = 52790

Plan hash value: 296924608

--------------------------------------------------------------------------------------------------
| Id  | Operation                  | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |           |      1 |        |      1 |00:00:00.01 |    1521 |
|   1 |  SORT AGGREGATE            |           |      1 |      1 |      1 |00:00:00.01 |    1521 |
|*  2 |   TABLE ACCESS STORAGE FULL| CUSTOMERS |      1 |      1 |    932 |00:00:00.01 |    1521 |
--------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - storage(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))
       filter(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))

Note
-----
   - automatic DOP: Computed Degree of Parallelism is 1 because of parallel threshold

The number of actual rows in plan line 2 is quite different from what the optimiser expected it to be.

I also executed the next example from Maria’s blog post:

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------

SQL_ID  5h284vjm2xtp9, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ country_id, cust_state_province,
count(*) from customers group by country_id, cust_state_province

Plan hash value: 1577413243

-----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                  | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |           |      1 |        |    145 |00:00:00.02 |    1521 |       |       |          |
|   1 |  HASH GROUP BY             |           |      1 |   1949 |    145 |00:00:00.02 |    1521 |  1015K|  1015K| 1371K (0)|
|   2 |   TABLE ACCESS STORAGE FULL| CUSTOMERS |      1 |  55500 |  55500 |00:00:00.02 |    1521 |  1025K|  1025K|          |
-----------------------------------------------------------------------------------------------------------------------------

Note
-----
   - automatic DOP: Computed Degree of Parallelism is 1 because of parallel threshold

Again cardinality estimates differ in plan line 1: instead of 1949 rows the optimiser expects to be returned there are only 145. This is a simple example, but quite often incorrect cardinality estimates lead to sub-optimal plan generation (although 12c has another new feature that tries to mitigate the effects of these incorrect cardinality estimates as well)

Column Groups

On the other hand the column usage monitor picked up information based on the “workload”. You can see this in sys.col_group_usage$

SQL> select u.*, o.object_name, object_type
  2  from sys.col_group_usage$ u, dba_objects o
  3  where u.obj# = o.data_object_id
  4  and owner = 'MARTIN';

      OBJ# COLS                           TIMESTAMP      FLAGS OBJECT_NAME                    OBJECT_TYPE
---------- ------------------------------ --------- ---------- ------------------------------ -----------------------
    111118 11,13                          26-JUN-15         36 CUSTOMERS                      TABLE
    111118 9,11,13                        26-JUN-15         33 CUSTOMERS                      TABLE

This is of course not the way to view this information-there’s an API for that.

SQL> select dbms_stats.report_col_usage(user, 'CUSTOMERS') from dual;

DBMS_STATS.REPORT_COL_USAGE(USER,'CUSTOMERS')
----------------------------------------------------------------------------------------------
LEGEND:
.......

EQ         : Used in single table EQuality predicate
RANGE      : Used in single table RANGE predicate
LIKE       : Used in single table LIKE predicate
NULL       : Used in single table is (not) NULL predicate
EQ_JOIN    : Used in EQuality JOIN predicate
NONEQ_JOIN : Used in NON EQuality JOIN predicate
FILTER     : Used in single table FILTER predicate
JOIN       : Used in JOIN predicate
GROUP_BY   : Used in GROUP BY expression
...............................................................................

###############################################################################

COLUMN USAGE REPORT FOR MARTIN.CUSTOMERS
........................................

1. COUNTRY_ID                          : EQ
2. CUST_CITY                           : EQ
3. CUST_STATE_PROVINCE                 : EQ
4. (CUST_CITY, CUST_STATE_PROVINCE,
    COUNTRY_ID)                        : FILTER
5. (CUST_STATE_PROVINCE, COUNTRY_ID)   : GROUP_BY
###############################################################################

So there is a potential candidates for extended stats in line 5. So far, nothing new. In version before 12c you now had to create the column groups manually. Again, please refer to Maria’s post for an example.

The difference in 12c

In 12c you don’t need to create these column groups manually. Consider this sequence of events:

SQL> select * from dba_stat_extensions where owner = 'MARTIN';

no rows selected

Elapsed: 00:00:00.28

SQL> exec dbms_stats.gather_table_stats(user,'CUSTOMERS')

PL/SQL procedure successfully completed.

SQL> select * from user_stat_extensions

TABLE_NAME                     EXTENSION_NAME                 EXTENSION                                          CREATO DRO
------------------------------ ------------------------------ -------------------------------------------------- ------ ---
CUSTOMERS                      SYS_STU#S#WF25Z#QAHIHE#MOFFMM_ ("CUST_STATE_PROVINCE","COUNTRY_ID")               USER   YES
CUSTOMERS                      SYS_STUMZ$C3AIHLPBROI#SKA58H_N ("CUST_CITY","CUST_STATE_PROVINCE","COUNTRY_ID")   USER   YES

2 rows selected.

SQL> SELECT column_name,
  2    num_distinct,
  3    num_buckets,
  4    histogram
  5  FROM dba_tab_col_statistics
  6  WHERE table_name = 'CUSTOMERS'
  7  AND owner        = 'MARTIN'
  8  AND column_name LIKE 'SYS%';

COLUMN_NAME                    NUM_DISTINCT NUM_BUCKETS HISTOGRAM
------------------------------ ------------ ----------- ---------------
SYS_STUMZ$C3AIHLPBROI#SKA58H_N          620         254 HYBRID
SYS_STU#S#WF25Z#QAHIHE#MOFFMM_          145           1 NONE

2 rows selected.

So in the above output you can see that there are no extended stats on the CUSTOMERS table before gathering stats. There is nothing special about the stats gathering command, the preferences are the defaults (reformatted here for readability)

SQL> l
  1  declare
  2    type prefs_t is table of varchar2(150);
  3    prefs prefs_t := prefs_t(
  4      'AUTOSTATS_TARGET','CASCADE','CONCURRENT','DEGREE','ESTIMATE_PERCENT',
  5      'METHOD_OPT','NO_INVALIDATE','GRANULARITY','PUBLISH','INCREMENTAL',
  6      'INCREMENTAL_STALENESS','INCREMENTAL_LEVEL','STALE_PERCENT',
  7      'GLOBAL_TEMP_TABLE_STATS','TABLE_CACHED_BLOCKS','OPTIONS');
  8    prefs_value varchar2(100);
  9  begin
 10    for p in prefs.first .. prefs.last loop
 11      select dbms_stats.get_prefs(prefs(p), user,'CUSTOMERS') into prefs_value from dual;
 12      dbms_output.put_line(prefs(p) || ': ' || prefs_value);
 13    end loop;
 14* end;
SQL> /
AUTOSTATS_TARGET:        AUTO
CASCADE:                 DBMS_STATS.AUTO_CASCADE
CONCURRENT:              MANUAL
DEGREE:                  NULL
ESTIMATE_PERCENT:        DBMS_STATS.AUTO_SAMPLE_SIZE
METHOD_OPT:              FOR ALL COLUMNS SIZE AUTO
NO_INVALIDATE:           DBMS_STATS.AUTO_INVALIDATE
GRANULARITY:             AUTO
PUBLISH:                 TRUE
INCREMENTAL:             FALSE
INCREMENTAL_STALENESS:
INCREMENTAL_LEVEL:       PARTITION
STALE_PERCENT:           10
GLOBAL_TEMP_TABLE_STATS: SESSION
TABLE_CACHED_BLOCKS:     1
OPTIONS:                 GATHER

PL/SQL procedure successfully completed.

Did you see the extended stats have histograms? There is even one of the new fancy “hybrid” ones. The effect is noticeable:

SQL> select /*+ gather_plan_statistics */ count(*) from customers
  2   where cust_city = 'Los Angeles'
  3   and cust_state_province = 'CA'
  4   and country_id = 52790;

SQL> select * from table(dbms_xplan.display_cursor(format => 'allstats last'));

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------------------------------
SQL_ID  0qmjk7qm3zwkw, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from customers  where
cust_city = 'Los Angeles'  and cust_state_province = 'CA'  and
country_id = 52790

Plan hash value: 296924608

--------------------------------------------------------------------------------------------------
| Id  | Operation                  | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |           |      1 |        |      1 |00:00:00.01 |    1521 |
|   1 |  SORT AGGREGATE            |           |      1 |      1 |      1 |00:00:00.01 |    1521 |
|*  2 |   TABLE ACCESS STORAGE FULL| CUSTOMERS |      1 |    969 |    932 |00:00:00.01 |    1521 |
--------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - storage(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))
       filter(("CUST_CITY"='Los Angeles' AND "CUST_STATE_PROVINCE"='CA' AND
              "COUNTRY_ID"=52790))

Note
-----
   - dynamic statistics used: dynamic sampling (level=2)
   - 1 Sql Plan Directive used for this statement

The cardinality estimate is a lot closer now. What surprised me was the SQL Plan Directive referenced. But this is material for another blog post.

If you use swingbench take note of sbutil

This is going to be a very short post for a change. I have used Swingbench extensively and really love the tool. Many thanks to Dominic Giles!

Recently he announced a new tool on his blog that you can use to inflate your data volume. So instead of using the “-scale” argument when executing oewizard you can just keep the defaults and later on create as much data as you like. Here is an example, the reason for this post.

Setting the Scene

If you have not yet downloaded the latest Swingbench version and JDK 8 do this first. You can get Swingbench from the tool’s landing page and the Java software from java.sun.com. I used Swingbench 2.5.791 (stable). With both deployed, I created the Order Entry schema in lights-out mode:

[oracle@lab bin]$ ./oewizard -dbap secret -u soe -p soe -cl -cs //lab/martin -ts soe_tbs -create -dba system
SwingBench Wizard
Author  :        Dominic Giles
Version :        2.5.0.971

Running in Lights Out Mode using config file : oewizard.xml
The following statement failed : GRANT EXECUTE ON dbms_lock TO soe : Due to : ORA-01031: insufficient privileges

============================================
|           Datagenerator Run Stats        |
============================================
Connection Time                        0:00:00.006
Data Generation Time                   0:01:06.110
DDL Creation Time                      0:00:30.346
Total Run Time                         0:01:36.465
Rows Inserted per sec                      183,121
Data Generated (MB) per sec                   14.9
Actual Rows Generated                   13,002,138

Post Creation Validation Report
===============================
The schema appears to have been created successfully.

Valid Objects
=============
Valid Tables : 'ORDERS','ORDER_ITEMS','CUSTOMERS','WAREHOUSES','ORDERENTRY_METADATA','INVENTORIES',
'PRODUCT_INFORMATION','PRODUCT_DESCRIPTIONS','ADDRESSES','CARD_DETAILS'
Valid Indexes : 'PRD_DESC_PK','PROD_NAME_IX','PRODUCT_INFORMATION_PK','PROD_SUPPLIER_IX','PROD_CATEGORY_IX',
'INVENTORY_PK','INV_PRODUCT_IX','INV_WAREHOUSE_IX','ORDER_PK','ORD_SALES_REP_IX',
'ORD_CUSTOMER_IX','ORD_ORDER_DATE_IX','ORD_WAREHOUSE_IX','ORDER_ITEMS_PK','ITEM_ORDER_IX',
'ITEM_PRODUCT_IX','WAREHOUSES_PK','WHS_LOCATION_IX','CUSTOMERS_PK','CUST_EMAIL_IX',
'CUST_ACCOUNT_MANAGER_IX','CUST_FUNC_LOWER_NAME_IX','ADDRESS_PK','ADDRESS_CUST_IX',
'CARD_DETAILS_PK','CARDDETAILS_CUST_IX'
Valid Views : 'PRODUCTS','PRODUCT_PRICES'
Valid Sequences : 'CUSTOMER_SEQ','ORDERS_SEQ','ADDRESS_SEQ','LOGON_SEQ','CARD_DETAILS_SEQ'
Valid Code : 'ORDERENTRY'
Schema Created

More Data!

The next step is to invoke sbutil:

[oracle@lab bin]$ ./sbutil -u soe -p soe  -cs //lab/martin -soe parallel 12 -dup 4
Getting table Info
Got table information. Completed in : 0:00:01.558
Dropping Indexes
Dropped Indexes. Completed in : 0:00:03.252
Creating copies of tables
Created copies of tables. Completed in : 0:00:00.042
Begining data duplication
Completed Iteration 4. Completed in : 0:00:07.942
Creating  Constraints
Created  Constraints. Completed in : 0:00:28.737
Creating  Indexes
Created  Indexes. Completed in : 0:00:54.541
Updating Metadata and Recompiling Code
Updated Metadata. Completed in : 0:00:00.754
Updating Sequences
Updated Sequences. Completed in : 0:00:00.792
Determining New Row Counts
Got New Row Counts. Completed in : 0:00:03.132
Completed Data Duplication in 0 hour(s) 2 minute(s) 8 second(s) 454 millisecond(s)
----------------------------------------------------------------------------------------------------------
|Table Name          |  Original Row Count|       Original Size|       New Row Count|            New Size|
----------------------------------------------------------------------------------------------------------
|ORDER_ITEMS         |           4,288,582|              280 MB|          17,154,328|              1.1 GB|
|CUSTOMERS           |           1,000,000|              136 MB|           4,000,000|            552.4 MB|
|CARD_DETAILS        |           1,500,000|               80 MB|           6,000,000|            337.8 MB|
|ORDERS              |           1,429,790|              160 MB|           5,719,160|              664 MB|
|ADDRESSES           |           1,500,000|              184 MB|           6,000,000|            571.8 MB|
----------------------------------------------------------------------------------------------------------
|Total               |                    |              840 MB|                    |              3.2 GB|
----------------------------------------------------------------------------------------------------------

How Cool is That?

Really, it is. And look at the timings. This didn’t take too long, even on my poor old AMD 6200 series lab server.