本文旨在帮助读者了解什么是全链路追踪以及如何使用工具来分析链路中性能瓶颈。阅读前提 链路概念和术语基本概念及工具全链路(Trace)追踪分析工具火焰图Span列表服务调用关系图持续时间执行时间全链路追踪 一般来说,单个追踪(Trace)由各个Span构成,是一棵树或有向无环图(DAG),每一个Span代表Trace中被命名并计时的连续性的执行片段,如下图所示。因为Span的核心是记录对应程序执行片段的开始时间和结束时间,而程序执行片段之间存在调用的父子关系,因而Span逻辑上形成树状结构。 注:span的父子关系可以通过子span的parentid等于父Span的spanid来关联 火焰图 火焰图(FlameGraph)是由Linux性能优化大师BrendanGregg发明的用于分析性能瓶颈的可视化图表,火焰图以一个全局的视野来看待时间分布,它从顶部往底部列出所有可能导致性能瓶颈Span。 绘制逻辑纵轴(Y轴)代表调用Span的层级深度,用于表示程序执行片段之间的调用关系:上面的Span是下面Span的父Span(数据上也可以通过子span的parentid等于父Span的spanid来关联来对应)。横轴(X轴)代表单个Trace下Span的持续时间(duration),一个格子的宽度越大,越说明该Span的从开始到结束的持续时间较长,可能是造成性能瓶颈的原因。 显示说明 火焰图火焰图上的每个Span格子的颜色都对应其服务(service)的颜色。 所以从火焰图上很直观的可以感知当前的Trace中涉及到有哪些服务请求在执行。(服务的颜色生成逻辑:用户登录到工作空间访问应用性能监测模块时,观测云会根据服务名称自动生成颜色,该颜色的集成会继承到链路查看器等分析页面)Span块默认显示:当前Span的资源(resource)或操作(operation)、持续时间(duration)以及是否存在错误(statuserror)每个Span提示都会显示当前Span对应的资源(resource)、持续时间(duration)以及整体耗时占比 服务列表 火焰图右侧的服务列表显示当前Trace内发生请求调用的服务名称、颜色及该服务执行占总执行时间的比率。 注意:服务名称显示为None的情况则表示当前trace未找到parentid0的顶层Span 特别说明 由于多线程或者存在异步任务等原因,所以火焰图在实际绘图时会遇到span之间的关系可以如下:同属于一个parent的兄弟span间可能重叠 因为存在Span重叠的情况,为了能更直观的看到每个Span及子Span的执行情况,我们前端在绘制火焰图的时候做了一些显示处理,即根据时间空间维度计算Span及子Span在完全不遮挡情况下显示的位置。 示例1: 正常Trace,同层级Span时间上不重叠,但跟下属子Span时间有重叠,通过连线的形式关联父子Span之间的关系,下面子Span存在连线的时候也是按照该逻辑做绘图处理。 示例2: 异常Trace,仍然存在同层级Span时间上重叠,但是因为实际数据里发现Trace的顶层Span(parentid0)的开始时间(start)大于子Span的开始时间。 分析逻辑:按照链路中根据程序执行的父子关系判断,父Span的开始时间一定是小于子Span的开始时间的,所以看到该火焰图的显示后,发现父Span跟子Span的服务不是一个时,可以判断两个服务所在服务器的系统时间可能存在不一致的情况,需要先去校验校准后再来分析实际的性能瓶颈。Span列表 显示说明 列表全收起状态 列1:显示服务类型、服务名称、服务颜色及当前服务下是否存在statuserror的Span列2:显示当前服务下面的Span数量列3:显示当前服务下Span持续时间(duration)的平均值列4:显示当前服务下Span的执行时间总和列5:显示当前服务的执行时间占总执行时间的比例 服务行展开显示 列1:显示资源名称(resource)、对应服务颜色及当前span是否存在statuserror列2:空列3:显示当前Span持续时间(duration)列4:显示当前Span的执行时间列5:显示当前Span的执行时间占总执行时间的比例服务调用关系图 显示说明 显示当前trace下的服务之间的调用关系拓扑 持续时间 Span对应程序执行片段的开始时间和结束时间,一般在Trace的数据中用duration字段来做标记。执行时间 上述的特别说明中有提及到可能会存在父子Span的结束时间不一致的情况,那么执行时间则参考以下逻辑计算得出。 Span执行时间子span可能在父span结束后才结束 子Span的执行时间Children的duration 总执行时间Children的结束时间Parent的开始时间 父Span的执行时间总执行时间子Span的执行时间子span可能在父span结束后才开始 子Span的执行时间Children的duration 总执行时间Children的结束时间Parent的开始时间 父Span的执行时间总执行时间子Span的执行时间同属于一个parent的兄弟span间可能重叠 父Span执行时间p(1)p(2) Children1Span执行时间c1(1)c1(2) Children2Span执行时间c2(1)c2(2) 注意:因为Children1Span、Children2Span实际执行中时间上存在部分重叠,所以这部分时间由两个Span平分。 示例说明 同步任务情况下,Span按照Span1开始Span1结束Span2开始Span2结束。。。顺序执行时,每个Span的执行时间及对应父Span的执行时间计算如下: 示例1: 父SpanCouldcareSPAN1 子SpanMyDQLSPAN2、MyDQLSPAN3、MyDQLSPAN4、MyDQLSPAN5、MyDQLSPAN6、MyDQLSPAN7、MyDQLSPAN8、MyDQLSPAN9、MyDQLSPAN10、MyDQLSPAN11 计算分析: 因为所有的子Span都没有再下层级的子Span,所以下图所有的子Span的执行时间等于他们的Span持续时间。父Span因为下面存在子Span的调用所以实际父Span的执行时间需要通过父Span的持续时间减去所有子Span的执行时间获得。 服务执行时间 每个服务的执行时间Trace内所有属于该服务的Span执行时间总和 总执行时间 总执行时间Trace内Span最后结束的时间Span最开始的时间链路查看分析场景示例采集器配置(主机安装) 进入DataKit安装目录下的conf。dddtrace目录,复制ddtrace。conf。sample并命名为ddtrace。conf。示例如下:〔〔inputs。ddtrace〕〕DDTraceAgentendpointsregisterbyversionrespectively。Endpointscanbeskippedlistenbyremovethemfromthelist。Defaultvaluesetasbelow。DONOTMODIFYTHESEENDPOINTSifnotnecessary。endpoints〔v0。3traces,v0。4traces,v0。5traces〕customertagsisalistofkeyscontainskeyssetbyclientcodelikespan。SetTag(key,value)thatwanttosendtodatacenter。Thosekeyssetbyclientcodewilltakeprecedenceoverkeysin〔inputs。ddtrace。tags〕。DOT(。)INKEYWILLBEREPLACEDBYDASH()WHENSENDING。customertags〔key1,key2,。。。〕Keepraretracingresourceslistswitch。Ifsomeresourcesarerareenough(notpresendin1hour),thoseresourcewillalwayssendtodatacenteranddonotconsidersamplersandfilters。keeprareresourcefalseBydefaulteveryerrorpresentsinspanwillbesendtodatacenterandomitanyfiltersorsampler。Ifyouwanttogetridofsomeerrorstatus,youcansettheerrorstatuslisthere。omiterrstatus〔404〕Ignoretracingresourcesmaplikeservice:〔resources。。。〕。Theservicenameisthefullservicenameincurrentapplication。Theresourcelistisregularexpressionsusestoblockresourcenames。Ifyouwanttoblocksomeresourcesuniversallyunderallservices,youcansettheservicenameas。Note:doublequotescannotbeomitted。〔inputs。ddtrace。closeresource〕service1〔resource1,resource2,。。。〕service2〔resource1,resource2,。。。〕〔closeresourceunderallservices〕。。。Samplerconfigusestosetglobalsamplingstrategy。samplingrateusedtosetglobalsamplingrate。〔inputs。ddtrace。sampler〕samplingrate1。0〔inputs。ddtrace。tags〕key1value1key2value2。。。Threadsconfigcontrolshowmanygoroutinesanagentcloudstart。bufferisthesizeofjobsbufferingofworkerchannel。threadsisthetotalnumberfogoroutinesatrunningtime。〔inputs。ddtrace。threads〕buffer100threads8Storageconfigalocalstoragespaceinharddirvertocachetracedata。pathisthelocalfilepathusedtocachedata。capacityistotalspacesize(MB)usedtostoredata。〔inputs。ddtrace。storage〕path。ddtracestoragecapacity5120 配置好后,重启DataKit即可。 HTTP设置 如果Trace数据是跨机器发送过来的,那么需要设置DataKit的HTTP设置。 如果有ddtrace数据发送给DataKit,那么在DataKit的monitor上能看到: DDtrace将数据发送给了v0。4traces接口SDK接入(Go示例) 安装依赖 安装ddtracegolanglibrary在开发目录下运行gogetvgithub。comDataDogddtracego 设置DataKit 需先安装、启动datakit,并开启ddtrace采集器 代码示例 以下代码演示了一个文件打开操作的trace数据收集。 在main()入口代码中,设置好基本的trace参数,并启动trace:packagemainimport(ioioutilostimegopkg。inDataDogddtracego。v1ddtraceextgopkg。inDataDogddtracego。v1ddtracetracer)funcmain(){tracer。Start(tracer。WithEnv(prod),tracer。WithService(testfileread),tracer。WithServiceVersion(1。2。3),tracer。WithGlobalTag(project,addddtraceingolangproject),)endofappexit,makesuretracerstoppeddefertracer。Stop()tick:time。NewTicker(time。Second)defertick。Stop()yourappmainentry。。。for{runApp()runAppWithError()select{casetick。C:}}}funcrunApp(){varerrerrorStartarootspan。span:tracer。StartSpan(get。data)deferspan。Finish(tracer。WithError(err))Createachildofit,computingthetimeneededtoreadafile。child:tracer。StartSpan(read。file,tracer。ChildOf(span。Context()))child。SetTag(ext。ResourceName,os。Args〔0〕)Performanoperation。varbts〔〕bytebts,errioutil。ReadFile(os。Args〔0〕)span。SetTag(filelen,len(bts))child。Finish(tracer。WithError(err))} 编译运行 LinuxMac环境:gobuildmain。goomyappDDAGENTHOSTlocalhostDDTRACEAGENTPORT9529。myapp Windows环境:gobuildmain。goomyapp。exeenv:DDAGENTHOSTlocalhost;env:DDTRACEAGENTPORT9529;。myapp。exe 程序运行一段时间后,即可在观测云看到类似如下trace数据: Golang程序trace数据展示 支持的环境变量 以下环境变量支持在启动程序的时候指定ddtrace的一些配置参数,其基本形式为:DDXXXenvvalueDDYYYenvvalue。myapp注意事项 这些环境变量将会被代码中用WithXXX()注入的对应字段覆盖,故代码注入的配置,优先级更高,这些ENV只有在代码未指定对应字段时才生效。 Key 默认值 说明 DDVERSION 设置应用程序版本,如1。2。3、2022。02。13 DDSERVICE 设置应用服务名 DDENV 设置应用当前的环境,如prod、preprod等 DDAGENTHOST localhost 设置DataKit的IP地址,应用产生的trace数据将发送给DataKit DDTRACEAGENTPORT 设置DataKittrace数据的接收端口。这里需手动指定DataKit的HTTP端口(一般为9529) DDDOGSTATSDPORT 如果要接收ddtrace产生的statsd数据,需在DataKit上手动开启statsd采集器 DDTRACESAMPLINGRULES 这里用JSON数组来表示采样设置(采样率应用以数组顺序为准),其中samplerate为采样率,取值范围为〔0。0,1。0〕。示例一:设置全局采样率为20:DDTRACESAMPLERATE〔{samplerate:0。2}〕。myapp示例二:服务名通配app1。、且span名称为abc的,将采样率设置为10,除此之外,采样率设置为20:DDTRACESAMPLERATE〔{service:app1。,name:b,samplerate:0。1},{samplerate:0。2}〕。myapp DDTRACESAMPLERATE 开启上面的采样率开关 DDTRACERATELIMIT 设置每个golang进程每秒钟的span采样数。如果DDTRACESAMPLERATE已经打开,则默认为100 DDTAGS 这里可注入一组全局tag,这些tag会出现在每个span和profile数据中。多个tag之间可以用空格和英文逗号分割,例如layer:api,team:intake、layer:apiteam:intake DDTRACESTARTUPLOGS true 开启ddtrace有关的配置和诊断日志 DDTRACEDEBUG false 开启ddtrace有关的调试日志 DDTRACEENABLED true 开启trace开关。如果手动将该开关关闭,则不会产生任何trace数据 DDSERVICEMAPPING 动态重命名服务名,各个服务名映射之间可用空格和英文逗号分割,如mysql:mysqlservicename,postgres:postgresservicename,mysql:mysqlservicenamepostgres:postgresservicename实际链路数据分析 1。登录观测云工作空间,查看应用性能监测模块的服务列表,从服务页面已经可以看出browser服务的P90响应时间是比较长的。 2。点击browser服务名称,查看该服务的概览分析视图,可以看出影响当前服务响应时间的最关键的资源是querydata这个接口,因为这个接口是观测云的一个数据查询接口,所以接下来我们看下这个接口在查询过程当中,到底是因为什么导致耗时较长。 3。点击资源名称,跳转到查看器,通过点击持续时间倒序查看响应时间的最大值。 4。点击Span数据,查看分析当前Span在整个链路里面的执行性能和其他相关信息。 5。点击右上角〔全屏〕模式按钮,放大查看火焰图相关信息。结合整体链路查看,可以看出browser服务在整个链路中的执行时间占比高达96。26,从Span列表也可以得出此结论。根据火焰图的占比和对应的链路详情信息,我们可以总和得出browser的这个querydataSpan在整个执行过程中可以看到resourcettfb(资源加载请求响应时间)耗时400多毫秒,resourcefirstbyte(资源加载首包时间)耗时1。46秒,再结合查看province的地理位置定位是Singapore(新加坡),而我们的站点部署在杭州节点,则可以得出是因为地理位置问题导致数据传输的时间变长从而影响了整个的耗时。 参考来源:https:www。guance。comlearningarticlesflamegraph01