| 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: | |
| 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: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".
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;