MySQL Query Randomly Lags
У меня есть запрос, который выглядит так:
SELECT id FROM user WHERE id='47'
Идентификатор индексируется, и чтение для этого запроса всегда выполняется при использовании профилирующих данных, например.
SET profiling = 1;
SHOW PROFILES;
Запросы всегда выполняются примерно за 0,0002 секунды.
Однако, если я профилирую запрос со стороны PHP, например:
$current = microtime(true);
$data = $conn->query($full_query);
$elapsed = microtime(true) - $current;
Тогда иногда, возможно, 1 из 50 из этих запросов займет примерно 2 сек. Тем не менее, в моем тесте script у меня есть код для проверки этого, который профилирует запрос, используя SET profiling = 1; и даже несмотря на то, что поездка в PHP через PDO может быть .2 секунды, время запроса было еще 0,0002.
Вещи, которые я знаю, или знаю, что это не вызывает проблемы:
- Запрос не медленный. Когда я смотрю на тот же запрос, из одного и того же запроса, профилированного на PHP и профилированного с использованием SET PROFILING, запрос всегда быстр и никогда не регистрируется в журнале медленных запросов, даже когда он показывает, что занимает 0,2 секунды со стороны PHP.
- Это не связанное с пропуском имя-разрешение - это непоследовательно, и у меня уже есть разрешение на имя пропущенного имени
- Это не связанный с кешем запросов, поведение существует как в
- Такое поведение происходит даже по запросам, выходящим из кеша.
- Запрос фактически не отображает идентификатор, но я использую этот запрос для тестирования, чтобы показать, что он не является проблемой доступа к диску, поскольку это поле определенно индексируется.
- Эти таблицы составляют всего 10-20 мегабайт с чем-то вроде индекса 1 мега. Машина показывает очень мало нагрузки, и innodb не использует все свои буферы.
- Это проверено на таблицу, которая не имеет других действий против нее, кроме моих тестовых запросов.
Есть ли у кого-нибудь идеи, что еще проверить? Мне кажется, что это сетевая проблема, но мне нужно уметь ее видеть и найти проблему, чтобы исправить ситуацию, и у меня заканчивается ситуация, чтобы проверить ее. Любые идеи?
Ответы
Ответ 1
Я бы прокомментировал машину.
Вы говорите, что это происходит ~ 1 в 50 раз, и каждый запрос имеет 0,2-секундный тест. Вы должны уметь накладывать верхнюю часть на экран, а затем запускать цикл запросов в PHP для загрузки тестов RDBMS и сбора статистики производительности.
Вероятно, вам придется запускать больше 50 * 0.2 =
10 seconds
, поскольку ваша статистика "1 из 50", вероятно, основана на ручных индивидуальных запросах - на основе того, что я читал в ваше описание. Попробуйте выполнить 30-секундные и 90-секундные тесты нагрузки.
В течение этого времени просмотрите экран процесса top
. Сортируйте его по CPU, нажав P
. Каждый раз, когда вы нажимаете "P", он изменяет порядок сортировки для потребления процессора и процессора, поэтому убедитесь, что у вас есть самое большое потребление. (нажатие M
сортирует по использованию памяти. man page).
Ищите все, что пузырится до вершины в течение времени (ов) вашего теста нагрузки. Вы должны увидеть что-то прыгать выше - на мгновение.
(обратите внимание, что такой процесс может не попасть в верхнюю часть списка - он не обязательно, но может все еще ввести достаточную нагрузку на диск или другую активность для задержки сервера MySQL).
Ответ 2
Я заметил одно и то же явление в своих системах. Запросы, которые обычно занимают миллисекунду, внезапно занимают 1-2 секунды. Все мои дела просты, одиночные таблицы INSERT/UPDATE/REPLACE - не на всех SELECT. Никакая нагрузка, блокировка или нить накапливаются.
Я подозревал, что это связано с очисткой грязных страниц, сбрасыванием изменений на диск или некоторыми скрытыми мьютексами, но мне еще предстоит сузить его.
Также исключен
-
Загрузка сервера - отсутствие корреляции с высоким
-
load Engine - происходит с запросом InnoDB/MyISAM/Memory MySQL
-
Кэш - бывает ли он включен или выключен
-
Логарифмические вращения - отсутствие корреляции в событиях
Ответ 3
Хорошо, что вы уже использовали профилировщик запросов. Если вы используете MySQL 5.6, у вас также есть доступ к множеству новых измерений производительности в PERFORMANCE_SCHEMA. Это позволяет измерять намного больше деталей, чем профилировщик запросов, а также измеряет глобальность вместо одного сеанса. Сообщается, что P_S заменит прокси-сервер запроса.
Чтобы диагностировать вашу проблему, я бы начал с подтверждения или исключения проблемы с TCP/IP. Например, протестируйте PHP script, чтобы узнать, получает ли он такую же прерывистую задержку при подключении через сокет UNIX. Вы можете сделать это, подключившись к localhost
, что означает, что PHP скрипт должен запускаться на том же сервере, что и база данных. Если проблема уходит, когда вы обходите TCP/IP, это скажет вам, что основной причиной может быть TCP/IP.
Если вы находитесь в виртуальной среде, такой как облачный хостинг, вы можете легко ощущать изменения в производительности, поскольку другие пользователи одного и того же облака периодически используют всю пропускную способность. Это один из недостатков облака.
Если вы подозреваете, что это проблема TCP/IP, вы можете проверить задержку TCP/IP независимо от PHP или MySQL. Типичные доступные инструменты включают ping
или traceroute
. Но есть многие другие. Вы также можете проверить скорость сети с помощью netcat. Используйте инструмент, который может измерять многократно с течением времени, потому что это звучит так, как будто у вас хорошая производительность в большинстве случаев со случайными сбоями.
Другая возможность заключается в том, что ошибка заключается в PHP. Вы можете попробовать профилировать PHP с помощью XHProf, чтобы узнать, где он проводит свое время.
Ответ 4
Попробуйте изолировать проблему. Запустите немного script следующим образом:
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 [email protected]: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: [email protected]
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: [email protected]/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
Что-то, что я нашел очень полезным при диагностике проблем MySQL в этом ключе, mysqltuner. Это PERL script, который смотрит на ваш экземпляр MySQL и предлагает различные улучшения настройки. Честно говоря, сложно отслеживать всю настройку, которую вы можете сделать, и этот script является потрясающим для того, чтобы дать вам пробой потенциальных точек засоса.
Что-то еще, чтобы рассмотреть, как работает сам Linux, что также может объяснить, почему вы случайно отстаете. Когда вы загружаете top
в ящик Linux (любое поле, независимо от загрузки), вы заметите, что ваша память почти полностью используется (если только вы не перезагрузились). Это не проблема или перегрузка вашей коробки. Linux загружает столько, сколько может, в оперативную память, чтобы сэкономить время и обменять нечасто используемые вещи в ваш файл подкачки, как и все современные операционные системы (называемые виртуальными RAM). Обычно это не большая проблема, но вы, вероятно, используете InnoDB
как тип таблицы (текущий по умолчанию), который загружает вещи в ОЗУ, чтобы сэкономить время. Что может случиться, ваш запрос загрузился в оперативную память (быстро), но сидел без дела достаточно долго, чтобы поменяться на файл подкачки (гораздо медленнее). Таким образом, вы получите небольшой выигрыш в производительности, в то время как Linux переместил его обратно в ОЗУ (swapfiles более эффективны, чем MySQL будет перемещать его с диска). Ни MySQL, ни InnoDB
не могут сказать об этом, потому что, насколько они есть, он все еще находится в ОЗУ. Эта проблема подробно описана в в этом блоге, при этом соответствующая часть
Обычно крошечный бит использования подкачки может быть в порядке (был действительно об активности и свопингах), но во многих случаях "реальные" полезные память заменяется: в основном это часть пула буферов InnoDB. когда его необходимо еще раз, большой удар производительности, чтобы поменять его обратно в, вызывая случайные задержки в случайных запросах. Это может привести к непредсказуемая производительность на производственных системах, и часто один раз система обмена может войти в спираль смерти производительности.
Ответ 7
Мы выяснили, что проблема с основным оборудованием вызвала это. Мы переместили сервер на новое оборудование с помощью VMotion, и проблема исчезла. VMWare не показывал предупреждения или проблемы с оборудованием. Тем не менее, устранение этого аппаратного обеспечения устранило проблему. Очень странно.