Vos instances redémarrent fréquemment et aléatoirement?
Vos sessions s’entassent et vos ressources semblent inaccessibles?
De plus, rien dans les logs, rien chez Oracle et pas de problème d’interconnect ?
N’évitez plus le bureau de votre DSI ! Nous avons peut être une solution …

LES MOT(S) CLEF(S) A RETENIR :

Dynamic Remastering | gc remaster wait event | ORA-56710 : DBRM process died unexpectedly

ENVIRONNEMENT(S) :

Tout système d’exploitation.
RAC en 11G.

SYMPTÔME(S) :

• Reboot d’instance. Aucune information explicative dans les logs. Fréquent et aléatoire.

Alert.log :
ORA-56710: DBRM process died unexpectedly
MON (ospid: 27121): terminating the instance due to error 56710
Instance terminated by PMON, pid = ####
USER (test : ####): terminating the instance
Instance terminated by USER, pid = ####
Starting ORACLE instance (normal)

=> ORA-56710 : DBRM process died unexpectedly ?
Cause : An explicit kill or internal error caused the death of the DBRM background process.
Action : Restart the instance

=> DBRM ?
DBRM = DataBase Resource Manager
The main goal of DBRM is to give the ODB server more control over resource management decision

• Ralentissement significatif de l’activité perçue côté client. Fréquent et aléatoire.
• Pics de sessions en attentes de réponse. Fréquent et aléatoire.
• Un nombre importants d’attentes de type « gc remaster » wait event.

NOTE(S) :

• My Oracle Support ne référence pas de correctif sur des symptômes identiques.
• Quelques bugs très semblables sont référencés mais aucun correctif n’est disponible.

PROBLEME(S) :

CADRE :

1 tablespace (objet logique) = 1- à N datafiles .dbf (ressources physiques) = X data block (emplacement physique de l’information). En environnent standard, quand une session souhaite interagir avec un objet, l’instance qui l’accueille se connecte à la base puis trouve et accède aux X data block liés à cet objet. Chaque data block (Data Base Ressource) est référencé et géré (mastered) par l’instance vie l’intermédiaire d’un « fichier de référencement » (hash table).
En environnement RAC (plusieurs instances), la maitrise des ressources est répartie entre les différentes instances. Chaque instance détient un « fichier de référencement » (hash-to-node table), mais ne maîtrise qu’une partie des ressources. Aussi, lorsque une session souhaite interagir avec un objet dont les ressources ne son pas maitrisées par son instance hôte, l’instance hôte demande (client-serveur) les informations (data block) à l’instance qui maîtrise ces ressources. Un re-référencement (ReMastering) des ressources listées en hash s’effectue en cas d’évènements particuliers (arrêt d’un nœud, arrêt d’instance, etc…).
En environnent RAC 11G, il existe une configuration cachée (shadow) et activée par défaut : DRM (Dynamic ReMastering). Cette option autorise le DRM des hash table pour répondre à un besoin de performance : confier la maitrise des ressources aux instances qui s’en servent le plus (voir configuration).

CAUSE(S) :

Durant un remastering des hash table, les ressources de la base ne sont plus référencées et sont donc inaccessibles (gc remaster wait event). Donc selon l’usage (métier) de la base et la configuration du DRM, l’on peut très vite avoir des DRM, et cela en plein pic d’activité. Résultat implicite de ce fonctionnement : Accès impossible aux ressources => Ralentissement massif, et éventuellement « crash ».

INVESTIGATION(S) :

Prenons le symptôme suivant : « crash » de l’instance1 noeud1 à 19h47.

- Extrait du rapport ASH noeud2 instance2 :
Slot Time  Count Event Count % Event
-------------------- -------- -----------------
19:35:00 115 library cache lock 29 0.39    : état normal.
CPU + Wait for CPU 27 0.36
db file sequential read 21 0.28
19:40:00 2,627 gc remaster 2,498 33.45     => état anormal
enq: TX - row lock contention 38 0.51
CPU + Wait for CPU 20 0.27
19:45:00  4,085 gc remaster 1,728 23.14     => état anormal : à 19h47 l'instance2 "kill" l'instance1
DFS lock handle 790 10.58
cursor: pin S wait on X 596 7.98
19:50:00  202 CPU + Wait for CPU 48 0.64    : état normal.
direct path read 41 0.55
rdbms ipc reply 29 0.39

=> Aucune information explicative dans les logs de l’instance1 noeud1. Une analyse ASH (Automated Session History) sur le noeud2 instance2 montre qu’un remastering (ici un DRM) a débuté dans les 5-10 minutes qui précédent le « crash » de l’instance1 noeud1.
Voici une requête utilisée pour identifier l’objet pour lequel le remastering a duré longtemps.
– Trace :
(Ouvrir la trace lmd0 adéquate et noter le PKEY de l’objet sujet du DRM)

Begin DRM(17) (swin 0) - AFFINITY transfer pkey 0001 to 1 oscan 0.0
...
2011-02-01 11:56:51.827771 :
* End DRM for pkey remastering request(s) (locally requested)

– Requête :

select * from dba_objects where data_object_id = '0001'

( l’objet est identifié par le PKEY « 0001 » dans le fichier de trace lmd « *lmd0*.trc »)
– Résultat :
0001 – TEST
=> L’objet TEST est une table très utilisée au quotidien par les deux instances.
Voici une requête utilisée pour identifier les moments ayant généré beaucoup de ‘gc remaster’ wait event dans les derniers jours (ou l’intervalle de rétention d’AWR).
– Requête :

alter session set nls_date_format='DD/MM/YYYY HH24:MI:SS';
set lines 120
set pages 1000
col snap_id format 999999
col BEGIN_INTERVAL_TIME format a25
col instance_number format 999
col dbid format 999999999999999
col STARTUP_TIME format a25
col cnt format 9999999
select sn.snap_id, sn.BEGIN_INTERVAL_TIME, sn.instance_number, sn.dbid, sn.STARTUP_TIME, count(*) cnt
from dba_hist_active_sess_history ash, dba_hist_snapshot sn
where ash.event like '%gc remaster%'
and sn.instance_number=ash.instance_number
and sn.snap_id=ash.snap_id
and sn.dbid=ash.dbid
group by sn.snap_id, sn.BEGIN_INTERVAL_TIME, sn.instance_number, sn.dbid, sn.STARTUP_TIME
having count(*) > 15
order by sn.BEGIN_INTERVAL_TIME;

=> having count(*) > 15 => 15 ayant été défini comme un seuil au regard du même « select » sans le « having count ».
– Résultat :

SNAP_ID BEGIN_INTERVAL_TIME INSTANCE_NUMBER STARTUP_TIME CNT
38544 05-JAN-11 04.00.15.809 PM 1 28-DEC-10 04.15.03.000 PM 35
39003 24-JAN-11 07.00.14.031 PM 2 28-DEC-10 07.13.58.000 PM 4230
=> état anormal : gc remaster wait event à compter de 07:00
39003 24-JAN-11 07.47.52.000 PM 1 24-JAN-11 07.47.52.000 PM 3142
=> état anormal : à 07:47 "kill" de l'instance1 noeud1 par l'instance2 noeud2.
39025 25-JAN-11 05.00.01.192 PM 2 28-DEC-10 07.13.58.000 PM 66

SOLUTION(S) :

Attendu qu’il s’agit d’un problème de configuration et non d’un bug, aucune « solution » à proprement parler n’existe, malgré tout quelques pistes sont possibles :

Afficher les paramètres cachés :

– Requête :

select a.ksppinm name,
b.ksppstvl value,
b.ksppstdf deflt,
decode(a.ksppity, 1, ‘boolean’, 2, ‘string’, 3, ‘number’, 4, ‘file’, a.ksppity) type,
a.ksppdesc description
from sys.x$ksppi a,
sys.x$ksppcv b
where a.indx = b.indx
and a.ksppinm like ‘_%’ escape ‘’
order by name

Désactiver le DRM sur les objets. (Solution que nous vous conseillons de tester)

Sauvergarder votre SPFILE actuel avant modification.
Placer le paramètre « _gc_affinity_locking=FALSE  »
Stop-Start de votre base.

Désactiver le DRM. (Solution de dernier recours)

Sauvergarder votre SPFILE actuel avant modification.
Placer le paramètre « _affinity_on=FALSE  »
Stop-Start de votre base.
=== === === === ===
Après une phase d’essai sur serveur de test, nous avons désactivé le DRM sur objet en environnement de production (Linux HPUX 11 64 / RAC 11.1.0.7). Les reboot intempestifs des instances ont cessé net, les DRM à cause de l’usage de la table TEST par les instances également.
NB: un grand merci à Arkzoyd 🙂


= OraNewB =
.