高可用之路-观测篇-那些年遇到过的指标幻觉

高可用之路-观测篇-那些年遇到过的指标幻觉前言当前AI的长程链路推导已经非常强大。一旦让Codex/CC接入可观测性平台它能够非常好的利用工具进行各种组合获取相应的数据来得到问题根因(RCA)。但笔者遇到过的很多问题往往是在一些很反直觉的地方无法通过现有的数据直接准确的推导到下一步尤其体现在观测指标数据本身无法表达问题的情况下这种很容易让AI跑偏毕竟监控只是事实的投影。在这里笔者就详细的阐述一下其中的一种表现—-指标幻觉即指标反映有问题未必意味着系统真的有问题指标反映没问题也未必意味着系统真的没问题甚至指标本身异常出现的时间和周期都可能误导我们。指标幻觉分类当前笔者主要阐述的是观测指标幻觉也即观测指标本身会误导我们找到RCA的种种情形。指标是我们为了反应整个业务情况而定义出的各种计数。这个计数可以是采集的数据Counter/Gauge或者对采集数据的运算(QPS/TPS等)。我们往往会定期的将指标读出并在时间轴上展示出来并观察这个指标曲线来观测业务的变化。无论是计数本身还是读取计数的时间点都可能产生幻觉。更有甚者多种计数之间由于没有原子性的保证就算它们各自是准确的时间点也是合适的但组合起来就成了幻觉。本文使用两套分类。首先按幻觉在观测链路中的产生环节分类最后再按幻觉对决策造成的结果分类。同一种产生机制可能同时导致假阳性、假阴性或错误归因。计数产生的幻觉指标幻觉未必来自数据错误。很多时候指标只呈现系统事实的某些维度。我们据此推断其他维度时可能超出它能够支持的范围。很多指标计数在定义的那一刻就已经在某些情况下会产生无法表达的情况了这个情况无法靠更换观测方式或者手段来解决。因为这是计数本身的固有限制。数据表达空间饱和导致幻觉这种情况往往是整个数据空间本身是有限的而我们的指标只能在这个空间内腾挪。例如TCP端口号最多从1-65535也就是在五元组中的四元组固定(源IP:协议:目的IP:目的端口号 这四者固定)的情况下能够同时存在的端口号也就65535个。在LVS中一个五元组用一个表项表示。它衡量新建连接用的就是五元组表项的新增数量。对应源代码如下所示:tcp_conn_schedule |-ip_vs_schedule /* 如果新建conn表项成功则对已有连接数 */ |-ip_vs_conn_stats 而在我们的入口函数ip\_vs\_in中 static unsigned int ip_vs_in(unsigned int hooknum, struct sk_buff *skb, const struct net_device *in, const struct net_device *out, int (*okfn) (struct sk_buff *)) { ...... // 如果能找到对应的五元组 cp pp-conn_in_get(af, skb, pp, iph, iph.len, 0, res_dir); ​ if (likely(cp)) { /* For full-nat/local-client packets, it could be a response */ if (res_dir IP_VS_CIDX_F_IN2OUT) { return handle_response(af, skb, pp, cp, iph.len); } } else { /* create a new connection */ int v; // 找不到对应的五元组则新建连接同时conn if (!pp-conn_schedule(af, skb, pp, v, cp)) return v; } ...... }由于2MSL的存在LVS本身会设置独立的表项超时策略在默认120s之后(FIN_WAIT/TIME_WAIT)才会回收表项。为了创建连接的性能考虑TCP协议允许端口复用LVS本身也会进行表项复用。但从上面代码可以看到LVS的新建连接数conn只是反映了表项的增长。所以这个监控指标完全无法反应端口复用的情况就导致LVS的新建连接数在新建连接超过一定速率导致复用表项的时候产生失真。表项的增长表达空间是有限的真实的新建连接数超过了这个限制。这就会产生一个幻觉明明新建连接速率变快了但这个监控指标却会反应出来速率大幅下跌甚至跌0如下图所示:一旦我们配置了跌0告警很容易让我们误以为当前系统出现了重大故障实际可能只是流量的正常增长。抑或将我们排查问题的思路错误导向到LVS上游流量出了问题。具体可以看笔者的这篇文章: 解Bug之路-NAT引发的性能瓶颈 - 苍天环绕的小世界注: 这个问题只是在当前案例下的LVS相关实现和配置导致的问题。数据精度不够导致幻觉当我们追求的指标精度超过了数据指标所能表达的精度范围之外也会产生幻觉。例如seconds_behind_master这个主从延迟的黄金指标。这个指标的单位是秒也就是说它只能表达秒级的延迟但有意思的是我们在监控计算上对它取平均的时候往往会产生百毫秒这种错觉。也即一个从库是20ms延迟另一个从库是500ms延迟。据此判定20ms从库比500ms从库主从延迟好就是从这个秒级指标衍生出来的幻觉事实上这两可能在实际延迟中完全一样唯一的不一样只在于主从连接的时候有没有由于主从clock的diff而在秒的维度产生较大的误差而已。如下图所示:图中主库时钟为1.0s、从库时钟为0.5s时建立连接计算出的clock_diff_with_master为-1。在实际复制延迟为0的假设下同一条连接的seconds_behind_master仍会随观测时刻在0和1之间变化。改变建连时刻又可能改变这个秒级时钟差的取整结果进而改变后续读数的分布。因此两个实际复制延迟相同的从库也可能呈现出不同的平均读数。这就是seconds_behind_master指标由于精度问题给我们带来的幻觉。 详情可以见笔者的博客: MySQL-Seconds_behind_master的精度误差 - 苍天环绕的小世界数据产生来源单一导致幻觉数据来源也很容易导致幻觉尤其是在我们要衡量不同节点之间差距的时候如果数据来源只有一个节点也就是只采集一个节点的数据做运算那么就天然的无法反应出在节点间无法通信时候的状况以至于让我们能产生这两节点没有任何差距的幻觉。seconds_behind_master这个主从延迟就能产生这种幻觉。Seconds_behind_master max(0,从库当前时间-正在回放时间的主库时间-主从时间差) 1.从库当前时间从 从库 取得 2.正在回放时间的主库时间是 当前从库正在回放的主库事件的时间戳这个事件已经被从库接受了 3.主从时间差从 主从connect的那一刻取得从上面的公式我们可以看出在计算seconds_behind_master的这一刻并没有同时从主库获取任何信息。主库事件的时间戳也是从库中本身的已经接收到的信息。那很明显的要衡量主从的差距没有主库事实信息的参与那肯定是不准确的。这个指标事实上只反应了SQL线程apply事件的时间和IO线程拉取到的事件时间的差距。 就举一个我们演练时候遇到的极端例子我们在演练时刻模拟主从网络断开从库无法拉取到最新的主库事件那么尽管主从延迟拉长到几十分钟seconds_behind_master仍可能保持为0SQL线程已回放完I/O线程此前接收到的事件而I/O线程尚未感知连接失效仍被标记为已连接。恢复连接并重新接收事件后SQL线程开始回放断网期间积压的旧事件指标才显示出数十分钟的延迟。在模拟断网时刻一切静悄悄一旦恢复类似的告警就会如潮水般涌来。如下图所示:在这个例子里我们就会在故障时刻产生啥问题都没有发生的岁月静好的幻觉但实际已经造成了很长时间的影响。数据被观测影响导致幻觉观测本身也会影响数据的生产有一些指标如果你做了某些特定的观测和不做这种观测会表现出不同的结果。笔者举一个例子Innodb_rows_inserted这个指标其本身设计的指标是来观察数据库的插入负载 但我们在做数据库的监控观测的时候会频繁的运行下面这个命令:select * from information_schema.processlist用来观察当前MySQL上的每个连接正在做什么用来获取慢SQL/锁等待等信息。查询information_schema.processlist时MySQL会动态生成查询结果。在该案例的执行路径中结果被写入InnoDB内部临时表这些内部插入也被计入了Innodb_rows_inserted尽管用户执行的是SELECT命令代码Stack如下:fill_schema_processlist() ...... -schema_table_store_record() ...... |-srv_stats_.n_rows_inserted.inc()当我们连接数过多的时候例如数千个一次processlist命令就会增加数千条innodb_rows_inserted。假设10s探测一次连接有5000个那我们就会发现在分钟级的监控中由innodb_rows_inserted计算出的QPS(在这里就是rows/s)平均多出了500如果我们有秒级监控则会发现在运行sql的那一秒突刺增加了5000。更有甚者一旦发现数据库有问题我们要动态加大观测频率的时候这个效应就会急剧放大我们观测到的insert rows QPS例如搞成1s一次在分钟级的监控中QPS就会凭空增长5000!如下图所示:一旦没有意识到这个问题这个监控指标就会直接将我们导入到MySQL负载暴增的错误方向!数据语义漂移导致幻觉指标的计算方式没有变化但我们在解读它时会不知不觉地切换概念。例如: Linux kernel的一个指标叫做throttled_timelinux源文档描述的是:throttled_time: The total time duration (in nanoseconds) for which entities of the group have been throttled也就是该cgroup调度实体被限流的总时长。这个解读起来就有不少幻觉的空间解读起来的语义会有各种漂移。 首先第一重幻觉:总时长是时间片而不是墙钟我throttled_time 3.9s不代表我整个cgroup停顿了3.9s而是不同的调度实体停顿增加起来的时间片是3.9s 第二重幻觉:调度实体并不是cgroup配置的CPU核数只要没有绑核调度实体可能分散在整个物理机上。 第三重幻觉:虽然cgroup运行的时间片和调度实体被限流的时间片计算方式都是在一个调度实体上用当前的时钟做delta。但运行时间片其实由于受cgroup的限制(例如配置了8C也就是800ms的时间片cfs_period_us是100ms)最多只能到800ms但受限制的时间片确由于没有这个限制所以可以累积到6400ms(分散在64核上)。如下图所示:在这里所以实际可运行的时间片和由于被限流导致停顿的时间片这两个都叫时间片其实表达的是不同的东西一个是service_time一个是wait_time。这个就像什么呢两辆车发生剐蹭处理花了这两辆车车主的10分钟(service_time10*220分钟)但是确让后面一百辆车都等了10分钟也就是浪费了大家100*101000分钟时间一样。在这个例子里面同样一个“时间”先被理解为墙钟时长再被理解为跨调度实体累加的时长最后又把运行时(service_time)与等待时间(wait_time)当成了同一种时间。这种解读过程中含义的逐步滑动就是语义的漂移。具体问题可以见笔者的博客:解Bug之路-with AI-应用被限流 - 苍天环绕的小世界值得注意的是由于throttle_time在我们的监控体系里面是分钟级指标笔者无法靠其发生的时间点来判定出CPU限流是导致线上系统问题的因还是果。于是通过日志造了一台示波器来解决了指标缺乏的问题。读取时间点产生的幻觉数据本身准确了但是采集的时间点不一样也会导致对于数据的解读不一样进而造成幻觉。读取时间点的相位固定导致幻觉监控往往是从用定时的方式从对应的机器取相关的数据例如每分钟一次。那么如果每分钟内负载其实有相当大的波动在前30s之内CPU能到50%在后30sCPU只能到10%但监控取点在这一分钟的相位往往是固定的例如A机器固定在第10s取点B机器固定在第50s取点在监控看来A机器的CPU负载就是B机器的五倍。注:当前采样公式为:每分钟采样一次 CPU.busy (当前采样时刻容器累计 CPU 时间 - 1 秒前容器累计 CPU 时间) / 1s如下图所示:如果我们无法识别出来这是由监控带来的相位幻觉那其实非常容易将我们排查问题的走向转向机器负载不均衡。 具体问题可以见笔者的博客: 日常问题排查-同应用同流量为什么CPU.busy差了 5 倍 - 苍天环绕的小世界读取时间点的相位漂移导致幻觉相位漂移会产生更加隐蔽的幻觉而且会在很大程度上影响我们的排查方向。固定的相位漂移会将我们误导到这是一个长周期的问题。就举一个很经典的例子这也是笔者和另一位同学一块排查的。这是一个CPU load每隔7小时就会飙高并持续8分钟的问题。很明显的按照通用的思路我们应该排查每7个小时一次的定时任务但我们始终无法找到。那后续我们采用的方案是采用ebpf抓那8分钟的CPU load对应的nr_running计数比对过数据发现每分钟都会在第37s的时间点有将近100ms的nr_running高。但这个100ms的nr_running高在故障时间段之外依旧保持同样的第37s高没有任何变化。这就让我们不得不怀疑起采样点的相位漂移问题。看了下源代码CPU load的采样周期是:LOAD_FREQ 5 * HZ 1 对应于现代服务器CONFIG_HZ1000也就是5s1ms也就是下一次采样的时候会产生1ms的漂移。这就造成了这个非常诡异的7小时”周期性”问题现象。 在这里笔者先给出一个图例吧:首先解释为什么会cpu load高8分钟: 很明显的100ms需要100次采样才能漂移走对应于1次5s也就是100*5500s也就是8.3分钟(8分钟20s)。 第二解释为什么每隔大约7小时会cpu load变高: 很明显的只要cpu load采集相位漂进这一分钟的100ms就会飙高。那么在原来第37s的CPU load漂走之后。下一个能漂进来的是原来第32s的采样它需要漂5s-100ms也就是4900ms才能达到第37s这个相位那么每漂1ms需要5s时间那么漂4900次就是(4900*5)为24500s也就是6.8小时(6小时48分20秒)。如果按照这两个过程的整体进行运算: 8分钟20s6小时48分20s 6小时56分40s。在我们进一步确认了详细的周期时间间隔后完美的对应上了一分钟都不差。时钟漂移导致幻觉这大概是最容易遇到也最容易被破解的幻觉了这个在观测多台机器日志的时候非常的频繁。这个幻觉经常会让我们觉得因果箭头反了举个最简单的例子如果我们订单的状态机按照代码逻辑是从ACCEPT-SUCCESS。但如果在分布式系统中更新成ACCEPT和更新成SUCCESS往往不在同一台机器例如在A机器更新为ACCEPTB机器更新为SUCCESS。这时候两台机器的时钟如果出现不一致B的墙钟落后A的墙钟那么我们很容易在按照时间戳排序的时候会发现日志中订单状态先被更新为SUCCESS再被更新为ACCEPT。两台机器的时钟不一样日志打印的时候看的是不同的clock就极其容易造成这种现象。这种幻觉在分布式系统中普遍存在由于分布式系统中往往没有统一的时钟(至少在观测指标的时候是如此)因此跨机器日志的时间戳顺序不能直接当作事件的因果顺序。数据与数据之间没有原子性导致的幻觉当我们在采集一个指标的时如果要要抓两份相关联的数据例如A和B这两份数据往往没有事务的保证。那么在系统的瞬态快照里面A和B是一致的但是分了两次抓取后B数据已经改变了当我们对A和B做相关运算的时候就会得到错误的结果。那其实在上面的相位漂移的例子排查过程中也遇到了这种幻觉。这也是我们为什么会采用ebpf去观察nr_running的原因。因为通常的PS命令无法抓到短进程我们以100ms的精度去抓发现进程数量少的可怜但是用ebpf中的工具确能抓到大量短进程。答案就在PS需要抓取多次数据而这多次数据间的不一致导致他无法正常的展示出短进程。整个过程如下图所示:由于/proc下的PID和stat数据之间没有做一致性的保护。就会导致系统里虽然存在的大量短进程但是我们依旧产生了进程数很少的幻觉。当然这只是PS漏掉短进程的一个因素还有一些其他因素例如短进程在PS遍历的时候确实已经消亡了。值得注意的是导致这个37s的突刺实际上是个监控系统在100ms之内新建了大量短进程去抓取其它机器的数据。这不得不说是观测系统自身导致了观测问题的又一个例子。幻觉影响决策我们依赖观测系统作去洞悉系统的状态但指标出现的幻觉会大幅影响我们的决策。按照影响决策的分类我们其实可以将幻觉分类为假阳性/假阴性/扰乱判断进而让我们做出错误的决策。假阳性这一类往往是指标提示我们有问题但实际并没有问题。例如我们的上面阐述的例子中:例子可能的错误决策lvs新建连接速率的指标问题会让我们误以为流量跌0了实际流量只是正常增长。抑或者将排查问题思路指向上游流量骤降。seconds_behind_master的精度问题会让我们误以为某台从库比另一台差从而错误的换掉了从库机器。CPU采样相位固定导致的负载不均衡会让我们误以为这几台CPU高的机器承受了其他流量或者CPU性能低从而进行错误的扩容或替换机器状态机的因果反转会让我们觉得代码写的有问题实际不是监控导致insert rows/s飙高会让我们觉得insert流量瞬间暴增实际只是监控导致的幻象假阴性这一类往往是指标提示我们没有问题但实际有问题。例如我们的上面阐述的例子中:例子可能的错误决策Seconds_behind_master的延迟反应让我们觉得从库正常实际已经延迟了好久导致无法快速下掉问题从库PS抓进程数量很少会让我们觉得机器上面进程数量正常而实际早已有无数的幽灵进程在瞬间生灭扰乱判断这一类往往是指标误导我们的思路让我们错误归因例子可能的错误决策CPU load每7小时飙高将我们导入到不存在的长周期性定时负载的错误思路。实际它是一个每分钟的第37s都存在的问题。throttled_time的语义漂移让我们认为容器在实际层面真的停顿了throttled_time的墙钟时间这个数值和流量实际停顿时间过于接近让我们直接错误归因。观测本身隐含边界再进一步这些假阳性和假阴性其实是在我们理解观测时候的前提边界相关。当我们使用一个指标的时候理解了其字面含义后其实也隐含的接受了指标本身的边界和前提。我们会错误决策往往是觉得一旦出现指标A那必然是系统状态B导致的。或者一旦没出现指标C那么必然没有系统状态D。但现实确不是这样不同系统状态可以产生完全相同的观测结果相同的系统状态也可以产生完全不同的观测结果。AI也会被指标所欺骗因为指标本身就是事实的投影当AI接入到可观测性平台的时候能够观测到的都是失去部分事实信息的指标。在这些指标失真的情况下很难判断出正确的结果而在现阶段AI在笔者的使用实践中很少能够自发的去质疑指标甚至去创造或寻找新的代理指标。所以当前自动化的TroubleShooting在很多情况下无法做到可靠还必须依靠人去质疑指标语义、检查采集实现、引入独立证据或者设计新的观测。总结我们所有的观测指标只是在观察事实的某一个投影投影会丢失维度从而与事实产生偏差偏差就可能导致我们错误决策。为了弥补这种偏差我们会改变采样时刻提高探测频率或者组合更多数据互相印证。但改变采样时刻可能引起更隐蔽的虚假周期性问题提高探测频率会加大系统负载甚至引入虚假QPS组合多种数据互相印证又会有数据间的一致性问题。这些手动消除了原有的偏差但可能引入了新的偏差。因此指标无法做到在毫无前提假设的情况下普适的可信。指标是否可信必须结合具体判断来回答它实际记录了什么我们希望据此推断什么两者之间依赖哪些条件当指标与独立证据矛盾时应检查这些条件并通过其他观测方式验证。