通过错/慢调用链排查应用产生异常的原因

更新时间:
复制 MD 格式

在生产环境中,引发应用异常(如耗时突增、错误率突增)的原因有很多,常见的包括流量不均、单机故障、程序异常和依赖组件故障等。在新应用上线或大促备战前通常建议做一次系统性的性能调优,分析当前系统存在哪些性能瓶颈,梳理出常出错的或耗时较高的接口和组件进行优化。本文介绍如何使用ARMS调用链分析的错/慢Trace分析功能,定位系统或应用产生错、慢调用的原因,帮助您排查问题、定位系统性能瓶颈。

前提条件

  • 已为应用安装探针,具体操作,请参见应用监控接入概述

  • 已切换至新版控制台。

    应用列表页面标题旁,单击切换新版按钮完成切换。

体验Demo

ARMS控制台Demo

通过错Trace分析功能排查错调用根因

步骤一:定位错调用发生时间

  1. 登录ARMS控制台,在左侧导航栏选择应用监控 > 应用列表

  2. 应用列表页面顶部选择目标地域,然后单击目标应用名称。

    说明

    语言列的图标含义如下:

    Java图标:接入应用监控的Java应用。

    image:接入应用监控的Golang应用。

    image:接入应用监控的Python应用。

    -:接入可观测链路 OpenTelemetry 版的应用。

  3. 在上方导航栏单击调用链分析

    说明

    仅新版控制台支持进入调用链分析页面,切换新版控制台的操作请参见前提条件

    可以发现示例应用mall-gateway15:20~15:28时间段出现了一些HTTP错误的调用。

    image

  4. 修改查询时间段为HTTP错误发生的时间,开始排查问题。

    调用链分析页签中,将右上角时间范围缩小为8min(例如 2024-06-26 15:20 ~ 2024-06-26 15:28),页面即展示该时段的调用次数柱状图、HTTP 500 错误数柱状图及耗时百分位折线图,可据此确认错误高发的具体时间窗口。

步骤二:定位错误调用所在的接口或组件

错/慢Trace分析页签,可以发现错Trace主要集中在/components/api/v1/mall/product接口上,且全都是500错误。

排查/components/api/v1/mall/product接口

  1. 在下方图表中单击spanName: /components/api/v1/mall/product

    image

    此时调用链分析会自动将serviceName="mall-gateway" AND spanName="/components/api/v1/mall/product"设置为筛选条件。

    可以发现/components/api/v1/mall/product接口的调用链全都出错了。

    共搜索到 1440 次调用,错误码均为 HTTP 500错/慢Trace分析 Tab 显示分析对象为 1000 条错 Trace(随机抽样)、0 条正常 Trace。

  2. 列表页签,单击任意Trace右侧的详情,可以查看错误详情。

    Trace详情显示调用链路包含三个Span,其中 mall-user-server 服务的 /components/api/v1/http/success 接口返回状态码 500。在右侧Span详情的 Attribute 标签页中,http.status_code 值为 500,确认该接口为错误来源。

通过慢Trace分析功能梳理慢接口

步骤一:定位慢调用发生时间

  1. 登录ARMS控制台,在左侧导航栏选择应用监控 > 应用列表

  2. 应用列表页面顶部选择目标地域,然后单击目标应用名称。

    说明

    语言列的图标含义如下:

    Java图标:接入应用监控的Java应用。

    image:接入应用监控的Golang应用。

    image:接入应用监控的Python应用。

    -:接入可观测链路 OpenTelemetry 版的应用。

  3. 在上方导航栏单击调用链分析

    可以发现示例应用mall-user-server15:40~15:49时间段存在许多5s以上的慢调用。

    image

  4. 修改查询时间段为慢调用发生的时间。

    例如在右上角时间选择器中选择 2024-06-26 15:40 ~ 2024-06-26 15:49(9分钟区间)。

  5. 错/慢Trace分析页签修改耗时对比临界值5000ms,开始排查问题。

    页面下方展示慢Trace分析结果,按贡献度排列影响慢Trace的关键特征(如接口名、HTTP响应状态码、命名空间),每项对比该特征在慢Trace与正常Trace中的占比差异。

步骤二:定位慢调用所在的接口或组件

错/慢Trace分析页签,可以发现慢Trace主要集中在接口名为/components/api/v1/http/success、上报协议为EagleEye,以及命名空间为arms-testSpan上,依次对它们进行排查。

分析基于54条慢Trace(定义为耗时≥5s)与837条正常Trace(随机抽样)的对比结果:Top1关键特征 /components/api/v1/http/success 在慢Trace中占比100.0%、正常Trace中占比0.0%;Top2 EagleEye 协议在慢Trace100.0%、正常Trace37.28%;Top3命名空间 arms-test 在慢Trace100.0%、正常Trace37.28%。

排查/components/api/v1/http/success接口

在下方图表中单击spanName: /components/api/v1/http/success

image

此时调用链分析会自动将serviceName="mall-user-server" AND spanName="/components/api/v1/http/success"设置为筛选条件。

可以发现,在该筛选条件下,每一次调用耗时都大于5s,/components/api/v1/http/success接口即为慢调用根因。

耗时百分位区域同样可以发现调用平均耗时大于5s。

排查attributes._arms.trace.protocol.type=EagleEyeSpan

在下方图表中单击attributes._arms.trace.protocol.type: EagleEye

image

此时调用链分析会自动将serviceName="mall-user-server" AND attributes._arms.trace.protocol.type="EagleEye"设置为筛选条件。

可以发现,在该筛选条件下,慢Trace的也指向了/components/api/v1/http/success接口。

Trace分析基于54条慢Trace312条正常Trace进行对比,除Top1指向 /components/api/v1/http/success 接口(占慢Trace 100%)外,Top2显示服务端IP 10.0.0.42 占慢Trace 46.3%,Top3显示 http 组件类型占慢Trace 100%。

/components/api/v1/http/success接口加入筛选条件中,可以发现每一次调用的耗时都大于5秒。

耗时百分位区域同样可以发现调用平均耗时大于5s。

排查命名空间为arms-testSpan

serviceName="mall-user-server" AND attributes.namespace="arms-test"筛选条件下,可以发现,慢Trace的依然指向/components/api/v1/http/success接口。

错/慢Trace分析结果显示,在54条慢Trace312条正常Trace的对比中,Top1关键特征为接口 /components/api/v1/http/success,贡献度为1,该接口在慢Trace中占比100%,在正常Trace中占比0%。

/components/api/v1/http/success接口加入筛选条件中,可以发现每一次调用的耗时都大于5秒。

经过上述的排查,可以发现慢调用都来自于接口/components/api/v1/http/success attributes._arms.trace.protocol.type="EagleEye"arms-test命名空间自身都没有问题,它们中出现了慢调用是因为/components/api/v1/http/success接口服务部署在arms-test命名空间,且它的调用链上报协议类型为EagleEye。