MySQL Bugs: #62381: Insert records LOCKED nearly all the queries in process list

Bug #62381	Insert records LOCKED nearly all the queries in process list
Submitted:	8 Sep 2011 7:20	Modified:	16 Feb 2012 20:06
Reporter:	Felix Wan	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S2 (Serious)
Version:	5.1.52	OS:	Linux (RHEL 5)
Assigned to:		CPU Architecture:	Any
Tags:	insert, large query cache, limited open_tables, locked, PROCESSLIST

Description:
We have test.sql file contains many lines of "insert into tbl (col1,col2,createTime) values (...);"
And import the content to DB via "string test.sql | mysql -H .... -p ... dbname".
But we found if we are inserting the first item of this table, nearly all other queries are in LOCKED state even they are working on different tables.
The schema of the problematic table is:
CREATE TABLE `time_stream` (
  `id` int(11) unsigned NOT NULL AUTO_INCREMENT,
  `streamId` int(11) unsigned NOT NULL,
  `duration` int(11) unsigned NOT NULL DEFAULT '0',
  `pktid` bigint(20) unsigned NOT NULL DEFAULT '0',
  `createTime` datetime NOT NULL,
  `updateTime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`),
  UNIQUE KEY `streamId` (`streamId`,`duration`),
  KEY `idx_createTime` (`createTime`)
) ENGINE=InnoDB AUTO_INCREMENT=203541360 DEFAULT CHARSET=utf8
------
Process list (Partial)
| 11911031 | pro-openiptv-1 | 10.10.1.86:41335    | openiptv | Query       |     3 | update                                                         | insert into time_stream (streamId, duration, pktid, createTime) values (6000, 0, 0,  |
| 11911033 | pro-openiptv-1 | 10.10.1.36:41607    | openiptv | Query       |     2 | Locked                                                         | select * from session where status='login' and          sessionId='07c8b48d-7e47-4474-851d-6f5626db32a |
| 11911034 | pro-openiptv-1 | 10.10.1.36:41618    | openiptv | Query       |     2 | Locked                                                         | select * from session where status='login' and          sessionId='e491235b-10ff-46b3-a9fa-48d6523341d |
| 11911035 | pro-openiptv-1 | 10.10.1.36:41619    | openiptv | Query       |     2 | Locked                                                         | select * from session where status='login' and          sessionId='669618d6-5e33-4764-b173-87a1609ce18 |
---
Open Status:
| Open_files | 679 |
| Open_streams | 0 |
| Open_table_definitions | 186 |
| Open_tables | 511 |
| Opened_files | 513941 |
| Opened_table_definitions | 122209 |
| Opened_tables | 135416 |
---
Qcache status:
| Qcache_free_blocks | 189427 |
| Qcache_free_memory | 620413064 |
| Qcache_hits | 901325300 |
| Qcache_inserts | 1781711383 |
| Qcache_lowmem_prunes | 765000 |
| Qcache_not_cached | 9906044763 |
| Qcache_queries_in_cache | 344268 |
| Qcache_total_blocks | 878036 |
--
mysql cnf:
open_files_limit                    1284
max_conn 250
open_tables: 512

How to repeat:
we found if we are inserting the first item of this table, nearly all other queries are in LOCKED state even they are working on different tables.

Please, send entire result set of SHOW FULL PROCESSLIST when this problem happens.

Also I do not understand if this table it still InnoDB or is it already replaced with MyISAM one(s) when this problem happens.

print process list * 3 times

Attachment: processlist.log (text/x-log), 133.16 KiB.

"time_stream" table is using MyISAM engine already.

Sorry, I need to correct my create table sql.
| time_stream | CREATE TABLE `time_stream ` (
  `id` int(11) unsigned NOT NULL AUTO_INCREMENT,
  `streamId` int(11) unsigned NOT NULL,
  `duration` int(11) unsigned NOT NULL DEFAULT '0',
  `packetId` bigint(20) unsigned NOT NULL DEFAULT '0',
  `createTime` datetime NOT NULL,
  `updateTime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`),
  UNIQUE KEY `streamId` (`streamId`,`duration`),
  KEY `idx_duration` (`duration`),
  KEY `idx_createTime` (`createTime`)
) ENGINE=MyISAM AUTO_INCREMENT=253714 DEFAULT CHARSET=utf8 |

Dear Developers,
We can constantly reproduce this issue now.
Before we start, set query cache size to 2GB.
1. Create ten tables time_stream[0-9] using the same schema.
2. insert (10000 streams * 1000 duration) records for each table.
3. select all these items one by one.
4. keep an eye on show status like '%cache%" until we used up half of the cache. | Qcache_free_memory      | 969126840 |
5. insert into one table of time_stream[0-9] using streamId=10001,duration=0...
6. It takes us about one minute to finish the statement.
7. show status like '%cache%'; tell us Qcache_free_memory      | 993395600 . Free a a lot of memory here.

Here is the profiling data:
Status * Duration *
starting 0.000046
checking permissions 0.000006
Opening tables 0.000008
System lock 0.000004
Table lock 0.000003
init 0.000023
update 53.916252
end 0.000008
query end 0.000003
freeing items 0.00005
logging slow query 0.000002
logging slow query 0.000009
cleaning up 0.000003
-----
But I don't understand what does it exactly mean by "update"?
Thanks.

Looks related to bug #21074.

Thanks for your reply.
I've checked that bug before, it seems like it'd been solved since 5.1.44 and we are using 5.1.52.

We worked around it by disabling the query cache completely.

Thank you for the feedback.

This looks like bug #54584. Are your parallel SELECTs blocked?

I also could not repeat described behavior in latest development version using provided test case. Which value of query_cache_size do you have? Could you also please try with latest version 5.1.61 to be sure it is not fixed in your environment?

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".