Bug #29071 invalid Open_files or Slave_open_temp_tables value in show global status
Submitted: 13 Jun 2007 12:15 Modified: 29 Aug 2017 9:12
Reporter: Shane Bester (Platinum Quality Contributor) Email Updates:
Status: Won't fix Impact on me:
None 
Category:MySQL Server: General Severity:S3 (Non-critical)
Version:5.0.66, 5.0.72,5.1.41, 5.1.49 OS:Any (MS Windows vista, xp, Mac)
Assigned to: Assigned Account CPU Architecture:Any
Tags: Open_files, Slave_open_temp_tables, status variables

[13 Jun 2007 12:15] Shane Bester
Description:
I saw this today:

mysql> show global status like '%ope%';
+------------------------+------------+
| Variable_name          | Value      |
+------------------------+------------+
| Com_ha_open            | 0          |
| Com_show_open_tables   | 2          |
| Open_files             | 4294967173 |<--------
| Open_streams           | 0          |
| Open_table_definitions | 2          |
| Open_tables            | 1          |
| Opened_tables          | 7319       |
| Slave_open_temp_tables | 0          |
+------------------------+------------+
8 rows in set (0.00 sec)

How to repeat:
no testcase yet.

ran mysqld with --flush-time=1 --table_open_cache=300 --open_files_limit=2030

and did a bunch of operations on tables with over 1000 partitions.

Suggested fix:
either find the code that forgets to increment/decrement the counter - or protect the variable with a mutex to avoid dirty reads by show global status.
[18 Jul 2007 8:39] MySQL Verification Team
Saw this again today.  While running long-running tests for bug #29838 on windows, I had not correctly set the maximum number of open files mysqld-nt.exe can access.  Also, I guess too many connections.  All this caused many error 24 to be returned.

DBD::mysql::st execute failed: Can't open file: '.\test\test0.frm' (errno: 24) at go.pl
DBD::mysql::st execute failed: Can't open file: '.\test\test0.frm' (errno: 24) at go.pl
DBD::mysql::st execute failed: Can't open file: '.\test\test0.frm' (errno: 24) at go.pl
DBD::mysql::st execute failed: Can't open file: '.\test\test2.frm' (errno: 24) at go.pl
DBD::mysql::st execute failed: Can't open file: '.\test\test2.frm' (errno: 24) at go.pl

mysql> show global status like '%open%';
+------------------------+------------+
| Variable_name          | Value      |
+------------------------+------------+
| Com_ha_open            | 0          |
| Com_show_open_tables   | 1          |
| Open_files             | 4294956328 | <-------- impossible
| Open_streams           | 0          |
| Open_tables            | 1          |
| Opened_tables          | 684873     |
| Slave_open_temp_tables | 0          |
+------------------------+------------+
7 rows in set (0.00 sec)

I guess some path in the code is not decrementing the counter. Some path can be when either MYI or MYD isn't opened?
[8 Aug 2007 21:28] MySQL Verification Team
start with --skip-grant-tables --open_files_limit=16 --table_cache=1 --max_connections=1 and paste the sql..

Attachment: bug29071_testcase.sql (application/octet-stream, text), 6.55 KiB.

[8 Aug 2007 21:31] MySQL Verification Team
above testcase ends like this on my 5.0.48 on Vista:

00 rows in set (4.92 sec)

ysql> show global status like '%open_files%';
---------------+------------+
 Variable_name | Value      |
---------------+------------+
 Open_files    | 4294967208 |
---------------+------------+
 row in set (0.00 sec)

I suspect that my_file_opened is decremented too many times.
[11 Feb 2008 9:40] Tatiana Azundris Nuernberg
tested on Windows XP and Linux; cannot reproduce there;
presumed fixed by the Bug#31066 / Bug#31177 / Bug#32757 patch family.
[11 Feb 2008 9:41] Tatiana Azundris Nuernberg
More specifically, test with current bk version 5.0.56
[26 Feb 2008 15:04] MySQL Verification Team
yes, 5.1.24 does indeed look fixed:

...
mysql> show global status like '%open_files%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Open_files    | 2     |
+---------------+-------+
1 row in set (0.01 sec)

mysql> select version();
+-----------------+
| version()       |
+-----------------+
| 5.1.24-rc-debug |
+-----------------+
1 row in set (0.00 sec)
[4 Jul 2008 4:38] MySQL Verification Team
reopening this bug and assigning to myself.  the problem still exists in 5.0.66:

mysql> show global status where variable_name in ('open_files');
+---------------+------------+
| Variable_name | Value      |
+---------------+------------+
| Open_files    | 4294965401 |
+---------------+------------+
1 row in set (0.02 sec)

mysql> select version();
+--------------+
| version()    |
+--------------+
| 5.0.66-debug |
+--------------+
1 row in set (0.03 sec)
[7 Jan 2009 10:37] MySQL Verification Team
easy to reproduce the bug on 5.0.72 when alot of temporary tables are created and dropped.
[1 Dec 2009 19:34] MySQL Verification Team
seen again on 5.1.41.  it happens after receiving a few errno 24 and a few flush tables are run.
[4 Dec 2009 9:47] Sveta Smirnova
See also bug #49450 which shows some problem with counters and can be duplicate of this one.
[7 Dec 2009 10:44] Sveta Smirnova
Thank you for the feedback.

Verified as described.

This can happen if my_strdup call fail in parallel threads while my_file_opened was 0.

To repeat:

1. Change 5.1 sources in this fashion:

$bzr diff
=== modified file 'mysys/my_open.c'
--- mysys/my_open.c     2007-10-11 15:07:40 +0000
+++ mysys/my_open.c     2009-12-07 10:30:21 +0000
@@ -155,7 +155,12 @@
     else
     {
       pthread_mutex_lock(&THR_LOCK_open);
-      if ((my_file_info[fd].name = (char*) my_strdup(FileName,MyFlags)))
+      if ( (0 != strcmp("./test/t0.frm", FileName))
+                         && (0 != strcmp("./test/t0.MYD", FileName))
+                         && (0 != strcmp("./test/t1.frm", FileName))
+                         && (0 != strcmp("./test/t1.MYD", FileName))
+                         &&
+                         (my_file_info[fd].name = (char*) my_strdup(FileName,MyFlags)))
       {
         my_file_opened++;
         my_file_total_opened++;
@@ -167,6 +172,9 @@
         DBUG_PRINT("exit",("fd: %d",fd));
         DBUG_RETURN(fd);
       }
+         fprintf(stderr, "my_file_opened: %d\n", my_file_opened);
+         sleep(3);
+         fprintf(stderr, "my_file_opened: %d\n", my_file_opened);
       pthread_mutex_unlock(&THR_LOCK_open);
       my_errno= ENOMEM;
     }

Then run following test for MTR:

drop table if exists t0;
flush tables;
--send create table t0(id int)engine=myisam

connect (addconroot1, localhost, root,,);
connection addconroot1;
drop table if exists t1;
--send create table t1(id int)engine=myisam

connect (addconroot2, localhost, root,,);
connection addconroot2;
drop table if exists t0;
--send create table t0(id int)engine=myisam

connect (addconroot, localhost, root,,);
connection addconroot;
flush tables;
sleep 1;
show global status like '%open_files%';
show global status where variable_name in ('open_files');
show global status like '%opened_files%';

connection default;
--error 1005
--reap
show global status like '%open_files%';
show global status where variable_name in ('open_files');
show global status like '%opened_files%';

Probably you need to repeat it several times before problem occurs.
[1 Mar 2010 14:59] Kristofer Pettersson
Unable to reproduce to reproduce on 5.1 using both original test case, and error-inducing test case. However, it seems probably that the variable 'my_file_opened' should be strongly associated with the setting of my_file_info[fd].type attribute.

In my_open.c:my_close() the value is decreased unconditionally

my_close(..)
{
.
.
if (fd < my_file_limit && my_file_info[fd].type != UNOPEN)
{
  ..
  my_file_info[fd].type= UNOPEN;
}
my_file_opened--;
.
.
}

And in my_register_filename() it is increased only if 0 > fd < my_file_limit.
my_register_filename is called unconditionally from my_open(..) but with parameters depend on platform: On windows there is a check_if_legal_file_name() which would cause my_register_filename() to only output an error but not increase my_file_opened.

Thus there is no apparent symmetry which would balance out my_file_open inc/dec in all situations.

In 5.0 the issue can be reproduced by error inducing. It can be fixed by adjusting the return code for my_register_filename() in case of an error.
[1 Mar 2010 15:26] 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/101900

2847 Kristofer Pettersson	2010-03-01
      Bug#29071 invalid Open_files or Slave_open_temp_tables value in show global status
      
      If my_register_filename() fails it should return an
      invalid file handle to indicate this failure or
      the open_files status variables will be
      decreased one time too many. As the variable is unsigned
      it will warp around to a very high number when this
      happens.
     @ mysys/my_open.c
        * If an error occurs, return -1 to indicate error.
[13 Apr 2010 20:41] Lou Donayre
I have a workaround that I have found to be helpful.  I had this same problem and it was causing me problems for knowing when or when not to shutdown the database safely.  lsof shows the temp files open and shutting down with open temp files has (of course) caused me data corruption with my 1Terabyte++ databases.  while I can't reproduce a test case I have found something that worked for me to get rid of the error and at least let me know if I may shut down the slaves.   

I didn't isolate which command did the trick but, I suspect that it is the flush tables of course.  This may seem obvious but, perhaps the order and process of flushing other things is relevant.  If I am able to better isolate it I will update this note.  I hope this helps someone else as it really has been helpful to me.

mysql> show status like '%temp%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| Slave_open_temp_tables | 2     |
+------------------------+-------+
1 row in set (0.02 sec)

mysql> flush hosts; 
Query OK, 0 rows affected (0.00 sec)

mysql> flush slave; 
Query OK, 0 rows affected (0.01 sec)

mysql> flush master;     <= NOTE: this one BLOWS AWAY your master config.  Before doing this do a "stop slave", "show slave status" and save the results so you can rebuild the master info later.
Query OK, 0 rows affected (5.93 sec)

mysql> flush tables;    
Query OK, 0 rows affected (0.41 sec)

mysql> show status like '%temp%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+ 
| Slave_open_temp_tables | 0     | 
+------------------------+-------+
1 row in set (0.02 sec)
[13 Apr 2010 20:47] Lou Donayre
Forgot to mention that this was MySQL 5.0.37 on Ubuntu 6.10, 
two dual core - Intel(R) Xeon(R) CPU 5110.

mysql --version
mysql  Ver 14.12 Distrib 5.0.37, for unknown-linux-gnu (x86_64) using readline 5.0

Linux 2.6.17-11-generic #2 SMP Fri May 18 22:25:27 UTC 2007 x86_64 GNU/Linux
[13 Apr 2010 20:55] Lou Donayre
Typo on my warning about master config reset.  It should read as a warning for "flush slave" not "flush master"

mysql> flush slave;     <= NOTE: this one BLOWS AWAY your master config.  Before doing
this do a "stop slave", "show slave status" and save the results so you can rebuild the
master info later.

mysql> flush master;
[2 Aug 2010 9:07] MySQL Verification Team
seen again in some random tests.

mysql> show global status like '%open%';
+--------------------------+------------+
| Variable_name            | Value      |
+--------------------------+------------+
| Com_ha_open              | 0          |
| Com_show_open_tables     | 0          |
| Open_files               | 4294957796 |
| Open_streams             | 0          |
| Open_table_definitions   | 38         |
| Open_tables              | 26         |
| Opened_files             | 157512     |
| Opened_table_definitions | 21455      |
| Opened_tables            | 25628      |
| Slave_open_temp_tables   | 0          |
+--------------------------+------------+
10 rows in set (0.00 sec)

mysql> select version();
+------------------------------------+
| version()                          |
+------------------------------------+
| 5.1.49-enterprise-gpl-advanced-log |
+------------------------------------+
1 row in set (0.00 sec)
[2 Aug 2010 9:58] Sveta Smirnova
Bug still repeatable with today bzr tree with test provided in comment "[7 Dec 2009 11:44] Sveta Smirnova" Open_files is 18446744073709551615 on 64-bit box.
[2 Aug 2010 11:17] Kristofer Pettersson
In "random test" isn't much to go on. Sveta, can we pinpoint this more accurately please?
[2 Aug 2010 11:33] Sveta Smirnova
Kristofer,

this is not random test. Here I try to explain what test does.

Lets look at the patch.

In patch we increase my_file_opened and my_file_total_opened only if no table named t1 and t0 is used.

In the test case I want to show we can have negative value under some circumstances. For this I just create tables t1 and t0 and check open_files value.

I hope this helps.
[13 Sep 2010 9:52] Kristofer Pettersson
@sveta using your patch and your test case I was able to detect an error in 5.0 but not in 5.1+. I did not agree with your patch for the 5.0 version. Further more 5.0 is not a valid target for this bug.

Can you help me find a deterministic test for 5.1+ ? Sbester writes "random test" above and I need a deterministic test case so I can reproduce the error.
[13 Sep 2010 19:22] Sveta Smirnova
I was able to repeat the problem with version 5.1 at August, 2.

Now I see:

show global status like '%open_files%';
Variable_name   Value
Open_files      18446744073709551615
show global status where variable_name in ('open_files');
Variable_name   Value
Open_files      18446744073709551615
show global status like '%opened_files%';
Variable_name   Value
Opened_files    86
ERROR HY000: Can't create table 't0' (errno: 12)
show global status like '%open_files%';
Variable_name   Value
Open_files      18446744073709551615
show global status where variable_name in ('open_files');
Variable_name   Value
Open_files      18446744073709551615
show global status like '%opened_files%';
Variable_name   Value
Opened_files    86
select version();
version()
5.1.51-debug-log

Please let me know why you disagree with my patch: it is for testing only to be able to repeat the problem. If attach *.test file to MTR DBUG should be used, not this patch of course.
[22 Sep 2010 8:38] Kristofer Pettersson
@Sveta I'm retried your test case in a recent 5.1 tree and this time I was indeed able to reproduce the error in 5.1 as well.
[27 Sep 2010 8:09] 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/119143

3197 Kristofer Pettersson	2010-09-27
      Bug#29071 invalid Open_files or Slave_open_temp_tables value in show global status
      
      If an error occurred during registration of
      a file handle, the Open_files counter would
      show very large numbers.
      
      Only decrese my_file_opened if the file
      descriptor was maked as anything but UNOPEN
     @ mysys/my_fopen.c
        * The variable "my_stream_opened" needs to be strongly associated
          with the my_file_info::type attribute.
     @ mysys/my_open.c
        * The variable "my_file_opened" needs to be strongly associated
          with the my_file_info::type attribute.
[27 Sep 2010 13:12] 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/119172

3197 Kristofer Pettersson	2010-09-27
      Bug#29071 invalid Open_files or Slave_open_temp_tables value in show global status
      
      If an error occurred during registration of
      a file handle, the Open_files counter would
      show very large numbers.
      
      Only decrese my_file_opened or my_stream_opened if the file
      descriptor was maked as anything but UNOPEN
     @ mysys/my_fopen.c
        * The variable "my_stream_opened" needs to be strongly associated
          with the my_file_info::type attribute.
     @ mysys/my_open.c
        * The variable "my_file_opened" needs to be strongly associated
          with the my_file_info::type attribute.
     @ unittest/gunit/CMakeLists.txt
        * Added two test cases my_open-t.cc, my_fopen-t.cc
[5 Oct 2010 12:38] 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/119992

3197 Kristofer Pettersson	2010-10-05
      Bug#29071 invalid Open_files or Slave_open_temp_tables value in show global status
      
      If an error occurred during registration of
      a file handle, the Open_files counter would
      show very large numbers.
      
      Only decrease my_file_opened or my_stream_opened if the file
      descriptor was maked as anything but UNOPEN
     @ include/my_global.h
        * In order to be able to map all file descriptors to the minimal requirement of concurrently open files we need to increase MY_NFILE to 256 which also matches the official recommendation better.
     @ mysql-test/t/myisampack.test
        * Add test file to verify that previously working scripts are still working within acceptable limits.
     @ mysys/my_file.c
        * Make sure that the my_file_limit is updated even if the requested number of file descriptors fit into the default static memory allocation.
        * If an allocation fail, make sure the my_file_info pointer is reverted to the default structure.
     @ mysys/my_fopen.c
        * The variable "my_stream_opened" needs to be strongly associated
          with the my_file_info::type attribute.
        * Move the THR_LOCK_open mutex so that we don't hold it while doing system calls.
     @ mysys/my_open.c
        * The variable "my_file_opened" needs to be strongly associated
          with the my_file_info::type attribute.
        * Move the THR_LOCK_open mutex so that we don't hold it while doing system calls.
        * Previously the file descriptor didn't map strictly to the my_file_info array and when very many files were used, the my_file_info array weren't updated.
     @ unittest/gunit/CMakeLists.txt
        * Added two test cases my_open-t.cc, my_fopen-t.cc
[14 Oct 2010 20:04] Vladislav Vaintroub
As discussed via email: there is no need for extraneous 
#ifdef _WIN32 

in this patch, especially manipulating my_file_info[fd].fhandle directly, this sort of breaks the layering, fhandle belongs to my_winfile.c and nowhere else.

my_winfile.c actually does all you need. my_win_close() would clean the slot in my_file_info array, my_win_open() would allocate the slot. There is no need for extra protection my_win_open/close with the mutex, it thread-safe - we assume after careful examination of the codebase that my_set_max_open_files() never runs unless directly at the process startup, otherwise my_winfile.c would never work :)

The explanation why it is clean
[14 Oct 2010 20:05] Vladislav Vaintroub
ignore the last incomplete sentence in prior entry:)
[30 Nov 2010 5:39] MySQL Verification Team
bug 58580 is a duplicate of this
[1 Dec 2015 8:52] Pavel Katiushyn
Recently had Slave_open_temp_tables = 1 on 5.6.16 slave even with stopped replication. 
[root@dbserver ~]# ls -l /tmp/
total 108
-rw-rw---- 1 mysql mysql  8628 Nov 26 10:29 #sqlc34_56d0a_374.frm
-rw-rw---- 1 mysql mysql 98304 Nov 26 10:29 #sqlc34_56d0a_374.ibd

Some backup scripts are checking this parameter and do not work, if it is not 0.
In my case "reset slave" helped. On slave:
1. stop slave;
2. Save user, pass, bin log and position of replication.
3. reset slave;
4. use change master to continue replication.
5. start slave;

After the actions Slave_open_temp_tables became 0, but temporary table was not dropped and still was in use:
[root@dbserver ~]# lsof | grep sqlc
mysqld      3124  mysql  437uW     REG              259,2        98304   10093473 /tmp/#sqlc34_56d0a_374.ibd
[29 Aug 2017 9:12] Kristofer Pettersson
Posted by developer:
 
We now have performance schema and this bug isn't likely to be address for 5.1.