Entenda o evento TCP Socket (KGAS) e como isso pode afetar o desempenho do seu banco de dados Oracle

TCP Socket (KGAS)

Algumas vezes já me deparei com algumas sessões esperando por este wait event em alguns BD’s de produção em versões 10.2+, como não era tão relevante para a performance dos aplicativo s e não havia nenhum usuário se queixando do mesmo, quase sempre, passava despercebido. Alguns dias, recebi um ligação de um usuário reclamando que sua sessão estava travada por um longo tempo e fui investigar o que estava ocorrendo.

1) Fui checar nossa principal view de performance (v$session), ela não tem esse propósito, mas é um bom começo para verificar o que está ocorrendo com o usuário que está sofrendo.

SQL> select sid,username,event,status
from v$session
where username='MUFALANI'; -- Digamos que eu mesmo reclamei sobre o problema

Repetindo a consulta por algumas vezes, verifiquei que a minha sessão estava ativa e esperando pelo evento abaixo:

      SID USERNAME     EVENT                          STATUS
---------- ------------ ------------------------------ --------
      377 MUFALANI     TCP Socket (KGAS)              ACTIVE

SQL> /

      SID USERNAME     EVENT                          STATUS
---------- ------------ ------------------------------ --------
      377 MUFALANI     TCP Socket (KGAS)              ACTIVE

SQL> /

      SID USERNAME     EVENT                          STATUS
---------- ------------ ------------------------------ --------
      377 MUFALANI     TCP Socket (KGAS)              ACTIVE

Fui checar o que a sessão estava executando para entender melhor o problema:

SQL> select sql_fulltext from v$sqlarea where sql_id='63059n4vwju24';

E o meu usuário estava executando a seguinte query:

select utl_http.request('http://8.8.8.8') from dual; -- isso é um endereço de DNS do google válido mas retorna ORA-29273 HTTP request failed, resumindo, dá erro por timeout.

Fiquei um tanto intrigado com este evento e fui ver sua descrição no MOS (My Oracle Support) já que eu havia descoberto o que estava ocasionando o mesmo.

KGAS é um componente o RDBMS server que trabalha com sockets TCP/IP  que é tipicamente usado em conexões dedicadas nas versões 10.2+ por alguns PLSQL built in packages como UTL_HTTP and UTL_TCP. A interface KGAS não está envolvida na comunicação client/server, mas é uma camada que pode ser usada enquanto uma sessão no servidor faz algumas chamadas TCP/IP externas, usando PLSQL packages como UTL_HTTP, por exemplo. Packages como UTL_FILE também podem reportar este evento quando fazendo uma chamada SMTP, por exemplo.

O parâmetro P1 é o único usado neste evento, abaixo seguem as descrições do mesmo.

Valores posséveis do P1:

1 Event Post

2 Call

3 Disconnect

4 Receive data

5 Send data

6 Wait for an event (eg wait for data to arrive)

7 Sleep

8 Special wait (for single object)

9 Special wait (for multiple objects)

10 Select operation

Wait time: é o tempo de espera pelos blocos da operação corrente, ou timeout/erros dependendo do caso.

É possível consultar o quanto este problema está afetando seu banco de dados:

SQL>  SELECT sid, total_waits, time_waited
   FROM v$session_event
  WHERE event='TCP Socket (KGAS)'
    and total_waits>0
  ORDER BY 3,2
 ;  

      SID TOTAL_WAITS TIME_WAITED
---------- ----------- -----------
      108          31           5
      377          27       12021

Obs: Note que no meu caso eu fiz testes com sessões diferentes, a 377 é que estou usando como base para este artigo.

Agora vamos ir um pouco mais a fundo e fazer um trace para essa sessão

SQL> alter session set events '10046 trace name context forever, level 8';

SQL> select utl_http.request('http://8.8.8.8') from dual;

Vamos olhar dentro do nosso DIAG já que estou rodando este teste em uma versão do Oracle 12cR1 (12.0.1.0)

$ORACLE_BASE/diag/rdbms/$ORACLE_SID/$ORACLE_SID/trace

Vamos abrir o trace gerado:

vi terc1_ora_21726.trc 

— Conteúdo do trace

Oracle Database 12c Release 12.1.0.1.0 - 64bit Production
ORACLE_HOME = /u01/db/oracle/product/12101/oh_1
System name:    Linux
Node name:      oracle
Release:        2.6.32-358.el6.x86_64
Version:        #1 SMP Tue Jan 29 11:47:41 EST 2013
Machine:        x86_64

Instance name: terc1
Redo thread mounted by this instance: 1
Oracle process number: 25

Unix process pid: 21726, image: oracle@oracle
*** 2013-10-31 12:35:12.776
*** SESSION ID:(377.42153) 2013-10-31 12:35:12.776
*** CLIENT ID:() 2013-10-31 12:35:12.776
*** SERVICE NAME:(terc1) 2013-10-31 12:35:12.776
*** MODULE NAME:(SQL*Plus) 2013-10-31 12:35:12.776
*** ACTION NAME:() 2013-10-31 12:35:12.776

WAIT #140642330794920: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=19689 tim=876578440838
*** 2013-10-31 12:36:22.022
WAIT #140642330794920: nam='SQL*Net message from client' ela= 69245794 driver id=1413697536 #bytes=1 p3=0 obj#=19689 tim=876647687242
CLOSE #140642330794920:c=0,e=13,dep=0,type=1,tim=876647687417
=====================
PARSING IN CURSOR #140642333602408 len=51 dep=0 uid=179 oct=3 lid=179 tim=876647702386 hv=935913540 ad='324c0c3a0' sqlid='63059n4vwju24'
select utl_http.request('http://8.8.8.8') from dual
END OF STMT

PARSE #140642333602408:c=3999,e=14867,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=876647702385
EXEC #140642333602408:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=876647702668
WAIT #140642333602408: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=19689 tim=876647702779

*** 2013-10-31 12:37:22.098

WAIT #140642333602408: nam='TCP Socket (KGAS)' ela= 60060295  =2  =0  =0 obj#=19689 tim=876707763447
FETCH #140642333602408:c=2000,e=60061000,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=876707763827
STAT #140642333602408 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)'
WAIT #140642333602408: nam='SQL*Net break/reset to client' ela= 6 driver id=1413697536 break?=1 p3=0 obj#=19689 tim=876707764087
WAIT #140642333602408: nam='SQL*Net break/reset to client' ela= 69736 driver id=1413697536 break?=0 p3=0 obj#=19689 tim=876707833856

*** 2013-10-31 12:39:09.892

WAIT #140642333602408: nam='SQL*Net message from client' ela= 107723307 driver id=1413697536 #bytes=1 p3=0 obj#=19689 tim=876815557271
CLOSE #140642333602408:c=0,e=41,dep=0,type=0,tim=876815557477
=====================

Podemos checar algumas informações interessantes nesse arquivo, tais como: O evento de espera que estamos checando “TCP Socket (KGAS)”, Os tempos de espera (ela), o sqlid do comando executado, o próprio cursor executado e também outro evento alarmado para a minha sessão “SQL*Net break/reset to client” quando deu erro de timeout.

Conselhos da Oracle para este evento: O tempo depende de quais sockets estão sendo utilizados na chamada externa (site remoto). Para achar o origem do problema, faça o que eu fiz neste artigo que chegará até onde o problema está sendo originado. Não há muito o que fazer dentro do banco de dados para “tunar” este evento e sim do lado de fora, ou talvez fazendo menos chamadas externas em sua aplicação para este evento de espera parar de ser alarmado.

Conclusão: Meu usuário estava fazendo diversas chamadas externas e não estava obtendo resposta, com isso a sessão dele estava processando por um longo tempo e parecia estar “travada”.

Referencias

• MOS “TCP Socket (KGAS)” Reference Note (Doc ID 558510.1)