Bug #63340 | Access to InnoDB data files not listed in P_S | ||
---|---|---|---|
Submitted: | 20 Nov 2011 14:46 | Modified: | 31 May 2012 17:17 |
Reporter: | Peter Laursen (Basic Quality Contributor) | Email Updates: | |
Status: | Closed | Impact on me: | |
Category: | MySQL Server: Performance Schema | Severity: | S3 (Non-critical) |
Version: | 5.5.18 | OS: | Windows |
Assigned to: | Marc ALFF | CPU Architecture: | Any |
Tags: | qc |
[20 Nov 2011 14:46]
Peter Laursen
[20 Nov 2011 15:10]
Peter Laursen
A clarification: "SELECT * FROM `performance_schema`.`file_instances`; -- now filter.." >> "SELECT * FROM `performance_schema`.`file_instances`; -- first check that no InnoDB data file or log file is listed in teh result set -- next filter.." (as obviously without 'innodb_file_per_table' the ibdata* file(s) are not in 'test' folder
[20 Nov 2011 17:48]
Valeriy Kravchuk
Well, I do not see any explicit claim in the manual that access to ibdata* files is instrumented. See http://dev.mysql.com/doc/refman/5.5/en/file-instances-table.html http://dev.mysql.com/doc/refman/5.5/en/file-summary-tables.html IMHO we have just a documentation request here.
[20 Nov 2011 18:55]
Peter Laursen
Now we are again starting MySQL 'bad manners' thinking that documenting a wrong behavior is a solution. I see no use the 2 P_S tables if it does not list each and every file opened for READ by the server (or alternatively only handles system tables and not user tables). Besides 'innodb_file_per_table' makes no difference: -- prepare SET GLOBAL innodb_file_per_table = 1; CREATE DATABASE newtest; USE newtest; CREATE TABLE `innotable` ( `id` INT(11) DEFAULT NULL ) ENGINE=INNODB DEFAULT CHARSET=utf8; INSERT INTO `innotable` VALUES (1); CREATE TABLE `mytable` ( `id` INT(11) DEFAULT NULL ) ENGINE=MYISAM DEFAULT CHARSET=utf8; INSERT INTO `innotable` VALUES (1); -- restart server and reconnect SELECT * FROM test.mytable; -- repeat 20 times SELECT * FROM test.innotable; -- repeat 20 times SELECT * FROM `performance_schema`.`file_instances`; -- no innodb data files returned Documentation says: COUNT_READ: "The number of read operations in the summarized events.". If it does not work like that it is not implemented as intended IMHO! But let developers of P_S consider and comment
[20 Nov 2011 19:02]
Peter Laursen
And BTW: please ignore my point no. 2.
[20 Nov 2011 19:30]
Valeriy Kravchuk
OK, I'd call the following result a bug in any case: C:\Program Files\MySQL\MySQL Server 5.5\bin>mysql -uroot -proot -P3308 test Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 3 Server version: 5.5.18 MySQL Community Server (GPL) Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> show variables like 'innodb_file%'; +--------------------------+----------+ | Variable_name | Value | +--------------------------+----------+ | innodb_file_format | Antelope | | innodb_file_format_check | ON | | innodb_file_format_max | Antelope | | innodb_file_per_table | ON | +--------------------------+----------+ 4 rows in set (0.06 sec) mysql> create table tif(c1 int) engine=InnoDB; Query OK, 0 rows affected (0.19 sec) mysql> insert into tif values(1); Query OK, 1 row affected (0.02 sec) mysql> select * from tif; +------+ | c1 | +------+ | 1 | +------+ 1 row in set (0.00 sec) mysql> select * from performance_schema.file_instances where file_name like '%ti f%'; +------------------------------------------------------------------------------- -----------------+----------------------+------------+ | FILE_NAME | EVENT_NAME | OPEN_COUNT | +------------------------------------------------------------------------------- -----------------+----------------------+------------+ | C:\Documents and Settings\All Users\Application Data\MySQL\MySQL Server 5.5\da ta\test\\tif.frm | wait/io/file/sql/FRM | 0 | +------------------------------------------------------------------------------- -----------------+----------------------+------------+ 1 row in set (0.02 sec) mysql> exit Bye C:\Program Files\MySQL\MySQL Server 5.5\bin>net stop mysql55 The MySQL55 service is stopping. The MySQL55 service was stopped successfully. C:\Program Files\MySQL\MySQL Server 5.5\bin>net start mysql55 The MySQL55 service is starting... The MySQL55 service was started successfully. C:\Program Files\MySQL\MySQL Server 5.5\bin>mysql -uroot -proot -P3308 test Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 1 Server version: 5.5.18 MySQL Community Server (GPL) Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> select * from tif; +------+ | c1 | +------+ | 1 | +------+ 1 row in set (0.00 sec) mysql> select * from performance_schema.file_instances where file_name like '%ti f%'; +------------------------------------------------------------------------------- -----------------+----------------------+------------+ | FILE_NAME | EVENT_NAME | OPEN_COUNT | +------------------------------------------------------------------------------- -----------------+----------------------+------------+ | C:\Documents and Settings\All Users\Application Data\MySQL\MySQL Server 5.5\da ta\test\\tif.frm | wait/io/file/sql/FRM | 0 | +------------------------------------------------------------------------------- -----------------+----------------------+------------+ 1 row in set (0.00 sec) We surely accessed .ibd file here: C:\Program Files\MySQL\MySQL Server 5.5\bin>dir "c:\Documents and Settings\All U sers\Application Data\MySQL\MySQL Server 5.5\data\test"\tif.* Volume in drive C is System Volume Serial Number is 8C8F-26A1 Directory of c:\Documents and Settings\All Users\Application Data\MySQL\MySQL S erver 5.5\data\test 20.11.2011 21:24 8 556 tif.frm 20.11.2011 21:24 98 304 tif.ibd 2 File(s) 106 860 bytes 0 Dir(s) 10 758 463 488 bytes free but .frm is reported while .ibd is not.
[21 Nov 2011 11:58]
Peter Laursen
My (unqualified) guess is that the problem is that InnoDB does not expose file system operations to the server. That could apply to other storage engines (and also all sorts of plugins actually) as well. So maybe this is a more general requirement/request for plugins and storage engines and the plugin interface/API as such?
[21 Nov 2011 17:57]
Marc ALFF
There are many things said in this report that needs to be clarified or corrected, so I am now addressing them one at a time in different comments to follow. -- Marc
[21 Nov 2011 19:09]
Marc ALFF
First, the description of what precisely is instrumented for the performance schema is *NOT* in the user manual, and that is expected. There are many reasons for that. 1) What is instrumented is the server code, and the server code changes all the time, without notice. Having to keep the manual up to date with that is not realistic. 2) There are 200+ instruments in 5.5, and 500+ instruments in 5.6. At best, documentation for each instruments belongs more to the server internals than in the user manual, as low level instruments are by definition related to the code itself (think mutexes). 3) More importantly, what is instrumented can be queried from the performance schema directly: select * from performance_schema.setup_instruments where name like "wait/io/file/innodb/%"; will list all the file io instrumented in innodb, for example. The main benefit of this feature is that one can see instantly what is instrumented, from the code itself, which is guaranteed: - to be up to date, since the data comes from the server binary, - to also cover plugins, - to be available to automated tools (while a user manual is not) Per the setup_instruments table, wait/io/file/innodb/innodb_data_file is instrumented.
[21 Nov 2011 19:23]
Valeriy Kravchuk
Great comment, Marc. It would be really nice to find similar explanation in the manual. Question still remains: is access to individual .ibd files instrumented, and how one can find this out?
[22 Nov 2011 10:42]
Marc ALFF
Second round of comments, on the next topic to correct. Before claiming that there is a bug in the statistics reported by the performance schema, one has to be certain that there are indeed events that did happen and were not counted properly. The server implementation contains a lot of optimizations with internal caching, that can make this very difficult. Just *assuming* that file io *has* to happen (or not) in such ans such case without knowing, to later claim that the performance schema results are incorrect, is not good enough. For example with *.FRM files: 1) After a CREATE TABLE and INSERT statement, the table definition is still present both in the table definition cache in the server, and on disk as a .frm file. After this, a SELECT statement will need to read the table definition, which will be read from memory in the table definition cache, if still present. Expecting that the server *has* to perform file io at this point is just wrong. The server behaves properly and efficiently by reading data from the table definition cache, and the performance schema behaves correctly by reporting the truth about what happened: no file io. So, in this example, a COUNT_READ of 0 on a frm file after a SELECT is perfectly valid, depending on the server internal state at that moment. In fact, the frm file was written to once, on CREATE TABLE, and never read since. 2) Trying to predict precisely when each file io is done on which file used by the server assumes a very deep understanding of the server. For example, innocent looking statements such as "use test" in a mysql client session can cause file io to read *.frm files in the test database, to support automatic completion in the mysql client, when running with --auto-rehash, which is the default. Given that the exact session, with every single statement sent to the server, was not provided in this bug report, there is no way to tell whether a COUNT_READ of 0 in one case and 7 in another is correct or not.
[22 Nov 2011 10:49]
Peter Laursen
@mark .. I asked you to ignore point 2). I mismatched two tables simply. What remains for me is that data (and index) files in some cases (MyISAM) are counted and in some cases (InnoDB) are not. That is a surprise at least. Not sure what would happen with other official engines (ARCHIVE, CSV) and 3rd party engines installed as a plugin (say PBXT).
[22 Nov 2011 11:58]
Valeriy Kravchuk
What I referred to when claiming that there is a problem is described in my comment dated [20 Nov 19:30] Valeriy Kravchuk I had restarted server and accessed InnoDB table represented by .frm file and .ibd file (that is, created with innodb_file_per_table=1), with SELECT. I see row for .frm file in the P_S table, but I do not see row for .ibd file. How, after server restart, server was able to execute SELECT without accessing .ibd file is beyond my understanding. So I claim there is either a bug in instrumentation or mistake in the way I checked (and, in later case, we need more clean manual on how to check properly). So for this bug status "Verified" still seems valid, either for instrumentation or for the manual.
[22 Nov 2011 13:12]
Peter Laursen
I tried with CSV and ARCHIVE tables as well. For CSV: both .frm and .CSV files appear (similar to MyISAM) For Archive: only .frm appears. Not .ARZ file (similar to InnoDB)
[29 Nov 2011 15:44]
Marc ALFF
Continuing the analysis ... I have tried to reproduce the bug reported, but was not able to. Script used, in mysql-test-run format: # Setup set global innodb_file_per_table=ON; update performance_schema.setup_consumers set enabled='YES'; update performance_schema.setup_instruments set enabled='NO'; update performance_schema.setup_instruments set enabled='YES' where name like "wait/io/file/innodb/%"; select * from performance_schema.setup_consumers where enabled='YES'; select * from performance_schema.setup_instruments where enabled='YES'; # Test select version(); create table test.t1(a int) engine=innodb; insert into test.t1 values (1); select * from performance_schema.file_instances where event_name like "wait/io/file/innodb/%"; select * from performance_schema.file_summary_by_instance where event_name like "wait/io/file/innodb/%"; --vertical_results select * from performance_schema.file_summary_by_instance where file_name like "%ibd"; # Cleanup update performance_schema.setup_instruments set enabled='YES'; set global innodb_file_per_table=OFF; drop table test.t1;
[29 Nov 2011 15:45]
Marc ALFF
Results for mysql 5.5.20: set global innodb_file_per_table=ON; update performance_schema.setup_consumers set enabled='YES'; update performance_schema.setup_instruments set enabled='NO'; update performance_schema.setup_instruments set enabled='YES' where name like "wait/io/file/innodb/%"; select * from performance_schema.setup_consumers where enabled='YES'; NAME ENABLED events_waits_current YES events_waits_history YES events_waits_history_long YES events_waits_summary_by_thread_by_event_name YES events_waits_summary_by_event_name YES events_waits_summary_by_instance YES file_summary_by_event_name YES file_summary_by_instance YES select * from performance_schema.setup_instruments where enabled='YES'; NAME ENABLED TIMED wait/io/file/innodb/innodb_data_file YES YES wait/io/file/innodb/innodb_log_file YES YES wait/io/file/innodb/innodb_temp_file YES YES select version(); version() 5.5.20-log create table test.t1(a int) engine=innodb; insert into test.t1 values (1); select * from performance_schema.file_instances where event_name like "wait/io/file/innodb/%"; FILE_NAME EVENT_NAME OPEN_COUNT /home/malff/BZR_TREE/mysql-5.5/mysql-test/var/mysqld.1/data/ib_logfile0 wait/io/file/innodb/innodb_log_file 1 /home/malff/BZR_TREE/mysql-5.5/mysql-test/var/mysqld.1/data/test/t1.ibd wait/io/file/innodb/innodb_data_file 1 /home/malff/BZR_TREE/mysql-5.5/mysql-test/var/mysqld.1/data/ibdata1 wait/io/file/innodb/innodb_data_file 1 /home/malff/BZR_TREE/mysql-5.5/mysql-test/var/mysqld.1/data/ib_logfile1 wait/io/file/innodb/innodb_log_file 1 select * from performance_schema.file_summary_by_instance where event_name like "wait/io/file/innodb/%"; FILE_NAME EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE /home/malff/BZR_TREE/mysql-5.5/mysql-test/var/mysqld.1/data/ib_logfile0 wait/io/file/innodb/innodb_log_file 6 5 69632 6144 /home/malff/BZR_TREE/mysql-5.5/mysql-test/var/mysqld.1/data/test/t1.ibd wait/io/file/innodb/innodb_data_file 0 3 0 114688 /home/malff/BZR_TREE/mysql-5.5/mysql-test/var/mysqld.1/data/ibdata1 wait/io/file/innodb/innodb_data_file 149 0 4505600 0 /home/malff/BZR_TREE/mysql-5.5/mysql-test/var/mysqld.1/data/ib_logfile1 wait/io/file/innodb/innodb_log_file 0 0 0 0 select * from performance_schema.file_summary_by_instance where file_name like "%ibd"; FILE_NAME /home/malff/BZR_TREE/mysql-5.5/mysql-test/var/mysqld.1/data/test/t1.ibd EVENT_NAME wait/io/file/innodb/innodb_data_file COUNT_READ 0 COUNT_WRITE 3 SUM_NUMBER_OF_BYTES_READ 0 SUM_NUMBER_OF_BYTES_WRITE 114688 update performance_schema.setup_instruments set enabled='YES'; set global innodb_file_per_table=OFF; drop table test.t1;
[29 Nov 2011 15:45]
Marc ALFF
Results for mysql 5.6.4: set global innodb_file_per_table=ON; update performance_schema.setup_consumers set enabled='YES'; update performance_schema.setup_instruments set enabled='NO'; update performance_schema.setup_instruments set enabled='YES' where name like "wait/io/file/innodb/%"; select * from performance_schema.setup_consumers where enabled='YES'; NAME ENABLED events_stages_current YES events_stages_history YES events_stages_history_long YES events_statements_current YES events_statements_history YES events_statements_history_long YES events_waits_current YES events_waits_history YES events_waits_history_long YES global_instrumentation YES thread_instrumentation YES select * from performance_schema.setup_instruments where enabled='YES'; NAME ENABLED TIMED wait/io/file/innodb/innodb_data_file YES YES wait/io/file/innodb/innodb_log_file YES YES wait/io/file/innodb/innodb_temp_file YES YES select version(); version() 5.6.4-m6-log create table test.t1(a int) engine=innodb; insert into test.t1 values (1); select * from performance_schema.file_instances where event_name like "wait/io/file/innodb/%"; FILE_NAME EVENT_NAME OPEN_COUNT /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/ibdata1 wait/io/file/innodb/innodb_data_file 1 /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/ib_logfile0 wait/io/file/innodb/innodb_log_file 1 /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/ib_logfile1 wait/io/file/innodb/innodb_log_file 1 /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/undo001 wait/io/file/innodb/innodb_data_file 0 /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/test/t1.ibd wait/io/file/innodb/innodb_data_file 1 select * from performance_schema.file_summary_by_instance where event_name like "wait/io/file/innodb/%"; FILE_NAME EVENT_NAME OBJECT_INSTANCE_BEGIN COUNT_STAR SUM_TIMER_WAIT MIN_TIMER_WAIT AVG_TIMER_WAIT MAX_TIMER_WAIT COUNT_READ SUM_TIMER_READ MIN_TIMER_READ AVG_TIMER_READ MAX_TIMER_READ SUM_NUMBER_OF_BYTES_READ COUNT_WRITE SUM_TIMER_WRITE MIN_TIMER_WRITE AVG_TIMER_WRITE MAX_TIMER_WRITE SUM_NUMBER_OF_BYTES_WRITE COUNT_MISC SUM_TIMER_MISC MIN_TIMER_MISC AVG_TIMER_MISC MAX_TIMER_MISC /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/ibdata1 wait/io/file/innodb/innodb_data_file 139701899661320 159 4313464775 2468315 27128390 1089383885 155 4277212530 10808685 27594860 1089383885 4603904 0 0 0 0 0 0 4 36252245 2468315 9062795 19559435 /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/ib_logfile0 wait/io/file/innodb/innodb_log_file 139701899662064 18 859997289125 579360 47777627075 737355723480 6 49179570 579360 8196595 40603480 69632 4 213666335 5489010 53416495 165793520 5120 8 859734443220 1563065 107466805225 737355723480 /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/ib_logfile1 wait/io/file/innodb/innodb_log_file 139701899662808 4 8753945 1363910 2188220 2830415 0 0 0 0 0 0 0 0 0 0 0 0 4 8753945 1363910 2188220 2830415 /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/undo001 wait/io/file/innodb/innodb_data_file 139701899663552 1 5419430 5419430 5419430 5419430 0 0 0 0 0 0 0 0 0 0 0 0 1 5419430 5419430 5419430 5419430 /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/test/t1.ibd wait/io/file/innodb/innodb_data_file 139701899761016 9 117401639975 4082855 13044626585 66887824130 0 0 0 0 0 0 3 214097305 13249665 71365650 149405300 114688 6 117187542670 4082855 19531256875 66887824130 select * from performance_schema.file_summary_by_instance where file_name like "%ibd"; FILE_NAME /home/malff/BZR_TREE/mysql-trunk/mysql-test/var/mysqld.1/data/test/t1.ibd EVENT_NAME wait/io/file/innodb/innodb_data_file OBJECT_INSTANCE_BEGIN 139701899761016 COUNT_STAR 9 SUM_TIMER_WAIT 117401639975 MIN_TIMER_WAIT 4082855 AVG_TIMER_WAIT 13044626585 MAX_TIMER_WAIT 66887824130 COUNT_READ 0 SUM_TIMER_READ 0 MIN_TIMER_READ 0 AVG_TIMER_READ 0 MAX_TIMER_READ 0 SUM_NUMBER_OF_BYTES_READ 0 COUNT_WRITE 3 SUM_TIMER_WRITE 214097305 MIN_TIMER_WRITE 13249665 AVG_TIMER_WRITE 71365650 MAX_TIMER_WRITE 149405300 SUM_NUMBER_OF_BYTES_WRITE 114688 COUNT_MISC 6 SUM_TIMER_MISC 117187542670 MIN_TIMER_MISC 4082855 AVG_TIMER_MISC 19531256875 MAX_TIMER_MISC 66887824130 update performance_schema.setup_instruments set enabled='YES'; set global innodb_file_per_table=OFF; drop table test.t1;
[29 Nov 2011 15:51]
Marc ALFF
As seen in the tests results, when: - the performance schema is configured to actually record file events (setup_instruments, setup_consumers) - innodb is configured to use one *.ibd file per table file io activity is seen by the performance schema for file test/t1.ibd. Note that the performance_schema.file_instance table in 5.6 provide more details compared to 5.5, but in both cases the performance schema knows about the file and reports statistics there.
[29 Nov 2011 17:09]
Marc ALFF
The bug reported, that the performance schema does not instrument file io to *.idb tables in the innobd storage engine, could not be reproduced. Closing this report. As for a follow up question, regarding file io with different storage engines, more clarification follows. For *FILE IO*, that is i/o operations on a physical file, each storage engine is free to instrument the code (or not) to report the file io performed to the performance schema. For the code maintained by Oracle, every file io operation has been instrumented, in the entire server and for storage engines. When a file io operation is located in a third party storage engine, or in general in third party code (engine, plug in, library, ...), it is up to the code owner to decide whether to instrument the code or not. The performance schema API themselves are publicly available, and documented. There are even tutorials on this topic, see: http://blogs.oracle.com/mysqlf/entry/mysql_university_performance_schema_instrumenting That being said, FILE IO (instrumented starting with 5.5) is a low level instrumentation. Starting with 5.6, the TABLE IO instrumentation is also available, to capture table io activity between the sql layer (mysql) and a storage engine. While instrumenting file io for each engine is up to each engine maintainer, the table io instrumentation is implemented in the sql layer itself, and is available regardless of the storage engine used. To simplify the overall picture: Application -- (sql statements) --> MySQL server MySQL server -- (table io) --> storage engine storage engine -- (file io) --> file system file system -- (disk io) --> disk storage Looking at the file io events collected by the performance schema is likely to show great discrepancies between storage engines (some cache data in memory, some don't, some are instrumented, others are not, etc) Looking at table io events collected by the performance schema is more likely to meaningful when profiling an application, to understand how the application causes data manipulation against tables themselves. Table IO is instrumented starting with 5.6 Also of interest, STATEMENT instrumentation is also available starting with 5.6. -- Marc Alff
[29 Nov 2011 17:22]
Peter Laursen
Well .. you did not close as you said you would. I also think that is Valeriy's decision and not yours. So I will consider this a verified bug with InnoDB (and Archive) engine(s). Please see my comment earlier "Maybe this is more a general requirement/request for the plugins interface". From your criteria it works as you have designed it. For users it makes no sense at all.
[31 May 2012 17:17]
Paul DuBois
Noted in 5.5.26, 5.6.6 changelogs. File access by the ARCHIVE storage engine was not instrumented and thus not shown in Performance Schema tables.
[8 Aug 2016 15:07]
MySQL Verification Team
I guess this was really about https://bugs.mysql.com/bug.php?id=68574