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.

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);
 
   /*

mysql-test/r/warnings_debug.result

+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;

mysql-test/t/warnings_debug.test

+--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;

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

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
   {

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:

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);
 }
 

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

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	\

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);
 

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
 }
 

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)