Resolva problemas de latência na biblioteca cliente Java

Introdução

Se a sua app tiver uma latência superior à habitual, um débito fraco ou tempos limite com o cliente Java Datastore, o problema pode ter origem na configuração gRPC do lado do cliente e não no back-end do Firestore/Datastore. Este guia ajuda a diagnosticar e resolver problemas comuns de limitação do lado do cliente, definições incorretas do conjunto de canais e rotatividade excessiva de canais.

Diagnóstico

Quando usar clientes Java, a ativação do registo detalhado do gRPC e do gax-java é fundamental para monitorizar a dinâmica do conjunto de canais, diagnosticar a limitação, os problemas de reutilização de ligações ou identificar a rotatividade excessiva de canais.

Ative o registo para clientes Java

Para ativar o registo detalhado, modifique o ficheiro logging.properties da seguinte forma:

## This tracks the lifecycle events of each grpc channel 
io.grpc.ChannelLogger.level=FINEST
## Tracks channel pool events(resizing, shrinking) from GAX level
com.google.api.gax.grpc.ChannelPool.level=FINEST

Além disso, atualize o nível de registo de saída em logging.properties para capturar estes registos:


# This could be changed to a file or other log output
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

Aplique a configuração

logging.properties pode ser aplicado através de um de dois métodos:

1. Através de uma propriedade do sistema JVM

Adicione este argumento ao iniciar a aplicação Java:

-Djava.util.logging.config.file=/path/to/logging.properties

2. Carregue de forma programática

Este método é útil para testes de integração ou aplicações em que a configuração de registo é gerida no código. Certifique-se de que este código é executado no início do ciclo de vida da aplicação.

LogManager logManager = LogManager.getLogManager();
  try (final InputStream is = Main.class.getResourceAsStream("/logging.properties")) {
logManager.readConfiguration(is);
}

Exemplo de registo

Depois de ativar o registo detalhado, vê uma combinação de mensagens de com.google.api.gax.grpc.ChannelPool e io.grpc.ChannelLogger:

Canais com aprovisionamento insuficiente que acionaram a expansão do conjunto de canais:

09:15:30.123 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6. 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.125 [grpc-nio-worker-ELG-1-5] TRACE io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] newCall() called 
09:15:30.126 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:30.127 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<7>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}} 
09:15:31.201 [grpc-nio-worker-ELG-1-6] TRACE io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] newCall() called 
09:15:31.202 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:31.203 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<8>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}

Canais com aprovisionamento excessivo que acionaram a redução do conjunto de canais:

09:13:59.609 [grpc-nio-worker-ELG-1-4] DEBUG io.grpc.ChannelLogger - [Channel<21>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<23>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}
09:14:01.998 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput drop to 0, shrinking channel pool size: 8 -> 6.
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Terminated
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Terminated

Estas entradas do registo são úteis para:

  1. Monitorizar as decisões de redimensionamento dos canais
  2. Identificar a reutilização de canais vs. Abandono
  3. Identificar problemas de conetividade de transporte

Interpretar registos para o diagnóstico de sintomas

Ao resolver problemas de desempenho, como latência elevada ou erros, comece por ativar o registo para com.google.api.gax.grpc.ChannelPool e io.grpc.ChannelLogger. Em seguida, faça corresponder os sintomas que está a observar com os cenários comuns neste guia para interpretar os registos e encontrar uma resolução.

Sintoma 1: latência elevada no arranque ou durante picos de tráfego

Pode reparar que os primeiros pedidos após o início da aplicação são lentos ou que a latência aumenta drasticamente sempre que o tráfego aumenta repentinamente.

Causa possível

Esta latência ocorre frequentemente quando o seu conjunto de canais tem um aprovisionamento insuficiente. Cada canal gRPC pode processar um número limitado de pedidos simultâneos (100 limitados pelo software intermédio da Google). Quando este limite é atingido, os novos RPCs são colocados em fila do lado do cliente, aguardando uma vaga disponível. Esta colocação em fila é a principal origem da latência.

Embora o conjunto de canais seja concebido para se adaptar às alterações na carga, a respetiva lógica de redimensionamento é executada periodicamente (por predefinição, a cada minuto) e expande-se gradualmente (por predefinição, adicionando, no máximo, 2 canais de cada vez). Por conseguinte, existe um atraso inerente entre o pico de tráfego inicial e a expansão do conjunto. A latência ocorre durante este período, enquanto os novos pedidos aguardam que os canais saturados fiquem disponíveis ou que o conjunto adicione novos canais no respetivo ciclo de redimensionamento seguinte.

Registos a procurar

Procure registos que indiquem que o conjunto de canais está a expandir-se. Esta é a prova principal de que o cliente está a reagir a um pico de tráfego que excedeu a respetiva capacidade atual.

Registo de expansão do conjunto de canais:

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6.

Interpretação: o conjunto detetou um pico de tráfego e está a abrir novas ligações para processar o aumento da carga. A expansão frequente, especialmente perto do arranque, é um sinal claro de que a configuração inicial não é suficiente para a sua carga de trabalho típica.

Como resolver

O objetivo é ter canais suficientes prontos antes da chegada do tráfego, evitando que o cliente tenha de os criar sob pressão.

Aumentar initialChannelCount (latência elevada no arranque):

Se observar uma latência elevada no arranque, a solução mais eficaz é aumentar o initialChannelCount no ChannelPoolSettings. Por predefinição, este valor está definido como 10, o que pode ser demasiado baixo para aplicações que processam um tráfego significativo no arranque.

Para encontrar o valor certo para a candidatura, deve:

  1. Ative o registo ao nível FINEST para com.google.api.gax.grpc.ChannelPool.
  2. Execute a sua aplicação sob uma carga de trabalho inicial típica ou um pico de tráfego.
  3. Observe os registos de expansão do conjunto de canais para ver em que tamanho o conjunto se estabiliza.

Por exemplo, se vir registos como os seguintes:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 80, expanding channel pool size: 4 -> 6.

e, um minuto depois, vir registos:

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 95, expanding channel pool size: 6 -> 8.

Se vir que o tamanho do conjunto de canais expandido se estabilizou em 8 canais e não encontrar mais registos de expansão, isto indica que a sua aplicação precisava de 8 canais para processar a respetiva carga de trabalho. Um bom ponto de partida seria definir o initialChannelCount como 8. Isto garante que as ligações são estabelecidas antecipadamente, reduzindo ou eliminando a latência causada pelo escalamento em tempo real.

O objetivo é garantir que o conjunto tem capacidade suficiente para processar o pico de carga sem colocar pedidos em fila de espera.

Aumentar minChannelCount (picos de tráfego):

Se sentir uma latência elevada, especificamente no início dos picos de tráfego, é um sinal de que o seu tráfego está a aumentar mais rapidamente do que o conjunto de canais consegue criar novas ligações de forma reativa. Isto é comum em aplicações com picos de tráfego previsíveis e repentinos.

O conjunto estabiliza com um pequeno número de canais durante o tráfego normal e adiciona proativamente mais à medida que o tráfego aumenta para evitar a saturação. Este processo de escalabilidade demora algum tempo, o que faz com que os pedidos iniciais numa rajada sejam colocados em fila, resultando numa latência elevada.

Aumentar o número de canais abertos permanentemente minChannelCount define uma base mais elevada. Isto garante que já existe capacidade suficiente para processar o pico inicial, eliminando o atraso no dimensionamento e o pico de latência associado.

Aumentar maxChannelCount (picos de tráfego):

Se observar uma latência elevada durante picos de tráfego e os seus registos mostrarem que o conjunto de canais está sempre no tamanho máximo (maxChannelCount), é provável que o limite atual seja demasiado baixo para o seu pico de tráfego. Por predefinição, maxChannelCount está definido como 200. Para determinar um valor melhor, use o guia de configuração do conjunto de ligações para calcular o número ideal de ligações com base nas consultas por segundo (QPS) de pico da sua aplicação e na latência média dos pedidos.

Sintoma 2: limites de tempo intermitentes ou falhas de RPC

Por vezes, a aplicação funciona bem na maioria das vezes, mas, ocasionalmente, sofre de limites de tempo intermitentes ou RPCs falhadas, mesmo durante períodos de tráfego normal.

Causa possível: instabilidade da rede

As ligações entre o cliente e o serviço Datastore estão a ser interrompidas. O cliente gRPC tenta restabelecer a ligação automaticamente, mas este processo pode causar falhas temporárias e latência.

Registos a procurar

O registo mais crítico para diagnosticar problemas de rede é TRANSIENT_FAILURE.

  • Registo de falhas temporárias:
[grpc-nio-worker-ELG-1-7] DEBUG io.grpc.ChannelLogger - [Channel<9>: (datastore.googleapis.com:443)] Entering TRANSIENT_FAILURE state
  • Interpretação: este registo é um grande sinal de alerta que indica que o canal perdeu a ligação. Uma falha única e isolada pode ser apenas uma pequena falha de rede. No entanto, se virmos estas mensagens com frequência ou um canal ficar bloqueado neste estado, significa que existe um problema subjacente significativo.

Como resolver

Investigue o seu ambiente de rede. Verifique se existem problemas com firewalls, proxies, routers ou instabilidade geral da rede entre a aplicação e datastore.googleapis.com.

Sintoma 3: latência elevada com mais de 20 000 pedidos simultâneos por cliente

Este sintoma específico aplica-se a aplicações executadas a uma escala muito elevada, normalmente quando uma única instância do cliente tem de processar mais de 20 000 pedidos simultâneos. A aplicação tem um bom desempenho em condições normais, mas,à medida que o tráfego aumenta para mais de 20 000 pedidos simultâneos por cliente, observa uma degradação acentuada e repentina no desempenho. A latência aumenta significativamente e permanece elevada durante todo o período de pico de tráfego. Isto ocorre porque o conjunto de ligações do cliente atingiu o tamanho máximo e não pode ser expandido mais.

Causa possível

O cliente está a sofrer de saturação do canal porque o conjunto de canais atingiu o limite configurado de maxChannelCount. Por predefinição, o conjunto está configurado com um limite de 200 canais. Uma vez que cada canal gRPC pode processar até 100 pedidos simultâneos, este limite só é atingido quando uma única instância do cliente está a processar aproximadamente 20 000 pedidos em simultâneo.

Quando o conjunto atinge este limite máximo, não pode criar mais ligações. Todos os 200 canais ficam sobrecarregados e os novos pedidos são colocados em fila de espera no lado do cliente, o que provoca o aumento acentuado na latência.

Os seguintes registos podem ajudar a confirmar que o maxChannelCount foi alcançado.

Registos a procurar

O indicador principal é observar que o conjunto de canais deixa de se expandir no limite configurado, mesmo que a carga continue.

  • Registos: são apresentados registos anteriores da expansão do conjunto. Com as predefinições, o último registo de expansão que vê antes dos picos de latência é aquele em que o conjunto atinge 200 canais:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - ... expanding channel pool size: 198 -> 200.
  • Indicador: durante o período de latência elevada, não verá mais registos de "expansão do tamanho do conjunto de canais". A ausência destes registos, combinada com a latência elevada, é um forte indicador de que o limite de maxChannelCount foi atingido.

Como resolver

O objetivo é garantir que o conjunto tem capacidade suficiente para processar o pico de carga sem colocar pedidos em fila de espera.

  • Aumentar maxChannelCount: a solução principal é aumentar a definição de maxChannelCount para um valor que possa suportar o pico de tráfego da aplicação. Consulte o guia de configuração do conjunto de ligações para calcular o número ideal de ligações com base nas consultas por segundo (CPS) de pico da aplicação e na latência média dos pedidos.

Anexo

As secções seguintes fornecem informações suplementares para ajudar na resolução de problemas.

Compreenda os estados dos canais

Os seguintes estados dos canais podem aparecer nos registos, fornecendo estatísticas sobre o comportamento da ligação:

Estado Descrição
IDLE O canal é criado, mas não tem ligações ativas nem RPCs. Está a aguardar tráfego.
A LIGAR O canal está a tentar ativamente estabelecer um novo transporte de rede (ligação) ao servidor gRPC.
PRONTO O canal tem um transporte estabelecido e saudável, e está pronto para enviar RPCs.
TRANSIENT_FAILURE O canal encontrou uma falha recuperável (por exemplo, falha de rede, indisponibilidade temporária do servidor). Vai tentar restabelecer a ligação automaticamente.
SHUTDOWN O canal foi fechado, manual (por exemplo, shutdown() chamou) ou devido a um tempo limite de inatividade. Não é possível iniciar novos RPCs.

Dicas

  • Se usar uma framework de registo estruturado, como SLF4J ou Logback, tem de configurar níveis de registo equivalentes em logback.xml ou noutros ficheiros de configuração do registador. Os níveis java.util.logging são mapeados pela fachada de registo.