Multiple ways to find duplicates rows and delete safely from bulk number of tables

Here comes the scenario, we have a bug in our app which introduced duplicate rows into the table where we don't have unique key on the table and How do we find and safely delete the duplicate rows  and have a copy of rows what we deleted.

Preparing a test setup with scenario, create table, insert some duplicates as below and do a select of rows...

CREATE TABLE `test` (
  `bid` int(11) NOT NULL AUTO_INCREMENT,
  `addtime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `refid` varchar(255) NOT NULL,
  PRIMARY KEY (`bid`),
  KEY `addtime` (`addtime`),
  KEY `refid` (`refid`)
) ENGINE=InnoDB AUTO_INCREMENT=128 DEFAULT CHARSET=utf8

MariaDB [test]> insert into test(refid) values ('suresh'),('kumar'),('kuna') ;
Query OK, 3 rows affected (0.00 sec)
Records: 3  Duplicates: 0  Warnings: 0

MariaDB [test]> insert into test(refid) values ('suresh'),('kumar'),('kuna') ;
Query OK, 3 rows affected (0.00 sec)
Records: 3  Duplicates: 0  Warnings: 0

MariaDB [test]> insert into test(refid) values ('suresh'),('kumar'),('kuna') ;
Query OK, 3 rows affected (0.00 sec)
Records: 3  Duplicates: 0  Warnings: 0

MariaDB [test]> insert into test(refid) values ('suresh'),('kumar'),('kuna') ;
Query OK, 3 rows affected (0.00 sec)
Records: 3  Duplicates: 0  Warnings: 0

MariaDB [test]> select * from test ;
+-----+---------------------+--------+
| bid | addtime             | refid  |
+-----+---------------------+--------+
|  84 | 2015-10-05 14:31:36 | test   |
|  85 | 2015-10-05 14:31:36 | test1  |
| 113 | 2015-10-05 14:31:50 | suresh |
| 114 | 2015-10-05 14:31:50 | kumar  |
| 115 | 2015-10-05 14:31:50 | kuna   |
| 116 | 2015-10-05 15:35:39 | suresh |
| 117 | 2015-10-05 15:35:39 | kumar  |
| 118 | 2015-10-05 15:35:39 | kuna   |
| 119 | 2015-10-05 15:35:40 | suresh |
| 120 | 2015-10-05 15:35:40 | kumar  |
| 121 | 2015-10-05 15:35:40 | kuna   |
| 122 | 2015-10-05 15:35:40 | suresh |
| 123 | 2015-10-05 15:35:40 | kumar  |
| 124 | 2015-10-05 15:35:40 | kuna   |
| 125 | 2015-10-05 15:35:41 | suresh |
| 126 | 2015-10-05 15:35:41 | kumar  |
| 127 | 2015-10-05 15:35:41 | kuna   |
+-----+---------------------+--------+
17 rows in set (0.00 sec)

Now, we have a table called test with duplicate rows in the table. 

We can delete the duplicates in several ways...and the most easier way if we have only one table with few rows to delete is to a simple select with where condition as below and delete using subquery select. Run the delete statement in for loop until we see the zero rows left in the where condition.

MariaDB [test]> select refid, count(1) from test where addtime between '2015-09-23 00:00:00' and '2015-10-30 00:00:00' group by refid HAVING count(*) > 1;

+--------+----------+

| refid  | count(1) |

+--------+----------+

| kumar  |        5 |

| kuna   |        5 |

| suresh |        5 |

+--------+----------+

3 rows in set (0.00 sec)

MariaDB [test]>  delete from test where refid in (select * from (select refid  from test where addtime between '2015-09-23 00:00:00' and '2015-10-30 00:00:00' group by refid HAVING count(*) > 1 ) a)  limit 1 ;

Query OK, 1 row affected, 2 warnings (0.00 sec)

MariaDB [test]> select refid, count(1) from test where addtime between '2015-09-23 00:00:00' and '2015-10-30 00:00:00' group by refid HAVING count(*) > 1;

+--------+----------+

| refid  | count(1) |

+--------+----------+

| kumar  |        5 |

| kuna   |        5 |

| suresh |        4 |

+--------+----------+

3 rows in set (0.00 sec)

MariaDB [test]> delete from test where refid in (select * from (select refid  from test where addtime between '2015-09-23 00:00:00' and '2015-10-30 00:00:00' group by refid HAVING count(*) > 1 ) a)  limit 1 ;

Query OK, 1 row affected, 2 warnings (0.00 sec)

MariaDB [test]> select refid, count(1) from test where addtime between '2015-09-23 00:00:00' and '2015-10-30 00:00:00' group by refid HAVING count(*) > 1;

+--------+----------+

| refid  | count(1) |

+--------+----------+

| kumar  |        4 |

| kuna   |        5 |

| suresh |        4 |

+--------+----------+

3 rows in set (0.00 sec)

MariaDB [test]> delete from test where refid in (select * from (select refid  from test where addtime between '2015-09-23 00:00:00' and '2015-10-30 00:00:00' group by refid HAVING count(*) > 1 ) a)  limit 1 ;

Query OK, 1 row affected, 2 warnings (0.01 sec)

MariaDB [test]> select refid, count(1) from test where addtime between '2015-09-23 00:00:00' and '2015-10-30 00:00:00' group by refid HAVING count(*) > 1;

+--------+----------+

| refid  | count(1) |

+--------+----------+

| kumar  |        4 |

| kuna   |        4 |

| suresh |        4 |

+--------+----------+

3 rows in set (0.00 sec)

Now, the interesting part. Let's say we have thousands of tables in several databases and we have to delete all the duplicates with less effort and as simple as above or more simpler than above.

For that, we need to have the percona tool called "pt-archiver". Download the tool on the server where you have the databases & tables which have duplicate and make it runnable or executable file.

Create a new table as same as the table which have duplicates to store the deleted duplicate row ( just in case if we need the data later to compare or to see for some or other reason ).  Altered the table and drop the the auto_increament key as we will have duplicates to insert into when we have multiple tables and dropped the primary key.

Finally, use the pt-archiver to store the duplicate rows in a separate table and start deleting from the bunch of tables. Verify the data in the test_duplicates table which has got deleted.

NOTE : Please use the --dry-run before running the pt-archiver to check on what is happening with the created statement.

wget percona.com/get/pt-archiver
chmod +x pt-archiver

create table test_duplicates like test ;

alter table test_duplicates modify bid int(11) NOT NULL ;

alter table test_duplicates drop primary key ;

* Inserted a bunch of rows again into the table and executing the pt-archiver.

for i in `mysql -u root -pxxxx test -s -N -e "show tables like 'test%';"`  ; do /root/pt-archiver  --source h=localhost,D=test,t=$i,u=root,p=xxxx --dest D=test,t=test_duplicates --where " refid in (select max(refid) from $i where addtime between '2015-09-23 00:00:00' and '2015-10-30 00:00:00' group by refid HAVING count(*) > 1 ) " --purge --no-check-columns --no-check-charset --limit=1 --commit-each --statistics --progress=1  ; done

TIME                ELAPSED   COUNT

2015-10-05T14:35:35       0       0

2015-10-05T14:35:35       0       1

2015-10-05T14:35:35       0       2

2015-10-05T14:35:35       0       3

2015-10-05T14:35:35       0       4

2015-10-05T14:35:35       0       5

2015-10-05T14:35:35       0       6

2015-10-05T14:35:35       0       7

2015-10-05T14:35:35       0       8

2015-10-05T14:35:35       0       9

2015-10-05T14:35:35       0      10

2015-10-05T14:35:35       0      11

2015-10-05T14:35:35       0      12

2015-10-05T14:35:35       0      13

2015-10-05T14:35:35       0      14

2015-10-05T14:35:35       0      15

2015-10-05T14:35:35       0      16

2015-10-05T14:35:35       0      17

2015-10-05T14:35:35       0      18

2015-10-05T14:35:35       0      19

2015-10-05T14:35:35       0      20

2015-10-05T14:35:35       0      21

2015-10-05T14:35:35       0      22

2015-10-05T14:35:35       0      23

2015-10-05T14:35:35       0      24

2015-10-05T14:35:35       0      25

2015-10-05T14:35:35       0      26

2015-10-05T14:35:35       0      27

2015-10-05T14:35:35       0      28

2015-10-05T14:35:35       0      29

2015-10-05T14:35:35       0      30

2015-10-05T14:35:35       0      31

2015-10-05T14:35:35       0      32

2015-10-05T14:35:35       0      32

Started at 2015-10-05T14:35:35, ended at 2015-10-05T14:35:35

Source: D=test,h=localhost,p=...,t=test,u=root

Dest:   D=test,h=localhost,p=...,t=test5,u=root

SELECT 32

INSERT 32

DELETE 32

Action         Count       Time        Pct

select            33     0.0150      37.79

commit            66     0.0075      18.95

deleting          32     0.0058      14.56

inserting         32     0.0057      14.32

other              0     0.0057      14.37

MariaDB [test]> select * from test_duplicates limit 32 ;

+-----+---------------------+--------+

| bid | addtime             | refid  |

+-----+---------------------+--------+

|   1 | 2015-10-05 12:13:25 | suresh |

|   2 | 2015-10-05 12:13:25 | kumar  |

|   3 | 2015-10-05 12:13:25 | kuna   |

|   4 | 2015-10-05 12:13:28 | suresh |

|   5 | 2015-10-05 12:13:28 | kumar  |

|   6 | 2015-10-05 12:13:28 | kuna   |

|   7 | 2015-10-05 12:13:29 | suresh |

|   8 | 2015-10-05 12:13:29 | kumar  |

|   9 | 2015-10-05 12:13:29 | kuna   |

|  10 | 2015-10-05 12:13:29 | suresh |

|  11 | 2015-10-05 12:13:29 | kumar  |

|  12 | 2015-10-05 12:13:29 | kuna   |

|  13 | 2015-10-05 12:13:30 | suresh |

|  14 | 2015-10-05 12:13:30 | kumar  |

|  15 | 2015-10-05 12:13:30 | kuna   |

|  16 | 2015-10-05 12:13:31 | suresh |

|  17 | 2015-10-05 12:13:31 | kumar  |

|  18 | 2015-10-05 12:13:31 | kuna   |

|  19 | 2015-10-05 12:13:31 | suresh |

|  20 | 2015-10-05 12:13:31 | kumar  |

|  21 | 2015-10-05 12:13:31 | kuna   |

|  22 | 2015-10-05 12:13:32 | suresh |

|  23 | 2015-10-05 12:13:32 | kumar  |

|  24 | 2015-10-05 12:13:32 | kuna   |

|  25 | 2015-10-05 12:13:32 | suresh |

|  26 | 2015-10-05 12:13:32 | kumar  |

|  27 | 2015-10-05 12:13:32 | kuna   |

|  28 | 2015-10-05 12:13:33 | suresh |

|  29 | 2015-10-05 12:13:33 | kumar  |

|  30 | 2015-10-05 12:13:33 | kuna   |

|  31 | 2015-10-05 12:13:33 | suresh |

|  32 | 2015-10-05 12:13:33 | kumar  |

+-----+---------------------+--------+

32 rows in set (0.00 sec)

MariaDB [test]> select * from test;

+-----+---------------------+--------+

| bid | addtime             | refid  |

+-----+---------------------+--------+

| 33 | 2015-10-05 XX:XX:XX | suresh |

| 34 | 2015-10-05 XX:XX:XX | kumar  |

| 35 | 2015-10-05 XX:XX:XX | kuna   |

+-----+---------------------+--------+

5 rows in set (0.00 sec)

Now, we have all the duplicates deleted from all the tables. The process with take time as per your number of tables and duplicates. It does take really very long time....

Due to the time contraint and with some options available in hand, started looking for another option.  Select the duplicates from all the tables and insert into a second table with the table name and then do a delete.

Create a table with additional column tablename, with out primary keys or unique keys.

create table test5 (

  `bid` int(11) NOT NULL,

`addtime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,

  `refid` varchar(255) NOT NULL,

  `tablename` varchar(255) NOT NULL,

  KEY `addtime` (`addtime`),

  KEY `refid` (`refid`)

) ENGINE=InnoDB

For a bunch of tables with duplicate rows, let's use s simple for loop to select and insert the duplicates into second table and then do a delete with join.

 for i in `mysql -u root -proot test -s -N -e " show tables like 'test%';"` ; do `mysql -u root -pxxxx test -e "insert into test1.test5(bid,addtime,refid,tablename) select  bid,addtime,refid,'$i' from $i where addtime between '2015-09-23 00:00:00' and '2015-10-11 00:00:00' group by refid HAVING count(*) > 1 ;  select sleep(1) ;  delete $i from $i inner join test1.test5 b on $i.refid=b.refid and $i.addtime=b.addtime and $i.bid=b.bid where 1=1 ; ” ` ; done

This one worked pretty well and we will have the backup of deleted rows. Go ahead and try...

Replication stopped with duplicate entry upon starting up of MySQL from cold backup

A few days ago, we faced a Duplicate entry problem in the mysqld server on one of our customer’s slave after cold backup. We do regular data sync checks for all of our customer's as daily reports and check for data discrepancies between master and slave server's, if any got picked up by our checks to investigate, and there was no issues for the particular server and with the report. When checked the entry details, there is a row with the same data in the table that was mentioned by Slave status Last_error entity. Quick check on the error log showed that the slave was started after cold back's and immediately stopped with a duplicate entry error and the mysqld server version is 5.0.77-log Source distribution. From the analysis of the below statements, we found that the slave SQL thread was stopped with the error at a position backwards than the SQL thread initialized after cold backup's.

[perl]
[pythian@dol5 ~]$ tail -20 /var/log/mysql/dol5-error.log
111221 7:42:33 [Note] Slave I/O thread: connected to master 'sslrepl@dol50.dollive.com:3306', replication started in log 'dol50-binlog.000763' at position 533765390
111222 7:05:55 [Note] /usr/libexec/mysqld: Normal shutdown
111222 7:05:55 [Note] Slave SQL thread exiting, replication stopped in log 'dol50-binlog.000767' at position 357198241
111222 7:05:55 [Note] Slave I/O thread killed while reading event
111222 7:05:55 [Note] Slave I/O thread exiting, read up to log 'dol50-binlog.000767', position 357511554 111222 7:05:55 InnoDB: Starting shutdown... 111222 7:06:01 InnoDB: Shutdown completed; log sequence number 372 128185461
111222 7:06:01 [Note] /usr/libexec/mysqld: Shutdown complete
111222 07:06:02 mysqld ended 111222 07:42:09 mysqld started
111222 7:42:18 InnoDB: Started; log sequence number 372 128185461
111222 7:42:20 [Note] /usr/libexec/mysqld: ready for connections. Version: '5.0.77-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Source distribution
111222 7:42:20 [Note] Slave SQL thread initialized, starting replication in log 'dol50-binlog.000767' at position 357198241, relay log '/var/lib/mysql/dol50-relay.000066' position: 357198386
111222 7:42:20 [Note] Slave I/O thread: connected to master 'sslrepl@dol50.dollive.com:3306', replication started in log 'dol50-binlog.000767' at position 357511554
111222 7:42:21 [ERROR] Slave: Error 'Duplicate entry '94335' for key 1' on query. Default database: 'live'. Query: 'insert into charges (amount, key, id) values (0.37, 'dlive', 23892)', Error_code: 1062
111222 7:42:21 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'dol50-binlog.000767' position 357198241

The slave status output on the server that which error occurred is as below.

mysql> show slave status\G
*************************** 1. row ***************************
...... ...........
Last_Errno: 1062
Last_Error: Error 'Duplicate entry '94335' for key 1' on query. Default database: 'live'. Query: 'insert into charges (amount, key, id) values (0.37, 'dlive', 23892)'
...... ..........
1 row in set (0.00 sec)
[/perl]

     Another quick check of the transaction details in master binary logs revealed that the transaction involved is the mixture of storage engines InnoDB and MyISAM. At this point, we have understood that the Duplicate entry error was due to the usage of different storage engines for tables involved in a transaction but how the rollback was performed is still a Question and it was not from application used by Customer. Here is the simple example below that shows the rows inserted into MyISAM table couldn't rolled back though we rollback the transaction.

[perl]
* Creating a table with MyISAM engine.
mysql> CREATE TABLE myisam_tbl ( item int, val int ) engine=MyISAM ;
Query OK, 0 rows affected (0.06 sec)

* Creating a table with Innodb engine.

mysql> CREATE TABLE innodb_tbl ( item int, val int ) engine=Innodb ;
Query OK, 0 rows affected (0.02 sec)

* Starting transaction, inserting rows into both tables and issues rollback.

mysql> START TRANSACTION ;
Query OK, 0 rows affected (0.06 sec)

mysql> INSERT INTO myisam_tbl (item, val) VALUES (1, 1), (2, 2);
Query OK, 2 rows affected (0.02 sec) Records: 2 Duplicates: 0 Warnings: 0

mysql> INSERT INTO innodb_tbl (item, val) VALUES (1, 1), (2, 2);
Query OK, 2 rows affected (0.00 sec) Records: 2 Duplicates: 0 Warnings: 0

mysql> ROLLBACK ;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show warnings ; +---------+------+---------------------------------------------------------------+ | Level | Code | Message | +---------+------+---------------------------------------------------------------+ | Warning | 1196 | Some non-transactional changed tables couldn't be rolled back | +---------+------+---------------------------------------------------------------+ 1 row in set (0.00 sec)

* This shows the rows inserted into MyISAM engine table exist and commited.

mysql> select * from myisam_tbl ;
+------+------+ | item | val | +------+------+
| 1 | 1 | | 2 | 2 |
+------+------+
2 rows in set (0.00 sec)

* This show the rows inserted into Innodb engine table were not commit-ed. mysql> select * from innodb_tbl ; Empty set (0.00 sec) [/perl]


    We did a check and collected the MyISAM and Innodb tables involved SQL statements in the transaction from binary logs at the position where the slave was stopped with an error. We have deleted all the inserted rows of the MyISAM engine involved in the tables of the transaction manually all at once on the slave server ( which caused the duplicate entry errors ) and started slave, it worked fine and no other error's found after it. If we delete one of the inserted rows of MyISAM involved tables one at a time and start the slave, then the replication thread will start executing the whole transaction again from the starting position where replay of transaction inserts the previously deleted entry and will stop at the second entry and goes on, it continues in round-robin fashion and the transaction never completes as it executes from the start position of the transaction again when we issue START SLAVE unless we skip the error which skips the complete transaction.

        After a detailed investigation of the incident by another DBA, we found that the cause was determined to be a transaction involving both MyISAM and InnoDB tables, which was rolled backed during MySQL shutdown and was applied again after start-up (this is a normal MySQL behavior). More details on the MySQL server shutdown process can be found here and see point 4 for rollback of SQL thread during shutdown if it is in the middle of transaction. The STOP SLAVE transaction behavior has been fixed in the version 5.1.35 as per change log to avoid the problems encountered in replication for transactional engine stated here, but it was impossible to roll back a mixed-engines transaction when one of the engines was non-transactional, which meant that the slave could not safely re-apply any transaction that had been interrupted by STOP SLAVE. While changes to InnoDB table were rolled back and then applied normally, changes to MyISAM table couldn't be rolled-back and were applied twice, as MyISAM is non-transactional engine where every single SQL statement will be committed right after the execution.

We made some recommendations to the Customer as below in which the option 3 was chosen as the slave was dedicated for backup's and a quick solution applicable for their data set and timeline for resolution of the issue.

1) Change queries or table types to ensure that transactional and non-transactional tables are not mixed in any transaction
2) Upgrade to MySQL 5.1.35 or later in which the stop slave behavior has been changed to avoid this particular issue ( transaction rollback during MySQL shutdown ).
3) Consider moving to hot backups which does not require MySQL to be shutdown and always ends at a completed transaction.

Alter waiting on Select statement to complete

A few days ago, we faced an interesting problem on one of our customer’s slave mysqld servers. An Alter for adding a new column was run on master server took 542 seconds where as it took few hours on the slave server to complete due to a SELECT blocking the Alter was not allowed to complete.

Here is the the select on the master server and it’s execution time from the binary logs.

# at 825737566
#110720 19:55:21 server id 31415  end_log_pos 825737730         Query   thread_id=83250629      exec_time=542   error_code=0
use collect/*!*/;
SET TIMESTAMP=1311216921/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
ALTER TABLE `track` ADD `source_track_id` int(10) UNSIGNED NULL DEFAULT NULL  AFTER `vendor_track_id`
/*!*/;

Alter statement completed well on the master and it got blocked by a SELECT on the slave where as the time frames of the threads in the processlist which were executing the Alter and the SELECT resembles the ALTER was started first and then the SELECT next. As per the binary logs on the master the Alter was a single statement by the thread_id and the slave started lagging.

mysql> show processlist ;
+---------+-------------+----------------------------+-------------+-------------+--------+----------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
| Id      | User        | Host                       | db          | Command     | Time   | State                                                          | Info                                                                                                 |
+---------+-------------+----------------------------+-------------+-------------+--------+----------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
|     864     | system user |                            | NULL         | Connect     | 479352 | Waiting for master to send event                               | NULL                                                                                                 |
|     865     | system user |                            | collect       | Connect     |   5383 | rename result table                                          | ALTER TABLE `track` ADD `source_track_id` int(10) UNSIGNED NULL DEFAULT NULL  AFTER `vendor_track_id |
| 3277392 | ios               | intreport:56045   | collect       | Query         |   4850 | Copying to tmp table                                       | SELECT /* Reporting Query 357 */
fdr.service_provider_code AS 'Provider',
fdr.service_provider_count |
| 3279284 | uios             | solr02:47871       | collect       | Query         |   4503 | Waiting for table                                              | select track_id,
vendor_track_id,
track_name,
if(promo = 'Y', 'true', 'false') as promo_track,
if( |
.........
.........
 
 Seconds_Behind_Master: 5131

We did the possible checks to find the status of the Alter and why is it waiting at the RENAME RESULT TABLE to complete. The file level checks shows that the creation of the temp table for Alter was completed while ago.

pythian@db04:~$ ls -ltr /ssd2/mysql/collect/track.*
-rwxr-xr-x 1 mysql mysql      19153 2011-07-15 06:11 /ssd2/mysql/collect/track.frm
-rwxr-xr-x 1 mysql mysql       8980 2011-07-15 06:11 /ssd2/mysql/collect/track.TRG
-rwxr-xr-x 1 mysql mysql 2646605824 2011-07-20 20:40 /ssd2/mysql/collect/track.ibd
 
pythian@db04:~$ ls -ltr /mysql/data/collect/track.*
lrwxrwxrwx 1 mysql mysql 26 2011-07-15 08:08 /mysql/data/collect/track.TRG -> /ssd2/mysql/collect/track.TRG
lrwxrwxrwx 1 mysql mysql 26 2011-07-15 08:08 /mysql/data/collect/track.ibd -> /ssd2/mysql/collect/track.ibd
lrwxrwxrwx 1 mysql mysql 26 2011-07-15 08:08 /mysql/data/collect/track.frm -> /ssd2/mysql/collect/track.frm
 
pythian@db04:~$ ls -ltr /mysql/data/collect/*#*
-rwxr-xr-x 1 mysql mysql      19205 2011-07-20 20:04 /mysql/data/collect/#sql-7130_361.frm
-rwxr-xr-x 1 mysql mysql 2499805184 2011-07-20 20:23 /mysql/data/collect/#sql-7130_361.ibd
 
pythian@db04:~$ date
Wed Jul 20 22:13:27 PDT 2011

The show engine innodb status shows that the Alter was not started yet though it was started, created the temp table and waiting at the the RENAME TABLE operation. The SELECT query which is ACTIVE for 9168 seconds blocked the Alter statement and not allowing it to complete.

---TRANSACTION 379ED1F1F, not started, process no 28976, OS thread id 1259583824
mysql tables in use 1, locked 2
MySQL thread id 865, query id 221087068 rename result table
ALTER TABLE `track` ADD `source_track_id` int(10) UNSIGNED NULL DEFAULT NULL  AFTER `vendor_track_id`
---TRANSACTION 379ED1883, ACTIVE 9168 sec, process no 28976, OS thread id 1279453520 fetching rows, thread declared inside InnoDB 49
mysql tables in use 8, locked 0
MySQL thread id 3277392, query id 221086895 intreport 10.1.4.151 collect Copying to tmp table
SELECT /* Reporting Query 357 */
fdr.service_provider_code AS 'Provider',

A few guesses from mates saying that

1) The select has been started first so it is blocking Alter. ( Not true in this case )
2) ALTER started first and before it completes, SELECT fires, fast index creation of secondary indexes allows concurrent SELECTS but still has to get global lock during RENAME as per the explanation in docs in this blog post. But the Alter in this case is not a secondary index rebuild.

A little more digging into documentation revealed that ALTER TABLE makes a temporary copy of the original table. MySQL waits for other operations that are modifying the table, then proceeds. It incorporates the alteration into the copy, deletes the original table, and renames the new one. While ALTER TABLE is executing, the original table is readable by other sessions, but at the end ALTER still has to acquire global lock on data dictionary to swap original and new table copies, that is why we could see other threads in “Waiting for table” state. Updates and writes to the table that begin after the ALTER TABLE operation begins are stalled until the new table is ready, then are automatically redirected to the new table without any failed updates. So what happened in this situation was: ALTER started first, then concurrent SELECT started on the same table, when ALTER finished copy to a temp table it tried to RENAME table, but failed to get global lock on data dictionary. All the threads that started after this point had to wait on ALTER to finish.

More details on the Alter operation can be found here.

Investigating Sort aborted issues

A few days ago, I and few of my fellow members had a discussion about the "Sort aborted" error in the error log should be monitored or it can be ignored because it doesn't bring any value by alerting the oncall DBA who checks the machine and mysqld server status when the error appears.

We have identified the possible or known causes of this error were

1) It could be generated when
a) users cancelling or killing queries in the middle of a filesort
b) web servers rebooting while some queries were sorting i.e when the connection to the database drops suddenly
2) Another is lack of sufficient temp disk space in the tmpdir prevented tmpfile from being created for queries to execute.

As a DBA, we can't do much with the first point apart from informing customer to check at the application side for connection drop outs.
The answer for the second point is to change tmpdir in the mysql to point to a directory (a new one, just for this purpose) in the biggest file system.

3) a transaction got rolled back or aborted due to lock wait timeout or deadlock.

In a database, a deadlock is a situation in which two or more transactions are waiting for one another to give up locks.
Even if a transaction is not involved in a deadlock, it might have to wait a considerable amount of time to obtain a lock because of a long-running transaction or transactions holding locks on the tables it needs. In such a situation, you might not want a transaction to wait indefinitely. Instead, you might want the waiting transaction to abort, or time out, after a reasonable amount of time, called a lock wait timeout.

In such cases, we have to increase the innodb_lock_wait_timeout value in the database server if we want the transaction to wait for more time and complete. We can find the deadlock details in "LATEST DETECTED DEADLOCK" section of the show engine innodb status\G output and therefore needs an investigation of the whole sql statements executed by both transactions with the application dev team to identify the root cause and it's resolution.

4) Unexpected errors, such as source table or even tmp table was corrupt processing of a subquery failed which was also sorting.

In this case, we have to repair the corrupted source table using repair table table_name or mysqlcheck.

5) insufficient memory for sort_buffer_size allocated or Out of sort memory; increase server sort buffer size.

Check the sort buffer size allocated on the server and increase a little at a time in amount of memory because it is a per connection variable and can cause out of memory on the server itself.

[perl]
mysql> show global variables like '%sort%';
+---------------------------+--------------+
| Variable_name | Value |
+---------------------------+--------------+
| max_length_for_sort_data | 1024 |
| max_sort_length | 1024 |
| myisam_max_sort_file_size | 107374182400 |
| myisam_sort_buffer_size | 36700160 |
| sort_buffer_size | 262144 |
+---------------------------+--------------+
5 rows in set (0.14 sec)
[/perl]

Apart from the above causes, Few more things needs to be checked when we see this type of messages in the error logs are :

1) How big is your biggest single table (data + index) ?
2) Do you have any JOINs that involve a huge amount of data being scanned or returned ?
3) What file-system do you have on your machine ?
4) Can you identify the queries that were running at that time ? How long does it run ?

Let's go through the above things in detail.

To find out the biggest table size in the database, execute the below sql query

[perl]
SELECT SQL_CALC_FOUND_ROWS TABLE_SCHEMA, TABLE_NAME, TABLE_TYPE, ENGINE, TABLE_ROWS,
TRUNCATE(DATA_LENGTH/pow(1024,2),2) as 'DATA (M)',
TRUNCATE(INDEX_LENGTH/pow(1024,2),2) as 'INDEX (M)',
TRUNCATE(((DATA_LENGTH+INDEX_LENGTH))/pow(1024,2),2) AS 'TOTAL(M)'
FROM information_schema.tables
WHERE TABLE_SCHEMA not in ( 'information_schema', 'mysql')
AND TABLE_TYPE = 'BASE TABLE'
ORDER BY 8 DESC
LIMIT 1;
[/perl]

The easiest way to find the query with JOINs that involve a huge amount of data being scanned or returned is to enable slow query log on the database server and run the below command on your shell prompt by replacing the actual slow query log, which gives the maximum rows scanned list in the slow query log.

[perl]
$less slowquery.log | grep -i "# Query_time:" | awk '{print $9}' | sort -rn | more
123949125
123947793
123858573
123855366
76087924
75933311
75776390
75691301
75671196
75556710
[/perl]

After finding out the top few large scan number details, then run the below by replacing the highest number in the grep condition to see the query details.

[perl]
$less slowquery.log | grep 123949125 -A 2 B4 | more
[/perl]

Once we got the list of queries which are going for large scan, we can tune it by using Explain plan, creating appropriate indexes for the columns involved in the joins and the sort order etc.

Coming to different filesystems and it's limitations, it can be find here
The filesystems and it's type on a linux machine can be found by running the below commands in the shell prompt.

[perl]
[suresh@home]$ df -T
Filesystem Type 1K-blocks Used Available Use% Mounted on
/dev/mapper/sysvg-root
ext3 470000608 24019012 421721808 6% /
/dev/mapper/mysqlvg-mysql
ext3 945112464 289180564 607148540 33% /mysql
/dev/sda1 ext3 505604 17557 461943 4% /boot
tmpfs tmpfs 24724440 0 24724440 0% /dev/shm

[suresh@home]$ mount
/dev/mapper/sysvg-root on / type ext3 (rw)
proc on /proc type proc (rw)
sysfs on /sys type sysfs (rw)
devpts on /dev/pts type devpts (rw,gid=5,mode=620)
/dev/mapper/mysqlvg-mysql on /mysql type ext3 (rw)
/dev/sda1 on /boot type ext3 (rw)
tmpfs on /dev/shm type tmpfs (rw)
none on /proc/sys/fs/binfmt_misc type binfmt_misc (rw)
sunrpc on /var/lib/nfs/rpc_pipefs type rpc_pipefs (rw)
[/perl]

If we have reached the file system size limits for a give table then we have go for better filesystems.

To find the queries that are running at that time and how long is to log the processlist into a log file periodically using the below command.

[perl]
mysqladmin --user=xxxx --password=xxxxx --sleep=300 processlist
[/perl]

The above are the possible ways of finding the possible causes and it's resolution methods for the error "Sort aborted".

Previously, earlier to the version 5.5.10, for queries that were aborted due to sort problem, the server wrote the message Sort aborted to the error log.
In the latest versions, developers realize that they need to add more details to the error log when ever the error occurs, mysqld server writes more information to provide a more specific message which is useful, such as:

[perl]
[ERROR] mysqld: Sort aborted: Out of memory (Needed 24 bytes)

[ERROR] mysqld: Sort aborted: Out of sort memory,
consider increasing server sort buffer size

[ERROR] mysqld: Sort aborted: Incorrect number of arguments for
FUNCTION test.f1; expected 0, got 1
In addition, if the server was started with --log-warnings=2,
the server write information about the host, user, and query.
[/perl]

In addition, if the server was started with --log-warnings=2, the server write information about the host, user, and query.

InnoDB error : Total number of locks exceeds the lock table size

Recently, one of the clients that I'm working with had a problem with one of their replication slaves where an sql statement gave an error while executing on the slave which got executed successfully on the Master server.

The slave stopped with the error as below.

mysql> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: reporting.com
Master_User: replication
Master_Port: 3306
Connect_Retry: 10
Master_Log_File: mysql3308-bin-log.000488
Read_Master_Log_Pos: 340658086
Relay_Log_File: mysql3319-relay-log.000156
Relay_Log_Pos: 4983506
Relay_Master_Log_File: mysql3308-bin-log.000462
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 1206
Last_Error: Error 'The total number of locks exceeds the lock table size' on query. Default database: 'production'. Query: 'create table Summary SELECT Dimension.calendarYearMonth, count(*) as EmailsSent, count(distinct Email_Sent.UserID) as "Unique Recipients"
FROM Dimension, Email_Sent
WHERE
Email_Sent.DateID = Dimension.id
AND Dimension.date >= '2010-11-01'
GROUP BY 1'
Skip_Counter: 0
Exec_Master_Log_Pos: 4983353
Relay_Log_Space: 14212286599
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 1206
Last_SQL_Error: Error 'The total number of locks exceeds the lock table size' on query. Default database: 'production'. Query: 'create table Summary SELECT Dimension.calendarYearMonth, count(*) as EmailsSent, count(distinct Email_Sent.UserID) as "Unique Recipients"
FROM Dimension, Email_Sent
WHERE
Email_Sent.DateID = Dimension.id
AND Dimension.date >= '2010-11-01'
GROUP BY 1'
1 row in set (0.00 sec)

I have started the slave and monitored the query running status using "show engine innodb status\G". According to the EXPLAIN plan of the query, it is estimated to scan and lock about 910 million rows. The below InnoDB status showed that it already locked 677 million rows and the slave got stopped again with the same error.

This is an error specific to InnoDB tables. The query mentioned above attempts to set locks on all records scanned, to ensure the data returned doesn’t change before creation of the new table. These locks are put into an area of memory allocated within innodb_buffer_pool_size variable.

---TRANSACTION 5722EE5D, ACTIVE 18100 sec, process no 13052, OS thread id 1222195536 fetching rows
mysql tables in use 2, locked 2
2653776 lock struct(s), heap size 327759856, 677089582 row lock(s)
MySQL thread id 2860, query id 1863366 Copying to tmp table on disk
create table Summary SELECT Dimension.calendarYearMonth, count(*) as EmailsSent, count(distinct Email_Sent.UserID) as "Unique Recipients"
FROM Dimension, Email_Sent
WHERE
Email_Sent.DateID = Dimension.id
AND Dimension.date >= '2010-11-01'
GROUP BY 1
TABLE LOCK table `production`.`Email_Sent` trx id 5722EE5D lock mode IS
RECORD LOCKS space id 5623 page no 11 n bits 440 index `ClientID` of table `production`.`Email_Sent` trx id 5722EE5D lock mode S
TABLE LOCK table `production`.`Date_Dimension` trx id 5722EE5D lock mode IS
RECORD LOCKS space id 5611 page no 34 n bits 240 index `PRIMARY` of table `production`.`Date_Dimension` trx id 5722EE5D lock mode S locks rec but not gap
RECORD LOCKS space id 5623 page no 12 n bits 440 index `ClientID` of table `production`.`Email_Sent` trx id 5722EE5D lock mode S
RECORD LOCKS space id 5623 page no 15 n bits 272 index `ClientID` of table `production`.`Email_Sent` trx id 5722EE5D lock mode S
RECORD LOCKS space id 5623 page no 18 n bits 440 index `ClientID` of table `production`.`Email_Sent` trx id 5722EE5D lock mode S
RECORD LOCKS space id 5623 page no 21 n bits 224 index `ClientID` of table `production`.`Email_Sent` trx id 5722EE5D lock mode S
RECORD LOCKS space id 5623 page no 29 n bits 440 index `ClientID` of table `production`.`Email_Sent` trx id 5722EE5D lock mode S
RECORD LOCKS space id 5623 page no 31 n bits 440 index `ClientID` of table `production`.`Email_Sent` trx id 5722EE5D lock mode S
TOO LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS

We found the main difference in MySQL configuration between Master and Slave was amount of memory allocated to InnoDB_buffer_pool_size because Slave was running several MySQL instances that were used for backup purposes.

Need to increase the memory of innodb_buffer_pool_size variable where the locks table can fit in the configuration file and restart the database should fix the problem.

InnoDB uses buffer pool to cache data and indexes of its tables, but it also uses it to store system information, like locks table. The query set locks on all the records it scans. If we have a small buffer pool size, then the InnoDB lock table may indeed grow so big that it does not fit in the buffer pool. Locks table size for the 677 million rows was 327M according to the innodb status. So, we have increased the innodb_buffer_pool_size from 500MB to 1GB which was enough to hold all the locks and restarted the database server. Now the SQL query completed successfully on the slave.


More details on the Innodb row level locks and the size it takes can be found here.

Aborted connection 31084472 to db: ‘ms’ user: ‘login’ host: `x.x.x.12′ (Got timeout reading communication packets)

ERROR Message :
081016 23:25:44 Aborted connection 31084472 to db: ‘ms’ user: ‘login’ host: `x.x.x.12′ (Got timeout reading communication packets)
081016 23:25:44 Aborted connection 31084391 to db: ‘ms’ user: ‘login’ host: `x.x.x.13′ (Got timeout reading communication packets)
081016 23:25:44 Aborted connection 31084488 to db: ‘ms’ user: ‘login’ host: `x.x.x.15′ (Got timeout reading communication packets)
081016 23:25:44 Aborted connection 31084509 to db: ‘ms’ user: ‘login’ host: `x.x.x.15′ (Got timeout reading communication packets)
081016 23:25:45 Aborted connection 31084518 to db: ‘ms’ user: ‘login’ host: `x.x.x..11′ (Got an error reading communication packets)
The below are the Reasons to get the above error :
Aborted connections messages appear in the error log, the cause can be any of the following:
1) The client program did not call mysql_close() before exiting.
2) The client had been sleeping more than wait_timeout or interactive_timeout seconds without issuing any requests to the server.
3) The client program ended abruptly in the middle of a data transfer.
When any of these things happen, the server increments the Aborted_clients status variable.
The server increments the Aborted_connects status variable when the following things happen:
1) A client doesn’t have privileges to connect to a database.
2) A client uses an incorrect password.
3) A connection packet doesn’t contain the right information.
4) It takes more than connect_timeout seconds to get a connect packet.

-Suresh Kuna

Fatal error: Can’t change to run as user ‘mysql’ ; Please check that the user exists!

Problem Statement:

I got the error while starting the server, and is it not able to start as mysql user.
It throws the below error

080915 19:58:10 mysqld started
Fatal error: Can’t change to run as user ‘mysql’ ; Please check that the user exists!
080915 19:58:10 Aborting

080915 19:58:10 /usr/local/mysql4.1.3/bin/mysqld: Shutdown complete

080915 19:58:10 mysqld ended

080915 20:03:59 mysqld started
Fatal error: Can’t change to run as user ‘mysql’ ; Please check that the user exists!
080915 20:03:59 Aborting

080915 20:03:59 /usr/local/mysql4.1.3/bin/mysqld: Shutdown complete

080915 20:03:59 mysqld ended

080915 20:09:07 mysqld started
Fatal error: Can’t change to run as user ‘mysql’ ; Please check that the user exists!
080915 20:09:07 Aborting

080915 20:09:07 /usr/local/mysql4.1.3/bin/mysqld: Shutdown complete

080915 20:09:07 mysqld ended

080915 20:12:21 mysqld started
080915 20:12:21 InnoDB: Started; log sequence number 0 43644
/usr/local/mysql/bin/mysqld: ready for connections.
Version: ‘4.1.3-beta-standard’ socket: ‘/tmp/mysql3311.sock’ port: 3311
080915 20:12:21 Slave SQL thread initialized, starting replication in log ‘hawk-bin.000027′ at position 301237442, relay log
‘./menus-relay-bin.000006′ position: 4
080915 20:12:21 Slave I/O thread: connected to master ‘replicate@x.x.x.90:3306′, replication started in log ‘hawk-bin.
000027′ at position 301237442
080915 20:12:21 Error reading packet from server: Client requested master to start replication from impossible position (ser
ver_errno=1236)
080915 20:12:21 Got fatal error 1236: ‘Client requested master to start replication from impossible position’ from master wh
en reading data from binary log
080915 20:12:21 Slave I/O thread exiting, read up to log ‘hawk-bin.000027′, position 301237442
080915 20:13:07 Aborted connection 4 to db: ‘unconnected’ user: ‘root’ host: `localhost’ (Got an error writing communication
packets)
080915 20:13:07 /usr/local/mysql/bin/mysqld: Normal shutdown

080915 20:13:07 Error reading relay log event: slave SQL thread was killed
080915 20:13:07 InnoDB: Starting shutdown…
080915 20:13:09 InnoDB: Shutdown completed; log sequence number 0 43644
080915 20:13:09 /usr/local/mysql/bin/mysqld: Shutdown complete

080915 20:13:09 mysqld ended

080915 20:23:30 mysqld started
080915 20:23:31 InnoDB: Started; log sequence number 0 43644
/usr/local/mysql/bin/mysqld: ready for connections.
Version: ‘4.1.3-beta-standard’ socket: ‘/tmp/mysql3311.sock’ port: 3311
080915 20:23:31 Slave SQL thread initialized, starting replication in log ‘hawk-bin.000027′ at position 301237442, relay log
‘./menus-relay-bin.000008′ position: 4
080915 20:23:31 Slave I/O thread: connected to master ‘replicate@x.x.x.90:3306′, replication started in log ‘hawk-bin.
000027′ at position 301237442
080915 20:23:31 Error reading packet from server: Client requested master to start replication from impossible position (ser
ver_errno=1236)
080915 20:23:31 Got fatal error 1236: ‘Client requested master to start replication from impossible position’ from master wh
en reading data from binary log
080915 20:23:31 Slave I/O thread exiting, read up to log ‘hawk-bin.000027′, position 301237442
080915 20:34:49 Aborted connection 3 to db: ‘unconnected’ user: ‘root’ host: `localhost’ (Got an error reading communication
packets)
080915 20:35:56 Error reading relay log event: slave SQL thread was killed
080915 20:35:59 Slave SQL thread initialized, starting replication in log ‘hawk-bin.000027′ at position 301237442, relay log
‘./menus-relay-bin.000009′ position: 4

Solution :
The issue was solve by running the server with “sudo - mysql” before the mysql start up script.

sudo -u mysql $BASEDIR/bin/mysqld –defaults-file=$DEFAULT –basedir=$BASEDIR –datadir=$DATADIR \
–user=mysql –pid-file=$PIDFILE 2>&1