MySQL查询随机延迟

41

我有一个查询看起来是这样的:

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。

我知道或者知道不会引起问题的事情:

  1. 查询不慢。当我查看相同的查询,从相同的查询运行中,在PHP中进行配置文件和使用SET PROFILING进行配置文件时,查询始终很快,并且即使从PHP端显示需要0.2秒,也从未在慢查询日志中记录。
  2. 这与skip-name-resolve无关-这是不一致的,而且我已经打开了skip-name-resolve
  3. 这与查询缓存无关,行为存在于两者中
  4. 即使是来自缓存的查询也会出现此行为。
  5. 查询实际上并没有选择ID,但我使用此查询进行测试以显示它不是磁盘访问问题,因为该字段肯定已索引。
  6. 这些表只有10-20兆字节,索引大约为1兆字节。机器显示非常少的负载,innodb没有使用其所有缓冲区。
  7. 这是针对一个除了我的测试查询之外没有其他活动的表进行测试的。

有人有什么其他检查的想法吗?对我来说,这似乎是一个网络问题,但我需要能够看到它并找到问题以修复它,而我已经没有地方可以检查了。有任何想法吗?


5
是否有可能其他进程正在获取这些表的读锁? - Mike
3
在整数上使用单引号是完全可接受的,MYSQL可以很好地解释它。 - GL_Stephen
9
Brian,这对我非常重要,因为在处理MySQL的15年中,我从未见过如此不稳定的查询行为,而你所引用的50次加载中只有1次是我上面说的情况。这不总是这个比率。我知道你没有全部上下文,但我们每月向数百万个唯一用户提供数百万个页面。这些性能比率变得非常重要。我来这里并不是问这是否是一个问题,而是问是否有人已经找到了我已经确定的问题的解决方案。 - GL_Stephen
5
这个问题的提问方式很好,值得点赞。很少见到有人按照规则来提问。请在两天后提醒我,我会给这个问题设置悬赏。否则,它将永远不会引起任何关注。 - Your Common Sense
2
你可以通过使用另一个API,例如旧版的MySQL,运行相同的查询来验证网络问题。 - Your Common Sense
显示剩余19条评论
7个回答

11

我会对机器进行性能分析。

你说这种情况大约发生了一次,每个查询的基准时间为0.2秒。 你应该能够在屏幕上使用 top 命令,并在 PHP 中运行查询循环来进行负载测试并收集性能统计信息。

由于你的“50个查询中的1个”统计数据可能是根据手动运行单个查询得出的,所以你可能需要运行超过 50 * 0.2 =10 秒。尝试进行30秒和90秒的负载测试。

在此期间,观察你的 top 进程屏幕。按 P 键按 CPU 进行排序。每次按下“P”键都会更改进程 CPU 消耗的排序顺序,因此请确保消耗最多的在顶部。(按下 M 键按内存使用率进行排序。请查看man页面了解更多信息)

在负载测试期间观察是否有任何东西冒泡到顶部。你应该会看到某些东西跳得更高——即使瞬间。
(注意,这样的进程可能不会成为列表的顶部,但仍可能引入足够的磁盘负载或其他活动来使 MySQL 服务器滞后)


7
我注意到在我的系统上出现了相同的现象。原本只需要一毫秒就能完成的查询突然要花费1-2秒的时间。所有这些情况都是简单的、单表的INSERT/UPDATE/REPLACE语句,而不是SELECT语句。没有负载、锁定或线程积累的迹象。
我曾怀疑这是由于清除脏页、将更改刷新到磁盘或某些隐藏的互斥体所致,但我还没有缩小范围。
也排除了以下可能性:
  1. 服务器负载 -- 没有高相关性

  2. 引擎 -- 在InnoDB/MyISAM/Memory MySQL Query中都会发生

  3. 缓存 -- 无论是开着还是关着都会发生

  4. 日志轮换 -- 事件中没有相关性


你好,你找到问题的原因了吗?我在一家英国托管公司的CentOS虚拟服务器上遇到了类似的问题。我只是运行着一个只有INNODB表格的数据库,执行简单的查询,大多数情况下一组12个查询总共只需要15毫秒来完成,但有时它们会每个要花费300毫秒甚至1个查询可能要花费1000毫秒。服务器内存很充足,启用了缓存,并且线程池也正常。唯一我考虑的是虚拟化做得不好或者硬件可能存在故障。 - NVG

6
很高兴您已经在使用查询分析器了。如果您正在使用MySQL 5.6,您还可以访问PERFORMANCE_SCHEMA中的许多新性能测量值。这个工具可以比查询分析器测量更多的细节,而且它也是全局性能测量而不仅是一次会话测量。据说P_S将替换查询分析器。
为了诊断您的问题,我建议首先确认或排除TCP/IP问题。例如,测试PHP脚本是否在通过UNIX套接字连接时遇到同样的间歇性延迟。您可以通过连接到localhost来实现这一点,这意味着PHP脚本必须在与数据库相同的服务器上运行。如果当您绕过TCP/IP时问题消失,这将告诉您根本原因很可能是TCP/IP。
如果您在像云托管这样的虚拟环境中,由于同一云中的其他用户不时地占用所有带宽,您很容易感受到性能变化。这是云的缺点之一。
如果您怀疑这是一个TCP/IP问题,您可以独立于PHP或MySQL测试TCP/IP延迟。可用的典型工具包括pingtraceroute。但是还有许多其他工具。您也可以使用netcat测试网络速度。使用一个可以重复测量的工具,因为看起来像您大部分时间性能良好,只是偶尔会出现故障。
另一种可能性是故障在于PHP。您可以尝试使用XHProf 对 PHP 进行分析以找出它花费时间的位置。

4

尝试分离问题。运行如下的小脚本:

https://drive.google.com/file/d/0B0P3JM22IdYZYXY3Y0h5QUg2WUk/edit?usp=sharing

我建议您运行以下命令,以便查看链中哪些步骤正在出现峰值。如果您已经安装了ssh2,它还将在最长运行的测试循环后立即返回ps axu以查看正在运行的内容。

在我的家庭开发框中针对本地主机运行,结果如下:

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结果毫无用处,因为我是连接到本地主机的。但是,我可以从这些结果中看出数据库连接延迟偶尔会出现波动,以及“网络”延迟(一些TCP/IP缓冲区?)。
如果我是你,我会将测试循环次数增加到5000或50000。

0
我们发现一个与底层硬件有关的问题导致了这个情况。我们使用 VMotion 将服务器迁移到新的硬件上,问题得到解决。VMWare 没有显示任何与硬件相关的警报或问题。尽管如此,将服务器从该硬件上移动解决了问题。非常奇怪。

0

我只能猜测,但既然您已经消除了服务器负载,并且我假设您在InnoDb-Stats中检查了红旗(phpmyadmin对此非常有帮助,尽管还有更专业的工具),那么剩下的就是键的不一致使用。可能您的查询略有不同,并且存在一种情况,使用次优索引

请添加FORCE INDEX PRIMARY或类似内容重复测试。


0

在诊断MySQL问题方面,我发现mysqltuner非常有用。它是一个PERL脚本,可以查看您的MySQL实例并建议各种调整改进。说实话,要跟踪所有可以进行的调整变得很困难,而这个脚本可以为您提供潜在瓶颈的详细信息,真的很棒。

还有一些需要考虑的是Linux本身的工作方式,这也可能解释为什么你会随机出现滞后。当你在Linux上加载top(任何负载的盒子),你会注意到你的内存几乎完全被使用了(除非你刚刚重启)。这不是你的盒子的问题或过载。Linux尽可能多地加载到RAM中以节省时间,并将不经常使用的东西交换到交换文件中,就像所有现代操作系统一样(称为虚拟RAM)。通常不是什么大问题,但你可能正在使用InnoDB作为表类型(当前默认值),它也会将东西加载到RAM中以节省时间。可能发生的情况是你的查询已经加载到RAM中(速度很快),但闲置了足够长的时间才被交换到交换文件中(速度慢得多)。因此,在Linux将其移回RAM时,你会遇到小的性能损失(swapfile比MySQL从磁盘中移动更有效率)。MySQL和InnoDB都没有办法告诉这一点,因为他们认为它仍然在RAM中。该问题在this blog中详细描述,相关部分如下:

通常来说,一点点的交换使用可能还可以(我们主要关心的是交换进出的活动),但在许多情况下,“真正”有用的内存被交换了:主要是InnoDB缓冲池的部分。当再次需要它时,将承受交换回来的巨大性能损失,在随机查询中引起随机延迟。这可能导致生产系统整体性能不可预测,并且通常一旦开始交换,系统可能会陷入性能死循环。

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接