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 延迟。现有的典型工具包括pingtraceroute。但是有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 查询随机滞后的主要内容,如果未能解决你的问题,请参考以下文章

mysql查询一随机?

mysql随机查询符合条件的几条记录

按随机和字段排序 MySQL 查询?

优化mysql随机查询

针对另一个表的随机 MySQL 查询验证

用另一个查询的随机值更新mysql表?