From d1be3765193013fa80e3cae77293b5eef1aff1d1 Mon Sep 17 00:00:00 2001 From: "serg@serg.mylan" <> Date: Mon, 21 Feb 2005 16:28:05 +0100 Subject: [PATCH 1/3] show automatic commits in general log --- sql/log_event.cc | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/sql/log_event.cc b/sql/log_event.cc index 1cdb1652d17..2cfefae51c5 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -1452,7 +1452,7 @@ int Query_log_event::exec_event(struct st_relay_log_info* rli) thd->variables.pseudo_thread_id= thread_id; // for temp tables mysql_log.write(thd,COM_QUERY,"%s",thd->query); DBUG_PRINT("query",("%s",thd->query)); - + if (ignored_error_code((expected_error= error_code)) || !check_expected_error(thd,rli,expected_error)) { @@ -3137,6 +3137,7 @@ int Xid_log_event::exec_event(struct st_relay_log_info* rli) { rli->inc_event_relay_log_pos(); /* For a slave Xid_log_event is COMMIT */ + mysql_log.write(thd,COM_QUERY,"COMMIT /* implicit, from Xid_log_event */"); return end_trans(thd, COMMIT); } #endif /* !MYSQL_CLIENT */ From b43029f4ebc1cb3bbaed3b32ec346423cdfab1d3 Mon Sep 17 00:00:00 2001 From: "serg@serg.mylan" <> Date: Tue, 22 Feb 2005 00:15:31 +0100 Subject: [PATCH 2/3] bug#8646 - deadlock if long transaction causes binlog rotate --- mysql-test/r/rpl_rotate_logs.result | 117 ++++++++++++++++++++++++++++ mysql-test/t/rpl_rotate_logs.test | 25 ++++++ sql/log.cc | 92 ++++++++++------------ sql/sql_class.h | 6 +- sql/sql_parse.cc | 12 +-- sql/sql_yacc.yy | 1 - 6 files changed, 190 insertions(+), 63 deletions(-) diff --git a/mysql-test/r/rpl_rotate_logs.result b/mysql-test/r/rpl_rotate_logs.result index ec29a01db10..2a73eea7517 100644 --- a/mysql-test/r/rpl_rotate_logs.result +++ b/mysql-test/r/rpl_rotate_logs.result @@ -92,3 +92,120 @@ count(*) 100 unlock tables; drop table if exists t1,t2,t3,t4; +slave stop; +reset master; +create table t1 (n int) engine=innodb; +begin; +commit; +drop table t1; +show binlog events in 'master-bin.000001'; +Log_name Pos Event_type Server_id End_log_pos Info +master-bin.000001 4 Format_desc 1 96 Server ver: 5.0.3-alpha-debug-log, Binlog ver: 4 +master-bin.000001 96 Query 1 197 use `test`; create table t1 (n int) engine=innodb +master-bin.000001 197 Query 1 266 use `test`; BEGIN +master-bin.000001 266 Query 1 94 use `test`; insert into t1 values(100 + 4) +master-bin.000001 360 Query 1 187 use `test`; insert into t1 values(99 + 4) +master-bin.000001 453 Query 1 280 use `test`; insert into t1 values(98 + 4) +master-bin.000001 546 Query 1 373 use `test`; insert into t1 values(97 + 4) +master-bin.000001 639 Query 1 466 use `test`; insert into t1 values(96 + 4) +master-bin.000001 732 Query 1 559 use `test`; insert into t1 values(95 + 4) +master-bin.000001 825 Query 1 652 use `test`; insert into t1 values(94 + 4) +master-bin.000001 918 Query 1 745 use `test`; insert into t1 values(93 + 4) +master-bin.000001 1011 Query 1 838 use `test`; insert into t1 values(92 + 4) +master-bin.000001 1104 Query 1 931 use `test`; insert into t1 values(91 + 4) +master-bin.000001 1197 Query 1 1024 use `test`; insert into t1 values(90 + 4) +master-bin.000001 1290 Query 1 1117 use `test`; insert into t1 values(89 + 4) +master-bin.000001 1383 Query 1 1210 use `test`; insert into t1 values(88 + 4) +master-bin.000001 1476 Query 1 1303 use `test`; insert into t1 values(87 + 4) +master-bin.000001 1569 Query 1 1396 use `test`; insert into t1 values(86 + 4) +master-bin.000001 1662 Query 1 1489 use `test`; insert into t1 values(85 + 4) +master-bin.000001 1755 Query 1 1582 use `test`; insert into t1 values(84 + 4) +master-bin.000001 1848 Query 1 1675 use `test`; insert into t1 values(83 + 4) +master-bin.000001 1941 Query 1 1768 use `test`; insert into t1 values(82 + 4) +master-bin.000001 2034 Query 1 1861 use `test`; insert into t1 values(81 + 4) +master-bin.000001 2127 Query 1 1954 use `test`; insert into t1 values(80 + 4) +master-bin.000001 2220 Query 1 2047 use `test`; insert into t1 values(79 + 4) +master-bin.000001 2313 Query 1 2140 use `test`; insert into t1 values(78 + 4) +master-bin.000001 2406 Query 1 2233 use `test`; insert into t1 values(77 + 4) +master-bin.000001 2499 Query 1 2326 use `test`; insert into t1 values(76 + 4) +master-bin.000001 2592 Query 1 2419 use `test`; insert into t1 values(75 + 4) +master-bin.000001 2685 Query 1 2512 use `test`; insert into t1 values(74 + 4) +master-bin.000001 2778 Query 1 2605 use `test`; insert into t1 values(73 + 4) +master-bin.000001 2871 Query 1 2698 use `test`; insert into t1 values(72 + 4) +master-bin.000001 2964 Query 1 2791 use `test`; insert into t1 values(71 + 4) +master-bin.000001 3057 Query 1 2884 use `test`; insert into t1 values(70 + 4) +master-bin.000001 3150 Query 1 2977 use `test`; insert into t1 values(69 + 4) +master-bin.000001 3243 Query 1 3070 use `test`; insert into t1 values(68 + 4) +master-bin.000001 3336 Query 1 3163 use `test`; insert into t1 values(67 + 4) +master-bin.000001 3429 Query 1 3256 use `test`; insert into t1 values(66 + 4) +master-bin.000001 3522 Query 1 3349 use `test`; insert into t1 values(65 + 4) +master-bin.000001 3615 Query 1 3442 use `test`; insert into t1 values(64 + 4) +master-bin.000001 3708 Query 1 3535 use `test`; insert into t1 values(63 + 4) +master-bin.000001 3801 Query 1 3628 use `test`; insert into t1 values(62 + 4) +master-bin.000001 3894 Query 1 3721 use `test`; insert into t1 values(61 + 4) +master-bin.000001 3987 Query 1 3814 use `test`; insert into t1 values(60 + 4) +master-bin.000001 4080 Query 1 3907 use `test`; insert into t1 values(59 + 4) +master-bin.000001 4173 Query 1 4000 use `test`; insert into t1 values(58 + 4) +master-bin.000001 4266 Query 1 4093 use `test`; insert into t1 values(57 + 4) +master-bin.000001 4359 Query 1 4186 use `test`; insert into t1 values(56 + 4) +master-bin.000001 4452 Query 1 4279 use `test`; insert into t1 values(55 + 4) +master-bin.000001 4545 Query 1 4372 use `test`; insert into t1 values(54 + 4) +master-bin.000001 4638 Query 1 4465 use `test`; insert into t1 values(53 + 4) +master-bin.000001 4731 Query 1 4558 use `test`; insert into t1 values(52 + 4) +master-bin.000001 4824 Query 1 4651 use `test`; insert into t1 values(51 + 4) +master-bin.000001 4917 Query 1 4744 use `test`; insert into t1 values(50 + 4) +master-bin.000001 5010 Query 1 4837 use `test`; insert into t1 values(49 + 4) +master-bin.000001 5103 Query 1 4930 use `test`; insert into t1 values(48 + 4) +master-bin.000001 5196 Query 1 5023 use `test`; insert into t1 values(47 + 4) +master-bin.000001 5289 Query 1 5116 use `test`; insert into t1 values(46 + 4) +master-bin.000001 5382 Query 1 5209 use `test`; insert into t1 values(45 + 4) +master-bin.000001 5475 Query 1 5302 use `test`; insert into t1 values(44 + 4) +master-bin.000001 5568 Query 1 5395 use `test`; insert into t1 values(43 + 4) +master-bin.000001 5661 Query 1 5488 use `test`; insert into t1 values(42 + 4) +master-bin.000001 5754 Query 1 5581 use `test`; insert into t1 values(41 + 4) +master-bin.000001 5847 Query 1 5674 use `test`; insert into t1 values(40 + 4) +master-bin.000001 5940 Query 1 5767 use `test`; insert into t1 values(39 + 4) +master-bin.000001 6033 Query 1 5860 use `test`; insert into t1 values(38 + 4) +master-bin.000001 6126 Query 1 5953 use `test`; insert into t1 values(37 + 4) +master-bin.000001 6219 Query 1 6046 use `test`; insert into t1 values(36 + 4) +master-bin.000001 6312 Query 1 6139 use `test`; insert into t1 values(35 + 4) +master-bin.000001 6405 Query 1 6232 use `test`; insert into t1 values(34 + 4) +master-bin.000001 6498 Query 1 6325 use `test`; insert into t1 values(33 + 4) +master-bin.000001 6591 Query 1 6418 use `test`; insert into t1 values(32 + 4) +master-bin.000001 6684 Query 1 6511 use `test`; insert into t1 values(31 + 4) +master-bin.000001 6777 Query 1 6604 use `test`; insert into t1 values(30 + 4) +master-bin.000001 6870 Query 1 6697 use `test`; insert into t1 values(29 + 4) +master-bin.000001 6963 Query 1 6790 use `test`; insert into t1 values(28 + 4) +master-bin.000001 7056 Query 1 6883 use `test`; insert into t1 values(27 + 4) +master-bin.000001 7149 Query 1 6976 use `test`; insert into t1 values(26 + 4) +master-bin.000001 7242 Query 1 7069 use `test`; insert into t1 values(25 + 4) +master-bin.000001 7335 Query 1 7162 use `test`; insert into t1 values(24 + 4) +master-bin.000001 7428 Query 1 7255 use `test`; insert into t1 values(23 + 4) +master-bin.000001 7521 Query 1 7348 use `test`; insert into t1 values(22 + 4) +master-bin.000001 7614 Query 1 7441 use `test`; insert into t1 values(21 + 4) +master-bin.000001 7707 Query 1 7534 use `test`; insert into t1 values(20 + 4) +master-bin.000001 7800 Query 1 7627 use `test`; insert into t1 values(19 + 4) +master-bin.000001 7893 Query 1 7720 use `test`; insert into t1 values(18 + 4) +master-bin.000001 7986 Query 1 7813 use `test`; insert into t1 values(17 + 4) +master-bin.000001 8079 Query 1 7906 use `test`; insert into t1 values(16 + 4) +master-bin.000001 8172 Query 1 7999 use `test`; insert into t1 values(15 + 4) +master-bin.000001 8265 Query 1 8092 use `test`; insert into t1 values(14 + 4) +master-bin.000001 8358 Query 1 8185 use `test`; insert into t1 values(13 + 4) +master-bin.000001 8451 Query 1 8278 use `test`; insert into t1 values(12 + 4) +master-bin.000001 8544 Query 1 8371 use `test`; insert into t1 values(11 + 4) +master-bin.000001 8637 Query 1 8464 use `test`; insert into t1 values(10 + 4) +master-bin.000001 8730 Query 1 8556 use `test`; insert into t1 values(9 + 4) +master-bin.000001 8822 Query 1 8648 use `test`; insert into t1 values(8 + 4) +master-bin.000001 8914 Query 1 8740 use `test`; insert into t1 values(7 + 4) +master-bin.000001 9006 Query 1 8832 use `test`; insert into t1 values(6 + 4) +master-bin.000001 9098 Query 1 8924 use `test`; insert into t1 values(5 + 4) +master-bin.000001 9190 Query 1 9016 use `test`; insert into t1 values(4 + 4) +master-bin.000001 9282 Query 1 9108 use `test`; insert into t1 values(3 + 4) +master-bin.000001 9374 Query 1 9200 use `test`; insert into t1 values(2 + 4) +master-bin.000001 9466 Query 1 9292 use `test`; insert into t1 values(1 + 4) +master-bin.000001 9558 Xid 1 9319 COMMIT /* xid=146 */ +master-bin.000001 9585 Rotate 1 9629 master-bin.000002;pos=4 +show binlog events in 'master-bin.000002'; +Log_name Pos Event_type Server_id End_log_pos Info +master-bin.000002 4 Format_desc 1 96 Server ver: 5.0.3-alpha-debug-log, Binlog ver: 4 +master-bin.000002 96 Query 1 173 use `test`; drop table t1 diff --git a/mysql-test/t/rpl_rotate_logs.test b/mysql-test/t/rpl_rotate_logs.test index 2b5c72d16d2..1029c64867a 100644 --- a/mysql-test/t/rpl_rotate_logs.test +++ b/mysql-test/t/rpl_rotate_logs.test @@ -152,3 +152,28 @@ unlock tables; connection master; drop table if exists t1,t2,t3,t4; sync_slave_with_master; + +# +# now the same in a transaction +# +slave stop; # we don't need it anymore +connection master; +reset master; +let $1=100; + +--disable_warnings +create table t1 (n int) engine=innodb; +--enable_warnings +begin; +--disable_query_log +while ($1) +{ + eval insert into t1 values($1 + 4); + dec $1; +} +--enable_query_log +commit; +drop table t1; +show binlog events in 'master-bin.000001'; +show binlog events in 'master-bin.000002'; + diff --git a/sql/log.cc b/sql/log.cc index 64c2a890969..803c2c0a8fe 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -1400,7 +1400,7 @@ bool MYSQL_LOG::append(Log_event* ev) pthread_mutex_unlock(&LOCK_index); } -err: +err: pthread_mutex_unlock(&LOCK_log); signal_update(); // Safe as we don't call close DBUG_RETURN(error); @@ -1548,16 +1548,15 @@ inline bool sync_binlog(IO_CACHE *cache) Write an event to the binary log */ -bool MYSQL_LOG::write(Log_event* event_info) +bool MYSQL_LOG::write(Log_event *event_info) { - THD *thd=event_info->thd; - bool error=1; - bool should_rotate = 0; - DBUG_ENTER("MYSQL_LOG::write(event)"); - + THD *thd= event_info->thd; + bool error= 1; + DBUG_ENTER("MYSQL_LOG::write(Log_event *)"); + pthread_mutex_lock(&LOCK_log); - /* + /* In most cases this is only called if 'is_open()' is true; in fact this is mostly called if is_open() *was* true a few instructions before, but it could have changed since. @@ -1567,7 +1566,7 @@ bool MYSQL_LOG::write(Log_event* event_info) const char *local_db= event_info->get_db(); IO_CACHE *file= &log_file; #ifdef HAVE_REPLICATION - /* + /* In the future we need to add to the following if tests like "do the involved tables match (to be implemented) binlog_[wild_]{do|ignore}_table?" (WL#1049)" @@ -1734,10 +1733,6 @@ COLLATION_CONNECTION=%u,COLLATION_DATABASE=%u,COLLATION_SERVER=%u", { if (flush_io_cache(file) || sync_binlog(file)) goto err; - - /* check automatic rotation; */ - DBUG_PRINT("info",("max_size: %lu",max_size)); - should_rotate= (my_b_tell(file) >= (my_off_t) max_size); } error=0; @@ -1751,28 +1746,39 @@ err: write_error=1; } if (file == &log_file) - signal_update(); - if (should_rotate) { - pthread_mutex_lock(&LOCK_index); - new_file(0); // inside mutex - pthread_mutex_unlock(&LOCK_index); + signal_update(); + rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED); } } pthread_mutex_unlock(&LOCK_log); -#ifdef HAVE_REPLICATION - if (should_rotate && expire_logs_days) - { - long purge_time= time(0) - expire_logs_days*24*60*60; - if (purge_time >= 0) - error= purge_logs_before_date(purge_time); - } -#endif DBUG_RETURN(error); } +void MYSQL_LOG::rotate_and_purge(uint flags) +{ + if (!prepared_xids && // see new_file() for the explanation + ((flags & RP_FORCE_ROTATE) || + (my_b_tell(&log_file) >= (my_off_t) max_size))) + { + if (flags & RP_LOCK_LOG_IS_ALREADY_LOCKED) + pthread_mutex_lock(&LOCK_index); + new_file(!(flags & RP_LOCK_LOG_IS_ALREADY_LOCKED)); + if (flags & RP_LOCK_LOG_IS_ALREADY_LOCKED) + pthread_mutex_unlock(&LOCK_index); +#ifdef HAVE_REPLICATION + // QQ why do we need #ifdef here ??? + if (expire_logs_days) + { + long purge_time= time(0) - expire_logs_days*24*60*60; + if (purge_time >= 0) + purge_logs_before_date(purge_time); + } +#endif + } +} uint MYSQL_LOG::next_file_id() { @@ -1797,24 +1803,20 @@ uint MYSQL_LOG::next_file_id() - The thing in the cache is always a complete transaction - 'cache' needs to be reinitialized after this functions returns. - TODO - fix it to become atomic - either the complete cache is added to binlog - or nothing (other storage engines rely on this, doing a ROLLBACK) - IMPLEMENTATION - To support transaction over replication, we wrap the transaction with BEGIN/COMMIT or BEGIN/ROLLBACK in the binary log. - We want to write a BEGIN/ROLLBACK block when a non-transactional table was - updated in a transaction which was rolled back. This is to ensure that the - same updates are run on the slave. + We want to write a BEGIN/ROLLBACK block when a non-transactional table + was updated in a transaction which was rolled back. This is to ensure + that the same updates are run on the slave. */ bool MYSQL_LOG::write(THD *thd, IO_CACHE *cache) { - bool should_rotate= 0, error= 0; + bool error= 0; VOID(pthread_mutex_lock(&LOCK_log)); - DBUG_ENTER("MYSQL_LOG::write(cache"); - + DBUG_ENTER("MYSQL_LOG::write(THD *, IO_CACHE *)"); + if (likely(is_open())) // Should always be true { uint length; @@ -1869,25 +1871,10 @@ bool MYSQL_LOG::write(THD *thd, IO_CACHE *cache) } signal_update(); DBUG_PRINT("info",("max_size: %lu",max_size)); - if (should_rotate= (my_b_tell(&log_file) >= (my_off_t) max_size)) - { - pthread_mutex_lock(&LOCK_index); - new_file(0); // inside mutex - pthread_mutex_unlock(&LOCK_index); - } - + rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED); } VOID(pthread_mutex_unlock(&LOCK_log)); -#ifdef HAVE_REPLICATION - if (should_rotate && expire_logs_days) - { - long purge_time= time(0) - expire_logs_days*24*60*60; - if (purge_time >= 0) - error= purge_logs_before_date(purge_time); - } -#endif - DBUG_RETURN(error); err: @@ -2993,6 +2980,7 @@ void TC_LOG_BINLOG::unlog(ulong cookie, my_xid xid) { if (thread_safe_dec_and_test(prepared_xids, &LOCK_prep_xids)) pthread_cond_signal(&COND_prep_xids); + rotate_and_purge(0); // in case ::write() was not able to rotate } int TC_LOG_BINLOG::recover(IO_CACHE *log, Format_description_log_event *fdle) diff --git a/sql/sql_class.h b/sql/sql_class.h index 5286990f9c6..e793f5776d7 100644 --- a/sql/sql_class.h +++ b/sql/sql_class.h @@ -174,6 +174,9 @@ typedef struct st_user_var_events uint charset_number; } BINLOG_USER_VAR_EVENT; +#define RP_LOCK_LOG_IS_ALREADY_LOCKED 1 +#define RP_FORCE_ROTATE 2 + class Log_event; /* @@ -300,7 +303,7 @@ public: } bool open_index_file(const char *index_file_name_arg, const char *log_name); - void new_file(bool need_lock= 1); + void new_file(bool need_lock); bool write(THD *thd, enum enum_server_command command, const char *format,...); bool write(THD *thd, const char *query, uint query_length, @@ -319,6 +322,7 @@ public: void make_log_name(char* buf, const char* log_ident); bool is_active(const char* log_file_name); int update_log_index(LOG_INFO* linfo, bool need_update_threads); + void rotate_and_purge(uint flags); int purge_logs(const char *to_log, bool included, bool need_mutex, bool need_update_threads, ulonglong *decrease_log_space); diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 8a5933f09a2..8940fbd2c06 100644 --- a/sql/sql_parse.cc +++ b/sql/sql_parse.cc @@ -6130,22 +6130,16 @@ bool reload_acl_and_cache(THD *thd, ulong options, TABLE_LIST *tables, the slow query log, and the relay log (if it exists). */ - /* + /* Writing this command to the binlog may result in infinite loops when doing mysqlbinlog|mysql, and anyway it does not really make sense to log it automatically (would cause more trouble to users than it would help them) */ tmp_write_to_binlog= 0; mysql_log.new_file(1); - mysql_bin_log.new_file(1); mysql_slow_log.new_file(1); + mysql_bin_log.rotate_and_purge(RP_FORCE_ROTATE); #ifdef HAVE_REPLICATION - if (mysql_bin_log.is_open() && expire_logs_days) - { - long purge_time= time(0) - expire_logs_days*24*60*60; - if (purge_time >= 0) - mysql_bin_log.purge_logs_before_date(purge_time); - } pthread_mutex_lock(&LOCK_active_mi); rotate_relay_log(active_mi); pthread_mutex_unlock(&LOCK_active_mi); @@ -6159,7 +6153,7 @@ bool reload_acl_and_cache(THD *thd, ulong options, TABLE_LIST *tables, if (options & REFRESH_QUERY_CACHE_FREE) { query_cache.pack(); // FLUSH QUERY CACHE - options &= ~REFRESH_QUERY_CACHE; // Don't flush cache, just free memory + options &= ~REFRESH_QUERY_CACHE; // Don't flush cache, just free memory } if (options & (REFRESH_TABLES | REFRESH_QUERY_CACHE)) { diff --git a/sql/sql_yacc.yy b/sql/sql_yacc.yy index 04db57c5540..c75068f0047 100644 --- a/sql/sql_yacc.yy +++ b/sql/sql_yacc.yy @@ -630,7 +630,6 @@ bool my_yyoverflow(short **a, YYSTYPE **b, ulong *yystacksize); %token VARCHAR %token VARIABLES %token VARIANCE_SYM -%token VARIANCE_SYM %token VARYING %token VIEW_SYM %token WARNINGS From 82571d6b844f0038a639c92c2b1cd1591b71901c Mon Sep 17 00:00:00 2001 From: "serg@serg.mylan" <> Date: Tue, 22 Feb 2005 00:43:37 +0100 Subject: [PATCH 3/3] MYSQL_LOG::recover was trying to allocate 0 bytes - bug#8661 --- sql/log.cc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/sql/log.cc b/sql/log.cc index 6292510f5c0..6cb465f839c 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -3000,11 +3000,11 @@ int TC_LOG_BINLOG::recover(IO_CACHE *log, Format_description_log_event *fdle) MEM_ROOT mem_root; if (! fdle->is_valid() || - hash_init(&xids, &my_charset_bin, tc_log_page_size/3, 0, + hash_init(&xids, &my_charset_bin, TC_LOG_PAGE_SIZE/3, 0, sizeof(my_xid), 0, 0, MYF(0))) goto err1; - init_alloc_root(&mem_root, tc_log_page_size, tc_log_page_size); + init_alloc_root(&mem_root, TC_LOG_PAGE_SIZE, TC_LOG_PAGE_SIZE); fdle->flags&= ~LOG_EVENT_BINLOG_IN_USE_F; // abort on the first error