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.

client/mysqltest.cc:
  If we detect recursive die(), at least print the message before aborting.
mysql-test/r/warnings_debug.result:
  Test case.
mysql-test/t/warnings_debug.test:
  Test case.
sql/handler.cc:
  Force generation of a warning with specific debug option, for testing.
sql/protocol.cc:
  Fix wrong DBUG_ENTER
sql/sql_class.h:
  Add method to count warnings pushed after set_ok_status() is called.
sql/sql_error.cc:
  Also count warnings pushed after set_ok_status() is called.
storage/xtradb/include/os0sync.h:
  Implement working os_sync_wait_time() for POSIX.
storage/xtradb/include/srv0srv.h:
  Make the purge thread wait for an event when sleeping, so we can signal it to
  wakeup immediately at shutdown.
storage/xtradb/log/log0log.c:
  Make the purge thread wait for an event when sleeping, so we can signal it to
  wakeup immediately at shutdown.
storage/xtradb/os/os0sync.c:
  Implement working os_sync_wait_time() for POSIX.
storage/xtradb/srv/srv0srv.c:
  Make the purge thread wait for an event when sleeping, so we can signal it to
  wakeup immediately at shutdown.

12 files changed, 109 insertions, 20 deletions

diff --git a/client/mysqltest.cc b/client/mysqltest.cc
index cb59c93365b..7f97dae3694 100644
--- a/client/mysqltest.cc
+++ b/client/mysqltest.cc
@@ -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);
 
   /*
diff --git a/mysql-test/r/warnings_debug.result b/mysql-test/r/warnings_debug.result
new file mode 100644
index 00000000000..08908bf0437
--- /dev/null
+++ b/mysql-test/r/warnings_debug.result
@@ -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;
diff --git a/mysql-test/t/warnings_debug.test b/mysql-test/t/warnings_debug.test
new file mode 100644
index 00000000000..99d02330960
--- /dev/null
+++ b/mysql-test/t/warnings_debug.test
@@ -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;
diff --git a/sql/handler.cc b/sql/handler.cc
index c331a3bb855..b849cfafc19 100644
--- a/sql/handler.cc
+++ b/sql/handler.cc
@@ -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
diff --git a/sql/protocol.cc b/sql/protocol.cc
index 3df0eddea93..bd2bb0e724a 100644
--- a/sql/protocol.cc
+++ b/sql/protocol.cc
@@ -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
   {
diff --git a/sql/sql_class.h b/sql/sql_class.h
index 56b6a246423..fd47de29a63 100644
--- a/sql/sql_class.h
+++ b/sql/sql_class.h
@@ -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:
diff --git a/sql/sql_error.cc b/sql/sql_error.cc
index 9ea7facbe41..835e60cd6ba 100644
--- a/sql/sql_error.cc
+++ b/sql/sql_error.cc
@@ -159,6 +159,8 @@ MYSQL_ERROR *push_warning(THD *thd, MYSQL_ERROR::enum_warning_level level,
   }
   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);
 }
 
diff --git a/storage/xtradb/include/os0sync.h b/storage/xtradb/include/os0sync.h
index 0c22162b900..c230a03b6db 100644
--- a/storage/xtradb/include/os0sync.h
+++ b/storage/xtradb/include/os0sync.h
@@ -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
diff --git a/storage/xtradb/include/srv0srv.h b/storage/xtradb/include/srv0srv.h
index dc455581350..8c64d5cee71 100644
--- a/storage/xtradb/include/srv0srv.h
+++ b/storage/xtradb/include/srv0srv.h
@@ -57,6 +57,9 @@ extern const char	srv_mysql50_table_name_prefix[9];
 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	\
diff --git a/storage/xtradb/log/log0log.c b/storage/xtradb/log/log0log.c
index fade31037b5..b9f19aeff31 100644
--- a/storage/xtradb/log/log0log.c
+++ b/storage/xtradb/log/log0log.c
@@ -3102,6 +3102,7 @@ logs_empty_and_mark_files_at_shutdown(void)
 	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);
 
diff --git a/storage/xtradb/os/os0sync.c b/storage/xtradb/os/os0sync.c
index 60467242e14..f9ab58c2ee4 100644
--- a/storage/xtradb/os/os0sync.c
+++ b/storage/xtradb/os/os0sync.c
@@ -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;
+
+	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;
+		}
+	}
 
-	/* In Posix this is just an ordinary, infinite wait */
+	os_fast_mutex_unlock(&(event->os_mutex));
 
-	os_event_wait(event);
+	if (srv_shutdown_state == SRV_SHUTDOWN_EXIT_THREADS) {
+
+		os_thread_exit(NULL);
+	}
 
-	return(0);
+	return ret;
 #endif
 }
 
diff --git a/storage/xtradb/srv/srv0srv.c b/storage/xtradb/srv/srv0srv.c
index c1d0f255c64..43799aab196 100644
--- a/storage/xtradb/srv/srv0srv.c
+++ b/storage/xtradb/srv/srv0srv.c
@@ -704,6 +704,8 @@ UNIV_INTERN srv_slot_t*	srv_mysql_table = NULL;
 
 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)