Desde o Caché 2017, o mecanismo SQL inclui um novo conjunto de estatísticas. Ele registra o número de vezes que uma consulta é executada e o tempo que leva para executá-la.
Esta é uma mina de ouro para qualquer pessoa que está monitorando e tentando otimizar o desempenho de uma aplicação que inclui muitas instruções SQL, mas que não é tão fácil de acessar os dados como algumas pessoas desejam.
Este artigo e o código de exemplo associado explicam como usar essas informações e como extrair rotineiramente um resumo de estatísticas diárias e manter um registro histórico de desempenho do SQL de sua aplicação.
Toda vez que uma instrução SQL é executada, o tempo gasto é registrado. Esse registro é muito leve e você não pode desativá-lo. Para minimizar o custo, as estatísticas são mantidas na memória e gravadas no disco periodicamente. Os dados incluem o número de vezes que uma consulta foi executada no dia e a média e o tempo total gasto.
Os dados não são gravados no disco imediatamente, e depois de gravados, as estatísticas são atualizadas pela tarefa "Atualizar estatísticas de consulta SQL" que geralmente é programada para se executada a cada hora. Essa tarefa pode ser executada manualmente, mas se você quiser ver as estatísticas em tempo real enquanto testa uma consulta, todo o processo requer um pouco de paciência.
Aviso: No InterSystems IRIS 2019 e anteriores, essas estatísticas não são coletadas para SQL embutido em classes ou rotinas que foram implantadas usando o mecanismo %Studio.Project:Deploy. Nada quebrará com o código de exemplo, mas pode enganar você (me enganou) fazendo-o pensar que tudo estava OK porque nada parecia tão custoso.
Você pode ver a lista de consultas no portal de gerenciamento. Vá para a página SQL e clique na aba ‘Instruções SQL’. É ótimo para uma nova consulta que você está executando e examinando, mas se houver milhares de consultas em execução, pode-se tornar incontrolável.
A alternativa é usar o SQL para pesquisar as consultas. As informações são armazenadas em tabelas no esquema INFORMATION_SCHEMA. Este esquema tem várias tabelas e incluí alguns exemplos de consultas SQL no final deste artigo.
Os dados de uma consulta são removidos sempre que ela é recompilada. Portanto, para consultas dinâmicas, isso pode significar quando as consultas em cache são limpas. Para SQL embutido, isso significa quando a classe ou rotina em que o SQL está embutido é recompilado.
Em um site ativo, é razoável esperar que as estatísticas sejam mantidas por mais de um dia, mas as tabelas que contêm as estatísticas não podem ser usadas como uma fonte de referência para relatórios ou análises de longo prazo.
Recomendo extrair os dados todas as noites em tabelas permanentes que são mais fáceis de trabalhar ao gerar os relatórios de desempenho. Há uma chance de que algumas informações sejam perdidas se as classes forem compiladas durante o dia, mas é improvável que isso faça alguma diferença real em sua análise de consultas lentas.
O código a seguir é um exemplo de como você pode extrair as estatísticas em um resumo diário para cada consulta. Inclui três classes curtas:
* Uma tarefa que deve ser executada todas as noites. * DRL.MonitorSQL é a classe principal que extrai e armazena os dados das tabelas INFORMATION_SCHEMA.Notas sobre o exemplo
A tarefa é extraída do dia anterior e, portanto, deve ser agendada logo após a meia-noite.
Você pode exportar mais dados históricos, se houver. Para extrair os últimos 120 dias
Faça ##class(DRL.MonitorSQL).Capture($h-120,$h-1)
O código de exemplo lê o ^rIndex global diretamente porque as versões mais antigas das estatísticas não expunham a Data ao SQL.
A variação, incluí loops em todos os namespaces na instância, mas isso nem sempre é apropriado.
Uma vez que os dados são extraídos, você pode encontrar as consultas mais pesadas executando
SELECT top 20 S.RunDate,S.RoutineName,S.TotalHits,S.SumpTIme,S.Hash,t.QueryText from DRL.MonitorSQL S left join DRL.MonitorSQLText T on S.Hash=T.Hash where RunDate='08/25/2019' order by SumpTime desc
Além disso, se você escolher o hash para uma consulta custosa, poderá ver o histórico dessa consulta com
SELECT S.RunDate,S.RoutineName,S.TotalHits,S.SumpTIme,S.Hash,t.QueryText from DRL.MonitorSQL S left join DRL.MonitorSQLText T on S.Hash=T.Hash where S.Hash='CgOlfRw7pGL4tYbiijYznQ84kmQ=' order by RunDate
No início deste ano, obtive dados de um site ativo e examinei as consultas mais custosas. Uma consulta demorava em média menos de 6 segundos, mas estava sendo chamada 14.000 vezes por dia, totalizando quase 24 horas decorridas todos os dias. Efetivamente, um núcleo estava totalmente ocupado com esta única consulta. Pior ainda, a segunda consulta que leva uma hora foi uma variação da primeira.
Data de Execução | Nome da Rotina | Visitas Totais | Tempo Total | Hash | Texto da Consulta (abreviado) |
---|---|---|---|---|---|
16/03/2019 | 14.576 | 85.094 | 5xDSguu4PvK04se2pPiOexeh6aE= | DECLARE C CURSOR FOR SELECT * INTO :%col(1) , :%col(2) , :%col(3) , :%col(4) … | |
16/03/2019 | 15.552 | 3.326 | rCQX+CKPwFR9zOplmtMhxVnQxyw= | DECLARE C CURSOR FOR SELECT * INTO :%col(1) , :%col(2) , :%col(3) , :%col(4) , … | |
16/03/2019 | 16.892 | 597 | yW3catzQzC0KE9euvIJ+o4mDwKc= | DECLARE C CURSOR FOR SELECT * INTO :%col(1) , :%col(2) , :%col(3) , :%col(4) , :%col(5) , :%col(6) , :%col(7) , | |
16/03/2019 | 16.664 | 436 | giShyiqNR3K6pZEt7RWAcen55rs= | DECLARE C CURSOR FOR SELECT * , TKGROUP INTO :%col(1) , :%col(2) , :%col(3) , .. | |
16/03/2019 | 74.550 | 342 | 4ZClMPqMfyje4m9Wed0NJzxz9qw= | DECLARE C CURSOR FOR SELECT … |
Tabela 1: Resultados reais do site do cliente
Tabelas no esquema INFORMATION_SCHEMAAssim como as estatísticas, as tabelas neste esquema controlam onde as consultas, colunas, índices etc. são usados. Normalmente, a instrução SQL é a tabela inicial e é juntada em algo como “Statements.Hash=OtherTable.Statement”.
A consulta equivalente para acessar essas tabelas diretamente para encontrar as consultas mais custosas para um dia seria…
SELECT DS.Day,Loc.Location,DS.StatCount,DS.StatTotal,S.Statement,S.Hash FROM INFORMATION_SCHEMA.STATEMENT_DAILY_STATS DS left join INFORMATION_SCHEMA.STATEMENTS S on S.Hash=DS.Statement left join INFORMATION_SCHEMA.STATEMENT_LOCATIONS Loc on S.Hash=Loc.Statement where Day='08/26/2019' order by DS.stattotal desc
Esteja você pensando em configurar um processo mais sistemático ou não, recomendo que todos com uma grande aplicação que usa SQL executem essa consulta hoje.
Se uma consulta específica parecer custosa, você pode obter o histórico executando
SELECT DS.Day, Loc.Location, DS.StatCount, DS.StatTotal, S.Statement, S.Hash
FROM INFORMATION_SCHEMA.STATEMENT_DAILY_STATS DS
left join INFORMATION_SCHEMA.STATEMENTS S
on S.Hash=DS.Statement
left join INFORMATION_SCHEMA.STATEMENT_LOCATION Loc
on S.Hash=Loc.Statement
where S.Hash='jDqCKaksff/4up7Ob0UXlkT2xKY='
order by DS.Day
Class DRL.MonitorSQLTask Extends %SYS.Task.Definition
{
Parameter TaskName = "SQL Statistics Summary";
Method OnTask() As %Status
{
set tSC=$$$OK
TRY {
do ##class(DRL.MonitorSQL).Run()
}
CATCH exp {
set tSC=$SYSTEM.Status.Error("Error in SQL Monitor Summary Task")
}
quit tSC
}
}
Class DRL.MonitorSQLText Extends %Persistent
{
/// Hash do texto da consulta
Property Hash As %String;
/// texto de consulta para hash
Property QueryText As %String(MAXLEN = 9999);
Index IndHash On Hash [ IdKey, Unique ];
}
/// Resumo das estatísticas de consulta SQL de custo muito baixo coletadas no Caché 2017.1 e posterior.
/// Consulte a documentação sobre "Detalhes da instrução SQL" para obter informações sobre os dados de origem.
/// Os dados são armazenados por data e hora para dar suporte a consultas ao longo do tempo.
/// Normalmente executado para resumir os dados da consulta SQL do dia anterior.
Class DRL.MonitorSQL Extends %Persistent
{
/// RunDate e RunTime identificam exclusivamente uma execução
Property RunDate As %Date;
/// Horário em que a captura foi iniciada
/// RunDate e RunTime identificam exclusivamente uma execução
Property RunTime As %Time;
/// Contagem do total de acessos para o período
Property TotalHits As %Integer;
/// Soma de pTime
Property SumPTime As %Numeric(SCALE = 4);
/// Rotina onde o SQL é encontrado
Property RoutineName As %String(MAXLEN = 1024);
/// Hash do texto da consulta
Property Hash As %String;
Property Variance As %Numeric(SCALE = 4);
/// Namespace onde as consultas são executadas
Property Namespace As %String;
/// A execução padrão processará os dados dos dias anteriores para um único dia.
/// Outras combinações de intervalo de datas podem ser obtidas usando o método de captura.
ClassMethod Run()
{
//Cada execução é identificada pela data / hora de início para manter os itens relacionados juntos
set h=$h-1
do ..Capture(+h,+h)
}
/// Captura estatísticas históricas para um intervalo de datas
ClassMethod Capture(dfrom, dto)
{
set oldstatsvalue=$system.SQL.SetSQLStatsJob(-1)
set currNS=$znspace
set tSC=##class(%SYS.Namespace).ListAll(.nsArray)
set ns=""
set time=$piece($h,",",2)
kill ^||TMP.MonitorSQL
do {
set ns=$o(nsArray(ns))
quit:ns=""
use 0 write !,"processing namespace ",ns
zn ns
for dateh=dfrom:1:dto {
set hash=""
set purgedun=0
do {
set hash=$order(^rINDEXSQL("sqlidx",1,hash))
continue:hash=""
set stats=$get(^rINDEXSQL("sqlidx",1,hash,"stat",dateh))
continue:stats=""
set ^||TMP.MonitorSQL(dateh,ns,hash)=stats
&SQL(SELECT Location into :tLocation FROM INFORMATION_SCHEMA.STATEMENT_LOCATIONS WHERE Statement=:hash)
if SQLCODE'=0 set Location=""
set ^||TMP.MonitorSQL(dateh,ns,hash,"Location")=tLocation
&SQL(SELECT Statement INTO :Statement FROM INFORMATION_SCHEMA.STATEMENTS WHERE Hash=:hash)
if SQLCODE'=0 set Statement=""
set ^||TMP.MonitorSQL(dateh,ns,hash,"QueryText")=Statement
} while hash'=""
}
} while ns'=""
zn currNS
set dateh=""
do {
set dateh=$o(^||TMP.MonitorSQL(dateh))
quit:dateh=""
set ns=""
do {
set ns=$o(^||TMP.MonitorSQL(dateh,ns))
quit:ns=""
set hash=""
do {
set hash=$o(^||TMP.MonitorSQL(dateh,ns,hash))
quit:hash=""
set stats=$g(^||TMP.MonitorSQL(dateh,ns,hash))
continue:stats=""
// No loop, pela primeira vez, exclua todas as estatísticas do dia para que seja executável novamente
// Mas se executarmos por um dia após os dados brutos terem sido eliminados, isso destruirá tudo
// então faça aqui, onde já sabemos que há resultados para inserir em seu lugar.
if purgedun=0 {
&SQL(DELETE FROM websys.MonitorSQL WHERE RunDate=:dateh )
set purgedun=1
}
set tObj=##class(DRL.MonitorSQL).%New()
set tObj.Namespace=ns
set tObj.RunDate=dateh
set tObj.RunTime=time
set tObj.Hash=hash
set tObj.TotalHits=$listget(stats,1)
set tObj.SumPTime=$listget(stats,2)
set tObj.Variance=$listget(stats,3)
set tObj.Variance=$listget(stats,3)
set queryText=^||TMP.MonitorSQL(dateh,ns,hash,"QueryText")
set tObj.RoutineName=^||TMP.MonitorSQL(dateh,ns,hash,"Location")
&SQL(Select ID into :TextID from DRL.MonitorSQLText where Hash=:hash)
if SQLCODE'=0 {
set textref=##class(DRL.MonitorSQLText).%New()
set textref.Hash=tObj.Hash
set textref.QueryText=queryText
set sc=textref.%Save()
}
set tSc=tObj.%Save()
//evite duplicar o texto da consulta em cada registro porque pode ser muito longo. Use uma tabela de pesquisa
//com chave no hash. Se não existir, adicione..
if $$$ISERR(tSc) do $system.OBJ.DisplayError(tSc)
if $$$ISERR(tSc) do $system.OBJ.DisplayError(tSc)
} while hash'=""
} while ns'=""
} while dateh'=""
do $system.SQL.SetSQLStatsJob(0)
}
Query Export(RunDateH1 As %Date, RunDateH2 As %Date) As %SQLQuery
{
SELECT S.Hash,RoutineName,RunDate,RunTime,SumPTime,TotalHits,Variance,RoutineName,T.QueryText
FROM DRL.MonitorSQL S LEFT JOIN DRL.MonitorSQLText T on S.Hash=T.Hash
WHERE RunDate>=:RunDateH1 AND RunDate<=:RunDateH2
}
}