Datapump - Export très lent - Streams AQ : enqueue blocked on low memory

Hello !

Et oui, toujours vivant... alors certes pas très actif depuis quelques mois, mais lami-dba revient avec un petit article sympa... Du moins, j'espère qu'il vous sera aussi sympathique que ce problème m'a fait chauffer le cerveau ou ce qu'il en reste...

Tout d'abord posons le contexte...  Un Rac (Standard Edition) en 12.2, et un export quotidien utile au client pour des raisons de refresh internes. Disons le tout de suite, ce problème, je l'ai déjà eu hors RAC.

OK,Mais quel est donc ce problème....

Tout simplement la durée de l'export est anormalement longue... pas loin de 4 heures pour générer un dump de 130GO. Pour avoir travaillé sur quelques bases bien plus volumineuse, que ce soit en données ou en nombre d'objets, cela ne peut et ne doit pas justifier cette durée... surtout qu'en observant un peu ce qu'il se passe durant l'export on se rend compte que même exporter des tables quasi vide prends 2-3 secondes... alors forcement vu le nombre de tables... on en arrive à ces problématiques.

Mine de rien, une fois qu'on a accepter qu'il y avait un problème, nous avons fait un grand pas. Why ? Because, quand on sait qu'il y a un problème, et bien on se doute qu'il y doit y avoir une solution...

Une fois qu'on a dit cela.. on fait quoi... Car le log d'un export, même si en 12c on peut avoir quelques informations supplémentaires, c'est pas avec cela qu'on va trouver quelque chose.

Cela devrait être un réflexe, et à chaque fois qu'on a besoin d'informations, le meilleur moyen d'en avoir est de demander à Oracle d'avoir la gentillesse de nous donner un peu plus d'infos...

Je décide donc de générer un peu plus de trace durant l'export, et je décide de le faire une fois que les grosses tables sont exportées... et que mon ennemi du jour datapump prends un temps énorme sur des petites tables.

Lets go !

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

System altered.

Histoire de ne pas pourrir mon serveur de fichier trace, je vais stopper mes traces au bout de 5-6 minutes en espérant que cela m'apportera quelque chose.

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

System altered.

Alors c'est bien d'avoir des fichiers de trace... mais comment savoir ceux qui sont liés à mon export qui continue de prendre son temps...

A savoir que lorsque l'on lance un export via datapump deux processus vont se mettre en action. 

dm00 => Master Process
dw00 => Worker Process

Et le fichiers de trace seront donc de type ORACLE_SID_dm00_xxxx.trc et ORACLE_SID_dw00_xxxx.trc

histoire de rendre ces traces utilisables, nous allons faire appel à notre ami tkprof ;)

tkprof LAO_dw00_30831.trc sort_dw00.out waits=y sort=exeela 
tkprof LAO_dw00_9391.trc sort_dw00.out waits=y sort=exeela 

Ce mystère qui agace tout le monde va t-il lever son voile... jetons un coup d’œil aux deux fichiers générés par tkprof.

pour dm00

et pour dw00

Il y a d'autres informations dans les fichiers de trace, mais je vais m’arrêter à ces informations.. car lorsqu'on voit dans les deux cas l'écart entre le temps cpu (deux dixièmes) & le elapsed time..(pas loin de 5 minutes), on comprend mieux pourquoi c'est lent !
Et dans les deux cas, on peut voir que les attentes sont de type Streams AQ : enqueue blocked on low memory. 

Nous n'avons pas forcement la solution à notre problème, mais on au moins on sait ou chercher...et ca finalement c'est le début du chemin vers la résolution.

La première idée qui me vient est de vérifier la répartition des zones mémoires et d'ajuster la zone "streams pool"

SQL> select component,current_size/1024/1024 as MB from v$sga_dynamic_components where current_size !=0 order by 1;
COMPONENT                              MB
------------------------------ ----------
DEFAULT buffer cache                 7584
Shared IO Pool                        512
java pool                              96
large pool                            160
shared pool                          7968
streams pool                           32

6 rows selected.

Soyons fous...

SQL> alter system set streams_pool_size=300m scope=memory sid='LAO1';

System altered.

Nouvelle répartition :

SQL> select component,current_size/1024/1024 as MB from v$sga_dynamic_components where current_size !=0 order by 1;

COMPONENT                              MB
------------------------------ ----------
DEFAULT buffer cache                 7296
Shared IO Pool                        512
java pool                              96
large pool                            160
shared pool                          7968
streams pool                          320

Stop au suspens... j'avoue que j'étais assez content de moi et pensais que l'affaire était dans le sac... et bien non.. malgré la modification, aucun gain, et les traces montraient toujours des attentes de type Streams AQ : enqueue blocked on low memory. 

Mais comme je mentionnais plus haut, lorsqu'on connait la source du problème, tout devient plus simple, une recherche rapide sur votre moteur de recherche préféré ou sur le support Oracle, on va normalement rapidement tomber sur la note Doc ID 2386566.1 qui va nous guider vers l'ivresse de la réussite.

JE donne également un lien vers un blog (pour ceux qui n'auraient pas d'accès à Oracle Support).

https://blogs.dbcloudsvc.com/oracle/expdp-and-event-streams-aq-enqueue-blocked-on-low-memory/

En lisant, ces notes, je vérifie si je suis bien dans ce contexte en lançant plusieurs fois la requête suivante.

SQL> select shrink_phase_knlasg from X$KNLASG;
SHRINK_PHASE_KNLASG
-------------------
1  

Bingo..... Un restart de la db pourrait peut être solutionner le problème... mais évidemment la production ne permet pas de faire ce genre de choses comme cela.. je vais donc appliquer le workaround proposé par la note Oracle.

connect / as sysdba
alter system set events 'immediate trace name mman_create_def_request level 6';

Et une petite vérification..

SQL> select shrink_phase_knlasg from X$KNLASG;
SHRINK_PHASE_KNLASG
-------------------
0

Je savourai à peine ce que je voyais que je ne me suis même pas rendu compte qu'une fois le "alter system" passé, l'export a soudainement accéléré (en fait a retrouvé sa vitesse normale) et s'est terminé très rapidement.

Un test rapide derrière a permis de confirmer que l'export s’exécutait maintenant en 30 minutes au lieu de 4 heures...

Remarque 1 : dans mon cas, le "alter system set events 'immediate trace name mman_create_def_request level 6';" a pris facilement quelques dizaines de seconde.. So, don't panic... just wait and enjoy ;)

Remarque 2 : La note Oracle indique l'existence d'un patch ( Patch 27634991 ) pour éviter que le soucis ne se reproduise.

Enjoy !