Resolver problemas de latência na biblioteca de cliente Java

Introdução

Se o app apresentar latência maior que o normal, baixa taxa de transferência ou tempos limite excedidos com o cliente Java Datastore, o problema pode ser causado pela configuração gRPC do lado do cliente, e não pelo back-end do Firestore/Datastore. Este guia ajuda a diagnosticar e resolver problemas comuns de limitação do lado do cliente, configurações inadequadas do pool de canais e rotatividade excessiva de canais.

Diagnóstico

Ao usar clientes Java, é fundamental ativar o registro detalhado do gRPC e do gax-java para monitorar a dinâmica do pool de canais, diagnosticar o controle de taxa, problemas de reutilização de conexão ou identificar churn excessivo de canais.

Ativar a geração de registros para clientes Java

Para ativar o registro detalhado, modifique o arquivo logging.properties da seguinte maneira:

## 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 geração de registros de saída em logging.properties para capturar esses registros:


# 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

O arquivo logging.properties pode ser aplicado usando um destes dois métodos:

1. Usando uma propriedade do sistema JVM

Adicione este argumento ao iniciar o aplicativo Java:

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

2. Carregar de maneira programática

Esse método é útil para testes de integração ou aplicativos em que a configuração de geração de registros é gerenciada no código. Verifique se esse código é executado no início do ciclo de vida do aplicativo.

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

Exemplo de geração de registros

Depois de ativar o registro detalhado, você vai ver uma mistura de mensagens de com.google.api.gax.grpc.ChannelPool e io.grpc.ChannelLogger:

Canais com provisionamento insuficiente que acionaram a expansão do pool 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 superprovisionados que acionaram a redução do pool 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

Essas entradas de registro são úteis para:

  1. Monitoramento das decisões de redimensionamento de canais
  2. Identificar a reutilização de canais x Desligamento
  3. Como identificar problemas de conectividade de transporte

Como interpretar registros para diagnóstico de sintomas

Ao resolver problemas de desempenho, como alta latência ou erros, comece ativando o registro em com.google.api.gax.grpc.ChannelPool e io.grpc.ChannelLogger. Em seguida, compare os sintomas que você está observando com os cenários comuns neste guia para interpretar os registros e encontrar uma solução.

Sintoma 1: alta latência na inicialização ou durante picos de tráfego

Você pode notar que as primeiras solicitações após o início do aplicativo são lentas ou que a latência aumenta muito sempre que o tráfego aumenta de repente.

Possível causa

Essa latência geralmente acontece quando o pool de canais está subprovisionado. Cada canal gRPC pode processar um número limitado de solicitações simultâneas (100, limitado pelo middleware do Google). Quando esse limite é atingido, novas RPCs são enfileiradas no lado do cliente, aguardando um slot disponível. Essa fila é a principal fonte de latência.

Embora o pool de canais seja projetado para se adaptar a mudanças na carga, a lógica de redimensionamento é executada periodicamente (por padrão, a cada minuto) e se expande gradualmente (por padrão, adicionando no máximo dois canais por vez). Portanto, há um atraso inerente entre o pico inicial de tráfego e a expansão do pool. A latência vai ocorrer durante esse período, enquanto novas solicitações aguardam a liberação dos canais saturados ou a adição de novos canais ao pool no próximo ciclo de redimensionamento.

Registros a serem procurados

Procure registros que indiquem que o pool de canais está sendo expandido. Essa é a principal evidência de que o cliente está reagindo a um pico de tráfego que excedeu a capacidade atual.

Registro de expansão do pool 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 pool detectou um pico de tráfego e está abrindo novas conexões para lidar com o aumento da carga. A expansão frequente, principalmente perto da inicialização, é um sinal claro de que a configuração inicial não é suficiente para sua carga de trabalho típica.

Como resolver

O objetivo é ter canais suficientes prontos antes da chegada do tráfego, evitando que o cliente precise criá-los sob pressão.

Aumento de initialChannelCount (alta latência na inicialização):

Se você observar alta latência na inicialização, a solução mais eficaz é aumentar o initialChannelCount no ChannelPoolSettings. Por padrão, esse valor é definido como 10, o que pode ser muito baixo para aplicativos que lidam com tráfego significativo na inicialização.

Para encontrar o valor certo para o aplicativo, faça o seguinte:

  1. Ative a geração de registros no nível FINEST para com.google.api.gax.grpc.ChannelPool.
  2. Execute o aplicativo em uma carga de trabalho inicial típica ou um pico de tráfego.
  3. Observe os registros de expansão do pool de canais para ver em qual tamanho o pool se estabiliza.

Por exemplo, se você encontrar registros como estes:
[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, você verá os registros:

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

Se o tamanho do pool de canais expandido se estabilizar em 8 canais e não for possível encontrar mais registros de expansão, isso indica que o aplicativo precisava de 8 canais para processar a carga de trabalho. Um bom ponto de partida é definir initialChannelCount como 8. Isso garante que as conexões sejam estabelecidas antecipadamente, reduzindo ou eliminando a latência causada pelo escalonamento dinâmico.

O objetivo é garantir que o pool tenha capacidade suficiente para lidar com o pico de carga sem enfileirar solicitações.

Aumento de minChannelCount (picos de tráfego):

Se você tiver alta latência especificamente no início dos picos de tráfego, isso significa que o tráfego está aumentando mais rápido do que o pool de canais pode criar novas conexões de forma reativa. Isso é comum para aplicativos com picos de tráfego repentinos e previsíveis.

O pool se estabiliza com um pequeno número de canais durante o tráfego normal e adiciona mais de forma proativa à medida que o tráfego aumenta para evitar a saturação. Esse processo de escalonamento leva tempo, fazendo com que as solicitações iniciais em um burst sejam enfileiradas, o que resulta em alta latência.

Aumentar minChannelCount define um valor de referência mais alto de canais permanentemente abertos. Isso garante que capacidade suficiente já esteja disponível para lidar com o burst inicial, eliminando o atraso no escalonamento e o pico de latência associado.

Aumento de maxChannelCount (picos de tráfego):

Se você observar alta latência durante picos de tráfego e seus registros mostrarem que o pool de canais está sempre no tamanho máximo (maxChannelCount), é provável que o limite atual seja muito baixo para o tráfego máximo. Por padrão, maxChannelCount é definido como 200. Para determinar um valor melhor, use o guia de configuração do pool de conexões e calcule o número ideal de conexões com base no pico de consultas por segundo (QPS) e na latência média de solicitação do aplicativo.

Sintoma 2: tempos limite intermitentes ou falhas de RPC

Às vezes, o aplicativo funciona bem na maior parte do tempo, mas ocasionalmente sofre tempos limite intermitentes ou falhas de RPC, mesmo durante períodos de tráfego normal.

Possível causa: instabilidade da rede

As conexões entre o cliente e o serviço do Datastore estão sendo descartadas. O cliente gRPC vai tentar se reconectar automaticamente, mas esse processo pode causar falhas temporárias e latência.

Registros a serem procurados

O registro mais importante para diagnosticar problemas de rede é TRANSIENT_FAILURE.

  • Registro de falha temporária:
[grpc-nio-worker-ELG-1-7] DEBUG io.grpc.ChannelLogger - [Channel<9>: (datastore.googleapis.com:443)] Entering TRANSIENT_FAILURE state
  • Interpretação: esse registro é um grande sinal de alerta que indica que o canal perdeu a conexão. Uma única falha isolada pode ser apenas uma pequena falha na rede. No entanto, se essas mensagens aparecerem com frequência ou se um canal ficar preso nesse estado, isso indica um problema significativo.

Como resolver

Investigue seu ambiente de rede. Verifique se há problemas com firewalls, proxies, roteadores ou instabilidade geral da rede entre o aplicativo e datastore.googleapis.com.

Sintoma 3: alta latência com mais de 20.000 solicitações simultâneas por cliente

Esse sintoma específico se aplica a aplicativos executados em uma escala muito alta, geralmente quando uma única instância de cliente precisa processar mais de 20.000 solicitações simultâneas. O aplicativo funciona bem em condições normais, mas,à medida que o tráfego aumenta para mais de 20.000 solicitações simultâneas por cliente, você observa uma degradação acentuada e repentina na performance. A latência aumenta significativamente e permanece alta durante todo o período de pico de tráfego. Isso ocorre porque o pool de conexões do cliente atingiu o tamanho máximo e não pode escalonar horizontalmente horizontalmente.

Possível causa

O cliente está sofrendo saturação do canal porque o pool de canais atingiu o maxChannelCount configurado. Por padrão, o pool é configurado com um limite de 200 canais. Como cada canal gRPC pode processar até 100 solicitações simultâneas, esse limite só é atingido quando uma única instância de cliente está processando aproximadamente 20.000 solicitações simultaneamente.

Quando o pool atinge esse limite, não é possível criar mais conexões. Todos os 200 canais ficam sobrecarregados, e novas solicitações são enfileiradas no lado do cliente, causando o pico acentuado na latência.

Os registros a seguir podem ajudar a confirmar que o maxChannelCount foi atingido.

Registros a serem procurados

O principal indicador é observar que o pool de canais para de se expandir no limite configurado, mesmo com a continuidade da carga.

  • Registros: você vai ver os registros anteriores do pool sendo expandidos. Com as configurações padrão, o último registro de expansão que você vê antes dos picos de latência é aquele em que o pool 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 alta latência, não haverá mais registros de "aumentando o tamanho do pool de canais". A ausência desses registros, combinada com a alta latência, é um forte indicador de que o limite de maxChannelCount foi atingido.

Como resolver

O objetivo é garantir que o pool tenha capacidade suficiente para lidar com o pico de carga sem enfileirar solicitações.

  • Aumentar maxChannelCount: a principal solução é aumentar a configuração maxChannelCount para um valor que possa oferecer suporte ao pico de tráfego do aplicativo. Consulte o guia de configuração do pool de conexões para calcular o número ideal de conexões com base no pico de consultas por segundo (QPS) e na latência média de solicitação do aplicativo.

Apêndice

As seções a seguir fornecem informações complementares para ajudar na solução de problemas.

Entender os estados do canal

Os seguintes estados de canal podem aparecer nos registros, fornecendo insights sobre o comportamento da conexão:

Estado Descrição
IDLE O canal é criado, mas não tem conexões ativas nem RPCs. Ele está aguardando o trânsito.
CONECTANDO O canal está tentando estabelecer um novo transporte de rede (conexão) com o servidor gRPC.
PRONTO O canal tem um transporte estabelecido e íntegro e está pronto para enviar RPCs.
TRANSIENT_FAILURE O canal encontrou uma falha recuperável (por exemplo, falha na rede, indisponibilidade temporária do servidor). Ele vai tentar se reconectar automaticamente.
SHUTDOWN O canal foi fechado manualmente (por exemplo, shutdown() chamada) ou devido a um tempo limite de inatividade. Não é possível iniciar novas RPCs.

Dicas

  • Se você usar uma estrutura de geração de registros estruturada, como SLF4J ou Logback, configure níveis de registro equivalentes em logback.xml ou outros arquivos de configuração do registrador. Os níveis java.util.logging serão mapeados pela fachada de geração de registros.