TokuDB: strange lock timeouts with infinity range

[Rick Pizzi]

We are experiencing strange lock timeouts where the range of the lock seems to go from minus infinity to plus infinity.

From log file:

2017-02-16 11:35:25 22994 [ERROR] TokuDB: lock timeout {"mysql_thread_id":699323, "dbname":"./myschema/BIG_STORAGE_07#P#p1837-main", "requesting_txnid":43317918344, "blocking_txnid":43317916654, "key_left":"-infinity", "key_right":"+infinity"}
2017-02-16 11:35:25 22994 [ERROR] TokuDB: requesting_thread_id:699323 q:DELETE FROM BIG_STORAGE_07 WHERE HASH_ID = '0a168c966bc965ad2397061ba169195db463d093656c0ad1ea38e870f4896b8f' AND EXPIRE_DATE > NOW()

Table structure is as follow:

CREATE TABLE `BIG_STORAGE_07` (
  `HASH_ID` char(64) NOT NULL,
  `SERIALIZATION_TYPE` enum('JAVA','PROTOSTUFF') NOT NULL,
  `COMPRESSION_TYPE` enum('DEFLATE','LZ4','NONE','GZIP') NOT NULL,
  `RAW_DATA` mediumblob NOT NULL,
  `LAST_UPDATE` datetime NOT NULL,
  `EXPIRE_DATE` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  KEY `EXPIRE_DATE_IX` (`EXPIRE_DATE`),
  KEY `HASH_ID` (`HASH_ID`)
) ENGINE=TokuDB DEFAULT CHARSET=latin1 ROW_FORMAT=TOKUDB_UNCOMPRESSED
/*!50100 PARTITION BY RANGE (UNIX_TIMESTAMP(EXPIRE_DATE))
(PARTITION p1861 VALUES LESS THAN (1487329200) ENGINE = TokuDB,
 PARTITION p1862 VALUES LESS THAN (1487332800) ENGINE = TokuDB,
 PARTITION p1863 VALUES LESS THAN (1487336400) ENGINE = TokuDB,
 PARTITION p1864 VALUES LESS THAN (1487340000) ENGINE = TokuDB,
 PARTITION p1865 VALUES LESS THAN (1487343600) ENGINE = TokuDB,
 PARTITION p1866 VALUES LESS THAN (1487347200) ENGINE = TokuDB,
 PARTITION p1867 VALUES LESS THAN (1487350800) ENGINE = TokuDB,
 PARTITION p1868 VALUES LESS THAN (1487354400) ENGINE = TokuDB,
 PARTITION p1869 VALUES LESS THAN (1487358000) ENGINE = TokuDB,
 PARTITION p1870 VALUES LESS THAN (1487361600) ENGINE = TokuDB,
 PARTITION p1871 VALUES LESS THAN (1487365200) ENGINE = TokuDB,
 PARTITION p1872 VALUES LESS THAN (1487368800) ENGINE = TokuDB,
 PARTITION p1873 VALUES LESS THAN (1487372400) ENGINE = TokuDB,
 PARTITION p1874 VALUES LESS THAN (1487376000) ENGINE = TokuDB,
 PARTITION p1875 VALUES LESS THAN (1487379600) ENGINE = TokuDB,
 PARTITION p1876 VALUES LESS THAN (1487383200) ENGINE = TokuDB,
 PARTITION p1877 VALUES LESS THAN (1487386800) ENGINE = TokuDB,
 PARTITION p1878 VALUES LESS THAN (1487390400) ENGINE = TokuDB,
 PARTITION p1879 VALUES LESS THAN (1487394000) ENGINE = TokuDB,
 PARTITION p1880 VALUES LESS THAN (1487397600) ENGINE = TokuDB,
 PARTITION p1881 VALUES LESS THAN (1487401200) ENGINE = TokuDB,
 PARTITION p1882 VALUES LESS THAN (1487404800) ENGINE = TokuDB,
 PARTITION p1883 VALUES LESS THAN (1487408400) ENGINE = TokuDB,
 PARTITION p1884 VALUES LESS THAN (1487412000) ENGINE = TokuDB,
 PARTITION p1885 VALUES LESS THAN (1487415600) ENGINE = TokuDB,
 PARTITION p1886 VALUES LESS THAN (1487419200) ENGINE = TokuDB,
 PARTITION p1887 VALUES LESS THAN (1487422800) ENGINE = TokuDB,
 PARTITION p1888 VALUES LESS THAN (1487426400) ENGINE = TokuDB,
 PARTITION p1889 VALUES LESS THAN (1487430000) ENGINE = TokuDB,
 PARTITION p1890 VALUES LESS THAN (1487433600) ENGINE = TokuDB,
 PARTITION p1891 VALUES LESS THAN (1487437200) ENGINE = TokuDB,
 PARTITION p1892 VALUES LESS THAN (1487440800) ENGINE = TokuDB,
 PARTITION p1893 VALUES LESS THAN (1487444400) ENGINE = TokuDB,
 PARTITION p1894 VALUES LESS THAN (1487448000) ENGINE = TokuDB,
 PARTITION p1895 VALUES LESS THAN (1487451600) ENGINE = TokuDB,
 PARTITION p1896 VALUES LESS THAN (1487455200) ENGINE = TokuDB,
 PARTITION p1897 VALUES LESS THAN (1487458800) ENGINE = TokuDB,
 PARTITION p1898 VALUES LESS THAN (1487462400) ENGINE = TokuDB,
 PARTITION p1899 VALUES LESS THAN (1487466000) ENGINE = TokuDB,
 PARTITION p1900 VALUES LESS THAN (1487469600) ENGINE = TokuDB,
 PARTITION p1901 VALUES LESS THAN (1487473200) ENGINE = TokuDB,
 PARTITION p1902 VALUES LESS THAN (1487476800) ENGINE = TokuDB,
 PARTITION p1903 VALUES LESS THAN (1487480400) ENGINE = TokuDB,
 PARTITION p1904 VALUES LESS THAN (1487484000) ENGINE = TokuDB,
 PARTITION p1905 VALUES LESS THAN (1487487600) ENGINE = TokuDB,
 PARTITION p1906 VALUES LESS THAN (1487491200) ENGINE = TokuDB,
 PARTITION p1907 VALUES LESS THAN (1487494800) ENGINE = TokuDB,
 PARTITION p1908 VALUES LESS THAN (1487498400) ENGINE = TokuDB,
 PARTITION p1909 VALUES LESS THAN (1487502000) ENGINE = TokuDB,
 PARTITION p1910 VALUES LESS THAN (1487505600) ENGINE = TokuDB,
 PARTITION p1911 VALUES LESS THAN (1487509200) ENGINE = TokuDB,
 PARTITION p1912 VALUES LESS THAN (1487512800) ENGINE = TokuDB,
 PARTITION p1913 VALUES LESS THAN (1487516400) ENGINE = TokuDB,
 PARTITION p1914 VALUES LESS THAN (1487520000) ENGINE = TokuDB,
 PARTITION p1915 VALUES LESS THAN (1487523600) ENGINE = TokuDB,
 PARTITION p1916 VALUES LESS THAN (1487527200) ENGINE = TokuDB,
 PARTITION p1917 VALUES LESS THAN (1487530800) ENGINE = TokuDB,
 PARTITION p1918 VALUES LESS THAN (1487534400) ENGINE = TokuDB,
 PARTITION p1919 VALUES LESS THAN (1487538000) ENGINE = TokuDB,
 PARTITION p1920 VALUES LESS THAN (1487541600) ENGINE = TokuDB,
 PARTITION p1921 VALUES LESS THAN (1487545200) ENGINE = TokuDB,
 PARTITION p1922 VALUES LESS THAN (1487548800) ENGINE = TokuDB,
 PARTITION p1923 VALUES LESS THAN (1487552400) ENGINE = TokuDB,
 PARTITION p1924 VALUES LESS THAN (1487556000) ENGINE = TokuDB,
 PARTITION p1925 VALUES LESS THAN (1487559600) ENGINE = TokuDB,
 PARTITION p1926 VALUES LESS THAN (1487563200) ENGINE = TokuDB,
 PARTITION p1927 VALUES LESS THAN (1487566800) ENGINE = TokuDB,
 PARTITION p1928 VALUES LESS THAN (1487570400) ENGINE = TokuDB) */
1 row in set (0.01 sec)

This table is missing the primary key by purpose. HASH_ID uniqueness is enforced at application level and besides, we always DELETE by HASH_ID before inserting.
We add a check on the EXPIRE_DATE when DELETING to avoid scanning stale partitions (i.e. for pruning).

Number of selects on this table is negligible. There are no UPDATEs, only INSERTs and DELETEs.

The locks above puzzle me. Why is a lock range like that being taken?

Server version: 5.6.35-80.0-log Percona Server (GPL), Release 80.0, Revision f113994f31

Thanks
Rick

[George Ormond Lorch III (gl-az)]

I suspect this is because of the missing PK. The delete is likely turning into a full table scan on the partition(s) within the range and thus requiring full read locks on those partitions.

You can try enabling the tokudb_lock_wait_timeout_debug https://www.percona.com/doc/percona-server/5.6/tokudb/tokudb_variables.html#tokudb_lock_timeout_debug and parsing the result as it should give you some idea of the conflicting locker.

[Rick Pizzi (pizzi)]

Thanks for your reply.
I have that enabled, this is where the log extract part above comes from.

Besides, if I run an explain partitions, everything looks good.
I only have these lock timeouts every now and then (on a server which is pretty busy).
The index seems to work just fine in our use case...

dbcache01>explain partitions DELETE FROM BIG_STORAGE_04 WHERE HASH_ID = 'ffe12c881315985fad3398999ac7be789dbcacb4df13bc0ac0cfd93fd3fdf854' AND EXPIRE_DATE > NOW()\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: BIG_STORAGE_04
   partitions: p1866,p1867,p1868,p1869,p1870,p1871,p1872,p1873,p1874,p1875,p1876,p1877,p1878,p1879,p1880,p1881,p1882,p1883,p1884,p1885,p1886,p1887,p1888,p1889,p1890,p1891,p1892,p1893,p1894,p1895,p1896,p1897,p1898,p1899,p1900,p1901,p1902,p1903,p1904,p1905,p1906,p1907,p1908,p1909,p1910,p1911,p1912,p1913,p1914,p1915,p1916,p1917,p1918,p1919,p1920,p1921,p1922,p1923,p1924,p1925,p1926,p1927,p1928
         type: range
possible_keys: EXPIRE_DATE_IX,HASH_ID
          key: HASH_ID
      key_len: 64
          ref: const
         rows: 1
        Extra: Using where
1 row in set (0.00 sec)

[Rick Pizzi (pizzi)]

Found out that these lock timeout only come out when we do a table swap by using something like:

RENAME TABLE t to t_old, t_new to t

2017-02-23 11:58:50 10765 [ERROR] TokuDB: lock timeout {"mysql_thread_id":347, "dbname":"./myschema/t#P#p2005-main", "requesting_txnid":44691136368, "blocking_txnid":44691134099, "key_left":"-infinity", "key_right":"+infinity"}
2017-02-23 11:58:50 10765 [ERROR] TokuDB: requesting_thread_id:347 q:DELETE FROM t WHERE HASH_ID = 'ebbb033e95c68baac38b542df9761ad303e7d4652ce95cefb1f726bc80ce4bf3' AND EXPIRE_DATE > NOW()

Don't think these should be expected. For sure they don't happen when we do the same with InnoDB.

[Nickolay Ihalainen (ihanick)]

Hi Rick,
I've tried to reproduce this case and just getting delete statement executed for 20 seconds (200 partitions) without any messages inside error log.

If I trying to execute rename table, right after delete statement start, it's waiting for metadata lock, in opposite case delete statement awaits for rename to complete.

Are you running rename with similar sized tables?
Could you explain in which order delete and rename statements are executed?

Is possible to reproduce this issue just with delete and rename, e.g. running
BEGIN;
DELETE ....
ROLLBACK;
and executing rename in parallel without additional queries?

[Launchpad Janitor (janitor)]

[Expired for Percona Server because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3644