如何排查应用程序负载均衡器的 TargetResponseTime 指标增加问题？

简短描述

TargetResponseTime 是从请求离开负载均衡器之时起，到收到来自目标的响应之时止期间经过的时间（以秒为单位）。这相当于 Application Load Balancer 访问日志中的 target_processing_time 字段。

TargetResponseTime 增加的可能原因包括：

• 主机运行不正常。
• 请求过多导致后端实例不堪重负。
• 后端实例上的 CPU 利用率高。
• 一个或多个目标存在故障。
• 在后端实例上运行的 Web 应用程序依赖关系存在问题。

解决方法

主机运行不正常

验证所有应用程序负载均衡器目标是否正常。请参阅如何排查和修复失败的应用程序负载均衡器运行状况检查？

请求过多导致后端实例不堪重负

检查 Application Load Balancer 的 Amazon CloudWatch RequestCount 和 ActiveConnectionCount 指标的 Sum（总和）统计数据。如果该总和的上升恰好与 TargetResponseTime 的增加相符，则可能说明后端实例无力承受请求负载。

要解决此问题，请为您的后端实例配置一个 Auto Scaling 组。请参阅教程：设置具有扩展和负载均衡功能的应用程序。

后端实例上的 CPU 利用率高

检查后端实例的 CloudWatch CPUUtilization 指标。如果 CPU 利用率很高，或者利用率出现峰值，请将您的实例升级到更大的实例类型。

一个或多个目标存在故障

如果目标存在故障，请按照以下步骤解决问题：

1.    为您的负载均衡器启用访问日志记录。

2.    当 TargetResponseTime 较高时，下载该时间范围内的访问日志。例如，要使用 AWS Command Line Interface（AWS CLI）下载从 2022-02-01T03:00 至 2022-02-01T03:35 之间的访问日志：

aws s3 cp s3://bucket-name[/prefix]/AWSLogs/aws-account-id/elasticloadbalancing/region/2022/02/01/ ./alblogs --recursive --exclude "*" --include "*20220201T03[0123]*"

**注意：**请将 bucket-name 替换为存储桶的名称，将 aws-account-id 替换为您的 AWS 账户 ID，将 region 替换为您的账户所在的 AWS 区域。

3.    使用命令行工具分析访问日志：

Elastic Load Balancing（ELB）访问日志采用 .gzip 压缩格式。

可选步骤：要提取日志，请使用以下命令：

$   gzip -dr ./alblogs

示例场景

要获取 target_processing_time 的最大延迟值，请运行以下命令。

压缩后的日志文件：

$zcat *.log.gz | awk '$7 != -1' | awk 'BEGIN{a=0}{if ($7>0+a) a=$7} END{print a}'

未压缩的日志文件：

$cat *.log | awk '$7 != -1' | awk 'BEGIN{a=0}{if ($7>0+a) a=$7} END{print a}'

–或者–

要计算每个目标的 target_processing_time ">=N" 秒的请求数，请用需要的秒数修改 N。

适用于压缩后的日志文件的示例命令：

$zcat *.log.gz | awk '{if($7 >= N){print $5}}' | sort | uniq -c

适用于未压缩的日志文件的示例命令：

$cat *.log | awk '{if($7 >= N){print $5}}' | sort | uniq -c

示例输出：

12 10.10.20.111:80 
12 10.10.60.163:80
254 10.10.70.7:80
6 10.10.80.109:80
20656 10.3.19.141:80

在前面的示例中，TargetResponseTime 增加的主要原因来自 IP 地址为 10.3.19.141 的目标。在这种情况下，应检查该目标的操作系统（OS）和 Web 应用程序。

在后端实例上运行的 Web 应用程序依赖关系存在问题

在目标上运行抓包命令以确定目标响应的延迟。对于 Linux 操作系统，请使用 tcpdump。

要捕获完整的 POST HTTP 传入和传出，包括端口 TCP/80 上的 HTTP 请求和响应：

tcpdump -i any -ns 0 -A 'tcp dst port 80 and tcp[((tcp[12:1] & 0xf0) >> 2):4] = 0x504F5354 or tcp[((tcp[12:1] & 0xf0) >> 2):4] = 0x48545450 or tcp[((tcp[12:1] & 0xf0) >> 2):4] = 0x3C21444F'

要捕获完整的 GET HTTP 传入和传出，包括端口 TCP/80 上的 HTTP 请求和响应：

tcpdump -i any -ns 0 -A 'tcp dst port 80 and tcp[((tcp[12:1] & 0xf0) >> 2):4] = 0x47455420 or tcp[((tcp[12:1] & 0xf0) >> 2):4] = 0x48545450 or tcp[((tcp[12:1] & 0xf0) >> 2):4] = 0x3C21444F'

示例输出：

14:04:12.186593 IP 10.10.30.219.13000 > 10.10.60.10.http: Flags [P.], seq 641705534:641705793, ack 1587610435, win 106, options [nop,nop,TS val 1165674323 ecr 263805247],
    length 259: HTTP: GET / HTTP/1.1 E..7."@...I. .. < 2..P&?.>^..C...j9...... Ez.S..Y?GET / HTTP/1.1 X-Forwarded-For: 54.66.76.204 X-Forwarded-Proto: http X-Forwarded-Port: 80 Host: labalbinternet-1236602672.ap-southeast-2.elb.amazonaws.com
    X-Amzn-Trace-Id: Root=1-6254355c-15db4904726649b66a1e47d7 User-Agent: curl/7.79.1 Accept: */* ................

14:04:21.187892 IP 10.10.60.10.http > 10.10.30.219.13000: Flags [P.], seq 1:592, ack 259, win 488, options [nop,nop,TS val 263814250
    ecr 1165674323], length 591: HTTP: HTTP/1.1 200 OK E...\.@.@.l. < ...P2.^..C&?.A....qn..... ..|jEz.SHTTP/1.1 200 OK Date: Mon, 11 Apr 2022 14:04:12 GMT Server: Apache/2.4.52 () OpenSSL/1.0.2k-fips X-Powered-By: PHP/7.2.34 Upgrade: h2,h2c
    Connection: Upgrade Transfer-Encoding: chunked Content-Type: text/html; charset=UTF-8 159 PHP file name: /index.php<br> ................

**注意：**在前面的示例输出中，GET HTTP 在 14:04:12 响应，而目标在 14:04:21 响应。TargetResponseTime 大约为 9 秒。您可以使用 X-Amzn-Trace-Id: Root 在访问日志中跟踪此记录。

适用于压缩后的日志文件的示例命令：

$zcat *.log.gz | awk '{if($20 ~ "1-6254355c-15db4904726649b66a1e47d7"){print $6,$7,$8 }}'

适用于未压缩的日志文件的示例命令：

$cat *.log | awk '{if($20 ~ "1-6254355c-15db4904726649b66a1e47d7"){print $6,$7,$8 }}'

示例输出：

0.008 9.002 0.000

---