Wednesday, August 1, 2012

Exadata Smart Scan for dbms_stats with auto_sample_size




In this Blog we will see how the DBMS_STATS.GATHER_TABLE_STATS will behave in exadata. Whether this full take full advantage of smart scan capabilities? We will see this in this blog.

rdbms&crs version - 11.2.0.3.0

Before taking and starting about investigation about the Smart Scan, we should bear in mind that following
are the requirements for smart scan to kick in

1) Database must choose Direct path read of its operation
2) Table should have parallel degree defined(if its a small table and satisfying the _small_table_threashold value)
3) If table is large (as defined by _small_table_threashold) then serial direct path read is performed(no parallel degree in this case)
4) Explain plan should have 'STORAGE' word in rowsource operation. For example in non-exadata operation is something like 'Table Access Full' but in Exadata its should be as 'Table Access Storage Full'
5) In Predicate section of Explain Plan, it should have storage clause

Note- Even if above conditions are satisfied, its not guranted smart scan would take place. We will see why this can happen in some cases.

However optimizer is not completely aware about the existence of exadata and direct path read decision is made after optimizer does its job. So there are some heuristics involved when to choose Direct path read operation somethink like segment size,numbers of blocks already in buffer cahceSGA size etc etc.

There is no direct way to check if Smart Scan has happened or not for a query and also how effective the smart scan is, is not known easily. However there are specific performance counters and some wait events for which we can check if a) Smart Scan happened at all or b) how much effective was the SMart scan. So we will use these tow techniques to check smart scan optimization.


I logged in to session and executed below query:
SQL> select s.name,m.value from v$sysstat s,v$mystat m where s.STATISTIC#=m.STATISTIC# and name like '%cell%';

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell physical IO interconnect bytes                                       0
cell physical IO bytes saved during optimized file creation               0
cell physical IO bytes saved during optimized RMAN file restore           0
cell physical IO bytes eligible for predicate offload                     0
cell physical IO bytes saved by storage index                             0
cell physical IO bytes sent directly to DB node to balance CPU            0
cell smart IO session cache lookups                                       0
cell smart IO session cache hits                                          0
cell smart IO session cache soft misses                                   0
cell smart IO session cache hard misses                                   0
cell smart IO session cache hwm                                           0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell num smart IO sessions in rdbms block IO due to user                  0
cell num smart IO sessions in rdbms block IO due to no cell mem           0
cell num smart IO sessions in rdbms block IO due to big payload           0
cell num smart IO sessions using passthru mode due to user                0
cell num smart IO sessions using passthru mode due to cellsrv             0
cell num smart IO sessions using passthru mode due to timezone            0
cell num smart file creation sessions using rdbms block IO mode           0
cell physical IO interconnect bytes returned by smart scan                0
cell num fast response sessions                                           0
cell num fast response sessions continuing to smart scan                  0
cell statistics spare1                                                    0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell statistics spare2                                                    0
cell statistics spare3                                                    0
cell statistics spare4                                                    0
cell statistics spare5                                                    0
cell statistics spare6                                                    0
cell scans                                                                0
cell blocks processed by cache layer                                      0
cell blocks processed by txn layer                                        0
cell blocks processed by data layer                                       0
cell blocks processed by index layer                                      0
cell commit cache queries                                                 0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell transactions found in commit cache                                   0
cell blocks helped by commit cache                                        0
cell blocks helped by minscn optimization                                 0
chained rows skipped by cell                                              0
chained rows processed by cell                                            0
chained rows rejected by cell                                             0
cell simulated physical IO bytes eligible for predicate offload           0
cell simulated physical IO bytes returned by predicate offload            0
cell CUs sent uncompressed                                                0
cell CUs sent compressed                                                  0
cell CUs sent head piece                                                  0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell CUs processed for uncompressed                                       0
cell CUs processed for compressed                                         0
cell IO uncompressed bytes                                                0
cell index scans                                                          0
cell flash cache read hits                                                0

49 rows selected.

SO there are 49 critical performance counters which can tell us the effiectivnes of smart scan optimization.
As it can be seen all these have zero values since this was fresh login to database(Note we used v%sysstat
and v$mystat, as we are only concern about our session)

SQL> select s.name,m.value from v$sysstat s,v$mystat m where s.STATISTIC#=m.STATISTIC# and name like '%physical%';

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
physical read total IO requests                                           0
physical read total multi block requests                                  0
physical read requests optimized                                          0
physical read total bytes optimized                                       0
physical read total bytes                                                 0
physical write total IO requests                                          0
physical write total multi block requests                                 0
physical write total bytes                                                0
cell physical IO interconnect bytes                                       0
physical reads                                                            0
physical reads cache                                                      0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
physical read flash cache hits                                            0
physical reads direct                                                     0
physical read IO requests                                                 0
physical read bytes                                                       0
physical writes                                                           0
physical writes direct                                                    0
physical writes from cache                                                0
physical write IO requests                                                0
physical reads direct temporary tablespace                                0
physical writes direct temporary tablespace                               0
physical write bytes                                                      0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
physical writes non checkpoint                                            0
physical reads cache prefetch                                             0
physical reads prefetch warmup                                            0
physical reads retry corrupt                                              0
physical reads direct (lob)                                               0
physical writes direct (lob)                                              0
physical reads for flashback new                                          0
cell physical IO bytes saved during optimized file creation               0
cell physical IO bytes saved during optimized RMAN file restore           0
cell physical IO bytes eligible for predicate offload                     0
cell physical IO bytes saved by storage index                             0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell physical IO bytes sent directly to DB node to balance CPU            0
cell physical IO interconnect bytes returned by smart scan                0
cell simulated physical IO bytes eligible for predicate offload           0
cell simulated physical IO bytes returned by predicate offload            0

37 rows selected.


We wanted to generate the Tracefile for this session

16:06:42 SQL> alter session set tracefile_identifier='tracing_gatherstats';

Session altered.

Elapsed: 00:00:00.00
16:06:57 SQL> alter session Set MAX_DUMP_FILE_SIZE='unlimited';

Session altered.

Elapsed: 00:00:00.00
16:07:04 SQL>
16:07:05 SQL> Alter session set events '10046 trace name context forever, level 12';

Session altered.

Elapsed: 00:00:00.00


From other session we first checked the DEGREE parameter for following table:

SQL> select degree from dba_tables where table_name='ACCT_STATEMENT';

DEGREE
----------------------------------------
         1

-----

Now we run the actual command for which we want to see the Smart Scan:

16:07:20 SQL> exec dbms_stats.gather_table_stats('BOB_PROD_ODS','ACCT_STATEMENT', estimate_percent => dbms_stats.auto_sample_size, method_opt => 'for all columns size 1');

PL/SQL procedure successfully completed.


Elapsed: 00:03:28.23

Note- We have not used the parallel attribute to cause this job to run in parallel and we have also used
AUTO_SAMPLE_SIZE. This table is around 10GB in size.

Notice the time is took for further references

16:11:22 SQL> select s.name,m.value from v$sysstat s,v$mystat m where s.STATISTIC#=m.STATISTIC# and name like '%cell%';

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell physical IO interconnect bytes                              6611836928
cell physical IO bytes saved during optimized file creation               0
cell physical IO bytes saved during optimized RMAN file restore           0
cell physical IO bytes eligible for predicate offload                     0
cell physical IO bytes saved by storage index                             0
cell physical IO bytes sent directly to DB node to balance CPU            0
cell smart IO session cache lookups                                       0
cell smart IO session cache hits                                          0
cell smart IO session cache soft misses                                   0
cell smart IO session cache hard misses                                   0
cell smart IO session cache hwm                                           0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell num smart IO sessions in rdbms block IO due to user                  0
cell num smart IO sessions in rdbms block IO due to no cell mem           0
cell num smart IO sessions in rdbms block IO due to big payload           0
cell num smart IO sessions using passthru mode due to user                0
cell num smart IO sessions using passthru mode due to cellsrv             0
cell num smart IO sessions using passthru mode due to timezone            0
cell num smart file creation sessions using rdbms block IO mode           0
cell physical IO interconnect bytes returned by smart scan                0
cell num fast response sessions                                           0
cell num fast response sessions continuing to smart scan                  0
cell statistics spare1                                                    0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell statistics spare2                                                    0
cell statistics spare3                                                    0
cell statistics spare4                                                    0
cell statistics spare5                                                    0
cell statistics spare6                                                    0
cell scans                                                                0
cell blocks processed by cache layer                                      0
cell blocks processed by txn layer                                        0
cell blocks processed by data layer                                       0
cell blocks processed by index layer                                      0
cell commit cache queries                                                 0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell transactions found in commit cache                                   0
cell blocks helped by commit cache                                        0
cell blocks helped by minscn optimization                                 0
chained rows skipped by cell                                              0
chained rows processed by cell                                            0
chained rows rejected by cell                                             0
cell simulated physical IO bytes eligible for predicate offload           0
cell simulated physical IO bytes returned by predicate offload            0
cell CUs sent uncompressed                                                0
cell CUs sent compressed                                                  0
cell CUs sent head piece                                                  0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell CUs processed for uncompressed                                       0
cell CUs processed for compressed                                         0
cell IO uncompressed bytes                                                0
cell index scans                                                          0
cell flash cache read hits                                           803266

49 rows selected.

Some observation made from above:
cell physical IO interconnect bytes is high i.e around 6GB, this means the amount of data flown through
Interconnects which included everything.(including buffer blocks)

cell physical IO bytes eligible for predicate offload is Zero (No smart scan)

cell physical IO bytes saved by storage index is Zero (No Storage index optimization here)

cell physical IO interconnect bytes returned by smart scan is Zero (No Smart scan Optimization)

cell flash cache read hits has non-zero value: (Flash cache helped us a bit)

Conclusion for above result is dbms_stats job didn't get any benefit outof smartscan.
Its time to get the same conclusion from Trace file:


Let check the Tkprof of trace:

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.09       0.28          0         51        232           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.09       0.29          0         51        232           1

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       3        0.00          0.00
  SQL*Net message from client                     2       33.99         45.55
  SQL*Net break/reset to client                   2        0.00          0.00
  Disk file operations I/O                      940        0.00          0.00
  DFS lock handle                                32        0.10          0.19
  row cache lock                                 40        0.00          0.00
  log file sync                                   1        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      361      0.02       0.03          0          0          0           0
Execute    697      0.11       0.13         10       2233        806         294
Fetch      360    186.02     207.79     807099    1306746          4         433
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1418    186.17     207.95     807109    1308979        810         727

Misses in library cache during parse: 4

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  asynch descriptor resize                        1        0.00          0.00
  enq: TM - contention                            3        0.00          0.00
  gc current block 3-way                         48        0.00          0.00
  Disk file operations I/O                        8        0.00          0.00
  gc current block 2-way                      21477        0.00          1.93
  gc current grant 2-way                          9        0.00          0.00
  cell single block physical read              2103        0.01          1.19
  gc cr block 2-way                              10        0.00          0.00
  gc current grant busy                           1        0.00          0.00
  gc cr multi block request                   17039        0.01          5.89
  gc current block congested                     74        0.00          0.00
  cell multiblock physical read                1223        0.03          1.06
  cell list of blocks physical read            9047        0.05         28.80
  latch: gcs resource hash                        2        0.00          0.00
  latch: gc element                              12        0.00          0.00
  gc cr grant 2-way                              25        0.00          0.00
  gc cr block busy                              115        0.00          0.06
  latch free                                      1        0.00          0.00

    3  user  SQL statements in session.
  233  internal SQL statements in session.
  236  SQL statements in session.
********************************************************************************
From above output also its confirmed that no smart scan happened here, if it were then we could have seen
'Cell smart scan' wait event.
Also notice high waits for 'cell single block physical read' and 'cell list of blocks physical read'
which clearly shows that operation was mostly depend upon the single path access plan.


Let put table in degree of 10 and see the performance(by doing this we are satisfying the requirements for smart
scan)

SQL> alter table bob_prod_ods.ACCT_STATEMENT parallel 10;

Table altered.


SQL*Plus: Release 11.2.0.3.0 Production on Wed Jul 11 16:17:52 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options

SQL> select s.name,m.value from v$sysstat s,v$mystat m where s.STATISTIC#=m.STATISTIC# and name like '%cell%';

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell physical IO interconnect bytes                                       0
cell physical IO bytes saved during optimized file creation               0
cell physical IO bytes saved during optimized RMAN file restore           0
cell physical IO bytes eligible for predicate offload                     0
cell physical IO bytes saved by storage index                             0
cell physical IO bytes sent directly to DB node to balance CPU            0
cell smart IO session cache lookups                                       0
cell smart IO session cache hits                                          0
cell smart IO session cache soft misses                                   0
cell smart IO session cache hard misses                                   0
cell smart IO session cache hwm                                           0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell num smart IO sessions in rdbms block IO due to user                  0
cell num smart IO sessions in rdbms block IO due to no cell mem           0
cell num smart IO sessions in rdbms block IO due to big payload           0
cell num smart IO sessions using passthru mode due to user                0
cell num smart IO sessions using passthru mode due to cellsrv             0
cell num smart IO sessions using passthru mode due to timezone            0
cell num smart file creation sessions using rdbms block IO mode           0
cell physical IO interconnect bytes returned by smart scan                0
cell num fast response sessions                                           0
cell num fast response sessions continuing to smart scan                  0
cell statistics spare1                                                    0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell statistics spare2                                                    0
cell statistics spare3                                                    0
cell statistics spare4                                                    0
cell statistics spare5                                                    0
cell statistics spare6                                                    0
cell scans                                                                0
cell blocks processed by cache layer                                      0
cell blocks processed by txn layer                                        0
cell blocks processed by data layer                                       0
cell blocks processed by index layer                                      0
cell commit cache queries                                                 0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell transactions found in commit cache                                   0
cell blocks helped by commit cache                                        0
cell blocks helped by minscn optimization                                 0
chained rows skipped by cell                                              0
chained rows processed by cell                                            0
chained rows rejected by cell                                             0
cell simulated physical IO bytes eligible for predicate offload           0
cell simulated physical IO bytes returned by predicate offload            0
cell CUs sent uncompressed                                                0
cell CUs sent compressed                                                  0
cell CUs sent head piece                                                  0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell CUs processed for uncompressed                                       0
cell CUs processed for compressed                                         0
cell IO uncompressed bytes                                                0
cell index scans                                                          0
cell flash cache read hits                                                0

49 rows selected.

Again notice the zero values for critical performance counters:

Setting the trace:
SQL> set time on timing on;
16:18:15 SQL> alter session set tracefile_identifier='tracing_gatherstats_parallel';

Session altered.

Elapsed: 00:00:00.00
16:18:23 SQL> alter session Set MAX_DUMP_FILE_SIZE='unlimited';

Session altered.

Elapsed: 00:00:00.00
16:18:27 SQL> Alter session set events '10046 trace name context forever, level 12';

Session altered.

Elapsed: 00:00:00.00

16:19:00 SQL> exec dbms_stats.gather_table_stats('BOB_PROD_ODS','ACCT_STATEMENT', estimate_percent => dbms_stats.auto_sample_size, method_opt => 'for all columns size 1');

PL/SQL procedure successfully completed.

Elapsed: 00:00:43.31

-wow, did you notice the time difference?
Also note the dbms_stats.auto_sample_size in the job

16:19:57 SQL> select s.name,m.value from v$sysstat s,v$mystat m where s.STATISTIC#=m.STATISTIC# and name like '%cell%';

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell physical IO interconnect bytes                              5514297160
cell physical IO bytes saved during optimized file creation               0
cell physical IO bytes saved during optimized RMAN file restore           0
cell physical IO bytes eligible for predicate offload            1.0614E+10
cell physical IO bytes saved by storage index                             0
cell physical IO bytes sent directly to DB node to balance CPU            0
cell smart IO session cache lookups                                     146
cell smart IO session cache hits                                        146
cell smart IO session cache soft misses                                  10
cell smart IO session cache hard misses                                   0
cell smart IO session cache hwm                                           0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell num smart IO sessions in rdbms block IO due to user                  0
cell num smart IO sessions in rdbms block IO due to no cell mem           0
cell num smart IO sessions in rdbms block IO due to big payload           0
cell num smart IO sessions using passthru mode due to user                0
cell num smart IO sessions using passthru mode due to cellsrv             0
cell num smart IO sessions using passthru mode due to timezone            0
cell num smart file creation sessions using rdbms block IO mode           0
cell physical IO interconnect bytes returned by smart scan       5507768136
cell num fast response sessions                                           0
cell num fast response sessions continuing to smart scan                  0
cell statistics spare1                                                    0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell statistics spare2                                                    0
cell statistics spare3                                                    0
cell statistics spare4                                                    0
cell statistics spare5                                                    0
cell statistics spare6                                                    0
cell scans                                                              156
cell blocks processed by cache layer                                1428684
cell blocks processed by txn layer                                  1428684
cell blocks processed by data layer                                 1300170
cell blocks processed by index layer                                      0
cell commit cache queries                                                 0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell transactions found in commit cache                                   0
cell blocks helped by commit cache                                        0
cell blocks helped by minscn optimization                           1428684
chained rows skipped by cell                                              0
chained rows processed by cell                                            0
chained rows rejected by cell                                             0
cell simulated physical IO bytes eligible for predicate offload           0
cell simulated physical IO bytes returned by predicate offload            0
cell CUs sent uncompressed                                                0
cell CUs sent compressed                                                  0
cell CUs sent head piece                                                  0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell CUs processed for uncompressed                                       0
cell CUs processed for compressed                                         0
cell IO uncompressed bytes                                       1.0651E+10
cell index scans                                                          0
cell flash cache read hits                                            15209

49 rows selected.

Its time  to explain some the these performance counters(i will cover it detail explanation later)

cell physical IO bytes eligible for predicate offload has around 10GB of value (smart scan if confirmed)

cell physical IO interconnect bytes returned by smart scan has gottan value, this performance counter is the
critical one to know whether smart scan happened or not. Generally the bytes sent back to database node through smart scan is quite low, but in our case its quite high. But one thing we made sure that smart scan has kicked in

cell blocks processed by cache layer
cell blocks processed by txn layer
cell blocks processed by data layer

All above counters got almost same amount of values which means there are 1428684 approx blocks which were processed by smart scan during optimization.(I will cover its details explanation later) These three holds the critical information like how much effective was smart Scan when scanning the blocks.


16:20:44 SQL> select s.name,m.value from v$sysstat s,v$mystat m where s.STATISTIC#=m.STATISTIC# and name like '%physical%';

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
physical read total IO requests                                       15242
physical read total multi block requests                              12540
physical read requests optimized                                      15209
physical read total bytes optimized                              1.0603E+10
physical read total bytes                                        1.0621E+10
physical write total IO requests                                          0
physical write total multi block requests                                 0
physical write total bytes                                                0
cell physical IO interconnect bytes                              5514297160
physical reads                                                      1296460
physical reads cache                                                    797

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
physical read flash cache hits                                            0
physical reads direct                                               1295663
physical read IO requests                                             15242
physical read bytes                                              1.0621E+10
physical writes                                                           0
physical writes direct                                                    0
physical writes from cache                                                0
physical write IO requests                                                0
physical reads direct temporary tablespace                                0
physical writes direct temporary tablespace                               0
physical write bytes                                                      0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
physical writes non checkpoint                                            0
physical reads cache prefetch                                           473
physical reads prefetch warmup                                            0
physical reads retry corrupt                                              0
physical reads direct (lob)                                               0
physical writes direct (lob)                                              0
physical reads for flashback new                                          0
cell physical IO bytes saved during optimized file creation               0
cell physical IO bytes saved during optimized RMAN file restore           0
cell physical IO bytes eligible for predicate offload            1.0614E+10
cell physical IO bytes saved by storage index                             0

NAME                                                                  VALUE
---------------------------------------------------------------- ----------
cell physical IO bytes sent directly to DB node to balance CPU            0
cell physical IO interconnect bytes returned by smart scan       5507768136
cell simulated physical IO bytes eligible for predicate offload           0
cell simulated physical IO bytes returned by predicate offload            0

From above its obvious that any physical read shown here had actually turned into smart scan. Look at
physical read total bytes optimized - which shows how many bytes has either optimized using a)storage index b) flash cache or smart scan.


Let confirm this from Trace file as will. Since we job ran in parallel(degree 10), so we got 10 traces in
trace directory. But we can confirm smart scan only by checking QC and one out of 10 Slave process trace,


Trace file for QC:

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.00       0.00          0          0          0           0
Execute      5      0.08       0.29          0         51        178           1
Fetch        9      0.25       0.25          0          0          0          86
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       19      0.34       0.56          0         51        178          87

Misses in library cache during parse: 2

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      13        0.00          0.00
  SQL*Net message from client                    13       64.43        209.74
  SQL*Net break/reset to client                   2        0.00          0.00
  Disk file operations I/O                      940        0.00          0.00
  DFS lock handle                                32        0.10          0.22
  row cache lock                                 40        0.00          0.00
  log file sync                                   1        0.00          0.00



OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      196      0.02       0.02          0          0          0           0
Execute    548      0.09       1.78          0       2233        692         238
Fetch      368     27.28      41.20        797      11019          2         445
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1112     27.39      43.02        797      13252        694         683

Misses in library cache during parse: 5
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  asynch descriptor resize                        1        0.00          0.00
  gc cr block 2-way                              10        0.00          0.00
  gc current block 2-way                        171        0.00          0.02
  enq: TM - contention                            3        0.00          0.00
  gc current block 3-way                        101        0.01          0.03
  Disk file operations I/O                        5        0.00          0.00
  gc current grant busy                           2        0.00          0.00
  gc current block busy                           1        0.00          0.00
  enq: KO - fast object checkpoint                4        0.66          0.66
  reliable message                                1        0.00          0.00
  enq: PS - contention                            3        0.01          0.01
  os thread startup                               8        0.15          0.98
  PX Deq: Join ACK                               10        0.00          0.01
  PX Deq: Parse Reply                            10        0.00          0.00
  PX Deq: Execute Reply                         720        1.06         13.40
  PX Deq: Signal ACK RSG                         10        0.00          0.00
  PX Deq: Signal ACK EXT                         10        0.00          0.01
  PX Deq: Slave Session Stats                    10        0.00          0.00
  gc cr multi block request                    1055        0.00          0.33
  gc cr grant 2-way                              25        0.00          0.00
  cell single block physical read               161        0.00          0.08
  cell list of blocks physical read              81        0.00          0.04
  gc current block congested                      2        0.00          0.00
  cell multiblock physical read                  82        0.00          0.08
  gc cr block busy                               76        0.00          0.04
  enq: HW - contention                            1        0.00          0.00


Observation:
We still see 'cell single block physical read' but this time its very less. There is no 'Cell Smart Scan' in above trace but remember its the slave process job to scan the segments, so would expect this wait events to appear in slave process trace.


Trace file for slave process:

Posting only rel event information:
PARSING IN CURSOR #46950731292240 len=6956 dep=1 uid=84 oct=3 lid=0 tim=1342003755944863 hv=3787614688 ad='76e8e9790' sqlid='079nqsmhw4ug0'
/* SQL Analyze(0) */ select /*+  full(t)    parallel(t,10) parallel_index(t,10) dbms_stats cursor_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitoring no_substrb_pad  */to_char(count("ACCT_ID")),to_char(substrb(dump(min("ACCT_ID")
----------------------
Above is the very first statement ran by slave processes( i have cut the rest of the lines and only shoed the prefix of this query)
Notice, optimzier has included parallel and Full hint for table segments and for its indexes.

Some initial lines from tracefiles..
END OF STMT
PARSE #46950731292240:c=0,e=120,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3385837045,tim=1342003755944862
WAIT #47183537774160: nam='Disk file operations I/O' ela= 264 FileOperation=2 fileno=1281 filetype=2 obj#=-1 tim=1342003755961284
WAIT #47183537774160: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1280 filetype=2 obj#=-1 tim=1342003755961329
WAIT #47183537774160: nam='Disk file operations I/O' ela= 4 FileOperation=2 fileno=1279 filetype=2 obj#=-1 tim=1342003755961346
WAIT #47183537774160: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1278 filetype=2 obj#=-1 tim=1342003755961360
WAIT #47183537774160: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1277 filetype=2 obj#=-1 tim=1342003755961377
WAIT #47183537774160: nam='Disk file operations I/O' ela= 5 FileOperation=2 fileno=1276 filetype=2 obj#=-1 tim=1342003755961391
WAIT #47183537774160: nam='Disk file operations I/O' ela= 2 FileOperation=2 fileno=1275 filetype=2 obj#=-1 tim=1342003755961405
WAIT #47183537774160: nam='Disk file operations I/O' ela= 1 FileOperation=2 fileno=1274 filetype=2 obj#=-1 tim=1342003755961426
WAIT #47183537774160: nam='Disk file operations I/O' ela= 2 FileOperation=2 fileno=1273 filetype=2 obj#=-1 tim=1342003755961441
WAIT #47183537774160: nam='Disk file operations I/O' ela= 5 FileOperation=2 fileno=1272 filetype=2 obj#=-1 tim=1342003755961463
WAIT #47183537774160: nam='Disk file operations I/O' ela= 4 FileOperation=2 fileno=1271 filetype=2 obj#=-1 tim=1342003755961487
WAIT #47183537774160: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1270 filetype=2 obj#=-1 tim=1342003755961505
WAIT #47183537774160: nam='Disk file operations I/O' ela= 5 FileOperation=2 fileno=1269 filetype=2 obj#=-1 tim=1342003755961523
WAIT #47183537774160: nam='Disk file operations I/O' ela= 2 FileOperation=2 fileno=1268 filetype=2 obj#=-1 tim=1342003755961537
WAIT #47183537774160: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1267 filetype=2 obj#=-1 tim=1342003755961550
WAIT #47183537774160: nam='Disk file operations I/O' ela= 13 FileOperation=2 fileno=1266 filetype=2 obj#=-1 tim=1342003755961578
WAIT #47183537774160: nam='Disk file operations I/O' ela= 10 FileOperation=2 fileno=1265 filetype=2 obj#=-1 tim=1342003755961601
WAIT #47183537774160: nam='Disk file operations I/O' ela= 6 FileOperation=2 fileno=1264 filetype=2 obj#=-1 tim=1342003755961616
WAIT #47183537774160: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1263 filetype=2 obj#=-1 tim=1342003755961631
WAIT #47183537774160: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1262 filetype=2 obj#=-1 tim=1342003755961645
WAIT #47183537774160: nam='Disk file operations I/O' ela= 9 FileOperation=2 fileno=1261 filetype=2 obj#=-1 tim=1342003755961662
WAIT #47183537774160: nam='Disk file operations I/O' ela= 4 FileOperation=2 fileno=1260 filetype=2 obj#=-1 tim=1342003755961676
WAIT #47183537774160: nam='Disk file operations I/O' ela= 3 FileOperation=2 fileno=1258 filetype=2 obj#=-1 tim=1342003755961689
WAIT #47183537774160: nam='Disk file operations I/O' ela= 5 FileOperation=2 fileno=1190 filetype=2 obj#=-1 tim=1342003755961706
WAIT #47183537774160: nam='Disk file operations I/O' ela= 1 FileOperation=2 fileno=1189 filetype=2 obj#=-1 tim=1342003755961726
WAIT #47183537774160: nam='Disk file operations I/O' ela= 4 FileOperation=2 fileno=1188 filetype=2 obj#=-1 tim=1342003755961741
WAIT #47183537774160: nam='Disk file operations I/O' ela= 4 FileOperation=2 fileno=1187 filetype=2 obj#=-1 tim=1342003755961777
WAIT #47183537774160: nam='Disk file operations I/O' ela= 10 FileOperation=2 fileno=1186 filetype=2 obj#=-1 tim=1342003755961798
WAIT #47183537774160: nam='Disk file operations I/O' ela= 2 FileOperation=2 fileno=1185 filetype=2 obj#=-1 tim=1342003755
------------------------------
WAIT #46950731292240: nam='PX Deq: Execution Msg' ela= 3990 sleeptime/senderid=268566527 passes=1 p3=31829234640 obj#=-1 tim=1342003755952048
WAIT #46950731292240: nam='cell smart table scan' ela= 171 cellhash#=1170179701 p2=0 p3=0 obj#=75635 tim=1342003755963472
WAIT #46950731292240: nam='cell smart table scan' ela= 151 cellhash#=2167730007 p2=0 p3=0 obj#=75635 tim=1342003755964454
WAIT #46950731292240: nam='cell smart table scan' ela= 138 cellhash#=3675430230 p2=0 p3=0 obj#=75635 tim=1342003755965431
WAIT #46950731292240: nam='cell smart table scan' ela= 132 cellhash#=3883045144 p2=0 p3=0 obj#=75635 tim=1342003755966388
WAIT #46950731292240: nam='cell smart table scan' ela= 156 cellhash#=1423418432 p2=0 p3=0 obj#=75635 tim=1342003755967396
WAIT #46950731292240: nam='cell smart table scan' ela= 122 cellhash#=1731298062 p2=0 p3=0 obj#=75635 tim=1342003755968112
WAIT #46950731292240: nam='cell smart table scan' ela= 122 cellhash#=1557764708 p2=0 p3=0 obj#=75635 tim=1342003755968826
WAIT #46950731292240: nam='cell smart table scan' ela= 141 cellhash#=3126672640 p2=0 p3=0 obj#=75635 tim=1342003755969535
WAIT #46950731292240: nam='cell smart table scan' ela= 181 cellhash#=3737599385 p2=0 p3=0 obj#=75635 tim=1342003755970278
WAIT #46950731292240: nam='cell smart table scan' ela= 118 cellhash#=283595207 p2=0 p3=0 obj#=75635 tim=1342003755971101
WAIT #46950731292240: nam='cell smart table scan' ela= 194 cellhash#=3222317718 p2=0 p3=0 obj#=75635 tim=1342003755971870
WAIT #46950731292240: nam='cell smart table scan' ela= 147 cellhash#=406411811 p2=0 p3=0 obj#=75635 tim=1342003755972587
WAIT #46950731292240: nam='cell smart table scan' ela= 108 cellhash#=2548483693 p2=0 p3=0 obj#=75635 tim=1342003755973309
WAIT #46950731292240: nam='cell smart table scan' ela= 736 cellhash#=1170179701 p2=0 p3=0 obj#=75635 tim=1342003755974470
WAIT #46950731292240: nam='cell smart table scan' ela= 763 cellhash#=2167730007 p2=0 p3=0 obj#=75635 tim=1342003755975271

So we have seen may 'cell smart table scan' in out traces which confirms us that smart scan has happened.
I have cover the reason for seeing too much 'Disk file operations I/O' wait event here.


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1     12.91      13.13     130372     131275         42           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     12.91      13.13     130372     131275         42           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  SORT AGGREGATE (cr=0 pr=0 pw=0 time=0 us)
         0          0          0   PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
         0          0          0    PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
         1          1          1     SORT AGGREGATE (cr=131275 pr=130372 pw=0 time=13131299 us)
   4040662    4040662    4040662      APPROXIMATE NDV AGGREGATE (cr=131275 pr=130372 pw=0 time=6992899 us cost=39917 size=5126019212 card=40362356)
   4040662    4040662    4040662       PX BLOCK ITERATOR (cr=131275 pr=130372 pw=0 time=2517894 us cost=39917 size=5126019212 card=40362356)
   4040662    4040662    4040662        TABLE ACCESS STORAGE FULL ACCT_STATEMENT (cr=131275 pr=130372 pw=0 time=2201673 us cost=39917 size=5126019212 card=40362356)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                          78        0.37          0.38
  Disk file operations I/O                      677        0.00          0.00
  latch free                                      6        0.00          0.00
  cell smart table scan                         348        0.00          0.15


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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  latch free                                      1        0.00          0.00
  cell smart table scan                          14        0.00          0.00
  PX Deq: Slave Session Stats                     1        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1     12.91      13.13     130372     131275         42           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     12.91      13.13     130372     131275         42           0

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                          78        0.37          0.38
  Disk file operations I/O                      677        0.00          0.00
  latch free                                      6        0.00          0.00
  cell smart table scan                         348        0.00          0.15

    1  user  SQL statements in session.
    0  internal SQL statements in session.
    1  SQL statements in session.
********************************************************************************
Observation:

1) We saw 'TABLE ACCESS STORAGE FULL ACCT_STATEMENT' in explain plan for query.(which is one of the requirement for smart scan)
2) Cell Smart Scan appeared for 348 times(recursive though). And also 14 times for non recursive query
3) Cell smart scan is the major contribute in wait evens for recursive and non recursive queries.

So trace of slave process also confirm us that smart scan has been used for this job


No comments:

Post a Comment