oracle-databaseoracle11gdatabase-administrationsql-tuningdatabase-tuning

Why there are current block reads in my TKPROF output on a simple select statement? Why there are two parses in one query?


In the query below, I used the sample SH schema in my query in Oracle. When I get the TKPROF output for that query, I see that, there are some current block reads. But as far as I know, current block reads happen when that block has a change on it. But I did not perform any update or something. I just executed that query.

So, why there are 28 current mode block reads?

Next question is, in the execution plan statistics, some starts values are 0. Does that mean this step is not performed? But when I check the autotrace output, it seems these steps are also executed. (For example, the index unique scan customers_pk has starts = 0). So is this step executed? If yes, why it writes 0 here?

Last question is, why there are both hard parse and soft parse (two parses) in one query?

Thanks in advance.

select s.prod_id, p.prod_name, s.cust_id, c.cust_first_name 
from
 sh.sales s, sh.products p, sh.customers c where s.prod_id = p.prod_id and 
  s.cust_id = c.cust_id and s.amount_sold > 1500


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.03       0.03          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      542      0.32       0.72          0       3607         28        8114
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      544      0.35       0.76          0       3607         28        8114

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      8114       8114       8114  HASH JOIN  (cr=3607 pr=0 pw=0 time=450527 us starts=1 cost=859 size=469504 card=8384)
      8114       8114       8114   NESTED LOOPS  (cr=1643 pr=0 pw=0 time=253284 us starts=1 cost=859 size=469504 card=8384)
      8114       8114       8114    NESTED LOOPS  (cr=1643 pr=0 pw=0 time=251761 us starts=1)
      8114       8114       8114     STATISTICS COLLECTOR  (cr=1643 pr=0 pw=0 time=250365 us starts=1)
      8114       8114       8114      HASH JOIN  (cr=1643 pr=0 pw=0 time=250044 us starts=1 cost=454 size=368896 card=8384)
        72         72         72       NESTED LOOPS  (cr=8 pr=0 pw=0 time=863 us starts=1 cost=454 size=368896 card=8384)
        72         72         72        STATISTICS COLLECTOR  (cr=8 pr=0 pw=0 time=790 us starts=1)
        72         72         72         TABLE ACCESS FULL PRODUCTS (cr=8 pr=0 pw=0 time=691 us starts=1 cost=3 size=2160 card=72)
         0          0          0        PARTITION RANGE ALL PARTITION: 1 28 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=451 size=1624 card=116)
         0          0          0         TABLE ACCESS BY LOCAL INDEX ROWID BATCHED SALES PARTITION: 1 28 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=451 size=1624 card=116)
         0          0          0          BITMAP CONVERSION TO ROWIDS (cr=0 pr=0 pw=0 time=0 us starts=0)
         0          0          0           BITMAP INDEX SINGLE VALUE SALES_PROD_BIX PARTITION: 1 28 (cr=0 pr=0 pw=0 time=0 us starts=0)(object id 101439)
      8114       8114       8114       PARTITION RANGE ALL PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=248277 us starts=1 cost=451 size=117376 card=8384)
      8114       8114       8114        TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=208294 us starts=28 cost=451 size=117376 card=8384)
         0          0          0     INDEX UNIQUE SCAN CUSTOMERS_PK (cr=0 pr=0 pw=0 time=0 us starts=0)(object id 101249)
         0          0          0    TABLE ACCESS BY INDEX ROWID CUSTOMERS (cr=0 pr=0 pw=0 time=0 us starts=0 cost=405 size=12 card=1)
     55500      55500      55500   TABLE ACCESS FULL CUSTOMERS (cr=1964 pr=0 pw=0 time=120870 us starts=1 cost=405 size=666000 card=55500)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                           35        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00
  SQL*Net message to client                     542        0.00          0.00
  SQL*Net message from client                   542       41.10         57.47
********************************************************************************

Solution

  • We don't usually get a lot of tuning/optimization questions here, but I'll try to answer this.

    1. Current block gets MIGHT indicate a change on the block (DML), but they don't always. They also appear whenever you have a full scan, because the segment headers have to be read in "current mode" in order to figure out how to scan the table.

    2. Yes, a "starts" of 0 means that step wasn't performed. You'll note that those steps also have 0 rows. Those steps are still part of the plan because if any rows did match those conditions, those steps would need to be executed. But in this case they weren't used.

    3. There aren't two parses - you're only running the statement once, so it's only being parsed once. That's what Parse count 1 means. It was a hard parse, because your first run of a query is always a hard parse. You can see that where it says "Misses in library cache during parse: 1". It checked to see whether this exact query had been run before and it hadn't; therefore it's a hard parse. If you ran this exact same query again, it would find it in the library cache and it would be a soft parse.