MySQL查询随机滞后

我有一个查询,看起来像这样:

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秒。 然而,在我的testing脚本中,我有代码来testing这个configuration文件查询使用SET profiling = 1; 即使通过PDO的PHP往返时间可能是0.2秒,查询时间仍然是0.0002。

我知道的东西,或者知道不是造成这个问题:

  1. 查询不慢。 当我查看相同的查询时,从相同的查询运行,在PHP中进行概要分析并使用SET PROFILING进行概要分析,查询总是很快,并且从不login缓慢的查询日志,即使它显示从PHP端花费0.2秒。
  2. 这不是skip-name-resolve相关 – 这是不一致的,我已经跳过名称parsing
  3. 这不是查询caching相关的,行为存在于两者中
  4. 甚至在从caching中出来的查询时也会发生这种行为。
  5. 该查询实际上并不selectID,但我使用此查询进行testing,以显示它不是磁盘访问问题,因为该字段肯定是索引的。
  6. 这张桌子只有10-20兆像一个1兆指数。 机器显示非常小的负载,innodb没有使用所有的缓冲区。
  7. 除了我的testing查询之外,这是针对没有其他活动的表进行testing的。

有没有人有什么想检查什么? 这似乎是一个networking问题,但我需要能够看到它,并find问题来解决它,我没有地方检查下一步。 有任何想法吗?

我会分析机器。

你说这发生〜50次,每个查询有0.2秒的基准。 您应该能够在屏幕上放置顶部,然后在PHP中运行一个查询循环来加载testingRDBMS并收集性能统计信息。

您可能必须运行超过50 * 0.2 = 10 seconds ,因为您的“50分之一”统计信息可能基于手动运行的单个查询 – 基于我在您的描述中阅读的内容。 尝试30秒和90秒的负载testing。

在此期间,请注意您的topstream程屏幕。 按Psorting。 每次按“P”时,它都会改变进程CPU消耗的sorting顺序,因此请确保您的CPU处于最耗电状态。 (按内存使用情况按Msorting,查看手册页了解更多信息)

在负载testing的时间内寻找任何有泡沫的东西。 你应该看到东西跳得更高 – 不过是暂时的。
(注意,这样的过程可能不会达到列表的顶部 – 它不需要,但仍然可以引入足够的磁盘负载或其他活动来延迟MySQL服务器)

我注意到我的系统上有同样的现象。 通常需要几毫秒的查询会突然花费1-2秒。 我所有的情况都是简单的,单表INSERT / UPDATE / REPLACE语句—不在任何SELECT上。 没有负载,locking或线程累积是显而易见的。

我怀疑是因为清理脏页面,刷新磁盘或隐藏的互斥体,但我还没有把它缩小。

也排除

  1. 服务器负载 – 与高无关

  2. 加载引擎 – 与InnoDB / MyISAM /内存MySQL查询发生

  3. caching – 发生是否打开或closures

  4. 日志旋转 – 事件中没有关联

好,你已经使用查询分析器。 如果您使用的是MySQL 5.6,则还可以在PERFORMANCE_SCHEMA中访问许多新的性能度量。 这有能力比查询分析器测量更多的细节,它也测量全球而不是一个会话。 据说P_S将取代查询分析器。

为了诊断您的问题,我将首先确认或排除TCP / IP问题。 例如,testingPHP脚本以查看在通过UNIX套接字连接时是否获得相同的间歇延迟。 您可以通过连接到localhost来执行此操作,这意味着PHP脚本必须在与数据库相同的服务器上运行。 如果绕过TCP / IP时问题消失,则会告诉您根本原因很可能是TCP / IP。

如果您处于虚拟环境(如云托pipe),则由于同一云的其他用户间歇性地占用了所有带宽,您可以轻松体验到性能的差异。 这是云的一个缺点。

如果您怀疑是TCP / IP问题,则可以独立于PHP或MySQLtestingTCP / IP延迟。 可用的典型工具包括pingtraceroute 。 但还有很多其他的 。 您也可以使用netcattestingnetworking速度 。 使用一个可以随着时间反复测量的工具,因为它听起来像你大多数时候都有良好的performance,偶尔会有小故障。

另一种可能性是,错误在于PHP。 你可以尝试使用XHProf来分析PHP,找出它在哪里花费时间。

尝试隔离问题。 运行一下这样的脚本:

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

…看到链中的哪些步骤是尖峰的。 如果你安装了ssh2 ,它也会在最长的运行testing循环之后立即返回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的结果在这里是相当无用的,因为我连接到本地主机。 但是,从这些结果中我可以看出,DB连接延迟偶尔会出现峰值,“networking”延迟(某些TCP / IP缓冲区)也是如此。

如果我是你,我会把testing周期的次数提高到5000或50000。

我只能猜测 ,但既然你消除了服务器负载,我假设你在InnoDb-Stats(phpmyadmin是一个很好的帮助,虽然有更多的专业工具)红旗检查,仍然是不一致的用法键。 难道是你的查询稍有不同,而且有一个使用次优指数的星座?

请添加一个FORCE INDEX PRIMARY或者重复你的testing。

在这方面,我发现在诊断MySQL问题方面非常有用的是mysqltuner 。 这是一个PERL脚本,用于查看您的MySQL实例,并提出各种调整改进build议。 说实话,很难跟踪所有你可以做的调整,这个脚本对于给你一个潜在的阻塞点分解是很棒的。

还有一点要考虑的是Linux本身是如何工作的,这也可以解释为什么你会随机落后。 当你加载一个Linux的盒子(任何盒子,不pipe负载)的top ,你会发现你的内存几乎完全被使用(除非你刚刚重新启动)。 这不是一个问题或重载你的盒子。 Linux尽可能多地加载到RAM中,以节省时间,并将不常用的东西交换到交换文件,就像所有现代操作系统(称为虚拟RAM)一样。 通常不是什么大问题,但是您可能使用InnoDB作为表types(当前的默认值),它将内容加载到RAM中以节省时间。 可能发生的事情是你的查询被加载到RAM中(快速),但是闲置足够长时间以便交换到交换文件(慢得多)。 因此,当Linux将其移回到RAM中时,性能会受到很小的影响(交换文件比MySQL更有效)。 无论是MySQL还是InnoDB都没有办法告诉这个,因为就他们而言,它仍然在RAM中。 在这个博客上详细描述了这个问题,其中有相关部分

通常情况下,交换使用的一小部分是可以的(我们真的关心活动交​​换进出),但是在很多情况下,“真正的”有用内存正在被交换:主要是InnoDB缓冲池的一部分。 当再次需要时,会有一个很大的性能冲击,将其重新置换,导致随机查询的随机延迟。 这可能会导致生产系统的总体不可预测的性能,并且一旦开始交换,系统可能进入性能死亡螺旋。

我们发现底层硬件的一个问题是造成这个问题。 我们使用VMotion将服务器移至新硬件,问题就消失了。 VMWare没有显示警告或硬件问题。 尽pipe如此,硬件解决了这个问题。 非常奇怪。