Operation LOAD TABLE CONVENTIONAL

[Róli]

A principal query do schema "de repente" muda o plano de execução e passa a vir muitas reclamções dos usuários.
O INSERT abaixo é executada muitas vezes no dia, trata-se de uma gravação de atendimento a pacientes:

INSERT INTO OWNER.TABELAXXXX( XXXX, XXX, XXXX,.... )
VALUES ( :B10 , :B9 , :B8 , :B7 , SYSDATE , TO_DATE('04044444','ddmmyyyy') , :B6 , :B5 , :B4 , :B3 , :B2 , :B1 )


PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------

--------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 1 | 111 | 1 (0)| 00:00:01 |
| 1 | LOAD TABLE CONVENTIONAL | TABELAXXXX| | | | |
---------------------------------------------------------------------------------------------------------

Não há quase notas no metalink que expliquem a operação LOAD TABLE CONVENTIONAL em um plano de execução, o que basicamente é informado é que deve ocorrer somente em Oracle versão Enterprise e em execução com paralelelismo.

Lembrando que, não foram criados nem dropados índices dessa tabela, a coleta de estatísticas passou a ser diária incremental ao invés de semanal full somente, e o restante nada mudou.

É um ambiente Oracle RAC.

O que poderia estar ocorrendo?

Desde já, obrigada

[portilho]

Este Access Path quer dizer que está sendo utilizado o método convencional de INSERT, via SGA (DB_CACHE_SIZE), ao invés do método DIRECT PATH, que acontece quando se usa a HINT de APPEND no INSERT, que utiliza a PGA, faz alocações de espaço apenas acima da marca d'água da tabela, e só pode acontecer um por vez. O DIRECT PATH é mais rápido, mas tem todas estas limitações.

O Acess Path LOAD TABLE CONVENTIONAL aparece em diversos perfis de INSERT, e não só com paralelismo:



SQL> CONN SCOTT/TIGER
Conectado.
SQL> SET AUTOTRACE ON EXPLAIN
SQL> SET PAGES 1000
SQL> SET LINES 300
SQL> INSERT INTO T3 VALUES (1);

1 linha criada.


Plano de ExecuþÒo
----------------------------------------------------------

---------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 1 | 100 | 1 (0)| 00:00:01 |
| 1 | LOAD TABLE CONVENTIONAL | T3 | | | | |
---------------------------------------------------------------------------------





SQL> INSERT INTO T1 SELECT * FROM T2 WHERE ROWNUM = 1;

1 linha criada.


Plano de ExecuþÒo
----------------------------------------------------------
Plan hash value: 1154646200

---------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 1 | 158 | 256 (3)| 00:00:03 |
| 1 | LOAD TABLE CONVENTIONAL | T1 | | | | |
|* 2 | COUNT STOPKEY | | | | | |
| 3 | TABLE ACCESS FULL | T2 | 101K| 15M| 256 (3)| 00:00:03 |
---------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - filter(ROWNUM=1)





SQL> INSERT INTO T1 SELECT * FROM T2;

253949 linhas criadas.


Plano de ExecuþÒo
----------------------------------------------------------
Plan hash value: 1513984157

---------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 101K| 15M| 256 (3)| 00:00:03 |
| 1 | LOAD TABLE CONVENTIONAL | T1 | | | | |
| 2 | TABLE ACCESS FULL | T2 | 101K| 15M| 256 (3)| 00:00:03 |
---------------------------------------------------------------------------------

SQL> ROLLBACK;

Rollback concluÝdo.





SQL> INSERT /*+ PARALLEL */ INTO T1 SELECT * FROM T2;

253949 linhas criadas.


Plano de ExecuþÒo
----------------------------------------------------------
Plan hash value: 1216610266

------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | TQ |IN-OUT| PQ Distrib |
------------------------------------------------------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 101K| 15M| 35 (0)| 00:00:01 | | | |
| 1 | LOAD TABLE CONVENTIONAL | T1 | | | | | | | |
| 2 | PX COORDINATOR | | | | | | | | |
| 3 | PX SEND QC (RANDOM) | :TQ10000 | 101K| 15M| 35 (0)| 00:00:01 | Q1,00 | P->S | QC (RAND) |
| 4 | PX BLOCK ITERATOR | | 101K| 15M| 35 (0)| 00:00:01 | Q1,00 | PCWC | |
| 5 | TABLE ACCESS FULL | T2 | 101K| 15M| 35 (0)| 00:00:01 | Q1,00 | PCWP | |
------------------------------------------------------------------------------------------------------------------

Note
-----
- automatic DOP: skipped because of IO calibrate statistics are missing





Mas se o plano mudou e ficou mais lento, precisamos analisar.
Você pode tirar um relatório SQLTXPLAIN deste SQL_ID?

[Róli]

Olá!

Bom, o cenário não era somente o INSERT. Gerei 3 traces de 3 processos em momentos distintos.

Abaixo, o resumo dos traces, sendo que no primeiro e segundo trace não foi feita nenhuma intervenção, sendo no terceiro trace, foi pinado em memória todas as tabelas envolvidas no processo.

Os maiores wait events são de SQL*Net message to client, SQL*Net message from client e gc current block 2-way. Há uma sopa de wait events nos traces, mas está indo para o lado de problemas na camada de rede, talvez o servidor de TS de conexão dessa aplicação esteja com algum problema ou até a prórpia interconect do RAC, mas as demais aplicações também deveriam estar apresentando lentidão.

Detalhes:

1. A aplicação que está com lentidão nesse processo, está em um TS (VM) separado dos demais.
2. As demais aplicações não reportam lentidão.
3. O processo de gravação (INSERTS com suas queries) deve demorar 10 segundos, mas está demorando mais de 1 minutos, até 3 minutos já levou.


=========================== TRACE 1:
Misses in library cache during parse: 213
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 4902 0.00 0.01
SQL*Net message from client 4902 199.37 468.60
row cache lock 19 0.00 0.00
library cache lock 15 0.00 0.00
library cache pin 14 0.00 0.00
gc cr block busy 2 0.00 0.00
KJC: Wait for msg sends to complete 4 0.00 0.00
Disk file operations I/O 3 0.00 0.00
gc cr grant 2-way 16 0.00 0.00
db file sequential read 41 0.07 0.32
gc current block 2-way 88 0.00 0.03
latch free 5 0.00 0.00
gc current grant 2-way 5 0.00 0.00
gc cr block 2-way 13 0.00 0.00
gc current grant busy 10 0.00 0.00
log file sync 2 0.00 0.00
DFS lock handle 1 0.00 0.00
SQL*Net break/reset to client 6 0.00 0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 713 0.02 0.02 0 0 0 0
Execute 1844 0.06 0.05 0 4 4 2
Fetch 1873 0.03 0.18 9 6001 1 1809
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4430 0.12 0.26 9 6005 5 1811

Misses in library cache during parse: 10
Misses in library cache during execute: 10

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
row cache lock 10 0.00 0.00
Disk file operations I/O 2 0.00 0.00
gc cr grant 2-way 8 0.00 0.00
db file sequential read 9 0.05 0.14
gc current block 2-way 6 0.00 0.00
gc current grant 2-way 1 0.00 0.00
gc cr block 2-way 5 0.00 0.00



=========================== TRACE 2:
Misses in library cache during parse: 98

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2303 0.00 0.00
SQL*Net message from client 2302 31.73 84.55
row cache lock 20 0.00 0.00
Disk file operations I/O 4 0.00 0.00
gc current block 2-way 83 0.00 0.04
gc cr grant 2-way 8 0.00 0.00
db file sequential read 25 0.03 0.30
gc current grant 2-way 7 0.00 0.00
gc cr block 2-way 2 0.00 0.00
library cache lock 15 0.00 0.00
library cache pin 15 0.00 0.00
latch free 1 0.00 0.00
log file sync 2 0.00 0.01
gc current grant busy 13 0.00 0.00
SQL*Net break/reset to client 6 0.00 0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 417 0.02 0.02 0 0 2 0
Execute 886 0.04 0.05 0 2 2 1
Fetch 1346 0.03 0.15 8 3129 1 2238
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2649 0.09 0.24 8 3131 5 2239

Misses in library cache during parse: 13
Misses in library cache during execute: 12

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
row cache lock 37 0.00 0.00
Disk file operations I/O 3 0.00 0.00
gc current block 2-way 1 0.00 0.00
gc cr grant 2-way 8 0.00 0.00
db file sequential read 8 0.03 0.12
gc current grant 2-way 1 0.00 0.00
library cache lock 1 0.00 0.00
library cache pin 1 0.00 0.00



=========================== TRACE 3: após pinar as tabelas envolvidas no processo para a memória do Oracle
Misses in library cache during parse: 65
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 690 0.00 0.00
SQL*Net message from client 689 30.05 36.55
library cache lock 3 0.00 0.00
library cache pin 2 0.00 0.00
log file sync 2 0.00 0.00
Disk file operations I/O 2 0.00 0.00
gc cr block 2-way 3 0.00 0.00
gc current block 2-way 21 0.00 0.00
DFS lock handle 1 0.00 0.00
latch free 1 0.00 0.00
enq: TM - contention 2 0.00 0.00
gc current grant busy 6 0.00 0.00
gc current grant 2-way 2 0.00 0.00
db file sequential read 2 0.00 0.00
SQL*Net break/reset to client 6 0.00 0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 230 0.00 0.01 0 0 0 0
Execute 407 0.01 0.01 0 2 3 1
Fetch 408 0.00 0.01 0 1107 1 392
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1045 0.03 0.03 0 1109 4 393

Misses in library cache during parse: 4
Misses in library cache during execute: 4

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
gc cr block 2-way 1 0.00 0.00
gc current block 2-way 2 0.00 0.00
row cache lock 1 0.00 0.00

[portilho]

Acho que o pior destes traces não é o SQL*Net, mas os eventos GC.

Um INSERT executado nos dois nós fará com que haja concorrência entre os Caches.
Se ficou lento e antes não era, ou sua carga aumentou, ou passou a ter lentidão na rede do Interconnect.

Sugiro que crie um Service para esta aplicação, de forma que este INSERT seja executado em apenas um nó. Tenho certeza de que ficará mais rápido.

[Róli]

Obrigada Portilho, realmente, a performance fica muito melhor no INSERT quando fixado o service em um nó somente. Fiz isso, mas não resolveu, só melhorou o plabo, mas o eventos de SQL net* ainda continuavam e a lentidão reportada pelos usuários.

Chemei um administrador de SO e mais o fornecedor, pois a situação já estava tensa, pacientes tendo que aguardar pela lentidão no processo.

Depois dos testes realizados, migramos a instalação da aplicação para uma máquina da TI, a performance ficou ótima, e depois de análises realizadas no TS, olha a causa da lentidão:
"Verifiquei que ao finalizar o procedimento de gravação no sistema, acessado pelo \\..\..\..\xxx.exe, é gerado um arquivo “.tmp”, o qual acaba salvo na raiz do compartilhamento de rede. Me parece que estes arquivos atingiram o número de bits limite(FFFF.tmp), acredito que limitado pelo sistema.
Movi estes arquivos antigos para a pasta \\..\OLD_TMP e, após feito isso, novos arquivos .tmp passaram a ser criados neste local e o sistema teve o desempenho esperado.
Pelo menos o procedimento que nos apresentaram o problema, agora está normalizado."


Problemas da aplicação..e o pior, o fornecedor caiu de pau encima do Oracle..

Mas tudo bem, problema provado, testato e comprovado!

[portilho]

Caramba!
Que aplicação boa... rs... grava arquivo temporário na rede, e com uma bomba relógio ainda por cima.
Que bom que o Service ajudou, e parabéns pelo rastreamento que trouxe a solução definitiva.