Ao olhar para uma consulta particularmente irritante sobre tabelas MyISAM que leva muito tempo para executar em várias ocasiões, notei que o MySQL parece expor um padrão de I/O bastante estranho: ao executar uma única consulta e ter que fazer um quantidade de E/S (por exemplo, para uma varredura de tabela ou quando os caches estão vazios, echo 3 > /proc/sys/vm/drop_cachesentão os índices precisam ser carregados do disco primeiro), o tamanho da fila para o dispositivo de bloco subjacente está próximo do valor 1, com desempenho péssimo de apenas 4-5 MB/s:

root@mysql-test:~# iostat -xdm 5 /dev/sda
Linux 3.2.0-40-generic (mysql-test)  04/30/2014      _x86_64_        (4 CPU)

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.14    24.82   18.26   88.79     0.75     4.61   102.56     2.83   26.39   19.29   27.85   2.46  26.31

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00    69.29  151.52   72.73     5.31     0.59    53.95     1.21    5.39    7.84    0.29   4.39  98.51

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00   153.06  144.29  174.69     4.96     1.36    40.54     1.39    4.36    8.91    0.60   3.15 100.49

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00   105.75  150.92  109.03     4.53     0.85    42.41     1.29    4.96    8.15    0.54   3.90 101.36

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00    48.89  156.36   51.72     5.28     0.76    59.38     1.28    6.16    8.02    0.55   4.77  99.23

Embora os 150 IOPS sejam simplesmente o que um único disco na configuração fornecida é capaz de fornecer em termos de I/O aleatório, o resultado ainda me surpreende, pois eu esperaria que o MySQL fosse capaz de executar I/O assíncrono para leituras e buscar um grande quantidade de blocos simultaneamente em vez de lê-los e avaliá-los um por um, negligenciando efetivamente os ganhos de paralelização disponíveis nas configurações de RAID. Qual decisão de projeto ou opção de configuração é responsável por isso? Este é um problema específico da plataforma?

Embora eu tenha testado isso com tabelas MyISAM grandes, vejo efeitos semelhantes com as mesmas tabelas convertidas para InnoDB (embora não seja tão ruim, a consulta de amostra ainda leva de 20 a 30 segundos, com a maior parte do tempo gasta na leitura do disco com um comprimento de fila de 1) depois de reiniciar o daemon mysql e, portanto, os buffer pools estão vazios. Também verifiquei que o mesmo problema persiste no 5.6 GA e no atual marco 14 do 5.7 - enquanto estiver usando um único thread de consulta, o MySQL parece incapaz de paralelizar as operações de E/S necessárias para o processamento da consulta.

A pedido, alguns detalhes adicionais sobre o cenário. O comportamento pode ser observado com vários tipos de consulta. Eu escolhi arbitrariamente um para testes adicionais, que é mais ou menos assim:

SELECT herp.id, herp.firstname, herp.lastname, derp.label, herp.email, 
(SELECT CONCAT(label, " (", zip_code, " ", city,")" ) FROM subsidiaries WHERE subsidiaries.id=herp.subsidiary_id ) AS subsidiary, 
(SELECT COUNT(fk_herp) from herp_missing_data WHERE fk_herp=herp.id) AS missing_data
FROM herp LEFT JOIN derp ON derp.id=herp.fk_derp
WHERE (herp.fk_pools='123456')  AND herp.city LIKE '%Some City%' AND herp.active='yes' 
ORDER BY herp.id desc LIMIT 0,10;

Sei que há espaço para otimização, mas decidi deixar por isso mesmo por vários motivos e me concentrar em encontrar uma explicação geral para o padrão de E/S inesperado que estou vendo.

As tabelas usadas têm um monte de dados nelas:

mysql> select table_name, engine, table_rows, data_length, index_length from information_schema.tables WHERE tables.TABLE_SCHEMA = 'mydb' and tables.table_name in ( 'herp', 'derp', 'missing_data', 'subsidiaries');
+-------------------------+--------+------------+-------------+--------------+
| table_name              | engine | table_rows | data_length | index_length |
+-------------------------+--------+------------+-------------+--------------+
| derp                    | MyISAM |      14085 |     1118676 |       165888 |
| herp                    | MyISAM |     821747 |   828106512 |    568057856 |
| missing_data            | MyISAM |    1220186 |    15862418 |     29238272 |
| subsidiaries            | MyISAM |       1499 |     6490308 |       103424 |
+-------------------------+--------+------------+-------------+--------------+
4 rows in set (0.00 sec)

Agora, quando estou executando a consulta acima nessas tabelas, estou obtendo tempos de execução de mais de 1 minuto, enquanto o sistema está aparentemente continuamente ocupado lendo dados do disco com um único thread.

O perfil para uma execução de consulta de amostra (que levou 1 minuto e 9,17 segundos neste exemplo) tem a seguinte aparência:

mysql> show profile for query 1;
+--------------------------------+-----------+
| Status                         | Duration  |
+--------------------------------+-----------+
| starting                       |  0.000118 |
| Waiting for query cache lock   |  0.000035 |
| init                           |  0.000033 |
| checking query cache for query |  0.000399 |
| checking permissions           |  0.000077 |
| checking permissions           |  0.000030 |
| checking permissions           |  0.000031 |
| checking permissions           |  0.000035 |
| Opening tables                 |  0.000158 |
| init                           |  0.000294 |
| System lock                    |  0.000056 |
| Waiting for query cache lock   |  0.000032 |
| System lock                    |  0.000116 |
| optimizing                     |  0.000063 |
| statistics                     |  0.001964 |
| preparing                      |  0.000104 |
| Sorting result                 |  0.000033 |
| executing                      |  0.000030 |
| Sending data                   |  2.031349 |
| optimizing                     |  0.000054 |
| statistics                     |  0.000039 |
| preparing                      |  0.000024 |
| executing                      |  0.000013 |
| Sending data                   |  0.000044 |
| optimizing                     |  0.000017 |
| statistics                     |  0.000021 |
| preparing                      |  0.000019 |
| executing                      |  0.000013 |
| Sending data                   | 21.477528 |
| executing                      |  0.000070 |
| Sending data                   |  0.000075 |
| executing                      |  0.000027 |
| Sending data                   | 45.692623 |
| end                            |  0.000076 |
| query end                      |  0.000036 |
| closing tables                 |  0.000109 |
| freeing items                  |  0.000067 |
| Waiting for query cache lock   |  0.000038 |
| freeing items                  |  0.000080 |
| Waiting for query cache lock   |  0.000044 |
| freeing items                  |  0.000037 |
| storing result in query cache  |  0.000033 |
| logging slow query             |  0.000103 |
| cleaning up                    |  0.000073 |
+--------------------------------+-----------+
44 rows in set, 1 warning (0.00 sec)