You are hereInterpretación de traces de Oracle (ejemplo)

Interpretación de traces de Oracle (ejemplo)


By KarlMudespacher - Posted on 26 October 2008

Tuve un comentario que me pareció muy interesante, se trataba de identificar un problema de soporte con un proceso que falló y generó un trace file. La idea detrás es la de interpretar un archivo de trace mediante un método que pudiera además hacer uso de la información que publiqué en el post Capas del Kernel de Oracle.

Y el comentario publicado dice así…

Gracias por enviarme el trace completo, voy a copiar lo que nos interesa para nuestro análisis.

Dentro del trace en la sección de los registros encontramos la misma dirección apuntada cuando se generó el evento SIGBUS cuando se estaba llamando la función koudcon().


*** SESSION ID:(17.28511) 2008-07-14 07:30:47.736
Exception signal: 10 (SIGBUS), code: 0 (unknown code), addr: 0×800003ffbfec0000, PC: [0x4000000002be5a90, koudcon()+40]
Registers:
r1: 800003ffbfebffd0 r22: 7fff sr4: b6b5800
rp: 4000000002be5a87 arg3: 7fff sr0: ac88c00
r3: 800003ffbffff3c0 arg2: 7fff sr1: 0
r4: 0 arg1: 0 sr2: 0
r5: 0 arg0: 800003ffbfebffff sr3: 0
r6: 1 dp: 8000000100112638 sr5: 395800
r7: 8000000100160c38 ret0: 800003ffbfebffe8 sr6: ea68400
r8: c00000002effe903 ret1: 800003ffbffffa20 sr7: ac88c00
r9: 800003ffbfffd5c8 sp: 800003ffbffff850 cr0: 1000000000001
r10: 3f r31: 800003ffbfec0000 cr8: fffffffffc071000
r11: 800003ffbfffd588 sar: 10 cr9: 0
r12: 800003ffbfffd584 pcoqh: 4000000002be5a93 ccr: 92ba0c0
r13: 4 pcsqh: 395800 cr12: 92ba1c0
r14: 800003ffbfea8020 pcoqt: 4000000002be5a97 cr13: 8211e00
r15: 800003ffbfea7fb0 pcsqt: 395800 cr24: 0
r16: 800003ffbfea6ec0 eiem: ffffffffffffffff cr25: 81dcb20
r17: 800003ffbfea6ee8 iir: f403342 cr26: 1
r18: e isr: ea68400 mpsfu_hi: 800003ffbfee1408
r19: 800000010018df28 ior: 800003ffbfec0000 mpsfu_lo: 95c56000
r20: 30 ipsw: 8040e0f mpsfu_ov: 9d65e00
r21: 10b38f0000000001 goto: 81bb84c pad: c0b3b87ba36b

De modo que la dirección pertenece a una variable de tipo bind.
Más adelante en el trace aparece la sentencia que generó el error.


SELECT RDM.ITEM_ID ARTICULO3,
RDM.STD_CASEPACK CASEPACKRDM3,
RMS.SUPP_PACK_SIZE CASEPACKRMS3
FROM ITEM_MASTER RDM,
RMS100.ITEM_SUPP_COUNTRY@FCRMSPRD RMS,
RMS100.ITEM_LOC@FCRMSPRD RMS1
WHERE RDM.ITEM_ID = RMS.ITEM
AND RMS.ITEM = RMS1.ITEM
AND RMS.SUPPLIER = RMS1.PRIMARY_SUPP
AND RMS.ORIGIN_COUNTRY_ID = RMS1.PRIMARY_CNTRY
AND RMS1.LOC_TYPE = ‘W’
AND RMS1.LOC = :P_CEDIS
AND RMS.PRIMARY_SUPP_IND = ‘Y’
AND RDM.STD_CASEPACK RMS.SUPP_PACK_SIZE
AND :P_PARAMETRO3 = ‘Y’

Inmediatamente después aparece la sección del stack

----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
——————– ——– ——————– —————————-
ksedmp()+184 ? ksedst() 800003FFBFFFD588 ?
800003FFBFFFF8B0 ?
34FF8BEC349DB6 ?
8000000100112638 ?
ssexhd()+636 ? ksedmp() 40000000016F11F7 ?
800003FFBFFFD540 ?
C0000000001A130B ?
800003FFBFFFFE18 ?
_sigreturn()+0 ? ssexhd() 0092BA0C0 ? 000000000 ?
00F403342 ?
800003FFBFFFF850 ?
koudcon()+40 ? _sigreturn() 000000000 ? 000000000 ?
000000000 ? 000000000 ?
kodmcon()+564 ? koudcon() 000000000 ? 000000000 ?
00000000E ? 00000003F ?
kokorsc()+964 ? kodmcon() 000000000 ? 000000000 ?
…..

kksald()+344 ? opiprs() 800000010011EDC0 ?

…..

main()+228 ? sou2o() 000000000 ?
C00000000020BB4B ?
000000002 ? 0680F0A9F ?
$START$()+160 ? main() 0680F0771 ? 000000000 ?
000000001 ?
800003FFBFFF08AB ?

——————— Binary Stack Dump ———————

Dado que es un stack (pila) leeremos la sección desde la primer línea que aparece pero teniendo en mente que estamos leyendo a partir de la última función ejecutada hasta la primer función ejecutada (cuando no se generaba el problema, incluso cuando se inició la sesión) que corresponde a main().

De este modo la última función es
ksedmp() función para preparar dumps dentro de la capa de servicios (Services Layer)
ssexhd() función dentro de la capa de servicios del sistema operativo (Operating System Dependencies)
_sigreturn() función que regresa la señal enviada por el sistema operativo después de ser llamado
koudcon() función en la que se presenta el error (como ya lo había notificado el RDBMS)

*** SESSION ID:(17.28511) 2008-07-14 07:30:47.736
Exception signal: 10 (SIGBUS), code: 0 (unknown code), addr: 0×800003ffbfec0000, PC: [0x4000000002be5a90, koudcon()+40]

Así que tenemos un trace que nos muestra una sesión que ejecuta lo siguiente
1) compilación de SQL. Lo que significa que dicho código no había sido ejecutado anteriormente (función kksald()),

2) no aparece una capa KX de ejecución pero sí aparecen las capas de acceso al sistema operativo. Para resolver el SQL Oracle necesita acceder a una dirección de memoria (Oracle solicita al sistema operativo el contenido de la dirección independientemente de si éste se encuentra en memoria o si ha sido enviado a la memoria virtual),

3) ejecución de la función koudcon(), otra función propia del RDBMS de Oracle, que solicita la lectura de lo que se encuentra en la dirección 0×800003ffbfec0000,

4) el sistema operativo regresa un error porque la dirección compartida (el sistema operativo es Unix) no tiene privilegios de acceso por parte del usuario oracle o bien porque no existe nada en dicha dirección,

5) el error se notifica a la función ssexhd()* desde el sistema operativo, esta es una función propia del RDBMS y se encuentra en las librerías
./libserver11.a
./libagtsh.so.1.0
./libagtsh.so
./libagent11.a
./libgeneric11.a
./liborasdk.so.11.1
./libclntsh.so
./libclntsh.so.11.1
./libclntsh.so.10.1
./liborasdk.so

6) la función ssexhd() debe de tener una sección para el manejo de excepciones y es precisamente en esta parte de su código donde se ejecuta la función ksedmp() de la capa KS (Services Layer) que es la que finalmente se encarga de generar las entradas en
-alert log
-salida estándar de la sesión que tuvo el problema
-el trace file (incluída su generación)

Finalmente tengo un par de comentarios.

A. Dado que el error se presenta en cierta dirección de memoria para un pedazo de código que se ejecuta muy frecuentemente (en las capas KK, S y KX) no creo que el error sea repetible y no es precisamente este SQL el que tendrá siempre problemas. El usuario final puede ejecutar nuevamente su proceso, pero dado que hay un problema de direccionamiento y/o cálculo de las direcciones donde se almacenan datos el problema estará latente y otro proceso será impactado. La situación que presentas es un bug.

B. Es muy importante revisar el resto de los traces cuando éstos se presentan, en el trace dentro del “Binary Stack Dump” hay siempre información relevante. En el resto de los logs (incluída la salida estándar) dice

ksedmp: internal or fatal error
ORA-07445: exception encountered: core dump [koudcon()+40] [SIGBUS] [unknown code] [0x800003FFBFEC0000] [] []

Pero en el trace file aparece lo siguiente

.....
800003FFC0000920 004F5241 2D303734 34353A20 65786365 [.ORA-07445: exce]
800003FFC0000930 7074696F 6E20656E 636F756E 74657265 [ption encountere]
800003FFC0000940 643A2063 6F726520 64756D70 205B6B6F [d: core dump [ko]
800003FFC0000950 7564636F 6E28292B 34305D20 5B534947 [udcon()+40] [SIG]
800003FFC0000960 4255535D 205B756E 6B6E6F77 6E20636F [BUS] [unknown co]
800003FFC0000970 64655D20 5B307838 30303030 33464642 [de] [0x800003FFB]
800003FFC0000980 46454330 3030305D 205B5D20 5B5D0A00 [FEC0000] [] []..]
…..

que es información nueva para el administrador si éste se guía únicamente por la información humanamente legible en los otros logs. Aquí nos dice claramente que existe un evento del sistema operativo SIGBUS (en otro lugar con el tipo 10), con esta información podemos acceder a la nota 211909.1 -que no transcribiré aquí- que nos explica con mucho menor detalle lo que expliqué en este comentario.

Notas:

*La función ssexhd() pertenece al RDMS por lo que tiene que ser portable con distintos sistemas operativos, es por ello que Oracle Corporation nos dice que los mensajes arrojados por esta función pueden variar dependiendo del sistema operativo sobre el que se instaló el RDBMS.



Syndicate

Syndicate content

Follow DatabasesLA on Twitter

Who's online

There are currently 0 users and 4 guests online.

Estadisticas

Locations of visitors to this page

hidden hit counter