lundi 28 septembre 2015

Calcul de statistiques et mode concurrent


Beaucoup d’entre vous utilisent surement le paramètre DEGREE dans les procédures du package DBMS_STATS afin de paralléliser leur traitement de calcul de statistiques. Mais ce que beaucoup ignorent c’est que le parallélisme ne se fait qu’au niveau du segment. Il ne peut y avoir un calcul de statistiques sur plusieurs segments à la fois. Donc, le parallélisme appliqué au calcul de statistiques n’est intéressant que lorsqu’on a affaire à de très grosses tables. Heureusement, depuis la 11.2.0.2 il est possible d’avoir un calcul de statistiques pouvant s’effectuer sur plusieurs tables et partitions en même temps, c’est ce qu’on appelle le mode CONCURRENT. Ce mode permet d’accélérer formidablement le calcul de statistiques en profitant pleinement des ressources de la machine d’autant plus qu’on peut le combiner avec le mode parallel.

J’ai récemment pu améliorer le temps de calcul de statistiques d’une des bases de mon client grâce au mode concurrent. Pour se rendre compte de l’amélioration apportée voyons d’abord ce que donne le calcul de statistiques effectué sans le mode concurrent sur un schéma de 800GB et dont les plus grosses tables font plusieurs dizaine de GB.

Test du calcul de stats séquentiel :

     
SQL> select sum(bytes)/1024/1024/1024 from dba_segments where owner='SCHEMA1';

SUM(BYTES)/1024/1024/1024

-------------------------

               801,098389

exec dbms_stats.gather_schema_stats(ownname => 'SCHEMA1', method_opt => 'for all columns size 1');

PL/SQL procedure successfully completed.

Elapsed: 12:55:42.16
Le calcul de statistiques sur le schéma a mis un peu de moins de 13 heures.

Pendant que le calcul de statistiques tournait j’ai lancé plusieurs requêtes à des moments différents pour voir les sessions actives sur ma base et on constate bien que le calcul de statistiques se faisait en mode séquentiel car seule une session était en train de travailler:
SQL> @sql_cur_stmt

  SID    SERIAL# PROG       ADDRESS          HASH_VALUE SQL_ID         CHILD PLAN_HASH_VALUE      EXECS   AVG_ETIME EVENT                SQL_TEXT

----- ---------- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------

    2      45373 sqlplus.ex 0000002D356943A8 3121805777 85j1xbkx15yfj      0       226853730          1      692.32 db file sequential r select /*+  no_parallel_index(t, "HISCRN1

Test du calcul de stats en parallel :


J’ai ensuite testé le calcul de stats en mode parallel avec un DEGREE de 16
exec dbms_stats.gather_schema_stats(ownname => 'SCHEMA1', degree=> 16, method_opt => 'for all columns size 1');

Elapsed: 11:15:20.68
Cette fois le calcul de statistiques a mis un peu plus de 11 heures. C’est mieux que le mode séquentiel mais ça reste néanmoins toujours trop long. Pendant que le calcul de statistiques en mode parallèle tournait j’ai également lancé quelques requêtes pour voir ce que j’avais dans mes sessions actives :
   SID    SERIAL# PROG       ADDRESS          HASH_VALUE SQL_ID         CHILD PLAN_HASH_VALUE      EXECS   AVG_ETIME EVENT                SQL_TEXT

----- ---------- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------

    5      12814 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

 1163      42516 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  235      40059 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  237      46728 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  314      18466 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  391      30356 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  468      20257 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  540      28533 sqlplus.ex 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 PX Deq: Execute Repl /* SQL Analyze(0) */ select /*+  full(t)

  547      15123 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  623      29688 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  702      62908 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  774      31336 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  852      17484 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  931       1917 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

 1005      45861 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

 1081      37925 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 db file scattered re /* SQL Analyze(0) */ select /*+  full(t)

  163      26835 oracle@eqd 0000002DDAA90A90 3664547584 9k9zph3d6t3s0      0      2617663258          1       50.30 ON CPU               /* SQL Analyze(0) */ select /*+  full(t)

On constate bien que le calcul de statistiques se faisait en parallèle puisque j’ai bien 16 sessions correspondant à mes process slaves et une session correspondant à ma session principale. On s’aperçoit également que bien que j’ai plusieurs sessions en parallèles elles travaillent toutes sur un seul objet qui est la table T. Cela rejoint donc ce que je disais en préambule de mon article : le mode parallel ne peut s’effectuer qu’au niveau segment et non pas sur plusieurs tables à la fois.


Test du calcul de stats en mode concurrent :

 

Pour utiliser le mode CONCURRENT il suffit de positionner le paramètre global CONCURRENT qui est désactivé par défaut (même en 12c). Le nombre de sessions concurrentes va dépendre de la valeur du paramètre job_queue_processes.

Voyons ce que le mode CONCURRENT donne pour mon schéma SCHEMA1 :
exec DBMS_STATS.SET_GLOBAL_PREFS('CONCURRENT','TRUE');

exec dbms_stats.gather_schema_stats(ownname => 'SCHEMA1', method_opt => 'for all columns size 1');

ORA-20000: Unable to gather statistics concurrently: Resource Manager is not enabled.

ORA-06512: at "SYS.DBMS_STATS", line 35980

ORA-06512: at line 1
Le message d’erreur m’indique qu’il n’y a pas de Resource Plan de défini, or pour que le calcul de statistiques se fasse en mode concurrent il faut que Ressource Manager puisse gérer les ressources consommées par chaque job. On peut soit définir son propre Resource Plan soit utiliser celui fourni par Oracle qui est le DEFAULT_PLAN :
ALTER SYSTEM SET RESOURCE_MANAGER_PLAN = default_plan;

exec DBMS_STATS.SET_GLOBAL_PREFS('CONCURRENT','TRUE');

exec dbms_stats.gather_schema_stats(ownname => 'SCHEMA1', method_opt => 'for all columns size 1');

PL/SQL procedure successfully completed.
 
Elapsed: 02:25:16.99
Cette fois ci le calcul de stats a pris 2h25 au lieu de 12h55 en mode séquentiel et 11h15 en mode parallèle. Le gain est énorme.

Voici ce qu’on pouvait voir dans V$SESSION pendant que les jobs concurrents tournaient :
SQL> @sql_cur_stmt
 

  SID    SERIAL# PROG       ADDRESS          HASH_VALUE SQL_ID         CHILD PLAN_HASH_VALUE      EXECS   AVG_ETIME EVENT                SQL_TEXT

----- ---------- ---------- ---------------- ---------- ------------- ------ --------------- ---------- ----------- -------------------- -----------------------------------------

  623       9359 oracle@eqd 0000002D32EF62F8 2948485349 3g5vrh6rvwn75      0       968244646          1       12.76 db file scattered re /* SQL Analyze(1) */ select /*+  full(t)

 1085      50128 oracle@eqd 0000002D3518A618 4209280689 4abxz8gxf91pj      1      1515091901          1      113.57 db file sequential r select /*+  no_parallel_index(t, "IHSPOS1

  701       8020 oracle@eqd 0000002CD975A2D8 3982881736 4qj5dp7qqbwy8      1      2053917943          1    1,079.45 db file sequential r select /*+  no_parallel_index(t, "IAVOPEI

   86      30708 oracle@eqd 0000002D148BDE88 1780980331 59p1yadp2g6mb      0               0         36         .02 Streams AQ: waiting  call DBMS_AQADM_SYS.REGISTER_DRIVER (  )

    2      45373 sqlplus.ex 0000002DFC7337D0 3466778119 8kruwyz7a5ph7      0               0          2   23,393.51 Streams AQ: waiting  BEGIN dbms_stats.gather_schema_stats(ownn

  930      47139 oracle@eqd 0000002E0DE75D10 2559624494 96u7bryc91j9f      1       614356722          1    1,905.43 db file sequential r select /*+  no_parallel_index(t, "HISMVC1

  548      12639 oracle@eqd 0000002CD8900280 1387000160 auv55cp9arwb0      1       981273022          1       65.32 db file sequential r select /*+  no_parallel_index(t, "ITPCRO9

  775      22196 oracle@eqd 0000002C7FC02950 2839555010 d92sd5qnn0ay2      1      3067632440          1       42.85 db file sequential r select /*+  no_parallel_index(t, "RTPSPR1

  773      32465 oracle@eqd 0000002CD3983ED0 1227027996 dh8dxq14k5xhw      0      3635621864          1      294.04 db file scattered re /* SQL Analyze(1) */ select /*+  full(t)

  317      19697 oracle@eqd 0000002C7E6227C0 2780047690 dtkjh72kv8aaa      0      3588248285          1         .01 db file scattered re /* SQL Analyze(1) */ select /*+  full(t)

  469      42289 oracle@eqd 0000002CDB8A0F60 1695986908 fzp1yupkjdd6w      1        43487272          1      862.32 db file sequential r select /*+  no_parallel_index(t, "AVICNF8

Comme le paramètre job_queue_processes est positionné à 10 j’ai uniquement 10 sessions concurrentes, et on s’aperçoit que contrairement au calcul de statistiques en parallèle chaque session travaille sur des tables différentes.

On peut penser qu’avec un paramètre job_queue_processes supérieur à 10 il aurait été possible d’obtenir un meilleur résultat.

Il est également possible de combiner le mode concurrent avec le calcul de statistiques en parallèle. Je l’ai testé pour mon schéma mais le gain n’est que de 2 minutes :
-- test calcul de stats concurrent+parallel

exec DBMS_STATS.SET_GLOBAL_PREFS('CONCURRENT','TRUE');

alter system set parallel_adaptive_multi_user=false;

exec dbms_stats.gather_schema_stats(ownname => 'SCHEMA1', degree=> 16, method_opt => 'for all columns size 1');

PL/SQL procedure successfully completed.

Elapsed: 02:23:41.27

jeudi 10 septembre 2015

Direct path reads et "enq KO – fast object checkpoint"


Bien que cet event commence par le mot « enq » il ne s’agit pas d’un enqueue au sens attente sur un lock. Je dis ça car récemment un développeur est venu me voir pour se plaindre de locks au niveau de sa base car il avait vu que certaines de ses requêtes étaient en attente sur cet event.

En réalité, si vous rencontrez cet event c’est que le moteur Oracle a choisi d’effectuer son full scan en utilisant du Direct Path Read et donc de bypasser le buffer cache en lisant les blocks directement depuis les datafiles. Cet event se déclenche si, parmi les blocs à lire, certains sont dirty (blocs modifiés dans le buffer cache mais pas encore envoyés par le processus DB Writer dans le disque). Pour avoir une lecture consistante un checkpoint doit être effectué pour mettre à jour les dirty blocs de la table à lire au niveau du disque. Pendant cette opération le process server en charge du direct path read attend sur l’event « enq KO – fast object checkpoint ».

Un exemple valant mieux qu’un long discours je me suis amusé à faire le petit test suivant sur ma base 12.1.0.2:
SQL>  create table T1 as select * from dba_objects;

Table created.

SQL> update T1 set created=sysdate where owner<>'SYS';

784976 rows updated.
Dans une session 1 j’ai créé une table T1 puis j’ai lancé un update de 78976 lignes pour avoir des dirty blocs dans le buffer cache.

La requête ci-dessous nous indique qu’on a 16 925 blocks qui sont dirty :
SQL> SELECT count(*)
  2  FROM v$bh b, dba_objects o
  3  WHERE b.objd = o.data_object_id and o.object_name='T1' and dirty='Y';
 

  COUNT(*)
----------
     16925
Dans une autre session je fais un count de la table en forçant le moteur SQL à choisir un Direct Path read en jouant sur le paramètre caché _serial_direct_read :
-- session 2
SQL> alter session set "_serial_direct_read"=always; 

Session altered. 

SQL> @10046.sql

SQL> set echo on feed on

SQL> ALTER SESSION SET  max_dump_file_size = UNLIMITED; 

Session altered. 

SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER = 'ahmed_10046_sql_trace'; 

Session altered.

SQL> -- enables SQL trace at level 12 for the session executing it.

SQL> ALTER SESSION SET events '10046 trace name context forever, level 12'; 

Session altered.

SQL> select count(*) from T1;

  COUNT(*)
----------
     1465568  

SQL> @dis_10046.sql

SQL> set echo on feed on

SQL> -- disables SQL trace for the session executing it.

SQL> ALTER SESSION SET events '10046 trace name context off';

Session altered.

J’ai préalablement activé une trace 10046 level 12 pour capturer les wait event et voici un extrait de la trace :
WAIT #427376872: nam='enq: KO - fast object checkpoint' ela= 769931 name|mode=1263468550 2=65568 0=1 obj#=-1 tim=131292719765

WAIT #427376872: nam='Disk file operations I/O' ela= 10331 FileOperation=2 fileno=1 filetype=2 obj#=104369 tim=131292730309

WAIT #427376872: nam='direct path read' ela= 3831 file number=1 first dba=99529 block cnt=55 obj#=104369 tim=131292734495

WAIT #427376872: nam='direct path read' ela= 903 file number=1 first dba=102528 block cnt=72 obj#=104369 tim=131292737068

WAIT #427376872: nam='direct path read' ela= 2035 file number=1 first dba=102656 block cnt=128 obj#=104369 tim=131292741080

WAIT #427376872: nam='direct path read' ela= 716 file number=1 first dba=102784 block cnt=128 obj#=104369 tim=131292745168

Jetez un oeil à la première ligne: avant de voir les wait events correspondant à l’accès disque en direct path on voit que le process server a attendu 0.76 seconde sur l’event « enq: KO - fast object checkpoint » car il a fallu que le process DB writer flush les dirty blocks de la table sur disque avant qu'il puisse faire ses direct I/Os.

D’ailleurs lorsque j'interroge de nouveau la vue v$bh je constate qu’il n’existe plus de dirty blocks en mémoire pour la table T1 :
SQL> SELECT count(*)
  2  FROM v$bh b, dba_objects o
  3  WHERE b.objd = o.data_object_id and o.object_name='T1' and dirty='Y'; 

  COUNT(*)
----------
         0
Par contre on a toujours des dirty blocks appartenant à d’autres segments que ma table T1 cela prouve que le checkpoint engendré par le direct path read n’est pas globale au buffer cache mais local aux blocs de la table requête (ce qui est plutôt rassurant pour la performance des requêtes en direct path reads, je pense notamment à l'exadata):
SQL> SELECT count(*)
  2  FROM v$bh b, dba_objects o
  3  WHERE b.objd = o.data_object_id and o.object_name<>'T1' and dirty='Y'; 

  COUNT(*)
----------
         37