| Bug #56343 | binlog_cache_use status is greater than expected | ||
|---|---|---|---|
| Submitted: | 28 Aug 2010 7:46 | Modified: | 4 Jan 2011 4:48 |
| Reporter: | Andrei Elkin | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | 5.5+ | OS: | Any |
| Assigned to: | Alfranio Tavares Correia Junior | CPU Architecture: | Any |
| Tags: | regression, transaction cache | ||
[28 Aug 2010 7:46]
Andrei Elkin
[28 Aug 2010 8:07]
Valeriy Kravchuk
Verified just as described: macbook-pro:5.5 openxs$ bin/mysql -uroot test Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 1 Server version: 5.5.6-m3-debug-log Source distribution Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved. This software comes with ABSOLUTELY NO WARRANTY. This is free software, and you are welcome to modify and redistribute it under the GPL v2 license Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> flush status; Query OK, 0 rows affected (0.00 sec) mysql> show status like "binlog_cache_use"; +------------------+-------+ | Variable_name | Value | +------------------+-------+ | Binlog_cache_use | 0 | +------------------+-------+ 1 row in set (0.01 sec) mysql> create table t_i (a int) engine=innodb; Query OK, 0 rows affected (0.45 sec) mysql> begin; insert into t_i values (1); commit; Query OK, 0 rows affected (0.00 sec) Query OK, 1 row affected (0.02 sec) Query OK, 0 rows affected (0.00 sec) mysql> show status like "binlog_cache_use"; +------------------+-------+ | Variable_name | Value | +------------------+-------+ | Binlog_cache_use | 2 | +------------------+-------+ 1 row in set (0.01 sec) mysql> show binlog events; +------------------------+-----+-------------+-----------+-------------+----------------------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | +------------------------+-----+-------------+-----------+-------------+----------------------------------------------------+ | macbook-pro-bin.000001 | 4 | Format_desc | 1 | 107 | Server ver: 5.5.6-m3-debug-log, Binlog ver: 4 | | macbook-pro-bin.000001 | 107 | Query | 1 | 182 | use `test`; flush status | | macbook-pro-bin.000001 | 182 | Query | 1 | 283 | use `test`; create table t_i (a int) engine=innodb | | macbook-pro-bin.000001 | 283 | Query | 1 | 351 | BEGIN | | macbook-pro-bin.000001 | 351 | Query | 1 | 440 | use `test`; insert into t_i values (1) | | macbook-pro-bin.000001 | 440 | Xid | 1 | 467 | COMMIT /* xid=17 */ | +------------------------+-----+-------------+-----------+-------------+----------------------------------------------------+ 6 rows in set (0.00 sec) Compare to 5.1: macbook-pro:5.1 openxs$ bin/mysql -uroot test Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 1 Server version: 5.1.51-debug-log Source distribution Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved. This software comes with ABSOLUTELY NO WARRANTY. This is free software, and you are welcome to modify and redistribute it under the GPL v2 license Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> flush status; Query OK, 0 rows affected (0.00 sec) mysql> show status like "binlog_cache_use"; +------------------+-------+ | Variable_name | Value | +------------------+-------+ | Binlog_cache_use | 0 | +------------------+-------+ 1 row in set (0.02 sec) mysql> create table t_i (a int) engine=innodb; Query OK, 0 rows affected (0.05 sec) mysql> begin; insert into t_i values (1); commit; Query OK, 0 rows affected (0.00 sec) Query OK, 1 row affected (0.00 sec) Query OK, 0 rows affected (0.01 sec) mysql> show status like "binlog_cache_use"; +------------------+-------+ | Variable_name | Value | +------------------+-------+ | Binlog_cache_use | 1 | +------------------+-------+ 1 row in set (0.00 sec) mysql> show binlog events; +------------------------+-----+-------------+-----------+-------------+----------------------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | +------------------------+-----+-------------+-----------+-------------+----------------------------------------------------+ | macbook-pro-bin.000001 | 4 | Format_desc | 1 | 106 | Server ver: 5.1.51-debug-log, Binlog ver: 4 | | macbook-pro-bin.000001 | 106 | Query | 1 | 181 | use `test`; flush status | | macbook-pro-bin.000001 | 181 | Query | 1 | 282 | use `test`; create table t_i (a int) engine=innodb | | macbook-pro-bin.000001 | 282 | Query | 1 | 350 | BEGIN | | macbook-pro-bin.000001 | 350 | Query | 1 | 439 | use `test`; insert into t_i values (1) | | macbook-pro-bin.000001 | 439 | Xid | 1 | 466 | COMMIT /* xid=9 */ | +------------------------+-----+-------------+-----------+-------------+----------------------------------------------------+ 6 rows in set (0.02 sec)
[30 Aug 2010 13:41]
Alfranio Tavares Correia Junior
The problem happens because TC_LOG_BINLOG::log_xid calls both binlog_flush_stmt_cache and binlog_flush_trx_cache without checking if such caches are empty thus unintentionally increasing the binlog_cache_use value twice.
Possible solution:
=== modified file 'sql/log.cc'
--- sql/log.cc 2010-08-20 02:59:58 +0000
+++ sql/log.cc 2010-08-30 13:21:23 +0000
@@ -6278,8 +6278,11 @@
We always commit the entire transaction when writing an XID. Also
note that the return value is inverted.
*/
- DBUG_RETURN(!binlog_flush_stmt_cache(thd, cache_mngr) &&
- !binlog_flush_trx_cache(thd, cache_mngr, &xle));
+ DBUG_RETURN(
+ (!cache_mngr->stmt_cache.empty() ?
+ !binlog_flush_stmt_cache(thd, cache_mngr) : TRUE) &&
+ (!cache_mngr->trx_cache.empty() ?
+ !binlog_flush_trx_cache(thd, cache_mngr, &xle) : TRUE));
}
void TC_LOG_BINLOG::unlog(ulong cookie, my_xid xid)
[30 Aug 2010 13:52]
Alfranio Tavares Correia Junior
This is a regression of BUG#50038.
[2 Sep 2010 17:51]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/117449 3196 Alfranio Correia 2010-09-02 BUG#56343 binlog_cache_use status is bigger than expected The binlog_cache_use is incremented twice when changes to a transactional table is committed and TC_LOG_BINLOG::log_xid calls is called. The problem happens because log_xid calls both binlog_flush_stmt_cache and binlog_flush_trx_cache without checking if such caches are empty thus unintentionally increasing the binlog_cache_use value twice. To fix the problem we did what follows: === modified file 'sql/log.cc' --- sql/log.cc 2010-08-20 02:59:58 +0000 +++ sql/log.cc 2010-08-30 13:21:23 +0000 @@ -6278,8 +6278,11 @@ We always commit the entire transaction when writing an XID. Also note that the return value is inverted. */ - DBUG_RETURN(!binlog_flush_stmt_cache(thd, cache_mngr) && - !binlog_flush_trx_cache(thd, cache_mngr, &xle)); + DBUG_RETURN( + (!cache_mngr->stmt_cache.empty() ? + !binlog_flush_stmt_cache(thd, cache_mngr) : TRUE) && + (!cache_mngr->trx_cache.empty() ? + !binlog_flush_trx_cache(thd, cache_mngr, &xle) : TRUE)); }
[3 Sep 2010 9:40]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/117498 3196 Alfranio Correia 2010-09-03 BUG#56343 binlog_cache_use status is bigger than expected The binlog_cache_use is incremented twice when changes to a transactional table is committed and TC_LOG_BINLOG::log_xid calls is called. The problem happens because log_xid calls both binlog_flush_stmt_cache and binlog_flush_trx_cache without checking if such caches are empty thus unintentionally increasing the binlog_cache_use value twice. To fix the problem we avoided incrementing the binlog_cache_use if the cache is empty. We also re-organized the code in the functions: binlog_flush_trx_cache and binlog_flush_stmt_cache.
[14 Sep 2010 0:22]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/118131 3196 Alfranio Correia 2010-09-14 BUG#56343 binlog_cache_use status is bigger than expected The binlog_cache_use is incremented twice when changes to a transactional table is committed and TC_LOG_BINLOG::log_xid calls is called. The problem happens because log_xid calls both binlog_flush_stmt_cache and binlog_flush_trx_cache without checking if such caches are empty thus unintentionally increasing the binlog_cache_use value twice. To fix the problem we avoided incrementing the binlog_cache_use if the cache is empty. We also re-organized the code around the functions: binlog_flush_trx_cache and binlog_flush_stmt_cache. Note that binlog_cache_use is incremented for both types of cache when they are flushed. However, binlog_cache_use is not incremented when the trx-cache is truncated.
[17 Sep 2010 9:04]
Libing Song
We decided that the variables should be increased even when the cache is truncated and nothing is written to the binary log. So we will do it in the patch.
[24 Sep 2010 9:37]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/119013 3203 Alfranio Correia 2010-09-24 BUG#56343 binlog_cache_use status is bigger than expected The binlog_cache_use is incremented twice when changes to a transactional table are committed, i.e. TC_LOG_BINLOG::log_xid calls is called. The problem happens because log_xid calls both binlog_flush_stmt_cache and binlog_flush_trx_cache without checking if such caches are empty thus unintentionally increasing the binlog_cache_use value twice. To fix the problem we avoided incrementing the binlog_cache_use if the cache is empty. We also decided to increment binlog_cache_use when the cache is truncated as the cache is used although its content is discarded and is not written to the binary log. Note that binlog_cache_use is incremented for both types of cache, transactional and non-transactional and that the behavior presented in this patch also applies to the binlog_cache_disk_use. Finally, we re-organized the code around the functions binlog_flush_trx_cache and binlog_flush_stmt_cache. @ mysql-test/extra/binlog_tests/binlog_cache_stat.test Updated the test case with comments and additional tests to check both transactional and non-transactional changes and what happens when a is transaction either committed or aborted. @ mysql-test/suite/binlog/r/binlog_innodb.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_mixed_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_row_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_stm_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/t/binlog_mixed_cache_stat.test Updated the test case with a new source file. @ mysql-test/suite/binlog/t/binlog_row_cache_stat.test Updated the test case with a new source file. @ mysql-test/suite/binlog/t/binlog_stm_cache_stat.test Updated the test case with a new source file.
[6 Oct 2010 8:36]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/120060 3203 Alfranio Correia 2010-10-06 BUG#56343 binlog_cache_use status is bigger than expected The binlog_cache_use is incremented twice when changes to a transactional table are committed, i.e. TC_LOG_BINLOG::log_xid calls is called. The problem happens because log_xid calls both binlog_flush_stmt_cache and binlog_flush_trx_cache without checking if such caches are empty thus unintentionally increasing the binlog_cache_use value twice. To fix the problem we avoided incrementing the binlog_cache_use if the cache is empty. We also decided to increment binlog_cache_use when the cache is truncated as the cache is used although its content is discarded and is not written to the binary log. Note that binlog_cache_use is incremented for both types of cache, transactional and non-transactional and that the behavior presented in this patch also applies to the binlog_cache_disk_use. Finally, we re-organized the code around the functions binlog_flush_trx_cache and binlog_flush_stmt_cache. @ mysql-test/extra/binlog_tests/binlog_cache_stat.test Updated the test case with comments and additional tests to check both transactional and non-transactional changes and what happens when a is transaction either committed or aborted. @ mysql-test/suite/binlog/r/binlog_innodb.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_mixed_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_row_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_stm_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/t/binlog_mixed_cache_stat.test Updated the test case with a new source file. @ mysql-test/suite/binlog/t/binlog_row_cache_stat.test Updated the test case with a new source file. @ mysql-test/suite/binlog/t/binlog_stm_cache_stat.test Updated the test case with a new source file. @ sql/log_event.cc Introduced debug information to check if Query_log_event("BEGIN"), Query_log_event("COMMIT") and Query_log_event("ROLLBACK"). @ sql/log_event.h Guaranteed Xid_log_event is always classified as a transactional event.
[11 Oct 2010 17:13]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/120520 3230 Alfranio Correia 2010-10-11 [merge] merging BUG#56343 into local.
[27 Oct 2010 14:32]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/122104 3247 Alfranio Correia 2010-10-27 [merge] BUG#56343 binlog_cache_use status is bigger than expected The binlog_cache_use is incremented twice when changes to a transactional table are committed, i.e. TC_LOG_BINLOG::log_xid calls is called. The problem happens because log_xid calls both binlog_flush_stmt_cache and binlog_flush_trx_cache without checking if such caches are empty thus unintentionally increasing the binlog_cache_use value twice. Although not explicitly mentioned in the bug, the binlog_cache_disk_use presents the same problem. The binlog_cache_use and binlog_cache_disk_use are status variables that are incremented when transactional (i.e. trx-cache) or non-transactional (i.e. stmt-cache) changes are committed. They are used to compute the ratio between the use of disk and memory while gathering updates for a transaction. The problem reported is fixed by avoiding incrementing the binlog_cache_use and binlog_cache_disk_use if a cache is empty. We also have decided to increment both variables when a cache is truncated as the cache is used although its content is discarded and is not written to the binary log. In this patch, we take the opportunity to re-organize the code around the function binlog_flush_trx_cache and binlog_flush_stmt_cache. @ mysql-test/extra/binlog_tests/binlog_cache_stat.test Updated the test case with comments and additional tests to check both transactional and non-transactional changes and what happens when a is transaction either committed or aborted. @ mysql-test/suite/binlog/r/binlog_innodb.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_mixed_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_row_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_stm_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/t/binlog_mixed_cache_stat.test Updated the test case with a new source file. @ mysql-test/suite/binlog/t/binlog_row_cache_stat.test Updated the test case with a new source file. @ mysql-test/suite/binlog/t/binlog_stm_cache_stat.test Updated the test case with a new source file. @ sql/log_event.h Guaranteed Xid_log_event is always classified as a transactional event.
[5 Nov 2010 13:59]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/122955 3121 Alfranio Correia 2010-11-05 [merge] BUG#56343 binlog_cache_use status is bigger than expected The binlog_cache_use is incremented twice when changes to a transactional table are committed, i.e. TC_LOG_BINLOG::log_xid calls is called. The problem happens because log_xid calls both binlog_flush_stmt_cache and binlog_flush_trx_cache without checking if such caches are empty thus unintentionally increasing the binlog_cache_use value twice. Although not explicitly mentioned in the bug, the binlog_cache_disk_use presents the same problem. The binlog_cache_use and binlog_cache_disk_use are status variables that are incremented when transactional (i.e. trx-cache) or non-transactional (i.e. stmt-cache) changes are committed. They are used to compute the ratio between the use of disk and memory while gathering updates for a transaction. The problem reported is fixed by avoiding incrementing the binlog_cache_use and binlog_cache_disk_use if a cache is empty. We also have decided to increment both variables when a cache is truncated as the cache is used although its content is discarded and is not written to the binary log. In this patch, we take the opportunity to re-organize the code around the function binlog_flush_trx_cache and binlog_flush_stmt_cache. @ mysql-test/extra/binlog_tests/binlog_cache_stat.test Updated the test case with comments and additional tests to check both transactional and non-transactional changes and what happens when a is transaction either committed or aborted. @ mysql-test/suite/binlog/r/binlog_innodb.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_mixed_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_row_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/r/binlog_stm_cache_stat.result Updated the result file. @ mysql-test/suite/binlog/t/binlog_mixed_cache_stat.test Updated the test case with a new source file. @ mysql-test/suite/binlog/t/binlog_row_cache_stat.test Updated the test case with a new source file. @ mysql-test/suite/binlog/t/binlog_stm_cache_stat.test Updated the test case with a new source file. @ sql/log.cc There are four changes in here: . Computed statistics on binlog_cache_use and binlog_cache_disk_use while resting the cache. . Refactored the code so binlog_flush_cache handles both the trx-cache and stmt-cache. . There are functions that encapsulate the calls to binlog_flush_cache and make easier to read the code. . binlog_commit_flush_stmt_cache is now taking into account the result: success or error. @ sql/log_event.h Guaranteed Xid_log_event is always classified as a transactional event.
[5 Dec 2010 23:15]
Alfranio Tavares Correia Junior
Pushed to mysql-5.5-bugteam and mysql-trunk-bugfixing.
[17 Dec 2010 12:53]
Bugs System
Pushed into mysql-5.5 5.5.9 (revid:georgi.kodinov@oracle.com-20101217124733-p1ivu6higouawv8l) (version source revid:alfranio.correia@oracle.com-20101205220144-82l3gzl3402n7n09) (merge vers: 5.5.8) (pib:24)
[17 Dec 2010 12:57]
Bugs System
Pushed into mysql-trunk 5.6.1 (revid:georgi.kodinov@oracle.com-20101217125013-y8pb3az32rtbplc9) (version source revid:alfranio.correia@oracle.com-20101205225522-jq2quc6jwqxyxqay) (merge vers: 5.6.1) (pib:24)
[4 Jan 2011 4:48]
Jon Stephens
Documented as follows in the 5.5.9 and 5.6.1 changelogs:
The Binlog_cache_use and Binlog_cache_disk_use status variables
were incremented twice by a change to a table using a
transactional storage engine.
Closed.
