1 2 Previous Next 19 Replies Latest reply: May 28, 2011 3:11 AM by Martin Preiss RSS

    slow queries with inappropriate high_value for interval partition

    Martin Preiss
      Hello,

      yesterday I defined an interval partitioned table with a single initial partition. The partition key was an integer value with a (sequence generated) run id, the interval was 1 - and since I did not know the value of the id, I set the high value for the initial partition to 1. Then I inserted some rows, started a simple query - and waited a long time for the result. A 10046-trace showed, that the query was using a lot of cpu - but I had no idea what it was doing.

      Today I created a simple test case (in 11.1.0.7 on a Centos 5-Server; but I got similar results on my Windows 11.2.0.1 database):
      -- test_interval.sql
      
      set verify off
      undefine high_value
      
      drop table test_interval_p1_&&high_value;
      
      create table test_interval_p1_&high_value
        partition by range (id)
        interval (1)
        (partition test_p1 values less than (&high_value))
      as
      select 100000 id
           , t.*
        from all_objects t
       where 1 = 0;
      
      insert into test_interval_p1_&high_value
      select 100000 id
           , t.*
        from all_objects t;
      
      commit;
      
      -- pause
        
      select id, count(*)
        from test_interval_p1_&high_value
       group by id;
      When I choose a high_value > 100000 the grouping query runs < 1 sec.
      With high_value = 100000: < 1 sec
      With high_value = 90000: < 1 sec
      With high_value = 80000: 3 sec
      With high_value = 70000: 9 sec
      With high_value = 60000: 17 sec
      With high_value = 50000: 28 sec
      With high_value = 40000: 34 sec
      With high_value = 30000: 47 sec
      With high_value = 20000: 61 sec
      With high_value = 10000: 76 sec
      With high_value = 1: 102 sec

      When I take snapshots from v$sesstat before and after the query execution, I see that the slow queries show signifikant higher values for 'CPU used when call started', 'CPU used by this session', 'DB time', 'session uga memory', 'session pga memory'.

      But I still have no idea, what the query does with all the cpu (perhaps iterating over possible - but non-existing - partitions? But that sounds a little bit silly). In the documentation (http://download.oracle.com/docs/cd/E11882_01/server.112/e16541/part_admin001.htm#VLDBG1088) I found no explanation (and I have no MOS access at the moment).

      Can someone explain to me what happens here?

      Thanks and regards

      Martin

      Edited by: mpreiss on May 25, 2011 8:05 PM

      Edited by: mpreiss on May 25, 2011 8:45 PM
        • 1. Re: slow queries with inappropriate high_value
          P.Forstmann
          Please post full TKPROF output of the slow queries.
          • 2. Re: slow queries with inappropriate high_value
            Martin Preiss
            here is the tkprof output for the slow query:
            select id, count(*)
              from test_interval_p1_1
             group by id
            
            call     count       cpu    elapsed       disk      query    current        rows
            ------- ------  -------- ---------- ---------- ---------- ----------  ----------
            Parse        1      0.00       0.02          0          2          0           0
            Execute      1      0.00       0.00          0          0          0           0
            Fetch        2    103.91     104.05          0        834          0           1
            ------- ------  -------- ---------- ---------- ---------- ----------  ----------
            total        4    103.92     104.07          0        836          0           1
            
            Misses in library cache during parse: 1
            Optimizer mode: ALL_ROWS
            Parsing user id: 198  
            
            Rows     Row Source Operation
            -------  ---------------------------------------------------
                  1  PARTITION RANGE ALL PARTITION: 1 1048575 (cr=834 pr=0 pw=0 time=0 us cost=320 size=2002117 card=154009)
                  1   HASH GROUP BY (cr=834 pr=0 pw=0 time=0 us cost=320 size=2002117 card=154009)
             107294    TABLE ACCESS FULL TEST_INTERVAL_P1_1 PARTITION: 1 1048575 (cr=834 pr=0 pw=0 time=0 us cost=313 size=2002117 card=154009)
            
            
            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        0.00          0.00
            And here the result for the fast query:
            select id, count(*)
              from test_interval_p1_100000
             group by id
            
            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.05       0.06          0        834          0           1
            ------- ------  -------- ---------- ---------- ---------- ----------  ----------
            total        4      0.05       0.06          0        836          0           1
            
            Misses in library cache during parse: 1
            Optimizer mode: ALL_ROWS
            Parsing user id: 198  
            
            Rows     Row Source Operation
            -------  ---------------------------------------------------
                  1  PARTITION RANGE ALL PARTITION: 1 1048575 (cr=834 pr=0 pw=0 time=0 us cost=318 size=1366937 card=105149)
                  1   HASH GROUP BY (cr=834 pr=0 pw=0 time=0 us cost=318 size=1366937 card=105149)
             107296    TABLE ACCESS FULL TEST_INTERVAL_P1_100000 PARTITION: 1 1048575 (cr=834 pr=0 pw=0 time=0 us cost=313 size=1366937 card=105149)
            
            
            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        0.00          0.00
            • 3. Re: slow queries with inappropriate high_value
              P.Forstmann
              It is really strange that all time values are exactly 0 microsecond in both execution plans. What is the output of:
              show parameter stat
              • 4. Re: slow queries with inappropriate high_value
                Martin Preiss
                SQL>  show parameter stat
                
                name                                 TYPE        value
                ------------------------------------ ----------- ----------
                log_archive_dest_state_1             string      enable
                log_archive_dest_state_10            string      enable
                log_archive_dest_state_2             string      enable
                log_archive_dest_state_3             string      enable
                log_archive_dest_state_4             string      enable
                log_archive_dest_state_5             string      enable
                log_archive_dest_state_6             string      enable
                log_archive_dest_state_7             string      enable
                log_archive_dest_state_8             string      enable
                log_archive_dest_state_9             string      enable
                optimizer_use_pending_statistics     boolean     FALSE
                statistics_level                     string      TYPICAL
                timed_os_statistics                  integer     0
                timed_statistics                     boolean     TRUE
                • 5. Re: slow queries with inappropriate high_value
                  P.Forstmann
                  I can reproduce this issue on 11.2.0.1 on Linux.

                  TKPROF output
                  select id, count(*)
                    from test_interval_p1_1
                   group by id
                  
                  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     46.60      49.58          0       1046          0           1
                  ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                  total        4     46.60      49.59          0       1048          0           1
                  
                  Misses in library cache during parse: 1
                  Optimizer mode: ALL_ROWS
                  Parsing user id: 5
                  
                  Rows     Row Source Operation
                  -------  ---------------------------------------------------
                        1  PARTITION RANGE ALL PARTITION: 1 1048575 (cr=1046 pr=0 pw=0 time=0 us cost=286 size=903448 card=69496)
                        1   HASH GROUP BY (cr=1046 pr=0 pw=0 time=0 us cost=286 size=903448 card=69496)
                    70964    TABLE ACCESS FULL TEST_INTERVAL_P1_1 PARTITION: 1 1048575 (cr=1046 pr=0 pw=0 time=392661 us cost=284 size=903448 card=69496)
                  
                  
                  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
                    asynch descriptor resize                        1        0.00          0.00
                    SQL*Net message from client                     2        0.00          0.00
                  and raw trace file:
                  PARSING IN CURSOR #5 len=58 dep=0 uid=5 oct=3 lid=5 tim=1306351436360825 hv=3283355953 ad='2d9d22b4' sqlid='965d68r1v829j'
                  select id, count(*)
                    from test_interval_p1_1
                   group by id
                  END OF STMT
                  PARSE #5:c=319952,e=383346,p=0,cr=72,cu=0,mis=1,r=0,dep=0,og=1,plh=1704390554,tim=1306351436360792
                  EXEC #5:c=999,e=433,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1704390554,tim=1306351436361517
                  WAIT #5: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1306351436361627
                  
                  *** 2011-05-25 21:24:45.916
                  WAIT #5: nam='asynch descriptor resize' ela= 15 outstanding #aio=0 current aio limit=130 new aio limit=194 obj#=-1 tim=1306351485915846
                  FETCH #5:c=46594916,e=49576270,p=0,cr=1046,cu=0,mis=0,r=1,dep=0,og=1,plh=1704390554,tim=1306351485937945
                  WAIT #5: nam='SQL*Net message from client' ela= 1346 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1306351485939515
                  FETCH #5:c=5999,e=6505,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1704390554,tim=1306351485946103
                  STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 1048575 (cr=1046 pr=0 pw=0 time=0 us cost=286 size=903448 card=69496)'
                  STAT #5 id=2 cnt=1 pid=1 pos=1 obj=0 op='HASH GROUP BY (cr=1046 pr=0 pw=0 time=0 us cost=286 size=903448 card=69496)'
                  STAT #5 id=3 cnt=70964 pid=2 pos=1 obj=73417 op='TABLE ACCESS FULL TEST_INTERVAL_P1_1 PARTITION: 1 1048575 (cr=1046 pr=0 pw=0 time=392661 us cost=284 size=903448 card=69496)'
                  WAIT #5: nam='SQL*Net message to client' ela= 69 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1306351485958770
                  This behaviour could be linked to new full table scan algorithm that can read directly database blocks into PGA but I'm not sure.
                  • 6. Re: slow queries with inappropriate high_value
                    Martin Preiss
                    The 0-values look strange - but I don't think it's a special problem of the database, because I could reproduce the same behaviour on three databases (2 x 11.1.0.7 and 1 x 11.2.0.1) with completly different configurations.
                    • 7. Re: slow queries with inappropriate high_value
                      Martin Preiss
                      in my Windows-Test-Database 11.2.0.1 I get the same results with scattered reads - so it should not be directly related to direct path FTS:
                      select id, count(*)
                        from test_interval_p1_1
                       group by id
                      
                      call     count       cpu    elapsed       disk      query    current        rows
                      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                      Parse        1      0.00       0.01          0          4          1           0
                      Execute      1      0.00       0.00          0          0          0           0
                      Fetch        2    148.68     149.17        727       1037          0           1
                      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                      total        4    148.68     149.18        727       1041          1           1
                      
                      Misses in library cache during parse: 1
                      Optimizer mode: ALL_ROWS
                      Parsing user id: 75  
                      
                      Rows     Row Source Operation
                      -------  ---------------------------------------------------
                            1  PARTITION RANGE ALL PARTITION: 1 1048575 (cr=1037 pr=727 pw=0 time=0 us cost=545 size=916695 card=70515)
                            1   HASH GROUP BY (cr=1037 pr=727 pw=0 time=0 us cost=545 size=916695 card=70515)
                        70071    TABLE ACCESS FULL TEST_INTERVAL_P1_1 PARTITION: 1 1048575 (cr=1037 pr=727 pw=0 time=13681 us cost=533 size=916695 card=70515)
                      
                      
                      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
                        db file scattered read                         54        0.01          0.11
                        db file sequential read                         3        0.00          0.00
                        SQL*Net message from client                     2        0.00          0.00
                      
                      -- unformatted:
                      PARSING IN CURSOR #2 len=58 dep=0 uid=75 oct=3 lid=75 tim=9393374094 hv=3283355953 ad='7ff55e0bb48' sqlid='965d68r1v829j'
                      select id, count(*)
                        from test_interval_p1_1
                       group by id
                      END OF STMT
                      PARSE #2:c=93600,e=155354,p=302,cr=76,cu=1,mis=1,r=0,dep=0,og=1,plh=1704390554,tim=9393374093
                      EXEC #2:c=0,e=81,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1704390554,tim=9393374274
                      WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9393374358
                      
                      *** 2011-05-25 21:20:48.123
                      WAIT #2: nam='db file scattered read' ela= 18296 file#=4 block#=270048 blocks=8 obj#=97924 tim=9542383930
                      WAIT #2: nam='db file scattered read' ela= 405 file#=4 block#=270057 blocks=7 obj#=97924 tim=9542384600
                      WAIT #2: nam='db file scattered read' ela= 243 file#=4 block#=270064 blocks=3 obj#=97924 tim=9542385074
                      WAIT #2: nam='db file scattered read' ela= 255 file#=4 block#=270068 blocks=4 obj#=97924 tim=9542385481
                      WAIT #2: nam='db file scattered read' ela= 8332 file#=4 block#=271104 blocks=8 obj#=97924 tim=9542394094
                      WAIT #2: nam='db file scattered read' ela= 408 file#=4 block#=271113 blocks=7 obj#=97924 tim=9542394748
                      WAIT #2: nam='db file scattered read' ela= 304 file#=4 block#=271120 blocks=5 obj#=97924 tim=9542395274
                      WAIT #2: nam='db file scattered read' ela= 197 file#=4 block#=271126 blocks=2 obj#=97924 tim=9542395666
                      WAIT #2: nam='db file scattered read' ela= 392 file#=4 block#=271129 blocks=7 obj#=97924 tim=9542396182
                      WAIT #2: nam='db file scattered read' ela= 427 file#=4 block#=271136 blocks=8 obj#=97924 tim=9542396840
                      WAIT #2: nam='db file scattered read' ela= 406 file#=4 block#=271145 blocks=7 obj#=97924 tim=9542397486
                      WAIT #2: nam='db file scattered read' ela= 409 file#=4 block#=271152 blocks=8 obj#=97924 tim=9542398280
                      WAIT #2: nam='db file scattered read' ela= 377 file#=4 block#=271161 blocks=7 obj#=97924 tim=9542399043
                      WAIT #2: nam='db file scattered read' ela= 353 file#=4 block#=271168 blocks=6 obj#=97924 tim=9542399783
                      WAIT #2: nam='db file sequential read' ela= 223 file#=4 block#=271175 blocks=1 obj#=97924 tim=9542400394
                      WAIT #2: nam='db file scattered read' ela= 330 file#=4 block#=271184 blocks=6 obj#=97924 tim=9542401098
                      WAIT #2: nam='db file sequential read' ela= 331 file#=4 block#=271191 blocks=1 obj#=97924 tim=9542401904
                      WAIT #2: nam='db file sequential read' ela= 383 file#=4 block#=271234 blocks=1 obj#=97924 tim=9542402417
                      WAIT #2: nam='db file scattered read' ela= 11520 file#=4 block#=271243 blocks=62 obj#=97924 tim=9542414360
                      WAIT #2: nam='db file scattered read' ela= 419 file#=4 block#=271313 blocks=7 obj#=97924 tim=9542418121
                      WAIT #2: nam='db file scattered read' ela= 1243 file#=4 block#=271328 blocks=27 obj#=97924 tim=9542420078
                      WAIT #2: nam='db file scattered read' ela= 308 file#=4 block#=271356 blocks=4 obj#=97924 tim=9542421695
                      WAIT #2: nam='db file scattered read' ela= 892 file#=4 block#=271362 blocks=17 obj#=97924 tim=9542422950
                      
                      *** 2011-05-25 21:20:48.169
                      WAIT #2: nam='db file scattered read' ela= 5156 file#=4 block#=271387 blocks=7 obj#=97924 tim=9542429137
                      WAIT #2: nam='db file scattered read' ela= 343 file#=4 block#=271402 blocks=4 obj#=97924 tim=9542430244
                      WAIT #2: nam='db file scattered read' ela= 549 file#=4 block#=271414 blocks=10 obj#=97924 tim=9542431341
                      WAIT #2: nam='db file scattered read' ela= 343 file#=4 block#=271440 blocks=4 obj#=97924 tim=9542432603
                      WAIT #2: nam='db file scattered read' ela= 10817 file#=4 block#=271456 blocks=32 obj#=97924 tim=9542444062
                      WAIT #2: nam='db file scattered read' ela= 1189 file#=4 block#=271490 blocks=23 obj#=97924 tim=9542446697
                      WAIT #2: nam='db file scattered read' ela= 1171 file#=4 block#=271521 blocks=27 obj#=97924 tim=9542449200
                      WAIT #2: nam='db file scattered read' ela= 6781 file#=4 block#=271556 blocks=19 obj#=97924 tim=9542457457
                      WAIT #2: nam='db file scattered read' ela= 7450 file#=4 block#=271583 blocks=5 obj#=97924 tim=9542465976
                      WAIT #2: nam='db file scattered read' ela= 375 file#=4 block#=271596 blocks=7 obj#=97924 tim=9542466936
                      WAIT #2: nam='db file scattered read' ela= 499 file#=4 block#=271626 blocks=5 obj#=97924 tim=9542468342
                      WAIT #2: nam='db file scattered read' ela= 1861 file#=4 block#=271639 blocks=7 obj#=97924 tim=9542470749
                      WAIT #2: nam='db file scattered read' ela= 339 file#=4 block#=271654 blocks=5 obj#=97924 tim=9542471706
                      WAIT #2: nam='db file scattered read' ela= 2359 file#=4 block#=271667 blocks=50 obj#=97924 tim=9542474663
                      WAIT #2: nam='db file scattered read' ela= 710 file#=4 block#=271728 blocks=16 obj#=97924 tim=9542477791
                      WAIT #2: nam='db file scattered read' ela= 713 file#=4 block#=271746 blocks=10 obj#=97924 tim=9542479334
                      WAIT #2: nam='db file scattered read' ela= 8741 file#=4 block#=271764 blocks=35 obj#=97924 tim=9542488850
                      WAIT #2: nam='db file scattered read' ela= 691 file#=4 block#=271807 blocks=11 obj#=97924 tim=9542491195
                      WAIT #2: nam='db file scattered read' ela= 1512 file#=4 block#=271826 blocks=29 obj#=97924 tim=9542493531
                      WAIT #2: nam='db file scattered read' ela= 567 file#=4 block#=271863 blocks=9 obj#=97924 tim=9542495527
                      WAIT #2: nam='db file scattered read' ela= 6304 file#=4 block#=271874 blocks=22 obj#=97924 tim=9542502390
                      WAIT #2: nam='db file scattered read' ela= 555 file#=4 block#=271904 blocks=10 obj#=97924 tim=9542504232
                      WAIT #2: nam='db file scattered read' ela= 1000 file#=4 block#=271922 blocks=15 obj#=97924 tim=9542505990
                      WAIT #2: nam='db file scattered read' ela= 1427 file#=4 block#=271945 blocks=31 obj#=97924 tim=9542508474
                      WAIT #2: nam='db file scattered read' ela= 760 file#=4 block#=271984 blocks=16 obj#=97924 tim=9542510830
                      WAIT #2: nam='db file scattered read' ela= 1276 file#=4 block#=272002 blocks=31 obj#=97924 tim=9542513006
                      WAIT #2: nam='db file scattered read' ela= 5469 file#=4 block#=272041 blocks=2 obj#=97924 tim=9542520128
                      WAIT #2: nam='db file scattered read' ela= 348 file#=4 block#=272051 blocks=4 obj#=97924 tim=9542520915
                      WAIT #2: nam='db file scattered read' ela= 279 file#=4 block#=272063 blocks=2 obj#=97924 tim=9542521700
                      WAIT #2: nam='db file scattered read' ela= 348 file#=4 block#=272081 blocks=6 obj#=97924 tim=9542522694
                      WAIT #2: nam='db file scattered read' ela= 802 file#=4 block#=272095 blocks=9 obj#=97924 tim=9542524120
                      WAIT #2: nam='db file scattered read' ela= 1711 file#=4 block#=272105 blocks=23 obj#=97924 tim=9542526397
                      WAIT #2: nam='db file scattered read' ela= 468 file#=4 block#=272130 blocks=9 obj#=97924 tim=9542527994
                      WAIT #2: nam='db file scattered read' ela= 979 file#=4 block#=272140 blocks=19 obj#=97924 tim=9542529509
                      FETCH #2:c=148668953,e=149156082,p=727,cr=1037,cu=0,mis=0,r=1,dep=0,og=1,plh=1704390554,tim=9542530482
                      WAIT #2: nam='SQL*Net message from client' ela= 704 driver id=1413697536 #bytes=1 p3=0 obj#=97924 tim=9542531260
                      FETCH #2:c=15601,e=16939,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1704390554,tim=9542548264
                      STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 1048575 (cr=1037 pr=727 pw=0 time=0 us cost=545 size=916695 card=70515)'
                      STAT #2 id=2 cnt=1 pid=1 pos=1 obj=0 op='HASH GROUP BY (cr=1037 pr=727 pw=0 time=0 us cost=545 size=916695 card=70515)'
                      STAT #2 id=3 cnt=70071 pid=2 pos=1 obj=97922 op='TABLE ACCESS FULL TEST_INTERVAL_P1_1 PARTITION: 1 1048575 (cr=1037 pr=727 pw=0 time=13681 us cost=533 size=916695 card=70515)'
                      WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=97924 tim=9542568131
                      WAIT #2: nam='SQL*Net message from client' ela= 2619 driver id=1413697536 #bytes=1 p3=0 obj#=97924 tim=9542570814
                      CLOSE #2:c=0,e=224,dep=0,type=0,tim=9542571080
                      XCTEND rlbk=0, rd_only=1, tim=9542576816
                      • 8. Re: slow queries with inappropriate high_value for interval partition
                        Jonathan Lewis
                        >

                        >
                        But I still have no idea, what the query does with all the cpu (perhaps iterating over possible - but non-existing - partitions? But that sounds a little bit silly). In the documentation (http://download.oracle.com/docs/cd/E11882_01/server.112/e16541/part_admin001.htm#VLDBG1088) I found no explanation (and I have no MOS access at the moment).

                        Can someone explain to me what happens here?
                        It looks like a bug - call it in to Oracle with an SR.

                        I repeated your test but only inserted one row into the table, and it took 15 seconds to run the query on my laptop when I set &high_value to 25000.

                        Check v$rowcache activity - that's where the CPU is going. You will see "100,000 - high_value" gets on on the dc_tablespaces and dc_users row cache entries when you run the query (and that's two latch hits on the rowcache latch for every get).


                        Regards
                        Jonathan Lewis
                        • 9. Re: slow queries with inappropriate high_value for interval partition
                          Martin Preiss
                          Jonathan,

                          thank you for the information about v$rowcache and the latches - that was what I was looking for.

                          Regards

                          Martin Preiss
                          • 10. Re: slow queries with inappropriate high_value for interval partition
                            864728
                            Try

                            alter session set "_gby_hash_aggregation_enabled"=false;
                            select id, count(*)
                            from test_interval_p1_1
                            group by id;
                            • 11. Re: slow queries with inappropriate high_value for interval partition
                              Martin Preiss
                              thank you for the suggestion: it work's - with gbyhash_aggregation_enabled=false the query runs again fast!

                              I knew that the parameter would change the execution plan and disable HASH GROUP BY (years ago I had some problems with Bug 4604970 - Wrong results with 'hash group by' aggregation enabled), but I did not think that this change would reduce the queries duration, because I thougth the data access part (= the FTS of the partitions) would remain unchanged. Obviously that's not true.
                              alter session set "_gby_hash_aggregation_enabled"=false;
                              
                              select id, count(*)
                                from test_interval_p1_70000
                               group by id;
                              
                              Abgelaufen: 00:00:00.06
                              
                              Ausführungsplan
                              ----------------------------------------------------------
                              Plan hash value: 3652604150
                              
                              --------------------------------------------------------------------------------------------------------------
                              | Id  | Operation           | Name                   | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
                              --------------------------------------------------------------------------------------------------------------
                              |   0 | SELECT STATEMENT    |                        |     1 |     3 |   545   (3)| 00:00:03 |       |       |
                              |   1 |  PARTITION RANGE ALL|                        |     1 |     3 |   545   (3)| 00:00:03 |     1 |1048575|
                              |   2 |   SORT GROUP BY     |                        |     1 |     3 |   545   (3)| 00:00:03 |       |       |
                              |   3 |    TABLE ACCESS FULL| TEST_INTERVAL_P1_70000 | 70081 |   205K|   533   (1)| 00:00:03 |     1 |1048575|
                              --------------------------------------------------------------------------------------------------------------
                              
                              alter session set "_gby_hash_aggregation_enabled"=true;
                              
                              Abgelaufen: 00:00:09.18
                              
                              Ausführungsplan
                              ----------------------------------------------------------
                              Plan hash value: 1682733399
                              
                              --------------------------------------------------------------------------------------------------------------
                              | Id  | Operation           | Name                   | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
                              --------------------------------------------------------------------------------------------------------------
                              |   0 | SELECT STATEMENT    |                        |     1 |     3 |   545   (3)| 00:00:03 |       |       |
                              |   1 |  PARTITION RANGE ALL|                        |     1 |     3 |   545   (3)| 00:00:03 |     1 |1048575|
                              |   2 |   HASH GROUP BY     |                        |     1 |     3 |   545   (3)| 00:00:03 |       |       |
                              |   3 |    TABLE ACCESS FULL| TEST_INTERVAL_P1_70000 | 70081 |   205K|   533   (1)| 00:00:03 |     1 |1048575|
                              --------------------------------------------------------------------------------------------------------------
                              Regards

                              Martin Preiss
                              • 12. Re: slow queries with inappropriate high_value for interval partition
                                698658
                                And Anyone can tell me how its related to 'v$rowcache activity' ?
                                Regards
                                GregG
                                • 13. Re: slow queries with inappropriate high_value for interval partition
                                  Jonathan Lewis
                                  GregG wrote:
                                  And Anyone can tell me how its related to 'v$rowcache activity' ?
                                  Bugs - can do anything:

                                  Here's (relevant) session stats, latch stats, and row cache stats when running with high_level = 1 (so the new partition skips ca. 100,000 partitions) and only one row in the table.
                                  Name                                                                     Value
                                  ----                                                                     -----
                                  workarea executions - optimal                                                6
                                  sorts (memory)                                                               6
                                  sorts (rows)                                                                34
                                  
                                  Latch                              Gets      Misses     Sp_Get     Sleeps     Im_Gets   Im_Miss Holding Woken Time ms
                                  -----                              ----      ------     ------     ------     -------   ------- ------- ----- -------
                                  row cache objects               601,726           0          0          0           0         0       0     0      .0
                                  SQL memory manager worka        200,610           0          0          0           0         0       0     0      .0
                                  
                                  Parameter                 Usage Fixed    Gets  Misses   Scans  Misses    Comp    Mods Flushes
                                  ---------                 ----- -----    ----  ------   -----  --------------    ---- -------
                                  dc_tablespaces                0     0 100,015       0       0       0       0       0       0
                                  dc_users                      0     0 100,008       0       0       0       0       0       0
                                  Note that the session records very few workarea operations, and they're all sorts - but the latch activity shows lots of 'SQL memory manager workarea list latch' activity - viz: enough for about 100,000 attempts at workarea manipulation. (And the rowcache activey is consistent with "something" happening 100,000 times).

                                  Now disable hash aggregation, and the latch and rowcache big numbers simply disappear:
                                  Name                                                                     Value
                                  ----                                                                     -----
                                  workarea executions - optimal                                                4
                                  sorts (memory)                                                         100,004
                                  sorts (rows)                                                                34
                                  All we can see of interest is 100,000 sorts - and they haven't made the workarea manager go through its paces.

                                  There is a bug in the interval partition handling - we're trying to do something (aggregate the data) for every single "missing" partition - then the cost of hash aggregating the non-existent data becomes visible as CPU usage because of the work done by the memory manager, but the work done doesn't seem to be recorded properly.

                                  This was 11.1.0.6, by the way, and 25 CPU seconds for the hash aggregation run.

                                  Regards
                                  Jonathan Lewis
                                  • 14. Re: slow queries with inappropriate high_value for interval partition
                                    603349
                                    mpreiss wrote:
                                    thank you for the suggestion: it work's - with gbyhash_aggregation_enabled=false the query runs again fast!
                                    It may work better, but it is still broken. Note the Execs column in the sql monitor reports.
                                    I've filed bug 12597302 for this.
                                    SQL> create table t_p1_1
                                      2    partition by range (id)
                                      3    interval (1)
                                      4    (partition p1 values less than (1))
                                      5  as
                                      6  select 100000 id, t.* from all_objects t where rownum <= 1;
                                    
                                    Table created.
                                    
                                    Elapsed: 00:00:00.10
                                    SQL> 
                                    SQL> create table t_p1_100000
                                      2    partition by range (id)
                                      3    interval (1)
                                      4    (partition p1 values less than (100000))
                                      5  as
                                      6  select 100000 id, t.* from all_objects t where rownum <= 1;
                                    
                                    Table created.
                                    
                                    Elapsed: 00:00:00.10
                                    SQL> 
                                    SQL> exec dbms_stats.gather_table_stats(user,'t_p1_1');
                                    
                                    PL/SQL procedure successfully completed.
                                    
                                    Elapsed: 00:00:00.18
                                    SQL> exec dbms_stats.gather_table_stats(user,'t_p1_100000');
                                    
                                    PL/SQL procedure successfully completed.
                                    
                                    Elapsed: 00:00:00.14
                                    SQL> 
                                    SQL> select /*+ monitor */ id, count(*) from t_p1_1 group by id;
                                    
                                                 ID        COUNT(*)
                                    --------------- ---------------
                                             100000               1
                                    
                                    Elapsed: 00:01:30.57
                                    SQL> select DBMS_SQLTUNE.REPORT_SQL_MONITOR(session_id=>sys_context('userenv','sid'), report_level=>'ALL') as report from dual;
                                    
                                    REPORT
                                    --------------------------------------------------------------------------------------------------------------------------------------------
                                    SQL Monitoring Report
                                    
                                    SQL Text
                                    ------------------------------
                                    select /*+ monitor */ id, count(*) from t_p1_1 group by id
                                    
                                    Global Information
                                    ------------------------------
                                     Status              :  DONE (ALL ROWS)
                                     Instance ID         :  1
                                     Session             :  GRAHN (386:147)
                                     SQL ID              :  1j9tzuf583cmb
                                     SQL Execution ID    :  16777233
                                     Execution Started   :  05/26/2011 16:16:58
                                     First Refresh Time  :  05/26/2011 16:16:58
                                     Last Refresh Time   :  05/26/2011 16:18:29
                                     Duration            :  91s
                                     Module/Action       :  SQL*Plus/-
                                     Service             :  SYS$USERS
                                     Program             :  sqlplus@zulu.us.oracle.com (TNS V1-V3)
                                     Fetch Calls         :  2
                                    
                                    Global Stats
                                    =================================================
                                    | Elapsed |   Cpu   |  Other   | Fetch | Buffer |
                                    | Time(s) | Time(s) | Waits(s) | Calls |  Gets  |
                                    =================================================
                                    |      91 |      91 |     0.02 |     2 |      3 |
                                    =================================================
                                    
                                    SQL Plan Monitoring Details (Plan Hash Value=2188347805)
                                    =====================================================================================================================================
                                    | Id |       Operation       |  Name  |  Rows   | Cost |   Time    | Start  | Execs |   Rows   |  Mem  | Activity | Activity Detail |
                                    |    |                       |        | (Estim) |      | Active(s) | Active |       | (Actual) | (Max) |   (%)    |   (# samples)   |
                                    =====================================================================================================================================
                                    |  0 | SELECT STATEMENT      |        |         |      |         1 |    +91 |     1 |        1 |       |          |                 |
                                    |  1 |   PARTITION RANGE ALL |        |       1 |    8 |         1 |    +91 |     1 |        1 |       |          |                 |
                                    |  2 |    HASH GROUP BY      |        |       1 |    8 |        91 |     +1 |  100K |        1 |    2M |   100.00 | Cpu (91)        |
                                    |  3 |     TABLE ACCESS FULL | T_P1_1 |       1 |    7 |         1 |    +91 |  100K |        1 |       |          |                 |
                                    =====================================================================================================================================
                                    
                                    
                                    Elapsed: 00:00:00.05
                                    SQL> 
                                    SQL> select /*+ monitor */ id, count(*) from t_p1_100000 group by id;
                                    
                                                 ID        COUNT(*)
                                    --------------- ---------------
                                             100000               1
                                    
                                    Elapsed: 00:00:00.01
                                    SQL> select DBMS_SQLTUNE.REPORT_SQL_MONITOR(session_id=>sys_context('userenv','sid'), report_level=>'ALL') as report from dual;
                                    
                                    REPORT
                                    --------------------------------------------------------------------------------------------------------------------------------------------
                                    SQL Monitoring Report
                                    
                                    SQL Text
                                    ------------------------------
                                    select /*+ monitor */ id, count(*) from t_p1_100000 group by id
                                    
                                    Global Information
                                    ------------------------------
                                     Status              :  DONE (ALL ROWS)
                                     Instance ID         :  1
                                     Session             :  GRAHN (386:147)
                                     SQL ID              :  a0p5z9k14fdug
                                     SQL Execution ID    :  16777227
                                     Execution Started   :  05/26/2011 16:18:29
                                     First Refresh Time  :  05/26/2011 16:18:29
                                     Last Refresh Time   :  05/26/2011 16:18:29
                                     Duration            :  .001s
                                     Module/Action       :  SQL*Plus/-
                                     Service             :  SYS$USERS
                                     Program             :  sqlplus@zulu.us.oracle.com (TNS V1-V3)
                                     Fetch Calls         :  2
                                    
                                    Global Stats
                                    ======================================
                                    | Elapsed |   Cpu   | Fetch | Buffer |
                                    | Time(s) | Time(s) | Calls |  Gets  |
                                    ======================================
                                    |    0.00 |    0.00 |     2 |      3 |
                                    ======================================
                                    
                                    SQL Plan Monitoring Details (Plan Hash Value=3239926216)
                                    ==========================================================================================================================================
                                    | Id |       Operation       |    Name     |  Rows   | Cost |   Time    | Start  | Execs |   Rows   |  Mem  | Activity | Activity Detail |
                                    |    |                       |             | (Estim) |      | Active(s) | Active |       | (Actual) | (Max) |   (%)    |   (# samples)   |
                                    ==========================================================================================================================================
                                    |  0 | SELECT STATEMENT      |             |         |      |         1 |     +0 |     1 |        1 |       |          |                 |
                                    |  1 |   PARTITION RANGE ALL |             |       1 |    8 |         1 |     +0 |     1 |        1 |       |          |                 |
                                    |  2 |    HASH GROUP BY      |             |       1 |    8 |         1 |     +0 |     2 |        1 |    2M |          |                 |
                                    |  3 |     TABLE ACCESS FULL | T_P1_100000 |       1 |    7 |         1 |     +0 |     2 |        1 |       |          |                 |
                                    ==========================================================================================================================================
                                    
                                    
                                    Elapsed: 00:00:00.03
                                    SQL> 
                                    SQL> alter session set "_gby_hash_aggregation_enabled"=false;
                                    
                                    Session altered.
                                    
                                    Elapsed: 00:00:00.00
                                    SQL> select /*+ monitor */ id, count(*) from t_p1_1 group by id;
                                    
                                                 ID        COUNT(*)
                                    --------------- ---------------
                                             100000               1
                                    
                                    Elapsed: 00:00:00.07
                                    SQL> select DBMS_SQLTUNE.REPORT_SQL_MONITOR(session_id=>sys_context('userenv','sid'), report_level=>'ALL') as report from dual;
                                    
                                    REPORT
                                    --------------------------------------------------------------------------------------------------------------------------------------------
                                    SQL Monitoring Report
                                    
                                    SQL Text
                                    ------------------------------
                                    select /*+ monitor */ id, count(*) from t_p1_1 group by id
                                    
                                    Global Information
                                    ------------------------------
                                     Status              :  DONE (ALL ROWS)
                                     Instance ID         :  1
                                     Session             :  GRAHN (386:147)
                                     SQL ID              :  1j9tzuf583cmb
                                     SQL Execution ID    :  16777234
                                     Execution Started   :  05/26/2011 16:18:29
                                     First Refresh Time  :  05/26/2011 16:18:29
                                     Last Refresh Time   :  05/26/2011 16:18:29
                                     Duration            :  .065336s
                                     Module/Action       :  SQL*Plus/-
                                     Service             :  SYS$USERS
                                     Program             :  sqlplus@zulu.us.oracle.com (TNS V1-V3)
                                     Fetch Calls         :  2
                                    
                                    Global Stats
                                    =================================================
                                    | Elapsed |   Cpu   |  Other   | Fetch | Buffer |
                                    | Time(s) | Time(s) | Waits(s) | Calls |  Gets  |
                                    =================================================
                                    |    0.07 |    0.06 |     0.00 |     2 |      3 |
                                    =================================================
                                    
                                    SQL Plan Monitoring Details (Plan Hash Value=1576175585)
                                    =====================================================================================================================================
                                    | Id |       Operation       |  Name  |  Rows   | Cost |   Time    | Start  | Execs |   Rows   |  Mem  | Activity | Activity Detail |
                                    |    |                       |        | (Estim) |      | Active(s) | Active |       | (Actual) | (Max) |   (%)    |   (# samples)   |
                                    =====================================================================================================================================
                                    |  0 | SELECT STATEMENT      |        |         |      |         1 |     +0 |     1 |        1 |       |          |                 |
                                    |  1 |   PARTITION RANGE ALL |        |       1 |    8 |         1 |     +0 |     1 |        1 |       |          |                 |
                                    |  2 |    SORT GROUP BY      |        |       1 |    8 |         1 |     +0 |  100K |        1 |  2048 |          |                 |
                                    |  3 |     TABLE ACCESS FULL | T_P1_1 |       1 |    7 |         1 |     +0 |  100K |        1 |       |          |                 |
                                    =====================================================================================================================================
                                    
                                    
                                    Elapsed: 00:00:00.04
                                    --
                                    Regards,
                                    Greg Rahn
                                    http://structureddata.org
                                    1 2 Previous Next