Estudio de traza de un Deadlock

Hoy vamos a ver como obtener algo mas de información de una incidencia que probablemente tengamos a menudo.

Los deadlocks no implican mal funcionamiento de la base de datos

Lo primero que tenemos que tener muy claro es que un deadlock no es un mal funcionamiento de la base de datos, un deadlock (la traducción posiblemente sea interbloqueo) es una situación en la que dos o mas usuarios están esperando cada uno a un recurso bloqueado por el otro.
La manera en la que Oracle soluciona esta situación es rolling back una de las sentencias implicadas en el deadlock, al liberar uno de estos bloqueos la otra finaliza su solicitud.
Cuando esta situación ocurre, Oracle deja un fichero de traza en el $DIAG_DEST , que nos indica cuales eran los procesos y sentencias implicados. El análisis de esa traza es lo que vamos a mirar hoy.

Deadlock Graph

Seguramente el apartado mas importante de la traza sea el llamado «deadlock graph», estas dos líneas que parecen tan crípticas son las que mas información nos van a dar sobre el bloqueo.

Deadlock graph:
--------Blocker(s)------- --------Waiter(s)--------
Resource Name           process session_holds waits process session_holds waits
TX-000e001a-002dd880     65               414    X       24          9       X
TX-00090006-01e831ca     24                 9    X        65        414      X

Viendo el tipo de bloqueo en «resource_name» y los distintos waits podremos obtener el tipo de bloqueo que ha sido, para ello tenemos una tabla maestra en la nota de soporte How to Identify ORA-00060 Deadlock Types Using Deadlock Graphs in Trace (Doc ID 1507093.1).
En nuestro caso, por ejemplo,tendríamos según soporte un claro caso de bloqueo de aplicación.
Bloqueo TX X X

Información de la sesión

Otro apartado interesante es el de la información de la sesión. En este apartado nos indica de manera mas sencilla cuales son las sesiones implicadas y cuales son los objectos en los que hemos tenido el problema .
Mediante esta información podemos buscar los objetos por los que se han causado el interbloqueo

session 414: DID 0001-0041-000592FB session 9: DID 0001-0018-00004FD9 
session 9: DID 0001-0018-00004FD9 session 414: DID 0001-0041-000592FB
Rows waited on:
Session 414: obj - rowid = 001272E0 - AAExowAQAAAACF5AAUv (dictionary objn - 1209056, file - 1024, block - 8569, slot - 20)
Session 9:   obj - rowid = 001272E0 - AAExowAQAAAACMNAAJ  (dictionary objn - 1209056, file - 1024, block - 8973, slot - 9)

SQL implicado

Finalmente llegamos al apartado que puede ser mas clarificador de cara al equipo de desarrollo encargado de depurar el código.
Este tercer bloque nos amplia la información de las sesiones implicadas, contándonos esquema, terminal y las consultas implicadas en el deadlock

----- Information for the OTHER waiting sessions -----
Session 9:
sid: 9 ser: 37801 audsid: 206118217 user: 103/SCHEMA1    flags: (0x45) USR/- flags_idl: (0x1) BSY/////- flags2: (0x40009) //INC  pid: 24 O/S info: user: SYSTEM, term: SERVERTEST, ospid: 12260  image: ORACLE.EXE (SHAD)

client details:
O/S info: user: launcherusr, term: , ospid: 13041768  machine: client2 program: schema2@client2 (TNS V1-V3)  application name: schema2@client2 (TNS V1-V3), hash  alue=54028978

current SQL:
UPDATE SCOTT2.TIPO_COCHE  SET COLOR = :1, CILINDRADA = :2 WHERE MATRICULA = :3 AND ANCHO = :4
----- End of information for the OTHER waiting sessions -----

Information for THIS session:
----- Current SQL Statement for this session (sql_id=8zqxt1a6d7ts1) -----
UPDATE SCOTT2.TIPO_COCHE SET TIPO = :1, PERSONA = :2 WHERE MATRICULA = :3 AND LARGO = :4

El fichero de traza es mucho mas amplio, pero, como habéis podido ver, mediante el estudio de la cabecera de la traza podemos recopilar mucha información para poder depurara el código de aplicación para que no vuelva a ocurrir

Como siempre, tenemos mas información en soporte, en las notas

  • Master Note for Database Error ORA-00060 «deadlock detected while waiting for resource» (Doc ID 1509919.1)
  • Master Note: Locks, Enqueues and Deadlocks (Doc ID 1392319.1)
  • How to Identify ORA-00060 Deadlock Types Using Deadlock Graphs in Trace (Doc ID 1507093.1)

Errores instalando Oracle 11 en la RedHat 7

Vamos a anotar rápidamente algunos errores que tenemos intentando instalar un Oracle 11.2.0.4 ( patch 13390677) en una RedHat 7.2

Repositorios adicionales

Lo primero con lo que vamos a encontrarnos es que uno de los paquetes que nos va a solicitar no está en el repositorio.
Captura

La solución a este problema es muy sencilla, y es el configurar un repositorio adicional.
Para ello ejecutaremos

yum install yum-utils.noarch
yum-config-manager --enable rhel-7-server-optional-rpms
yum install compat-libstdc++-33

Problemas en fase de linkado

errror_captura

Para esto hemos encontrado una nota (19692824 ) nos dice que es relativo a un bug y que lo ignoremos.
Para poder seguir con el relinkado podemos hacer


1.Editamos /u01/app/oracle/product/11.2.0/dbhome_1/sysman/lib/ins_emagent.mk
2. Cambiamos
OLD: $(MK_EMAGENT_NMECTL)
NEW: $(MK_EMAGENT_NMECTL) -lnnz11

Con estas dos pequeñas acciones podremos instalarlo sin mas problemas

Error «Update home dependency failed» desplegando agentes del oem12c

Tras un periodo demasiado largo sin publicar , vamos a ver la solución a un problema muy sencillo, pero que nos puede traer de cabeza.

Llevando a cabo la instalación del agente para unix (AIX 64) del Enterprise Manager12c, me he encontrado con el error

Update home dependency failed.

2016-05-13_09-42-17:INFO:Action description Ejecución del comando  /bin/sh -c '/applics/oem12c/agente_12c/ADATMP_2016-05-13_08-53-57-AM/agentDeploy.sh -ignorePrereqs ORACLE_HOSTNAME=servertarget.pamplona.name AGENT_BASE_DIR=/applics/oem12c/agente_12c OMS_HOST=ascoem.gseguros.com EM_UPLOAD_PORT=4904 AGENT_INSTANCE_HOME=/applics/oem12c/agente_12c/agent_inst b_doDiscovery=false b_startAgent=false b_forceInstCheck=true AGENT_PORT=3872'  en el host servertarget.pamplona.name
2016-05-13_09-42-17:INFO:Attempt :1 pty required false  with no inputs
2016-05-13_09-46-14:INFO:/bin/sh -c '/applics/oem12c/agente_12c/ADATMP_2016-05-13_08-53-57-AM/agentDeploy.sh -ignorePrereqs ORACLE_HOSTNAME=servertarget.pamplona.name AGENT_BASE_DIR=/applics/oem12c/agente_12c OMS_HOST=ascoem.gseguros.com EM_UPLOAD_PORT=4904 AGENT_INSTANCE_HOME=/applics/oem12c/agente_12c/agent_inst b_doDiscovery=false b_startAgent=false b_forceInstCheck=true AGENT_PORT=3872' execution failed on host servertarget.pamplona.name
2016-05-13_09-46-14:INFO:Pattern ERROR: found in file /u01/app/oracle/gc_inst/em/EMGC_OMS1/sysman/agentpush//2016-05-13_08-53-57-AM/logs/servertarget.pamplona.name/install.log Line ERROR: Update home dependency failed.
2016-05-13_09-46-14:INFO:Error Message found  Update home dependency failed.
2016-05-13_09-46-14:INFO: ACTION Ejecución del comando  /applics/oem12c/agente_12c/ADATMP_2016-05-13_08-53-57-AM/agentDeploy.sh -ignorePrereqs ORACLE_HOSTNAME=servertarget.pamplona.name AGENT_BASE_DIR=/applics/oem12c/agente_12c OMS_HOST=ascoem.gseguros.com EM_UPLOAD_PORT=4904 AGENT_INSTANCE_HOME=/applics/oem12c/agente_12c/agent_inst b_doDiscovery=false b_startAgent=false b_forceInstCheck=true AGENT_PORT=3872 en el host servertarget.pamplona.name
2016-05-13_09-46-14:INFO: OUT null
2016-05-13_09-46-14:INFO: ERR  Update home dependency failed.
2016-05-13_09-46-14:INFO: EXIT CODE1
2016-05-13_09-46-14:INFO:InvocationTargetException Exception
2016-05-13_09-46-14:INFO:Printing Exception :java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at oracle.sysman.core.agentpush.ui.deployer.BaseDeployerOps.executeActions(BaseDeployerOps.java:1862)
        at oracle.sysman.core.agentpush.ui.deployer.NewAgentDeployer.deploy(NewAgentDeployer.java:59)
        at oracle.sysman.core.agentpush.ui.deployfwk.DeploymentWorker.run(DeploymentWorker.java:26)
        at oracle.sysman.util.threadPoolManager.WorkerThread.run(Worker.java:311)
Caused by: CommandException: err:  Update home dependency failed.  out: null exitcode: 1
 stacktrace:
null
        at oracle.sysman.core.agentpush.ui.deployer.DeployerOps.executeCommandOnNodeInteractive(DeployerOps.java:1199)
        at oracle.sysman.core.agentpush.ui.deployer.DeployerOps.executeCommandOnNodeInteractive(DeployerOps.java:1045)
        at oracle.sysman.core.agentpush.ui.deployer.DeployerOps.executeCmdOnNode(DeployerOps.java:639)
        at oracle.sysman.core.agentpush.ui.deployer.DeployerOps.executeCmdOnNode(DeployerOps.java:593)
        at oracle.sysman.core.agentpush.ui.deployer.BaseDeployerOps.doInstall(BaseDeployerOps.java:437)
        ... 8 more

2016-05-13_09-46-14:INFO:=========Command Exception :Mensaje de Error: Update home dependency failed. 

Código de Salida :1 2016-05-13_09-46-14:INFO:Updating Action Installwith Status FAILED and error Message :Mensaje de Error: Update home dependency failed.

Código de Salida :1 and problem Ejecución del comando /applics/oem12c/agente_12c/ADATMP_2016-05-13_08-53-57-AM/agentDeploy.sh -ignorePrereqs ORACLE_HOSTNAME=servertarget.pamplona.name AGENT_BASE_DIR=/applics/oem12c/agente_12c OMS_HOST=ascoem.gseguros.com EM_UPLOAD_PORT=4904 AGENT_INSTANCE_HOME=/applics/oem12c/agente_12c/agent_inst b_doDiscovery=false b_startAgent=false b_forceInstCheck=true AGENT_PORT=3872 en el host servertarget.pamplona.name Fallo and recommendation Corrija la causa del error y vuelva a intentar la operación 2016-05-13_09-46-14:INFO:=================action status is not empty FAILED 2016-05-13_09-46-14:INFO:Breaking since the action has failed 2016-05-13_09-46-14:INFO:Skipping action SecureAgent since some previous step has failed 2016-05-13_09-46-14:INFO:Skipping action RunRootSH since some previous step has failed 2016-05-13_09-46-14:INFO:Not Skipping action CollectLog since some previous step has failed 2016-05-13_09-46-14:INFO:sudo exists value false 2016-05-13_09-46-14:INFO:==SUDO EXISTS false SUDO PRIV false

Si buscamos en los foros de soporte e oracle o en el propio metalink,encontraremos que es un error que puede deberse a bastantes casos, sin embargo, hay una causa que ( en mi caso era la razón) es muy sencilla de comprobar, y que puede ser la causa principal del error.


If the warning from the installer is bypassed, failure of the console to effectively deploy an agent can be just one of the resulting symptoms.
Unpublished BUG OMS CONFIG FAILING IF SWAP SPACE IS LESS THAN 6GB

Así que, ante este tipo de error , lo mas rápido, sencillo e inmediato es comprobar si tenemos al menos 6 Gb de swap space, es un requisito no publicado que hace que falle la instalacion.

Paquete UTL_MAIL en 12c

El paquete UTL_MAIL es uno de esos paquetes que, aunque en mi opinión no debería de usarse nunca, siempre nos encontramos con casos de aplicaciones que hacen uso del mismo.
Si migramos (no update) a la 12c (creo que los ultimos patchsets de la 11g puede pasar también), nos encontramos con que aparece este error:

PLS-00201: el identificador 'SYS.UTL_MAIL' se debe declarar
PLS-00201: identifier 'SYS.UTL_MAIL' must be declared

El motivo de este error queda bastante claro en la entrada de Database PL/SQL Packages and Types Reference UTL_MAIL de la documentación de los paquetes de la 12g.

UTL_MAIL no está instalado de forma predeterminada debido al requisito de configuración SMTP_OUT_SERVER y la exposición de la seguridad que ello implica.
Con la instalación de UTL_MAIL, usted deberá configurar el sistema para agregar la salida a los puertos definidos en SMTP_OUT_SERVER .

Así pues nos tocará instalarlo a mano con:

sqlplus sys/
SQL> @$ORACLE_HOME/rdbms/admin/utlmail.sql
SQL> @$ORACLE_HOME/rdbms/admin/prvtmail.plb

y dar los permisos al esquema que nos necesite

GRANT EXECUTE ON UTL_MAIL TO esquema;

En cualquier caso, aunque lo instalemos a mano, tendremos que empezar a lidiar con el paquete UTL_SMTP, con lo que nos vendrá bien tener a mano las entradas :

Errores Private strand flush not complete en el alert.log

Vamos a echar un vistazo rápido a un error bastante común en los alert.log

Una alerta bastante común que vemos en los alertlog es

Thread 1 cannot allocate new log, sequence 6180
Private strand flush not complete

Esta línea nos indica que, no hemos completado la operación de guardar todo el REDO cuando hacemos el switch.
El término strand es la palabra que utiliza Oracle para referrse a los latches de los redo log, lo que tenemos en este caso es un caso de este tipo, y lo que nos está indicando es qeu en ved de bajar el redo en tiempo real, lo «bajará» con el commit.

Este tipo de mensajes no es alarmante a no ser que haya mas mensajes del tipo «cannot allocate new log» o «advanced to log sequence»

En cualquier caso, pueden indicarnos que hay problemas con la velocidad de IO del almacenamiento donde se encuentran o en caso de ser logs remotos con la red