I'm aware I should expect slower fetch times for large result sets generally, but I don't understand why fetching should be this slow. The workload fetches a large number of rows (1-10M) from a large table (100M+ rows).
mysql> describe testdb.test_table;
+-------+---------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+-------+---------+------+-----+---------+-------+
| col1 | int(11) | NO | PRI | NULL | |
| col2 | int(11) | NO | PRI | NULL | |
| col3 | int(11) | NO | PRI | NULL | |
+-------+---------+------+-----+---------+-------+
For the test case I use as simple query as possible:
select * from test_table limit 1000000;
However, the client appears to bottleneck around 1.5-2.5M rows/sec per query (1.5M in a Python client, 2.5M in MySQL Workbench). I know 2.5M rows/sec seems pretty fast, but that only works out to 30 MB/sec (2.5M * 3 cols * 4-byte ints). I'm on macOS 10.15.4, MySQL 5.7.29 installed via Homebrew, and connecting to the server over localhost. Python is using the MySQLClient
db driver.
The query plan shows the results selected from the primary index, as expected:
+----+-------------+----------+------------+-------+---------------+---------+---------+------+----------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+----------+------------+-------+---------------+---------+---------+------+----------+----------+-------------+
| 1 | SIMPLE | my_table | NULL | index | NULL | PRIMARY | 12 | NULL | 10821795 | 100.00 | Using index |
+----+-------------+----------+------------+-------+---------------+---------+---------+------+----------+----------+-------------+
The query profile doesn't indicate any hot spots.
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000055 |
| checking permissions | 0.000008 |
| Opening tables | 0.000016 |
| init | 0.000015 |
| System lock | 0.000021 |
| optimizing | 0.000011 |
| statistics | 0.000012 |
| preparing | 0.000019 |
| explaining | 0.000028 |
| end | 0.000007 |
| query end | 0.000007 |
| closing tables | 0.000009 |
| freeing items | 0.000015 |
| cleaning up | 0.000023 |
+----------------------+----------+
And as best I can tell, the entire test db fits in the buffer pool, and no disk IO occurs during the query. The Innodb_buffer_pool_reads
value is unchanged after executing the query, and the InnoDB Status
metrics from MySQL Workbench's performance dashboard are all zero throughout its runtime.
In MySQL Workbench's Duration / Fetch Time
columns, the duration stays consistently under 1ms, regardless of the number of rows selected. However, the fetch time is proportional to rows returned: ~0.5 sec for 1M and and 5.0 sec for 10M rows.
When I observe processes with top
I can see MySQL spiking to 100% CPU for a short time followed by MySQLWorkbench spiking to 100% for the remaining duration of the query after the query completes. The same test with the Python client (that doesn't do any additional work) shows the time a little more evenly split, but it's hard to measure.
That seems to only leave the the db client driver or the network connection itself as the bottleneck. I assume it's not the network since I'm testing over localhost (though I have not tested localhost in isolation). Does it make sense that the client bottlenecks processing rows at 30MB/sec? Can anything be done to improve throughput?
Update
Including requested global status, variables, processlist, and innodb status, but note that this is not on a dedicated server. My tests are on a MacBook Pro with 16GB RAM, 4-cores with Hyperthreading (i.e. macOS sees 8 hardware threads). The hard drive is an NVMe (~232k Read IOPS RND4k@QD32), but as I noted above, I observe no disk IO (and that includes swapping/paging by the OS).
I wanted to further isolate duration vs fetch time, so I trimmed the table to exactly 10M rows, and then compared a large select with an aggregate version of the same query using a "cheap" aggregate function.
select col1, col2, col3
from test_table;
Duration: 0.00082 sec, Fetch Time: 4.729 sec
select count(col1), count(col2), count(col3)
from test_table;
Duration: 2.692 sec, Fetch Time: 0.000011 sec
I think the duration/fetch time metrics are a little confusing, since I assume the first query duration only includes time to identify row IDs (not buffer them), while the second has to get each row in memory, a step that overlaps with fetch behavior in the first query, even though it's included in duration in the second.
Assuming 25% overhead for count()
that's about 2 secs to walk through 10M rows, so 5M rows or 60 MB/sec. Assuming the same access time cost for the first query, that would mean an additional ~45 MB/sec to copy them into a buffer to fetch.
In any case, even assuming additional data overhead per row, it seems like at a minimum simply accessing rows in memory in InnoDB is a significant bottleneck, regardless of the driver or network. mysqld
CPU% maxes out one thread for the duration of the aggregate query, so it appears to be a CPU-bound operation. Does that sound right? Is this just the cost of doing business with B+ trees? For (an unfair) comparison, the same operation takes about 200ms in Python using Pandas.
Additional info
>>show create table test_table;
...
CREATE TABLE `test_table ` (
`col1` int(11) NOT NULL,
`col2 ` int(11) NOT NULL,
`col3 ` int(11) NOT NULL,
PRIMARY KEY (`col1`,`col3`,`col2`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
...
>ulimit
unlimited
>ulimit -n
256
>ulimit -u
2784
>iostat
disk0 disk2 cpu load average
KB/t tps MB/s KB/t tps MB/s us sy id 1m 5m 15m
24.24 31 0.73 12.61 0 0.00 4 3 93 2.46 2.21 2.42
>top
Processes: 541 total, 2 running, 3 stuck, 536 sleeping, 2564 threads 11:40:37
Load Avg: 1.71, 1.53, 1.53 CPU usage: 6.94% user, 6.94% sys, 86.11% idle SharedLibs: 364M resident, 61M data, 16M linkedit.
MemRegions: 246424 total, 6527M resident, 153M private, 2132M shared. PhysMem: 16G used (3318M wired), 86M unused.
VM: 7190G vsize, 1995M framework vsize, 26292674(64) swapins, 27667013(0) swapouts. Networks: packets: 137115709/125G in, 167115774/85G out.
Disks: 13216718/253G read, 8333988/245G written.