Please provide the complete table definition without reductions. If they've been made for the sake of confidentiality, it doesn't make sense anyway, because the column names are still shown in indexes, we just lose information about their definition, and can't get the same plans as yours.
Did you try to use engine-independent table statistics? At least it should provide stable execution plans, whether they are going to be good plans remains to be seen.
Please also attach your cnf file(s).
Hello Elena,
It was cut for shortness. Here is the complete current table definition (some index changes, but I still have to use FORCE INDEX for proper operation):
| radacct | CREATE TABLE `radacct` ( |
`RadAcctId` bigint(21) NOT NULL AUTO_INCREMENT, |
`AcctSessionId` varchar(64) DEFAULT NULL, |
`AcctUniqueId` varchar(32) NOT NULL DEFAULT '', |
`UserName` varchar(64) NOT NULL DEFAULT '', |
`Realm` varchar(64) DEFAULT '', |
`NASIPAddress` varchar(15) NOT NULL DEFAULT '', |
`NASPort` int(12) DEFAULT NULL, |
`NASPortId` char(32) DEFAULT '0', |
`NASPortType` varchar(32) DEFAULT NULL, |
`AcctStartTime` datetime NOT NULL DEFAULT '0000-00-00 00:00:00', |
`AcctStopTime` datetime NOT NULL DEFAULT '0000-00-00 00:00:00', |
`AcctSessionTime` int(12) DEFAULT NULL, |
`AcctAuthentic` varchar(32) DEFAULT NULL, |
`ConnectInfo_start` varchar(32) DEFAULT NULL, |
`ConnectInfo_stop` varchar(32) DEFAULT NULL, |
`AcctInputOctets` bigint(12) DEFAULT NULL, |
`AcctOutputOctets` bigint(12) DEFAULT NULL, |
`CalledStationId` varchar(50) NOT NULL DEFAULT '', |
`CallingStationId` varchar(50) NOT NULL DEFAULT '', |
`AcctTerminateCause` varchar(32) NOT NULL DEFAULT '', |
`ServiceType` varchar(32) DEFAULT NULL, |
`FramedProtocol` varchar(32) DEFAULT NULL, |
`FramedIPAddress` varchar(15) NOT NULL DEFAULT '', |
`AcctStartDelay` int(12) DEFAULT NULL, |
`AcctStopDelay` int(12) DEFAULT NULL, |
`ProductID` bigint(20) DEFAULT NULL, |
`AcctInputGigawords` int(11) DEFAULT '0', |
`AcctOutputGigawords` int(11) DEFAULT '0', |
`AcctInputOctets64` char(18) DEFAULT '0', |
`AcctOutputOctets64` char(18) DEFAULT '0', |
`LastUpdated` datetime DEFAULT NULL, |
PRIMARY KEY (`RadAcctId`), |
KEY `UserName` (`UserName`), |
KEY `AcctSessionId` (`AcctSessionId`), |
KEY `AcctUniqueId` (`AcctUniqueId`), |
KEY `AcctStartTime` (`AcctStartTime`), |
KEY `AcctStopTime` (`AcctStopTime`), |
KEY `RadCheckProductID` (`ProductID`), |
KEY `user_start_stop_ip` (`UserName`,`AcctStartTime`,`AcctStopTime`,`FramedIPAddress`), |
KEY `user_stop` (`UserName`,`AcctStopTime`), |
KEY `user_stop_start_ip` (`UserName`,`AcctStopTime`,`AcctStartTime`,`FramedIPAddress`), |
KEY `AcctStartTime_AcctUniqueId` (`AcctStartTime`,`AcctUniqueId`), |
KEY `CallingStationId` (`CallingStationId`), |
KEY `LastUpdated` (`LastUpdated`), |
KEY `updates` (`UserName`,`NASIPAddress`,`AcctSessionId`), |
KEY `NASIPAddress` (`NASIPAddress`), |
KEY `stale` (`AcctStopTime`,`LastUpdated`), |
KEY `FramedIPAddress` (`FramedIPAddress`) |
) ENGINE=TokuDB AUTO_INCREMENT=194622508 DEFAULT CHARSET=latin1 `compression`='tokudb_zlib' |
For engine-independent table statistics, I assume we have not used it, we have use_stat_tables = NEVER in variable list. I'll read on the matter and try it. Doing full scan to ANALYZE from time to time may be bad though, the table is huge.
Configuration is as follows:
[mysqld]
|
datadir=/db/mysql
|
port=3306
|
socket=/var/lib/mysql/mysql.sock
|
pid-file=/var/lib/mysql/mysql.pid
|
default-storage-engine=InnoDB
|
user=mysql
|
open_files_limit=8192
|
innodb_file_per_table
|
skip-name-resolve
|
|
|
# charset
|
character-sets-dir=/usr/share/mysql/charsets
|
character-set-server=utf8
|
|
|
# fix for .NET appservers with pooling issues
|
connect_timeout=300
|
|
|
# This one does not affect the issue, I've tried commenting it already
|
optimizer_switch=index_merge_sort_union=on,index_merge_sort_intersection=on,orderby_uses_equalities=on
|
|
|
# optimization
|
table_cache=1024
|
max_connections=1024
|
back_log=1024
|
thread_cache_size=4
|
concurrent_insert=2
|
delay_key_write=ALL
|
max_allowed_packet=16M
|
preload_buffer_size=256K
|
key_buffer_size=16M
|
join_buffer_size=16M
|
query_cache_size=128M
|
query_cache_limit=256K
|
query_prealloc_size=64K
|
transaction_prealloc_size=64K
|
sort_buffer_size=16M
|
read_buffer_size=64K
|
read_rnd_buffer_size=64K
|
tmp_table_size=64K
|
max_heap_table_size=32M
|
innodb_file_format=Barracuda
|
innodb_buffer_pool_size=320M
|
innodb_log_buffer_size=32M
|
innodb_log_file_size=64M
|
|
|
# recovery
|
innodb_force_recovery = 0
|
myisam-recover=DEFAULT,BACKUP,FORCE
|
|
|
# logs
|
log-error = /db/logs/mysql.log
|
slow_query_log = 1
|
slow_query_log_file = /db/logs/mysql-slow.log
|
|
|
# binlog
|
binlog_format=MIXED
|
log-bin=/db/binlog/mysql_binary_log
|
log-slave-updates=1
|
binlog-do-db=radius
|
binlog-do-db=dns
|
binlog-do-db=maildb
|
binlog-do-db=mail
|
binlog-do-db=ACS
|
binlog-do-db=webconfig_snappy
|
binlog-do-db=ldap
|
binlog-do-db=managed_cpes
|
server-id=1
|
gtid-domain-id=40
|
expire_logs_days=666
|
|
|
# temp dir
|
tmpdir=/db/temp
|
|
|
[mysqld_safe]
|
log-error = /db/logs/mysqld-safe.log
|
|
|
[mariadb]
|
plugin-load=ha_tokudb
|
tokudb_cache_size=320M
|
tokudb_data_dir=/db/tokudb/data
|
tokudb_log_dir=/db/tokudb/log
|
tokudb_tmp_dir=/db/tokudb/temp
|
tokudb_lock_timeout=50000
|
tokudb_prelock_empty=0
|
|
|
[client]
|
character-sets-dir=/usr/share/mysql/charsets
|
socket=/var/lib/mysql/mysql.sock
|
Thanks.
Doing full scan to ANALYZE from time to time may be bad though, the table is huge.
This is very true, and also it can take quite a lot of resources, which is why I don't usually suggest it for really big tables. However, if you have a staging instance, it would be worth trying to see if it really helps, and if it does, what's the price for it (analyze time).
I am having similar issues since 10.1.24. elenst has linked TDB-2 to this, but I don't think it is related unless you have wrong row counts (do check this though!).
The regression occurs immediately on upgrading to 10.1.24 and can be fixed immediately by downgrading to 10.1.23 on the same data dir. The other way to (temporarily, I think) work around is by doing ALTER TABLE blah ENGINE=tokudb; and for some reason after doing this the index selection is correct. Obviously this is a very expensive operation for large tables.
Thanks for the info, Phil. Row counts are correct. Indeed the table it's not picking up index for has hot created indexes (including the one it's not picking up), so it may really be related to TDB-35.
OK!! Now you've have got me thinking about this again and after re-reading Jun's fix for TDB-35, I've realised that each index has its own row count, and this wasn't being written to the metadata properly. So I remembered from an old row count ticket there's a CLI utility to dump the tokudb info.
I've had a look at one of the indexes that is being inappropriately used and I see this:
$ /usr/local/mysql/bin/tokuftdump --header /var/lib/mysql/data/forum/<table>key<index_name>_190f8b66d_3_1d_P_0.tokudb
<snip>
estimated numrows=2412860
estimated numbytes=260980666
logical row count=-8978474
Yeah.. negative 9 million rows for logical row count.
I had a look at the slave where i did the alter table engine=tokudb and low and behold (of course):
estimated numrows=2395122
estimated numbytes=260981897
logical row count=2411520
Can you try this command and see what yours looks like Alex/AT? Next step of course is how can we repair this row count without doing an alter table engine=tokudb. I guess you can hot create another index (with the fix for TDB-35) and drop the original. And using this CLI command you can determine which indexes are broken across your tables.
Indeed I have some broken counts, but they're just -1, not a large negative value.
_radius_sql_5600_2b_key_AcctStopTime_a6_8_1b.tokudb
estimated numrows=28729817
logical row count=-1
_radius_sql_5600_2b_key_AcctUniqueId_a6_6_1b.tokudb
estimated numrows=7046798
logical row count=-1
_radius_sql_5600_2b_key_RadCheckProductID_a6_a_1b.tokudb
estimated numrows=9840951
logical row count=-1
I'm now trying to roll up my own RPMs of 10.1.28 with the patch included. It will take some time because I need to stage-test it.
OK I compiled my own build of 10.1.28 with the two line fix for TDB-35. Can confirm that creating a new hot index for the index with the wrong logical row count (checked via the CLI utility).. and dropping the old one corrects the index selection. Now to find all my indexes with the wrong row count :-/
Okay, I've build 10.1.28 with patch/commit fixing TDB-35 (https://github.com/percona/PerconaFT/commit/9783d7a6b5ba3a623f6d7b3afe98f9bac06d6038) applied, and it passed all the internal tests. I've rolled it up on the server in question and was trying to recover from a wrong query plan condition by recreating indexes.
I'll put conclusion first to clarify things: nor TDB-2, nor TDB-35 fixes solve this wrong query plan issue. It's still using an index merge instead of encompassing index. I tried EXPAIN at different moments (after first index rebuild / see below, after second index rebuild and after doing full background ANALYZE on a table). All of them displayed the same query plan using index merge.
And now for the good/bad news after trying 10.1.28 with TDB-35 fix:
1. /good/ Row counts on index recreation seemingly return back to normal. I don't have any '-1' count shown by tokuftdump --header anymore.
2. /bad/ Update from 10.1.25 to 10.1.28 broke total row counts for the table again, and then when recreating indexes I've got 'fetched XXXXXX rows out of 0 rows', 'fetched XXXXXX rows out of 35 rows' and other stuff like that. Resulting index cardinality on recreation was affected by that and was seemingly wrong.
3. /good/ After doing ANALYZE in RECOUNT ROWS mode, total row count returned to normal, allowing me to recreate indexes properly.
4. /bad/ After recreating indexes, I've got strangely similar cardinality values for all the indexes after recreating them. Wonder if that is as it should be...
---------------------------------------------------------------------------------------------------------------------------------------------
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
---------------------------------------------------------------------------------------------------------------------------------------------
| radacct | 0 | PRIMARY | 1 | RadAcctId | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | UserName | 1 | UserName | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | FramedIPAddress | 1 | FramedIPAddress | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | NASIPAddress | 1 | NASIPAddress | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | AcctUniqueId | 1 | AcctUniqueId | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | AcctSessionId | 1 | AcctSessionId | A | 6558353 | NULL | NULL | YES | BTREE | ||
| radacct | 1 | AcctStartTime | 1 | AcctStartTime | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | AcctStopTime | 1 | AcctStopTime | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | CallingStationId | 1 | CallingStationId | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | RadCheckProductID | 1 | ProductID | A | 6558353 | NULL | NULL | YES | BTREE | ||
| radacct | 1 | LastUpdated | 1 | LastUpdated | A | 6558353 | NULL | NULL | YES | BTREE | ||
| radacct | 1 | AcctStartTime_AcctUniqueId | 1 | AcctStartTime | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | AcctStartTime_AcctUniqueId | 2 | AcctUniqueId | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_start_stop_ip | 1 | UserName | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_start_stop_ip | 2 | AcctStartTime | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_start_stop_ip | 3 | AcctStopTime | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_start_stop_ip | 4 | FramedIPAddress | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop | 1 | UserName | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop | 2 | AcctStopTime | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop_start_ip | 1 | UserName | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop_start_ip | 2 | AcctStopTime | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop_start_ip | 3 | AcctStartTime | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop_start_ip | 4 | FramedIPAddress | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | updates | 1 | UserName | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | updates | 2 | NASIPAddress | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | updates | 3 | AcctSessionId | A | 6558353 | NULL | NULL | YES | BTREE | ||
| radacct | 1 | stale | 1 | AcctStopTime | A | 6558353 | NULL | NULL | BTREE | |||
| radacct | 1 | stale | 2 | LastUpdated | A | 6558353 | NULL | NULL | YES | BTREE |
---------------------------------------------------------------------------------------------------------------------------------------------
5. /bad/ Full background ANALYZE did not return cardinality to adequate until restarting the mariadb server process.
Seems like we have some another bug here: background ANALYZE does not post cardinality changes to the engine.
Indeed I can confirm another (but unrelated) problem with background ANALYZE. Foreground one pushes cardinalities back properly. Should I create a separate bug ticket for that?
So for this one, where are we now:
1. 10.1.28 with TDB-35 fix applied.
2. Cardinalities are seemingly ok (given ANALYZE was run as foreground), row counts are ok.
3. Query plan still wrong. I assume it has to do something with optimizer, not only TokuDB.
alex/at My master DB is now running with my custom build, and I only fixed the index with -9,000,000 rows. The rest are all either normal values or -1. I have a feeling -1 is OK and probably means logical row counts are ignored. Everything seems to be running OK for me right now.
You seem to have an unrelated issue to the logical_row_count on the index.
Indeed, this seems to be a combination of issues. Fixing logical row counts fixed some other queries plans but this one still remains 
Hopefully someone from MariaDB team can shed a light on that.
But another thing is: backup server running on 10.1.23 do not exhibit this behavior 
So regression is still somewhere around 10.1.24.
alex/at So with my main issue fixed (The minus 8 million row index).. I'm now seeing a small number of queries that are doing crazy stuff and scanning millions of rows - guess I'm seeing similar things to you now. Time to return to 10.1.23 :-/
Elena Stepanova has linked TDB-2 to this, but I don't think it is related
philsweeney, I intentionally link them all together. It doesn't imply direct causation, but I think this cluster of problems should be looked at as a whole, otherwise it is likely to cause even more confusion – when one tries fix A, and it doesn't help, then one instead tries fix B, it also doesn't help, while in fact it only helps when you apply A, and B, and also some C on top of it (but without A and B there will be no effect of C). We do need to look into the suspected optimizer problem, but we can only do it efficiently if there are no obvious upstream problems on the way.
So for this one, where are we now:
1. 10.1.28 with TDB-35 fix applied.
2. Cardinalities are seemingly ok (given ANALYZE was run as foreground), row counts are ok.
3. Query plan still wrong. I assume it has to do something with optimizer, not only TokuDB.
Alex/AT, could you please provide the summary of this variation of the problem (or point at parts of it if they are already here among all the comments):
- show create table if it's different from the description
- row counts (statistics from I_S)
- cardinalities (SHOW INDEX IN or alike)
- query
- execution plan (if possible, in the form of ANALYZE FORMAT=JSON <query> – but be aware that it will actually execute the DML, so if it's undesirable or too time-consuming, then the traditional one)
- expected execution plan (if you can tweak it with hints) or just verbose description of your expectation
Sure thing. I'll do in in multiple posts.
Table definition (no, it does not really differ):
| radacct | CREATE TABLE `radacct` ( |
`RadAcctId` bigint(21) NOT NULL AUTO_INCREMENT, |
`AcctSessionId` varchar(64) DEFAULT NULL, |
`AcctUniqueId` varchar(32) NOT NULL DEFAULT '', |
`UserName` varchar(64) NOT NULL DEFAULT '', |
`Realm` varchar(64) DEFAULT '', |
`NASIPAddress` varchar(15) NOT NULL DEFAULT '', |
`NASPort` int(12) DEFAULT NULL, |
`NASPortId` char(32) DEFAULT '0', |
`NASPortType` varchar(32) DEFAULT NULL, |
`AcctStartTime` datetime NOT NULL DEFAULT '0000-00-00 00:00:00', |
`AcctStopTime` datetime NOT NULL DEFAULT '0000-00-00 00:00:00', |
`AcctSessionTime` int(12) DEFAULT NULL, |
`AcctAuthentic` varchar(32) DEFAULT NULL, |
`ConnectInfo_start` varchar(32) DEFAULT NULL, |
`ConnectInfo_stop` varchar(32) DEFAULT NULL, |
`AcctInputOctets` bigint(12) DEFAULT NULL, |
`AcctOutputOctets` bigint(12) DEFAULT NULL, |
`CalledStationId` varchar(50) NOT NULL DEFAULT '', |
`CallingStationId` varchar(50) NOT NULL DEFAULT '', |
`AcctTerminateCause` varchar(32) NOT NULL DEFAULT '', |
`ServiceType` varchar(32) DEFAULT NULL, |
`FramedProtocol` varchar(32) DEFAULT NULL, |
`FramedIPAddress` varchar(15) NOT NULL DEFAULT '', |
`AcctStartDelay` int(12) DEFAULT NULL, |
`AcctStopDelay` int(12) DEFAULT NULL, |
`ProductID` bigint(20) DEFAULT NULL, |
`AcctInputGigawords` int(11) DEFAULT '0', |
`AcctOutputGigawords` int(11) DEFAULT '0', |
`AcctInputOctets64` char(18) DEFAULT '0', |
`AcctOutputOctets64` char(18) DEFAULT '0', |
`LastUpdated` datetime DEFAULT NULL, |
PRIMARY KEY (`RadAcctId`), |
KEY `UserName` (`UserName`), |
KEY `FramedIPAddress` (`FramedIPAddress`), |
KEY `AcctUniqueId` (`AcctUniqueId`), |
KEY `AcctSessionId` (`AcctSessionId`), |
KEY `AcctStartTime` (`AcctStartTime`), |
KEY `AcctStopTime` (`AcctStopTime`), |
KEY `CallingStationId` (`CallingStationId`), |
KEY `RadCheckProductID` (`ProductID`), |
KEY `LastUpdated` (`LastUpdated`), |
KEY `AcctStartTime_AcctUniqueId` (`AcctStartTime`,`AcctUniqueId`), |
KEY `user_start_stop_ip` (`UserName`,`AcctStartTime`,`AcctStopTime`,`FramedIPAddress`), |
KEY `user_stop` (`UserName`,`AcctStopTime`), |
KEY `user_stop_start_ip` (`UserName`,`AcctStopTime`,`AcctStartTime`,`FramedIPAddress`), |
KEY `updates` (`UserName`,`NASIPAddress`,`AcctSessionId`), |
KEY `stale` (`AcctStopTime`,`LastUpdated`), |
KEY `NASIPAddress` (`NASIPAddress`) |
) ENGINE=TokuDB AUTO_INCREMENT=194947711 DEFAULT CHARSET=latin1 `compression`='tokudb_zlib' |
INFORMATION_SCHEMA data:
TABLES
| TABLE_CATALOG | TABLE_SCHEMA | TABLE_NAME | TABLE_TYPE | ENGINE | VERSION | ROW_FORMAT | TABLE_ROWS | AVG_ROW_LENGTH | DATA_LENGTH | MAX_DATA_LENGTH | INDEX_LENGTH | DATA_FREE | AUTO_INCREMENT | CREATE_TIME | UPDATE_TIME | CHECK_TIME | TABLE_COLLATION | CHECKSUM | CREATE_OPTIONS | TABLE_COMMENT |
| def | radius | radacct | BASE TABLE | TokuDB | 10 | Dynamic | 6552800 | 372 | 2441337995 | 9223372036854775807 | 3667676735 | 18446744069536708694 | 194947741 | 2015-09-28 10:40:15 | 2017-10-02 06:42:51 | NULL | latin1_swedish_ci | NULL | `compression`='tokudb_zlib' |
TokuDB_fractal_tree_info
| dictionary_name | internal_file_name | bt_num_blocks_allocated | bt_num_blocks_in_use | bt_size_allocated | bt_size_in_use | table_schema | table_name | table_dictionary_name |
| ./radius/radacct-key-AcctSessionId | /db/tokudb/data/_radius_radacct_key_AcctSessionId_17a69764_3_1d_B_0.tokudb | 121 | 121 | 62528000 | 50169417 | radius | radacct | key-AcctSessionId |
| ./radius/radacct-key-AcctStartTime | /db/tokudb/data/_radius_radacct_key_AcctStartTime_17a6c223_3_1d_B_0.tokudb | 55 | 55 | 36520960 | 35826750 | radius | radacct | key-AcctStartTime |
| ./radius/radacct-key-AcctStartTime_AcctUniqueId | /db/tokudb/data/_radius_radacct_key_AcctStartTime_AcctUniqueId_17a7495b_3_1d_B_0.tokudb | 107 | 107 | 157975552 | 156575828 | radius | radacct | key-AcctStartTime_AcctUniqueId |
| ./radius/radacct-key-AcctStopTime | /db/tokudb/data/_radius_radacct_key_AcctStopTime_17a6d286_3_1d_B_0.tokudb | 110 | 56 | 41564160 | 39984702 | radius | radacct | key-AcctStopTime |
| ./radius/radacct-key-AcctUniqueId | /db/tokudb/data/_radius_radacct_key_AcctUniqueId_17a66ccc_3_1d_B_0.tokudb | 92 | 92 | 153154048 | 128172101 | radius | radacct | key-AcctUniqueId |
| ./radius/radacct-key-CallingStationId | /db/tokudb/data/_radius_radacct_key_CallingStationId_17a6f7af_3_1d_B_0.tokudb | 104 | 104 | 40336896 | 34341445 | radius | radacct | key-CallingStationId |
| ./radius/radacct-key-FramedIPAddress | /db/tokudb/data/_radius_radacct_key_FramedIPAddress_17a641c2_3_1d_B_0.tokudb | 63 | 63 | 33589248 | 27132997 | radius | radacct | key-FramedIPAddress |
| ./radius/radacct-key-LastUpdated | /db/tokudb/data/_radius_radacct_key_LastUpdated_17a73c94_3_1d_B_0.tokudb | 94 | 48 | 31870976 | 29947458 | radius | radacct | key-LastUpdated |
| ./radius/radacct-key-NASIPAddress | /db/tokudb/data/_radius_radacct_key_NASIPAddress_17a87ba5_3_1d_B_0.tokudb | 134 | 68 | 28427264 | 27357765 | radius | radacct | key-NASIPAddress |
| ./radius/radacct-key-RadCheckProductID | /db/tokudb/data/_radius_radacct_key_RadCheckProductID_17a722d1_3_1d_B_0.tokudb | 41 | 41 | 25395712 | 23821890 | radius | radacct | key-RadCheckProductID |
| ./radius/radacct-key-UserName | /db/tokudb/data/_radius_radacct_key_UserName_17a633bb_3_1d_B_0.tokudb | 74 | 74 | 36732928 | 29462597 | radius | radacct | key-UserName |
| ./radius/radacct-key-stale | /db/tokudb/data/_radius_radacct_key_stale_17a80a12_3_1d_B_0.tokudb | 124 | 63 | 45487104 | 43228753 | radius | radacct | key-stale |
| ./radius/radacct-key-updates | /db/tokudb/data/_radius_radacct_key_updates_17a7e586_3_1d_B_0.tokudb | 184 | 184 | 65729536 | 55432821 | radius | radacct | key-updates |
| ./radius/radacct-key-user_start_stop_ip | /db/tokudb/data/_radius_radacct_key_user_start_stop_ip_17a76c0c_3_1d_B_0.tokudb | 128 | 128 | 97480192 | 81173625 | radius | radacct | key-user_start_stop_ip |
| ./radius/radacct-key-user_stop | /db/tokudb/data/_radius_radacct_key_user_stop_17a78a50_3_1d_B_0.tokudb | 89 | 89 | 66537472 | 54097492 | radius | radacct | key-user_stop |
| ./radius/radacct-key-user_stop_start_ip | /db/tokudb/data/_radius_radacct_key_user_stop_start_ip_17a7b0ce_3_1d_B_0.tokudb | 128 | 128 | 100743680 | 86226041 | radius | radacct | key-user_stop_start_ip |
| ./radius/radacct-main | /db/tokudb/data/_radius_sql_5600_2b_main_a6_2_1b.tokudb | 3674 | 1590 | 689671168 | 615507994 | radius | radacct | main |
| ./radius/radacct-status | /db/tokudb/data/_radius_sql_5600_2b_status_a6_1_1b.tokudb | 11 | 9 | 41472 | 4096 | radius | radacct | status |
SHOW INDEX output: please note row count already differs a bit: the table is very active on writes (append mostly, major deletes sometimes)
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
| radacct | 0 | PRIMARY | 1 | RadAcctId | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | UserName | 1 | UserName | A | 47484 | NULL | NULL | BTREE | |||
| radacct | 1 | FramedIPAddress | 1 | FramedIPAddress | A | 47830 | NULL | NULL | BTREE | |||
| radacct | 1 | AcctUniqueId | 1 | AcctUniqueId | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | AcctSessionId | 1 | AcctSessionId | A | 6552804 | NULL | NULL | YES | BTREE | ||
| radacct | 1 | AcctStartTime | 1 | AcctStartTime | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | AcctStopTime | 1 | AcctStopTime | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | CallingStationId | 1 | CallingStationId | A | 50406 | NULL | NULL | BTREE | |||
| radacct | 1 | RadCheckProductID | 1 | ProductID | A | 1 | NULL | NULL | YES | BTREE | ||
| radacct | 1 | LastUpdated | 1 | LastUpdated | A | 6552804 | NULL | NULL | YES | BTREE | ||
| radacct | 1 | AcctStartTime_AcctUniqueId | 1 | AcctStartTime | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | AcctStartTime_AcctUniqueId | 2 | AcctUniqueId | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | user_start_stop_ip | 1 | UserName | A | 47484 | NULL | NULL | BTREE | |||
| radacct | 1 | user_start_stop_ip | 2 | AcctStartTime | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | user_start_stop_ip | 3 | AcctStopTime | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | user_start_stop_ip | 4 | FramedIPAddress | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop | 1 | UserName | A | 47484 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop | 2 | AcctStopTime | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop_start_ip | 1 | UserName | A | 47484 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop_start_ip | 2 | AcctStopTime | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop_start_ip | 3 | AcctStartTime | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | user_stop_start_ip | 4 | FramedIPAddress | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | updates | 1 | UserName | A | 47484 | NULL | NULL | BTREE | |||
| radacct | 1 | updates | 2 | NASIPAddress | A | 48182 | NULL | NULL | BTREE | |||
| radacct | 1 | updates | 3 | AcctSessionId | A | 6552804 | NULL | NULL | YES | BTREE | ||
| radacct | 1 | stale | 1 | AcctStopTime | A | 6552804 | NULL | NULL | BTREE | |||
| radacct | 1 | stale | 2 | LastUpdated | A | 6552804 | NULL | NULL | YES | BTREE | ||
| radacct | 1 | NASIPAddress | 1 | NASIPAddress | A | 25 | NULL | NULL | BTREE |
The query is:
analyze format=json UPDATE `radacct` SET `acctsessiontime` = 10853, `acctinputoctets` = 9394240, `acctinputoctets64` = 0<<32|9394240, `acctinputgigawords` = 0>>32, `acctoutputoctets` = 385664891, `acctoutputoctets64` = 0<<32|385664891, `acctoutputgigawords` = 0>>32, `framedipaddress` = '<IP>', `lastupdated` = NOW() WHERE (`acctsessionid` = '<long string>') AND (`username` = '<small string>') AND (`nasipaddress` = '<IP>'); |
Some values were hidden as <...> because of being user-specific information, but they does not matter. There is multitude of such queries and the worst thing query plan seemingly varies as random for them even for a single query.
ANALYZE with a seemingly weird query plan (now it uses intersect with unnecessary secondary index given 100% encompassed match):
{
|
"query_block": {
|
"select_id": 1,
|
"r_total_time_ms": 0.509,
|
"table": {
|
"update": 1,
|
"table_name": "radacct",
|
"access_type": "index_merge",
|
"possible_keys": [
|
"UserName",
|
"AcctSessionId",
|
"user_start_stop_ip",
|
"user_stop",
|
"user_stop_start_ip",
|
"updates",
|
"NASIPAddress"
|
],
|
"index_merge": {
|
"intersect": {
|
"range": {
|
"key": "AcctSessionId",
|
"used_key_parts": ["AcctSessionId"]
|
},
|
"range": {
|
"key": "updates",
|
"used_key_parts": ["UserName", "NASIPAddress", "AcctSessionId"]
|
}
|
}
|
},
|
"rows": 1,
|
"r_rows": 1,
|
"r_filtered": 100,
|
"r_total_time_ms": 0.2273,
|
"attached_condition": "((radacct.AcctSessionId = '<long string>') and (radacct.UserName = '<small string>') and (radacct.NASIPAddress = '<IP>'))"
|
}
|
}
|
}
|
For now it just intersects with AcctSessionId, that's ok and fast. But when it starts intersecting with i.e. UserName or NASIPAddress, things start looking grim: full scan for each update.
Even just using AcctSessionId without any intersection would be much better because it's almost unique. But this is still wrong nevertheless. Also, it strangely tries to intersect key with another key fully containing that first one key.
And as said (well, better to repeat myself here): query plans are random. Once it's AcctSessionId, it's ok. But when it's suddenly some other index... well, it starts crawling: doing 50-100 full scans per second is tad too much.
Expected query plan: I've added FORCE INDEX (`updates`) to force the proper index:
{
|
"query_block": {
|
"select_id": 1,
|
"r_total_time_ms": 0.3426,
|
"table": {
|
"update": 1,
|
"table_name": "radacct",
|
"access_type": "range",
|
"possible_keys": ["updates"],
|
"key": "updates",
|
"key_length": "150",
|
"used_key_parts": ["UserName", "NASIPAddress", "AcctSessionId"],
|
"rows": 1,
|
"r_rows": 1,
|
"r_filtered": 100,
|
"r_total_time_ms": 0.2908,
|
"attached_condition": "((radacct.AcctSessionId = '<long string>') and (radacct.UserName = '<small string>') and (radacct.NASIPAddress = '<IP>'))"
|
}
|
}
|
}
|
This results in much simpler plan. Shouldn't it be ref type query? The key is not unique, but nevertheless it's full ref.
The least possible repeatable case I found is:
CREATE TABLE `radacct_test` ( |
`RadAcctId` bigint(21) NOT NULL AUTO_INCREMENT, |
`AcctSessionId` varchar(64) DEFAULT NULL, |
`AcctUniqueId` varchar(32) NOT NULL DEFAULT '', |
`UserName` varchar(64) NOT NULL DEFAULT '', |
`Realm` varchar(64) DEFAULT '', |
`NASIPAddress` varchar(15) NOT NULL DEFAULT '', |
`NASPort` int(12) DEFAULT NULL, |
`NASPortId` char(32) DEFAULT '0', |
`NASPortType` varchar(32) DEFAULT NULL, |
`AcctStartTime` datetime NOT NULL DEFAULT '0000-00-00 00:00:00', |
`AcctStopTime` datetime NOT NULL DEFAULT '0000-00-00 00:00:00', |
`AcctSessionTime` int(12) DEFAULT NULL, |
`AcctAuthentic` varchar(32) DEFAULT NULL, |
`ConnectInfo_start` varchar(32) DEFAULT NULL, |
`ConnectInfo_stop` varchar(32) DEFAULT NULL, |
`AcctInputOctets` bigint(12) DEFAULT NULL, |
`AcctOutputOctets` bigint(12) DEFAULT NULL, |
`CalledStationId` varchar(50) NOT NULL DEFAULT '', |
`CallingStationId` varchar(50) NOT NULL DEFAULT '', |
`AcctTerminateCause` varchar(32) NOT NULL DEFAULT '', |
`ServiceType` varchar(32) DEFAULT NULL, |
`FramedProtocol` varchar(32) DEFAULT NULL, |
`FramedIPAddress` varchar(15) NOT NULL DEFAULT '', |
`AcctStartDelay` int(12) DEFAULT NULL, |
`AcctStopDelay` int(12) DEFAULT NULL, |
`ProductID` bigint(20) DEFAULT NULL, |
`AcctInputGigawords` int(11) DEFAULT '0', |
`AcctOutputGigawords` int(11) DEFAULT '0', |
`AcctInputOctets64` char(18) DEFAULT '0', |
`AcctOutputOctets64` char(18) DEFAULT '0', |
`LastUpdated` datetime DEFAULT NULL, |
PRIMARY KEY (`RadAcctId`), |
KEY `UserName` (`UserName`), |
KEY `FramedIPAddress` (`FramedIPAddress`), |
KEY `AcctUniqueId` (`AcctUniqueId`), |
KEY `AcctSessionId` (`AcctSessionId`), |
KEY `AcctStartTime` (`AcctStartTime`), |
KEY `AcctStopTime` (`AcctStopTime`), |
KEY `CallingStationId` (`CallingStationId`), |
KEY `RadCheckProductID` (`ProductID`), |
KEY `LastUpdated` (`LastUpdated`), |
KEY `AcctStartTime_AcctUniqueId` (`AcctStartTime`,`AcctUniqueId`), |
KEY `user_start_stop_ip` (`UserName`,`AcctStartTime`,`AcctStopTime`,`FramedIPAddress`), |
KEY `user_stop` (`UserName`,`AcctStopTime`), |
KEY `user_stop_start_ip` (`UserName`,`AcctStopTime`,`AcctStartTime`,`FramedIPAddress`), |
KEY `updates` (`UserName`,`NASIPAddress`,`AcctSessionId`), |
KEY `stale` (`AcctStopTime`,`LastUpdated`), |
KEY `NASIPAddress` (`NASIPAddress`) |
) ENGINE=TokuDB DEFAULT CHARSET=latin1 `compression`='tokudb_zlib'; |
INSERT INTO `radacct_test` (`AcctSessionId`, `username`, `nasipaddress`) VALUES ('a', 'b', 'c'), ('d', 'e', 'c'); |
ANALYZE FORMAT=json UPDATE `radacct_test` SET `acctsessiontime` = 10990, `acctinputoctets` = 339842, `acctinputoctets64` = 0<<32|339842, |
`acctinputgigawords` = 0>>32, `acctoutputoctets` = 269650, `acctoutputoctets64` = 0<<32|269650, `acctoutputgigawords` = 0>>32,
|
`framedipaddress` = '1.2.3.4', `lastupdated` = NOW() |
WHERE (`acctsessionid` = 'd') AND (`username` = 'e') AND (`nasipaddress` = 'c'); |
ANALYZE FORMAT=json UPDATE `radacct_test` FORCE INDEX (`updates`) SET `acctsessiontime` = 10990, `acctinputoctets` = 339842, `acctinputoctets64` = 0<<32|339842, |
`acctinputgigawords` = 0>>32, `acctoutputoctets` = 269650, `acctoutputoctets64` = 0<<32|269650, `acctoutputgigawords` = 0>>32,
|
`framedipaddress` = '1.2.3.4', `lastupdated` = NOW() |
WHERE (`acctsessionid` = 'd') AND (`username` = 'e') AND (`nasipaddress` = 'c'); |
The query without FORCE INDEX uses intersect on `UserName` and `NASIPAddress` or `AcctSessionId` instead of ref to `updates`, and that's totally bad in case of huge table...
{
|
"query_block": {
|
"select_id": 1,
|
"r_total_time_ms": 0.3586,
|
"table": {
|
"update": 1,
|
"table_name": "radacct_test",
|
"access_type": "index_merge",
|
"possible_keys": [
|
"UserName",
|
"AcctSessionId",
|
"user_start_stop_ip",
|
"user_stop",
|
"user_stop_start_ip",
|
"updates",
|
"NASIPAddress"
|
],
|
"index_merge": {
|
"intersect": {
|
"range": {
|
"key": "UserName",
|
"used_key_parts": ["UserName"]
|
},
|
"range": {
|
"key": "AcctSessionId",
|
"used_key_parts": ["AcctSessionId"]
|
}
|
}
|
},
|
"rows": 1,
|
"r_rows": 1,
|
"r_filtered": 100,
|
"r_total_time_ms": 0.1465,
|
"attached_condition": "((radacct_test.AcctSessionId = 'd') and (radacct_test.UserName = 'e') and (radacct_test.NASIPAddress = 'c'))"
|
}
|
}
|
}
|
alex/at Maybe try that reproducer on Percona Server, then if it happens there too, log the issue in Percona's jira.
This requires me to build a completely separate test environment, but indeed I'll do.
alex/at Just FYI the reproducer seems to happen on 10.1.23 as well - which seems to contradict the idea it was introduced in 10.1.24.
Alex/AT Also FYI I randomly stumbled upon this old ticket that looks similar: https://jira.mariadb.org/browse/MDEV-6904
Phil Sweeney, Alex/AT, thanks a lot.
It looks like it is the same bug as MDEV-6904, reproducible with TokuDB and InnoDB, not with myisam on MariaDB 5.5-10.3
a little bit simplified testcase:
CREATE TABLE t1 ( |
acc varchar(64) DEFAULT NULL, nm varchar(64), a1 varchar(15), u datetime DEFAULT NULL, |
KEY (nm), |
KEY (acc), |
KEY ind3 (nm,a1,acc), |
KEY (a1)) ENGINE=TokuDB ; |
|
|
INSERT INTO t1 (acc, nm, a1) VALUES ('a', 'b', 'c'), ('d', 'e', 'c'); |
|
|
EXPLAIN UPDATE t1 SET u = NOW() WHERE (acc = 'd') AND (nm = 'e') AND (a1 = 'c'); |
EXPLAIN UPDATE t1 FORCE INDEX (ind3) SET u = NOW() WHERE (acc = 'd') AND (nm = 'e') AND (a1 = 'c'); |
--------------
|
EXPLAIN UPDATE t1 SET u = NOW() WHERE (acc = 'd') AND (nm = 'e') AND (a1 = 'c')
|
--------------
|
+------+-------------+-------+-------------+----------------+--------+---------+------+------+--------------------------------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+-------------+----------------+--------+---------+------+------+--------------------------------------+
|
| 1 | SIMPLE | t1 | index_merge | nm,acc,ind3,a1 | nm,acc | 67,67 | NULL | 1 | Using intersect(nm,acc); Using where |
|
+------+-------------+-------+-------------+----------------+--------+---------+------+------+--------------------------------------+
|
1 row in set (0.00 sec)
|
|
|
--------------
|
EXPLAIN UPDATE t1 FORCE INDEX (ind3) SET u = NOW() WHERE (acc = 'd') AND (nm = 'e') AND (a1 = 'c')
|
--------------
|
+------+-------------+-------+-------+---------------+------+---------+------+------+-------------+
|
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
|
+------+-------------+-------+-------+---------------+------+---------+------+------+-------------+
|
| 1 | SIMPLE | t1 | range | ind3 | ind3 | 152 | NULL | 1 | Using where |
|
+------+-------------+-------+-------+---------------+------+---------+------+------+-------------+
|
1 row in set (0.00 sec)
|
|
|
--------------
|
ANALYZE FORMAT=json UPDATE t1 SET u = NOW() WHERE (acc = 'd') AND (nm = 'e') AND (a1 = 'c')
|
--------------
|
{
|
"query_block": {
|
"select_id": 1,
|
"r_total_time_ms": 0.3286,
|
"table": {
|
"update": 1,
|
"table_name": "t1",
|
"access_type": "index_merge",
|
"possible_keys": ["nm", "acc", "ind3", "a1"],
|
"index_merge": {
|
"intersect": {
|
"range": {
|
"key": "nm",
|
"used_key_parts": ["nm"]
|
},
|
"range": {
|
"key": "acc",
|
"used_key_parts": ["acc"]
|
}
|
}
|
},
|
"rows": 1,
|
"r_rows": 1,
|
"r_filtered": 100,
|
"r_total_time_ms": 0.0657,
|
"attached_condition": "((t1.acc = 'd') and (t1.nm = 'e') and (t1.a1 = 'c'))"
|
}
|
}
|
}
|
1 row in set (0.07 sec)
|
|
|
--------------
|
ANALYZE FORMAT=json UPDATE t1 FORCE INDEX (ind3) SET u = NOW() WHERE (acc = 'd') AND (nm = 'e') AND (a1 = 'c')
|
--------------
|
{
|
"query_block": {
|
"select_id": 1,
|
"r_total_time_ms": 0.0577,
|
"table": {
|
"update": 1,
|
"table_name": "t1",
|
"access_type": "range",
|
"possible_keys": ["ind3"],
|
"key": "ind3",
|
"key_length": "152",
|
"used_key_parts": ["nm", "a1", "acc"],
|
"rows": 1,
|
"r_rows": 1,
|
"r_filtered": 100,
|
"r_total_time_ms": 0.0266,
|
"attached_condition": "((t1.acc = 'd') and (t1.nm = 'e') and (t1.a1 = 'c'))"
|
}
|
}
|
}
|
1 row in set (0.00 sec)
|
|
Bump. Still relevant.