MySQL Bugs: #10699: AUTO_INCREMENT locking during replication execution of unrelated db+tables

Bug #10699	AUTO_INCREMENT locking during replication execution of unrelated db+tables
Submitted:	18 May 2005 6:56	Modified:	4 Jun 2005 14:21
Reporter:	Darryl Miles	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	4.0.22	OS:	FreeBSD (freebsd)
Assigned to:	Matthew Lord	CPU Architecture:	Any

Description:
This host is a replication slave for the "realtime" database.  There is a local database "impression_c2" which never receives replication statements.

However it appears that when a (what I call) long running job, "INSERT INTO ... SELECT FROM ..." is running within the slave replicated database, it locks out AUTO_INCREMENT number generation on a table in another database "impression_c2.impression_head".

This does not make any sense.  All of the tables in use by the replication execution are all within the "realtime" database.  There is no cross-database activity on the server at all.

I would expect the SQL sever to still be able to service an unrelated AUTO_INCREMENT table as there is no dependancy I can see.

The box its hosted on is a dual CPU machine, not that I think that makes any difference, as the long running statement is bound to be re-scheduled a number of times before its completion.

As you can see the SQL server is quite busy, loggin webserver activity at a 24h average of 32qps.  Once my application has the AUTO_INCREMENT ID number the remaining inserts are with DELAYED as its purely a logging function.  I've never seen any of these appear in the process list blocked by the replication thread.

mysql> status
--------------
/opt/mysql/bin/mysql  Ver 12.22 Distrib 4.0.22, for unknown-freebsd5.2.1 (i386)

Connection id:          56207
Current database:
Current user:           root@localhost
SSL:                    Not in use
Current pager:          more
Using outfile:          ''
Server version:         4.0.22-log
Protocol version:       10
Connection:             Localhost via UNIX socket
Client characterset:    latin1
Server characterset:    latin1
UNIX socket:            /usr/opt/mysql/mysql.sock
Uptime:                 4 days 18 hours 15 min 34 sec

Threads: 49  Questions: 13387737  Slow queries: 4  Opens: 306  Flush tables: 2  Open tables: 81  Queries per second avg: 32.547
--------------

mysql> show processlist;
+-------+-------------+-----------+---------------+---------+--------+----------------------------------------+------------------------------------------------------------------------------------------------------+
| Id    | User        | Host      | db            | Command | Time   | State                                  | Info                                                            |
+-------+-------------+-----------+---------------+---------+--------+----------------------------------------+------------------------------------------------------------------------------------------------------+
|     1 | system user |           | NULL          | Connect | 411335 | Queueing master event to the relay log | NULL                                                            |
|     2 | system user |           | realtime     | Connect | 511695 | Sending data                           | INSERT INTO stats_new SELECT NULLAS stats_id, sh.afid AS
        afid, sh.ca |
| 56109 | impress     | localhost | impression_c2 | Query   | 468    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56118 | impress     | localhost | impression_c2 | Query   | 479    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56143 | impress     | localhost | impression_c2 | Query   | 474    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56161 | impress     | localhost | impression_c2 | Query   | 467    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56162 | impress     | localhost | impression_c2 | Query   | 463    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56165 | impress     | localhost | impression_c2 | Query   | 472    | Locked                                 | UPDATE impression_head SET finish_level='1',finish_when=NOW() WHERE impression_id='3888866' AND (fin |
| 56175 | impress     | localhost | impression_c2 | Query   | 458    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56179 | impress     | localhost | impression_c2 | Query   | 472    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56180 | impress     | localhost | impression_c2 | Query   | 471    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56195 | impress     | localhost | impression_c2 | Query   | 479    | update                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56196 | impress     | localhost | impression_c2 | Query   | 456    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56198 | impress     | localhost | impression_c2 | Query   | 439    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56205 | impress     | localhost | impression_c2 | Query   | 446    | Locked                                 | UPDATE impression_head SET cookie_value='1200510637428AE08A' WHERE impression_id='5310007'           |
| 56206 | impress     | localhost | impression_c2 | Query   | 479    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56207 | root        | localhost | NULL          | Query   | 0      | NULL                                   | show processlist                                                            |
| 56208 | impress     | localhost | impression_c2 | Query   | 468    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56209 | impress     | localhost | impression_c2 | Query   | 468    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56210 | impress     | localhost | impression_c2 | Query   | 458    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56212 | impress     | localhost | impression_c2 | Query   | 457    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56211 | impress     | localhost | impression_c2 | Query   | 457    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56213 | impress     | localhost | impression_c2 | Query   | 455    | Locked                                 | UPDATE impression_head SET finish_level='1',finish_when=NOW() WHERE impression_id='899363' AND (fini |
| 56214 | impress     | localhost | impression_c2 | Query   | 454    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56215 | impress     | localhost | impression_c2 | Query   | 452    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56216 | impress     | localhost | impression_c2 | Query   | 450    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56217 | impress     | localhost | impression_c2 | Query   | 450    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56218 | impress     | localhost | impression_c2 | Query   | 448    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56219 | impress     | localhost | impression_c2 | Query   | 447    | Locked                                 | UPDATE impression_head SET finish_level='1',finish_when=NOW() WHERE impression_id='3952002' AND (fin |
| 56220 | impress     | localhost | impression_c2 | Query   | 446    | Sending data                           | SELECT * FROM impression_head WHERE cookie_value='1200296A03426BCFC8'                                |
| 56221 | impress     | localhost | impression_c2 | Query   | 445    | statistics                             | SELECT * FROM impression_head WHERE cookie_value='1200117BCD4248A76F'                                |
| 56222 | impress     | localhost | impression_c2 | Query   | 444    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56223 | impress     | localhost | impression_c2 | Query   | 444    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56224 | impress     | localhost | impression_c2 | Query   | 443    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56225 | impress     | localhost | impression_c2 | Query   | 441    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56226 | impress     | localhost | impression_c2 | Query   | 439    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56227 | impress     | localhost | impression_c2 | Query   | 438    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56228 | impress     | localhost | impression_c2 | Query   | 438    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56229 | impress     | localhost | impression_c2 | Query   | 434    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56230 | impress     | localhost | impression_c2 | Query   | 434    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56231 | impress     | localhost | impression_c2 | Query   | 433    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56232 | impress     | localhost | impression_c2 | Query   | 433    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56233 | impress     | localhost | impression_c2 | Query   | 425    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56234 | impress     | localhost | impression_c2 | Query   | 425    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56235 | impress     | localhost | impression_c2 | Query   | 425    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56236 | impress     | localhost | impression_c2 | Query   | 425    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56237 | impress     | localhost | impression_c2 | Query   | 424    | Locked                                 | UPDATE impression_head SET finish_level='1',finish_when=NOW() WHERE impression_id='3888866' AND (fin |
| 56238 | impress     | localhost | impression_c2 | Query   | 423    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56239 | impress     | localhost | impression_c2 | Query   | 419    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56240 | impress     | localhost | impression_c2 | Query   | 419    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
| 56241 | impress     | localhost | impression_c2 | Query   | 400    | Locked                                 | INSERT INTO impression_head (impression_id, cookie_value, start_when, start_level, finish_when, fini |
+-------+-------------+-----------+---------------+---------+--------+----------------------------------------+------------------------------------------------------------------------------------------------------+
51 rows in set (0.03 sec)

How to repeat:
On your replication SLAVE, setup an AUTO_INCREMENT table in a local database.

Then in another database (which is being replicated) on the master issue a long running UPDATE/INSERT job, to cause the slave to begin executing it.

Then try performing a regular AUTO_INCREMENT insert on your unrelated local database table.

First lets make it clear that it's not the replication thread which is locking your updates:

State: Locked
Time: 447
Query: UPDATE impression_head SET
finish_level='1',finish_when=NOW() WHERE impression_id='3952002' AND (fin

State: Sending data
Time: 446
Query: SELECT * FROM impression_head WHERE cookie_value='1200296A03426BCFC8'

State: statistics
Time: 445
Query: SELECT * FROM impression_head WHERE cookie_value='1200117BCD4248A76F'

Try the mailing lists or other community resources for support.

I hear what you are saying, but then for some reason within MySQL, the threads that should be "sending data" or "statistics" for trivial queries took more than 1.5 hours to complete (while replication is running) with replication disabled this problem never occurs.  The processlist I quoted you was of about the 3rd time hence the 400 second times but the first before I let it run as long as I could in the hope it would fix itself.

What I mean by trivial queries is that the threads you quoted are selecting on the table using their unique key index to return a single record.  This lookup takes micro/nano seconds with replication disabled, but locks soon after "START SLAVE".

The states "sending data" and "statistics" sound very inert to me.  Sending data sounds like its writing the results with IO, so if its got my results ready to send and I am using the MySQL API in fetch all mode (not --quick mode) and I already know its only going to return a single record (or no record) then I would logically presume that all necessary implicit locking is complete and this thread is not now blocking any other sinces its done with looking at the data and now sending the data to the client.

The state "statistics" sounds like the query is all but finished.  Again not obviously a state which retains any implicit locking that would block another query.

Yet these two states persisted for over 1 hour 30 mins.

Also during this time the MySQL server hung on client and mysqladmin queries to "STOP SLAVE" and to "shutdown", i.e. it would not accept these instructions no matter what.  It would however return 95% of "show processlist" requests.  5% of those hung to.

If this is indeed not a bug within MySQL then what am I to ask in the forums you suggest ?  How would you technicaly describe this stuck behaviour.

Hi Daryll,

Thank you for your bug report!

We need a repeatable test case to proceed further in this avenue.  What I see
here is a long running SELECT which is causing the queuing of INSERTS and 
UPDATES.  Why this query is running for so long I cannot tell from this information.
It could be that the queries being replicated are causing heavy disk contention or
using extreme amounts of other resources.

As far as the query states you mentioned, "statistics" means that the optimizer is 
trying to figure out the best way to execute the statement.  "sending data" means
that the result set is being returned to the client.  Locks are in use in both of those
stages.  We cannot allow the row you selected to be updated before it is returned 
to the client.

Please open a support ticket with us and we will help you get to the bottom of
the problem.  If you do not have a support contract you have these community
based options available:
mysql.com/IRC
forums.mysql.com
lists.mysql.com

Best Regards