Bug #75966 metadata_table_reference_count innodb metric goes negative
Submitted: 19 Feb 2015 12:40 Modified: 5 Apr 18:21
Reporter: Shane Bester (Platinum Quality Contributor) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:8.0.0 OS:Microsoft Windows
Assigned to: CPU Architecture:Any

[19 Feb 2015 12:40] Shane Bester
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);
[23 Feb 2015 10:13] Umesh Shastry
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 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 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 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 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 14:46] Shane Bester
It might help in debugging to run server with --table-open-cache-instances=1 !
[15 Mar 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 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.