Como identificar causas de latência no app com o Cloud Monitoring e o OpenCensus

Com este documento, você saberá como identificar as causas da latência de cauda usando o OpenCensus e o Monitoring para monitorar métricas e rastreamento distribuído para desenvolvedores de apps.

Ao observar como o aplicativo atende os usuários, você verá que alguns deles têm uma latência maior que os outros. As diferenças aumentam com quantidades maiores de usuários e maior uso dos recursos. Identificar e abordar as fontes da alta latência podem ajudar a expandir a base de usuários para um número maior com ótimos níveis de recursos de uso. Se você aumentar o uso de recursos, a latência de cauda será a primeira coisa a se tornar aparente devido à contenção de recursos.

Talvez haja poucos usuários com latências maiores, mas eles podem ser importantes, por exemplo, caso sejam os primeiros de um novo mercado potencial.

Neste tutorial, você verá como identificar e explicar as fontes de alta latência experimentada por esse usuários. Ele responde, em especial, as seguintes perguntas:

  • Como medir a latência de cauda com precisão?
  • Quais as principais causas da latência do aplicativo?
  • Como avaliar estratégias para reduzir a latência de cauda?

Os principais temas que respondem essas perguntas são as seguintes:

  • Como identificar as causas de imprecisão nas estimativas da métrica de monitoramento.
  • Como identificar as causas de alta latência.
  • Como reduzir a latência de cauda.

O código-fonte do app de teste pode ser encontrado em um repositório do GitHub (em inglês).

Neste documento, presumimos que você tenha familiaridade com o uso básico do OpenCensus, Cloud Monitoring, Cloud Trace, BigQuery e desenvolvimento de apps em Java.

Terminologia

métrica
Uma medida do desempenho do app.
latência
O tempo que o app leva para executar uma tarefa. Os valores de latência neste tutorial são medidos no código do aplicativo.
latência de cauda
Os valores de latência mais altos observados em um pequeno grupo de usuários. A latência de cauda pode ser definida em valores de percentil. Por exemplo, o 99º percentil é o 1% mais alto dos valores de latência para solicitações medidas em um intervalo de tempo. Para mais informações, consulte a seção "Como se preocupar com a latência de cauda" (Worrying about your Tail) no capítulo "Como monitorar sistemas distribuídos" (Monitoring Distributed Systems) do livro Engenharia de Confiabilidade do Site (Site Reliability Engineering, em inglês).
modelo de agregação
Uma representação de métricas de monitoramento que exibem a distribuição estatística das medidas coletadas. Neste tutorial, pressupõe-se um modelo de histograma com o período de latências dividido em buckets, e as contagens de cada um dos buckets gravadas para cada período de tempo. O Monitoring usa os termos "métrica de distribuição" para métricas com esse tipo de representação.

Contexto

Os proprietários de apps em nuvem geralmente monitoram uma combinação de valores de latência mediana e de cauda. A latência mediana é um bom indicador para a integridade geral do seu app. No entanto, à medida que seu aplicativo é escalonado, podem surgir alguns problemas sutis que não são facilmente observáveis por meio da latência mediana.

Compreender a latência de cauda pode ser útil para vários objetivos:

  • Detectar problemas crescentes rapidamente que não são visíveis na latência mediana.
  • Garantir que a alta utilização não seja alcançada à custa do processamento deficiente de algumas solicitações.
  • Monitorar uma frota quando um único servidor não for íntegro ou quando um caminho de código que apenas uma minoria de usuários siga não for bem processado.
  • Informar estratégias para reduzir a latência de cauda, como definir valores apropriados para tempos limites e para espera de nova tentativa. É possível ajustar o tempo limite para uma latência um pouco maior que a de 99º percentil de modo a descartar as conexões e tentar novamente, em vez de deixar as solicitações suspensas por períodos prolongados.

Pode haver muitas causas de latência de cauda. As causas comuns são:

  • variação no tamanho de payload da solicitação;
  • alta utilização da CPU;
  • estrutura de código do aplicativo não ideal;
  • variação na distância de roteamento de chamadas de rede;
  • eventuais reinicializações inesperadas do servidor com conexões interrompidas associadas e inicializações a frio;
  • armazenamento em buffer ou fila;
  • gerenciamento da conexão, como restabelecimento de conexões desatualizadas;
  • congestionamento de rede, incluindo perda de pacotes;
  • coleta de lixo ou compactação de dados que levam à suspensão do processamento de solicitações do usuário;
  • latência variável de serviços em nuvem;
  • configurações não ideais para o tempo limite de conexão.

As estratégias para identificar as causas da latência incluem o seguinte:

  • Estabelecer métodos para a acurácia precisa da latência: como a latência de cauda é, por definição, uma pequena proporção do tráfego, a acurácia das medições precisa ser entendida.
  • Implementar soluções de monitoramento, rastreamento e geração de registros: ao usar o OpenCensus e o Monitoring, um trace de período raiz é criado pelo app para que as solicitações contenham períodos filhos para diferentes medições. Períodos filho são gerados automaticamente com a integração HTTP do OpenCensus e o trace para a integração de registros é adicionado para gravar o contexto extra. Isso minimiza o outro código necessário para monitoramento e trace.
  • Explorar os dados: analise os relatórios e gráficos que mostram a cauda de solicitações de execução longa e identifique qual período filho demora mais para ser executado.
  • Identificar os motivos da latência de cauda: colete informações de fontes relacionadas que possam ajudar a explicar os motivos de longos períodos filho e compare com as anotações nos períodos de amostra.
  • Entender consultas mais detalhadas: exporte registros para o BigQuery e combine com informações de trace para detalhar e quantificar o comportamento do aplicativo.

A análise abordada nesse tutorial é o resultado da análise de sistemas de alto tráfego escalonados horizontalmente com o Cloud Storage e microsserviços. As principais causas de variabilidade na latência de cauda foram erros de medição, tamanho de payload, latência variável nos serviços em nuvem e carga nas máquinas virtuais que hospedam o aplicativo.

Os usuários da nuvem podem escolher usar métricas de integrações pré-construídas incluídas em bibliotecas, métricas compatíveis com provedores de nuvem e métricas personalizadas. Exemplos de métricas de integrações predefinidas são as integrações gRPC, HTTP e SQL do OpenCensus. O Google Cloud inclui um grande número de métricas compatíveis, que são expostas por meio do Monitoring. Uma alternativa é desenvolver um código para outras métricas personalizadas, que geralmente são contadores e temporizadores. Comparar séries temporais dessas três fontes é uma tarefa comum na análise da fonte de latência em microsserviços e no armazenamento de dados de aplicativos.

Visão geral do app de teste

O app de teste simula problemas de latência de cauda e integra-se ao OpenCensus e ao Monitoring para demonstrar as ferramentas e abordagens necessárias para identificar os problemas. O código-fonte, os arquivos de construção e as instruções são fornecidos no projeto do GitHub. O aplicativo de exemplo está escrito em Java, mas é possível aplicar este documento a outros idiomas. Para saber mais sobre a instrumentação OpenCensus de solicitações HTTP, veja a integração Jetty para Java e para Go. O app de teste é baseado neste código de exemplo do GitHub (links em inglês).

Veja a seguir um diagrama esquemático do app.

Diagrama arquitetônico do aplicativo cliente em comunicação com o Cloud Storage e o aplicativo servidor no Compute Engine.

O app cliente se comunica com o Cloud Storage e com um aplicativo do servidor hospedado em uma instância do Compute Engine.

Veja abaixo um fluxo de solicitação comum:

  1. A API do Cloud Storage recupera um arquivo JSON do Cloud Storage no aplicativo cliente.
  2. O conteúdo do arquivo é enviado ao servidor.
  3. O servidor processa os dados enviados pelo cliente para simular o tempo e os recursos usados por um aplicativo real.
  4. Uma resposta HTTP é enviada de volta ao cliente.
  5. O cliente executa o processamento downstream. Neste momento, o aplicativo de teste substitui a aritmética simples pela lógica de negócios.

Na inicialização, o app inicializa o seguinte:

  • O cliente Java Util Logging (JUL) para exportar o Cloud Logging com IDs de trace incluídos. O servidor usa um logback logging appender (em inglês) para a correlação entre trace-registro.
  • As visualizações de métricas HTTP do OpenCensus são registradas. A integração HTTP para Java (em inglês) do OpenCensus inclui várias visualizações de métricas para latência, códigos de resposta HTTP e bytes enviados e recebidos.
  • O exportador stats do Monitoring no OpenCensus envia métricas agregadas para o Monitoring em uma linha de execução em segundo plano.
  • O exportador de trace do Monitoring no OpenCensus envia períodos de trace para o Monitoring em uma linha de execução em segundo plano.
  • A API cliente do Cloud Storage faz o download dos arquivos usados para payloads HTTP.
  • Um pool de linhas de execução de apps é criado para enviar a carga para o aplicativo. Várias linhas geram uma carga maior para o servidor do que uma única linha.

Métricas de monitoramento e dados de trace são coletados e processados usando as seguintes etapas:

  1. As bibliotecas do OpenCensus coletam métricas e fazem o trace de dados.
  2. Periodicamente, o OpenCensus agrega dados de métricas e os exporta para o Monitoring. Os dados do trace são exportados para o Cloud Trace sem agregação.
  3. O OpenCensus adiciona IDs de trace às entradas do Cloud Logging. As entradas de registro são exportadas para o serviço do Cloud Logging.

É possível exportar as métricas coletadas com o OpenCensus para vários sistemas de monitoramento de back-end que fornecem armazenamento, análise, visualização e alerta. Cada sistema tem um formato de representação de dados diferente. O foco deste documento é o Monitoring.

Acurácia das métricas de monitoramento agregadas

O OpenCensus e o Monitoring oferecem ferramentas que podem ser usadas para monitorar o desempenho de apps. Para evitar uma falsa sensação de segurança nas linhas dos gráficos, é necessário entender como elas foram criadas, especialmente para as linhas que representam a latência de cauda, como o 99º percentil (p99). As seções a seguir analisam as limitações da agregação de dados de métricas.

Representação de séries temporais de métricas no Monitoring

O Monitoring calcula os percentis de latência para métricas de distribuição com base nos limites do bucket em intervalos numéricos. Esse é um método comum usado pelo Monitoring e OpenCensus em que o OpenCensus representa e exporta dados de métricas para o Monitoring. O método TimeSeries.list da API Cloud Monitoring retorna as contagens e os limites do bucket para os tipos de projeto e métrica. É possível recuperar os limites do bucket no objeto BucketOptions da API Cloud Monitoring, que pode ser testado no API Explorer para TimeSeries.list.

Para filtrar a latência do cliente HTTP do OpenCensus na API Explorer, use o seguinte filtro:

resource.type=global metric.type="custom.googleapis.com/opencensus/opencensus.io/http/client/roundtrip_latency"

O resultado inclui uma matriz de objetos de ponto de dados. O exemplo a seguir mostra o esquema de buckets e contagens de buckets:

"points": [ {
  "interval": { "startTime": "2019-02-14T18:11:24.971Z",
                "endTime": "2019-02-14T18:33:35.541Z" },
  "value": {
    "distributionValue": {
...
    "explicitBuckets": {
      "bounds": [0, 1, 2, 3, 4, 5, 6, 8, 10, 13, 16, 20, 25, 30, 40, 50, 65, 80, 100, 130, ...] }
              },
      "bucketCounts": [0, 0, 0, 0, 0, 14, 17, 164, 3, 0, 1, 0, 0, 0, 0, ...]
}}]

Cada ponto em um gráfico de Monitoramento para um valor de latência é derivado de uma distribuição. Para definir os buckets, use um fator de crescimento em vez de definir limites para cada um deles. Por exemplo, um fator de crescimento de 2,0 daria limites de bucket de 0-1, 1-2, 2-4, 4-8 (...). Para mais informações sobre as métricas do Monitoring, consulte Estrutura dos tipos de métricas.

É possível editar o gráfico para mostrar linhas para a latência dos percentis 50º (mediana), 95º e 99º de modo a exibir o seguinte gráfico de linhas.

Gráfico de latência de cauda mostrando os percentis 50º, 95º e 99º.

Para entender os dados usados para calcular esses valores de percentil, adicione o tipo de gráfico Mapa de Calor. Quando o Agregador for definido como soma, o seguinte mapa de calor de latência do cliente será exibido.

Gráfico do mapa de calor da latência de cauda.

Os mapas de calor são uma maneira de exibir os dados de distribuição armazenados pelo Monitoring. As áreas do mapa de calor correspondem aos limites do bucket recuperados usando a API REST. É possível manter o ponteiro do mouse sobre as áreas do mapa de calor para descobrir quantos pontos estão contidos em um determinado bucket para um período de tempo. Os dados usados para calcular os valores de percentil no gráfico de linhas são esparsos.

Se quiser medidas de latência mais precisas, existem algumas estratégias:

  • Adicionar mais dados. É possível gerar mais dados em experimentos, mas o tráfego para um aplicativo de produção pode não ser alto o suficiente.
  • Reduza os buckets e altere os limites para melhor se adequar aos dados. Essa é uma boa opção se você estiver criando métricas personalizadas. No entanto, talvez não seja possível fazer esses ajustes se você estiver usando dados de integrações predefinidas do OpenCensus ou coletados pelo Google Cloud a partir de seus serviços de back-end. Os limites do bucket para as integrações do OpenCensus são determinados pelos implementadores das integrações do OpenCensus em Visualizações. Por exemplo, os limites do bucket de latência do cliente HTTP são definidos na classe HttpViewConstants.java (em inglês). Da mesma forma, as métricas do Google Cloud são definidas internamente no Monitoring.
  • Use traces ou registros em vez de dados de métricas para os percentis de cauda. Essas opções são exploradas em seções posteriores deste documento.

Dados simulados

É possível comparar a precisão dos modelos de agregação com dados brutos simulados, extraídos de uma distribuição aleatória, para ver a diferença que os limites do bucket podem fazer. Neste exemplo, uma distribuição Beta (em inglês) modela a distribuição distorcida típica dos valores reais de latência. Esta é uma distribuição de uma variável aleatória contínua, sem valores menores que zero, um pico distinto e uma latência de cauda longa e decrescente. A distribuição Beta usa a função random.beta de NumPy (links em inglês) com parâmetros a = 2, b = 5 e é multiplicada por um fator constante de 70 para simular valores de latência realistas com um valor mediano de 18,5 ms. A simulação inclui 100.000 valores aleatórios da distribuição beta na planilha tail_latency_lab.ipynb (em inglês) da Colab incluída no projeto do GitHub.

O gráfico a seguir mostra que os buckets estão muito espaçados com growthFactor = 2.0 para fornecer estimativas precisas de latências de cauda.

Modelo de agregação mostrando fator de crescimento de 2,0.

O eixo linear no gráfico mostra a forma pretendida da distribuição aleatória. O gráfico a seguir mostra os limites do bucket com growthFactor = 1.4.

Modelo de agregação mostrando fator de crescimento de 1,4.

O gráfico a seguir mostra que os limites do bucket com growthFactor = 1.2 se parecem mais com a forma pretendida, mas ainda são um pouco grossos na extremidade superior da distribuição.

Modelo de agregação mostrando fator de crescimento de 1,2.

A tabela a seguir mostra estimativas fundamentadas na distribuição baseada em intervalos, em comparação com um cálculo baseado em valores brutos.

Distribuição Mediana 99º percentil
Bruto 18,5 49,5
Fator de crescimento 2,0 19,2 62,0
Fator de crescimento 1,4 18,7 53,9
Fator de crescimento 1,2 18,6 51,1

Nesse caso, é necessário um fator de crescimento de 1,2 para fornecer uma estimativa razoavelmente precisa da latência do 99º percentil. No exportador do OpenCensus, é possível converter os valores brutos em uma distribuição de amostra. Ao criar uma visualização do OpenCensus (em inglês), configure os limites do bucket. As visualizações contêm um objeto Aggregation. Para mais informações, consulte a documentação do Java ou a documentação do Go (links em inglês).

Medição da latência HTTP com o OpenCensus

Ao medir a latência HTTP, meça e registre o tempo para enviar e receber uma solicitação HTTP de um cliente para um servidor. Implemente isso no código criando uma Tag do OpenCensus (em inglês) ou usando a integração predefinida para clientes HTTP. A integração HTTP é fornecida para Go com o pacote Go HTTP e para Java com o cliente HTTP Jetty. A vantagem de usar a integração HTTP do OpenCensus é que você não precisa adicionar objetos Tag para cada métrica que quer coletar.

Como identificar fontes de latência

O aplicativo de teste descrito anteriormente gerou estresse em si mesmo, o que levou ao aumento da latência de cauda. Os seguintes problemas são demonstrados:

  • Payloads que podem ser grandes
  • Alta CPU
  • Tempos limites curtos
  • Variações no caminho do código do aplicativo com novas tentativas

Nas seções a seguir, você verá como detectar e quantificar esses problemas.

Efeito de payload grande

Para investigar o efeito do tamanho de payload, o código a seguir aumentou aleatoriamente o tamanho do payload enviado em 1 de 20 solicitações HTTP:

static byte[] getContent(String bucket) {
  BlobId blobId = null;
  int n = rand.nextInt(100);
  if (n >= 95) {
    blobId = BlobId.of(bucket, LARGE_FILE);
  } else {
    blobId = BlobId.of(bucket, SMALL_FILE);
  }
  return storage.readAllBytes(blobId);
}

Ao visualizar os traces para solicitações de latência mais alta na Lista de traces, eles podem ser correlacionados ao tamanho do payload maior.

Lista de trace mostrando solicitações de alta latência.

Para mais detalhes sobre o payload enviado e recebido, clique em Mostrar eventos. Se houver alta latência, ele mostra um tamanho de payload maior.

O Cloud Trace é melhor do que o Monitoring na identificação da latência por estes motivos:

  • O trace fornece valores de latência para solicitações, em vez de valores agregados.
  • O trace fornece o tamanho de payload para a solicitação.

Efeito da alta utilização da CPU

A alta utilização da CPU pode causar maior latência de cauda devido ao processamento simultâneo, o que pode resultar em contenção de recursos e subsequente enfileiramento da CPU para lidar com solicitações. O Monitoring fornece a utilização da CPU como uma das métricas integradas para instâncias do Compute Engine. Porém, ao executar testes de desempenho ou investigar problemas de desempenho, recomenda-se instalar o agente do Monitoring. Ele fornece mais sistemas operacionais e métricas de código aberto, incluindo memória, uso de disco e outras métricas que podem mostrar diferentes tipos de contenção de recursos. Para mais informações, consulte a lista de métricas de agente.

Gerenciar a utilização da CPU é mais fácil para apps de servidor do que de cliente por causa do escalonamento automático. No Compute Engine, os grupos de instâncias gerenciadas podem usar políticas de escalonamento automático com base na utilização média da CPU, na capacidade de serviço de balanceamento de carga ou nas métricas do Monitoring. Essas políticas adicionam máquinas virtuais para que a frota tenha a dimensão adequada para lidar com a carga. É possível que a utilização da CPU do cliente seja mais difícil de gerenciar de maneira consistente e afete a medição da latência porque os payloads precisam ser lidos na rede e desserializados, o que requer a utilização da CPU. Como a visualização de latência do app cliente determina a experiência do usuário em maior grau, o foco deste tutorial é este tipo de latência.

O monitoramento é mais apropriado do que o rastreamento para identificar o efeito da alta utilização da CPU porque ela não costuma ser o resultado de uma solicitação HTTP. No exemplo a seguir, o efeito da utilização da CPU é investigado com o uso do app de teste para executar várias linhas de código de uma só vez e executar o código do cliente em uma máquina virtual g1-small. Em seguida, a utilização da CPU e a latência são comparadas aos valores do app cliente executado em uma máquina virtual vCPU n1-standard-1.

Os gráficos a seguir mostram a mediana e a latência completa do 95º percentil para uma experiência. A taxa de solicitação foi aumentada às 3:21 da manhã, removendo uma instrução de suspensão entre solicitações para mostrar a diferença de latência com um grande aumento na utilização da CPU. Os comandos para criar as máquinas virtuais e executar os testes estão disponíveis no repositório do GitHub (em inglês).

Latência mediana por gráfico de ID da instância.

O gráfico anterior mostra a latência mediana para o cliente e o servidor durante um experimento de carga. Observe o aumento às 3:21 quando a carga foi aumentada. O gráfico a seguir mostra a latência do 95º percentil durante o mesmo teste.

95ª latência por gráfico de ID da instância.

O gráfico a seguir mostra a utilização da CPU para o teste. Também há um aumento às 3:21.

Gráfico de utilização da CPU da instância do Compute Engine.

Aumentar a taxa de solicitação afeta a latência, mas não na proporção da utilização da CPU. É surpreendente que a latência seja consistente tanto para 1 vCPU quanto para instâncias pequenas, mesmo que elas estejam sendo executadas em torno de 78% de utilização da CPU. Esse resultado sugere a possibilidade de executar uma frota com alta utilização da CPU. Um cuidado a ser tomado é que esse teste não se destina a um estudo comparativo de mercado, e os resultados podem variar durante a implementação do app.

O Cloud Profiler é uma ferramenta útil para investigar instâncias de alto consumo de CPU.

Latência devido a ramificações de código do aplicativo e valores de parâmetros

A geração de registros pode ajudar a resolver os problemas mais difíceis de latência do aplicativo. Nesta seção, você verá como combinar dados de registro e trace para investigar problemas de latência que são influenciados pela variação de caminhos de código e valores de parâmetros. Uma abordagem de trace para registro evita adicionar muitas instruções de tempo ao código. O problema comum em aplicativos baseados em microsserviços é o gerenciamento de tempos limites e de tentativas de repetição. Tempos limites prolongados podem levar a uma experiência ruim do usuário e derrubar um aplicativo se muitas conexões forem vinculadas. Recomenda-se definir um tempo limite curto, aguardar um pouco e tentar novamente. Porém, tentativas agressivas podem levar a problemas e dificultar a recuperação de incidentes. É preciso definir o tempo limite para que apenas uma pequena porcentagem de solicitações, por exemplo, menos de 1%, exija novas tentativas. No entanto, o aplicativo de teste define o tempo de nova tentativa como um valor baixo para solicitações HTTP ao servidor de teste para demonstrar novas tentativas em ação sem ter que esperar uma interrupção real.

As novas tentativas também são implementadas na biblioteca de cliente da API do Google para o Cloud Storage. Assim, não é preciso implementá-la em seu próprio código. Para mais informações sobre espera exponencial, consulte Espera exponencial truncada.

Com a integração Correlação de registro do OpenCensus no Monitoring, é possível ver as entradas de registro dos traces. Essa integração usa um Enhancer do Cloud Logging para adicionar informações de trace aos registros. Configure a geração de registros para Java e adicione a dependência opencensus-contrib-log-correlation-stackdriver1 (em inglês) do Maven à sua construção para incluí-lo no seu app. Até a publicação inicial deste tutorial, a integração do registro com o Go ainda não havia sido implementada, mas é possível solicitar o recurso (em inglês). A alternativa atual para o Go é adicionar anotações para fazer o trace de períodos com as informações necessárias.

Este é o método no app de teste para preparar, enviar e processar solicitações para o microsserviço:

private void prepareSendProcess(
    HttpClient httpClient,
    HttpMethod method,
    Function<Integer[], Integer> downStreamFn,
    String fnName)
    throws InterruptedException {
  Tracer tracer = Tracing.getTracer();
  try (Scope scope = tracer.spanBuilder("main").startScopedSpan()) {
    StopWatch s = StopWatch.createStarted();
    byte[] content = new byte[0];
    if (method == HttpMethod.POST) {
      content = TestInstrumentation.getContent(testOptions.bucket());
    }
    byte[] payload = sendWithRetry(httpClient, method, content);
    TestInstrumentation.processPayload(payload, downStreamFn, fnName);
    TestInstrumentation.recordTaggedStat(
        method.toString(), s.getTime(TimeUnit.NANOSECONDS) / 1.0e6);
  }
}

O método cria um período de escopo definido como um trace de nível superior para a solicitação que cobre o código para todas as fases da preparação, enviando a solicitação HTTP para o servidor e o processamento posterior. O método prepareSendProcess chama sendWithRetry, que une a solicitação HTTP a um mecanismo de repetição:

private byte[] sendWithRetry(HttpClient httpClient, HttpMethod method, byte[] content)
    throws InterruptedException {
  ExponentialBackOff backoff = new ExponentialBackOff.Builder()
    .setInitialIntervalMillis(500)
    .setMaxElapsedTimeMillis(5*60*1000)
    .setMultiplier(2.0)
    .setRandomizationFactor(0.5)
    .build();
  for (int i = 0; i < MAX_RETRIES; i++) {
    try {
      return sendRequest(httpClient, method, content);
    } catch (RetryableException e) {
      LOGGER.log(Level.WARNING, "RetryableException attempt: " + (i + 1) + " " + e.getMessage());
    } catch (InterruptedException e) {
      LOGGER.log(
          Level.WARNING, "InterruptedException attempt: " + (i + 1) + " " + e.getMessage());
    } catch (TimeoutException e) {
      LOGGER.log(Level.WARNING, "TimeoutException attempt: " + (i + 1) + " " + e.getMessage());
    } catch (ExecutionException e) {
      LOGGER.log(Level.WARNING, "ExecutionException attempt: " + (i + 1) + " " + e.getMessage());
    }
    try {
      Thread.sleep(backoff.nextBackOffMillis());
    } catch(IOException e) {
      throw new RuntimeException("MaxElapsedTime exceeded");
    }
  }
  throw new RuntimeException("Max retries exceeded");
}

O método a seguir envia a solicitação HTTP:

private byte[] sendRequest(HttpClient httpClient, HttpMethod method, byte[] content)
    throws InterruptedException, TimeoutException, ExecutionException, RetryableException {
  String targetURL = testOptions.targetURL();
  HttpRequest request = (HttpRequest) httpClient.newRequest(targetURL).method(method);
  if (request == null) {
    throw new RetryableException("Request is null");
  }
  if (method == HttpMethod.POST) {
    ContentProvider contentProvider =
        new StringContentProvider(new String(content, StandardCharsets.UTF_8));
    request.content(contentProvider, "application/json");
  }
  request.timeout(testOptions.httpTimeout(), TimeUnit.MILLISECONDS);
  ContentResponse response = request.send();
  int status = response.getStatus();
  LOGGER.info("Response status: " + status + ", " + method);
  if (HttpStatus.isSuccess(status)) {
    byte[] payload = response.getContent();
    LOGGER.info("Response payload: " + payload.length + " bytes");
    return payload;
  } else if (HttpStatus.isServerError(status)) {
    throw new RetryableException(response.getReason());
  }
  return new byte[0];
}

Este método cria um objeto HTTPRequest e, em seguida, adiciona o payload se uma solicitação POST for enviada. Veja a seguir um exemplo de trace detalhado.

Exemplo de trace de um objeto `HTTPRequest`.

No Monitoring, quando você clica em Mostrar registros, os registros são exibidos nos detalhes do trace. Ao clicar no ícone Trace Detail, conforme descrito em Como localizar e exibir trace, as informações de trace serão exibidas. É possível corresponder o texto do registro ao código-fonte para entender qual caminho do código foi usado para gerar o trace visualizado e descobrir detalhes de outros parâmetros, como método e resposta HTTP. O exemplo anterior mostra que ocorreu um tempo limite nesse trace. O período é subsequentemente longo porque é penalizado pela espera. Também há seis tentativas de repetição, que é o número máximo configurado.

Para visualizar os eventos de trace, clique em Show Events.

Rastreie eventos com alta latência.

A alta latência foi causada por um grande payload. O tempo limite de 8 ms foi muito baixo para lidar com esse grande volume de payload. Ele precisa ser redefinido para um valor mais alto.

É possível adicionar anotações para rastrear períodos com informações semelhantes a log statements. Porém, adicionar informações importantes sobre os diferentes caminhos de código no aplicativo aos intervalos de trace exige a adição do código para os intervalos de trace no código do aplicativo. Se a equipe de desenvolvimento não estiver familiarizada com o rastreamento, pode ser mais fácil adicionar isso nos log statements com JUL ou Logback e configurar a Geração de registros para Java. Além disso, talvez você já tenha log statements no código.

Para identificar as solicitações mais lentas, gere um relatório de análise de trace, que inclui traces de amostra em diferentes percentis de solicitação, conforme mostrado na captura de tela a seguir.

Relatório de análise de trace com traces de amostra em diferentes percentis de solicitação.

Para ver traces detalhados dos percentis mais altos, basta clicar nos traces de amostra.

Como combinar log statements e IDs de trace no BigQuery

Para pesquisar mais informações de registros, faça consultas diretamente no Visualizador de registros do Cloud Logging usando um filtro de registro.

Consulta de registro com filtro de registro.

Uma utilidade desse filtro é que ele conecta três entradas de registro com o mesmo ID de trace. Conecte entradas de registro da mesma solicitação com IDs de trace. Em seguida, é possível exportar as entradas de registro para o BigQuery com um filtro como resource.type="gce_instance".

Filtro de registro para a instância do Compute Engine.

Se você exportar os registros para um conjunto de dados chamado application_test_dataset, poderá explorá-los com a seguinte consulta:

SELECT
  TIME(timestamp) AS Time,
  SUBSTR(textPayload, 90) as Message,
  SUBSTR(trace, 31) as trace_id
FROM
  `application_test_dataset.java_log_20190328`
WHERE REGEXP_CONTAINS(textPayload, "attempt")
LIMIT 10;
...
Time             Message                            trace_id
10:59:11.782000  WARNING: TimeoutException attempt: 008a0ce...

Uma linha de dados de amostra é exibida. O resultado desta consulta fornece informações semelhantes ao visualizador de registros. Porém, agora que os dados do registro estão no BigQuery, é possível fazer consultas mais eficientes. A consulta a seguir mostra quantas solicitações tiveram um número diferente de novas tentativas:

SELECT
  RetryCount,
  COUNT(trace) AS RequestCount
FROM(
  SELECT
    COUNT(REGEXP_CONTAINS(textPayload, "attempt")) as RetryCount,
    trace
  FROM
    `application_test_dataset.java_log_20190328`
  WHERE NOT REGEXP_CONTAINS(trace, '00000000000000000000000000000000')
  Group BY trace
)
GROUP BY RetryCount
ORDER BY RetryCount DESC
LIMIT 10;
...
RetryCount RequestCount
8          13
7          180
6          2332
5          242
4          507
3          416605
1          1

A partir dos resultados da consulta, é possível ver que havia 13 solicitações com o máximo de 8 contagens de tentativas. Use os resultados desta consulta para refinar parâmetros de novas tentativas. Por exemplo, é possível aumentar o tempo limite, variar o tempo limite com o tamanho do payload ou aumentar o número máximo de tentativas.

A seguir