背景
某药业集团是一家以创新技术驱动的线下医疗数据 SaaS 平台建设和运营公司,其主营的某智慧医疗平台产品,围绕线下医疗场景痛点提供一体化服务解决方案。近期集团对其生物检材在线递检系统进行功能升级开发及 IaaS 平台迁移。在针对新系统和新基础设施服务进行性能压测时,偶发后端服务响应超时问题并影响到最终系统上线的项目进度,也影响了新引入 IaaS 服务商的云产品能力评估。为快速闭环该问题,推动服务按时迁移上线。用户决定采用观测云作为上线前性能压测的辅助分析工具,找出产生后端服务响应超时问题的根因。
接入准备
经与开发工程师沟通,本次测试的在线递检系统基于 .NET Core 框架进行后端业务的开发,部署方式采用 K8s 云服务部署,要求性能分析数据采集探针能够良好适配 .Net Core 微服务环境。观测云数据采集探针 DataKit 提供了优秀的 APM 分布式跟踪能力,可支持包括 .NET Framework 和 .NET Core 应用程序在内的多种开发语言程序在实际运行环境中的分析。帮助用户有效感知上线后应用的运行状态,解决故障异常和性能异常等问题。
针对用户环境中采用容器化部署的方式,我们将 .Net 数据采集器打入容器镜像,并配置相应的环境变量,使服务在加载时同步启动 APM 数据采集器。当有应用请求访问到当前服务时,链路记录的数据将发送至本集群 DataKit 探针,实现应用链路数据的采集和发送:
FROM xxx/sdk:6.0 #base image# Install datadog-dotnet-apm for Cent&RH
#COPY datadog-dotnet-apm-2.42.0-1.x86_64.rpm /opt
#RUN sudo rpm -Uvh /opt/datadog-dotnet-apm-2.42.0-1.x86_64.rpm && /opt/datadog/createLogPath.sh# Install dd-dotnet for Ubuntu
COPY datadog-dotnet-apm_2.42.0_amd64.deb /opt
RUN dpkg -i /opt/datadog-dotnet-apm_2.42.0_amd64.deb && /opt/datadog/createLogPath.sh# Set Datakit receiver endpoint
ENV DD_TRACE_AGENT_URL=http://datakit-service.datakit:9529
ENV DD_AGENT_HOST=datakit-service.datakit
ENV DD_TRACE_AGENT_PORT=9529# Set environment variables
ENV CORECLR_ENABLE_PROFILING=1
ENV CORECLR_PROFILER={846F5F1C-F9AE-4B07-969E-05C26BC060D8}
ENV CORECLR_PROFILER_PATH=/opt/datadog/Datadog.Trace.ClrProfiler.Native.so
ENV DD_DOTNET_TRACER_HOME=/opt/datadog# Set additional Datadog environment variables
ENV DD_LOGS_INJECTION=true
ENV DD_RUNTIME_METRICS_ENABLED=true
问题分析
在完成应用数据接入后,针对当前客户遇到的性能问题表现,我们计划了以下几个分析步骤,来逐步探查性能问题产生的原因:
1、应用性能概览查看异常 span
受实际应用程序的规模和复杂性的影响,我们首先需要排除是否是运行时环境的各种 Exception 处理或重试导致了该问题。如果一个 .NET 应用程序的 span 显示出高延迟,用户可以通过观测云应用性能概览和服务详情列表,并点击存在异常的错误服务,跳转至链路详情来分析判断性能问题是否与故障相关:
例如在上面的服务详情中,我们点击服务错误数并跳转查看相关链路,在链路详情列表中点击对应的长耗时 span,即可查看到当前长耗时状态是否是发生错误的 span 导致的。在示例图的应用链路火焰图中,最下层的查询错误是导致整个链路超时的原因,这个故障可通过观测云 APM 火焰图直接定位发现,可以大幅提升代码问题分析效率。
2、长耗时应用 span 的跳转分析
对于没有产生显著错误但性能依然存在问题的调用过程,我们需要借助观测云应用性能监测的服务列表统计或应用性能概览继续分析问题原因。首先需要找到慢响应服务的位置,再通过跳转分析的方式打开链路执行详情进行进一步分析。例如在下图中,首先根据服务名称确定我们需要分析的接口。再通过对应接口的 P99 响应时长,定位到和前端 app 操作时响应超时相关的具体链路:
以上面的分析场景为例,我们结合客户压测过程中前端某接口的响应超时,对其请求的 Orxxx.WebApi 服务进行进一步的分析。通过时间窗筛选,查看测试时间段附近统计的各服务接口,点击该服务后跳转到对应该链路的详情页,进一步查看指定接口调用统计及资源耗时情况:
点击下方资源调用分析列表中的长耗时接口,跳转进入火焰图将该接口的详细调用过程进行展开分析。通过火焰图中的链路调用详情,可以看到最底层的 /_search 调用即是本次调用耗时最长的接口,而这次长耗时调用进一步导致了当前服务最终对外返回超时的问题:
对于大多数问题分析场景,定位到这样的具体接口已可转开发团队进行代码层面的进一步分析和优化修改。但也不排除有时会因为运行时环境出现的某种异常,反向干扰到代码执行的情况,这种故障单从代码执行层面无法找到故障原因。此外,还可能遇到在进行代码优化后可能仍未获取到比较满意的性能得情况。或者单纯通过静态代码分析无法查找出具体的异常代码,需要进一步定位分析原因。这种情况下我们需要使用观测云 APM 的 Profile 功能对应用执行的运行时环境指标进行分析,进一步查找影响性能的相关线索。
3、应用性能监测 Profile 分析
观测云提供的应用性能 Profile 提供基于线程采样的代码详细执行耗时统计,帮助用户进一步探查链路长耗时 span 在资源消耗方面存在的问题。例如,用户可通过 CPU Time 这个 profile 指标,找到消耗大量 CPU 周期的代码块。或通过 Walltime 指标,找出执行时间长的方法。当某个 method 因某种原因未被操作系统完全调度在核心上的线程执行时(等待 I/O 或等待锁),Profile 分析可以帮助用户找出这类请求,并明确执行变慢的原因。
由于 Profile 功能本身有一定的性能开销。在本次性能分析过程中我们通过观 K8s 负载的环境变量,按需开启指定 api 负载所在容器的 .Net Profile 功能。当运行时环境开启 Profile 采集后,即可在应用性能监测的 Profile 页面中看到相关数据的采集列表:
查看与慢调用 span 相关的 Profile 数据通常有两种方式,对于执行时间明显超过某个阈值的单块调用 (CPU time>500ms) ,观测云将自动关联该 Profile 数据到对应的链路,用户通过应用链路详情界面的代码热点功能即可跳转至对应的 Profile 火焰图,查看对应的长耗时执行时间是由哪个 method 产生。在本次故障问题的定位中。我们发现订单接口的货品查询 api 在采样周期内有明显的锁等待耗时长的问题。表现为故障时间段内会出现若干个查询连续超时的情况。原因如图中所示,其信号量和自旋锁的等待时间都比较长,这通常与运行时环境的参数配置有关。对于此类问题,即便代码持续优化,只要参数配置不合理就无法从根源上解决性能劣化的问题。
另一种查看对应 Profile 数据的方式是根据性能异常链路的执行时间,直接在 Profile 详情页中查看对应时段内的 Profile 详情火焰图。这种方式适用于单个代码块执行时间未超过系统自动关联的判定阈值,但依然需要分析其性能问题的场合。由于其分析效果与上述方法基本等同,这里不再赘述。
在本次问题的分析过程中,我们针对 _search 服务执行时间超时问题进行了进一步的 Profiling 分析,通过反复压测相关接口,触发超时步骤并查看 Profile 数据,发现在高并发条件下 Orxxx.WebApi 服务的几个副本随机出现的少量超时,其原因为信号量及锁竞争。需要结合当前并发量及资源访问或运行时参数的配置情况,转给开发和环境运维的同学进行后续的分析和优化。
结语
结合对 Profile 的数据分析,开发同学对该查询接口的读写锁进行了优化,重新调整了部分运行时参数。并根据观测云 APM 的数据,对周边代码逻辑进行了全面排查。通过本轮优化后,线上递检系统在云资源配置、规格不变的情况下,顺利通过了迁移前性能压测,并按时完成系统上线工作。在后续的生产系统线上运行保障过程中,观测云还将继续同客户运维团队一起,为应用持续稳定运行提供可观测保障,及时发现性能隐患,消除性能问题,确保递检系统生产环境 SLA 顺利达成。