searchusermenu
  • 发布文章
  • 消息中心
点赞
收藏
评论
分享
原创

记一次网络配置导致的慢查询排查过程

2023-10-27 07:02:07
19
0

背景

客户线上环境反馈两条慢SQL语句,执行时间都在10s以上。两条SQL都只是简单扫视图,并不涉及复杂的JOIN操作,虽然SQL1有聚合函数,但由于视图pg_stat_database并不大,其开销也不会很大。

两条SQL语句如下所示(语句中的常量信息用$代替):

SQL1:

SQL2:

 

初步分析

这两条慢SQL在一开始非常令人困惑。但按照慢SQL排查的常规流程,首先还是查看SQL语句的执行计划。通过加上EXPLAIN ANALYZE关键字查看其执行信息,这里以SQL1为例:

两个子查询耗时很短,主查询中SeqScan on pg_database耗时也很短,主要耗时全在最外层的Aggregate算子上。Aggregate算子主要是对SELECT coalesce(sum(xx)) FROM pg_stat_database d 系统视图中的数据做聚合操作,初步怀疑和系统视图pg_stat_database有关。

pg_stat_database是系统视图而不是系统表,查询时底层涉及到建立视图的操作,并不是直接SeqScan on pg_stat_database。在本地环境测试也发现,直接查询系统表如pg_database时间会快很多。

通过\d+ pg_stat_database命令查看系统视图定义如下:

在客户环境执行该VIEW DIFINITION(相当于SELECT * FROM pg_stat_database):

从执行计划可以看出,创建这个系统视图的操作就花费10秒钟,而客户整个SQL语句的用时基本都花在这上面。

而这个建视图语句执行计划并不复杂,SeqScan on pg_database获取oid字段,然后调用各种系统函数如pg_stat_get_db_xact_commit(oid)来生成系统视图中的字段。

pg_database表本身并不大(rows=4),耗时不可能在SeqScan on pg_database上,只可能在这些系统函数调用上。

 

深入分析

单独测试VIEW DIFINITION中的每个函数,每个函数都会导致慢SQL。

这里以pg_stat_get_db_xact_commit()函数为例:

这里继续看pg_stat_fetch_stat_dbentry()函数:

可以看到这里调用了backend_read_statsfile()函数(上面的系统视图定义中调用的所有系统函数最后其实都调用到该函数):

/*
 * 如果未完成,将 stats collector 的统计信息文件读入哈希表。 
 * 结果将一直保留到 pgstat_clear_snapshot() 被调用(通常在事务结束时)。
 */
static void
backend_read_statsfile(void)
{
	TimestampTz min_ts = 0;
	TimestampTz ref_ts = 0;
	Oid			inquiry_db;
	int			count;

	/* already read it? */
	if (pgStatDBHash)
		return;
	Assert(!pgStatRunningInCollector);

	/*
	 * 在 normal backend 中,检查自己的数据库的数据是否过时,因此在查询消息中发送 MyDatabaseId。 
	 * 在 autovac launcher 中,检查共享目录数据的过时性,并在查询消息中发送 InvalidOid。
	 */
	if (IsAutoVacuumLauncherProcess())
		inquiry_db = InvalidOid;
	else
		inquiry_db = MyDatabaseId;

	/*
	 * Loop,直到 stats file 足够新,或者 ran out of time。
	 * 统计信息查询消息会重复发送,以防 collector 将其丢弃,但不是每次,防止干扰 collector。
	 */
	for (count = 0; count < PGSTAT_POLL_LOOP_COUNT; count++)		/* #define PGSTAT_POLL_LOOP_COUNT 1000 */
	{
		bool		ok;
		TimestampTz file_ts = 0;
		TimestampTz cur_ts;

		CHECK_FOR_INTERRUPTS();

		ok = pgstat_read_db_statsfile_timestamp(inquiry_db, false, &file_ts);		/* 文件时间戳 file_ts */

		cur_ts = GetCurrentTimestamp();			/* 当前系统时间戳 cur_ts */
		/* 计算最小的可接受的时间戳,即 cutoff timestamp */
		if (count == 0 || cur_ts < ref_ts)		/* 只会在第一次 Loop 中计算 cutoff ts,除非 cur_ts 倒退 */
		{
			/*
			 * cutoff ts 设为 PGSTAT_STAT_INTERVAL before now msec,确保 collector 不需要比 PGSTAT_STAT_INTERVAL 更频繁地写 stats file;
			 * 但在 autovacuum worker 中,我们希望较低的延迟以避免使用过时的数据,因此 cutoff ts 使用 PGSTAT_RETRY_DELAY(因为 worker 数量很少,这应该不是问题)
			 */
			ref_ts = cur_ts;
			if (IsAutoVacuumWorkerProcess())
				min_ts = TimestampTzPlusMilliseconds(ref_ts,
													 -PGSTAT_RETRY_DELAY);
			else
				min_ts = TimestampTzPlusMilliseconds(ref_ts,
													 -PGSTAT_STAT_INTERVAL);		/* #define PGSTAT_STAT_INTERVAL 500 */
		}

		/*
		 * 如果 file_ts 上比 cur_ts 更新,出现了时钟故障(系统时间倒退),或者当前 backend 进程和 stats collector 进程之间存在时钟偏差。
		 * 接受文件,但还是发送查询消息,pgstat_recv_inquiry 对 collector 的时间进行检查。
		 */
		if (ok && file_ts > cur_ts)
		{
			/*
			 * 进程之间的少量时钟偏差可接受,但很大的差异需要记录(1000 ms) 
			 */
			if (file_ts >= TimestampTzPlusMilliseconds(cur_ts, 1000))
			{
				char	   *filetime;
				char	   *mytime;

				/* Copy because timestamptz_to_str returns a static buffer */
				filetime = pstrdup(timestamptz_to_str(file_ts));
				mytime = pstrdup(timestamptz_to_str(cur_ts));
				ereport(LOG,
						(errmsg("statistics collector's time %s is later than backend local time %s",
								filetime, mytime)));
				pfree(filetime);
				pfree(mytime);
			}

			pgstat_send_inquiry(cur_ts, min_ts, inquiry_db);
			break;
		}

		/* Normal case : file_ts >= cutoff ts */
		if (ok && file_ts >= min_ts)
			break;

		/* stats file 没有被接受,文件太旧,通知 collector 并等待 */
		if ((count % PGSTAT_INQ_LOOP_COUNT) == 0)			/* #define PGSTAT_INQ_LOOP_COUNT 64 */
			pgstat_send_inquiry(cur_ts, min_ts, inquiry_db);

        /* wait 10 ms */
		pg_usleep(PGSTAT_RETRY_DELAY * 1000L);		/* #define PGSTAT_RETRY_DELAY 10 */
	}

	if (count >= PGSTAT_POLL_LOOP_COUNT)		/* 走完 Loop,输出一条错误日志 */
		ereport(LOG,
				(errmsg("using stale statistics instead of current ones "
						"because stats collector is not responding")));

	/*
	 读取 stats file
	 */
	if (IsAutoVacuumLauncherProcess())
		pgStatDBHash = pgstat_read_statsfiles(InvalidOid, false, false);
	else
		pgStatDBHash = pgstat_read_statsfiles(MyDatabaseId, false, true);
}


/*
 *	读取现有的 stats file,并返回 database HTAB。如果 onlydb 不是 InvalidOid,则表示只需要该数据库的数据以及共享目录(“DB 0”)。 仍然会为所有数据库填充数据库哈希表,但不会为其他数据库创建 tables 和 functions 两张 HTAB;
 *	permanent 指定从永久文件而不是临时文件中读取。如果为 true(仅在收集器启动时发生),则在读取后删除文件;内存中状态现在为权威,如果其他人读取文件,这些文件将过期
 *	如果 deep == true,深度读取,则读取表/函数统计信息,否则 tables 和 functions HTAB 将保持为 NULL
 */
static HTAB* pgstat_read_statsfiles(Oid onlydb, bool permanent, bool deep) 
{
    /* 读取文件,填充 HTAB */
    ....;
}

注意到其中有一行pg_usleep(),如果走到这里肯定会导致函数执行时间变长。

函数中会设置一个可以接受的最旧的统计信息的时间戳min_ts,由第一次 loop 时的系统时间ref_ts和参数PGSTAT_STAT_INTERVAL决定:

min_ts = TimestampTzPlusMilliseconds(ref_ts, -PGSTAT_STAT_INTERVAL);		/* define 500 */

正常情况下,如果每一次 loop 时读取的统计信息文件时间戳file_ts满足要求,即file_ts >= min_ts,则直接跳出 loop,将统计信息文件读入哈希表并返回。

但如果文件时间戳不满足要求,即file_ts < min_ts,则会走到pg_usleep()函数,睡眠之前还会尝试给stats collector进程发送请求,通知其刷新文件。

if ((count % PGSTAT_INQ_LOOP_COUNT) == 0)
pgstat_send_inquiry(cur_ts, min_ts, inquiry_db);

睡眠时间由PGSTAT_RETRY_DELAY参数控制(默认10ms):

pg_usleep(PGSTAT_RETRY_DELAY * 1000L);		/* define 10 */

但在本地实际测试,执行SELECT * FROM pg_stat_database时总会走到pg_usleep()这里,但下一次Loop就正常跳出,只sleep一次,sleep的参数与本地测试EXPLAIN ANALYZE得出的执行时间吻合。

文件时间 file_ts

截止时间 min_ts 和第一次 loop 时的系统时间 cur_ts

第一次执行backend_read_statsfile()后,哈希表pgStatDBHash字段已经被填充,不会再走这个读文件并检查时间戳的逻辑,直接return。

但是在pg_usleep()函数中只会睡10ms,即使stats collector进程没有立刻收到通知并刷新统计信息文件,也不会长达10s之久,除非一直循环。

 

 

问题验证

在客户环境执行如下SQL:

EXPLAIN ANALYZE SELECT pg_stat_get_db_xact_commit(d.oid) AS xact_commit FROM pg_database d;

gdb调试:

查看collector进程:

collector进程通信过程:

static void
backend_read_statsfile() 
{
    ....;
    pgstat_send_inquiry(cur_ts, min_ts, inquiry_db);	/* 向 collector 进程发送消息 */	
    ....;
}

static void
pgstat_send_inquiry(TimestampTz clock_time, TimestampTz cutoff_time, Oid databaseid) 
{
    /* 组织并发送 msg */
    ....;
    pgstat_send(&msg, sizeof(msg));
}

static void
pgstat_send(void* msg, int len)
{
    ....;
    do 
    {
        rc = send(pgStatSock, msg, len, 0);		/* static pgsocket pgStatSock,使用套接字通信 */
    } while (rc < 0 && errno == EINTR);
}

void pgstat_init(void)
{
    ....;
    if ((pgStatSock = socket(addr->ai_family, SOCK_DGRAM, 0)) == PGINVALID_SOCKET) 	/* UDP socket */
    {
        ....;
    }
    ....;
}

backendstats collector进程间通信方式使用 UDP 套接字。

查看系统的UDP套接字信息:

查看网络设置:

stats collector进程的套接字创建在IPv6地址上,而localhost设置中禁用了IPv6,导致其他进程无法与stats collector正常通信。

 

问题复现

在本地环境,修改网络配置,在localhost上禁用IPv6:

sudo vi /etc/sysctl.conf

##### 修改配置
net.ipv6.conf.lo.disable_ipv6 = 1

##### 配置生效
sudo sysctl -p

此时查看网卡信息:

正常启动pg数据库并查看系统中udp套接字的连接情况:

netstat -u -n -p

此时pg的stats collector进程并没有使用IPv6地址。

只有在/etc/sysctl.conf文件中设置net.ipv6.conf.lo.disable_ipv6 = 0,在localhost上启用IPv6并生效后,此时再启动pg数据库,其stats collector进程才会在IPv6地址上创建UDP套接字:

然后此时再修改网络设置,再次修改参数net.ipv6.conf.lo.disable_ipv6 = 1,禁用IPv6并应用,此时stats collector进程仍然在使用IPv6的套接字,而localhost上已经禁用IPv6,此时执行SQL语句查询pg_stat_*系统视图,场景复现:

 

解决方案

1.系统启用ipv6:按问题复现中的操作修改网络设置。

2.禁止pg监听ipv6:修改postgresql.conf和/etc/hosts文件,删除ipv6相关条目。

3.使用pg15之后的版本:pg15之后取消了stats collector进程,使用共享内存存储统计信息

 

0条评论
0 / 1000
benzecat
5文章数
0粉丝数
benzecat
5 文章 | 0 粉丝
原创

记一次网络配置导致的慢查询排查过程

2023-10-27 07:02:07
19
0

背景

客户线上环境反馈两条慢SQL语句,执行时间都在10s以上。两条SQL都只是简单扫视图,并不涉及复杂的JOIN操作,虽然SQL1有聚合函数,但由于视图pg_stat_database并不大,其开销也不会很大。

两条SQL语句如下所示(语句中的常量信息用$代替):

SQL1:

SQL2:

 

初步分析

这两条慢SQL在一开始非常令人困惑。但按照慢SQL排查的常规流程,首先还是查看SQL语句的执行计划。通过加上EXPLAIN ANALYZE关键字查看其执行信息,这里以SQL1为例:

两个子查询耗时很短,主查询中SeqScan on pg_database耗时也很短,主要耗时全在最外层的Aggregate算子上。Aggregate算子主要是对SELECT coalesce(sum(xx)) FROM pg_stat_database d 系统视图中的数据做聚合操作,初步怀疑和系统视图pg_stat_database有关。

pg_stat_database是系统视图而不是系统表,查询时底层涉及到建立视图的操作,并不是直接SeqScan on pg_stat_database。在本地环境测试也发现,直接查询系统表如pg_database时间会快很多。

通过\d+ pg_stat_database命令查看系统视图定义如下:

在客户环境执行该VIEW DIFINITION(相当于SELECT * FROM pg_stat_database):

从执行计划可以看出,创建这个系统视图的操作就花费10秒钟,而客户整个SQL语句的用时基本都花在这上面。

而这个建视图语句执行计划并不复杂,SeqScan on pg_database获取oid字段,然后调用各种系统函数如pg_stat_get_db_xact_commit(oid)来生成系统视图中的字段。

pg_database表本身并不大(rows=4),耗时不可能在SeqScan on pg_database上,只可能在这些系统函数调用上。

 

深入分析

单独测试VIEW DIFINITION中的每个函数,每个函数都会导致慢SQL。

这里以pg_stat_get_db_xact_commit()函数为例:

这里继续看pg_stat_fetch_stat_dbentry()函数:

可以看到这里调用了backend_read_statsfile()函数(上面的系统视图定义中调用的所有系统函数最后其实都调用到该函数):

/*
 * 如果未完成,将 stats collector 的统计信息文件读入哈希表。 
 * 结果将一直保留到 pgstat_clear_snapshot() 被调用(通常在事务结束时)。
 */
static void
backend_read_statsfile(void)
{
	TimestampTz min_ts = 0;
	TimestampTz ref_ts = 0;
	Oid			inquiry_db;
	int			count;

	/* already read it? */
	if (pgStatDBHash)
		return;
	Assert(!pgStatRunningInCollector);

	/*
	 * 在 normal backend 中,检查自己的数据库的数据是否过时,因此在查询消息中发送 MyDatabaseId。 
	 * 在 autovac launcher 中,检查共享目录数据的过时性,并在查询消息中发送 InvalidOid。
	 */
	if (IsAutoVacuumLauncherProcess())
		inquiry_db = InvalidOid;
	else
		inquiry_db = MyDatabaseId;

	/*
	 * Loop,直到 stats file 足够新,或者 ran out of time。
	 * 统计信息查询消息会重复发送,以防 collector 将其丢弃,但不是每次,防止干扰 collector。
	 */
	for (count = 0; count < PGSTAT_POLL_LOOP_COUNT; count++)		/* #define PGSTAT_POLL_LOOP_COUNT 1000 */
	{
		bool		ok;
		TimestampTz file_ts = 0;
		TimestampTz cur_ts;

		CHECK_FOR_INTERRUPTS();

		ok = pgstat_read_db_statsfile_timestamp(inquiry_db, false, &file_ts);		/* 文件时间戳 file_ts */

		cur_ts = GetCurrentTimestamp();			/* 当前系统时间戳 cur_ts */
		/* 计算最小的可接受的时间戳,即 cutoff timestamp */
		if (count == 0 || cur_ts < ref_ts)		/* 只会在第一次 Loop 中计算 cutoff ts,除非 cur_ts 倒退 */
		{
			/*
			 * cutoff ts 设为 PGSTAT_STAT_INTERVAL before now msec,确保 collector 不需要比 PGSTAT_STAT_INTERVAL 更频繁地写 stats file;
			 * 但在 autovacuum worker 中,我们希望较低的延迟以避免使用过时的数据,因此 cutoff ts 使用 PGSTAT_RETRY_DELAY(因为 worker 数量很少,这应该不是问题)
			 */
			ref_ts = cur_ts;
			if (IsAutoVacuumWorkerProcess())
				min_ts = TimestampTzPlusMilliseconds(ref_ts,
													 -PGSTAT_RETRY_DELAY);
			else
				min_ts = TimestampTzPlusMilliseconds(ref_ts,
													 -PGSTAT_STAT_INTERVAL);		/* #define PGSTAT_STAT_INTERVAL 500 */
		}

		/*
		 * 如果 file_ts 上比 cur_ts 更新,出现了时钟故障(系统时间倒退),或者当前 backend 进程和 stats collector 进程之间存在时钟偏差。
		 * 接受文件,但还是发送查询消息,pgstat_recv_inquiry 对 collector 的时间进行检查。
		 */
		if (ok && file_ts > cur_ts)
		{
			/*
			 * 进程之间的少量时钟偏差可接受,但很大的差异需要记录(1000 ms) 
			 */
			if (file_ts >= TimestampTzPlusMilliseconds(cur_ts, 1000))
			{
				char	   *filetime;
				char	   *mytime;

				/* Copy because timestamptz_to_str returns a static buffer */
				filetime = pstrdup(timestamptz_to_str(file_ts));
				mytime = pstrdup(timestamptz_to_str(cur_ts));
				ereport(LOG,
						(errmsg("statistics collector's time %s is later than backend local time %s",
								filetime, mytime)));
				pfree(filetime);
				pfree(mytime);
			}

			pgstat_send_inquiry(cur_ts, min_ts, inquiry_db);
			break;
		}

		/* Normal case : file_ts >= cutoff ts */
		if (ok && file_ts >= min_ts)
			break;

		/* stats file 没有被接受,文件太旧,通知 collector 并等待 */
		if ((count % PGSTAT_INQ_LOOP_COUNT) == 0)			/* #define PGSTAT_INQ_LOOP_COUNT 64 */
			pgstat_send_inquiry(cur_ts, min_ts, inquiry_db);

        /* wait 10 ms */
		pg_usleep(PGSTAT_RETRY_DELAY * 1000L);		/* #define PGSTAT_RETRY_DELAY 10 */
	}

	if (count >= PGSTAT_POLL_LOOP_COUNT)		/* 走完 Loop,输出一条错误日志 */
		ereport(LOG,
				(errmsg("using stale statistics instead of current ones "
						"because stats collector is not responding")));

	/*
	 读取 stats file
	 */
	if (IsAutoVacuumLauncherProcess())
		pgStatDBHash = pgstat_read_statsfiles(InvalidOid, false, false);
	else
		pgStatDBHash = pgstat_read_statsfiles(MyDatabaseId, false, true);
}


/*
 *	读取现有的 stats file,并返回 database HTAB。如果 onlydb 不是 InvalidOid,则表示只需要该数据库的数据以及共享目录(“DB 0”)。 仍然会为所有数据库填充数据库哈希表,但不会为其他数据库创建 tables 和 functions 两张 HTAB;
 *	permanent 指定从永久文件而不是临时文件中读取。如果为 true(仅在收集器启动时发生),则在读取后删除文件;内存中状态现在为权威,如果其他人读取文件,这些文件将过期
 *	如果 deep == true,深度读取,则读取表/函数统计信息,否则 tables 和 functions HTAB 将保持为 NULL
 */
static HTAB* pgstat_read_statsfiles(Oid onlydb, bool permanent, bool deep) 
{
    /* 读取文件,填充 HTAB */
    ....;
}

注意到其中有一行pg_usleep(),如果走到这里肯定会导致函数执行时间变长。

函数中会设置一个可以接受的最旧的统计信息的时间戳min_ts,由第一次 loop 时的系统时间ref_ts和参数PGSTAT_STAT_INTERVAL决定:

min_ts = TimestampTzPlusMilliseconds(ref_ts, -PGSTAT_STAT_INTERVAL);		/* define 500 */

正常情况下,如果每一次 loop 时读取的统计信息文件时间戳file_ts满足要求,即file_ts >= min_ts,则直接跳出 loop,将统计信息文件读入哈希表并返回。

但如果文件时间戳不满足要求,即file_ts < min_ts,则会走到pg_usleep()函数,睡眠之前还会尝试给stats collector进程发送请求,通知其刷新文件。

if ((count % PGSTAT_INQ_LOOP_COUNT) == 0)
pgstat_send_inquiry(cur_ts, min_ts, inquiry_db);

睡眠时间由PGSTAT_RETRY_DELAY参数控制(默认10ms):

pg_usleep(PGSTAT_RETRY_DELAY * 1000L);		/* define 10 */

但在本地实际测试,执行SELECT * FROM pg_stat_database时总会走到pg_usleep()这里,但下一次Loop就正常跳出,只sleep一次,sleep的参数与本地测试EXPLAIN ANALYZE得出的执行时间吻合。

文件时间 file_ts

截止时间 min_ts 和第一次 loop 时的系统时间 cur_ts

第一次执行backend_read_statsfile()后,哈希表pgStatDBHash字段已经被填充,不会再走这个读文件并检查时间戳的逻辑,直接return。

但是在pg_usleep()函数中只会睡10ms,即使stats collector进程没有立刻收到通知并刷新统计信息文件,也不会长达10s之久,除非一直循环。

 

 

问题验证

在客户环境执行如下SQL:

EXPLAIN ANALYZE SELECT pg_stat_get_db_xact_commit(d.oid) AS xact_commit FROM pg_database d;

gdb调试:

查看collector进程:

collector进程通信过程:

static void
backend_read_statsfile() 
{
    ....;
    pgstat_send_inquiry(cur_ts, min_ts, inquiry_db);	/* 向 collector 进程发送消息 */	
    ....;
}

static void
pgstat_send_inquiry(TimestampTz clock_time, TimestampTz cutoff_time, Oid databaseid) 
{
    /* 组织并发送 msg */
    ....;
    pgstat_send(&msg, sizeof(msg));
}

static void
pgstat_send(void* msg, int len)
{
    ....;
    do 
    {
        rc = send(pgStatSock, msg, len, 0);		/* static pgsocket pgStatSock,使用套接字通信 */
    } while (rc < 0 && errno == EINTR);
}

void pgstat_init(void)
{
    ....;
    if ((pgStatSock = socket(addr->ai_family, SOCK_DGRAM, 0)) == PGINVALID_SOCKET) 	/* UDP socket */
    {
        ....;
    }
    ....;
}

backendstats collector进程间通信方式使用 UDP 套接字。

查看系统的UDP套接字信息:

查看网络设置:

stats collector进程的套接字创建在IPv6地址上,而localhost设置中禁用了IPv6,导致其他进程无法与stats collector正常通信。

 

问题复现

在本地环境,修改网络配置,在localhost上禁用IPv6:

sudo vi /etc/sysctl.conf

##### 修改配置
net.ipv6.conf.lo.disable_ipv6 = 1

##### 配置生效
sudo sysctl -p

此时查看网卡信息:

正常启动pg数据库并查看系统中udp套接字的连接情况:

netstat -u -n -p

此时pg的stats collector进程并没有使用IPv6地址。

只有在/etc/sysctl.conf文件中设置net.ipv6.conf.lo.disable_ipv6 = 0,在localhost上启用IPv6并生效后,此时再启动pg数据库,其stats collector进程才会在IPv6地址上创建UDP套接字:

然后此时再修改网络设置,再次修改参数net.ipv6.conf.lo.disable_ipv6 = 1,禁用IPv6并应用,此时stats collector进程仍然在使用IPv6的套接字,而localhost上已经禁用IPv6,此时执行SQL语句查询pg_stat_*系统视图,场景复现:

 

解决方案

1.系统启用ipv6:按问题复现中的操作修改网络设置。

2.禁止pg监听ipv6:修改postgresql.conf和/etc/hosts文件,删除ipv6相关条目。

3.使用pg15之后的版本:pg15之后取消了stats collector进程,使用共享内存存储统计信息

 

文章来自个人专栏
PostgreSQL
5 文章 | 1 订阅
0条评论
0 / 1000
请输入你的评论
1
0