Bug #69782 Old files not being removed from performance_schema.file_instances
Submitted: 18 Jul 2013 17:42 Modified: 14 Jan 2014 18:27
Reporter: Don Coffin Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:5.6.12 OS:Linux
Assigned to: Marc Alff CPU Architecture:Any
Tags: performance_schema

[18 Jul 2013 17:42] Don Coffin
Description:
Per the documentation at http://dev.mysql.com/doc/refman/5.5/en/file-instances-table.html:

"When a file is deleted from the disk, it is also removed from the file_instances table."  This is not true on either 5.5.23 or 5.6.11.  I have three relay log files on disk, but the file_instances table lists thousands of relay logs.

The documentation for 5.6 is identical and also appears to be wrong.

How to repeat:
[root@mysql-5-5-23-host ~]# mysql -e "select @@version; select count(*) from performance_schema.file_instances where file_name like '%relay%';"
+------------+
| @@version  |
+------------+
| 5.5.23-log |
+------------+
+----------+
| count(*) |
+----------+
|     5779 |
+----------+
[root@mysql-5-5-23-host ~]# ls -l /path/to/relay/logs/relay* | wc -l
3

[root@mysql-5-6-11-host ~]# mysql -e "select @@version; select count(*) from performance_schema.file_instances where file_name like '%relay%';"
+------------+
| @@version  |
+------------+
| 5.6.11-log |
+------------+
+----------+
| count(*) |
+----------+
|     6161 |
+----------+
[root@mysql-5-6-11-host ~]# ls /path/to/relay/logs/relay* | wc -l
3
[24 Jul 2013 6:22] Umesh Shastry
Hello Don, 

Thank you for the bug report. 
Verified as described on MySQL 5.6.12 version.

Thanks,
Umesh
[24 Jul 2013 6:24] Umesh Shastry
//

slave1 [localhost] {root} ((none)) > select version();
+------------+
| version()  |
+------------+
| 5.6.12-log |
+------------+
1 row in set (0.00 sec)

slave1 [localhost] {root} ((none)) > select count(*) from performance_schema.file_instances where file_name like '/data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin%';
+----------+
| count(*) |
+----------+
|        6 |
+----------+
1 row in set (0.00 sec)

slave1 [localhost] {root} ((none)) > select * from performance_schema.file_instances where file_name like '/data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin%';
+-----------------------------------------------------------------------------------------+-------------------------------+------------+
| FILE_NAME                                                                               | EVENT_NAME                    | OPEN_COUNT |
+-----------------------------------------------------------------------------------------+-------------------------------+------------+
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000007 | wait/io/file/sql/binlog       |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000006 | wait/io/file/sql/binlog       |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000008 | wait/io/file/sql/relaylog     |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000009 | wait/io/file/sql/relaylog     |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000010 | wait/io/file/sql/relaylog     |          1 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.index  | wait/io/file/sql/binlog_index |          1 |
+-----------------------------------------------------------------------------------------+-------------------------------+------------+
6 rows in set (0.00 sec)

slave1 [localhost] {root} ((none)) >

//// file system snapshot - to confirm ***-relay-bin.000007/6/8 doesn't exist on disk...

[ushastry@cluster-repo ~]$ more sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.index
./mysql_sandbox19078-relay-bin.000009
./mysql_sandbox19078-relay-bin.000010
[ushastry@cluster-repo ~]$  ls -l sandboxes/rsandbox_5_6_12/node1/data/
total 110684
-rw-rw---- 1 ushastry ushastry       56 Jul 19 20:03 auto.cnf
-rw-rw---- 1 ushastry ushastry 12582912 Jul 25 09:43 ibdata1
-rw-rw---- 1 ushastry ushastry 50331648 Jul 25 09:43 ib_logfile0
-rw-rw---- 1 ushastry ushastry 50331648 Jul 19 20:03 ib_logfile1
-rw-rw---- 1 ushastry ushastry      130 Jul 25 09:43 master.info
-rw-r----- 1 ushastry ushastry    21979 Jul 25 09:43 msandbox.err
drwx------ 2 ushastry ushastry     4096 Jul 19 20:03 mysql
-rw-rw---- 1 ushastry ushastry      143 Jul 19 20:07 mysql-bin.000001
-rw-rw---- 1 ushastry ushastry      120 Jul 24 12:44 mysql-bin.000002
-rw-rw---- 1 ushastry ushastry      143 Jul 24 12:44 mysql-bin.000003
-rw-rw---- 1 ushastry ushastry      120 Jul 25 09:43 mysql-bin.000004
-rw-rw---- 1 ushastry ushastry       76 Jul 25 09:43 mysql-bin.index
-rw-rw---- 1 ushastry ushastry        5 Jul 25 09:43 mysql_sandbox19078.pid
-rw-rw---- 1 ushastry ushastry      349 Jul 25 09:43 mysql_sandbox19078-relay-bin.000009
-rw-rw---- 1 ushastry ushastry      283 Jul 25 09:43 mysql_sandbox19078-relay-bin.000010
-rw-rw---- 1 ushastry ushastry       76 Jul 25 09:43 mysql_sandbox19078-relay-bin.index
drwx------ 2 ushastry ushastry     4096 Jul 19 20:03 performance_schema
-rw-rw---- 1 ushastry ushastry       73 Jul 25 09:43 relay-log.info
drwx------ 2 ushastry ushastry     4096 Jul 19 20:03 test
[24 Jul 2013 6:24] Umesh Shastry
///  Creating new *relay files on slave

slave1 [localhost] {root} ((none)) > stop slave;
Query OK, 0 rows affected (0.09 sec)

slave1 [localhost] {root} ((none)) > start slave;
Query OK, 0 rows affected (0.05 sec)

slave1 [localhost] {root} ((none)) > stop slave;
Query OK, 0 rows affected (0.09 sec)

slave1 [localhost] {root} ((none)) > start slave;
Query OK, 0 rows affected (0.05 sec)

slave1 [localhost] {root} ((none)) > select count(*) from performance_schema.file_instances where file_name like '/data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin%';
+----------+
| count(*) |
+----------+
|        8 |
+----------+
1 row in set (0.00 sec)

slave1 [localhost] {root} ((none)) > select * from performance_schema.file_instances where file_name like '/data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin%';
+-----------------------------------------------------------------------------------------+-------------------------------+------------+
| FILE_NAME                                                                               | EVENT_NAME                    | OPEN_COUNT |
+-----------------------------------------------------------------------------------------+-------------------------------+------------+
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000007 | wait/io/file/sql/binlog       |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000006 | wait/io/file/sql/binlog       |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000008 | wait/io/file/sql/relaylog     |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000009 | wait/io/file/sql/relaylog     |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000010 | wait/io/file/sql/relaylog     |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000011 | wait/io/file/sql/relaylog     |          0 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.000012 | wait/io/file/sql/relaylog     |          1 |
| /data/ushastry/sandboxes/rsandbox_5_6_12/node1/data/mysql_sandbox19078-relay-bin.index  | wait/io/file/sql/binlog_index |          1 |
+-----------------------------------------------------------------------------------------+-------------------------------+------------+
8 rows in set (0.00 sec)

// from file system snapshot

[ushastry@cluster-repo ~]$  ls -l sandboxes/rsandbox_5_6_12/node1/data/
total 110684
-rw-rw---- 1 ushastry ushastry       56 Jul 19 20:03 auto.cnf
-rw-rw---- 1 ushastry ushastry 12582912 Jul 25 09:43 ibdata1
-rw-rw---- 1 ushastry ushastry 50331648 Jul 25 09:43 ib_logfile0
-rw-rw---- 1 ushastry ushastry 50331648 Jul 19 20:03 ib_logfile1
-rw-rw---- 1 ushastry ushastry      130 Jul 25 09:57 master.info
-rw-r----- 1 ushastry ushastry    24295 Jul 25 09:57 msandbox.err
drwx------ 2 ushastry ushastry     4096 Jul 19 20:03 mysql
-rw-rw---- 1 ushastry ushastry      143 Jul 19 20:07 mysql-bin.000001
-rw-rw---- 1 ushastry ushastry      120 Jul 24 12:44 mysql-bin.000002
-rw-rw---- 1 ushastry ushastry      143 Jul 24 12:44 mysql-bin.000003
-rw-rw---- 1 ushastry ushastry      120 Jul 25 09:43 mysql-bin.000004
-rw-rw---- 1 ushastry ushastry       76 Jul 25 09:43 mysql-bin.index
-rw-rw---- 1 ushastry ushastry        5 Jul 25 09:43 mysql_sandbox19078.pid
-rw-rw---- 1 ushastry ushastry      349 Jul 25 09:57 mysql_sandbox19078-relay-bin.000011
-rw-rw---- 1 ushastry ushastry      283 Jul 25 09:57 mysql_sandbox19078-relay-bin.000012
-rw-rw---- 1 ushastry ushastry       76 Jul 25 09:57 mysql_sandbox19078-relay-bin.index
drwx------ 2 ushastry ushastry     4096 Jul 19 20:03 performance_schema
-rw-rw---- 1 ushastry ushastry       73 Jul 25 09:57 relay-log.info
drwx------ 2 ushastry ushastry     4096 Jul 19 20:03 test
[ushastry@cluster-repo ~]$

^^ Clearly mysql_sandbox19078-relay-bin.000007..10 relay logs doesn't exist on file system but still file_instances lists them which some
how contradicts " If a file on disk has never been opened, it will not be in file_instances. When a file is deleted from the disk, it is also removed from the file_instances table. "  - Please reference http://dev.mysql.com/doc/refman/5.6/en/file-instances-table.html

Imho - either this behavior should be documented or fixed in code.

Thanks,
Umesh
[14 Jan 2014 18:27] Paul Dubois
Noted in 5.6.16, 5.7.4 changelogs.

Some files in the Performance Schema file_instances table were not 
being removed because the file-removal operation was not
instrumented.
[3 Feb 2014 11:55] Laurynas Biveinis
5.6$ bzr log -r 5715
------------------------------------------------------------
revno: 5715
committer: Venkata Sidagam <venkata.sidagam@oracle.com>
branch nick: 5.6
timestamp: Fri 2013-12-27 14:11:20 +0530
message:
  Bug #17209750 OLD FILES NOT BEING REMOVED FROM 
                PERFORMANCE_SCHEMA.FILE_INSTANCES
  
  Description: "When a file is deleted from the disk, it is
  also removed from the file_instances table."  This is not
  true on either 5.5.23 or 5.6.11.  When there are three 
  relay log files on disk, but the file_instances table 
  lists more number of relay logs. Even this case is 
  happening for master bin and slave bin logs.
  
  Analysis: When we are deleting the 
  slave-relay-bin/master-bin/slave-bin log files we were
  using the my_delete() function which is not P_S 
  instrumented function. Hence, the files are not removed
  from the file_instances table.
  
  Fix: As part of the fix we replaced my_delete() 
  function with P_S instrumented mysql_file_delete() function.