令人毛骨悚然的PostgreSQL事件

2022-02-13 17:54:43

今天下午5点17分,正当我结束一天的工作时,我的经理打电话给我说:

<;经理>;:嗨,杰里米-我们有一个<;其他团队>;票证-升级至<;领导者>&书信电报;领导者>;,等等<;校长>;也在尝试提供建议。如果需要诊断,您今晚有空吗&书信电报;同事>;正在通话中

没有义务;只是想看看我有什么空。我很快就想好了——今晚我没有任何计划,日程上没有什么特别的安排。为什么不呢?如果我能帮忙的话,队里的其他人就不需要了,今晚我也没有更好的事情要做。

我与同事同步,然后加入了前线技术团队正在进行故障排除的桥接线。

上周,我和几个和我一起工作的软件工程师聊天,我记得我分享了我的观点,最有趣的问题不是显而易见的问题,比如崩溃。总的来说,崩溃(通常生成核心转储)很容易调试。真正险恶的问题更像是模糊的褐化。它们永远不会触发你的健康监测或警报。所有的合成用户事务都可以工作。日志中没有错误。但应用程序中通常在几秒钟内完成的一个特定功能或模块突然开始需要10分钟才能完成。这可能是由于单个SQL查询突然开始花费更长的时间来完成,这令人费解。每当您自己运行SQL时,它都会在几秒钟内完成。然而,你可以看到数据库连接堆积如山,应用程序中不相关的部分开始延迟获取新的连接……没有什么事情会一直失败,但最终用户仍然无法使用某些东西。一些工作队列中开始出现不祥的积压,如果不尽快处理,可能会出现更大的问题。你看到货运火车正朝你开来…。极其缓慢且不可避免。

这和我今天遇到的情况很相似。我遇到的技术团队在其应用程序架构的一部分中使用PostgreSQL作为数据存储。他们在世界各地部署了许多此应用程序。今天上午,在一个地理位置,他们对PostgreSQL数据库进行了一次重大的版本升级,升级到了版本11。升级后,应用程序的一部分开始出现问题。

当我加入电话时,调查小组已经深入调查了几个小时。他们知道应用程序的哪个部分受到了影响。他们知道这个模块执行的一个特定SQL有问题。有一个“节流阀”可以用来减慢或暂停这个特定的应用程序模块,所以他们暂时关闭该模块以防止对数据库造成不利影响——除非我们正在积极排除故障。当模块被启用时,PostgreSQL视图pg_stat_活动显示数百个连接将同时运行此SQL。视图中没有明显的等待事件,这意味着SQL在CPU上处于活动状态。系统CPU利用率飙升至100%左右,因此很明显,这不是未安装仪器的CPU等待问题。

查询本身实际上相当简单——有一个小问题:一个包含1到1000个元素的动态in列表。很常见的模式。这很有趣,因为它可以防止计算机和人类轻松地将相关查询分组在一起。例如,pg_stat_statements视图将有几百个不同的条目,每个条目都有不同数量的in-list元素。但该查询只对一个表进行操作,除了in列表(一个';<;=';运算符)之外,只有一个过滤器。

从(';first1';1),(';second1';2),…)中的(文本#列1,数字#列3)表格中选择*时间戳_col1<;=:1.

就这些!易于理解的根据pg_关系_size(),该表为845GB。存在两个与当前查询相关的索引:一个是229GB的btree“index1”(text_col1,text_col2),另一个是206GB的btree“index2”(numeric_col1,numeric_col2,numeric_col3,timestamp_col1)。需要注意的是,第二个索引中的最后两列在查询中被引用。

最明显的理论是规划者提出了一个糟糕的执行计划。任何关系数据库的主要版本升级都会出现这种情况。主要版本是当你对规划器、优化器、成本计算算法等进行所有调整和改进时。你的大多数查询要么保持不变,要么变得更快。但很自然,可能会出现一两次倒退。只需要一个人就能毁了你的工作日…。

尽管如此,当我们从psql执行查询时,它在几毫秒内返回——这是我们预期的良好性能。我们还连接到另一个地理位置不同的部署(仍然使用较旧的PostgreSQL主版本),并验证了相同的执行时间和执行计划。当我加入这个调用时,有人提出这样一种理论:应用程序使用准备好的语句,可能在升级之后,应用程序在更新的统计数据准备就绪之前,已经将准备好的语句与糟糕的计划连接并缓存起来。

旁注:我相信本文的所有优秀读者都知道,在PostgreSQL中,对象统计信息会随着主要版本的升级而重置!启动新的主要版本后,您需要运行ANALYZE来更新统计信息!

因此,该团队正准备使用最近升级的数据库在地理位置上启动应用服务器组的滚动重启。他们验证了数据库具有最新的统计数据,并希望确保应用程序服务器能够以最佳的执行计划获得新的数据库连接。

我仔细听着,但我意识到没有太多证据表明这会解决这个问题(尽管这是一个很好的猜测)。与此同时,我一直在阅读罚单记录,并交叉检查围绕测试执行计划所做的工作。

与其他一些关系数据库不同,PostgreSQL对运行时使用的执行计划没有多少可见性。有一个auto_explain可以记录SQL的实际计划,该计划在运行时超过某个阈值时成功完成。pg_stat_activity视图在PostgreSQL 14中添加了查询id,我希望有一天会有一个计划id——但这项工作还没有完成。在pg_stat_活动和EXPLAIN输出中都有一个计划散列,因此很难知道应用服务器当前执行的查询是否与您刚才在psql中运行的查询具有相同的计划——即使是由于容量原因而无法记录的低延迟、高频率查询。当然,动态列表可能仍然会对这一点产生影响,但我不知道有哪种关系数据库有很好的解决方案。

(编辑:2022年2月10日:Joshua留下了一条评论,提醒我Cybertec和铃木广信的pg_show_扩展计划。在我第一次写这篇文章时,没有提到这一点是一个疏忽,我很高兴Joshua提到了它。我以前看过这个扩展,但还没有机会安装并试用。你可以确定它不是w优先考虑仔细观察!)

我知道的下一个最好的解决方案是使用pg_stat_语句作为某种代理。我请团队中的一位DBA运行以下查询:

substr | calls | total | time | mean | time | stddev | u time | blks | rows------------------------------------------------------+----------------------------+---------------------------------选择*从表格whe | 57 | 21904.791707 | 384.294591350877 1249.553887634356 | 2444ッ24选择*从表格whe 1243 12420875.1330768;|10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10 10选择从表选择从表选择从表选择从表选择从表选择*从从表选择从从从从从从表选择从表选择从从从从从表选择从表选择从从从从从从从从从从表选择从从从从从从从从从从124; 12767.352093 |120.446717858491 | 293.357452072648 | 1756 | 24从表格whe | 51 | 12442.307684 | 243.96681733333 | 530.104152533396 | 2077 | 22中选择*。。。解释分析详细内容| 1 | 23.031251 | 23.031251 | 0 | 241 | 0从表格whe | 2 | 11.987225 | 5.9936125 | 0.7968815 | 46 | 2从表格whe | 1 | 6.697005 | 6.697005 1240 1246 1246 1246 1246 1240 1246 1246 1246 1246 1246 1246 1246 1246 1246 1246 1240)中选择1240

我让他们在另一个仍在运行较旧的PostgreSQL主要版本的地理位置上运行相同的查询。当然,其他地理位置显示的调用计数要高得多,因为此查询显示自上次数据库重新启动以来的累计总数,当然,问题数据库是在升级过程中重新启动的。

我注意到的第一件事是,这两个地区之间的行与块的比率完全不同——良好的地理位置有更多的行。这是否意味着使用了不同的执行计划?然后我意识到我在解释我自己的问题时犯了一个错误;我报告的是“每次呼叫的块数”,但我报告的是“所有呼叫的总行数”。在我弄明白了这一点之后,我意识到,好的地理位置和坏的地理位置之间的数字实际上似乎没有显著的差异。当我们在psql提示符下运行问题查询时,执行计划和执行时间也是如此——在好的和坏的地理位置上,它们都是相同的“好”值。

表上的位图堆扫描(成本=3791.09..80234213.68行=6713宽度=273)(实际时间=74.911..74.953行=0循环=1)输出:<;所有栏目>;重新检查条件:((text_col1)::text=';第一名:文本)或。。。或者((text_col1)::text=';第二个1';::text)过滤器:((timestamp_col1<;=';2022-02-09 00:00:00';::不带时区的时间戳)和(((text_col1)::text=';第一名:文本)和。。。和(numeric_col3=';2';::numeric))->;BitmapOr(成本=3791.09..3791.09行=212565宽度=0)(实际时间=74.905..74.946行=0循环=1)>;index1上的位图索引扫描(成本=0.00..38.65行=2261宽度=0)(实际时间=0.026..0.026行=0循环=1)索引条件:((text_col1)::text=';第一名:文本)->;index1上的位图索引扫描(成本=0.00..38.65行=2261宽度=0)(实际时间=0.446..0.446行=0循环=1)索引条件:((text_col1)::text=';第二个1';::文本)->;index1上的位图索引扫描(成本=0.00..38.65行=2261宽度=0)(实际时间=0.447..0.447行=0循环=1)索引条件:((text_col1)::text=';第三条:(文本)

在听电话时,我听到有人提到,由于语句超时设置为2分钟左右,查询超时。这导致了一些问题,即pg_stat_语句数据是否只是因为出错而没有反映长期运行的查询。我认为事实就是这样。但这引出了另一个想法——我问有权访问PostgreSQL日志文件的人是否可以计算他们看到超时错误的速率。(错误是USE方法和RED方法的常见“E”!需要密切关注!)这进一步证实了问题是从升级开始的,在其他地区不存在,但在其他很多地区不存在。

在这一点上,我开始感到有点担心。如果不是计划变更,那会是什么?硬件问题,比如CPU运行频率不正确?(以前见过。)Linux内核深处有一些难以发现的bug?(我也看过,我不喜欢。)我的队友已经做了一次快速而糟糕的表演,抓到了一张截图,但我决定加大赌注。我们有自己的脚本,非常类似于塔内尔·波德的run_xcpu。在他的房间里。工具收藏。它使用perf对运行进程中的堆栈执行低频、保守的采样。它在后台持续运行,将数据保留一周,并可以安全运行数月。即使是在一个有几十个内核的负载很重的服务器上,它也不会用太多的文件或太多的字节来压倒系统。就像塔内尔的剧本一样,它的设计目的是在生产中安全使用。我们扳动开关,开始分析CPU,数据库的CPU为100%。

大约10分钟后,我生成了一个火焰图。以下是我们看到的:

当我第一次看到坏系统上的CPU配置文件时,我认为它不会有多大帮助。调用堆栈基本上符合我们在上面看到的执行计划,在我们的测试中表现良好!Executor_Run正在调用ExecScan(对应于“位图堆扫描”),后者又在调用BitmapIndexScan。我知道经典的索引扫描和seqscan速度很慢(用session GUCs测试),但这两种情况在这里都没有发生。它显然在进行位图扫描。这只是证实了我的担忧,即我们的问题不是一个坏计划。

为了进行比较,我使用了相同的脚本,并在good geography中为较旧的PostgreSQL数据库生成了火焰图。我突出显示了ExecScan函数的出现。下面是它的样子:

首先要注意的是样本数。请记住,这两种方法都是以相同的频率采集样本,持续时间大致相同(10分钟)——因此样本计数的差异实际上反映了CPU时间的差异。我们在健康系统上看到的一切可能仍然存在于不健康系统的某个地方…。但它太小了,你看不见,因为它只是几个数据点,而一个糟糕的查询产生的40万个数据点正在消耗CPU。

现在我心想,这个问题查询一定在健康系统的某个地方运行。调用堆栈可能与较旧的PostgreSQL主版本有微小的差异,但我敢打赌它将大致相同。我从这些ExecScan节点开始,查看了堆栈中显示最低的节点。没过多久我就找到了它——这是唯一一个之前没有某种排序或循环的:

当我放大这个节点时,我注意到一些我不太理解的东西。它看起来几乎和我不健康的系统一模一样——我很自信我的问题就在那里——但还有更多。我看到了函数MultiExecBitmapAnd,但只有23个样本。还有这个函数MultiExecBitmapOr和63个样本。类似的执行计划非常接近导致问题的执行计划。

现在我是Oak Table Network的忠实粉丝,其中一个原因是他们固执地倡导采用基于证据、科学和系统的方法来解决数据库问题。(你会惊讶地发现,这种方法是多么普遍,“找出谁听起来最聪明/声音最大,让他们猜测,直到问题消失……”但坦率地说,虽然我会从这种有条不紊的方法中挤出最后一滴,对于棘手的问题,诊断数据通常是不可用的,在解决方案明确之前,你需要从一个步骤到下一个步骤进行演绎。这似乎是其中一种情况。我摘下耳机,离开桌子。走了一会儿,试图跳出框框思考。

我在想,“我想知道这些是否相关?”我在bad flame图上搜索了MultiExecBitmapOr——瞧,它就在那里——只有366个样本,坏SQL旁边有一条看不见的小细条。大约在这个时候,我重新访问了good SQL语句的执行计划,我注意到了一件重要的事情:有一个名为“BitmapOr”的计划节点。当我查看这两个系统的FlameGraph时,这个想法变得越来越容易理解:“我想知道这个好的SQL计划是否真的与我在健康系统上看到的堆栈对应?这个好的SQL计划是否不是杀死CPU的计划?”

是时候学习一些关于PostgreSQL的新知识了!“BitmapOr”和“BitmapAnd”的确切区别是什么?为什么后者会谋杀我的CPU?!我首先搜索了PostgreSQL文档,找到了一两处,但没有特别有用的地方。接下来,我尝试了谷歌,这让我在PG芥末网站上看到了一个小广告。我越来越自信,我的CPU配置文件可能是一个糟糕计划的确凿证据。最后,我跳转到GitHub,快速搜索了PostgreSQL代码库。浏览了一些评论和代码点击。我现在确信,来自坏数据库的flame图上的调用堆栈反映了与我们自己运行查询时得到的不同的计划。

该查询有一个包含一系列OR条件的in列表。但它还有另一个过滤器——由AND条件连接:时间戳。我想,如果规划者希望日期过滤器的基数更低,它可能会尝试从索引中提取数据,构建位图,并更改我的执行计划。我尝试重新运行查询,简单地将年份从2022更改为2021。

查询…没有…返回。我等了10秒…30秒…1分钟。我尽量不显得激动或是做任何事情,在桥牌上随意发表了一条评论,说我已经更改了日期,我的查询仍在运行。

经过数小时的故障排除,我们可能最终复制了一个错误的执行计划。几分钟后,查询仍在运行。我本能地输入了EXPLAIN ANALYZE,我在等待它完成,这样我就可以把计划发布到罚单上。我的经理指出,我可以马上去解释并得到计划。当然,我为什么没想到呢!(别那样看着我。我知道你有时也会忘记一些显而易见的事情。)

表上的位图堆扫描(成本=50887511.91..3195672174.06行=73035宽度=24)重新检查条件:((text_col1)::text=&39;第一名:文本)或。。。或者((text_col1)::text=';第二个1';::text)和(timestamp_col1<;=';2021-02-09 00:00:00';::不带时区的时间戳)过滤器:(((text_col1)::text=';第一名:文本)和(数字3=';1';::数字)或。。。或者((text#col1)::text=';第二个1';::文本)和(数字3=';2';::数字))->;BitmapAnd(成本=50887511.91..50887511.91行=418910宽度=0)->;BitmapOr(成本=13320.96..13320.96行=513729宽度=0)->;index1上的位图索引扫描(成本=0.00..36.56行=2114宽度=0)索引条件:((text_col1)::text=';第一名:文本)->;index1上的位图索引扫描(成本=0.00..36.56行=2114宽度=0)索引条件:((text_col1)::text=';第二个1';::文本)->;index1上的位图索引扫描(成本=0.00..36.56行=2114宽度=0)索引条件:((text_col1)::text=';第三条:文本)->;index2上的位图索引扫描(成本=0.00..50874172.44行=2597695782宽度=0)索引条件:(timestamp_col1<;=';2021-02-09 00:00:00';::不带时区的时间戳)(493行)

我是否看到位图和平面节点?是吗?我从来没有这么高兴看到BitmapAnd执行节点!事实上,我的查询从未完成,再加上这个执行计划和CPU配置文件——在我看来,我们现在有了问题根源的确凿证据。

第一:PostgreSQL,我亲爱的,我可爱的关系朋友,你在想什么?!这是一个四列206GB索引,其中只有第三列和第四列在SQL中。这不是点选择,甚至不是范围选择。您必须扫描所有206GB内存才能生成此位图,其中只包含几个条目。你为什么要这样对我?

更重要的是:我们还没有解决方案。我们还在下线。所以…回去工作吧。

遗憾的是,PostgreSQL中的选项非常有限。这个数据库没有pg_提示_计划。我对混合会话级别集语句和连接池有点怀疑。我喜欢这样一个技巧:将SQL封装在SQL(不是PL/pgSQL)函数中,并在函数defini上使用SET属性

......