Errores psdgbt: bind csid (X) does not match session csid (YY)

Hoy vamos a ver una entrada rapida y sencilla que nos ayudara a evitar una cascada de errores en el alert.log

Es posible que, la reiniciar alguna e nuestras bases de datos que se encuentran bajo la monitorizacion de un Enterprise manager veamos que el alert.log de nuestra base de datos comienza a mostrar continuamente errores del tipo

Errors in file /u01/app/oracle/diag/rdbms/TEST_stby/TEST/trace/TEST_ora_743.trc:
Mon March 11 12:24:47 2019
Errors in file /u01/app/oracle/diag/rdbms/TEST_stby/TEST/trace/TEST_ora_743.trc:
Mon March 11 12:25:06 2019
Errors in file /u01/app/oracle/diag/rdbms/TEST_stby/TEST/trace/TEST_ora_743.trc:

Si comprobamos la traza podemos ver como se trata de errores del tipo

psdgbt: bind csid (1) does not match session csid (46)
psdgbt: session charset is XXX

Donde el charset variara en funcion de nuestra base de datos, veamos una de estas trazas

ORACLE_HOME = /u01/app/oracle/product/12.1.0/db
System name: Linux
Node name: test.pamplona.name
Release: 3.8.13-118.19.12.el6uek.x86_64
Version: #2 SMP Tue Oct 31 12:31:15 PDT 2017
Machine: x86_64
Instance name: TEST
Redo thread mounted by this instance: 1
Oracle process number: 32
Unix process pid: 743, image: oracle@test.pamplona.name

*** 2019-03-11 21:20:06.886
*** SESSION ID:(2.57596) 2019-03-11 21:20:06.886
*** CLIENT ID:() 2019-03-11 21:20:06.886
*** SERVICE NAME:() 2019-03-11 21:20:06.886
*** MODULE NAME:(emagent_SQL_oracle_database) 2019-03-11 21:20:06.886
*** CLIENT DRIVER:(jdbcthin) 2019-03-11 21:20:06.886
*** ACTION NAME:(ME$icc_dbs_age_last_backup) 2019-03-11 21:20:06.886

psdgbt: bind csid (1) does not match session csid (46)
psdgbt: session charset is WE8ISO8859P15

*** 2019-03-11 21:20:06.886
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=1, mask=0x0)
—– Error Stack Dump —–
—– Current SQL Statement for this session (sql_id=a0qc12302fzfk) —–
begin dbms_application_info.set_module(:1 , :2 ); end;

La solucion para este problema es muy muy sencila, simplemente, reinicia el agente del enterprise manager del servidor donde se encuentra ubicada la base de datos.

Como siempre, mas informacion en soporte de Oracle
Doc ID 956222.1

ORA-38870: cannot backup a control file that may have incorrect data file structure.

Hoy vamos a volver con una entrada rapida de un problema muy facil de solucionar.

A veces, podemos encnontrarnos en el alert.log con el error

ORA-38870:cannot backup a control file that may have incorrect data file structure

Si miramos las trazas asustan bastante

2018-10-23T16:08:43.542081+02:00
Errors in file /u01/app/oracle/diag/rdbms/test_stby/test/trace/test_m000_425.trc:
ORA-38870: cannot backup a control file that may have incorrect data file structure.
2018-10-23T16:13:43.189251+02:00
Starting control autobackup
********************  WARNING ***************************
The errors during Server autobackup are not fatal, as it
is attempted after sucessful completion of the command.
However, it is recomended to take an RMAN control file
backup as soon as possible because the Autobackup failed
with the following error:
ORA-38870: cannot backup a control file that may have incorrect data file structure.
********************  END OF WARNING *******************

Pero, buscando en la documentacion de Oracle, nos contraremos que

Error code: ORA-38870

Description: cannot backup a control file that may have incorrect data file structure.
This control file was created or converted based on a control file from a time different from the time of the database.
Action: Open database read-only to synchronize the control file with the database dictionary to fix the control file

Cualquier cosa relaccionada con una estructura invalida de un controlfile puede asustar bastante, pero , este alarmante problema se soluciona de manera muy rapida y sencilla, simplemente haciendo eso, abriendo la base de datos en modo lectura.
Y ya no volveremos a ver mas el problema

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 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

Monitorizando el alert con adrci

Hoy vamos a ver un pequeño script que puede ser muy útil para la monitorizacion.
Vamos a llamar a adrci indicándole que nos muestre los errores del alert desde la última vez que se ejecuto.
Para ello vamos a usar el comando show alert -p , marcándole como rango temporal a buscar la diferencia entre esta ejecución y a anterior.

#!/bin/bash
#
# Script que monitoriza el alert.log de una instancia desde la ultima vez que se ejecutó
# Si esta ultima ejecucion es menor de 5 minutos ejecuta los ultimos 5 minutos
#
#
# Si no guarda diene la guarda de ultima ejecucion sale con un ERROR
#
#  Asuminos timestamp'2015-02-18 00:07:49.767000 +01:00'
#

# Salida de debug
DEBUG=0

 #Comprobamos que se ha llamado de manera correcta
if  [ $# -ne 1 ]; then
echo "Uso adrci_alert  SID"
exit 3;
fi



# Inicializamos valores para el script
export ORAENV_ASK=NO
export TEMPORAL=/var/tmp/temporal_salida_alert_$$.log
export SALIDA=/var/tmp/salida_salida_alert_$$.log
export SID=$1
export GUARDA=/var/tmp/guarda_alert_${SID}.txt
DIA=`date +%Y-%m-%d`
HORA=`date +%H:%M:%S`
export AHORA="${DIA} ${HORA}.0000000 +01:00"
. oraenv  1>/dev/null



## Comenzamos la ejecucion
if [ $DEBUG -eq 1 ]; then
        echo "DEBUG: ORACLE_BASE=$ORACLE_BASE"
        echo "DEBUG: GUARDA= ${GUARDA}"
        echo "DEBUG: SALIDA= ${SALIDA} "
        echo "DEBUG: ORACLE_SID=$SID"
        echo "DEBUG: AHORA=$AHORA"
fi


# Buscamos ultima iteracion
if [ ! -f  $GUARDA ]; then
        echo "No tenemos ejecucion anterior"
        echo $AHORA > ${GUARDA}
        exit 1;
fi

#  Obtenemos el timestamp de la ultima ejecucion
TIEMPO=`cat ${GUARDA}`

# COmprobamos que han pasado mas de 5 minutos
OLD=`cat ${GUARDA}|awk '{print($1,$2)}'`
NOW="${DIA} ${HORA}.0000000"
SEGOLD=$(date -u -d "$OLD" +"%s")
SEGNOW=$(date -u -d "$NOW" +"%s")
DIFERENCIA=$((SEGNOW-SEGOLD))

# Comenzamos las iteraciones
adrci_homes=( $(adrci exec="show homes" | grep -e rdbms |grep ${SID}))
  for adrci_home in ${adrci_homes[@]}
    do
  #Generamos el fichero de comandos
   echo "SET TERMOUT OFF" > ${TEMPORAL}
   echo "SET ECHO OFF" >> ${TEMPORAL}
   echo "set home ${adrci_home} ;" >> ${TEMPORAL}
   echo "spool ${SALIDA} append " >>${TEMPORAL}
   echo "show alert -p \"message_text like '%ORA-%' and originating_timestamp >= \'${TIEMPO}\' \" -term " >>${TEMPORAL}
   echo "exit; " >> ${TEMPORAL}
     if [ $DEBUG -eq 1 ]; then
       echo "DEBUG: "
       echo "DEBUG:  adrci SCRIPT=${TEMPORAL}"
       echo "DEBUG: EL etemporal es "
       echo "DEBUG: -inicio temporal-"
       cat ${TEMPORAL}
       echo "DEBUG: -fin temporal-"
      fi
   adrci  SCRIPT=${TEMPORAL}   1>/dev/null
   tail -n+4 ${SALIDA}
   rm ${TEMPORAL}
done

#Actualizamos la guarda solamente si hace menos de 5 minutos que lo hemos ejecutado
if [ "$DIFERENCIA" -gt  299 ]; then
        echo $AHORA > ${GUARDA}
fi

## Añadir aqui la integración con monitorizacion

##Borramos la salida 
rm ${SALIDA}
#Salimos correctamente
exit 0 ;

A partir de aqui, solamente tenemos que integrar el tratamiento del fichero $SALIDA que es donde tendremos los errores del alert