[Commits] Rev 2964: MBug#643463: slow XtraDB shutdown due to 10 second sleep in purge thread in http://bazaar.launchpad.net/~maria-captains/maria/5.1

knielsen at knielsen-hq.org knielsen at knielsen-hq.org
Wed Nov 3 23:40:54 EET 2010


At http://bazaar.launchpad.net/~maria-captains/maria/5.1

------------------------------------------------------------
revno: 2964
revision-id: knielsen at knielsen-hq.org-20101103214053-je3lm7eaw22955tm
parent: knielsen at knielsen-hq.org-20101029075645-mxpl750gto4zfdtb
committer: knielsen at knielsen-hq.org
branch nick: work-5.1-mysqltest
timestamp: Wed 2010-11-03 22:40:53 +0100
message:
  MBug#643463: slow XtraDB shutdown due to 10 second sleep in purge thread
  
  Implement os_event_wait_time() for POSIX systems.
  
  In the purge thread, use os_event_wait_time() when sleeping rather than sleep,
  and signal the event when server shuts down, so we do not need to wait for
  upto 10 seconds until the purge thread wakes up.
  
  Also fix bug that warnings that were pushed after we call set_ok_status() were
  not included in the waning count sent to the client in the result packet.
  
  Also in mysqltest, in recursive die() invocation at least print the message
  before aborting.
=== modified file 'client/mysqltest.cc'
--- a/client/mysqltest.cc	2010-10-29 07:56:45 +0000
+++ b/client/mysqltest.cc	2010-11-03 21:40:53 +0000
@@ -1254,15 +1254,6 @@ void die(const char *fmt, ...)
   DBUG_ENTER("die");
   DBUG_PRINT("enter", ("start_lineno: %d", start_lineno));
 
-  /*
-    Protect against dying twice
-    first time 'die' is called, try to write log files
-    second time, just exit
-  */
-  if (dying)
-    cleanup_and_exit(1);
-  dying= 1;
-
   /* Print the error message */
   fprintf(stderr, "mysqltest: ");
   if (cur_file && cur_file != file_stack)
@@ -1281,6 +1272,15 @@ void die(const char *fmt, ...)
   fprintf(stderr, "\n");
   fflush(stderr);
 
+  /*
+    Protect against dying twice
+    first time 'die' is called, try to write log files
+    second time, just exit
+  */
+  if (dying)
+    cleanup_and_exit(1);
+  dying= 1;
+
   log_file.show_tail(opt_tail_lines);
 
   /*

=== added file 'mysql-test/r/warnings_debug.result'
--- a/mysql-test/r/warnings_debug.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/r/warnings_debug.result	2010-11-03 21:40:53 +0000
@@ -0,0 +1,10 @@
+drop table if exists t1;
+create table t1 (a int primary key) engine=innodb;
+SET SESSION debug="+d,warn_during_ha_commit_trans";
+INSERT INTO t1 VALUES (1);
+Warnings:
+Warning 1196    Some non-transactional changed tables couldn't be rolled back
+SHOW WARNINGS;
+Level   Code    Message
+Warning 1196    Some non-transactional changed tables couldn't be rolled back
+drop table t1;

=== added file 'mysql-test/t/warnings_debug.test'
--- a/mysql-test/t/warnings_debug.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/t/warnings_debug.test	2010-11-03 21:40:53 +0000
@@ -0,0 +1,19 @@
+--source include/have_innodb.inc
+--source include/have_debug.inc
+
+--disable_warnings
+drop table if exists t1;
+--enable_warnings
+
+create table t1 (a int primary key) engine=innodb;
+
+# Test that warnings produced during autocommit (after calling
+# set_ok_status()) are still reported to the client.
+SET SESSION debug="+d,warn_during_ha_commit_trans";
+INSERT INTO t1 VALUES (1);
+# The warning will be shown automatically by mysqltest; there was a bug where
+# this didn't happen because the warning was not counted when sending result
+# packet. Show the warnings manually also.
+SHOW WARNINGS;
+
+drop table t1;

=== modified file 'sql/handler.cc'
--- a/sql/handler.cc	2010-10-20 10:58:43 +0000
+++ b/sql/handler.cc	2010-11-03 21:40:53 +0000
@@ -1093,6 +1093,12 @@ int ha_commit_trans(THD *thd, bool all)
   my_xid xid= thd->transaction.xid_state.xid.get_my_xid();
   DBUG_ENTER("ha_commit_trans");
 
+  /* Just a random warning to test warnings pushed during autocommit. */
+  DBUG_EXECUTE_IF("warn_during_ha_commit_trans",
+    push_warning(thd, MYSQL_ERROR::WARN_LEVEL_WARN,
+                 ER_WARNING_NOT_COMPLETE_ROLLBACK,
+                 ER(ER_WARNING_NOT_COMPLETE_ROLLBACK)););
+
   /*
     We must not commit the normal transaction if a statement
     transaction is pending. Otherwise statement transaction

=== modified file 'sql/protocol.cc'
--- a/sql/protocol.cc	2010-08-27 14:12:44 +0000
+++ b/sql/protocol.cc	2010-11-03 21:40:53 +0000
@@ -203,7 +203,7 @@ net_send_ok(THD *thd,
   NET *net= &thd->net;
   uchar buff[MYSQL_ERRMSG_SIZE+10],*pos;
   bool error= FALSE;
-  DBUG_ENTER("my_ok");
+  DBUG_ENTER("net_send_ok");
 
   if (! net->vio)       // hack for re-parsing queries
   {

=== modified file 'sql/sql_class.h'
--- a/sql/sql_class.h	2010-10-19 13:58:35 +0000
+++ b/sql/sql_class.h	2010-11-03 21:40:53 +0000
@@ -1211,6 +1211,13 @@ public:
     return m_total_warn_count;
   }
 
+  /* Used to count any warnings pushed after calling set_ok_status(). */
+  void increment_warning()
+  {
+    if (m_status != DA_EMPTY)
+      m_total_warn_count++;
+  }
+
   Diagnostics_area() { reset_diagnostics_area(); }
 
 private:

=== modified file 'sql/sql_error.cc'
--- a/sql/sql_error.cc	2009-02-13 16:41:47 +0000
+++ b/sql/sql_error.cc	2010-11-03 21:40:53 +0000
@@ -159,6 +159,8 @@ MYSQL_ERROR *push_warning(THD *thd, MYSQ
   }
   thd->warn_count[(uint) level]++;
   thd->total_warn_count++;
+  /* Make sure we also count warnings pushed after calling set_ok_status(). */
+  thd->main_da.increment_warning();
   DBUG_RETURN(err);
 }
 

=== modified file 'storage/xtradb/include/os0sync.h'
--- a/storage/xtradb/include/os0sync.h	2010-01-06 12:00:14 +0000
+++ b/storage/xtradb/include/os0sync.h	2010-11-03 21:40:53 +0000
@@ -189,7 +189,7 @@ os_event_wait_low(
 
 /**********************************************************//**
 Waits for an event object until it is in the signaled state or
-a timeout is exceeded. In Unix the timeout is always infinite.
+a timeout is exceeded.
 @return 0 if success, OS_SYNC_TIME_EXCEEDED if timeout was exceeded */
 UNIV_INTERN
 ulint

=== modified file 'storage/xtradb/include/srv0srv.h'
--- a/storage/xtradb/include/srv0srv.h	2010-10-19 12:16:15 +0000
+++ b/storage/xtradb/include/srv0srv.h	2010-11-03 21:40:53 +0000
@@ -57,6 +57,9 @@ extern const char	srv_mysql50_table_name
 thread starts running */
 extern os_event_t       srv_lock_timeout_thread_event;
 
+/* This event is set to tell the purge thread to shut down */
+extern os_event_t       srv_purge_thread_event;
+
 /* If the last data file is auto-extended, we add this many pages to it
 at a time */
 #define SRV_AUTO_EXTEND_INCREMENT       \

=== modified file 'storage/xtradb/log/log0log.c'
--- a/storage/xtradb/log/log0log.c	2010-09-03 15:41:57 +0000
+++ b/storage/xtradb/log/log0log.c	2010-11-03 21:40:53 +0000
@@ -3102,6 +3102,7 @@ logs_empty_and_mark_files_at_shutdown(vo
         algorithm only works if the server is idle at shutdown */
 
         srv_shutdown_state = SRV_SHUTDOWN_CLEANUP;
+        os_event_set(srv_purge_thread_event);
 loop:
         os_thread_sleep(100000);
 

=== modified file 'storage/xtradb/os/os0sync.c'
--- a/storage/xtradb/os/os0sync.c	2010-01-06 12:00:14 +0000
+++ b/storage/xtradb/os/os0sync.c	2010-11-03 21:40:53 +0000
@@ -31,6 +31,9 @@ Created 9/6/1995 Heikki Tuuri
 
 #ifdef __WIN__
 #include <windows.h>
+#else
+#include <sys/time.h>
+#include <time.h>
 #endif
 
 #include "ut0mem.h"
@@ -407,14 +410,14 @@ os_event_wait_low(
 
 /**********************************************************//**
 Waits for an event object until it is in the signaled state or
-a timeout is exceeded. In Unix the timeout is always infinite.
+a timeout is exceeded.
 @return 0 if success, OS_SYNC_TIME_EXCEEDED if timeout was exceeded */
 UNIV_INTERN
 ulint
 os_event_wait_time(
 /*===============*/
         os_event_t      event,  /*!< in: event to wait */
-        ulint           time)   /*!< in: timeout in microseconds, or
+        ulint           wtime)  /*!< in: timeout in microseconds, or
                                 OS_SYNC_INFINITE_TIME */
 {
 #ifdef __WIN__
@@ -422,8 +425,8 @@ os_event_wait_time(
 
         ut_a(event);
 
-        if (time != OS_SYNC_INFINITE_TIME) {
-                err = WaitForSingleObject(event->handle, (DWORD) time / 1000);
+        if (wtime != OS_SYNC_INFINITE_TIME) {
+                err = WaitForSingleObject(event->handle, (DWORD) wtime / 1000);
         } else {
                 err = WaitForSingleObject(event->handle, INFINITE);
         }
@@ -439,13 +442,47 @@ os_event_wait_time(
                 return(1000000); /* dummy value to eliminate compiler warn. */
         }
 #else
-        UT_NOT_USED(time);
+        int     err;
+        int     ret = 0;
+        ulint   tmp;
+        ib_int64_t      old_count;
+        struct timeval tv_start;
+        struct timespec timeout;
+
+        if (wtime == OS_SYNC_INFINITE_TIME) {
+                os_event_wait(event);
+                return 0;
+        }
+
+        /* Compute the absolute point in time at which to time out. */
+        gettimeofday(&tv_start, NULL);
+        tmp = tv_start.tv_usec + wtime;
+        timeout.tv_sec = tv_start.tv_sec + (tmp / 1000000);
+        timeout.tv_nsec = (tmp % 1000000) * 1000;
+
+        os_fast_mutex_lock(&(event->os_mutex));
+        old_count = event->signal_count;
 
-        /* In Posix this is just an ordinary, infinite wait */
+        for (;;) {
+                if (event->is_set == TRUE || event->signal_count != old_count)
+                        break;
+
+                err = pthread_cond_timedwait(&(event->cond_var),
+                                             &(event->os_mutex), &timeout);
+                if (err == ETIMEDOUT) {
+                        ret = OS_SYNC_TIME_EXCEEDED;
+                        break;
+                }
+        }
 
-        os_event_wait(event);
+        os_fast_mutex_unlock(&(event->os_mutex));
+
+        if (srv_shutdown_state == SRV_SHUTDOWN_EXIT_THREADS) {
+
+                os_thread_exit(NULL);
+        }
 
-        return(0);
+        return ret;
 #endif
 }
 

=== modified file 'storage/xtradb/srv/srv0srv.c'
--- a/storage/xtradb/srv/srv0srv.c	2010-10-19 12:16:15 +0000
+++ b/storage/xtradb/srv/srv0srv.c	2010-11-03 21:40:53 +0000
@@ -704,6 +704,8 @@ UNIV_INTERN srv_slot_t*	srv_mysql_table 
 
 UNIV_INTERN os_event_t  srv_lock_timeout_thread_event;
 
+UNIV_INTERN os_event_t  srv_purge_thread_event;
+
 UNIV_INTERN srv_sys_t*  srv_sys = NULL;
 
 /* padding to prevent other memory update hotspots from residing on
@@ -1009,6 +1011,7 @@ srv_init(void)
         }
 
         srv_lock_timeout_thread_event = os_event_create(NULL);
+        srv_purge_thread_event = os_event_create(NULL);
 
         for (i = 0; i < SRV_MASTER + 1; i++) {
                 srv_n_threads_active[i] = 0;
@@ -3337,9 +3340,10 @@ loop:
                 mutex_exit(&kernel_mutex);
 
                 sleep_ms = 10;
+                os_event_reset(srv_purge_thread_event);
         }
 
-        os_thread_sleep( sleep_ms * 1000 );
+        os_event_wait_time(srv_purge_thread_event, sleep_ms * 1000);
 
         history_len = trx_sys->rseg_history_len;
         if (history_len > 1000)



More information about the commits mailing list