Bug #61186 MYSQL_BIN_LOG::new_file_impl cant create new bin-log file
Submitted: 16 May 2011 11:09 Modified: 26 May 2012 18:33
Reporter: Mikhail Goryachkin Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Locking Severity:S2 (Serious)
Version:5.5.11, 5.5.15 OS:Linux
Assigned to: CPU Architecture:Any
Tags: new_file_impl purge_logs_before_date mysqld_list_processes

[16 May 2011 11:09] Mikhail Goryachkin
Description:
If binary logging is switched on, once a week mysql server stops running transactions, if new bin-log need to be created.

mysql> show processlist;
+---------+-----------------+-----------------+-------------------------+---------+-------+-----------------------------+------------------------------------------------------------------------------------------------------+
| Id      | User            | Host            | db                      | Command | Time  | State                       | Info                                                                                                 |
+---------+-----------------+-----------------+-------------------------+---------+-------+-----------------------------+------------------------------------------------------------------------------------------------------+
|       1 | event_scheduler | localhost       | NULL                    | Daemon  |     1 | Waiting for next activation | NULL                                                                                                 |
|  782368 | java_ui         | localhost:44440 | paynet_crystals         | Query   | 68485 | NULL                        | commit                                                                                               |
|  782380 | java_ui         | localhost:44442 | paynet_crystals         | Killed  | 69509 | NULL                        | NULL                                                                                                 |
|  819778 | paynettest      | localhost:51549 | paynet_crystals         | Query   | 40086 | optimizing                  | select max(tevt_id) tevt_id
      from tevt                                                          |
|  942248 | java_proc       | localhost:33079 | paynet_crystals         | Query   | 68484 | NULL                        | commit                                                                                               |
|  955054 | java_proc       | localhost:55164 | paynet_crystals         | Query   | 68484 | NULL                        | commit                                                                                               |
|  966385 | paynettest      | localhost       | paynet_crystals         | Connect | 68491 | query end                   | insert into event_execution_logs(event_name, start_date)
         values ( NAME_CONST('i_event_name' |
|  966386 | paynettest      | localhost       | paynet_crystals         | Connect | 68491 | query end                   | insert into event_execution_logs(event_name, start_date)
         values ( NAME_CONST('i_event_name' |
|  966389 | paynettest      | localhost       | paynet_crystals         | Connect | 68486 | query end                   | insert into event_execution_logs(event_name, start_date)
         values ( NAME_CONST('i_event_name' |
|  966393 | paynettest      | localhost:60203 | paynet_crystals         | Query   | 68479 | After create                | create temporary table if not exists temp_job_processor_priorities(
      priority_value int(10) uns |
|  966403 | paynettest      | localhost       | paynet_crystals_sandbox | Connect | 68467 | query end                   | insert into event_execution_logs(event_name, start_date)
         values ( NAME_CONST('i_event_name' |
|  966404 | paynettest      | localhost       | paynet_crystals_sandbox | Connect | 68467 | query end                   | insert into event_execution_logs(event_name, start_date)
         values ( NAME_CONST('i_event_name' |
...
| 1011650 | paynettest      | localhost:36710 | paynet_crystals_sandbox | Query   |  3133 | After create                | create temporary table if not exists temp_job_processor_priorities(
      priority_value int(10) uns |
+---------+-----------------+-----------------+-------------------------+---------+-------+-----------------------------+------------------------------------------------------------------------------------------------------+
23 rows in set (0.00 sec)

mysql> select * from performance_schema.threads where THREAD_ID = 966409;
+-----------+----------------+-------------------------+
| THREAD_ID | PROCESSLIST_ID | NAME                    |
+-----------+----------------+-------------------------+
|    966409 |         966385 | thread/sql/event_worker |
+-----------+----------------+-------------------------+
1 row in set (0.00 sec)

mysql> select * from performance_schema.events_waits_current where THREAD_ID = 966409;
+-----------+----------+---------------------------------------------------+-------------+---------------------+-----------+------------+-------+---------------+-------------+-------------+-----------------------+------------------+-----------+-----------------+-------+
| THREAD_ID | EVENT_ID | EVENT_NAME                                        | SOURCE      | TIMER_START         | TIMER_END | TIMER_WAIT | SPINS | OBJECT_SCHEMA | OBJECT_NAME | OBJECT_TYPE | OBJECT_INSTANCE_BEGIN | NESTING_EVENT_ID | OPERATION | NUMBER_OF_BYTES | FLAGS |
+-----------+----------+---------------------------------------------------+-------------+---------------------+-----------+------------+-------+---------------+-------------+-------------+-----------------------+------------------+-----------+-----------------+-------+
|    966409 |      134 | wait/synch/cond/sql/MYSQL_BIN_LOG::COND_prep_xids | log.cc:4207 | 1393809832689362505 |      NULL |       NULL |  NULL | NULL          | NULL        | NULL        |              15816848 |             NULL | wait      |            NULL |     0 |
+-----------+----------+---------------------------------------------------+-------------+---------------------+-----------+------------+-------+---------------+-------------+-------------+-----------------------+------------------+-----------+-----------------+-------+

As you can see process 966385 waiting for mutex wait/synch/cond/sql/MYSQL_BIN_LOG::COND_prep_xids and setting lock wait/synch/mutex/sql/LOG::LOCK_log

mysql> select * from performance_schema.mutex_instances where OBJECT_INSTANCE_BEGIN = 15815624;
+------------------------------------+-----------------------+---------------------+
| NAME                               | OBJECT_INSTANCE_BEGIN | LOCKED_BY_THREAD_ID |
+------------------------------------+-----------------------+---------------------+
| wait/synch/mutex/sql/LOG::LOCK_log |              15815624 |              966409 |
+------------------------------------+-----------------------+---------------------+
1 row in set (0.02 sec)

All other sessions waiting for this lock.

On file system we have two full binary logs, but next bin-log can not be created (Why?) and as a result no more transactions on mysql server.

How to repeat:
CREATE TABLE `event_execution_logs` (
  `eexl_id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `event_name` varchar(64) DEFAULT NULL,
  `start_date` datetime DEFAULT NULL,
  `end_date` datetime DEFAULT NULL,
  PRIMARY KEY (`eexl_id`),
  KEY `idx_event_execution_logs_end_date` (`end_date`)
) ENGINE=InnoDB AUTO_INCREMENT=10532 DEFAULT CHARSET=utf8;

    create temporary table if not exists temp_job_processor_priorities(
      priority_value int(10) unsigned,
      job_type       varchar(128),
      retry_count    int(10),
      retry_interval varchar(128)
    )
    engine = memory;
[16 May 2011 11:10] Mikhail Goryachkin
thread dump

Attachment: thread dump.txt (text/plain), 113.65 KiB.

[16 May 2011 13:00] Mikhail Goryachkin
According to documentation 

If a write to the binary log causes the current log file size to exceed the value of this variable, the server rotates the binary logs (closes the current file and opens the next one). The minimum value is 4096 bytes. The maximum and default value is 1GB.
A transaction is written in one chunk to the binary log, so it is never split between several binary logs. Therefore, if you have big transactions, you might see binary log files larger than max_binlog_size.

But as i can see all our binary logs have maximum size 1G and all transactions created during binary log rotation can't be written to old log file.
[17 May 2011 12:46] Mikhail Goryachkin
Similar bug can be reprodused using the following algorythm.
1. in cnf file
log-bin=/home/mysql55/opt/mysql/logs/mysqld-bin
log-bin-trust-function-creators=1
expire_logs_days = 3 # !!!
max_binlog_size = 512K
binlog_format=mixed
log_slave_updates
2. run DML operations on server to produce a lot of bin-logs
3. during switching of bin-log files run
show processlist;

system hangup
stack trace 2 in attach
[17 May 2011 12:48] Mikhail Goryachkin
purge binary logs vs show processlist

Attachment: thread dump 2.txt (text/plain), 251.54 KiB.

[18 May 2011 14:11] MySQL Verification Team
possibly related: bug #56299
[18 May 2011 14:12] Valeriy Kravchuk
Reminds me bug #56299 and bug#50038 (although last one must be fixed in 5.5.11)
[2 Jun 2011 5:50] Mikhail Goryachkin
this bug consist of two bugs, first looks like
http://bugs.mysql.com/bug.php?id=26079
it is already fixed, but problem is the same (look at first thread dump in this ticket? system hangs up on the same locks)
and second is about binary log rotation if EXPIRE_LOG_DAYS is not null
[16 Nov 2011 13:15] Dima Drug
Got the same problem on 5.5.12 Linux.
Performance schema was on, so here is the state of processes.

SHOW PROCESSLIST;
+-----+------------+-----------------------------------+--------------------+-------------+---------+-------------------------------------------------------+--------------------+
| Id  | User       | Host                              | db                 | Command     | Time    | State                                                 | Info               |
+-----+------------+-----------------------------------+--------------------+-------------+---------+-------------------------------------------------------+--------------------+
|   2 | rslave     | slave_host1 | NULL               | Binlog Dump | 1739380 | Finished reading one binlog; switching to next binlog | NULL               |
| 236 | db_user | localhost                         | host1           | Query       |    1238 | NULL                                                  | commit             |

WAITS FROM PERFORMANCE_SCHEMA.
For session 2:
            THREAD_ID: 18
             EVENT_ID: 537490
           EVENT_NAME: wait/synch/mutex/sql/LOG::LOCK_log
               SOURCE: log_event.cc:1000

For session 236:
            THREAD_ID: 252
             EVENT_ID: 452839969
           EVENT_NAME: wait/synch/cond/sql/MYSQL_BIN_LOG::COND_prep_xids
               SOURCE: log.cc:4207
[16 Nov 2011 13:18] Dima Drug
expire_logs_days=1
max_binlog_size=1073741824  

last binary log file size is about 14Gb
[3 Dec 2011 6:17] Mikhail Goryachkin
One more thread dump for 5.5.15 might be useful
[3 Dec 2011 6:19] Mikhail Goryachkin
no new connections, server can not shut down

Attachment: 03.12.2011.dump (application/octet-stream, text), 15.24 KiB.

[3 Dec 2011 6:29] Mikhail Goryachkin
During master hang up on slave server

mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
...
                Connect_Retry: 60
              Master_Log_File: mysqld-bin.000026
          Read_Master_Log_Pos: 501101659
               Relay_Log_File: paynet-stream-relay-bin.000065
                Relay_Log_Pos: 501101806
        Relay_Master_Log_File: mysqld-bin.000026
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
...
          Exec_Master_Log_Pos: 501101659
              Relay_Log_Space: 501102014
...
        Seconds_Behind_Master: 0
...
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 0
               Last_SQL_Error: 
...
             Master_Server_Id: 2
[3 Dec 2011 6:50] Mikhail Goryachkin
bin logs sizes 
mysqld-bin.000024 │766591K│Nov 11 08:44│
mysqld-bin.000025 │  1024M│Nov 25 04:29│
mysqld-bin.000026 │489376K│Dec  3 09:56│
mysqld-bin.000027 │ 967252│Dec  3 10:31│
hang up time near Dec  3 09:00
[26 Apr 2012 18:33] Sveta Smirnova
Thank you for the feedback.

One of similar bugs (bug #56299) was fixed in 5.5.19. Please try with latest version and inform us if this problem still exists in your environment.
[27 May 2012 1:00] Bugs System
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".