[MDEV-19552] DROP TABLE locks SHOW CREATE TABLE and SELECT with sorting since 10.1.34 Created: 2019-05-22  Updated: 2021-01-14  Resolved: 2021-01-14

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1.34
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Sergey Chernomorets Assignee: Marko Mäkelä
Resolution: Incomplete Votes: 2
Labels: need_feedback, regression

Attachments: HTML File vars    
Issue Links:
Relates
relates to MDEV-8069 DROP or rebuild of a large table may ... Closed

 Description   

After upgrade from 10.1.30 to 10.1.34 (10.1.40 affected too) we discovery that drop table locks many queries like 'show create table ....' on working server (15-25 Krps).
Drop of just created table works unexpected long for table about 250Krows, 80 Mb on server with SSD and big buffer pool (140Gb and 400Gb):

  • about 0.1 sec on empty 140G buffer pool (after start)
  • about 1 sec on full 140G buffer pool
  • about 3 sec on full 400G buffer pool

Script to reproduce:

#!/bin/bash                                                                              
                                                                                         
tmp=`mktemp`
 
tmp1=`mktemp`                                                                            
tmp2=`mktemp`                                                                            
                                                                                         
mysql -h server >$tmp <<EOF
 
use tmp;
 
drop table if exists sss1, sss2, sss3;
 
create table sss1 like  search.company_search_summary_table;                             
insert into sss1 select * from search.company_search_summary_table ;                     
EOF
 
                                                                                         
                                                                                         
(
 
mysql -t -h server >$tmp1 <<EOF                                                        
select "drop";
 
set profiling = 1;
 
drop table tmp.sss1;
 
show profile source;
 
status;                                                                                  
EOF
 
) &
 
    
(
 
mysql -t -h server >$tmp2  <<EOF                                                       
set profiling = 1;
 
show create table sys.date_time;                                                         
show profile source;
 
show create table sys.date_time;                                                         
show profile source;                                                                     
show create table sys.date_time;                                                         
show profile source;                                                                     
show create table sys.date_time;                                                         
show profile source;
 
status;
 
EOF
 
) &
 
 
 
wait
 
head -n400 $tmp $tmp1 $tmp2 
/bin/rm -f $tmp $tmp1 $tmp2

Output 

$ cat /tmp/aa
 
==> /tmp/tmp.Fn4nIpaTFj <==
 
 
 
==> /tmp/tmp.L9qGfzb24e <==
 
+------+
 
| drop |
 
+------+
 
| drop |
 
+------+
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| Status               | Duration | Source_function       | Source_file  | Source_line |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| starting             | 0.000035 | NULL                  | NULL         |        NULL |
 
| checking permissions | 0.000028 | check_access          | sql_parse.cc |        6154 |
 
| Opening tables       | 0.000039 | open_tables           | sql_base.cc  |        4532 |
 
| After opening tables | 0.000024 | open_tables           | sql_base.cc  |        4779 |
 
| System lock          | 0.000024 | mysql_lock_tables     | lock.cc      |         308 |
 
| Table lock           | 0.000066 | mysql_lock_tables     | lock.cc      |         313 |
 
| closing tables       | 0.000023 | close_thread_tables   | sql_base.cc  |         919 |
 
| Unlocking tables     | 1.101685 | mysql_unlock_tables   | lock.cc      |         396 |
 
| query end            | 0.000102 | mysql_execute_command | sql_parse.cc |        5706 |
 
| closing tables       | 0.000059 | close_thread_tables   | sql_base.cc  |         919 |
 
| freeing items        | 0.000050 | mysql_parse           | sql_parse.cc |        7466 |
 
| updating status      | 0.000062 | dispatch_command      | sql_parse.cc |        1954 |
 
| cleaning up          | 0.000049 | dispatch_command      | sql_parse.cc |        1973 |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
--------------
 
mysql  Ver 15.1 Distrib 10.1.37-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
 
 
 
Connection id:          3742891
 
Current database:
 
Current user:           user@10.10.8.36
 
SSL:                    Not in use
 
Current pager:          stdout
 
Using outfile:          ''
 
Using delimiter:        ;
 
Server:                 MariaDB
 
Server version:         10.1.34-MariaDB MariaDB Server
 
Protocol version:       10
 
Connection:             server via TCP/IP
 
Server characterset:    utf8
 
Db     characterset:    utf8
 
Client characterset:    utf8
 
Conn.  characterset:    utf8
 
TCP port:               3306
 
Uptime:                 42 min 35 sec
 
 
 
Threads: 688  Questions: 55997878  Slow queries: 0  Opens: 8070  Flush tables: 1  Open tables: 2033  Queries per second avg: 21916.977
 
--------------
 
 
 
 
 
==> /tmp/tmp.RX2wgWmf9w <==
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| Table     | Create Table                                                                                                                                                                                                |
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| date_time | CREATE TABLE `date_time` (
 
  `date` int(10) unsigned NOT NULL DEFAULT '0',
 
  `name` varchar(255) NOT NULL DEFAULT 'unknown',
 
  PRIMARY KEY (`name`)
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC |
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| Status               | Duration | Source_function       | Source_file  | Source_line |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| starting             | 0.000084 | NULL                  | NULL         |        NULL |
 
| checking permissions | 0.000041 | check_access          | sql_parse.cc |        6154 |
 
| Opening tables       | 0.000036 | open_tables           | sql_base.cc  |        4532 |
 
| After opening tables | 0.000044 | open_tables           | sql_base.cc  |        4779 |
 
| closing tables       | 0.000042 | close_thread_tables   | sql_base.cc  |         919 |
 
| query end            | 0.000025 | mysql_execute_command | sql_parse.cc |        5706 |
 
| closing tables       | 0.000024 | close_thread_tables   | sql_base.cc  |         919 |
 
| freeing items        | 0.000030 | mysql_parse           | sql_parse.cc |        7466 |
 
| updating status      | 0.000034 | dispatch_command      | sql_parse.cc |        1954 |
 
| cleaning up          | 0.000037 | dispatch_command      | sql_parse.cc |        1973 |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| Table     | Create Table                                                                                                                                                                                                |
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| date_time | CREATE TABLE `date_time` (
 
  `date` int(10) unsigned NOT NULL DEFAULT '0',
 
  `name` varchar(255) NOT NULL DEFAULT 'unknown',
 
  PRIMARY KEY (`name`)
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC |
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| Status               | Duration | Source_function       | Source_file  | Source_line |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| starting             | 0.000039 | NULL                  | NULL         |        NULL |
 
| checking permissions | 0.000025 | check_access          | sql_parse.cc |        6154 |
 
| Opening tables       | 0.000027 | open_tables           | sql_base.cc  |        4532 |
 
| After opening tables | 1.100046 | open_tables           | sql_base.cc  |        4779 |
 
| closing tables       | 0.000155 | close_thread_tables   | sql_base.cc  |         919 |
 
| query end            | 0.000103 | mysql_execute_command | sql_parse.cc |        5706 |
 
| closing tables       | 0.000060 | close_thread_tables   | sql_base.cc  |         919 |
 
| freeing items        | 0.000051 | mysql_parse           | sql_parse.cc |        7466 |
 
| updating status      | 0.000072 | dispatch_command      | sql_parse.cc |        1954 |
 
| cleaning up          | 0.000068 | dispatch_command      | sql_parse.cc |        1973 |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| Table     | Create Table                                                                                                                                                                                                |
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| date_time | CREATE TABLE `date_time` (
 
  `date` int(10) unsigned NOT NULL DEFAULT '0',
 
  `name` varchar(255) NOT NULL DEFAULT 'unknown',
 
  PRIMARY KEY (`name`)
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC |
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| Status               | Duration | Source_function       | Source_file  | Source_line |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| starting             | 0.000090 | NULL                  | NULL         |        NULL |
 
| checking permissions | 0.000047 | check_access          | sql_parse.cc |        6154 |
 
| Opening tables       | 0.000043 | open_tables           | sql_base.cc  |        4532 |
 
| After opening tables | 0.084826 | open_tables           | sql_base.cc  |        4779 |
 
| closing tables       | 0.000127 | close_thread_tables   | sql_base.cc  |         919 |
 
| query end            | 0.000054 | mysql_execute_command | sql_parse.cc |        5706 |
 
| closing tables       | 0.000041 | close_thread_tables   | sql_base.cc  |         919 |
 
| freeing items        | 0.000036 | mysql_parse           | sql_parse.cc |        7466 |
 
| updating status      | 0.000066 | dispatch_command      | sql_parse.cc |        1954 |
 
| cleaning up          | 0.000053 | dispatch_command      | sql_parse.cc |        1973 |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| Table     | Create Table                                                                                                                                                                                                |
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| date_time | CREATE TABLE `date_time` (
 
  `date` int(10) unsigned NOT NULL DEFAULT '0',
 
  `name` varchar(255) NOT NULL DEFAULT 'unknown',
 
  PRIMARY KEY (`name`)
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC |
 
+-----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| Status               | Duration | Source_function       | Source_file  | Source_line |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| starting             | 0.000356 | NULL                  | NULL         |        NULL |
 
| checking permissions | 0.000059 | check_access          | sql_parse.cc |        6154 |
 
| Opening tables       | 0.000050 | open_tables           | sql_base.cc  |        4532 |
 
| After opening tables | 0.000103 | open_tables           | sql_base.cc  |        4779 |
 
| closing tables       | 0.000048 | close_thread_tables   | sql_base.cc  |         919 |
 
| query end            | 0.000039 | mysql_execute_command | sql_parse.cc |        5706 |
 
| closing tables       | 0.000039 | close_thread_tables   | sql_base.cc  |         919 |
 
| freeing items        | 0.000043 | mysql_parse           | sql_parse.cc |        7466 |
 
| updating status      | 0.000054 | dispatch_command      | sql_parse.cc |        1954 |
 
| cleaning up          | 0.000050 | dispatch_command      | sql_parse.cc |        1973 |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
--------------
 
mysql  Ver 15.1 Distrib 10.1.37-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
 
 
 
Connection id:          3742892
 
Current database:
 
Current user:           user@10.10.8.36
 
SSL:                    Not in use
 
Current pager:          stdout
 
Using outfile:          ''
 
Using delimiter:        ;
 
Server:                 MariaDB
 
Server version:         10.1.34-MariaDB MariaDB Server
 
Protocol version:       10
 
Connection:             server via TCP/IP
 
Server characterset:    utf8
 
Db     characterset:    utf8
 
Client characterset:    utf8
 
Conn.  characterset:    utf8
 
TCP port:               3306
 
Uptime:                 42 min 35 sec
 
 
 
Threads: 462  Questions: 56002787  Slow queries: 0  Opens: 8070  Flush tables: 1  Open tables: 2033  Queries per second avg: 21918.899
 
--------------

One of 'show create' locks on 1 seconds (10.1.34-NN - files with results of serveral script calling):

# egrep 'After|unlock|Uptime'  10.1.34-*
 
10.1.34-82:| After opening tables | 0.000033 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-82:| Unlocking tables     | 1.117436 | mysql_unlock_tables   | lock.cc      |         396 |
 
10.1.34-82:Uptime:                      41 min 35 sec
 
10.1.34-82:| After opening tables | 0.000035 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-82:| After opening tables | 0.000029 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-82:| After opening tables | 0.000051 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-82:| After opening tables | 1.113856 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-82:Uptime:                      41 min 35 sec
 
 
 
10.1.34-83:| After opening tables | 0.000039 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-83:| Unlocking tables     | 1.100278 | mysql_unlock_tables   | lock.cc      |         396 |
 
10.1.34-83:Uptime:                      42 min 5 sec
 
10.1.34-83:| After opening tables | 1.098836 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-83:| After opening tables | 0.089455 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-83:| After opening tables | 0.000078 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-83:| After opening tables | 0.000076 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-83:Uptime:                      42 min 5 sec
 
 
 
10.1.34-84:| After opening tables | 0.000024 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-84:| Unlocking tables     | 1.101685 | mysql_unlock_tables   | lock.cc      |         396 |
 
10.1.34-84:Uptime:                      42 min 35 sec
 
10.1.34-84:| After opening tables | 0.000044 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-84:| After opening tables | 1.100046 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-84:| After opening tables | 0.084826 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-84:| After opening tables | 0.000103 | open_tables           | sql_base.cc  |        4779 |
 
10.1.34-84:Uptime:                      42 min 35 sec

On version 10.1.33 max time not so high:

10.1.33-96:| After opening tables | 0.000024 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-96:| Unlocking tables     | 0.131976 | mysql_unlock_tables   | lock.cc      |         396 |
 
10.1.33-96:Uptime:                      49 min 35 sec
 
10.1.33-96:| After opening tables | 0.000038 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-96:| After opening tables | 0.032584 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-96:| After opening tables | 0.000044 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-96:| After opening tables | 0.000038 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-96:Uptime:                      49 min 34 sec
 
10.1.33-97:| After opening tables | 0.000022 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-97:| Unlocking tables     | 0.035330 | mysql_unlock_tables   | lock.cc      |         396 |
 
10.1.33-97:Uptime:                      50 min 1 sec
 
10.1.33-97:| After opening tables | 0.000051 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-97:| After opening tables | 0.027047 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-97:| After opening tables | 0.000030 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-97:| After opening tables | 0.000044 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-97:Uptime:                      50 min 1 sec
 
10.1.33-98:| After opening tables | 0.000023 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-98:| Unlocking tables     | 0.141847 | mysql_unlock_tables   | lock.cc      |         396 |
 
10.1.33-98:Uptime:                      50 min 27 sec
 
10.1.33-98:| After opening tables | 0.000040 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-98:| After opening tables | 0.031896 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-98:| After opening tables | 0.000036 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-98:| After opening tables | 0.000063 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-98:Uptime:                      50 min 27 sec
 
10.1.33-99:| After opening tables | 0.000041 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-99:| Unlocking tables     | 0.042536 | mysql_unlock_tables   | lock.cc      |         396 |
 
10.1.33-99:Uptime:                      50 min 54 sec
 
10.1.33-99:| After opening tables | 0.000045 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-99:| After opening tables | 0.000040 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-99:| After opening tables | 0.000039 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-99:| After opening tables | 0.000033 | open_tables           | sql_base.cc  |        4769 |
 
10.1.33-99:Uptime:                      50 min 55 sec


MariaDB [search]> show table status like 'company_search_summary_table'\G
 
*************************** 1. row ***************************
 
           Name: company_search_summary_table
 
         Engine: InnoDB
 
        Version: 10
 
     Row_format: Compact
 
           Rows: 267016
 
 Avg_row_length: 332
 
    Data_length: 88719360
 
Max_data_length: 0
 
   Index_length: 0
 
      Data_free: 6291456
 
 Auto_increment: NULL
 
    Create_time: 2019-05-22 16:21:40
 
    Update_time: NULL
 
     Check_time: NULL
 
      Collation: utf8_general_ci
 
       Checksum: NULL
 
 Create_options: 
        Comment:

This server has 140G buffer pool, on out main server with buffer pool 400G locks duration more than 3 seconds.

 Comments   
Comment by Sergey Chernomorets [ 2019-05-23 ]

Locks reproduces also without others queries when buffer pool is full.

Comment by Sergey Chernomorets [ 2019-05-23 ]

Selects locks on stage "Sorting result" (10.1.40) and "Creating sort index" (10.3.15).

Script and results for 10.1.40:

$ cat test3.sh 
#!/bin/bash
 
 
 
tmp=`mktemp`
 
tmp1=`mktemp`
 
tmp2=`mktemp`
 
 
 
mysql -h sphinx11 >$tmp <<EOF
 
use tmp;
 
drop table if exists sss1, sss2, sss3;
 
create table sss1 like  search.company_search_summary_table;
 
insert into sss1 select * from search.company_search_summary_table ;
 
create table sss2 like  search.company_search_summary_table;
 
insert into sss2 select * from search.company_search_summary_table ;
 
create table sss3 like  search.company_search_summary_table;
 
insert into sss3 select * from search.company_search_summary_table ;
 
 
 
EOF
 
 
 
 
 
(
 
mysql -t -h server >$tmp1 <<EOF
 
select "drop";
 
set profiling = 1;
 
drop table tmp.sss1;
 
show profile source;
 
drop table tmp.sss2;
 
show profile source;
 
drop table tmp.sss3;
 
show profile source;
 
EOF
 
) &
 
 
 
(
 
mysql -t -h server >$tmp2  <<EOF
 
set profiling = 1;
 
SELECT * FROM hr.received_resume_event WHERE id_client = '3561906' AND id_resume = '20310224' ORDER BY date_event DESC, type DESC;
 
show profile source;
 
SELECT * FROM hr.received_resume_event WHERE id_client = '3561906' AND id_resume = '20310224' ORDER BY date_event DESC, type DESC;
 
show profile source;
 
SELECT * FROM hr.received_resume_event WHERE id_client = '3561906' AND id_resume = '20310224' ORDER BY date_event DESC, type DESC;
 
show profile source;
 
SELECT * FROM hr.received_resume_event WHERE id_client = '3561906' AND id_resume = '20310224' ORDER BY date_event DESC, type DESC;
 
show profile source;
 
EOF
 
) &
 
 
 
wait
 
 
 
head -n400 $tmp $tmp1 $tmp2 
 
 
/bin/rm -f $tmp $tmp1 $tmp2


$ ./test3.sh   
==> /tmp/tmp.1iSoNU8upy <==
 
 
 
==> /tmp/tmp.aB2mOXs15i <==
 
+------+
 
| drop |
 
+------+
 
| drop |
 
+------+
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| Status               | Duration | Source_function       | Source_file  | Source_line |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| starting             | 0.000035 | NULL                  | NULL         |        NULL |
 
| checking permissions | 0.000017 | check_access          | sql_parse.cc |        6161 |
 
| Opening tables       | 0.000036 | open_tables           | sql_base.cc  |        4579 |
 
| After opening tables | 0.000014 | open_tables           | sql_base.cc  |        4827 |
 
| System lock          | 0.000014 | mysql_lock_tables     | lock.cc      |         308 |
 
| Table lock           | 0.000067 | mysql_lock_tables     | lock.cc      |         313 |
 
| closing tables       | 0.000010 | close_thread_tables   | sql_base.cc  |         921 |
 
| Unlocking tables     | 0.989668 | mysql_unlock_tables   | lock.cc      |         396 |
 
| query end            | 0.000024 | mysql_execute_command | sql_parse.cc |        5712 |
 
| closing tables       | 0.000020 | close_thread_tables   | sql_base.cc  |         921 |
 
| freeing items        | 0.000011 | mysql_parse           | sql_parse.cc |        7486 |
 
| updating status      | 0.000024 | dispatch_command      | sql_parse.cc |        1961 |
 
| cleaning up          | 0.000018 | dispatch_command      | sql_parse.cc |        1980 |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| Status               | Duration | Source_function       | Source_file  | Source_line |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| starting             | 0.000049 | NULL                  | NULL         |        NULL |
 
| checking permissions | 0.000027 | check_access          | sql_parse.cc |        6161 |
 
| Opening tables       | 0.000057 | open_tables           | sql_base.cc  |        4579 |
 
| After opening tables | 0.000026 | open_tables           | sql_base.cc  |        4827 |
 
| System lock          | 0.000025 | mysql_lock_tables     | lock.cc      |         308 |
 
| Table lock           | 0.000101 | mysql_lock_tables     | lock.cc      |         313 |
 
| closing tables       | 0.000027 | close_thread_tables   | sql_base.cc  |         921 |
 
| Unlocking tables     | 0.994154 | mysql_unlock_tables   | lock.cc      |         396 |
 
| query end            | 0.000023 | mysql_execute_command | sql_parse.cc |        5712 |
 
| closing tables       | 0.000019 | close_thread_tables   | sql_base.cc  |         921 |
 
| freeing items        | 0.000010 | mysql_parse           | sql_parse.cc |        7486 |
 
| updating status      | 0.000026 | dispatch_command      | sql_parse.cc |        1961 |
 
| cleaning up          | 0.000017 | dispatch_command      | sql_parse.cc |        1980 |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| Status               | Duration | Source_function       | Source_file  | Source_line |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
| starting             | 0.000092 | NULL                  | NULL         |        NULL |
 
| checking permissions | 0.000033 | check_access          | sql_parse.cc |        6161 |
 
| Opening tables       | 0.000078 | open_tables           | sql_base.cc  |        4579 |
 
| After opening tables | 0.000017 | open_tables           | sql_base.cc  |        4827 |
 
| System lock          | 0.000019 | mysql_lock_tables     | lock.cc      |         308 |
 
| Table lock           | 0.000071 | mysql_lock_tables     | lock.cc      |         313 |
 
| closing tables       | 0.000011 | close_thread_tables   | sql_base.cc  |         921 |
 
| Unlocking tables     | 0.996784 | mysql_unlock_tables   | lock.cc      |         396 |
 
| query end            | 0.000023 | mysql_execute_command | sql_parse.cc |        5712 |
 
| closing tables       | 0.000014 | close_thread_tables   | sql_base.cc  |         921 |
 
| freeing items        | 0.000011 | mysql_parse           | sql_parse.cc |        7486 |
 
| updating status      | 0.000027 | dispatch_command      | sql_parse.cc |        1961 |
 
| cleaning up          | 0.000019 | dispatch_command      | sql_parse.cc |        1980 |
 
+----------------------+----------+-----------------------+--------------+-------------+
 
--------------

selects:

==> /tmp/tmp.o34IJkjum4 <==
 
+----------------------+----------+-----------------------+---------------+-------------+
 
| Status               | Duration | Source_function       | Source_file   | Source_line |
 
+----------------------+----------+-----------------------+---------------+-------------+
 
| starting             | 0.000117 | NULL                  | NULL          |        NULL |
 
| checking permissions | 0.000035 | check_access          | sql_parse.cc  |        6161 |
 
| Opening tables       | 0.000049 | open_tables           | sql_base.cc   |        4579 |
 
| After opening tables | 0.000026 | open_tables           | sql_base.cc   |        4827 |
 
| System lock          | 0.000025 | mysql_lock_tables     | lock.cc       |         308 |
 
| Table lock           | 0.000027 | mysql_lock_tables     | lock.cc       |         313 |
 
| init                 | 0.000053 | mysql_select          | sql_select.cc |        3475 |
 
| optimizing           | 0.000040 | optimize_inner        | sql_select.cc |        1097 |
 
| statistics           | 0.000099 | optimize_inner        | sql_select.cc |        1402 |
 
| preparing            | 0.000022 | optimize_inner        | sql_select.cc |        1427 |
 
| executing            | 0.000011 | exec_inner            | sql_select.cc |        2595 |
 
| Sorting result       | 0.000169 | exec_inner            | sql_select.cc |        3112 |
 
| Sending data         | 0.000032 | exec_inner            | sql_select.cc |        3270 |
 
| end                  | 0.000012 | mysql_select          | sql_select.cc |        3510 |
 
| query end            | 0.000011 | mysql_execute_command | sql_parse.cc  |        5712 |
 
| closing tables       | 0.000010 | close_thread_tables   | sql_base.cc   |         921 |
 
| Unlocking tables     | 0.000012 | mysql_unlock_tables   | lock.cc       |         396 |
 
| freeing items        | 0.000011 | mysql_parse           | sql_parse.cc  |        7486 |
 
| updating status      | 0.000023 | dispatch_command      | sql_parse.cc  |        1961 |
 
| cleaning up          | 0.000016 | dispatch_command      | sql_parse.cc  |        1980 |
 
+----------------------+----------+-----------------------+---------------+-------------+
 
+----------------------+----------+-----------------------+---------------+-------------+
 
| Status               | Duration | Source_function       | Source_file   | Source_line |
 
+----------------------+----------+-----------------------+---------------+-------------+
 
| starting             | 0.000035 | NULL                  | NULL          |        NULL |
 
| checking permissions | 0.000015 | check_access          | sql_parse.cc  |        6161 |
 
| Opening tables       | 0.000019 | open_tables           | sql_base.cc   |        4579 |
 
| After opening tables | 0.000014 | open_tables           | sql_base.cc   |        4827 |
 
| System lock          | 0.000011 | mysql_lock_tables     | lock.cc       |         308 |
 
| Table lock           | 0.000011 | mysql_lock_tables     | lock.cc       |         313 |
 
| init                 | 0.000018 | mysql_select          | sql_select.cc |        3475 |
 
| optimizing           | 0.000015 | optimize_inner        | sql_select.cc |        1097 |
 
| statistics           | 0.000038 | optimize_inner        | sql_select.cc |        1402 |
 
| preparing            | 0.000018 | optimize_inner        | sql_select.cc |        1427 |
 
| executing            | 0.000010 | exec_inner            | sql_select.cc |        2595 |
 
| Sorting result       | 0.987236 | exec_inner            | sql_select.cc |        3112 |
 
| Sending data         | 0.000078 | exec_inner            | sql_select.cc |        3270 |
 
| end                  | 0.000024 | mysql_select          | sql_select.cc |        3510 |
 
| query end            | 0.000017 | mysql_execute_command | sql_parse.cc  |        5712 |
 
| closing tables       | 0.000014 | close_thread_tables   | sql_base.cc   |         921 |
 
| Unlocking tables     | 0.000019 | mysql_unlock_tables   | lock.cc       |         396 |
 
| freeing items        | 0.000016 | mysql_parse           | sql_parse.cc  |        7486 |
 
| updating status      | 0.000039 | dispatch_command      | sql_parse.cc  |        1961 |
 
| cleaning up          | 0.000022 | dispatch_command      | sql_parse.cc  |        1980 |
 
+----------------------+----------+-----------------------+---------------+-------------+
 
+----------------------+----------+-----------------------+---------------+-------------+
 
| Status               | Duration | Source_function       | Source_file   | Source_line |
 
+----------------------+----------+-----------------------+---------------+-------------+
 
| starting             | 0.000088 | NULL                  | NULL          |        NULL |
 
| checking permissions | 0.000044 | check_access          | sql_parse.cc  |        6161 |
 
| Opening tables       | 0.000037 | open_tables           | sql_base.cc   |        4579 |
 
| After opening tables | 0.000025 | open_tables           | sql_base.cc   |        4827 |
 
| System lock          | 0.000040 | mysql_lock_tables     | lock.cc       |         308 |
 
| Table lock           | 0.000043 | mysql_lock_tables     | lock.cc       |         313 |
 
| init                 | 0.000046 | mysql_select          | sql_select.cc |        3475 |
 
| optimizing           | 0.000039 | optimize_inner        | sql_select.cc |        1097 |
 
| statistics           | 0.000146 | optimize_inner        | sql_select.cc |        1402 |
 
| preparing            | 0.000044 | optimize_inner        | sql_select.cc |        1427 |
 
| executing            | 0.000024 | exec_inner            | sql_select.cc |        2595 |
 
| Sorting result       | 0.993569 | exec_inner            | sql_select.cc |        3112 |
 
| Sending data         | 0.000072 | exec_inner            | sql_select.cc |        3270 |
 
| end                  | 0.000021 | mysql_select          | sql_select.cc |        3510 |
 
| query end            | 0.000017 | mysql_execute_command | sql_parse.cc  |        5712 |
 
| closing tables       | 0.000014 | close_thread_tables   | sql_base.cc   |         921 |
 
| Unlocking tables     | 0.000017 | mysql_unlock_tables   | lock.cc       |         396 |
 
| freeing items        | 0.000015 | mysql_parse           | sql_parse.cc  |        7486 |
 
| updating status      | 0.000046 | dispatch_command      | sql_parse.cc  |        1961 |
 
| cleaning up          | 0.000021 | dispatch_command      | sql_parse.cc  |        1980 |
 
+----------------------+----------+-----------------------+---------------+-------------+
 
+----------------------+----------+-----------------------+---------------+-------------+
 
| Status               | Duration | Source_function       | Source_file   | Source_line |
 
+----------------------+----------+-----------------------+---------------+-------------+
 
| starting             | 0.000079 | NULL                  | NULL          |        NULL |
 
| checking permissions | 0.000038 | check_access          | sql_parse.cc  |        6161 |
 
| Opening tables       | 0.000051 | open_tables           | sql_base.cc   |        4579 |
 
| After opening tables | 0.000043 | open_tables           | sql_base.cc   |        4827 |
 
| System lock          | 0.000010 | mysql_lock_tables     | lock.cc       |         308 |
 
| Table lock           | 0.000020 | mysql_lock_tables     | lock.cc       |         313 |
 
| init                 | 0.000028 | mysql_select          | sql_select.cc |        3475 |
 
| optimizing           | 0.000018 | optimize_inner        | sql_select.cc |        1097 |
 
| statistics           | 0.000046 | optimize_inner        | sql_select.cc |        1402 |
 
| preparing            | 0.000019 | optimize_inner        | sql_select.cc |        1427 |
 
| executing            | 0.000010 | exec_inner            | sql_select.cc |        2595 |
 
| Sorting result       | 0.000085 | exec_inner            | sql_select.cc |        3112 |
 
| Sending data         | 0.996415 | exec_inner            | sql_select.cc |        3270 |
 
| end                  | 0.000045 | mysql_select          | sql_select.cc |        3510 |
 
| query end            | 0.000025 | mysql_execute_command | sql_parse.cc  |        5712 |
 
| closing tables       | 0.000016 | close_thread_tables   | sql_base.cc   |         921 |
 
| Unlocking tables     | 0.000021 | mysql_unlock_tables   | lock.cc       |         396 |
 
| freeing items        | 0.000020 | mysql_parse           | sql_parse.cc  |        7486 |
 
| updating status      | 0.000049 | dispatch_command      | sql_parse.cc  |        1961 |
 
| cleaning up          | 0.000022 | dispatch_command      | sql_parse.cc  |        1980 |
 
+----------------------+----------+-----------------------+---------------+-------------+
 
--------------

This select return empty set:

MariaDB [(none)]>  SELECT * FROM hr.received_resume_event WHERE id_client = '3561906' AND id_resume = '20310224' ORDER BY date_event DESC, type DESC;
 
Empty set (0.01 sec)
 
 
 
MariaDB [(none)]> explain SELECT * FROM hr.received_resume_event WHERE id_client = '3561906' AND id_resume = '20310224' ORDER BY date_event DESC, type DESC;
 
+------+-------------+-----------------------+-------------+---------------------+---------------------+---------+------+------+-------------------------------------------------------------------+
 
| id   | select_type | table                 | type        | possible_keys       | key                 | key_len | ref  | rows | Extra                                                             |
 
+------+-------------+-----------------------+-------------+---------------------+---------------------+---------+------+------+-------------------------------------------------------------------+
 
|    1 | SIMPLE      | received_resume_event | index_merge | id_client,id_resume | id_resume,id_client | 4,4     | NULL |    1 | Using intersect(id_resume,id_client); Using where; Using filesort |
 
+------+-------------+-----------------------+-------------+---------------------+---------------------+---------+------+------+-------------------------------------------------------------------+
 
1 row in set (0.00 sec)
 
 
 
MariaDB [(none)]> show create table hr.received_resume_event;
 
+-----------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 
| Table                 | Create Table                                                                                                                                                                                                                                         
+-----------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 
| received_resume_event | CREATE TABLE `received_resume_event` (
 
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
 
  `id_client` int(10) unsigned NOT NULL DEFAULT '0',
 
  `id_user` int(10) unsigned NOT NULL DEFAULT '0',
 
  `id_resume` int(10) unsigned NOT NULL DEFAULT '0',
 
  `id_vac` int(10) unsigned NOT NULL DEFAULT '0',
 
  `type` tinyint(3) unsigned NOT NULL DEFAULT '0',
 
  `date_event` int(10) unsigned NOT NULL DEFAULT '0',
 
  `text` varchar(255) DEFAULT NULL,
 
  PRIMARY KEY (`id`),
 
  UNIQUE KEY `user_resume_vac_date_type` (`id_user`,`id_resume`,`id_vac`,`date_event`,`type`),
 
  KEY `id_client` (`id_client`),
 
  KEY `id_resume` (`id_resume`),
 
  KEY `id_vac` (`id_vac`),
 
  KEY `type` (`type`)
 
) ENGINE=InnoDB AUTO_INCREMENT=141327999 DEFAULT CHARSET=utf8 ROW_FORMAT=DYNAMIC |
 
+-----------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 
1 row in set (0.00 sec)

Comment by Sergey Chernomorets [ 2019-05-23 ]

And for 10.3.14:

==> /tmp/tmp.Ds6oLqDtq7 <==
 
 
 
==> /tmp/tmp.bgzZl6zbmn <==
 
+------+
 
| drop |
 
+------+
 
| drop |
 
+------+
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Status                 | Duration | Source_function | Source_file  | Source_line |
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Starting               | 0.000023 | NULL            | NULL         |        NULL |
 
| Checking permissions   | 0.000008 | <unknown>       | sql_parse.cc |        6760 |
 
| Opening tables         | 0.000028 | <unknown>       | sql_base.cc  |        4051 |
 
| After opening tables   | 0.000006 | <unknown>       | sql_base.cc  |        4299 |
 
| System lock            | 0.000006 | <unknown>       | lock.cc      |         340 |
 
| Table lock             | 0.000018 | <unknown>       | lock.cc      |         345 |
 
| Closing tables         | 0.000004 | <unknown>       | sql_base.cc  |         720 |
 
| Unlocking tables       | 0.000009 | <unknown>       | lock.cc      |         431 |
 
| Closing tables         | 0.111401 | <unknown>       | lock.cc      |         444 |
 
| Query end              | 0.000023 | <unknown>       | sql_parse.cc |        6295 |
 
| Commit                 | 0.000008 | <unknown>       | sql_parse.cc |        6358 |
 
| Closing tables         | 0.000005 | <unknown>       | sql_base.cc  |         720 |
 
| Commit_implicit        | 0.000007 | <unknown>       | sql_parse.cc |        6402 |
 
| Starting cleanup       | 0.000005 | <unknown>       | sql_parse.cc |        6430 |
 
| Freeing items          | 0.000005 | <unknown>       | sql_parse.cc |        8108 |
 
| Updating status        | 0.000020 | <unknown>       | sql_parse.cc |        2409 |
 
| Reset for next command | 0.000011 | <unknown>       | sql_parse.cc |        2433 |
 
+------------------------+----------+-----------------+--------------+-------------+
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Status                 | Duration | Source_function | Source_file  | Source_line |
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Starting               | 0.000020 | NULL            | NULL         |        NULL |
 
| Checking permissions   | 0.000006 | <unknown>       | sql_parse.cc |        6760 |
 
| Opening tables         | 0.000017 | <unknown>       | sql_base.cc  |        4051 |
 
| After opening tables   | 0.000006 | <unknown>       | sql_base.cc  |        4299 |
 
| System lock            | 0.000006 | <unknown>       | lock.cc      |         340 |
 
| Table lock             | 0.000013 | <unknown>       | lock.cc      |         345 |
 
| Closing tables         | 0.000005 | <unknown>       | sql_base.cc  |         720 |
 
| Unlocking tables       | 0.000006 | <unknown>       | lock.cc      |         431 |
 
| Closing tables         | 0.091156 | <unknown>       | lock.cc      |         444 |
 
| Query end              | 0.000013 | <unknown>       | sql_parse.cc |        6295 |
 
| Commit                 | 0.000006 | <unknown>       | sql_parse.cc |        6358 |
 
| Closing tables         | 0.000005 | <unknown>       | sql_base.cc  |         720 |
 
| Commit_implicit        | 0.000008 | <unknown>       | sql_parse.cc |        6402 |
 
| Starting cleanup       | 0.000005 | <unknown>       | sql_parse.cc |        6430 |
 
| Freeing items          | 0.000006 | <unknown>       | sql_parse.cc |        8108 |
 
| Updating status        | 0.000020 | <unknown>       | sql_parse.cc |        2409 |
 
| Reset for next command | 0.000014 | <unknown>       | sql_parse.cc |        2433 |
 
+------------------------+----------+-----------------+--------------+-------------+
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Status                 | Duration | Source_function | Source_file  | Source_line |
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Starting               | 0.000021 | NULL            | NULL         |        NULL |
 
| Checking permissions   | 0.000008 | <unknown>       | sql_parse.cc |        6760 |
 
| Opening tables         | 0.000018 | <unknown>       | sql_base.cc  |        4051 |
 
| After opening tables   | 0.000010 | <unknown>       | sql_base.cc  |        4299 |
 
| System lock            | 0.000010 | <unknown>       | lock.cc      |         340 |
 
| Table lock             | 0.000019 | <unknown>       | lock.cc      |         345 |
 
| Closing tables         | 0.000006 | <unknown>       | sql_base.cc  |         720 |
 
| Unlocking tables       | 0.000012 | <unknown>       | lock.cc      |         431 |
 
| Closing tables         | 0.012384 | <unknown>       | lock.cc      |         444 |
 
| Query end              | 0.000010 | <unknown>       | sql_parse.cc |        6295 |
 
| Commit                 | 0.000005 | <unknown>       | sql_parse.cc |        6358 |
 
| Closing tables         | 0.000005 | <unknown>       | sql_base.cc  |         720 |
 
| Commit_implicit        | 0.000006 | <unknown>       | sql_parse.cc |        6402 |
 
| Starting cleanup       | 0.000005 | <unknown>       | sql_parse.cc |        6430 |
 
| Freeing items          | 0.000005 | <unknown>       | sql_parse.cc |        8108 |
 
| Updating status        | 0.000028 | <unknown>       | sql_parse.cc |        2409 |
 
| Reset for next command | 0.000012 | <unknown>       | sql_parse.cc |        2433 |
 
+------------------------+----------+-----------------+--------------+-------------+
 
--------------
 
mysql  Ver 15.1 Distrib 10.1.37-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
 
 
 
Connection id:          23
 
Current database:
 
Current user:           user@10.10.8.36
 
SSL:                    Not in use
 
Current pager:          stdout
 
Using outfile:          ''
 
Using delimiter:        ;
 
Server:                 MariaDB
 
Server version:         10.3.14-MariaDB-log MariaDB Server
 
Protocol version:       10
 
Connection:             server via TCP/IP
 
Server characterset:    utf8
 
Db     characterset:    utf8
 
Client characterset:    utf8
 
Conn.  characterset:    utf8
 
TCP port:               3306
 
Uptime:                 2 min 43 sec
 
 
 
Threads: 9  Questions: 126  Slow queries: 0  Opens: 32  Flush tables: 1  Open tables: 17  Queries per second avg: 0.773
 
--------------
 
 
 
 
 
==> /tmp/tmp.4DT2EGRcha <==
 
+------------------------+----------+-----------------+---------------+-------------+
 
| Status                 | Duration | Source_function | Source_file   | Source_line |
 
+------------------------+----------+-----------------+---------------+-------------+
 
| Starting               | 0.000062 | NULL            | NULL          |        NULL |
 
| Checking permissions   | 0.000010 | <unknown>       | sql_parse.cc  |        6760 |
 
| Opening tables         | 0.000022 | <unknown>       | sql_base.cc   |        4051 |
 
| After opening tables   | 0.000007 | <unknown>       | sql_base.cc   |        4299 |
 
| System lock            | 0.000005 | <unknown>       | lock.cc       |         340 |
 
| Table lock             | 0.000007 | <unknown>       | lock.cc       |         345 |
 
| Init                   | 0.000029 | <unknown>       | sql_select.cc |        4215 |
 
| Optimizing             | 0.000016 | <unknown>       | sql_select.cc |        1515 |
 
| Statistics             | 0.000088 | <unknown>       | sql_select.cc |        1886 |
 
| Preparing              | 0.000015 | <unknown>       | sql_select.cc |        1958 |
 
| Sorting result         | 0.000013 | <unknown>       | sql_select.cc |        3212 |
 
| Executing              | 0.000005 | <unknown>       | sql_select.cc |        3852 |
 
| Sending data           | 0.000008 | <unknown>       | sql_select.cc |        4034 |
 
| Creating sort index    | 0.000140 | <unknown>       | sql_select.cc |       20367 |
 
| End of update loop     | 0.000011 | <unknown>       | sql_select.cc |        4250 |
 
| Query end              | 0.000005 | <unknown>       | sql_parse.cc  |        6295 |
 
| Commit                 | 0.000005 | <unknown>       | sql_parse.cc  |        6358 |
 
| Closing tables         | 0.000005 | <unknown>       | sql_base.cc   |         720 |
 
| Unlocking tables       | 0.000004 | <unknown>       | lock.cc       |         431 |
 
| Closing tables         | 0.000006 | <unknown>       | lock.cc       |         444 |
 
| Starting cleanup       | 0.000004 | <unknown>       | sql_parse.cc  |        6430 |
 
| Freeing items          | 0.000007 | <unknown>       | sql_parse.cc  |        8108 |
 
| Updating status        | 0.000016 | <unknown>       | sql_parse.cc  |        2409 |
 
| Reset for next command | 0.000011 | <unknown>       | sql_parse.cc  |        2433 |
 
+------------------------+----------+-----------------+---------------+-------------+
 
+------------------------+----------+-----------------+---------------+-------------+
 
| Status                 | Duration | Source_function | Source_file   | Source_line |
 
+------------------------+----------+-----------------+---------------+-------------+
 
| Starting               | 0.000027 | NULL            | NULL          |        NULL |
 
| Checking permissions   | 0.000006 | <unknown>       | sql_parse.cc  |        6760 |
 
| Opening tables         | 0.000009 | <unknown>       | sql_base.cc   |        4051 |
 
| After opening tables   | 0.000005 | <unknown>       | sql_base.cc   |        4299 |
 
| System lock            | 0.000005 | <unknown>       | lock.cc       |         340 |
 
| Table lock             | 0.000006 | <unknown>       | lock.cc       |         345 |
 
| Init                   | 0.000014 | <unknown>       | sql_select.cc |        4215 |
 
| Optimizing             | 0.000010 | <unknown>       | sql_select.cc |        1515 |
 
| Statistics             | 0.000036 | <unknown>       | sql_select.cc |        1886 |
 
| Preparing              | 0.000010 | <unknown>       | sql_select.cc |        1958 |
 
| Sorting result         | 0.000007 | <unknown>       | sql_select.cc |        3212 |
 
| Executing              | 0.000005 | <unknown>       | sql_select.cc |        3852 |
 
| Sending data           | 0.000007 | <unknown>       | sql_select.cc |        4034 |
 
| Creating sort index    | 0.109193 | <unknown>       | sql_select.cc |       20367 |
 
| End of update loop     | 0.000024 | <unknown>       | sql_select.cc |        4250 |
 
| Query end              | 0.000008 | <unknown>       | sql_parse.cc  |        6295 |
 
| Commit                 | 0.000006 | <unknown>       | sql_parse.cc  |        6358 |
 
| Closing tables         | 0.000005 | <unknown>       | sql_base.cc   |         720 |
 
| Unlocking tables       | 0.000005 | <unknown>       | lock.cc       |         431 |
 
| Closing tables         | 0.000008 | <unknown>       | lock.cc       |         444 |
 
| Starting cleanup       | 0.000005 | <unknown>       | sql_parse.cc  |        6430 |
 
| Freeing items          | 0.000008 | <unknown>       | sql_parse.cc  |        8108 |
 
| Updating status        | 0.000022 | <unknown>       | sql_parse.cc  |        2409 |
 
| Reset for next command | 0.000013 | <unknown>       | sql_parse.cc  |        2433 |
 
+------------------------+----------+-----------------+---------------+-------------+
 
+------------------------+----------+-----------------+---------------+-------------+
 
| Status                 | Duration | Source_function | Source_file   | Source_line |
 
+------------------------+----------+-----------------+---------------+-------------+
 
| Starting               | 0.000030 | NULL            | NULL          |        NULL |
 
| Checking permissions   | 0.000005 | <unknown>       | sql_parse.cc  |        6760 |
 
| Opening tables         | 0.000010 | <unknown>       | sql_base.cc   |        4051 |
 
| After opening tables   | 0.000005 | <unknown>       | sql_base.cc   |        4299 |
 
| System lock            | 0.000005 | <unknown>       | lock.cc       |         340 |
 
| Table lock             | 0.000006 | <unknown>       | lock.cc       |         345 |
 
| Init                   | 0.000016 | <unknown>       | sql_select.cc |        4215 |
 
| Optimizing             | 0.000011 | <unknown>       | sql_select.cc |        1515 |
 
| Statistics             | 0.000039 | <unknown>       | sql_select.cc |        1886 |
 
| Preparing              | 0.000011 | <unknown>       | sql_select.cc |        1958 |
 
| Sorting result         | 0.000007 | <unknown>       | sql_select.cc |        3212 |
 
| Executing              | 0.000005 | <unknown>       | sql_select.cc |        3852 |
 
| Sending data           | 0.000007 | <unknown>       | sql_select.cc |        4034 |
 
| Creating sort index    | 0.090712 | <unknown>       | sql_select.cc |       20367 |
 
| End of update loop     | 0.000023 | <unknown>       | sql_select.cc |        4250 |
 
| Query end              | 0.000007 | <unknown>       | sql_parse.cc  |        6295 |
 
| Commit                 | 0.000006 | <unknown>       | sql_parse.cc  |        6358 |
 
| Closing tables         | 0.000006 | <unknown>       | sql_base.cc   |         720 |
 
| Unlocking tables       | 0.000005 | <unknown>       | lock.cc       |         431 |
 
| Closing tables         | 0.000009 | <unknown>       | lock.cc       |         444 |
 
| Starting cleanup       | 0.000005 | <unknown>       | sql_parse.cc  |        6430 |
 
| Freeing items          | 0.000009 | <unknown>       | sql_parse.cc  |        8108 |
 
| Updating status        | 0.000023 | <unknown>       | sql_parse.cc  |        2409 |
 
| Reset for next command | 0.000013 | <unknown>       | sql_parse.cc  |        2433 |
 
+------------------------+----------+-----------------+---------------+-------------+
 
+------------------------+----------+-----------------+---------------+-------------+
 
| Status                 | Duration | Source_function | Source_file   | Source_line |
 
+------------------------+----------+-----------------+---------------+-------------+
 
| Starting               | 0.000033 | NULL            | NULL          |        NULL |
 
| Checking permissions   | 0.000007 | <unknown>       | sql_parse.cc  |        6760 |
 
| Opening tables         | 0.000015 | <unknown>       | sql_base.cc   |        4051 |
 
| After opening tables   | 0.000007 | <unknown>       | sql_base.cc   |        4299 |
 
| System lock            | 0.000009 | <unknown>       | lock.cc       |         340 |
 
| Table lock             | 0.000006 | <unknown>       | lock.cc       |         345 |
 
| Init                   | 0.000023 | <unknown>       | sql_select.cc |        4215 |
 
| Optimizing             | 0.000014 | <unknown>       | sql_select.cc |        1515 |
 
| Statistics             | 0.000044 | <unknown>       | sql_select.cc |        1886 |
 
| Preparing              | 0.000013 | <unknown>       | sql_select.cc |        1958 |
 
| Sorting result         | 0.000007 | <unknown>       | sql_select.cc |        3212 |
 
| Executing              | 0.000005 | <unknown>       | sql_select.cc |        3852 |
 
| Sending data           | 0.000007 | <unknown>       | sql_select.cc |        4034 |
 
| Creating sort index    | 0.012129 | <unknown>       | sql_select.cc |       20367 |
 
| End of update loop     | 0.000015 | <unknown>       | sql_select.cc |        4250 |
 
| Query end              | 0.000005 | <unknown>       | sql_parse.cc  |        6295 |
 
| Commit                 | 0.000006 | <unknown>       | sql_parse.cc  |        6358 |
 
| Closing tables         | 0.000005 | <unknown>       | sql_base.cc   |         720 |
 
| Unlocking tables       | 0.000005 | <unknown>       | lock.cc       |         431 |
 
| Closing tables         | 0.000007 | <unknown>       | lock.cc       |         444 |
 
| Starting cleanup       | 0.000005 | <unknown>       | sql_parse.cc  |        6430 |
 
| Freeing items          | 0.000007 | <unknown>       | sql_parse.cc  |        8108 |
 
| Updating status        | 0.000019 | <unknown>       | sql_parse.cc  |        2409 |
 
| Reset for next command | 0.000009 | <unknown>       | sql_parse.cc  |        2433 |
 
+------------------------+----------+-----------------+---------------+-------------+
 
--------------
 
mysql  Ver 15.1 Distrib 10.1.37-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
 
 
 
Connection id:          24
 
Current database:
 
Current user:           user@10.10.8.36
 
SSL:                    Not in use
 
Current pager:          stdout
 
Using outfile:          ''
 
Using delimiter:        ;
 
Server:                 MariaDB
 
Server version:         10.3.14-MariaDB-log MariaDB Server
 
Protocol version:       10
 
Connection:             server via TCP/IP
 
Server characterset:    utf8
 
Db     characterset:    utf8
 
Client characterset:    utf8
 
Conn.  characterset:    utf8
 
TCP port:               3306
 
Uptime:                 2 min 43 sec
 
 
 
Threads: 9  Questions: 126  Slow queries: 0  Opens: 32  Flush tables: 1  Open tables: 17  Queries per second avg: 0.773
 
--------------

select freezes on 'Creating sort index':

| Creating sort index    | 0.000140 | <unknown>       | sql_select.cc |       20367 |
 
| Creating sort index    | 0.109193 | <unknown>       | sql_select.cc |       20367 |
 
| Creating sort index    | 0.090712 | <unknown>       | sql_select.cc |       20367 |
 
| Creating sort index    | 0.012129 | <unknown>       | sql_select.cc |       20367 |

Comment by Sergey Chernomorets [ 2019-05-27 ]

If table does not used some time (select from INNODB_BUFFER_PAGE not found any pages for this table) drop spent about 0.2 seconds on server with buffer pool 400Gb.

Comment by Sergey Chernomorets [ 2019-06-03 ]

Some info from show engine innodb status (for 10.3.14):

--Thread 140145927911168 has waited at srv0srv.cc line 2010 for 3.00 seconds the semaphore:
 
X-lock on RW-latch at 0x7f7dfe849800/140179117742080 created in file dict0dict.cc line 1103
 
a writer (thread id 140147674986240) has reserved it in mode exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3329
 
 
 
--Thread 140145877554944 has waited at row0purge.cc line 1057 for 2.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7f7dfe849800/140179117742080 created in file dict0dict.cc line 1103
 
a writer (thread id 140147674986240) has reserved it in mode exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3329
 
 
 
 
 
--Thread 140145869162240 has waited at row0purge.cc line 1057 for 2.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7f7dfe849800/140179117742080 created in file dict0dict.cc line 1103
 
a writer (thread id 140147674986240) has reserved it in mode exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3329
 
 
 
--Thread 140145852376832 has waited at row0purge.cc line 1057 for 2.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7f7dfe849800/140179117742080 created in file dict0dict.cc line 1103
 
a writer (thread id 140147674986240) has reserved it in mode exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3329
 
 
 
--Thread 140179126355712 has waited at row0undo.cc line 294 for 0.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7f7dfe849800/140179117742080 created in file dict0dict.cc line 1103
 
a writer (thread id 140147674986240) has reserved it in mode exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3329
 
 
 
--Thread 140145860769536 has waited at row0purge.cc line 1057 for 2.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7f7dfe849800/140179117742080 created in file dict0dict.cc line 1103
 
a writer (thread id 140147674986240) has reserved it in mode exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3329
 
 
 
 
 
 
 
---TRANSACTION 328544135199, ACTIVE 4 sec dropping table
 
0 lock struct(s), heap size 1136, 0 row lock(s)
 
MySQL thread id 578961534, OS thread handle 140147674986240, query id 18850267799 10.10.1.142 sj_cron Closing tables
 
 
 
DROP TABLE IF EXISTS search.company_search_summary_table_new,search.company_search_summary_table_old
 
 
 
---TRANSACTION 328544136586, ACTIVE 0 sec inserting
 
mysql tables in use 1, locked 1
 
ROLLING BACK 2 lock struct(s), heap size 1136, 1 row lock(s)
 
MySQL thread id 267518929, OS thread handle 140179126355712, query id 18850314850 10.10.1.142 sj_cron_mailer Update
 
 
 
INSERT INTO stat_ru.statistics_daily SET
 
date_new = DATE(NOW()),
 
vacsubscriptions_sent_messages = 1373
 
ON DUPLICATE KEY UPDATE
 
vacsubscriptions_sent_messages = vacsubscriptions_sent_messages + VALUES(vacsubscriptions_sent_messages)
 
 
 
 
 
 
 
 
 
ROW OPERATIONS
 
0 queries inside InnoDB, 0 queries in queue
 
5 read views open inside InnoDB
 
Process ID=21039, Main thread ID=140145927911168, state: enforcing dict cache limit
 
Number of rows inserted 2790340494, updated 2097929103, deleted 327549828, read 2286594671753
 
42.98 inserts/s, 2003.00 updates/s, 1.50 deletes/s, 436118.94 reads/s
 
Number of system rows inserted 477395114, updated 0, deleted 477395114, read 477395140
 
103.45 inserts/s, 0.00 updates/s, 103.45 deletes/s, 103.45 reads/s

Comment by Marko Mäkelä [ 2020-04-16 ]

chernomorets, I just noticed this bug.

In InnoDB, INSERT…SELECT is unfortunate in that it will create an explicit lock for every InnoDB index record visited by the SELECT part of the statement. I wonder if all your problems are related to that?

Can you try creating the source table in some other table than InnoDB?

MDEV-14479 could provide some help to this, allowing you to use LOCK TABLE to prevent the explicit record locks from being created. Could you please try that as well?

Comment by Sergey Chernomorets [ 2020-04-16 ]

@Marko Mäkelä, I use INSERT..SELECT here only to fill table, DROP TABLE and SHOW CREATE... executed after INSERT..SELECT.

And important thing: DROP big TABLE locking other queries for other tables. We drop table A and SHOW CREATE TABLE for table B is locked between "After opening tables" and "closing table".

If I drop table which used recently - other queries will be locked. If I drop table which does not used several hours (and evicted from buffer pool) when other queries will not be locked. So now we renaming tables to temporary schema and drop such tables at night to avoid locks.

Is it need to test MDEV-14479? I think record locks are not couse of this problem.

Comment by Sergey Chernomorets [ 2020-04-16 ]

I've tested 10.5.2

MariaDB [tmp]> show table status like 'sss1'\G;
 
*************************** 1. row ***************************
 
            Name: sss1
 
          Engine: InnoDB
 
         Version: 10
 
      Row_format: Dynamic
 
            Rows: 337106
 
  Avg_row_length: 166
 
     Data_length: 56164352
 
 Max_data_length: 0
 
    Index_length: 0
 
       Data_free: 7340032
 
  Auto_increment: NULL
 
     Create_time: 2020-04-16 22:13:25
 
     Update_time: 2020-04-16 22:13:28
 
      Check_time: NULL
 
       Collation: utf8_general_ci
 
        Checksum: NULL
 
  Create_options: 
         Comment: 
Max_index_length: 0
 
       Temporary: N
 
1 row in set (0.01 sec)

drop table sss1

+------------------------+----------+-----------------+--------------+-------------+
 
| Status                 | Duration | Source_function | Source_file  | Source_line |
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Starting               | 0.000032 | NULL            | NULL         |        NULL |
 
| checking permissions   | 0.000017 | <unknown>       | sql_parse.cc |        6619 |
 
| Opening tables         | 0.000030 | <unknown>       | sql_base.cc  |        4245 |
 
| After opening tables   | 0.000008 | <unknown>       | sql_base.cc  |        4502 |
 
| System lock            | 0.000017 | <unknown>       | lock.cc      |         336 |
 
| table lock             | 0.000020 | <unknown>       | lock.cc      |         341 |
 
| closing tables         | 0.000009 | <unknown>       | sql_base.cc  |         873 |
 
| Unlocking tables       | 0.000018 | <unknown>       | lock.cc      |         427 |
 
| closing tables         | 0.016854 | <unknown>       | lock.cc      |         440 |
 
| Query end              | 0.000010 | <unknown>       | sql_parse.cc |        5920 |
 
| Commit                 | 0.000008 | <unknown>       | sql_parse.cc |        5965 |
 
| closing tables         | 0.000007 | <unknown>       | sql_base.cc  |         873 |
 
| Commit implicit        | 0.000011 | <unknown>       | sql_parse.cc |        6006 |
 
| Starting cleanup       | 0.000009 | <unknown>       | sql_parse.cc |        6034 |
 
| Freeing items          | 0.000009 | <unknown>       | sql_parse.cc |        7970 |
 
| Updating status        | 0.000015 | <unknown>       | sql_parse.cc |        2425 |
 
| Reset for next command | 0.000012 | <unknown>       | sql_parse.cc |        2449 |
 
+------------------------+----------+-----------------+--------------+-------------+

At same time one of many queries SHOW CREATE TABLE sys.date_time

+------------------------+----------+-----------------+--------------+-------------+
 
| Status                 | Duration | Source_function | Source_file  | Source_line |
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Starting               | 0.000019 | NULL            | NULL         |        NULL |
 
| checking permissions   | 0.000006 | <unknown>       | sql_parse.cc |        6619 |
 
| Opening tables         | 0.000009 | <unknown>       | sql_base.cc  |        4245 |
 
| After opening tables   | 0.016512 | <unknown>       | sql_base.cc  |        4502 |
 
| closing tables         | 0.000037 | <unknown>       | sql_base.cc  |         873 |
 
| Query end              | 0.000009 | <unknown>       | sql_parse.cc |        5920 |
 
| Commit                 | 0.000009 | <unknown>       | sql_parse.cc |        5965 |
 
| closing tables         | 0.000010 | <unknown>       | sql_base.cc  |         873 |
 
| Starting cleanup       | 0.000008 | <unknown>       | sql_parse.cc |        6034 |
 
| Freeing items          | 0.000009 | <unknown>       | sql_parse.cc |        7970 |
 
| Updating status        | 0.000017 | <unknown>       | sql_parse.cc |        2425 |
 
| Reset for next command | 0.000014 | <unknown>       | sql_parse.cc |        2449 |
 
+------------------------+----------+-----------------+--------------+-------------+

other queries looks like this:

+------------------------+----------+-----------------+--------------+-------------+
 
| Status                 | Duration | Source_function | Source_file  | Source_line |
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Starting               | 0.000021 | NULL            | NULL         |        NULL |
 
| checking permissions   | 0.000008 | <unknown>       | sql_parse.cc |        6619 |
 
| Opening tables         | 0.000010 | <unknown>       | sql_base.cc  |        4245 |
 
| After opening tables   | 0.000013 | <unknown>       | sql_base.cc  |        4502 |
 
| closing tables         | 0.000008 | <unknown>       | sql_base.cc  |         873 |
 
| Query end              | 0.000011 | <unknown>       | sql_parse.cc |        5920 |
 
| Commit                 | 0.000012 | <unknown>       | sql_parse.cc |        5965 |
 
| closing tables         | 0.000005 | <unknown>       | sql_base.cc  |         873 |
 
| Starting cleanup       | 0.000005 | <unknown>       | sql_parse.cc |        6034 |
 
| Freeing items          | 0.000012 | <unknown>       | sql_parse.cc |        7970 |
 
| Updating status        | 0.000017 | <unknown>       | sql_parse.cc |        2425 |
 
| Reset for next command | 0.000013 | <unknown>       | sql_parse.cc |        2449 |
 
+------------------------+----------+-----------------+--------------+-------------+
 
 
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Status                 | Duration | Source_function | Source_file  | Source_line |
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Starting               | 0.000030 | NULL            | NULL         |        NULL |
 
| checking permissions   | 0.000013 | <unknown>       | sql_parse.cc |        6619 |
 
| Opening tables         | 0.000014 | <unknown>       | sql_base.cc  |        4245 |
 
| After opening tables   | 0.000019 | <unknown>       | sql_base.cc  |        4502 |
 
| closing tables         | 0.000010 | <unknown>       | sql_base.cc  |         873 |
 
| Query end              | 0.000005 | <unknown>       | sql_parse.cc |        5920 |
 
| Commit                 | 0.000006 | <unknown>       | sql_parse.cc |        5965 |
 
| closing tables         | 0.000006 | <unknown>       | sql_base.cc  |         873 |
 
| Starting cleanup       | 0.000005 | <unknown>       | sql_parse.cc |        6034 |
 
| Freeing items          | 0.000006 | <unknown>       | sql_parse.cc |        7970 |
 
| Updating status        | 0.000009 | <unknown>       | sql_parse.cc |        2425 |
 
| Reset for next command | 0.000020 | <unknown>       | sql_parse.cc |        2449 |
 
+------------------------+----------+-----------------+--------------+-------------+
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Status                 | Duration | Source_function | Source_file  | Source_line |
 
+------------------------+----------+-----------------+--------------+-------------+
 
| Starting               | 0.000017 | NULL            | NULL         |        NULL |
 
| checking permissions   | 0.000013 | <unknown>       | sql_parse.cc |        6619 |
 
| Opening tables         | 0.000022 | <unknown>       | sql_base.cc  |        4245 |
 
| After opening tables   | 0.000021 | <unknown>       | sql_base.cc  |        4502 |
 
| closing tables         | 0.000015 | <unknown>       | sql_base.cc  |         873 |
 
| Query end              | 0.000016 | <unknown>       | sql_parse.cc |        5920 |
 
| Commit                 | 0.000017 | <unknown>       | sql_parse.cc |        5965 |
 
| closing tables         | 0.000015 | <unknown>       | sql_base.cc  |         873 |
 
| Starting cleanup       | 0.000017 | <unknown>       | sql_parse.cc |        6034 |
 
| Freeing items          | 0.000016 | <unknown>       | sql_parse.cc |        7970 |
 
| Updating status        | 0.000022 | <unknown>       | sql_parse.cc |        2425 |
 
| Reset for next command | 0.000015 | <unknown>       | sql_parse.cc |        2449 |
 
+------------------------+----------+-----------------+--------------+-------------+


Total large memory allocated 430033600512
 
Dictionary memory allocated 2551692312
 
Buffer pool size   25683200
 
Free buffers       1024
 
Database pages     26413493
 
Old database pages 9750273
 
Modified db pages  3354

I see the same problem: other processes locks when some table is dropping. These tables (dropping and reading) are different tables.

Yes, dropping is very fast now and locks are fast. But is it normal situation when droping one table locks all other processes with another tables?

Now on 10.3.17 dropping big recent used table (about 200gb on disk) may lasts 20-30 seconds and more...

Comment by Eugene Kosov (Inactive) [ 2020-06-10 ]

Probably your problem was fixed in https://github.com/MariaDB/server/commit/264a98eaa0a783e1ce76d18b9105ae00dc11098b A new release with that patch should appear soon.

Could you provide more info?

Specifically could you try to catch a long unlink() via strace and somehow check that it's the reason for blocking?

Built-in trace is very imprecise. Could you try perf or BPF trace + https://github.com/brendangregg/FlameGraph ? http://www.brendangregg.com/blog/2016-10-21/linux-efficient-profiler.html Function names are a must in such a trace! If you use Debian/Ubuntu you might need to install a separate package to see function names.

Comment by Marko Mäkelä [ 2020-12-17 ]

chernomorets, can you reproduce this in MariaDB Server 10.5.4 or later?

Generated at Thu Feb 08 08:52:34 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.