O monitoramento revelou o consumo de recursos. E agora?
O Couchbase Server 4.5 introduziu um mecanismo para ficar de olho nas solicitações em execução, de modo que as solicitações com desempenho lento pudessem ser destacadas.
Este artigo da DZone aborda o assunto do monitoramento N1QL em grande detalhe, mas a questão agora é: temos os desordeiros, como verificamos suas demandas?
Em termos gerais, todo mecanismo de banco de dados fornece meios para analisar o plano de consulta usado por uma solicitação para retornar dados, na forma de algum tipo de instrução EXPLAIN, mas isso faz exatamente o que a palavra diz: explica o plano, mas não diz de fato qual parte do plano está se comportando mal, usando números concretos.
Administradores de banco de dados experientes podem dizer, usando uma mistura de, bem, experiência, heurística e intuição, como um plano específico poderia ser aprimorado, mas esse conjunto de habilidades específicas requer uma quantidade substancial de treinamento e, para ser justo, um certo grau de adivinhação também está envolvido.
Podemos fazer melhor?
Entrar na criação de perfil
O Couchbase 5.0 introduz, entre outras coisas, a capacidade de coletar métricas em todas as partes móveis de solicitações individuais.
Quando o recurso está ativado, as informações de criação de perfil são retornadas pela solicitação após o documento de resultados e ficam disponíveis nos espaços de chave do sistema para processamento posterior.
Essa métrica mostra a árvore de execução em detalhes, com informações como o tempo gasto em cada operador e em cada fase de processamento, bem como os documentos ingeridos e digeridos.
Munidos desse conjunto de dados, os administradores de banco de dados podem identificar facilmente os operadores caros em uma solicitação e resolver o problema, por exemplo, criando o índice correto para minimizar o número de chaves qualificadas retornadas pela varredura do índice.
Mas vamos começar do início.
Ativação da criação de perfil
O uso mais frequente da criação de perfis é para entender por que um determinado extrato é lento.
Dessa forma, a declaração lenta já foi identificada e provavelmente está sendo testada em um ambiente sandbox - a única informação necessária é o texto da declaração culpada e não há necessidade de coletar perfis de qualquer outra coisa.
Por outro lado, um nó de produção pode estar passando por um patch lento.
A solicitação culpada não foi identificada e é importante coletar todas as informações de diagnóstico disponíveis imediatamente para que, assim que a solicitação lenta for identificada, a criação de perfil já esteja disponível sem a necessidade de executar novamente a instrução ofensiva.
No nível da solicitação
Isso pode ser feito com o perfil parâmetro da API REST da solicitação, passado para o serviço de consulta junto com a instrução da solicitação - ideal para investigar instruções individuais.
Isso pode ser feito no nível mais baixo possível, como exemplificado a seguir enrolar exemplo
1 |
enrolar http://localhost:8093/consulta/serviço -d 'statement=select * from `travel-sample`&profile=timings' -u Administrador:senha |
Ou, mais simplesmente, de uma sessão de cbq shell
1 |
cbq> \definir -perfil horários; |
O Query Workbench habilita a criação de perfil por padrão, como veremos mais adiante.
O perfil
assume três valores: desligado
(o padrão), fases
e horários
.
A primeira, como esperado, apenas desativa o recurso.
A segunda permite um resumo dos tempos de execução para cada fase da solicitação, enquanto a última oferece o nível mais alto de informações disponíveis: tempos completos por operador de execução.
Em nível de serviço
Quando a criação de perfil é necessária em todas as solicitações, ela pode ser ativada na inicialização do nó por meio do -Perfil
parâmetro da linha de comando.
Ele usa os mesmos argumentos que o parâmetro da API REST de consulta, com o mesmo significado.
Qualquer solicitação que não especifique nenhum nível de criação de perfil no nível da API REST assume o valor do argumento da linha de comando como a opção selecionada.
Em tempo real
Quando os clusters de produção estão mostrando sinais de fadiga, é possível alterar a configuração do perfil de serviço de consulta em tempo real por meio do ponto de extremidade REST /admin/settings, por exemplo
1 |
enrolar http://localhost:8093/administrador/configurações -d '{"profile": "timings"}' -u Administrador:senha |
Isso tem o mesmo efeito que inicializar o serviço de consulta usando o comando -Perfil
no entanto, ele também se aplica a solicitações que já foram iniciadas, o que significa que, quando as solicitações não especificarem uma configuração de perfil de nível de consulta, o nível recém-definido será considerado a opção selecionada.
É importante saber que as informações de perfil são coletadas o tempo todo - as opções acima apenas determinam se e quantas informações são relatadas.
Portanto, é possível ativar retroativamente a criação de perfis para solicitações já iniciadas, o que significa que, ao perceber uma lentidão no sistema, um DBA pode criar perfis para todas as solicitações já em execução, sem precisar reenviar nenhuma das solicitações ou investigar primeiro qual delas está com desempenho ruim!
Obtenção de informações de perfil
As informações de perfil de solicitação individual são disponibilizadas como um subdocumento json que detalha a árvore de execução.
Em termos gerais, trata-se de uma estrutura com o mesmo formato e conteúdo muito próximo do EXPLICAR mas acrescido de estatísticas de execução.
Isso pode ser acessado pelo aplicativo cliente, por meio do documento de resposta (que é útil para investigações pontuais), e por terceiros, por meio dos espaços-chave do sistema, o que é útil, por exemplo, para comparar diferentes variações da mesma declaração ou a execução da mesma declaração com valores diferentes para espaços reservados.
Da resposta da solicitação
O exemplo a seguir mostra a execução de uma instrução no cbq, com a criação de perfil ativada
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 |
cbq> \definir -perfil horários; cbq> selecionar * de `viagens-amostra` limite 1; { "requestID": "eff5d221-fc0d-459f-9de3-727747368a3e", "assinatura": { "*": "*" }, "resultados": [ { "amostra de viagem": { "indicativo": "MILE-AIR", "país": "Estados Unidos", "iata": "Q5", "icao": "MLA", "id": 10, "name" (nome): "40 milhas aéreas", "tipo": "companhia aérea" } } ], "status": "sucesso", "métricas": { "elapsedTime" (tempo decorrido): "65.441768ms", "executionTime": "65.429661ms", "resultCount": 1, "resultSize": 300 }, "profile" (perfil): { "phaseTimes": { "autorizar": "1.544104ms", "fetch" (buscar): "1.776843ms", "instanciar": "777.209µs", "parse" (analisar): "840.796µs", "plano": "53.121896ms", "primaryScan": "6.741329ms", "executar": "10.244259ms" }, "phaseCounts": { "fetch" (buscar): 1, "primaryScan": 1 }, "phaseOperators": { "autorizar": 1, "fetch" (buscar): 1, "primaryScan": 1 }, "executionTimings": { "#operator": "Sequência", "#stats": { "#phaseSwitches": 2, "execTime": "3.41µs", "kernTime": "10.23877ms" }, "~crianças": [ { "#operator": "Authorize" (Autorizar), "#stats": { "#phaseSwitches": 4, "execTime": "3.268µs", "kernTime": "8.651859ms", "servTime": "1.540836ms" }, "privilégios": { "Lista": [ { "Alvo": "default:travel-sample" (padrão: amostra de viagem), "Priv": 7 } ] }, "~child": { "#operator": "Sequência", "#stats": { "#phaseSwitches": 3, "execTime": "8.764µs", "kernTime": "8.639269ms" }, "~crianças": [ { "#operator": "Sequência", "#stats": { "#phaseSwitches": 2, "execTime": "8.037µs", "kernTime": "8.591094ms" }, "~crianças": [ { "#operator": "PrimaryScan", "#stats": { "#itemsOut": 1, "#phaseSwitches": 7, "execTime": "6.254658ms", "kernTime": "1.609µs", "servTime": "486.671µs" }, "índice": "def_primary", "espaço-chave": "amostra de viagem", "limite": "1", "namespace": "default", "usando": "gsi" }, { "#operator": "Buscar", "#stats": { "#itemsIn": 1, "#itemsOut": 1, "#phaseSwitches": 11, "execTime": "48.055µs", "kernTime": "6.766558ms", "servTime": "1.728788ms" }, "espaço-chave": "amostra de viagem", "namespace": "default" }, { "#operator": "Sequência", "#stats": { "#phaseSwitches": 5, "execTime": "1.675µs", "kernTime": "8.580305ms" }, "~crianças": [ { "#operator": "InitialProject" (Projeto inicial), "#stats": { "#itemsIn": 1, "#itemsOut": 1, "#phaseSwitches": 9, "execTime": "4.113µs", "kernTime": "8.555317ms" }, "result_terms": [ { "expr": "self", "estrela": verdadeiro } ] }, { "#operator": "FinalProject" (Projeto Final), "#stats": { "#itemsIn": 1, "#itemsOut": 1, "#phaseSwitches": 11, "execTime": "2.201µs", "kernTime": "8.570215ms" } } ] } ] }, { "#operator": "Limite", "#stats": { "#itemsIn": 1, "#itemsOut": 1, "#phaseSwitches": 11, "execTime": "3.244µs", "kernTime": "8.621338ms" }, "expr": "1" } ] } }, { "#operator": "Fluxo", "#stats": { "#itemsIn": 1, "#itemsOut": 1, "#phaseSwitches": 9, "execTime": "8.647µs", "kernTime": "10.225903ms" } } ], "~versões": [ "2.0.0-N1QL", "5.1.0-1256-enterprise" ] } } } |
Observe que a resposta agora inclui um perfil
seção, mostrando informações de fase, como phaseTimes
, phaseCounts
, phaseOperators
(respectivamente, o tempo gasto na execução de cada fase, o número de documentos processados por fase e o número de operadores que executam cada fase) - as únicas informações fornecidas quando perfil
é definido como fases
- bem como um executionTimings
subseção.
Dos espaços de chaves do sistema
As consultas nos espaços de chave do sistema podem retornar informações de criação de perfil de solicitação, desde que a criação de perfil esteja ativada para essas solicitações no momento da consulta.
Aqui está um exemplo rápido:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 |
cbq> selecionar * de sistema:active_requests; { "requestID": "7f500733-faba-45dc-8015-3127e305e86e", "assinatura": { "*": "*" }, "resultados": [ { "active_requests": { "elapsedTime" (tempo decorrido): "87.698587ms", "executionTime": "87.651658ms", "nó": "127.0.0.1:8091", "phaseCounts": { "primaryScan": 1 }, "phaseOperators": { "autorizar": 1, "fetch" (buscar): 1, "primaryScan": 1 }, "phaseTimes": { "autorizar": "1.406584ms", "fetch" (buscar): "15.793µs", "instanciar": "50.802µs", "parse" (analisar): "438.25µs", "plano": "188.113µs", "primaryScan": "75.53238ms" }, "remoteAddr": "127.0.0.1:57711", "requestId": "7f500733-faba-45dc-8015-3127e305e86e", "requestTime": "2017-10-09 19:36:04.317448352 +0100 BST", "scanConsistency": "unbounded" (ilimitado), "estado": "em execução", "declaração": "select * from system:active_requests;", "userAgent": "Go-http-client/1.1 (godbc/2.0.0-N1QL)", "usuários": "Administrador" } } ], "status": "sucesso", "métricas": { "elapsedTime" (tempo decorrido): "88.016701ms", "executionTime": "87.969113ms", "resultCount": 1, "resultSize": 1220 } } |
O registro da seleção em system:active_requests
em si é uma informação de fase esportiva.
Se a criação de perfil estiver definida como horários
A árvore de execução detalhada é relatada como plano acessível por meio do meta()
função:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 |
cbq> selecionar *, meta().plano de sistema:active_requests; { "requestID": "53e3b537-c781-402a-b3ae-49cd4ad4b4ac", "assinatura": { "*": "*", "plano": "json" }, "resultados": [ { "active_requests": { "elapsedTime" (tempo decorrido): "58.177768ms", "executionTime": "58.163366ms", "nó": "127.0.0.1:8091", "phaseCounts": { "primaryScan": 1 }, "phaseOperators": { "autorizar": 1, "fetch" (buscar): 1, "primaryScan": 1 }, "phaseTimes": { "autorizar": "674.937µs", "fetch" (buscar): "8.26µs", "instanciar": "20.294µs", "parse" (analisar): "985.136µs", "plano": "69.766µs", "primaryScan": "47.460796ms" }, "remoteAddr": "127.0.0.1:57817", "requestId": "53e3b537-c781-402a-b3ae-49cd4ad4b4ac", "requestTime": "2017-10-09 19:36:31.374286818 +0100 BST", "scanConsistency": "unbounded" (ilimitado), "estado": "em execução", "declaração": "select *, meta().plan from system:active_requests;", "userAgent": "Go-http-client/1.1 (godbc/2.0.0-N1QL)", "usuários": "Administrador" }, "plano": { "#operator": "Sequência", "#stats": { "#phaseSwitches": 1, "execTime": "818ns", "kernTime": "57.105844ms", "estado": "kernel" }, "~crianças": [ { "#operator": "Authorize" (Autorizar), "#stats": { "#phaseSwitches": 3, "execTime": "3.687µs", "kernTime": "56.428974ms", "servTime": "671.25µs", "estado": "kernel" }, "privilégios": { "Lista": [ { "Priv": 4, "Alvo": "#system:active_requests" } ] }, "~child": { "#operator": "Sequência", "#stats": { "#phaseSwitches": 1, "execTime": "1,35µs", "kernTime": "56.439225ms", "estado": "kernel" }, "~crianças": [ { "#operator": "PrimaryScan", "#stats": { "#itemsOut": 1, "#phaseSwitches": 7, "execTime": "19.430376ms", "kernTime": "2.821µs", "servTime": "28.03042ms" }, "índice": "#primary", "espaço-chave": "active_requests", "namespace": "#system", "usando": "sistema" }, { "#operator": "Buscar", "#stats": { "#itemsIn": 1, "#phaseSwitches": 7, "execTime": "8.26µs", "kernTime": "47.474703ms", "servTime": "8.946656ms", "estado": "serviços" }, "espaço-chave": "active_requests", "namespace": "#system" }, { "#operator": "Sequência", "#stats": { "#phaseSwitches": 1, "execTime": "638ns", "kernTime": "56.466039ms", "estado": "kernel" }, "~crianças": [ { "#operator": "InitialProject" (Projeto inicial), "#stats": { "#phaseSwitches": 1, "execTime": "1.402µs", "kernTime": "56.471719ms", "estado": "kernel" }, "result_terms": [ { "expr": "self", "estrela": verdadeiro }, { "expr": "(meta(`active_requests`).`plan`)" } ] }, { "#operator": "FinalProject" (Projeto Final), "#stats": { "#phaseSwitches": 1, "execTime": "1.105µs", "kernTime": "56.49816ms", "estado": "kernel" } } ] } ] } }, { "#operator": "Fluxo", "#stats": { "#phaseSwitches": 1, "execTime": "366ns", "kernTime": "57.250988ms", "estado": "kernel" } } ], "~versões": [ "2.0.0-N1QL", "5.1.0-1256-enterprise" ] } } ], "status": "sucesso", "métricas": { "elapsedTime" (tempo decorrido): "59.151099ms", "executionTime": "59.136024ms", "resultCount": 1, "resultSize": 6921 } } |
As informações mostradas aqui em system:active_requests
também é acessível a partir de system:completed_requests
supondo que a solicitação em questão, ao ser concluída, esteja qualificada para armazenamento em system:completed_requests
e a criação de perfil foi ativada.
Observe que as informações de tempo retornadas por system:active_requests
é atualo que significa que ele inclui os tempos de execução acumulados até o momento: um segundo select em system:active_requests
pode, portanto, ser usado para determinar o custo de um operador específico no intervalo de tempo decorrido entre as duas seleções.
Informações fornecidas
Conforme mostrado no exemplo a seguir
1 2 3 4 5 6 7 8 9 10 11 12 13 |
{ "#operator": "Buscar", "#stats": { "#itemsIn": 1, "#phaseSwitches": 7, "execTime": "8.26µs", "kernTime": "47.474703ms", "servTime": "8.946656ms", "estado": "serviços" }, "espaço-chave": "active_requests", "namespace": "#system" } |
O documento da árvore de execução informa, para cada operador, o número de documentos ingeridos e digeridos (#itemsIn
e #itemsOut
), tempo gasto na execução do código do operador (execTime
), aguardando agendamento (kernTime
) e aguardando que os serviços forneçam dados (servTime
), o número de vezes que o operador mudou de estado (executando, aguardando agendamento, aguardando dados) e o estado atual (supondo que a solicitação ainda não tenha sido concluída).
As estatísticas do operador são propositalmente muito detalhadas por natureza: cada medida individual é conhecida por se destacar durante investigações específicas de desempenho, e não tenho vergonha de dizer que elas também foram usadas de forma proveitosa durante minhas próprias sessões de depuração!
Para dar uma ideia do tipo de coisas que podem ser alcançadas, vamos considerar phaseSwitches
.
Suponha que, depois de coletar perfis duas vezes, o número de phaseSwitches
para uma determinada operadora não aumentou.
Esse operador específico pode não estar operando corretamente: o estado ficar preso em "serviços"dependendo do operador, ele pode estar esperando no armazenamento de documentos (para uma busca) ou no serviço de indexação (para uma varredura).
Talvez o serviço relevante esteja inativo ou travado?
Por outro lado, se estiver preso em "kernel"Se o operador não aceitar dados, é possível que um consumidor no pipeline não esteja aceitando dados ou que a máquina esteja tão carregada que o programador não esteja encontrando fatias de tempo para o operador.
A próxima seção abordará alguns sinais reveladores de alguns cenários comuns, primeiro os cenários mais prováveis.
Interpretação de perfis
Qualquer operador: tempo elevado do núcleo
Esse é um gargalo em um operador mais adiante no pipeline.
Procure um operador com alto tempo de execução ou de serviços.
Se não for possível encontrar um, o kernel do tempo de execução está lutando para agendar operadores: o nó de consulta está sobrecarregado e adicionar um novo pode ser útil.
Fetches, Joins, Scans: tempos de serviço elevados
Isso pode indicar um serviço externo estressado.
Uma confirmação disso viria de uma baixa taxa de mudança em #itemsOut
Embora isso exija a obtenção do mesmo perfil mais de uma vez, o que pode ser inconveniente (ou impossível, se a solicitação já tiver sido concluída).
Como alternativa, procure os sintomas descritos a seguir.
Fetches e Joins: alto tempo de serviço por documento recebido
As buscas de documentos individuais devem ser rápidas.
Dividir servTime
por #itemsOut
deve sempre gerar tempos de busca substancialmente menores que um milissegundo.
Se não for, o armazenamento de documentos está sob estresse.
Para deixar claro, não é necessariamente a solicitação com perfil que está colocando o armazenamento sob estresse: o mais provável é que o problema seja a carga geral do serviço.
Uma maneira de verificar se a carga geral é o problema, pelo menos durante a execução de testes de estresse, é reduzir o número de clientes de trabalho: em um armazenamento sobrecarregado, os tempos de busca individuais permanecem constantes à medida que o número de clientes diminui e só começam a melhorar quando a carga chega a um nível que pode ser mais facilmente manipulado.
Fetches: alto número de documentos ingeridos
Um bom plano de consulta deve usar um índice que produza apenas as chaves de documento relevantes para a solicitação.
Se o número de chaves passadas para o operador Fetch for muito maior do que o número final de documentos retornados ao cliente, o índice escolhido não é suficientemente seletivo.
Digitalizações: grande número de documentos produzidos
Essa é a contrapartida do sintoma anterior: o índice escolhido não é suficientemente seletivo. Considere a possibilidade de criar um índice para que predicados adicionais possam ser enviados para a varredura do índice.
Une: baixo número de documentos ingeridos, alto número de documentos produzidos
Mais uma vez, definitivamente um caminho de índice errado: a junção deveria produzir tantos resultados em primeiro lugar?
Filtros: alto número de documentos ingeridos, baixo número de documentos produzidos
Outro indicador de "índice escolhido definitivamente não é seletivo o suficiente".
Filtros: alto tempo de execução
Isso nunca deve acontecer e, se acontecer, é mais provável que seja acompanhado pelo sintoma anterior.
Além de o índice não ser seletivo o suficiente e retornar muitas chaves de documentos, a avaliação de todas as expressões na cláusula WHERE para tantos documentos está se mostrando bastante cara!
Projeção: alto tempo de execução
Novamente, um improvável: o serviço de consulta está lutando para reunir os documentos de resultados para a solicitação.
Quantos termos você tem na cláusula de projeção do comando SELECT? Corte alguns!
Você tem expressões complexas?
Stream: alto tempo de execução
A solicitação está se esforçando para converter o resultado em formato JSON e enviá-lo ao cliente.
O bonito
O parâmetro REST pode ter sido definido como verdadeiro
por engano.
A lista de projeções pode ter um número excessivo de termos.
Como alternativa, há um problema de rede ou os documentos de resultado que estão sendo enviados são grandes demais para a rede suportar.
Controles
Muitas vezes, o comportamento da solicitação depende de valores de espaço reservado, portanto, seria muito útil capturar valores de espaço reservado junto com os perfis.
Isso pode ser feito com o controles
API REST de consulta, parâmetro de linha de comando e /admin/settings REST, que recebe um verdadeiro
ou falso
valor.
Seu comportamento é exatamente o mesmo que o do perfil
e pode ser definido por solicitação, na inicialização, em tempo real, em todo o serviço, sendo também aplicado retrospectivamente a solicitações em execução que não tenham especificado uma configuração.
Os parâmetros nomeados e posicionais serão relatados na saída da solicitação em sua própria seção de controle:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 |
cbq> \definir -controles verdadeiro; cbq> \definir -$a 1; cbq> selecionar * de padrão onde a = $a; { "requestID": "bf6532d6-f009-4e55-b333-90e0b1d17283", "assinatura": { "*": "*" }, "resultados": [ ], "status": "sucesso", "métricas": { "elapsedTime" (tempo decorrido): "9.864639ms", "executionTime": "9.853572ms", "resultCount": 0, "resultSize": 0 }, "controles": { "namedArgs": { "a": 1 } } } |
bem como nos espaços de chaves do sistema (embora, diferentemente dos perfis, não seja necessário acessar nenhum anexo por meio do meta()
função):
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 |
cbq> selecionar * de sistema:active_requests; { "requestID": "dced4ef6-7a31-4291-a15d-030ac67b033c", "assinatura": { "*": "*" }, "resultados": [ { "active_requests": { "elapsedTime" (tempo decorrido): "69.458652ms", "executionTime": "69.434706ms", "namedArgs": { "a": 1 }, "nó": "127.0.0.1:8091", "phaseCounts": { "primaryScan": 1 }, "phaseOperators": { "autorizar": 1, "fetch" (buscar): 1, "primaryScan": 1 }, "remoteAddr": "127.0.0.1:63095", "requestId": "dced4ef6-7a31-4291-a15d-030ac67b033c", "requestTime": "2017-10-09 20:51:33.400550619 +0100 BST", "scanConsistency": "unbounded" (ilimitado), "estado": "em execução", "declaração": "select * from system:active_requests;", "userAgent": "Go-http-client/1.1 (godbc/2.0.0-N1QL)", "usuários": "Administrador" } } ], "status": "sucesso", "métricas": { "elapsedTime" (tempo decorrido): "69.62242ms", "executionTime": "69.597934ms", "resultCount": 1, "resultSize": 977 } } |
Perfis visuais
Uma maneira bastante fácil de acessar informações detalhadas de criação de perfil para declarações individuais, sem precisar fazer nada de especial, é por meio da guia Query (Consulta) na interface do usuário do Admin Console.
O Query WorkBench ativa a criação de perfis por padrão e, após a conclusão da solicitação, os tempos e as contagens de documentos ficam prontamente disponíveis em forma de gráfico, clicando no botão "plan".
As operadoras são codificadas por cores de acordo com o custo e, ao passar o mouse sobre cada operadora, aparecem várias informações sobre os horários brutos.
As Preferências permitem alterar as configurações de criação de perfil, bem como outras configurações, como parâmetros nomeados e posicionais.
A criação de perfis é muito mais do que apenas criar perfis
As informações de perfil e controles também podem ser usadas para um monitoramento mais detalhado.
Por exemplo, para localizar solicitações com qualquer operador que produza quantidades excessivas de documentos, pode-se usar
1 2 |
selecionar * de sistema:active_requests onde qualquer o dentro de meta().plano satisfaz o.`#itemsOut` > 100000 final; |
(altere o limite dos documentos de saída conforme necessário).
O exemplo é bastante simplista e, na verdade, poderia ser feito com mais facilidade usando phaseCounts
, mas troque a cláusula ANY para satisfazer
1 2 3 |
o.`#operador` = "Buscar" e o.Espaço-chave = "viagens-amostra" e o.`#estatísticas`.`#itemsOut` > 100000 |
e pronto!, as solicitações que carregam um espaço de chave específico são reveladas.
Da mesma forma, a localização de qualquer solicitação que tenha usado um valor específico para qualquer parâmetro nomeado pode ser obtida com
1 2 |
selecionar * de sistema:active_requests onde namedArgs.`alguns parâmetro` = "alvo valor"; |
(substitua "algum parâmetro" e "valor-alvo" pelos valores necessários!)
As possibilidades são infinitas.
Uma última consideração
As informações de criação de perfil são mantidas na própria árvore de execução, que usa uma quantidade razoável de memória.
Isso, por si só, não é um problema, mas lembre-se de que quando uma solicitação de execução lenta se torna elegível para armazenamento em system:completed_requests
e perfil
é definido como horários
a árvore de execução inteira também será armazenada.
Isso, novamente, não é um problema em si. No entanto, pode se tornar um problema se system:completed_requests
é definido para registrar todas as solicitações, não tem limite, e todas as solicitações têm perfil
definido como horários
Nesse caso, o uso da memória pode crescer além do razoável, porque você está armazenando todos os tempos de todas as solicitações já executadas desde o início dos tempos!
Felizmente, as configurações padrão para system:completed_requests
O registro em log significa que você não terá problemas sem saber e, de qualquer forma, não estou sugerindo que você deva ser econômico com a quantidade de horas que registra, mas esse é um caso em que o excesso pode ser doloroso.
Você foi avisado.
Conclusões
A partir da versão 5.0 do Couchbase Server, o N1QL oferece ferramentas especializadas para analisar e analisar os tempos de execução com profundidade considerável.
Foram dados exemplos de como acessar a funcionalidade e interpretar os dados coletados.