mirror/mariadb
1
0
Fork 0
mirror of https://github.com/MariaDB/server.git synced 2025-01-16 03:52:35 +01:00
Code Issues Projects Releases Packages Wiki Activity Actions

MDEV-14705: slow innodb startup/shutdown can exceed systemd timeout

Browse source 
Use systemd EXTEND_TIMEOUT_USEC to advise systemd of progress

Move towards progress measures rather than pure time based measures.

Progress reporting at numberious shutdown/startup locations incuding:
* For innodb_fast_shutdown=0 trx_roll_must_shutdown() for rolling back incomplete transactions.
* For merging the change buffer (in srv_shutdown(bool ibuf_merge))
* For purging history, srv_do_purge

Thanks Marko for feedback and suggestions.
This commit is contained in:
Daniel Black 2017-11-30 13:37:59 +11:00 committed by Marko Mäkelä
parent e7f4e61f6e
commit 1479273cdb
18 changed files with 151 additions and 30 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

11
include/my_systemd.h → include/my_service_manager.h
View file

@ -16,8 +16,8 @@
*/
#ifndef MY_SYSTEMD_INCLUDED
#define MY_SYSTEMD_INCLUDED
#ifndef MY_SERVICE_MANAGER_INCLUDED
#define MY_SERVICE_MANAGER_INCLUDED
#if defined(HAVE_SYSTEMD) && !defined(EMBEDDED_LIBRARY)
/*
@ -26,9 +26,14 @@
*/
#define __STDC_FORMAT_MACROS
#include <systemd/sd-daemon.h>
/** INTERVAL in seconds followed by printf style status */
#define service_manager_extend_timeout(INTERVAL, FMTSTR, ...) \
sd_notifyf(0, "STATUS=" FMTSTR "\nEXTEND_TIMEOUT_USEC=%u\n", ##__VA_ARGS__, INTERVAL * 1000000)
#else
#define sd_notify(X, Y)
#define sd_notifyf(E, F, ...)
#define service_manager_extend_timeout(I, FMTSTR, ...)
#endif
#endif /* MY_SYSTEMD_INCLUDED */
#endif /* MY_SERVICE_MANAGER_INCLUDED */

6
sql/mysqld.cc
View file

@ -111,7 +111,7 @@
#include <poll.h>
#endif
#include <my_systemd.h>
#include <my_service_manager.h>
#define mysqld_charset &my_charset_latin1
@ -6482,7 +6482,7 @@ void handle_connections_sockets()
#endif
sd_notify(0, "READY=1\n"
"STATUS=Taking your SQL requests now...");
"STATUS=Taking your SQL requests now...\n");
DBUG_PRINT("general",("Waiting for connections."));
MAYBE_BROKEN_SYSCALL;
@ -6700,7 +6700,7 @@ void handle_connections_sockets()
set_current_thd(0);
}
sd_notify(0, "STOPPING=1\n"
"STATUS=Shutdown in progress");
"STATUS=Shutdown in progress\n");
DBUG_VOID_RETURN;
}

9
storage/innobase/buf/buf0dump.cc
View file

@ -42,6 +42,7 @@ Created April 08, 2011 Vasil Dimov
#include "ut0byte.h" /* ut_ull_create() */
#include "ut0sort.h" /* UT_SORT_FUNCTION_BODY */
#include "mysql/service_wsrep.h" /* wsrep_recovery */
#include <my_service_manager.h>
enum status_severity {
STATUS_INFO,
@ -333,6 +334,14 @@ buf_dump(
i + 1, srv_buf_pool_instances,
j + 1, n_pages);
}
if ( (j % 1024) == 0) {
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"Dumping buffer pool "
ULINTPF "/" ULINTPF ", "
"page " ULINTPF "/" ULINTPF,
i + 1, srv_buf_pool_instances,
j + 1, n_pages);
}
}
ut_free(dump);

10
storage/innobase/buf/buf0flu.cc
View file

@ -54,6 +54,8 @@ Created 11/11/1995 Heikki Tuuri
#include "mysql/service_thd_wait.h"
#include "fil0pagecompress.h"
#include <my_service_manager.h>
/** Number of pages flushed through non flush_list flushes. */
static ulint buf_lru_flush_page_count = 0;
@ -528,6 +530,14 @@ buf_flush_remove(
buf_pool_t* buf_pool = buf_pool_from_bpage(bpage);
ulint zip_size;
/* TODO Marko: "I think that it might be useful to have a global time base for the shutdown progress reporting and extending the timeout intervals." */
if (UNIV_UNLIKELY(srv_shutdown_state == SRV_SHUTDOWN_FLUSH_PHASE)) {
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"Flush and remove page with tablespace id %d"
", Poolid %d, flush list length %d",
bpage->space, buf_pool->instance_no, UT_LIST_GET_LEN(buf_pool->flush_list));
}
ut_ad(buf_pool_mutex_own(buf_pool));
ut_ad(mutex_own(buf_page_get_mutex(bpage)));
ut_ad(bpage->in_flush_list);

2
storage/innobase/handler/ha_innodb.cc
View file

@ -55,7 +55,7 @@ MYSQL_PLUGIN_IMPORT extern char mysql_unpacked_real_data_home[];
#include <io.h>
#endif
#include <my_systemd.h>
#include <my_service_manager.h>
/** @file ha_innodb.cc */

4
storage/innobase/include/univ.i
View file

@ -65,6 +65,10 @@ component, i.e. we show M.N.P as M.N */
IB_TO_STR(INNODB_VERSION_MAJOR) "." \
IB_TO_STR(INNODB_VERSION_MINOR) "/en/"
/** How far ahead should we tell the service manager the timeout
(time in seconds) */
#define INNODB_EXTEND_TIMEOUT_INTERVAL 30
#ifdef MYSQL_DYNAMIC_PLUGIN
/* In the dynamic plugin, redefine some externally visible symbols
in order not to conflict with the symbols of a builtin InnoDB. */

26
storage/innobase/log/log0log.cc
View file

@ -39,7 +39,7 @@ Created 12/9/1995 Heikki Tuuri
#ifndef UNIV_HOTBACKUP
#if MYSQL_VERSION_ID < 100200
# include <my_systemd.h> /* sd_notifyf() */
# include <my_service_manager.h>
#endif
#include "mem0mem.h"
@ -1443,6 +1443,11 @@ log_write_up_to(
return;
}
if (srv_shutdown_state != SRV_SHUTDOWN_NONE) {
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"log write up to: %llu", lsn);
}
loop:
ut_ad(++loop_count < 100);
@ -2351,8 +2356,9 @@ loop:
if (recv_sys->report(ut_time())) {
ib_logf(IB_LOG_LEVEL_INFO, "Read redo log up to LSN=" LSN_PF,
start_lsn);
sd_notifyf(0, "STATUS=Read redo log up to LSN=" LSN_PF,
start_lsn);
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"Read redo log up to LSN=" LSN_PF,
start_lsn);
}
if (start_lsn != end_lsn) {
@ -3320,10 +3326,16 @@ wait_suspend_loop:
before proceeding further. */
count = 0;
#define COUNT_INTERVAL 600
#define CHECK_INTERVAL 100000
service_manager_extend_timeout(COUNT_INTERVAL * CHECK_INTERVAL/1000000 * 2,
"Waiting for page cleaner");
while (buf_page_cleaner_is_active) {
++count;
os_thread_sleep(100000);
if (srv_print_verbose_log && count > 600) {
os_thread_sleep(CHECK_INTERVAL);
if (srv_print_verbose_log && count > COUNT_INTERVAL) {
service_manager_extend_timeout(COUNT_INTERVAL * CHECK_INTERVAL/1000000 * 2,
"Waiting for page cleaner");
ib_logf(IB_LOG_LEVEL_INFO,
"Waiting for page_cleaner to "
"finish flushing of buffer pool");
@ -3408,6 +3420,8 @@ wait_suspend_loop:
}
if (!srv_read_only_mode) {
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"ensuring dirty buffer pool are written to log");
log_make_checkpoint_at(LSN_MAX, TRUE);
mutex_enter(&log_sys->mutex);
@ -3451,6 +3465,8 @@ wait_suspend_loop:
srv_thread_type type = srv_get_active_thread_type();
ut_a(type == SRV_NONE);
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"Free innodb buffer pool");
buf_all_freed();
ut_a(lsn == log_sys->lsn);

9
storage/innobase/log/log0recv.cc
View file

@ -30,7 +30,7 @@ Created 9/20/1997 Heikki Tuuri
#include <stdio.h> // Solaris/x86 header file bug
#include <vector>
#include <my_systemd.h>
#include <my_service_manager.h>
#include "log0recv.h"
@ -1717,8 +1717,8 @@ recv_recover_page_func(
if (recv_sys->report(time)) {
ib_logf(IB_LOG_LEVEL_INFO,
"To recover: " ULINTPF " pages from log", n);
sd_notifyf(0, "STATUS=To recover: " ULINTPF
" pages from log", n);
service_manager_extend_timeout(
INNODB_EXTEND_TIMEOUT_INTERVAL, "To recover: " ULINTPF " pages from log", n);
}
}
@ -2911,6 +2911,9 @@ recv_init_crash_recovery(void)
and restore them from the doublewrite buffer if
possible */
service_manager_extend_timeout(
INNODB_EXTEND_TIMEOUT_INTERVAL, "Starting Innodb crash recovery");
if (srv_force_recovery < SRV_FORCE_NO_LOG_REDO) {
buf_dblwr_process();

10
storage/innobase/srv/srv0srv.cc
View file

@ -77,6 +77,12 @@ Created 10/8/1995 Heikki Tuuri
#include "fil0pagecompress.h"
#include "btr0scrub.h"
#include <my_service_manager.h>
#ifdef WITH_WSREP
extern int wsrep_debug;
extern int wsrep_trx_is_aborting(void *thd_ptr);
#endif
/* The following is the maximum allowed duration of a lock wait. */
UNIV_INTERN ulong srv_fatal_semaphore_wait_threshold = DEFAULT_SRV_FATAL_SEMAPHORE_TIMEOUT;
@ -2727,6 +2733,10 @@ srv_do_purge(
*n_total_purged += n_pages_purged;
if (n_pages_purged > 0) {
service_manager_extend_timeout(
INNODB_EXTEND_TIMEOUT_INTERVAL, "Innodb %d pages purged", n_pages_purged);
}
} while (!srv_purge_should_exit(n_pages_purged)
&& n_pages_purged > 0
&& purge_sys->state == PURGE_STATE_RUN);

12
storage/innobase/trx/trx0roll.cc
View file

@ -25,7 +25,7 @@ Created 3/26/1996 Heikki Tuuri
*******************************************************/
#include "my_config.h"
#include <my_systemd.h>
#include <my_service_manager.h>
#include "trx0roll.h"
@ -740,11 +740,17 @@ UNIV_INTERN void trx_roll_report_progress()
n_rows += t->undo_no;
}
}
if (n_rows > 0) {
service_manager_extend_timeout(
INNODB_EXTEND_TIMEOUT_INTERVAL,
"To roll back: " ULINTPF " transactions, "
"%llu rows", n_trx, n_rows);
}
ib_logf(IB_LOG_LEVEL_INFO,
"To roll back: " ULINTPF " transactions, "
"%llu rows", n_trx, n_rows);
sd_notifyf(0, "STATUS=To roll back: " ULINTPF " transactions, "
"%llu rows", n_trx, n_rows);
}
mutex_exit(&recv_sys->mutex);

9
storage/xtradb/buf/buf0dump.cc
View file

@ -42,6 +42,7 @@ Created April 08, 2011 Vasil Dimov
#include "ut0byte.h" /* ut_ull_create() */
#include "ut0sort.h" /* UT_SORT_FUNCTION_BODY */
#include "mysql/service_wsrep.h" /* wsrep_recovery */
#include <my_service_manager.h>
enum status_severity {
STATUS_INFO,
@ -333,6 +334,14 @@ buf_dump(
i + 1, srv_buf_pool_instances,
j + 1, n_pages);
}
if ( (j % 1024) == 0) {
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"Dumping buffer pool "
ULINTPF "/" ULINTPF ", "
"page " ULINTPF "/" ULINTPF,
i + 1, srv_buf_pool_instances,
j + 1, n_pages);
}
}
ut_free(dump);

10
storage/xtradb/buf/buf0flu.cc
View file

@ -54,6 +54,8 @@ Created 11/11/1995 Heikki Tuuri
#include "mysql/service_thd_wait.h"
#include "fil0pagecompress.h"
#include <my_service_manager.h>
/** Number of pages flushed through non flush_list flushes. */
// static ulint buf_lru_flush_page_count = 0;
@ -575,6 +577,14 @@ buf_flush_remove(
buf_pool_t* buf_pool = buf_pool_from_bpage(bpage);
ulint zip_size;
/* TODO Marko: "I think that it might be useful to have a global time base for the shutdown progress reporting and extending the timeout intervals." */
if (UNIV_UNLIKELY(srv_shutdown_state == SRV_SHUTDOWN_FLUSH_PHASE)) {
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"Flush and remove page with tablespace id %d"
", Poolid %d, flush list length %d",
bpage->space, buf_pool->instance_no, UT_LIST_GET_LEN(buf_pool->flush_list));
}
ut_ad(mutex_own(buf_page_get_mutex(bpage)));
#if defined UNIV_DEBUG || defined UNIV_BUF_DEBUG
ut_ad(buf_page_get_state(bpage) != BUF_BLOCK_ZIP_DIRTY

2
storage/xtradb/handler/ha_innodb.cc
View file

@ -50,7 +50,7 @@ this program; if not, write to the Free Software Foundation, Inc.,
#include <io.h>
#endif
#include <my_systemd.h>
#include <my_service_manager.h>
/** @file ha_innodb.cc */

4
storage/xtradb/include/univ.i
View file

@ -73,6 +73,10 @@ component, i.e. we show M.N.P as M.N */
IB_TO_STR(INNODB_VERSION_MAJOR) "." \
IB_TO_STR(INNODB_VERSION_MINOR) "/en/"
/** How far ahead should we tell the service manager the timeout
(time in seconds) */
#define INNODB_EXTEND_TIMEOUT_INTERVAL 30
#ifdef MYSQL_DYNAMIC_PLUGIN
/* In the dynamic plugin, redefine some externally visible symbols
in order not to conflict with the symbols of a builtin InnoDB. */

26
storage/xtradb/log/log0log.cc
View file

@ -49,7 +49,7 @@ Created 12/9/1995 Heikki Tuuri
#ifndef UNIV_HOTBACKUP
#if MYSQL_VERSION_ID < 100200
# include <my_systemd.h> /* sd_notifyf() */
# include <my_service_manager.h>
#endif
#include "mem0mem.h"
@ -1561,6 +1561,11 @@ log_write_up_to(
return;
}
if (srv_shutdown_state != SRV_SHUTDOWN_NONE) {
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"log write up to: %llu", lsn);
}
loop:
ut_ad(++loop_count < 100);
@ -2602,8 +2607,9 @@ loop:
if (recv_recovery_is_on() && recv_sys && recv_sys->report(ut_time())) {
ib_logf(IB_LOG_LEVEL_INFO, "Read redo log up to LSN=" LSN_PF,
start_lsn);
sd_notifyf(0, "STATUS=Read redo log up to LSN=" LSN_PF,
start_lsn);
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"Read redo log up to LSN=" LSN_PF,
start_lsn);
}
if (start_lsn != end_lsn) {
@ -3636,6 +3642,10 @@ wait_suspend_loop:
before proceeding further. */
count = 0;
#define COUNT_INTERVAL 600
#define CHECK_INTERVAL 100000
service_manager_extend_timeout(COUNT_INTERVAL * CHECK_INTERVAL/1000000 * 2,
"Waiting for page cleaner");
os_rmb;
while (buf_page_cleaner_is_active || buf_lru_manager_is_active) {
if (srv_print_verbose_log && count == 0) {
@ -3644,8 +3654,10 @@ wait_suspend_loop:
"finish flushing of buffer pool");
}
++count;
os_thread_sleep(100000);
if (count > 600) {
os_thread_sleep(CHECK_INTERVAL);
if (srv_print_verbose_log && count > COUNT_INTERVAL) {
service_manager_extend_timeout(COUNT_INTERVAL * CHECK_INTERVAL/1000000 * 2,
"Waiting for page cleaner");
count = 0;
}
os_rmb;
@ -3730,6 +3742,8 @@ wait_suspend_loop:
}
if (!srv_read_only_mode) {
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"ensuring dirty buffer pool are written to log");
log_make_checkpoint_at(LSN_MAX, TRUE);
mutex_enter(&log_sys->mutex);
@ -3774,6 +3788,8 @@ wait_suspend_loop:
srv_thread_type type = srv_get_active_thread_type();
ut_a(type == SRV_NONE);
service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
"Free innodb buffer pool");
buf_all_freed();
ut_a(lsn == log_sys->lsn);

9
storage/xtradb/log/log0recv.cc
View file

@ -30,7 +30,7 @@ Created 9/20/1997 Heikki Tuuri
#include <stdio.h> // Solaris/x86 header file bug
#include <vector>
#include <my_systemd.h>
#include <my_service_manager.h>
#include "log0recv.h"
@ -1804,8 +1804,8 @@ recv_recover_page_func(
if (recv_sys->report(time)) {
ib_logf(IB_LOG_LEVEL_INFO,
"To recover: " ULINTPF " pages from log", n);
sd_notifyf(0, "STATUS=To recover: " ULINTPF
" pages from log", n);
service_manager_extend_timeout(
INNODB_EXTEND_TIMEOUT_INTERVAL, "To recover: " ULINTPF " pages from log", n);
}
}
@ -3001,6 +3001,9 @@ recv_init_crash_recovery(void)
and restore them from the doublewrite buffer if
possible */
service_manager_extend_timeout(
INNODB_EXTEND_TIMEOUT_INTERVAL, "Starting Innodb crash recovery");
if (srv_force_recovery < SRV_FORCE_NO_LOG_REDO) {
buf_dblwr_process();

10
storage/xtradb/srv/srv0srv.cc
View file

@ -86,6 +86,12 @@ ibool innobase_get_slow_log();
in the server */
UNIV_INTERN ulint srv_activity_count = 0;
#include <my_service_manager.h>
#ifdef WITH_WSREP
extern int wsrep_debug;
extern int wsrep_trx_is_aborting(void *thd_ptr);
#endif
/* The following is the maximum allowed duration of a lock wait. */
UNIV_INTERN ulong srv_fatal_semaphore_wait_threshold = DEFAULT_SRV_FATAL_SEMAPHORE_TIMEOUT;
@ -3435,6 +3441,10 @@ srv_do_purge(
*n_total_purged += n_pages_purged;
if (n_pages_purged > 0) {
service_manager_extend_timeout(
INNODB_EXTEND_TIMEOUT_INTERVAL, "Innodb %d pages purged", n_pages_purged);
}
} while (!srv_purge_should_exit(n_pages_purged)
&& n_pages_purged > 0
&& purge_sys->state == PURGE_STATE_RUN);

12
storage/xtradb/trx/trx0roll.cc
View file

@ -25,7 +25,7 @@ Created 3/26/1996 Heikki Tuuri
*******************************************************/
#include "my_config.h"
#include <my_systemd.h>
#include <my_service_manager.h>
#include "trx0roll.h"
@ -752,11 +752,17 @@ UNIV_INTERN void trx_roll_report_progress()
n_rows += t->undo_no;
}
}
if (n_rows > 0) {
service_manager_extend_timeout(
INNODB_EXTEND_TIMEOUT_INTERVAL,
"To roll back: " ULINTPF " transactions, "
"%llu rows", n_trx, n_rows);
}
ib_logf(IB_LOG_LEVEL_INFO,
"To roll back: " ULINTPF " transactions, "
"%llu rows", n_trx, n_rows);
sd_notifyf(0, "STATUS=To roll back: " ULINTPF " transactions, "
"%llu rows", n_trx, n_rows);
}
mutex_exit(&recv_sys->mutex);