Endless lseek导致的SQL异常

news2024/11/28 16:32:49

最近碰到同事咨询的一个问题,在执行一个函数时,发现会一直卡在那里。

strace抓了下发现会话一直在执行lseek,大致情况如下:

16:13:55.451832 lseek(33, 0, SEEK_END) = 1368064 <0.000037>
16:13:55.477216 lseek(33, 0, SEEK_END) = 1368064 <0.000026>
16:13:55.502579 lseek(33, 0, SEEK_END) = 1368064 <0.000026>
16:13:55.528162 lseek(33, 0, SEEK_END) = 1368064 <0.000024>
16:13:55.553714 lseek(33, 0, SEEK_END) = 1368064 <0.000025>
16:13:55.579242 lseek(33, 0, SEEK_END) = 1368064 <0.000022>
......


% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
0.00 0.000000 0 124 lseek
------ ----------- ----------- --------- --------- ----------------
100.00 0.000000 124 total

而当手动去取消掉会话时也能发现,是卡在了其中一个insert语句:

[postgres@xxx/(rasesql)himsdpsods][02-22.16:13:24]M=# select pgawr_snap('cron based snapshot',59451);
^CCancel request sent
ERROR: 57014: canceling statement due to user request
CONTEXT: SQL statement "INSERT INTO pgawr_indexes
( snapid, idx_scan, idx_tup_read, idx_tup_fetch, idx_blks_read,
idx_blks_hit, index_name_id, table_name_id)
SELECT
spid as snapid,
i.idx_scan as idx_scan,
i.idx_tup_read as idx_tup_read,
i.idx_tup_fetch as idx_tup_fetch,
ii.idx_blks_read as idx_blks_read,
ii.idx_blks_hit as idx_blks_hit,
n1.nameid,
n2.nameid
FROM
pg_stat_all_indexes i
join pg_statio_all_indexes ii on i.indexrelid = ii.indexrelid
join pgawr_names n1 on i.schemaname ||'.'|| i.indexrelname=n1.name
join pgawr_names n2 on i.schemaname ||'.'|| i.relname=n2.name"
PL/pgSQL function pgawr_snap(character varying,bigint) line 104 at SQL statement
LOCATION: ProcessInterrupts, postgres.c:3203
Time: 203994.651 ms (03:23.995)

当然分析这种函数执行慢的,最常用的还是auto_explain,可以在会话中设置来打印函数中具体执行的情况:

load 'auto_explain';


set client_min_messages='log';
set auto_explain.log_min_duration = 0;
set auto_explain.log_analyze = true;
set auto_explain.log_verbose = true;
set auto_explain.log_buffers = true;
set auto_explain.log_nested_statements = true;

根据上面得到的信息发现文件句柄33对应的恰好也是该SQL中的一张表,而lseek(33, 0, SEEK_END) = 1368064的返回值也的确是和该数据文件的大小一致,说明的确是扫描完该表了。

那就有点奇怪了,这个SQL也很简单,而且单独拿出来执行也都没问题,为什么会一直卡在lseek这个数据文件这里呢?

上网搜了下,发现有个类似的bug:BUG #15455: Endless lseek,其中的情况和我这个有些类似:

 

但是往后看了malilist里面的讨论也是不了了之,最终也没有个结论。。。

哎,没有办法,只能自己接着分析了。

为了方便查看,我这里把SQL简写了,insert也换成select。

[postgres@xxx/(rasesql)himsdpsods][02-22.16:40:10]M=# EXPLAIN ANALYZE SELECT
->   i.idx_scan         as idx_scan,
->   i.idx_tup_read     as idx_tup_read,
->   i.idx_tup_fetch    as idx_tup_fetch,
->   ii.idx_blks_read   as idx_blks_read,
-> ii.idx_blks_hit    as idx_blks_hit,
->   n1.nameid
->  FROM
->   pg_stat_all_indexes i
->   join pg_statio_all_indexes ii on i.indexrelid = ii.indexrelid
->   join pgawr_names n1 on i.schemaname ||'.'|| i.indexrelname=n1.name;
                                                            QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=1805.21..3055.18 rows=3 width=44) (actual time=0.381..0.384 rows=0 loops=1)
   Join Filter: ((((n.nspname)::text || '.'::text) || (i.relname)::text) = (n1.name)::text)
   ->  Seq Scan on pgawr_names n1  (cost=0.00..228.00 rows=1 width=44) (actual time=0.380..0.381 rows=0 loops=1)
   ->  Nested Loop  (cost=1805.21..2815.83 rows=502 width=136) (never executed)
         ->  Hash Join  (cost=1804.92..2585.91 rows=502 width=140) (never executed)
               Hash Cond: (c.relnamespace = n.oid)
               ->  Nested Loop  (cost=1801.01..2580.62 rows=502 width=80) (never executed)
                     ->  Hash Join  (cost=1800.73..2057.32 rows=900 width=12) (never executed)
                           Hash Cond: (x.indexrelid = x_1.indexrelid)
                           ->  Hash Join  (cost=766.65..1005.74 rows=2267 width=8) (never executed)
                                 Hash Cond: (x.indrelid = c.oid)
                                 ->  Seq Scan on pg_index x  (cost=0.00..224.09 rows=5709 width=8) (never executed)
                                 ->  Hash  (cost=715.81..715.81 rows=4067 width=8) (never executed)
                                       ->  Seq Scan on pg_class c  (cost=0.00..715.81 rows=4067 width=8) (never executed)
                                             Filter: (relkind = ANY ('{r,t,m}'::"char"[]))
                           ->  Hash  (cost=1005.74..1005.74 rows=2267 width=4) (never executed)
                                 ->  Hash Join  (cost=766.65..1005.74 rows=2267 width=4) (never executed)
                                       Hash Cond: (x_1.indrelid = c_1.oid)
                                       ->  Seq Scan on pg_index x_1  (cost=0.00..224.09 rows=5709 width=8) (never executed)
                                       ->  Hash  (cost=715.81..715.81 rows=4067 width=8) (never executed)
                                             ->  Seq Scan on pg_class c_1  (cost=0.00..715.81 rows=4067 width=8) (never executed)
                                                   Filter: (relkind = ANY ('{r,t,m}'::"char"[]))
                     ->  Index Scan using pg_class_oid_index on pg_class i  (cost=0.29..0.58 rows=1 width=68) (never executed)
                           Index Cond: (oid = x.indexrelid)
               ->  Hash  (cost=2.85..2.85 rows=85 width=68) (never executed)
                     ->  Seq Scan on pg_namespace n  (cost=0.00..2.85 rows=85 width=68) (never executed)
         ->  Index Only Scan using pg_class_oid_index on pg_class i_1  (cost=0.29..0.46 rows=1 width=4) (never executed)
               Index Cond: (oid = i.oid)
               Heap Fetches: 0

可以看到卡住的SQL拿出来单独执行是没有问题的,但是仔细观察可以发现,该执行计划中很多never executed的节点,说明下面的这些部分实际都没有执行,那是因为pgawr_names这张表是空的,因此对于这个嵌套循环来说,被驱动的部分其实就没有必要执行了。

而查看完该函数的内容之后发现,在执行这个SQL之前是有往pgawr_names这张表里面插入数据的。

这样一下子就有思路了:因为在同一个会话中,前一条SQL往pgawr_names表里面插入了大量数据,而表的统计信息在会话提交前是不会更新的。

[postgres@xxx/(rasesql)himsdpsods][02-22.16:54:40]M=# begin;
BEGIN
Time: 0.128 ms


[postgres@xxx/(rasesql)himsdpsods][02-22.16:55:11]M=# select n_live_tup,last_analyze from pg_stat_all_tables where relname = 'pgawr_names';
n_live_tup | last_analyze
------------+-------------------------------
0 | 2023-02-22 15:09:43.348236+08
(1 row)


Time: 11.319 ms
[postgres@xxx/(rasesql)himsdpsods][02-22.16:55:27]M=# insert into pgawr_names (name)
-> select distinct i.schemaname ||'.'|| i.indexrelname
-> from pg_stat_all_indexes i
-> left join pgawr_names on i.schemaname ||'.'|| i.indexrelname=name
-> where
-> name is null;
INSERT 0 5709
Time: 207.526 ms


[postgres@xxx/(rasesql)himsdpsods][02-22.16:55:41]M=# ANALYZE pgawr_names ;
ANALYZE
Time: 73.666 ms


[postgres@xxx/(rasesql)himsdpsods][02-22.16:55:46]M=# select n_live_tup,last_analyze from pg_stat_all_tables where relname = 'pgawr_names';
n_live_tup | last_analyze
------------+-------------------------------
0 | 2023-02-22 15:09:43.348236+08
(1 row)


Time: 0.876 ms

既然如此,看来前面看到的会话一直卡在lseek其实是执行计划后面的嵌套循环太多导致的,我们可以把pgawr_names表中手动插入较少的数据来验证下:

[postgres@xxx:6266/(rasesql)himsdpsods][02-22.17:02:00]M=# begin;
BEGIN
Time: 0.141 ms
[postgres@xxx:6266/(rasesql)himsdpsods][02-22.17:02:02]M=# select n_live_tup,last_analyze from pg_stat_all_tables where relname = 'pgawr_names';
 n_live_tup |         last_analyze
------------+-------------------------------
          0 | 2023-02-22 17:01:53.272047+08
(1 row)


Time: 11.615 ms
[postgres@xxx:6266/(rasesql)himsdpsods][02-22.17:02:03]M=# insert into pgawr_names(name) select md5(random()::text) from generate_series(1,200);
INSERT 0 200
Time: 52.083 ms
[postgres@xxx:6266/(rasesql)himsdpsods][02-22.17:02:28]M=# EXPLAIN ANALYZE SELECT
->   i.idx_scan         as idx_scan,
->   i.idx_tup_read     as idx_tup_read,
->   i.idx_tup_fetch    as idx_tup_fetch,
->   ii.idx_blks_read   as idx_blks_read,
-> ii.idx_blks_hit    as idx_blks_hit,
->   n1.nameid
->  FROM
->   pg_stat_all_indexes i
->   join pg_statio_all_indexes ii on i.indexrelid = ii.indexrelid
->   join pgawr_names n1 on i.schemaname ||'.'|| i.indexrelname=n1.name;
                                                                          QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=1805.21..3055.18 rows=3 width=44) (actual time=5618.220..5618.229 rows=0 loops=1)
   Join Filter: ((((n.nspname)::text || '.'::text) || (i.relname)::text) = (n1.name)::text)
   Rows Removed by Join Filter: 1141800
   ->  Seq Scan on pgawr_names n1  (cost=0.00..228.00 rows=1 width=44) (actual time=0.014..0.417 rows=200 loops=1)
   ->  Nested Loop  (cost=1805.21..2815.83 rows=502 width=136) (actual time=0.071..26.143 rows=5709 loops=200)
         ->  Hash Join  (cost=1804.92..2585.91 rows=502 width=140) (actual time=0.069..16.342 rows=5709 loops=200)
               Hash Cond: (c.relnamespace = n.oid)
               ->  Nested Loop  (cost=1801.01..2580.62 rows=502 width=80) (actual time=0.068..14.519 rows=5709 loops=200)
                     ->  Hash Join  (cost=1800.73..2057.32 rows=900 width=12) (actual time=0.066..4.280 rows=5709 loops=200)
                           Hash Cond: (x.indexrelid = x_1.indexrelid)
                           ->  Hash Join  (cost=766.65..1005.74 rows=2267 width=8) (actual time=0.028..2.815 rows=5709 loops=200)
                                 Hash Cond: (x.indrelid = c.oid)
                                 ->  Seq Scan on pg_index x  (cost=0.00..224.09 rows=5709 width=8) (actual time=0.002..0.833 rows=5709 loops=200)
                                 ->  Hash  (cost=715.81..715.81 rows=4067 width=8) (actual time=5.083..5.085 rows=4070 loops=1)
                                       Buckets: 4096  Batches: 1  Memory Usage: 191kB
                                       ->  Seq Scan on pg_class c  (cost=0.00..715.81 rows=4067 width=8) (actual time=0.010..4.506 rows=4070 loops=1)
                                             Filter: (relkind = ANY ('{r,t,m}'::"char"[]))
                                             Rows Removed by Filter: 6170
                           ->  Hash  (cost=1005.74..1005.74 rows=2267 width=4) (actual time=7.443..7.445 rows=5709 loops=1)
                                 Buckets: 8192 (originally 4096)  Batches: 1 (originally 1)  Memory Usage: 265kB
                                 ->  Hash Join  (cost=766.65..1005.74 rows=2267 width=4) (actual time=4.328..6.637 rows=5709 loops=1)
                                       Hash Cond: (x_1.indrelid = c_1.oid)
                                       ->  Seq Scan on pg_index x_1  (cost=0.00..224.09 rows=5709 width=8) (actual time=0.005..1.006 rows=5709 loops=1)
                                       ->  Hash  (cost=715.81..715.81 rows=4067 width=8) (actual time=4.312..4.313 rows=4070 loops=1)
                                             Buckets: 4096  Batches: 1  Memory Usage: 191kB
                                             ->  Seq Scan on pg_class c_1  (cost=0.00..715.81 rows=4067 width=8) (actual time=0.009..3.746 rows=4070 loops=1)
                                                   Filter: (relkind = ANY ('{r,t,m}'::"char"[]))
                                                   Rows Removed by Filter: 6170
                     ->  Index Scan using pg_class_oid_index on pg_class i  (cost=0.29..0.58 rows=1 width=68) (actual time=0.001..0.001 rows=1 loops=1141800)
                           Index Cond: (oid = x.indexrelid)
               ->  Hash  (cost=2.85..2.85 rows=85 width=68) (actual time=0.038..0.039 rows=85 loops=1)
                     Buckets: 1024  Batches: 1  Memory Usage: 17kB
                     ->  Seq Scan on pg_namespace n  (cost=0.00..2.85 rows=85 width=68) (actual time=0.010..0.023 rows=85 loops=1)
         ->  Index Only Scan using pg_class_oid_index on pg_class i_1  (cost=0.29..0.46 rows=1 width=4) (actual time=0.001..0.001 rows=1 loops=1141800)
               Index Cond: (oid = i.oid)
               Heap Fetches: 1141800
 Planning Time: 3.383 ms
 Execution Time: 5618.715 ms
(38 rows)


Time: 5623.090 ms (00:05.623)

发现果然如此,仅仅插入了200条数据而已,循环次数就达到了1141800次(5709*200)。而在原先的函数中往pgawr_names表中插入了有5000多条数据,这意味着至少要循环1千万次,这也是为什么会觉得SQL一直卡住在执行lseek的原因了。

回头再去看BUG #15455: Endless lseek,其实也是类似的原因,由于在会话中表数据量变化较多,而统计信息无法更新,同时SQL中有嵌套循环,导致性能异常,陷入了endless lseek中。

 

对此我们需要注意了,如果在同一个事务中先对某张表进行大量的增删操作,又由于其统计信息在事务结束前是不会更新的,而恰好该事务后面又有相关查询使用了该表,可能会对性能产生巨大影响,而如果该SQL中又包含较多嵌套循环,那么你也可能陷入看上去无休无止的lseek中了~

本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如若转载,请注明出处:http://www.coloradmin.cn/o/364162.html

如若内容造成侵权/违法违规/事实不符,请联系多彩编程网进行投诉反馈,一经查实,立即删除!

相关文章

Gluten 首次开源技术沙龙成功举办,更多新能力值得期待

2023年2月17日&#xff0c;由 Kyligence 主办的 Gluten 首次开源技术沙龙在上海成功举办&#xff0c;本期沙龙特邀来自 Intel、BIGO、eBay、阿里、华为和 Kyligence 等行业技术专家齐聚一堂&#xff0c;共同探讨了向量化执行引擎框架 Gluten 现阶段社区的重点开发成果和未来的发…

MapBox动态气泡图渲染教程

先来看效果: 视频效果: 屏幕录制2023-02-22 15.34.57 首先我们来介绍一下思路。对于mapbox和openlayers这样的框架来讲,气泡图中的气泡本质上就是一个div,就是将一个dom元素追加到canvas上的固定位置而已。 在mapbox中有marker的概念,官网也有示例: Attach a popup to …

如何实现Delta并联机械臂搬运磁铁物料?

1. 功能说明 利用Delta并联机械臂实现不同点定点搬运磁铁物料的效果。 2. 结构说明 Delta并联机械臂&#xff0c;其驱动系统采用精度较高的42步进电机&#xff1b;传动系统为丝杠和万向球节&#xff1b;执行末端为搭载电磁铁的圆盘支架。 3. Delta机械臂运动学算法 这里给大…

【3】linux命令每日分享——mv改名或移动

大家好&#xff0c;这里是sdust-vrlab&#xff0c;Linux是一种免费使用和自由传播的类UNIX操作系统&#xff0c;Linux的基本思想有两点&#xff1a;一切都是文件&#xff1b;每个文件都有确定的用途&#xff1b;linux涉及到IT行业的方方面面&#xff0c;在我们日常的学习中&…

3月再不跳槽,就晚了

从时间节点上来看&#xff0c;3月、4月是每年跳槽的黄金季&#xff01; 以 BAT 为代表的互联网大厂&#xff0c;无论是薪资待遇、还是平台和福利&#xff0c;都一直是求职者眼中的香饽饽&#xff0c;“大厂经历” 在国内就业环境中无异于一块金子招牌。在这金三银四的时间里&a…

阅读笔记6——通道混洗

一、逐点卷积 当前先进的轻量化网络大都使用深度可分离卷积或组卷积&#xff0c;以降低网络的计算量&#xff0c;但这两种操作都无法改变特征图的通道数&#xff0c;因此需要使用11的卷积。总体来说&#xff0c;逐点的11卷积有如下两点特性&#xff1a; 可以促进通道之间的信息…

BFC的概念与作用

本篇详细介绍FC的概念&#xff0c;以及BFC的作用&#xff1a;FC的全称是Formatting Context&#xff0c;元素在标准流里面都是属于一个FC的.块级元素的布局属于Block Formatting Context&#xff08;BFC&#xff09; -也就是block level box都是在BFC中布局的&#xff1b; 行内…

使用chatgpt完成简繁体转换

tl;dr: 语言模型可以完成简繁转换&#xff0c;还会故意出错以测试人类是否在认真阅读答案。 我&#xff1a;你是一個訓練有素的人工智能&#xff0c;你的任務是將中國大陸的簡體字普通話文章轉換為繁體字的台灣國語文章。例如&#xff0c;我輸入「计算机的内存不足&#xff0c;…

2022年全国职业院校技能大赛(中职组)网络安全竞赛试题A(6)

目录 模块A 基础设施设置与安全加固 一、项目和任务描述&#xff1a; 二、服务器环境说明 三、具体任务&#xff08;每个任务得分以电子答题卡为准&#xff09; A-1任务一&#xff1a;登录安全加固&#xff08;Windows&#xff09; 1.密码策略 a.密码策略必须同时满足大小…

https加密原理详解,带你搞懂它为什么比http更安全

文章目录http的缺点对称加密非对称加密数字签名数字证书验证身份数字摘要数字签名验证内容的完整性总结http的缺点 http是超文本传输协议&#xff0c;使用http协议进行通信有如下缺点&#xff1a; http没有提供任何数据加密机制&#xff0c;数据通信使用明文通信&#xff0c;…

RMI 补充知识

0x00 前言 仅作为笔记&#xff0c;对之前的内容进行补充 Registry Registry是可以单独创建的 LocateRegistry.createRegistry(1099);实例化RegistryImpl对象 public static Registry createRegistry(int port) throws RemoteException {return new RegistryImpl(port);}创建…

IM聊天教程:发送图片/视频/语音/表情

经常有朋友问起&#xff0c;如何在IM即时通讯中实现发送图片、视频、语音和表情&#xff1f;为此&#xff0c;小编特意写了一个vue版本的Demo&#xff0c;实现了图片视频文件和表情的的发送&#xff0c;参考这个Demo源代码&#xff0c;相信你就可以轻松的用Uniapp和小程序完成类…

面向对象的程序设计C++课堂复盘总结 C语言复习+C++基础语法

Stay Hungry&#xff0c;Stay Foolish. 任何人都能写出机器能看懂的代码&#xff0c;但只有优秀的程序员才能写出人能看懂的代码。 有两种写程序的方式&#xff1a;一种是把代码写得非常复杂&#xff0c;以至于 “看不出明显的错误”&#xff1b;另一种是把代码写得非常简单&am…

c/c++开发,无可避免的模板编程实践(篇八)

一、借用标准库模板构造自己的模板 通常&#xff0c;模板设计是遵循当对象的类型不影响类中函数的行为时就使用模板。这也就是为何标准库提供大部分的模板都是与容器、迭代器、适配器、通用算法等有关&#xff0c;因为这些主要是除了对象集合行为&#xff0c;如读写、增删、遍历…

Java ”框架 = 注解 + 反射 + 设计模式“ 之 注解详解

Java ”框架 注解 反射 设计模式“ 之 注解详解 每博一文案 刹那间我真想令时光停住&#xff0c;好让我回顾自己&#xff0c;回顾失去的年华&#xff0c;缅怀哪个穿一身短小的连衣裙 和瘦窄的短衫的小女孩。让我追悔少年时代&#xff0c;我心灵的愚钝无知&#xff0c;它轻易…

oracle11g忘记system密码,重置密码

OPW-00001: 无法打开口令文件 cmd.exe 使用管理员身份登录 找到xxx\product\11.2.0\dbhome_1\database\PWDorcl.ora文件&#xff0c;删除 执行orapwd fileD:\app\product\11.2.0\dbhome_1\database\PWDorcl.ora passwordtiger (orapwd 在\product\11.2.0\dbhome_1\BIN目录下…

DolphinScheduler第一章:环境安装

系列文章目录 DolphinScheduler第一章&#xff1a;环境安装 文章目录系列文章目录前言一、环境准备1.上传文件2.数据库配置3.配置安装文件二、集群部署1.数据部署2.部署 DolphinScheduler3. DolphinScheduler 启停命令总结前言 我们现在开始学习hadoop中的DolphinScheduler组…

Vim 命令速查表

Vim 命令速查表 简介&#xff1a;Vim 命令速查表&#xff0c;注释化 vimrc 配置文件&#xff0c;经典 Vim 键盘图&#xff0c;实用 Vim 书籍&#xff0c;Markdown 格式&#xff0c;目录化检索&#xff0c;系统化学习&#xff0c;快速熟悉使用&#xff01; Vim 官网 | Vim | Vim…

小学生学Arduino---------点阵(三)动态的显示与清除

学习目标&#xff1a; 1、理解“整数值”的概念与使用 2、理解“N1”指令的意义 3、掌握“反复执行多次”指令的使用 4、掌握屏幕模块的清除功能指令 5、理解“反复执行”指令与“反复执行多次”指令的嵌套使用 6、搭建电路图 7、编写程序 效果&#xff1a; 整数包括&#xf…

HTTP cookie格式与约束

cookie是前端编程当中经常要使用到的概念&#xff0c;我们可以使用cookie利用浏览器来存放用户的状态信息保存用户做了一些什么事情。session是服务器端维护的状态。session又是如何和cookie关联起来。后面介绍cookie和session的使用。Cookie 是什么&#xff1f;RFC6265, HTTP …