MySQL 查询随机滞后
Posted
技术标签:
【中文标题】MySQL 查询随机滞后【英文标题】:MySQL Query Randomly Lags 【发布时间】:2014-01-02 14:37:54 【问题描述】:我的查询如下所示:
SELECT id FROM user WHERE id='47'
使用分析数据时,此查询的 ID 已编入索引并且读取速度总是很快。
SET profiling = 1;
SHOW PROFILES;
查询总是在 0.0002 秒左右执行。
但是,如果我从 php 端分析查询,如下所示:
$current = microtime(true);
$data = $conn->query($full_query);
$elapsed = microtime(true) - $current;
然后偶尔可能有 50 个查询中的 1 个需要大约 0.2 秒。但是,在我的测试脚本中,我有代码来测试它,它使用 SET profiling = 1; 来分析查询。即使通过 PDO 的 PHP 往返行程可能是 0.2 秒,但查询时间仍然是 0.0002。
我知道或知道不会导致问题的事情:
-
查询并不慢。当我从同一个查询运行中查看相同的查询时,在 PHP 中进行分析并使用 SET PROFILING 进行分析时,查询总是很快并且从未记录在慢查询日志中,即使它显示从 PHP 端需要 0.2 秒。李>
这与 skip-name-resolve 无关 - 这是不一致的,我已经启用了 skip-name-resolve
这与查询缓存无关,这两种行为都存在
即使查询从缓存中出来,也会发生这种行为。
该查询实际上并未选择 ID,但我使用此查询进行测试以表明这不是磁盘访问问题,因为该字段肯定已编入索引。
这个表只有 10-20 兆,索引类似于 1 兆。机器显示的负载非常小,并且 innodb 没有使用它的所有缓冲区。
这是针对除我的测试查询之外没有其他活动的表进行测试的。
有人知道还有什么要检查的吗?在我看来,这似乎是一个网络问题,但我需要能够看到它并找到解决它的问题,而且我已经没有地方可以检查了。有什么想法吗?
【问题讨论】:
是否有可能另一个进程正在获取表上的读锁? 整数上的单引号是完全可以接受的,mysql 解释得很好。 Brian,这对我来说很重要,因为在处理 mySQL 的 15 年中,我从未见过如此不稳定的查询行为,并且您引用的 50 个负载中的 1 个只是我上面所说的。这并不总是这个比例。我知道您没有完整的背景信息,但我们每月为数百万个唯一用户提供数百万个页面。这些性能比变得很重要。我不是来这里问是否有问题,我是来问是否有人对我已经确定的问题有解决方案。 +1 仅针对此问题的提问方式。遵循规则提出的问题是如此罕见。请在 2 天后提醒我 - 我会悬赏这个问题。否则它永远不会受到关注。 你可以通过简单地使用另一个 api 运行相同的查询来验证网络问题,例如旧的 mysql。 【参考方案1】:我会分析机器。
您说这种情况每 50 次发生约 1 次,并且每个查询都有 0.2 秒的基准。您应该能够将 top 放在屏幕上,然后在 PHP 中运行循环查询以对 RDBMS 进行负载测试并收集性能统计信息。
您可能必须运行超过50 * 0.2 =
10 seconds
,因为您的“50 分之一”统计数据可能基于手动运行的单个查询 - 基于我读到的内容你的描述。尝试 30 秒和 90 秒的负载测试。
在此期间,请注意您的 top
进程屏幕。按P
按CPU 对其进行排序。每次您按“P”时,它都会更改进程 CPU 消耗的排序顺序,因此请确保您将最消耗的排在最前面。 (按M
按内存使用情况排序。查看the man page 了解更多信息)
在负载测试期间寻找任何浮出水面的东西。您应该会看到更高的东西跳动 - 但只是暂时的。(请注意,这样的过程可能不会到达列表的顶部 - 它不需要,但仍然可以引入足够的磁盘负载或其他滞后于 MySQL 服务器的活动)
【讨论】:
【参考方案2】:我在我的系统上发现了同样的现象。通常需要一毫秒的查询会突然需要 1-2 秒。我的所有案例都是简单的单表 INSERT/UPDATE/REPLACE 语句 --- 不在任何 SELECT 上。没有明显的负载、锁定或螺纹堆积。
我曾怀疑这是由于清除脏页、刷新磁盘更改或某些隐藏的互斥锁造成的,但我还没有缩小范围。
也排除了
服务器负载——与高无关
加载引擎——发生在 InnoDB/MyISAM/Memory MySQL 查询中
缓存——无论是打开还是关闭都会发生
日志轮换 -- 事件中没有相关性
【讨论】:
您好,您找到问题的原因了吗?我在一家英国托管公司的 CentOS 虚拟服务器上遇到了类似的问题。我只是运行一个只有 INNODB 表的数据库,使用简单的查询,大多数时候一组 12 个查询总共需要 15 毫秒来执行,但有时它们需要 300 毫秒,甚至 1 个查询可能需要 1000 毫秒。有很多 RAM ,启用缓存,线程池正常。 MySQL 服务器和 PHP 服务在同一台服务器上。我唯一想到的是虚拟化做得不好或者硬件可能有故障。【参考方案3】:您已经在使用查询分析器了。如果您使用的是 MySQL 5.6,您还可以访问 PERFORMANCE_SCHEMA 中的许多新性能测量。与查询分析器相比,它具有测量更多细节的能力,并且它还可以全局测量,而不仅仅是一个会话。据报道,P_S 将取代查询分析器。
要诊断您的问题,我会先确认或排除 TCP/IP 问题。例如,测试 PHP 脚本以查看它在通过 UNIX 套接字连接时是否获得相同的间歇性延迟。您可以通过连接到localhost
来执行此操作,这意味着 PHP 脚本必须在与数据库相同的服务器上运行。如果绕过 TCP/IP 后问题消失,这将告诉您根本原因很可能是 TCP/IP。
如果您处于云托管之类的虚拟环境中,您很容易会遇到性能变化,因为同一云的其他用户会间歇性地耗尽所有带宽。这是云的缺点之一。
如果您怀疑这是 TCP/IP 问题,您可以独立于 PHP 或 MySQL 测试 TCP/IP 延迟。现有的典型工具包括ping
或traceroute
。但是有many others。你也可以test network speed with netcat。使用可以随时间重复测量的工具,因为听起来您大部分时间都表现良好,偶尔会出现故障。
另一种可能是问题出在 PHP 上。您可以尝试使用 XHProf 分析 PHP 以了解它在哪里花费时间。
【讨论】:
【参考方案4】:尝试隔离问题。像这样运行一个小脚本:
https://drive.google.com/file/d/0B0P3JM22IdYZYXY3Y0h5QUg2WUk/edit?usp=sharing
...查看链条中的哪些步骤正在飙升。如果您安装了ssh2,它还会在运行时间最长的测试循环之后立即返回ps axu
,以查看正在运行的内容。
在我家开发盒子上运行localhost,结果如下:
Array
(
[tests summary] => Array
(
[host_ping] => Array
(
[total_time] => 0.010216474533081
[max_time] => 0.00014901161193848
[min_time] => 9.7036361694336E-5
[tests] => 100
[failed] => 0
[last_run] => 9.8943710327148E-5
[average] => 0.00010216474533081
)
[db_connect] => Array
(
[total_time] => 0.11583232879639
[max_time] => 0.0075201988220215
[min_time] => 0.0010058879852295
[tests] => 100
[failed] => 0
[last_run] => 0.0010249614715576
[average] => 0.0011583232879639
)
[db_select_db] => Array
(
[total_time] => 0.011744260787964
[max_time] => 0.00031399726867676
[min_time] => 0.00010991096496582
[tests] => 100
[failed] => 0
[last_run] => 0.0001530647277832
[average] => 0.00011744260787964
)
[db_dataless_query] => Array
(
[total_time] => 0.023221254348755
[max_time] => 0.00026106834411621
[min_time] => 0.00021100044250488
[tests] => 100
[failed] => 0
[last_run] => 0.00021481513977051
[average] => 0.00023221254348755
)
[db_data_query] => Array
(
[total_time] => 0.075078248977661
[max_time] => 0.0010559558868408
[min_time] => 0.00023698806762695
[tests] => 100
[failed] => 0
[last_run] => 0.00076413154602051
[average] => 0.00075078248977661
)
)
[worst full loop] => 0.039211988449097
[times at worst loop] => Array
(
[host_ping] => 0.00014400482177734
[db_connect] => 0.0075201988220215
[db_select_db] => 0.00012803077697754
[db_dataless_query] => 0.00023698806762695
[db_data_query] => 0.00023698806762695
)
[ps_at_worst] => USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1 0.0 0.0 2884 1368 ? Ss Sep19 0:29 /sbin/init
root 2 0.0 0.0 0 0 ? S Sep19 0:00 [kthreadd]
root 3 0.0 0.0 0 0 ? S Sep19 0:00 [migration/0]
root 4 0.0 0.0 0 0 ? S Sep19 0:06 [ksoftirqd/0]
root 5 0.0 0.0 0 0 ? S Sep19 0:00 [migration/0]
root 6 0.0 0.0 0 0 ? S Sep19 0:25 [watchdog/0]
root 7 0.0 0.0 0 0 ? S Sep19 7:42 [events/0]
root 8 0.0 0.0 0 0 ? S Sep19 0:00 [cgroup]
root 9 0.0 0.0 0 0 ? S Sep19 0:00 [khelper]
root 10 0.0 0.0 0 0 ? S Sep19 0:00 [netns]
root 11 0.0 0.0 0 0 ? S Sep19 0:00 [async/mgr]
root 12 0.0 0.0 0 0 ? S Sep19 0:00 [pm]
root 13 0.0 0.0 0 0 ? S Sep19 0:23 [sync_supers]
root 14 0.0 0.0 0 0 ? S Sep19 0:24 [bdi-default]
root 15 0.0 0.0 0 0 ? S Sep19 0:00 [kintegrityd/0]
root 16 0.0 0.0 0 0 ? S Sep19 0:47 [kblockd/0]
root 17 0.0 0.0 0 0 ? S Sep19 0:00 [kacpid]
root 18 0.0 0.0 0 0 ? S Sep19 0:00 [kacpi_notify]
root 19 0.0 0.0 0 0 ? S Sep19 0:00 [kacpi_hotplug]
root 20 0.0 0.0 0 0 ? S Sep19 0:00 [ata/0]
root 21 0.0 0.0 0 0 ? S Sep19 0:00 [ata_aux]
root 22 0.0 0.0 0 0 ? S Sep19 0:00 [ksuspend_usbd]
root 23 0.0 0.0 0 0 ? S Sep19 0:00 [khubd]
root 24 0.0 0.0 0 0 ? S Sep19 0:00 [kseriod]
root 25 0.0 0.0 0 0 ? S Sep19 0:00 [md/0]
root 26 0.0 0.0 0 0 ? S Sep19 0:00 [md_misc/0]
root 27 0.0 0.0 0 0 ? S Sep19 0:01 [khungtaskd]
root 28 0.0 0.0 0 0 ? S Sep19 0:00 [kswapd0]
root 29 0.0 0.0 0 0 ? SN Sep19 0:00 [ksmd]
root 30 0.0 0.0 0 0 ? S Sep19 0:00 [aio/0]
root 31 0.0 0.0 0 0 ? S Sep19 0:00 [crypto/0]
root 36 0.0 0.0 0 0 ? S Sep19 0:00 [kthrotld/0]
root 38 0.0 0.0 0 0 ? S Sep19 0:00 [kpsmoused]
root 39 0.0 0.0 0 0 ? S Sep19 0:00 [usbhid_resumer]
root 70 0.0 0.0 0 0 ? S Sep19 0:00 [iscsi_eh]
root 74 0.0 0.0 0 0 ? S Sep19 0:00 [cnic_wq]
root 75 0.0 0.0 0 0 ? S< Sep19 0:00 [bnx2i_thread/0]
root 87 0.0 0.0 0 0 ? S Sep19 0:00 [kstriped]
root 123 0.0 0.0 0 0 ? S Sep19 0:00 [ttm_swap]
root 130 0.0 0.0 0 0 ? S< Sep19 0:04 [kslowd000]
root 131 0.0 0.0 0 0 ? S< Sep19 0:05 [kslowd001]
root 231 0.0 0.0 0 0 ? S Sep19 0:00 [scsi_eh_0]
root 232 0.0 0.0 0 0 ? S Sep19 0:00 [scsi_eh_1]
root 291 0.0 0.0 0 0 ? S Sep19 0:35 [kdmflush]
root 293 0.0 0.0 0 0 ? S Sep19 0:00 [kdmflush]
root 313 0.0 0.0 0 0 ? S Sep19 2:11 [jbd2/dm-0-8]
root 314 0.0 0.0 0 0 ? S Sep19 0:00 [ext4-dio-unwrit]
root 396 0.0 0.0 2924 1124 ? S<s Sep19 0:00 /sbin/udevd -d
root 705 0.0 0.0 0 0 ? S Sep19 0:00 [kdmflush]
root 743 0.0 0.0 0 0 ? S Sep19 0:00 [jbd2/sda1-8]
root 744 0.0 0.0 0 0 ? S Sep19 0:00 [ext4-dio-unwrit]
root 745 0.0 0.0 0 0 ? S Sep19 0:00 [jbd2/dm-2-8]
root 746 0.0 0.0 0 0 ? S Sep19 0:00 [ext4-dio-unwrit]
root 819 0.0 0.0 0 0 ? S Sep19 0:18 [kauditd]
root 1028 0.0 0.0 3572 748 ? Ss Sep19 0:00 /sbin/dhclient -1 -q -lf /var/lib/dhclient/dhclient-eth0.leases -pf /var/run/dhclient-eth0.pid eth0
root 1072 0.0 0.0 13972 828 ? S<sl Sep19 2:13 auditd
root 1090 0.0 0.0 2052 512 ? Ss Sep19 0:00 /sbin/portreserve
root 1097 0.0 0.2 37568 3940 ? Sl Sep19 2:01 /sbin/rsyslogd -i /var/run/syslogd.pid -c 5
rpc 1120 0.0 0.0 2568 800 ? Ss Sep19 0:09 rpcbind
rpcuser 1138 0.0 0.0 2836 1224 ? Ss Sep19 0:00 rpc.statd
root 1161 0.0 0.0 0 0 ? S Sep19 0:00 [rpciod/0]
root 1165 0.0 0.0 2636 472 ? Ss Sep19 0:00 rpc.idmapd
root 1186 0.0 0.0 2940 756 ? Ss Sep19 13:27 lldpad -d
root 1195 0.0 0.0 0 0 ? S Sep19 0:00 [scsi_tgtd/0]
root 1196 0.0 0.0 0 0 ? S Sep19 0:00 [fc_exch_workque]
root 1197 0.0 0.0 0 0 ? S Sep19 0:00 [fc_rport_eq]
root 1199 0.0 0.0 0 0 ? S Sep19 0:00 [fcoe_work/0]
root 1200 0.0 0.0 0 0 ? S< Sep19 0:00 [fcoethread/0]
root 1201 0.0 0.0 0 0 ? S Sep19 0:00 [bnx2fc]
root 1202 0.0 0.0 0 0 ? S< Sep19 0:00 [bnx2fc_l2_threa]
root 1203 0.0 0.0 0 0 ? S< Sep19 0:00 [bnx2fc_thread/0]
root 1206 0.0 0.0 2184 564 ? Ss Sep19 1:08 /usr/sbin/fcoemon --syslog
root 1240 0.0 0.0 8556 976 ? Ss Sep19 1:22 /usr/sbin/sshd
root 1415 0.0 0.1 12376 2088 ? Ss Sep19 6:09 sendmail: accepting connections
smmsp 1424 0.0 0.0 12168 1680 ? Ss Sep19 0:02 sendmail: Queue runner@01:00:00 for /var/spool/clientmqueue
root 1441 0.0 0.0 5932 1260 ? Ss Sep19 0:56 crond
root 1456 0.0 0.0 2004 504 tty2 Ss+ Sep19 0:00 /sbin/mingetty /dev/tty2
root 1458 0.0 0.0 2004 504 tty3 Ss+ Sep19 0:00 /sbin/mingetty /dev/tty3
root 1460 0.0 0.0 2004 508 tty4 Ss+ Sep19 0:00 /sbin/mingetty /dev/tty4
root 1462 0.0 0.0 2004 504 tty5 Ss+ Sep19 0:00 /sbin/mingetty /dev/tty5
root 1464 0.0 0.0 2004 508 tty6 Ss+ Sep19 0:00 /sbin/mingetty /dev/tty6
root 1467 0.0 0.0 3316 1740 ? S< Sep19 0:00 /sbin/udevd -d
root 1468 0.0 0.0 3316 1740 ? S< Sep19 0:00 /sbin/udevd -d
apache 3796 0.0 0.4 32668 9452 ? S Dec16 0:08 /usr/sbin/httpd
apache 3800 0.0 0.4 32404 9444 ? S Dec16 0:08 /usr/sbin/httpd
apache 3801 0.0 0.4 33184 9556 ? S Dec16 0:07 /usr/sbin/httpd
apache 3821 0.0 0.4 32668 9612 ? S Dec16 0:08 /usr/sbin/httpd
apache 3840 0.0 0.4 32668 9612 ? S Dec16 0:07 /usr/sbin/httpd
apache 3841 0.0 0.4 32404 9464 ? S Dec16 0:07 /usr/sbin/httpd
apache 4032 0.0 0.4 32668 9632 ? S Dec16 0:07 /usr/sbin/httpd
apache 4348 0.0 0.4 32668 9460 ? S Dec16 0:07 /usr/sbin/httpd
apache 4355 0.0 0.4 32664 9464 ? S Dec16 0:07 /usr/sbin/httpd
apache 4356 0.0 0.5 32660 9728 ? S Dec16 0:07 /usr/sbin/httpd
apache 4422 0.0 0.4 32676 9460 ? S Dec16 0:06 /usr/sbin/httpd
root 5002 0.0 0.0 2004 504 tty1 Ss+ Nov21 0:00 /sbin/mingetty /dev/tty1
root 7540 0.0 0.0 5112 1380 ? S Dec17 0:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --socket=/var/lib/mysql/mysql.sock --pid-file=/var/run/mysqld/mysqld.pid --basedir=/usr --user=mysql
mysql 7642 0.1 1.0 136712 20140 ? Sl Dec17 2:35 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
root 8001 0.0 0.4 31028 9600 ? Ss Dec13 0:18 /usr/sbin/httpd
root 8092 0.0 0.0 0 0 ? S 13:47 0:00 [flush-253:2]
root 8511 0.0 0.0 0 0 ? S 13:48 0:00 [flush-8:0]
root 8551 16.0 0.4 28612 8008 pts/0 S+ 13:49 0:00 php test-mysql-connection.php exit
root 8552 44.0 0.1 11836 3252 ? Ss 13:49 0:00 sshd: root@notty
root 8560 0.0 0.0 4924 1032 ? Rs 13:49 0:00 ps axu
root 12520 0.0 0.1 11500 3212 ? Ss 09:05 0:00 sshd: jonwire [priv]
jonwire 12524 0.0 0.1 11832 1944 ? S 09:05 0:05 sshd: jonwire@pts/0
jonwire 12525 0.0 0.0 5248 1736 pts/0 Ss 09:05 0:00 -bash
root 16309 0.0 0.0 5432 1436 pts/0 S 12:01 0:00 su -
root 16313 0.0 0.0 5244 1732 pts/0 S 12:01 0:00 -bash
apache 16361 0.0 0.5 32908 9836 ? S Dec15 0:08 /usr/sbin/httpd
apache 16363 0.0 0.5 32908 9784 ? S Dec15 0:08 /usr/sbin/httpd
apache 16364 0.0 0.4 32660 9612 ? S Dec15 0:08 /usr/sbin/httpd
apache 16365 0.0 0.4 32668 9608 ? S Dec15 0:08 /usr/sbin/httpd
apache 16366 0.0 0.7 35076 13948 ? S Dec15 0:08 /usr/sbin/httpd
apache 16367 0.0 0.4 32248 9264 ? S Dec15 0:08 /usr/sbin/httpd
apache 16859 0.0 0.5 32916 9844 ? S Dec15 0:08 /usr/sbin/httpd
apache 20379 0.0 0.4 32248 8904 ? S Dec15 0:08 /usr/sbin/httpd
root 28368 0.0 0.0 0 0 ? S Nov01 0:21 [flush-253:0]
apache 31973 0.0 0.4 31668 8608 ? S Dec16 0:08 /usr/sbin/httpd
)
ps axu
这里的结果非常没用,因为我正在连接到 localhost。但是,我可以从这些结果中看到,数据库连接延迟偶尔会出现峰值,“网络”延迟(一些 TCP/IP 缓冲区?)也是如此。
如果我是你,我会将测试周期数增加到 5000 或 50000 个。
【讨论】:
【参考方案5】:我只能猜测,但是由于您消除了服务器负载,并且我假设您检查了 InnoDb-Stats 中的危险信号(phpmyadmin 对此有很大帮助,尽管有更专业的工具),剩下的是密钥的不一致使用。会不会是您的查询略有不同,并且存在使用次优索引的星座?
请添加FORCE INDEX PRIMARY
或类似的重复您的测试。
【讨论】:
【参考方案6】:mysqltuner 是我发现在诊断 MySQL 问题方面非常有用的东西。这是一个 PERL 脚本,它查看您的 MySQL 实例并建议各种调整改进。老实说,很难跟踪您可以执行的所有调整,而这个脚本非常棒,可以为您提供潜在阻塞点的细分。
另外需要考虑的是 Linux 本身是如何工作的,这也可以解释为什么你会随机滞后。当您在 Linux 机器上加载top
时(任何机器,无论负载如何),您会注意到您的内存几乎完全被使用(除非您刚刚重新启动)。这不是您的盒子的问题或超载。 Linux 尽可能多地加载到 RAM 中以节省时间并将不经常使用的东西交换到交换文件中,就像所有现代操作系统(称为虚拟 RAM)一样。通常没什么大不了的,但您可能使用InnoDB
作为表类型(当前默认值),它会将内容加载到 RAM 中以节省时间。可能发生的情况是您的查询已加载到 RAM 中(速度很快),但闲置的时间刚好足以换出到交换文件(慢得多)。因此,当 Linux 将其移回 RAM 时,您会受到很小的性能影响(交换文件在这方面比 MySQL 将其从磁盘中移出更有效)。 MySQL 和InnoDB
都没有办法说明这一点,因为就他们而言,它仍然在 RAM 中。该问题在this blog上有详细描述,相关部分为
通常少量的交换使用是可以的(我们真的很担心 关于活动——交换进出),但在许多情况下,“真正”有用 内存正在被交换:主要是 InnoDB 缓冲池的一部分。什么时候 再次需要它,需要很大的性能才能将其交换回来 in,导致随机查询的随机延迟。这可能导致整体 生产系统上不可预测的性能,并且通常是一次 交换开始,系统可能进入性能死亡螺旋。
【讨论】:
【参考方案7】:我们发现底层硬件的问题导致了这种情况。我们使用 VMotion 将服务器移至新硬件,问题就消失了。 VMWare 没有显示警报或硬件问题。尽管如此,离开硬件解决了这个问题。非常非常奇怪。
【讨论】:
以上是关于MySQL 查询随机滞后的主要内容,如果未能解决你的问题,请参考以下文章