Performance von Analytics

Tom Kyte pflegt zu sagen: "Analytics rock Analytics roll" - und damit hat er völlig recht, da man mit Hilfe analytischer Funktionen ganz erstaunliche Dinge machen kann. Dass Analytics bei großen Sortierungen auch Ärger machen können, hat Jonathan Lewis vor einiger Zeit gezeigt (einen Link dazu findet man auch schon an anderer Stelle hier im Blog). Heute habe ich ein Beispiel gesehen, in dem eine CTAS-Operation auf Basis einer einzelnen Tabelle, die ohne Analytics < 10 sec. lief, nach dem Einbau von vier Kennzahlen mit Analytics ca. 3 min benötigte. Dass das nicht nur an der Menge der zu sortierenden Daten liegen kann, wird deutlich, wenn man die Operation als Join der Basistabelle an gruppierte Zwischenergebnisse umformuliert - dadurch sinkt die Laufzeit im gegebenen Fall unter 2 min.

Den Fall habe ich zum Anlaß genommen, einen kleinen Test zu basteln - bei dem ich aber nicht allzu tief in die Details absteigen wollte:

• Version: 11.1.0.7
• Blockgröße: 16 K
• Noarchivelog
• ASSM

-- Anlage einer Testtabelle, die etwa der Struktur des beobachteten Falls entspricht
create table test_analytics
as
select t1.*
     , t2.col_day_of_month
     , round(dbms_random.value(10, 1000)) val1
     , round(dbms_random.value(10, 1000)) val2
  from (select level col1
             , round(dbms_random.value(1, 40)) col2
             , round(dbms_random.value(1, 40)) col3
             , round(dbms_random.value(1, 10000)) col4
          from dual
       connect by level <= 100000) t1
     , (select level col_day_of_month
          from dual
       connect by level <= 31) t2;

Im Rahmen des Tests wurde dann folgendes Script ausgeführt, in dem jeweils ein paar Parametrisierungen angepasst wurden:

-- Parameter ... 
exec DBMS_MONITOR.SESSION_TRACE_ENABLE()

drop table test_analytics_0;
create table test_analytics_0
as
select col1
     , col2
     , col3
     , col4
     , col_day_of_month
  -- , median (val1) over ( partition by col1 ) median_val1
     , val1
  from test_analytics;

drop table test_analytics_1;
create table test_analytics_1
as
select col1
     , col2
     , col3
     , col4
     , col_day_of_month
     , median (val1) over ( partition by col1 ) median_val1
     , val1
  from test_analytics;

drop table test_analytics_2;
create table test_analytics_2
as
select col1 
     , col2
     , col3
     , col4
     , col_day_of_month
     , median (val1) over ( partition by col1 ) median_val1
     , median (val2) over ( partition by col1 ) median_val2
     , val1
  from test_analytics;
  
exec DBMS_MONITOR.SESSION_TRACE_DISABLE()

exit

Geprüft wurden folgende Varianten:

• Standardverhalten (ohne weitere Parametrisierung)
• manuelle Setzung von SORT_AREA%_SIZE-Parameter +_sort_multiblock_read_count = 16
• Setzung von _newsort_enabled=false

Heraus kam dabei Folgendes:

1. Standard:

• Laufzeit/Gesamt: 56.96
• Laufzeit/test_analytics_0: 3.10 sec
• Laufzeit/test_analytics_1: 18.82 sec
• Laufzeit/test_analytics_2: 34.90 sec

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       14      0.01       0.02          0          3          0           0
Execute     15     52.43      56.94      62757      20289      27016     9300009
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       29     52.44      56.96      62757      20292      27016     9300009

Misses in library cache during parse: 7

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      14        0.00          0.00
  SQL*Net message from client                    14        0.00          0.00
  reliable message                                3        0.00          0.00
  log file sync                                   4        0.00          0.00
  db file sequential read                       272        0.00          0.00
  db file scattered read                        393        0.00          0.40
  control file sequential read                   15        0.00          0.00
  direct path write                            1243        0.03          1.81
  direct path sync                                5        0.29          0.77
  enq: RO - fast object reuse                     2        0.03          0.06
  direct path write temp                       3259        0.02          3.79
  direct path read temp                       86146        0.00          1.33

Das unformatierte Trace-File enthält sehr viele WAIT-Angaben direct path read temp mit cnt=1, was mich an die hier beobachteten Effekte erinnert.

2. manuelles PGA-Management

alter session set WORKAREA_SIZE_POLICY=Manual;
alter session set sort_area_size = 500000000;
alter session set sort_area_retained_size = 500000000;
-- zur Sicherheit doppelt 
alter session set sort_area_size = 500000000;
alter session set sort_area_retained_size = 500000000;
alter session set "_sort_multiblock_read_count" = 16;

• Laufzeit/Gesamt: 34.77 sec
• Laufzeit/test_analytics_0: 3.06 sec
  
• Laufzeit/test_analytics_1: 12.14 sec
  
• Laufzeit/test_analytics_2: 19.51 sec

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       14      0.00       0.00          0          3          0           0
Execute     15     32.93      34.77      19132      20289      26962     9300009
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       29     32.94      34.77      19132      20292      26962     9300009

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

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      14        0.00          0.00
  SQL*Net message from client                    14        0.00          0.00
  db file sequential read                       216        0.00          0.00
  db file scattered read                        388        0.00          0.40
  control file sequential read                   15        0.00          0.00
  direct path write                            1252        0.01          1.72
  direct path sync                                3        0.29          0.76
  log file sync                                   4        0.03          0.07
  enq: RO - fast object reuse                     1        0.00          0.00

Auffällig ist zunächst, dass das raw trace file < 1 MB ist, im Fall 1 aber ca. 11 MB umfasste. Darüber hinaus spart sich diese Variante die ganzen direct path read temp/direct path write temp Waits.

3. _newsort_enabled auf false

alter session set "_newsort_enabled" =false;

• Laufzeit/Gesamt: 56.69 sec
  
• Laufzeit/test_analytics_0: 3.10 sec
  
• Laufzeit/test_analytics_1: 18.65 sec
  
• Laufzeit/test_analytics_2: 34.78 sec

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       14      0.00       0.00          0          3          0           0
Execute     15     52.32      56.69      62211      20291      27036     9300009
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       29     52.32      56.69      62211      20294      27036     9300009

Misses in library cache during parse: 6

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      14        0.00          0.00
  SQL*Net message from client                    14        0.00          0.00
  reliable message                                1        0.00          0.00
  enq: RO - fast object reuse                     3        0.03          0.07
  log file sync                                   5        0.00          0.00
  db file sequential read                       336        0.00          0.01
  db file scattered read                        354        0.02          0.40
  control file sequential read                   15        0.00          0.00
  direct path write                            1254        0.02          1.69
  direct path sync                                5        0.29          0.77
  direct path write temp                       3219        0.02          3.76
  direct path read temp                       86146        0.00          1.31

Erinnert sehr stark an Fall 1.

Aus Zeitgründen nur ein ganz kurzes Fazit:

• manuelles PGA-Management beschleunigt die Operation deutlich (ist aber für Parallelisierung wohl eher ungeeignet, da ja jede workarea-Operation auf die mit sort_area_size gesetzten Speichermenge zugreifen darf)
• die Beschleunigung ergibt sich offenbar daraus, dass die Sortierung im Speicher erfolgen kann, wie das Fehlen der write/read temp Waits andeutet (und der deutliche Unterschied bei den disk reads)
• _newsort_enabled scheint gegenüber dem Standard keinen Unterschied zu bringen. Zu prüfen wäre noch, wie der Parameter in der Instanz gesetzt ist
• ich kann mich nicht mehr erinnern, ob die WAIT-Angaben direct path read temp mit cnt=1 ein Problem sind (d.h., ob hier größere Blöcke erscheinen sollten)
• beim manuellen PGA-Management muss man darauf achten, die ALTER SESSION-Kommandos doppelt abzusetzen, da das System den Hinweis sonst nicht ernst nimmt... (ich falle darauf regelmäßig rein)

Gelegentlich vielleicht mehr dazu...

Nachtrag 30.01.2011: die direct path read temp mit cnt=1 gehören vermutlich in den Kontext von Bug 9041800 - Window function operation using IO inefficiently [ID 9041800.8]: "If an operation involving a sort shows poor IO throughput or spends a lot of time doing reads from the temp tablespace, you may be encountering this problem." Dort wird empfohlen ein 10032er Trace zu erstellen, was ich vielleicht auch noch machen werde.