大家好今天我要讲的主题是CPU Profiler它是如何工作的首先我叫陈霜我是来自Pincap公司Title B Insight团队的研发工程师日常的工作是做Title B可观测性提高Title B问题准断效率相关的事情之前是在Title B内核团队做开发工作比较熟悉的模块是Title B的DDL模块数据写入以及事务相关的模块然后下面是我的工作邮箱这一次TALK主要会强以下这些类型首先会介绍为什么需要CPU Profiler以及CPU Profiler是什么然后会介绍CPU Profiler它的工作原理再然后就是介绍我们在工作中遇到的问题以及我们是如何利用类似CPU Profiler的原理去解决的这个问题最后是一个小的demo首先来看一个小的故事某一天我发现我们的应用性能变差了然后它的COPYS一直在掉然后相应的响应延迟也一直在上升所以我就连到这台应用的服务器上面去执行TOP命令想看一下CPU使用率然后我发现有一个demo1进程的CPU使用率很高然后这个demo1就是我昨天写的一个测试用力那为啥它的CPU使用率这么高呢是不是代码有bug或者说如果没有bug是不是代码有哪些地方是可以优化的这个时候我就会用到CPU Profiler工具了因为通过CPU Profiler工具我能知道具体是哪块demo在消耗CPU资源那CPU Profiler是什么呢简单来说它是一个可以获取当前函数具体消耗了多少CPU比例的工具常见的CPU Profiler工具有perfGoogle的gperf2以及购源的pprof然后在下面的这个week页面中还列举了很多其他的性能分析工具除了分析CPU还有分析磁盘类传其他等其他资源的工具但我们今天主要是聚焦在CPU Profiler工具上回到最开始的问题我们发现demo1这个进程的CPU使用率很高我们可以用perf工具的perfRecorderMeaning来抓一个这个进程当前的CPU Profiler我们用perfRecorderMeaning然后通过GunF指定采样频率这里99代表是采样频率为99Hz然后用GunPy来指定demo1进程的进程ID然后GunG表示获取函数的执行对战最后Sleep5表示连续抓5秒钟的CPU Profiler然后perf抓完CPU Profiler之后会把数据写到当前路径下的perf.data文件中然后我们就可以用perfRecorderMeaning来读取这个读取CPU Profiler数据它默认会在当前路径下的perf.data文件中读然后这个meaning输出结果中它的第一列代表的是它这个对应的函数以及这个函数调用的其他函数它总共的一个CPU消耗比例然后第二列是指它这个函数本身它自己消耗的CPU比例然后第三列是指这个进程的名字然后最后一列就是指这个函数的名字那么从第二列的函数的CPU消耗之后我们就可以看出是processdata这个函数它消耗了大概78%的CPU资源那么我觉得可能这是不符合预期的然后就可以打开demo1的代码去找到这个函数然后看能不能去优化这个函数或者说分析一下是不是这个函数的调用不太合理有bug然后perf工具还有很多其他的强大的功能关于perf工具更多的使用用力可以看下面的这个文档然后另外一个我们也可以用火焰图生成工具来生成CPU profile它对应的一个火焰图例如我们直接把这个工具的代码给cullown下来然后执行下面的命令就能生成perf.data数据它对应的一个火焰图SVG文件然后又有流量器打开就可以查看然后我们可以从火焰图中看到每个函数的CPU使用率以及函数的调用对战例如这里妹函数它调用了HandleRequest函数然后HandleRequest函数又调用了FinishPrepare以及ProcessData函数然后可以看到ProcessData函数这里它的CPU使用比例是71.46那CPU Profiner它是如何实现的呢这里介绍常见的按照采样的方式来实现的CPU Profiner基于采样原理的CPU Profiner它是通过一个定时器每隔一段时间去记录当前CPU上正在执行的函数的对战信息然后按照函数的对战信息来统计这个对战出现的次数例如在头中CPU的执行从最开始的执行函数A然后它又调用了函数B然后又调用了函数C最后函数C执行完之后又返回到最开始的函数A然后函数A又调用了函数D然后在这个左边有一个定时器这里是近期每隔10毫秒超时一出之后就会去记录当前CPU上正在执行的对战比如这你第一次采样的时候它的对战就是函数A然后第二次采样的时候它的对战就是函数B并同时它会去累计这个对战它出现的次数比如这个函数A函数B这个对战出现次数是1然后第三次采样的时候也是这个函数A函数B这个对战但是它的次数就是2了然后这样一直类推然后每隔10毫秒采样一次那它的采样频率就是100然后另外一个问题就是在多核CPU上那么每次采样的时候就会采集每个CPU上当前正在运行的对战信息这里举一个采样后的例子假设我们做了一秒钟的CPU profile然后最终我们采集到了对战以及次数如这个比较所思那么我们根据这个信息就能绘制出以下的这种类似的火焰图信息以及CPU profile它也是有优缺点的比如它的优点就是它对应用的性能影响很小几乎是要小于1%的另外一个优点是CPU profile它生成的profile数据相对来说是比较小的比起其他的吹声工具生成的数据量要小很多然后CPU profile它的缺点就是采样容易漏掉那些执行速度比较快但执行次数很少的函数然后对于那种CPU负载并不高然后比如说CPU Hang住它在等待网络或者是等待磁派IO的时候这个时候CPU profile工具也不适合最后CPU profile它比较适合的工作场景是第一个场景是在对待做性能调优的时候比如用CPU profile工具我们可以发现是哪些比较消耗CPU的函数然后我们去针对这个函数去做优化降低CPU的消耗以及当线上出现故障比如CPU负载很高的时候我们也可以尝试用CPU profile工具来找出是什么代码来消耗了这么多的CPU然后我们也可以自己实现一个CPU profile工具然后我们内部就针对Rust的语言实现了自己的CPU profile工具然后它的代码量也比较少非常适合用来学习然后代码里面也有涉及到如何启动一个定时器中断然后在中断初年还是说中统计当前执行对战的次数然后CPU profile工具它对开发者来说是一个非常棒的工具但是对用户或者说对用用为人人来说就会难以理解因为他们可能都不懂他抓到的那些函数是用来干什么的比如我们的用户在遇到问题后比如说TTB数据库现在响应时间很慢而且数据库的CPU也特别高这个时候用户就选择知道是哪些浅球或者说哪些任务消耗了这么多的CPU因为一般情况下数据库的CPU消耗不会突然变得很高大多是因为比如说数据库你突然来了一些比较消耗资源的CPU浅球然后这些浅球影响到了普通的CPU浅球或者是说某些CPU的执行计划发生了变化例如之前的CPU是能够做索引的现在因为这个索引它被删掉或者是其他的原因然后导致现在没有办法走索引那这种情况下处理这个CPU浅球所消耗的CPU资源肯定也会显著上升另外一个问题是对于数据库来说可能不同的CPU浅球它们会有一个相同的执行对战例如下面的这两个逆子两个 下面两个都是全标嫂舍赖新服供T1和舍赖新服供T2然后比较T1只有100行数据然后比较T2有100万行数据这两个CPU浅球浅球的执行的寒兽对战路径是完全一样的但是它们消耗的CPU资源却是差了很多倍这里有一个简单的类比的demo needs来模拟刚刚的这种情况就是有一个Mate寒数它一直负责发送不同的CPU浅球给Handle CircleRequest寒数执行然后每种浅球的资源消耗也是不一样的比如说你一共有4种CPU浅球ID分别是1234然后这里ID越高可以看到ID值越大然后它对应的CPU消耗也是越高的所以然后按照总的CPU使用率是100%来计算然后这4种Code浅球它们的CPU消耗个子应该是10% 20% 30% 40%然后我们把这个demo跑起来之后用PARF工具对齐做CPU Profile就会得到这个火焰图我们的确可以看到Handle CircleRequest这个还说消耗了很多的资源但是用户无法从中知道各个CPU浅球它各自消耗了多少的CPU资源为了解决这个问题我们模仿了CPU Profile的原理实现了统计各个浅球的CPU资源使用率我们可以首先先回顾一下CPU Profile它的原理它是通过一个定时器每隔一段时间去记录当前CPU上正在执行的函数堆战信息并且按照函数堆战来统计这个堆战出现的次数那么想要知道各种浅球用了多少的CPU资源我们也可以通过一个定时器每隔一段时间去记录当前CPU上正在执行的浅球类型并按照浅球类型来统计这个类型出现的次数例如在头中CPU执行最开始是在执行浅球1然后执行浅球2 然后执行浅球3然后左边有一个定时器用于每间隔10毫秒去获取当前CPU上正在执行的浅球类型比如它第一次是记录到是在执行浅球1然后是次数是1第二次是抓到的是浅球2次数也是1然后第三次采样也是抓到浅球2然后它次数就变成2第四次抓到就是浅球类型是3然后第一次出现然后第五次就是还是3然后第二次出现然后这里可能有人会问的一个问题就是为什么不直接在浅球的结束和浅球的开始和结束的时候分别记一个时间戳然后比如说记一个STARTS和一个NDTS然后我们最终用一个NDTS减去STARTS就能得到浅球的CPU使用时间首先这里有一个问题就是并不是所有的浅球在处理的时候都是在使用CPU的比如说它在等待网络刺判IO的时候它是这个浅球它是不消耗CPU时间的所以直接用结束的时间减去开始的时间得到了是浅球的一个处理时间并不是它的CPU的消耗时间另外一个问题就是它没有办法保证实施性比如说假设有一个浅球它执行了很久没有执行完并且它非常的消耗CPU资源那么在它执行完之前我就没有办法知道是这个浅球它消耗了这么多的CPU资源了但如果是采样的方式即便这个浅球它没有执行完我也能知道在采样的时间段之内它大概消耗了多少比例的CPU资源同样主义一个例子假设我们采样一秒钟之后最终得到浅球类型以及它每个类型出现的次数如这个表所是然后比如说浅球类型ID分别是1S34然后它们出现的次数分别是10,20,30,40那我们就可以得出它每个浅球的CPU使用率是10%20%、30%、40%因为这里总共加起来是100然后用每个浅球出现的次数除以总数就可以得到它的一个CPU使用率然后这里有一个小的demo是来掩饰如何按照浅球类型来统计这个浅球的CPU使用率我们直接从Mate还是开始看吧首先Mate还是说这个代码是用Rot的写的就是它首先从Mate还是说进来它最开始是设置了一个中断电视器我们跳进去看一下然后这里是一个关于设置中断电视器的一个文档然后这个地方这段代码大概的意思就是说我设置了一个定时器然后它的频率是99Hz然后就是一秒钟它会出发99次然后每次都会出发一个中断然后这个步骤是去注册一个中断函数然后这个中断函数它做什么事情呢中断函数它做的事情很简单就是每次在执行这个中断函数的时候它会获取当前这个线程上的Tag然后把这个Tag累加到一个Hasimap里面去这个Profiner它是一个一个带锁的Hasimap就这个是一个全局的一个带锁的Hasimap然后这个就是这个Setup Timer这个还要做的事情然后我们设置电视器之后呢我们起了两个线程然后这两个线程做什么事情呢就是循环的一直去执行请求1234这里是有四种请求ID分别是1234然后但是有个差别在于它在真正的去执行Handle Request这个执行之前它会先设置它这个线程的一个Tag它会把这个请求的Tag设置到它这个线程的Tag上然后这个地方也很简单这个设置Tag其实就是用到了一个Thread Local 线程本地辨量的一个特性就是说每个线程它都有一个自己的Request Tag然后它在开始执行之前把那个请求的ID设置到自己的这个线程的Tag上去然后设置完之后呢它才开始执行这个请求然后这个请求也跟之前一样就是这个ID越大然后它消耗的CPU资源也就越多然后执行完这个请求之后呢它就把这个Tag给签掉就给它简单的设置回凌然后这个就是这两个线程做的事情然后这个Main还说里面的主线程它做的事情也很简单就是它也是有一个循环然后进来之后呢它就它先Sleep一秒钟然后Sleep一秒钟之后呢从这个全局的HashMap中读到读出它统计到的数据就是因为那个定时系统段它会它会往这个HashMap里面存数据嘛然后它把这个HashMap里面的数据给拿出来拿出来之后呢就把它给答应出来然后这里答应逻辑也很简单就是首先它会对这个HashMap里面的直球一个核就是去看总共一共触发了多少次的这个中断然后就把每一个请求类型的ID给答应出来然后这个请求类型它被统计到了次数以及它的CPU使用率是直接用它出现的次数乘以100然后出以它的这个总数就能得到这个请求的一个CPU使用率然后我们现在可以简单的Round一下这个代码我们直接用CargoGunRound就可以跑起来可以看到它是每隔一秒钟就会输出一次每个请求的一个CPU使用率因为我们直接停掉看一下我们可以看到比如这里请求ID为一的然后它进中断的次数是18然后这里统计到这里算出来它的CPU使用率大概是10%然后请求ID是二的它的出现次数是34然后它的CPU使用率是19%然后请求ID是3它的CPU使用率大概是31%请求ID是4它的CPU使用率是38%这个基本是符合我们的预期的那比如我们还可以做一个测试就是比如说我们的HandleRequest这个函数它对某些请求ID它并不去消耗CPU资源比如说我就让它去做一个sleep操作比如对于请求ID如果这个ID等于4的话我就不让它去做任何操作我就简单让它去做一个sleep不要sleep这么久就sleep一毫秒吧然后sleep完之后就直接让它返回然后我们可以再来看一下再来执行一下这个单来观察一下这个时候其实我们期望的就是对于请求ID是4的请求我们的CPU使用率应该很低才对对因为它都在sleep没有没有进到下面的这个CPU消耗我们直接cargo run跑起来我们现在可以看到请求ID是4的它的CPU使用率已经很低了比如说这里就同一到百分之一然后其他的像请求ID12它的CPU随即就上升了这个是符合预期的然后这里请求ID是4的CPU使用率确实是已经降下来了基本上已经很低几乎没有这是符合预期的然后这个代码已经上传到我的get hub上了然后大家可以clo-on下来做一些修改去自己去尝试一下然后我们继续然后下一个要讲的就是continuous refining这个意思是说如果等发生事故之后再去做profile可能就已经晚了因为事故的现场可能已经不在了所以我们需要持续不断的对应用做profile正如刚刚demo演示的那样我们可以每秒钟都对应用程序做一次profile然后把这个profile的结果都保存起来这样子我们后续也能查看历史时刻的profile数据了比如说我们就可以绘制出这样一个表它的x走是时间线然后它的y走是一个CPU使用率然后这里的1234分别是代表请求的内形然后每个颜色的柱子代表这个请求内形它使用的CPU资源消化的多少那我们就可以看到它在之前的历史时刻中比如说在第四时刻一共有两个请求消耗的CPU资源其中请求4的它消耗的CPU资源大概是红色柱子这么高然后请求内形为3的请求它大概消耗了这个橙色的这么多的CPU然后另一个就是如何在分布式应用中来测量就是因为现分布式应用越来越常见比如我们做的就是我们这是一个做分布式数据库的然后我们有三个组件计算成了TITLE B然后存储成的TITLE V 组件然后还有一个负责TITLE B的TITLE Q然后还有一个负责TITLE V 集群调度以及原信息管理的组件PD然后客户端它是通过一个MAXICAL客户端把SICAL请求发送给TITLE B节点然后TITLE B会去解析然后执行这个请求然后然后从TITLE V中读取这个请求所需的数据最终完成计算之后它再将这个结果返回给这个MAXICAL客户端这一个请求的处理实际上对TITLE BTITLE V 组件都会有性能消耗所以我们想要知道一个SICAL请求它到底消耗了多少的CPU资源需要把各个组件上关于这个请求的消耗的资源都要统计上那我们的做法是会是在TITLE B给TITLE V发送API请求的时候也会带上这个请求它原来的SICAL的一个Tag然后在TITLE B和TITLE V中分别按照这个Tag来统计CPU的资源使用率最终然后各个组件分别将各自统计到的CPU资源存储到一个监控节点上面那这样子后面我们就能从这个监控节点上读取读取某一类请求它在某一个历史时刻在某一个组件上面它消耗了多少的CPU资源OK 以上就是我今天的分享谢谢大家请不吝点赞 订阅 转发 打赏支持明镜与点点栏目