HA! Just after i gave up, i triggered it again, but on my LOCAL server (where i don't have any logging enabled :().
So, here's what i did that locked it up:
Using mysql-query-browser:
start transaction
set time_zone = '-00:00'
call User_UAMS_Login('some@one.com','asd5443asd4f3as4df3as4df3asdf3','054987aa35777777asdf5e09','0','Firefox','Linux','Fedora','127.0.0.1','C','2010-06-15 22:29:13')
commit << this threw an error 'Commands out of synch: you can't run this command now'
rollback << this threw the same error
select eid,pid,status,ip,email,name from UAMS_User where name like '%Hughes%' << this threw the same error
The gui would sometimes give the error in the output console at the bottom, and sometimes it would give the pop-up:
Error while executing query: COMMIT
MySQL Error Nr. 2014
Commands out of sync; you can't run this command now
using cli:
mysql> select * from UAMS_User limit 1
-> ;
+-----+----------------------------------+-----+-----------+-------+--------+--------+----------+----------+-----------+----+---------+--------+---------------------+---------------------+-------+--------+--------------+---------------------+----------------------------------+-------------+--------+------------+--------+
| eid | sid | pid | clearance | admin | status | viewed | verified | disabled | authforms | w9 | attacks | logins | ctime | ltime | rcwid | rcwpin | subscription | email | pwd | question | answer | ip | name |
+-----+----------------------------------+-----+-----------+-------+--------+--------+----------+----------+-----------+----+---------+--------+---------------------+---------------------+-------+--------+--------------+---------------------+----------------------------------+-------------+--------+------------+--------+
| 1 | af8fd5asd5f7asdf4a6sd7f676asdfe4 | 1 | 99 | 1 | 5 | 0 | 1 | 0 | 1 | 0 | 0 | 80 | 2000-01-01 01:01:01 | 2010-06-15 17:23:03 | TEST4 | 1030 | 1 | some@one.com | somemd5functionoutputgoeshere | What is 2+2 | 4 | 1110104949 | System |
+-----+----------------------------------+-----+-----------+-------+--------+--------+----------+----------+-----------+----+---------+--------+---------------------+---------------------+-------+--------+--------------+---------------------+----------------------------------+-------------+--------+------------+--------+
1 row in set (0.00 sec)
mysql>
mysql>
mysql>
mysql>
mysql>
mysql> update UAMS_User set ltime=ltime limit 1; << waited 50 seconds, then:
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
mysql>
So i added logging to the database via:
# Vector's Changes #
log = query.log
log-bin = binary.log
log_bin_trust_function_creators = 1
log-slow-queries = slow.log
long_query_time = 1
log-queries-not-using-indexes
profiling = 1
# End Changes #
And here's what we got:
query.log
/usr/libexec/mysqld, Version: 5.1.47-log (Source distribution). started with:
Tcp port: 0 Unix socket: /var/lib/mysql/mysql.sock
Time Id Command Argument
100615 22:01:43 1 Connect Access denied for user 'UNKNOWN_MYSQL_USER'@'localhost' (using password: NO)
100615 22:02:17 2 Connect Database@localhost on
2 Query SELECT @@sql_mode
2 Query SET SESSION sql_mode=''
2 Query SET NAMES utf8
2 Query show databases
2 Query SHOW TABLES
100615 22:02:22 2 Init DB Database
2 Query SHOW FULL TABLES
2 Query SHOW COLUMNS FROM `A long list of tables`
2 Init DB Database
2 Query SHOW PROCEDURE STATUS
2 Query SHOW CREATE PROCEDURE `a long list of procedures`
2 Query SHOW CREATE FUNCTION `a long list of functions`
2 Init DB Database
2 Query START TRANSACTION
100615 22:02:26 2 Query SHOW VARIABLES LIKE 'character_set_server'
2 Query SELECT @@SQL_MODE
2 Query set time_zone = '-00:00'
100615 22:02:29 2 Query SELECT @@SQL_MODE
2 Query call User_UAMS_Login('some@one.com','asdf65a74sdf76asdf67as4f6asd6f','asdf6as4df6asdf6asdfa66663asdf6','0','Firefox','Linux','Fedora','127.0.0.1','C','2010-06-15 22:29:13')
binary.000001
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#100615 22:01:43 server id 1 end_log_pos 106 Start: binlog v 4, server v 5.1.47-log created 100615 22:01:43 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
hzAYTA8BAAAAZgAAAGoAAAABAAQANS4xLjQ3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAACHMBhMEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
slow.log
empty! :D
Note that i replaced the real md5 values above with a bunch of garbage, for obvious reasons. I noted the note in the binary log, and decided to restart the server and retry the transaction set, just to be sure that it didn't have anything to do with a previous log not existing (remember, i wasn't logging ANYTHING on my local development server prior to just now). After restarting, i looked at binlog 2, and it was the exact same as binlog 1.
Now, using only the cli:
mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)
mysql> set time_zone = '-00:00';
Query OK, 0 rows affected (0.00 sec)
mysql> call User_UAMS_Login('some@one.com','66a45asdf3asa3s74f73asf1d2cd','05asdf4as6d6asdf6ddbdb8f5e09','0','Firefox','Linux','Fedora','127.0.0.1','C','2010-06-15 22:29:13');
+---+
| 6 |
+---+
| 6 |
+---+
1 row in set (0.01 sec)
Query OK, 0 rows affected (0.01 sec)
mysql> commit;
Query OK, 0 rows affected (0.08 sec)
mysql> update UAMS_User set ltime=ltime limit 1
-> ;
Query OK, 0 rows affected, 1 warning (0.00 sec)
Rows matched: 1 Changed: 0 Warnings: 0
mysql>
As you can see, no problems at all when going solely from the cli. So, i don't really know what to make of all of this, but i can now reproduce the error on-command, so that's a huge step forward. I wonder if this is a bug in mysql-query-browser?
Here's the logged result of doing it from the cli:
query.log
6 Query select @@version_comment limit 1
100615 22:48:26 6 Query start transaction
100615 22:48:29 6 Query set time_zone = '-00:00'
100615 22:48:35 6 Query call User_UAMS_Login('some@one.com','66fas6f8asd6fa6df6asdfasdcd','0a6sdfas6df6a6asd6f6b8f5e09','0','Firefox','Linux','Fedora','127.0.0.1','C','2010-06-15 22:29:13')
100615 22:48:43 6 Query commit
100615 22:48:49 6 Query update UAMS_User set ltime=ltime limit 1
slow.log
# Time: 100615 22:48:49
# User@Host: giveopp[giveopp] @ localhost []
# Query_time: 0.000541 Lock_time: 0.000231 Rows_sent: 0 Rows_examined: 0
SET timestamp=1276656529;
update UAMS_User set ltime=ltime limit 1;
binary log (i can't exactly tell where the last session starts in this thing...)
/*!*/;
# at 1363
#100615 22:48:43 server id 1 end_log_pos 1434 Query thread_id=6 exec_time=0 error_code=0
SET TIMESTAMP=1276656523/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
BEGIN
/*!*/;
# at 1434
#100615 22:48:35 server id 1 end_log_pos 1477 User_var
SET @`ip`:=2130706433/*!*/;
# at 1477
#100615 22:48:35 server id 1 end_log_pos 1728 Query thread_id=6 exec_time=0 error_code=0
SET TIMESTAMP=1276656515/*!*/;
SET @@session.sql_mode=524288/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
insert into UAMS_Login_Attempt (ip,attempts,ctime)values(@ip,1, NAME_CONST('sp_ltime',_binary'2010-06-15 22:29:13' COLLATE 'binary')) on duplicate key update attempts=attempts+1
/*!*/;
# at 1728
#100615 22:48:43 server id 1 end_log_pos 1755 Xid = 354
COMMIT/*!*/;
# at 1755
#100615 22:48:49 server id 1 end_log_pos 1826 Query thread_id=6 exec_time=0 error_code=0
SET TIMESTAMP=1276656529/*!*/;
SET @@session.sql_mode=0/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
BEGIN
/*!*/;
# at 1826
#100615 22:48:49 server id 1 end_log_pos 1932 Query thread_id=6 exec_time=0 error_code=0
SET TIMESTAMP=1276656529/*!*/;
update UAMS_User set ltime=ltime limit 1
/*!*/;
# at 1932
#100615 22:48:49 server id 1 end_log_pos 2004 Query thread_id=6 exec_time=0 error_code=0
SET TIMESTAMP=1276656529/*!*/;
COMMIT
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
If you'll notice in the slow.log, the lock times aren't using ridiculously large numbers. Also, btw, pow(4,64) gives me the same thing on my local and live server (3.40282366920938e+38).
Also, when i lock it up, here is the result of 'show innodb status':
=====================================
100615 23:00:20 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 41 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 12, signal count 12
Mutex spin waits 0, rounds 100, OS waits 5
RW-shared spins 12, OS waits 6; RW-excl spins 1, OS waits 1
------------
TRANSACTIONS
------------
Trx id counter 0 144398
Purge done for trx's n:o < 0 144396 undo n:o < 0 0
History list length 12
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 20684, OS thread id 139853871122192
MySQL thread id 8, query id 439 localhost root
show innodb status
---TRANSACTION 0 144397, ACTIVE 7 sec, process no 20684, OS thread id 139853871388432
5 lock struct(s), heap size 1216, 3 row lock(s), undo log entries 1
MySQL thread id 2, query id 427 localhost giveopp
Trx read view will not see trx with id >= 0 144398, sees < 0 144398
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
105 OS file reads, 27 OS file writes, 23 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.02 writes/s, 0.02 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5, seg size 7,
0 inserts, 0 merged recs, 0 merges
Hash table size 17393, node heap has 0 buffer(s)
0.00 hash searches/s, 0.29 non-hash searches/s
---
LOG
---
Log sequence number 0 942831062
Log flushed up to 0 942831062
Last checkpoint at 0 942830953
0 pending log writes, 0 pending chkp writes
20 log i/o's done, 0.02 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 20372936; in additional pool allocated 967936
Dictionary memory allocated 137200
Buffer pool size 512
Free buffers 400
Database pages 112
Modified db pages 2
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 112, created 0, written 10
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
Main thread process no. 20684, id 139853664614160, state: sleeping
Number of rows inserted 0, updated 3, deleted 0, read 28
0.00 inserts/s, 0.02 updates/s, 0.00 deletes/s, 0.17 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
It doesn't really look like the output of the live server once the live server was locked up... The live server is 5.1.*, my local server is:
mysql Ver 14.14 Distrib 5.1.47, for redhat-linux-gnu (x86_64) using readline 5.1
premium domain names that i'm selling
Edited 8 time(s). Last edit at 06/15/2010 09:05PM by Vector Thorn.