| Bug #75966 | metadata_table_reference_count innodb metric goes negative | ||
|---|---|---|---|
| Submitted: | 19 Feb 2015 12:40 | Modified: | 5 Apr 2019 18:21 |
| Reporter: | Shane Bester (Platinum Quality Contributor) | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 8.0.0 | OS: | Windows |
| Assigned to: | CPU Architecture: | Any | |
[23 Feb 2015 10:13]
MySQL Verification Team
Hello Shane, Thank you for the report. Thanks, Umesh
[16 Feb 2016 10:45]
Erlend Dahl
Not reproducible on latest sources.
[18 Jun 2016 21:16]
Omer Barnir
Posted by developer: Reported version value updated to reflect release name change from 5.8 to 8.0
[15 Mar 2019 10:54]
Jakub Lopuszanski
Posted by developer: I can see the problem on today's mysql-trunk: echo "--innodb-monitor-enable=metadata_table_reference_count" > mysql-test/suite/innodb/t/very_simple-master.opt echo "SELECT * FROM information_schema.innodb_metrics WHERE name='metadata_table_reference_count';" > mysql-test/suite/innodb/t/very_simple.test ./mtr --mem very_simple SELECT * FROM information_schema.innodb_metrics WHERE name='metadata_table_reference_count'; NAME SUBSYSTEM COUNT MAX_COUNT MIN_COUNT AVG_COUNT COUNT_RESET MAX_COUNT_RESET MIN_COUNT_RESET AVG_COUNT_RESET TIME_ENABLED TIME_DISABLED TIME_ELAPSED TIME_RESET STATUS TYPE COMMENT metadata_table_reference_count metadata -102 -91 -102 -102 -102 -91 -102 NULL 2019-03-15 13:45:37 NULL 1 NULL enabled counter Table reference counter
[15 Mar 2019 12:14]
Jakub Lopuszanski
Posted by developer:
I've instrumented the code so that it will report to std::cerr all MONITOR_INC/MONITOR_DEC and actuall n_ref_count++/--, as follows [1].
Then I've run the very_simple MTR again, and got the following output:
[jlopusza@supra06]/export/home/jlopusza/mysql-bin/mysql-test: ack dd_table /dev/shm/var_auto_JxiE/log/bootstrap.log | head -n20
dd_table_report_reference(18446744069414584320,1,0)
dd_table_report_reference(18446744069414584320,-1,0)
dd_table_report_monitor(18446744069414584320,-1)
dd_table_report_reference(18446744073709551614,1,0)
dd_table_report_reference(18446744073709551614,-1,0)
dd_table_report_monitor(18446744073709551614,-1)
dd_table_report_reference(1,1,1)
dd_table_report_reference(1,-1,0)
dd_table_report_monitor(1,-1)
dd_table_report_reference(2,1,1)
dd_table_report_reference(2,-1,0)
dd_table_report_monitor(2,-1)
dd_table_report_reference(3,1,1)
dd_table_report_reference(3,-1,0)
dd_table_report_monitor(3,-1)
dd_table_report_reference(4,1,1)
dd_table_report_reference(4,-1,0)
dd_table_report_monitor(4,-1)
dd_table_report_reference(5,1,1)
dd_table_report_reference(5,-1,0)
So, it looks like we are sometimes calling MONITOR_DEC without first calling MONITOR_INC.
In all there were 703 decrements and 124 increments. Which leads to another interesting question: since 124-703 is not equal to the value reported by SQL query which was around -100. Quite possibly this means that even if we enable the counter from the command line, we still miss some increments/decrements.
Could it be that command line arguments are acted upon after we've already done some decrements/increments?
I've compiled a version with MONITOR_DEFAULT_ON instead of MONITOR_DEFAULT_NONE for this counter, and then the `./mtr --mem very_simple` reports still the same values.
Perhaps we call reset on this counter reseting it while it has non zero value?
This is quite possible as it has -51 in COUNT_RESET column, and TIME_RESET equal to 2.
Still, something is very wrong with this all, as COUNT should track the value from the beginning regardless of resets.
Another theory is that perhaps we loose some values because we use MONITOR_INC/MONITOR_DEC instead of MONITOR_ATOMIC_INC/MONITOR_ATOMIC_DEC ?
I've tried recompiling with MONITOR_ATOMIC_INC/DEC, and I've run MTR again. This didn't change anything.
So, it looks like the monitor is actually turned OFF while we perform some of increments/decrements.
So, I've augmented debug output to include the state of the monitor, by means of `MONITOR_IS_ON(MONITOR_TABLE_REFERENCE)`.
Indeed
[jlopusza@supra06]/export/home/jlopusza/mysql-bin/mysql-test: ack dd_table_report_monitor /dev/shm/var_auto_CGBJ/log/bootstrap.log | ack 'OFF' | wc -l
2
[jlopusza@supra06]/export/home/jlopusza/mysql-bin/mysql-test: ack dd_table_report_monitor /dev/shm/var_auto_CGBJ/log/bootstrap.log | ack 'ON' | wc -l
821
However, this only explains why we didn't count 2 decrements out of many many more missing.
Finally, I've realized I'm looking at a wrong error log file: there are two, one for "bootstraping" phase of MTR and the other for running actual test:
[jlopusza@supra06]/export/home/jlopusza/mysql-bin/mysql-test: ack dd_table_report_monitor /dev/shm/var_auto_CGBJ/log/mysqld.1.err | ack 'ON' | wc -l
201
[jlopusza@supra06]/export/home/jlopusza/mysql-bin/mysql-test: ack dd_table_report_monitor /dev/shm/var_auto_CGBJ/log/mysqld.1.err | ack 'OFF' | wc -l
0
[jlopusza@supra06]/export/home/jlopusza/mysql-bin/mysql-test: ack dd_table_report_monitor /dev/shm/var_auto_CGBJ/log/mysqld.1.err | ack ',1' | wc -l
18
[jlopusza@supra06]/export/home/jlopusza/mysql-bin/mysql-test: ack dd_table_report_monitor /dev/shm/var_auto_CGBJ/log/mysqld.1.err | ack ',-1' | wc -l
183
[jlopusza@supra06]/export/home/jlopusza/mysql-bin/mysql-test: ack dd_table_report_monitor /dev/shm/var_auto_CGBJ/log/bootstrap.log | ack ',-1' | wc -l
701
[jlopusza@supra06]/export/home/jlopusza/mysql-bin/mysql-test: ack dd_table_report_monitor /dev/shm/var_auto_CGBJ/log/bootstrap.log | ack ',1' | wc -l
122
Please note, that still, neither 18-183, nor 122-701, nor (18+122)-(183-701), explains why we report COUNT -102:
NAME SUBSYSTEM COUNT MAX_COUNT MIN_COUNT AVG_COUNT COUNT_RESET MAX_COUNT_RESET MIN_COUNT_RESET AVG_COUNT_RESET TIME_ENABLED TIME_DISABLED TIME_ELAPSED TIME_RESET STATUS TYPE COMMENT
metadata_table_reference_count metadata -102 -91 NULL -51 -102 -91 NULL NULL 2019-03-15 14:56:56 NULL 2 NULL enabled counter Table reference counter
Very mysterious.
I've then added calls to `if(delta<0)my_print_stacktrace(nullptr, 0);` to `dd_table_report_monitor(,delta)` and these are examples of stacktraces:
Example 1
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x2e) [0x1ce08de]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0x2028239]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dict_table_close(dict_table_t*, unsigned long, unsigned long)+0x18e) [0x202f40e]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(btr_sdi_create_index(unsigned int, bool)+0x2a1) [0x1fab851]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(srv_start(bool, std::string const&)+0x330d) [0x1f266ed]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0x1dc98f1]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::bootstrap::DDSE_dict_init(THD*, dict_init_mode_t, unsigned int)+0x81) [0x1a4e4e1]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::bootstrap::initialize(THD*)+0x7a) [0x1a5138a]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0xf13161]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0x217c52f]
/lib64/libpthread.so.0(+0x7dd5) [0x7f180040edd5]
/lib64/libc.so.6(clone+0x6d) [0x7f17fe7f4f6d]
Example 2
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x2e) [0x1ce08de]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0x2028239]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dict_table_close(dict_table_t*, unsigned long, unsigned long)+0x18e) [0x202f40e]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(btr_sdi_create_index(unsigned int, bool)+0x2a1) [0x1fab851]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0x1dcad7c]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::bootstrap::DDSE_dict_init(THD*, dict_init_mode_t, unsigned int)+0x81) [0x1a4e4e1]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::bootstrap::initialize(THD*)+0x7a) [0x1a5138a]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0xf13161]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0x217c52f]
/lib64/libpthread.so.0(+0x7dd5) [0x7f180040edd5]
/lib64/libc.so.6(clone+0x6d) [0x7f17fe7f4f6d]
Example 3
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x2e) [0x1ce08de]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0x2028239]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dict_table_close(dict_table_t*, unsigned long, unsigned long)+0x18e) [0x202f40e]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd_table_close(dict_table_t*, THD*, MDL_ticket**, bool)+0x17) [0x203c077]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(row_create_index_for_mysql(dict_index_t*, trx_t*, unsigned long const*, dict_table_t*)+0x27c) [0x1ecafec]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(create_table_info_t::create_table(dd::Table const*)+0x754) [0x1db4254]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(int innobase_basic_ddl::create_impl<dd::Table>(THD*, char const*, TABLE*, HA_CREATE_INFO*, dd::Table*, bool, bool, bool, unsigned long, unsigned long)+0x185) [0x1dbd955]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*, dd::Table*)+0x7b) [0x1dcd22b]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, bool, bool, dd::Table*)+0xd37) [0xf6d447]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0xdc90c3]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(mysql_create_table_no_lock(THD*, char const*, char const*, HA_CREATE_INFO*, Alter_info*, unsigned int, bool, bool*, handlerton**)+0x54b) [0xdc9a7b]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(mysql_create_table(THD*, TABLE_LIST*, HA_CREATE_INFO*, Alter_info*)+0x5d5) [0xdca265]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Sql_cmd_create_table::execute(THD*)+0x615) [0x110dcd5]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(mysql_execute_command(THD*, bool)+0x237a) [0xd431aa]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Execute_sql_statement::execute_server_code(THD*)+0x1cf) [0xd6f05f]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Prepared_statement::execute_server_runnable(Server_runnable*)+0x1fe) [0xd7033e]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Ed_connection::execute_direct(Server_runnable*)+0x9a) [0xd71a4a]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Ed_connection::execute_direct(MYSQL_LEX_STRING)+0x25) [0xd71b55]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::execute_query(THD*, std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> > const&)+0x57) [0x1a425f7]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::initialize_dd_properties(THD*)+0x57) [0x1a4c3b7]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::bootstrap::initialize_dictionary(THD*, bool, dd::Dictionary_impl*)+0x58) [0x1a50e58]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::bootstrap::initialize(THD*)+0x8b) [0x1a5139b]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0xf13161]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0x217c52f]
Example 4
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dict_table_close(dict_table_t*, unsigned long, unsigned long)+0x18e) [0x202f40e]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd_table_close(dict_table_t*, THD*, MDL_ticket**, bool)+0x17) [0x203c077]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(row_create_index_for_mysql(dict_index_t*, trx_t*, unsigned long const*, dict_table_t*)+0x27c) [0x1ecafec]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(create_index(trx_t*, TABLE const*, unsigned long, char const*, unsigned int, dd::Table const*)+0x5fa) [0x1dad19a]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(create_table_info_t::create_table(dd::Table const*)+0x477) [0x1db3f77]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(int innobase_basic_ddl::create_impl<dd::Table>(THD*, char const*, TABLE*, HA_CREATE_INFO*, dd::Table*, bool, bool, bool, unsigned long, unsigned long)+0x185) [0x1dbd955]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*, dd::Table*)+0x7b) [0x1dcd22b]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, bool, bool, dd::Table*)+0xd37) [0xf6d447]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0xdc90c3]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(mysql_create_table_no_lock(THD*, char const*, char const*, HA_CREATE_INFO*, Alter_info*, unsigned int, bool, bool*, handlerton**)+0x54b) [0xdc9a7b]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(mysql_create_table(THD*, TABLE_LIST*, HA_CREATE_INFO*, Alter_info*)+0x5d5) [0xdca265]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Sql_cmd_create_table::execute(THD*)+0x615) [0x110dcd5]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(mysql_execute_command(THD*, bool)+0x237a) [0xd431aa]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Execute_sql_statement::execute_server_code(THD*)+0x1cf) [0xd6f05f]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Prepared_statement::execute_server_runnable(Server_runnable*)+0x1fe) [0xd7033e]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Ed_connection::execute_direct(Server_runnable*)+0x9a) [0xd71a4a]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(Ed_connection::execute_direct(MYSQL_LEX_STRING)+0x25) [0xd71b55]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::execute_query(THD*, std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> > const&)+0x57) [0x1a425f7]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::create_tables(THD*, std::set<std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> >, std::less<std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> > >, std::allocator<std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> > > > const*)+0x267) [0x1a496d7]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::bootstrap::initialize_dictionary(THD*, bool, dd::Dictionary_impl*)+0x66) [0x1a50e66]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld(dd::bootstrap::initialize(THD*)+0x8b) [0x1a5139b]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0xf13161]
/export/home/jlopusza/mysql-bin/runtime_output_directory/mysqld() [0x217c52f]
/lib64/libpthread.so.0(+0x7dd5) [0x7f180040edd5]
/lib64/libc.so.6(clone+0x6d) [0x7f17fe7f4f6d]
[1]
diff --git a/storage/innobase/dict/dict0dict.cc b/storage/innobase/dict/dict0dict.cc
index 7a9e794..9a5108a 100644
--- a/storage/innobase/dict/dict0dict.cc
+++ b/storage/innobase/dict/dict0dict.cc
@@ -549,6 +549,7 @@ void dict_table_close(dict_table_t *table, /*!< in/out: table */
dict_stats_deinit(table);
}
+ dd_table_report_monitor(table->id,-1);
MONITOR_DEC(MONITOR_TABLE_REFERENCE);
if (!dict_locked) {
@@ -1119,6 +1120,7 @@ dict_table_t *dict_table_open_on_name(
table->acquire();
+ dd_table_report_monitor(table->id,+1);
MONITOR_INC(MONITOR_TABLE_REFERENCE);
}
diff --git a/storage/innobase/include/dict0dd.ic b/storage/innobase/include/dict0dd.ic
index faaee97..5b5aff7 100644
--- a/storage/innobase/include/dict0dd.ic
+++ b/storage/innobase/include/dict0dd.ic
@@ -38,6 +38,11 @@ this program; if not, write to the Free Software Foundation, Inc.,
#include "sql/table.h"
#include "sql_base.h"
+UNIV_INLINE
+void dd_table_report_monitor(table_id_t id,int delta){
+ std::cerr << "dd_table_report_monitor(" << id << "," << delta << ")" << std::endl;
+}
+
/** Get the explicit dd::Tablespace::id of a partition.
@param[in] partition partition or subpartition
@return the explicit dd::Tablespace::id
@@ -251,6 +256,7 @@ inline dict_table_t *dd_table_open_on_id_in_mem(table_id_t table_id,
table->acquire();
+ dd_table_report_monitor(table->id,+1);
MONITOR_INC(MONITOR_TABLE_REFERENCE);
}
@@ -284,6 +290,7 @@ inline dict_table_t *dd_table_open_on_name_in_mem(const char *name,
table->acquire();
+ dd_table_report_monitor(table->id,+1);
MONITOR_INC(MONITOR_TABLE_REFERENCE);
}
diff --git a/storage/innobase/include/dict0dict.ic b/storage/innobase/include/dict0dict.ic
index e153989..f078684 100644
--- a/storage/innobase/include/dict0dict.ic
+++ b/storage/innobase/include/dict0dict.ic
@@ -38,6 +38,12 @@ this program; if not, write to the Free Software Foundation, Inc.,
#include "srv0srv.h"
#include "sync0rw.h"
+UNIV_INLINE
+void dd_table_report_reference(table_id_t id,int delta,bool locked){
+ std::cerr << "dd_table_report_reference(" << id << "," << delta << ',' << locked << ")" << std::endl;
+}
+
+
/** Gets the column number.
@return col->ind, table column position (starting from 0) */
UNIV_INLINE
@@ -1201,6 +1207,7 @@ inline uint64_t dict_table_t::get_ref_count() const { return (n_ref_count); }
/** Acquire the table handle. */
inline void dict_table_t::acquire() {
ut_ad(mutex_own(&dict_sys->mutex) || is_intrinsic());
+ dd_table_report_reference(id, +1, false);
++n_ref_count;
}
@@ -1214,6 +1221,7 @@ inline void dict_table_t::acquire_with_lock() {
n_ref_count, or finds the n_ref_count is not 0, so not to destry the stats
information. */
lock();
+ dd_table_report_reference(id, +1, true);
++n_ref_count;
unlock();
}
@@ -1221,6 +1229,7 @@ inline void dict_table_t::acquire_with_lock() {
/** Release the table handle. */
inline void dict_table_t::release() {
ut_ad(n_ref_count > 0);
+ dd_table_report_reference(id, -1, false);
--n_ref_count;
}
[15 Mar 2019 13:51]
Jakub Lopuszanski
Posted by developer: OK, I was silly: there is no wonder that the balance in error log file is different then the one reported information_schema.innodb_metrics, because AFTER the query is performed there are some further MONITOR_INC/DEC going on, in particular quite a lot of them after shut-down. If I run the server myself (bin/mysql --socket=data/socket --user=root) and perform the query, I get COUNT = -96, and if at the same time I query the logs I get numbers which are in agreement with this result: [jlopusza@supra06]/export/home/jlopusza/mysql-bin: ack dd_table_report_monitor run.log | ack ',-1' | wc -l 100 [jlopusza@supra06]/export/home/jlopusza/mysql-bin: ack dd_table_report_monitor run.log | ack ',1' | wc -l 4 4-100 = 96. So, the only mistery left is why do we perform more decrements than increments.
[15 Mar 2019 14:28]
Jakub Lopuszanski
Posted by developer:
By using following awk script, I tried to find the increments of refcount which are missing MONITOR_INC, yet the corresponding decrement of refcount calls MONITOR_DEC:
Increment of reference count for table 1 at
mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x2e) [0x1ce08fe]
mysqld() [0x203bd38]
mysqld(dict_table_t* dd_open_table_one<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*, std::deque<char const*, ut_allocator<char const*> >&)+0x178c) [0x204e92c]
mysqld(dict_table_t* dd_open_table<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*)+0xb4) [0x2050044]
mysqld(ha_innobase::open(char const*, int, unsigned int, dd::Table const*)+0x1044) [0x1dce554]
mysqld(handler::ha_open(TABLE*, char const*, int, int, dd::Table const*)+0x53) [0xf62d03]
mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*)+0x1276) [0xe225e6]
mysqld(open_table(THD*, TABLE_LIST*, Open_table_context*)+0x1166) [0xcde036]
mysqld(open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x493) [0xce37d3]
mysqld(dd::Open_dictionary_tables_ctx::open_tables()+0xa6) [0x1c86966]
mysqld(dd::tables::DD_properties::init_cached_properties(THD*)+0x180) [0x1b530d0]
mysqld(dd::tables::DD_properties::unchecked_get(THD*, std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> > const&, std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> >*, bool*)+0x22) [0x1b53462]
mysqld(dd::tables::DD_properties::get(THD*, std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> > const&, unsigned int*, bool*)+0x2b) [0x1b5369b]
mysqld(dd::initialize_dd_properties(THD*)+0x28a) [0x1a4c60a]
mysqld(dd::bootstrap::restart(THD*)+0x8c) [0x1a5157c]
mysqld() [0x1c7ed41]
mysqld(dd::upgrade_57::do_pre_checks_and_initialize_dd(THD*)+0x7c8) [0x1c85418]
mysqld() [0xf13181]
mysqld() [0x217c76f]
Did not cause MONITOR_INC, but there was a MONITOR_DEC for this table at
mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x2e) [0x1ce08fe]
mysqld() [0x2028d19]
mysqld(dict_table_close(dict_table_t*, unsigned long, unsigned long)+0x175) [0x202f765]
mysqld(dd_table_close(dict_table_t*, THD*, MDL_ticket**, bool)+0x17) [0x203c307]
mysqld(row_prebuilt_free(row_prebuilt_t*, unsigned long)+0x2a6) [0x1ec6806]
mysqld(ha_innobase::close()+0x2b) [0x1dac24b]
mysqld(closefrm(TABLE*, bool)+0x189) [0xe1b519]
mysqld(intern_close_table(TABLE*)+0x3d) [0xcd357d]
mysqld(Table_cache::free_all_unused_tables()+0x58) [0xe22d38]
mysqld(Table_cache_manager::free_all_unused_tables()+0x43) [0xe23433]
mysqld(close_cached_tables(THD*, TABLE_LIST*, bool, unsigned long)+0xbf) [0xcdab5f]
mysqld(handle_reload_request(THD*, unsigned long, TABLE_LIST*, int*)+0x180) [0xd76d40]
mysqld(mysql_execute_command(THD*, bool)+0x8d5) [0xd41725]
mysqld(Execute_sql_statement::execute_server_code(THD*)+0x1cf) [0xd6f07f]
mysqld(Prepared_statement::execute_server_runnable(Server_runnable*)+0x1fe) [0xd7035e]
mysqld(Ed_connection::execute_direct(Server_runnable*)+0x9a) [0xd71a6a]
mysqld(Ed_connection::execute_direct(MYSQL_LEX_STRING)+0x25) [0xd71b75]
mysqld(dd::execute_query(THD*, std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> > const&)+0x57) [0x1a42617]
mysqld(dd::sync_meta_data(THD*)+0xa56) [0x1a4b7e6]
mysqld(dd::bootstrap::restart(THD*)+0xd6) [0x1a515c6]
mysqld() [0x1c7ed41]
mysqld(dd::upgrade_57::do_pre_checks_and_initialize_dd(THD*)+0x7c8) [0x1c85418]
mysqld() [0xf13181]
mysqld() [0x217c76f]
Increment of reference count for table 31 at
and many more.
Most popular seem to be:
10
mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x2e) [0x1ce08fe]
mysqld() [0x203bd38]
mysqld(dict_table_t* dd_open_table_one<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*, std::deque<char const*, ut_allocator<char const*> >&)+0x178c) [0x204e92c]
mysqld(dict_table_t* dd_open_table<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*)+0xb4) [0x2050044]
mysqld(ha_innobase::open(char const*, int, unsigned int, dd::Table const*)+0x1044) [0x1dce554]
mysqld(handler::ha_open(TABLE*, char const*, int, int, dd::Table const*)+0x53) [0xf62d03]
mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*)+0x1276) [0xe225e6]
mysqld(open_table(THD*, TABLE_LIST*, Open_table_context*)+0x1166) [0xcde036]
mysqld(open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x493) [0xce37d3]
mysqld(open_and_lock_tables(THD*, TABLE_LIST*, unsigned int, Prelocking_strategy*)+0x68) [0xce4128]
mysqld(check_engine_type_for_acl_table(THD*)+0x5de) [0xeb350e]
mysqld(acl_init(bool)+0xaa) [0xec363a]
mysqld(mysqld_main(int, char**)+0x3855) [0xc675e5]
mysqld() [0xc55535]
14
mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x2e) [0x1ce08fe]
mysqld() [0x203bd38]
mysqld(dict_table_t* dd_open_table_one<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*, std::deque<char const*, ut_allocator<char const*> >&)+0x178c) [0x204e92c]
mysqld(dict_table_t* dd_open_table<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*)+0xb4) [0x2050044]
mysqld(ha_innobase::open(char const*, int, unsigned int, dd::Table const*)+0x1044) [0x1dce554]
mysqld(handler::ha_open(TABLE*, char const*, int, int, dd::Table const*)+0x53) [0xf62d03]
mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*)+0x1276) [0xe225e6]
mysqld(open_table(THD*, TABLE_LIST*, Open_table_context*)+0x1166) [0xcde036]
mysqld(open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x493) [0xce37d3]
mysqld(dd::Open_dictionary_tables_ctx::open_tables()+0xa6) [0x1c86966]
mysqld(bool dd::cache::Storage_adapter::get<dd::Item_name_key, dd::Abstract_table>(THD*, dd::Item_name_key const&, enum_tx_isolation, bool, dd::Abstract_table const**)+0xa0) [0x1ab0970]
mysqld(dd::sync_meta_data(THD*)+0x570) [0x1a4b300]
mysqld(dd::bootstrap::restart(THD*)+0xd6) [0x1a515c6]
mysqld() [0x1c7ed41]
mysqld(dd::upgrade_57::do_pre_checks_and_initialize_dd(THD*)+0x7c8) [0x1c85418]
mysqld() [0xf13181]
mysqld() [0x217c76f]
14
mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x2e) [0x1ce08fe]
mysqld(dict_table_t::acquire_with_lock()+0x217) [0x1db58e7]
mysqld(ha_innobase::open(char const*, int, unsigned int, dd::Table const*)+0x10d6) [0x1dce5e6]
mysqld(handler::ha_open(TABLE*, char const*, int, int, dd::Table const*)+0x53) [0xf62d03]
mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*)+0x1276) [0xe225e6]
mysqld(open_table(THD*, TABLE_LIST*, Open_table_context*)+0x1166) [0xcde036]
mysqld(open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x493) [0xce37d3]
mysqld(dd::Open_dictionary_tables_ctx::open_tables()+0xa6) [0x1c86966]
mysqld(bool dd::cache::Storage_adapter::get<dd::Item_name_key, dd::Abstract_table>(THD*, dd::Item_name_key const&, enum_tx_isolation, bool, dd::Abstract_table const**)+0xa0) [0x1ab0970]
mysqld(bool dd::cache::Shared_dictionary_cache::get<dd::Item_name_key, dd::Abstract_table>(THD*, dd::Item_name_key const&, dd::cache::Cache_element<dd::Abstract_table>**)+0x49) [0x1aa6589]
mysqld(bool dd::cache::Dictionary_client::acquire<dd::Item_name_key, dd::Abstract_table>(dd::Item_name_key const&, dd::Abstract_table const**, bool*, bool*)+0x21b) [0x1a69f4b]
mysqld(bool dd::cache::Dictionary_client::acquire<dd::Abstract_table>(std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> > const&, std::basic_string<char, std::char_traits<char>, Stateless_allocator<char, dd::String_type_alloc, My_free_functor> > const&, dd::Abstract_table const**)+0x159) [0x1a6b599]
mysqld(dd::table_exists(dd::cache::Dictionary_client*, char const*, char const*, bool*)+0x88) [0x1a16288]
mysqld(open_table(THD*, TABLE_LIST*, Open_table_context*)+0xde5) [0xcddcb5]
mysqld(open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x493) [0xce37d3]
mysqld(open_and_lock_tables(THD*, TABLE_LIST*, unsigned int, Prelocking_strategy*)+0x68) [0xce4128]
mysqld(open_n_lock_single_table(THD*, TABLE_LIST*, thr_lock_type, unsigned int, Prelocking_strategy*)+0x3c) [0xce41cc]
mysqld(System_table_access::open_table(THD*, MYSQL_LEX_STRING, MYSQL_LEX_STRING, unsigned int, thr_lock_type, TABLE**, Open_tables_backup*)+0x668) [0x19a69e8]
mysqld(Gtid_table_access_context::init(THD**, TABLE**, bool)+0x9c) [0x1953ffc]
mysqld(Gtid_table_persistor::fetch_gtids(Gtid_set*)+0xbb) [0x195583b]
mysqld(mysqld_main(int, char**)+0x2d0a) [0xc66a9a]
mysqld() [0xc55535]
56
mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x2e) [0x1ce08fe]
mysqld(dict_table_t::acquire_with_lock()+0x217) [0x1db58e7]
mysqld(ha_innobase::open(char const*, int, unsigned int, dd::Table const*)+0x10d6) [0x1dce5e6]
mysqld(handler::ha_open(TABLE*, char const*, int, int, dd::Table const*)+0x53) [0xf62d03]
mysqld(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*)+0x1276) [0xe225e6]
mysqld(open_table(THD*, TABLE_LIST*, Open_table_context*)+0x1166) [0xcde036]
mysqld(open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)+0x493) [0xce37d3]
mysqld(dd::Open_dictionary_tables_ctx::open_tables()+0xa6) [0x1c86966]
mysqld(bool dd::cache::Dictionary_client::fetch<dd::View>(std::vector<dd::View const*, std::allocator<dd::View const*> >*, dd::Object_key const*)+0x19f) [0x1a63a1f]
mysqld(bool dd::cache::Dictionary_client::fetch_schema_components<dd::View>(dd::Schema const*, std::vector<dd::View const*, std::allocator<dd::View const*> >*)+0x3c) [0x1a63bcc]
mysqld() [0x1c6d8ea]
mysqld(dd::info_schema::update_I_S_metadata(THD*)+0x188) [0x1c6ea58]
mysqld() [0xf13181]
mysqld() [0x217c76f]
[15 Mar 2019 14:46]
MySQL Verification Team
It might help in debugging to run server with --table-open-cache-instances=1 !
[15 Mar 2019 14:50]
Jakub Lopuszanski
Posted by developer:
Looking at commit 54386a631691 Date: Thu Feb 17 06:06:09 2011 -0800 it looks like the initial intent for MONITOR_TABLE_REFERENCE was to keep track each increment and ecrement of n_ref_count:
--- a/storage/innobase/dict/dict0dict.c
+++ b/storage/innobase/dict/dict0dict.c
@@ -394,6 +394,8 @@ dict_table_close(
--table->n_ref_count;
+ MONITOR_DEC(MONITOR_TABLE_REFERENCE);
+
ut_ad(dict_lru_validate());
#ifdef UNIV_DEBUG
@@ -689,6 +691,8 @@ dict_table_open_on_id(
}
++table->n_ref_count;
+
+ MONITOR_INC(MONITOR_TABLE_REFERENCE);
}
if (!dict_locked) {
@@ -844,6 +848,8 @@ dict_table_open_on_name_low(
}
++table->n_ref_count;
+
+ MONITOR_INC(MONITOR_TABLE_REFERENCE);
}
at that time these were the only three places this field was modified:
[jlopusza@supra06]/export/home/jlopusza/5.7/mysql/storage/innobase: ack n_ref_count
handler/handler0alter.cc
804: ut_a(innodb_table->n_ref_count == 2);
936: ut_a(innodb_table->n_ref_count == 1);
937: ut_a(indexed_table->n_ref_count == 0);
958: ut_a(innodb_table->n_ref_count == 1);
962: ut_a(innodb_table->n_ref_count == 0);
1016: ut_a(!new_primary || innodb_table->n_ref_count == 1);
handler/i_s.cc
4498: table->n_ref_count));
include/dict0mem.h
645: ulint n_ref_count;
row/row0merge.c
2587: ut_a(table->n_ref_count == 0);
row/row0mysql.c
3284: if (table->n_ref_count == 0) {
3287: } else if (table->n_ref_count > 0 || table->n_rec_locks > 0) {
3701: if (table->n_ref_count > 0) {
dict/dict0dict.c
393: ut_a(table->n_ref_count > 0);
395: --table->n_ref_count;
693: ++table->n_ref_count;
850: ++table->n_ref_count;
1083: if (table->n_ref_count == 0) {
1088: a window where the table->n_ref_count can be zero but
1568: ut_a(table->n_ref_count == 0);
lock/lock0lock.c
1767: ut_ad(index->table->n_ref_count > 0 || !index->table->can_be_evicted);
3833: ut_ad(table->n_ref_count > 0 || !table->can_be_evicted);
Therefore, I think it is logical to move MONITOR_INC/MONITOR_DEC inside dict_table_t::acquire/acquire_with_lock/release and be done with this mess.
[5 Apr 2019 18:21]
Daniel Price
Posted by developer: Fixed as of the upcoming 8.0.17 release, and here's the changelog entry: The INNODB_METRICS metadata_table_reference_count counter reported a negative value.
Description: mysql> select * from information_schema.innodb_metrics where name='metadata_table_reference_count'\G *************************** 1. row *************************** NAME: metadata_table_reference_count SUBSYSTEM: metadata COUNT: -314893 MAX_COUNT: -39 MIN_COUNT: -314893 AVG_COUNT: -72.40584042308576 COUNT_RESET: -314893 MAX_COUNT_RESET: -39 MIN_COUNT_RESET: -314893 AVG_COUNT_RESET: NULL TIME_ENABLED: 2015-02-19 12:59:32 TIME_DISABLED: 2015-02-19 14:12:01 TIME_ELAPSED: 4349 TIME_RESET: NULL STATUS: disabled TYPE: counter COMMENT: Table reference counter 1 row in set (0.00 sec) How to repeat: was just running some random queries, nothing special. Suggested fix: dunno, probably need to see where the unbalanced calls are made from. MONITOR_DEC(MONITOR_TABLE_REFERENCE); MONITOR_INC(MONITOR_TABLE_REFERENCE);