MySQL Bugs: #43985: FILE_SUMMARY_BY_INSTANCE.SUM_NUMBER_OF_BYTES

Bug #43985	FILE_SUMMARY_BY_INSTANCE.SUM_NUMBER_OF_BYTES_* are wrong
Submitted:	31 Mar 2009 12:26	Modified:	14 Jan 2010 18:02
Reporter:	Guilhem Bichot	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Performance Schema	Severity:	S3 (Non-critical)
Version:	mysql-6.0-perf	OS:	Linux (32-bit)
Assigned to:	Marc ALFF	CPU Architecture:	Any

Description:
I have marc.alff@sun.com-20090328101325-yfsug776ebsz55uy .
I do this:
./mtr --mem alias --start --debug &
../client/mysql --html -uroot -S var/tmp/mysqld.1.sock < /m/wl2360/dump_all_pfs.sql > /tmp/dump_all_pfs.html
where the SQL file is attached to the bug report.
Here's the oddity I see:
./performance_schema/EVENTS_WAITS_SUMMARY_BY_INSTANCE.frm	wait/io/file/sql/FRM	11	7	338293	334880
./performance_schema/EVENTS_WAITS_SUMMARY_BY_THREAD_BY_EVENT_NAME.frm	wait/io/file/sql/FRM	10	6	382043	380700
Those numbers are not reasonable (too big). By looking at the --debug trace, I see that the actual number of bytes read from those frm files is <1000 (I see this by reading debug printouts of my_read() and my_pread()).

How to repeat:
./mtr --mem alias --start --debug &
../client/mysql --html -uroot -S var/tmp/mysqld.1.sock < /m/wl2360/dump_all_pfs.sql > /tmp/dump_all_pfs.html

SQL for BUG#43985

Attachment: dump_all_pfs.sql (text/x-sql), 1.08 KiB.

It could be linked to the fact that, even though I see lf_hash_insert() calls in storage/perfschema, I don't see any lf_hash_delete() (I expected this to be called when a file is closed). Possibly the same line in FILE_SUMMARY_BY_INSTANCE gets re-used over and over for different files without proper resetting, and thus all writes to different files are attributed to a single file, making a big sum??

Patch not attached automatically to the bug report, adding it manually:

#At file:///home/malff/BZR-TREE/mysql-6.0-perf/ based on revid:marc.alff@sun.com-20090331002247-aeju27e9vijtzg23

 2841 Marc Alff	2009-03-31
      Bug#43985 FILE_SUMMARY_BY_INSTANCE.SUM_NUMBER_OF_BYTES_* are wrong
      
      In case of code sequence like this:
        file_A= MYSQL_OPEN(key_file_A, "AAA", ...);
        MYSQL_READ(file_A, ...);
        MYSQL_CLOSE_(file_A);
      
        file_B= my_open("BBB"); <-- un instrumented call
        MYSQL_WRITE(file_B, ...);
        MYSQL_CLOSE_(file_B);
      
      and in case the same file descriptor number is used for file A and B
      (it can be reused after the call to close()),
      the performance schema would charge the file io for B against instrumented
      file A, which is incorrect.
      
      With this fix:
      - the instrumentation for A is properly cleaned up on close,
      - the file io for B is lost since file B is not instrumented.
modified:
  storage/perfschema/pfs.cc
  storage/perfschema/unittest/pfs-t.cc

=== modified file 'storage/perfschema/pfs.cc'
--- a/storage/perfschema/pfs.cc	2009-03-29 21:38:18 +0000
+++ b/storage/perfschema/pfs.cc	2009-03-31 17:44:18 +0000
@@ -25,6 +25,11 @@
 #undef HAVE_TABLE_WAIT
 
 /**
+  @file
+  The performance schema implementation of all instruments.
+*/
+
+/**
   @page PAGE_PERFORMANCE_SCHEMA The Performance Schema main page
   MySQL PERFORMANCE_SCHEMA implementation.
 
@@ -1221,6 +1226,17 @@ get_thread_file_descriptor_locker_v1(Fil
     if (pfs_file)
     {
       PFS_thread *pfs_thread;
+
+      /*
+        We are about to close a file by descriptor number,
+        and the calling code still holds the descriptor.
+        Cleanup the file descriptor <--> file instrument association.
+        Remove the instrumentation *before* the close to avoid race conditions
+        with another thread opening a file (that could be given the same descriptor).
+      */
+      if (op == PSI_FILE_CLOSE)
+        file_instrumentation[index]= NULL;
+
       DBUG_ASSERT(pfs_file->m_info != NULL);
       if (! pfs_file->m_info->m_instr.m_enabled)
         return NULL;

=== modified file 'storage/perfschema/unittest/pfs-t.cc'
--- a/storage/perfschema/unittest/pfs-t.cc	2009-03-27 20:06:50 +0000
+++ b/storage/perfschema/unittest/pfs-t.cc	2009-03-31 17:44:18 +0000
@@ -1018,6 +1018,92 @@ void test_locker_disabled()
   shutdown_performance_schema();
 }
 
+void test_file_instrumentation_leak()
+{
+  PSI *psi;
+
+  diag("test_file_instrumentation_leak");
+
+  psi= load_perfschema();
+
+  PSI_file_key file_key_A;
+  PSI_file_key file_key_B;
+  PSI_file_info all_file[]=
+  {
+    { & file_key_A, "F-A", 0},
+    { & file_key_B, "F-B", 0}
+  };
+
+  PSI_thread_key thread_key_1;
+  PSI_thread_info all_thread[]=
+  {
+    { & thread_key_1, "T-1", 0}
+  };
+
+  psi->register_file("test", all_file, 2);
+  psi->register_thread("test", all_thread, 1);
+
+  PFS_file_info *file_info_A;
+  PFS_file_info *file_info_B;
+  PSI_thread *thread_1;
+
+  /* Preparation */
+
+  thread_1= psi->new_thread(thread_key_1, NULL);
+  ok(thread_1 != NULL, "T-1");
+  psi->set_thread_id(thread_1, 1);
+
+  file_info_A= find_file_info(file_key_A);
+  ok(file_info_A != NULL, "file info A");
+
+  file_info_B= find_file_info(file_key_B);
+  ok(file_info_B != NULL, "file info B");
+
+  psi->set_thread(thread_1);
+
+  /* Pretend everything is enabled */
+  /* ----------------------------- */
+
+  setup_thread(thread_1, true);
+  flag_events_waits_current= true;
+  file_info_A->m_instr.m_enabled= true;
+  file_info_B->m_instr.m_enabled= true;
+
+  PSI_file_locker *file_locker;
+
+  /* Simulate OPEN + READ of 100 bytes + CLOSE on descriptor 12 */
+
+  file_locker= psi->get_thread_file_name_locker(file_key_A, PSI_FILE_OPEN, "AAA", NULL);
+  ok(file_locker != NULL, "locker");
+  psi->start_file_open_wait(file_locker, __FILE__, __LINE__);
+  psi->end_file_open_wait_and_bind_to_descriptor(file_locker, 12);
+
+  file_locker= psi->get_thread_file_descriptor_locker((File) 12, PSI_FILE_READ);
+  ok(file_locker != NULL, "locker");
+  psi->start_file_wait(file_locker, 100, __FILE__, __LINE__);
+  psi->end_file_wait(file_locker, 100);
+
+  file_locker= psi->get_thread_file_descriptor_locker((File) 12, PSI_FILE_CLOSE);
+  ok(file_locker != NULL, "locker");
+  psi->start_file_wait(file_locker, 0, __FILE__, __LINE__);
+  psi->end_file_wait(file_locker, 0);
+
+  /* Simulate uninstrumented-OPEN + WRITE on descriptor 24 */
+
+  file_locker= psi->get_thread_file_descriptor_locker((File) 24, PSI_FILE_WRITE);
+  ok(file_locker == NULL, "no locker, since the open was not instrumented");
+
+  /*
+    Simulate uninstrumented-OPEN + WRITE on descriptor 12 :
+    the instrumentation should not leak (don't charge the file io on unknown B to "AAA")
+  */
+
+  file_locker= psi->get_thread_file_descriptor_locker((File) 12, PSI_FILE_WRITE);
+  ok(file_locker == NULL, "no locker, no leak");
+
+  shutdown_performance_schema();
+}
+
 void test_enabled()
 {
 #ifdef LATER
@@ -1061,11 +1147,12 @@ void do_all_tests()
   test_bad_registration();
   test_init_disabled();
   test_locker_disabled();
+  test_file_instrumentation_leak();
 }
 
 int main(int, char **)
 {
-  plan(148);
+  plan(155);
 
   my_init_thread();
   my_thread_global_init();

Queued in mysql-6.0-perfschema

Merged in:
- mysql-next-mr (Celosia / 5.5.99-m3)
- mysql-6.0-codebase (6.0.14)

Not in any released version. No changelog entry needed.