Skip to content

M
MariaDB
Commit 9c47beb8 authored by Marko Mäkelä's avatar Marko Mäkelä
Browse files
Options

MDEV-11027 InnoDB log recovery is too noisy 

Provide more useful progress reporting of crash recovery.

recv_sys_t::progress_time: The time of the last report.

recv_scan_print_counter: Remove.

log_group_read_log_seg(): After after each I/O request,
report progress if needed.

recv_apply_hashed_log_recs(): At the start of each batch,
if there are pages to be recovered, issue a message.
parent 1fd3cc8c
Hide whitespace changes
Inline Side-by-side
Showing with 90 additions and 156 deletions
storage/innobase/include/log0recv.h
View file @ 9c47beb8
/*****************************************************************************
Copyright (c) 1997, 2010, Innobase Oy. All Rights Reserved.
Copyright (c) 2017, MariaDB Corporation.
This program is free software; you can redistribute it and/or modify it under
the terms of the GNU General Public License as published by the Free Software
......@@ -428,6 +429,8 @@ struct recv_sys_struct{
scan find a corrupt log block, or a corrupt
log record, or there is a log parsing
buffer overflow */
/** the time when progress was last reported */
ib_time_t progress_time;
#ifdef UNIV_LOG_ARCHIVE
log_group_t* archive_group;
/*!< in archive recovery: the log group whose
......
storage/innobase/log/log0log.c
View file @ 9c47beb8
......@@ -2,6 +2,7 @@
Copyright (c) 1995, 2010, Oracle and/or its affiliates. All Rights Reserved.
Copyright (c) 2009, Google Inc.
Copyright (c) 2017, MariaDB Corporation.
Portions of this file contain modifications contributed and copyrighted by
Google, Inc. Those modifications are gratefully acknowledged and are described
......@@ -2303,6 +2304,7 @@ log_group_read_log_seg(
ulint len;
ulint source_offset;
ibool sync;
ib_time_t time;
ut_ad(mutex_own(&(log_sys->mutex)));
......@@ -2335,6 +2337,15 @@ log_group_read_log_seg(
start_lsn += len;
buf += len;
time = ut_time();
if (recv_sys->progress_time - time >= 15) {
recv_sys->progress_time = time;
ut_print_timestamp(stderr);
fprintf(stderr, " InnoDB: Read redo log up to LSN=%llu\n",
start_lsn);
}
if (start_lsn != end_lsn) {
goto loop;
......
storage/innobase/log/log0recv.c
View file @ 9c47beb8
/*****************************************************************************
Copyright (c) 1997, 2016, Oracle and/or its affiliates. All Rights Reserved.
Copyright (c) 2017, MariaDB Corporation.
This program is free software; you can redistribute it and/or modify it under
the terms of the GNU General Public License as published by the Free Software
......@@ -65,7 +66,7 @@ this must be less than UNIV_PAGE_SIZE as it is stored in the buffer pool */
#define RECV_READ_AHEAD_AREA 32
/** The recovery system */
UNIV_INTERN recv_sys_t* recv_sys = NULL;
UNIV_INTERN recv_sys_t* recv_sys;
/** TRUE when applying redo log records during crash recovery; FALSE
otherwise. Note that this is FALSE while a background thread is
rolling back incomplete transactions. */
......@@ -121,9 +122,6 @@ UNIV_INTERN ibool recv_is_making_a_backup = FALSE;
UNIV_INTERN ibool recv_is_from_backup = FALSE;
# define buf_pool_get_curr_size() (5 * 1024 * 1024)
#endif /* !UNIV_HOTBACKUP */
/** The following counter is used to decide when to print info on
log scan */
static ulint recv_scan_print_counter;
/** The type of the previous parsed redo log record */
static ulint recv_previous_parsed_rec_type;
......@@ -275,8 +273,6 @@ recv_sys_var_init(void)
recv_no_ibuf_operations = FALSE;
recv_scan_print_counter = 0;
recv_previous_parsed_rec_type = 999999;
recv_previous_parsed_rec_offset = 0;
......@@ -342,6 +338,7 @@ recv_sys_init(
recv_sys->last_block = ut_align(recv_sys->last_block_buf_start,
OS_FILE_LOG_BLOCK_SIZE);
recv_sys->found_corrupt_log = FALSE;
recv_sys->progress_time = ut_time();
recv_max_page_lsn = 0;
......@@ -1490,6 +1487,7 @@ recv_recover_page_func(
ibool success;
#endif /* !UNIV_HOTBACKUP */
mtr_t mtr;
ib_time_t time;
mutex_enter(&(recv_sys->mutex));
......@@ -1669,6 +1667,8 @@ recv_recover_page_func(
mtr_commit(&mtr);
time = ut_time();
mutex_enter(&(recv_sys->mutex));
if (recv_max_page_lsn < page_lsn) {
......@@ -1677,11 +1677,16 @@ recv_recover_page_func(
recv_addr->state = RECV_PROCESSED;
ut_a(recv_sys->n_addrs);
recv_sys->n_addrs--;
mutex_exit(&(recv_sys->mutex));
ut_a(recv_sys->n_addrs > 0);
if (--recv_sys->n_addrs && recv_sys->progress_time - time >= 15) {
recv_sys->progress_time = time;
ut_print_timestamp(stderr);
fprintf(stderr,
" InnoDB: To recover: " ULINTPF " pages from log\n",
recv_sys->n_addrs);
}
mutex_exit(&recv_sys->mutex);
}
#ifndef UNIV_HOTBACKUP
......@@ -1727,9 +1732,6 @@ recv_read_in_area(
}
buf_read_recv_pages(FALSE, space, zip_size, page_nos, n);
/*
fprintf(stderr, "Recv pages at %lu n %lu\n", page_nos[0], n);
*/
return(n);
}
......@@ -1753,7 +1755,6 @@ recv_apply_hashed_log_recs(
recv_addr_t* recv_addr;
ulint i;
ulint n_pages;
ibool has_printed = FALSE;
mtr_t mtr;
loop:
mutex_enter(&(recv_sys->mutex));
......@@ -1773,6 +1774,16 @@ recv_apply_hashed_log_recs(
recv_no_ibuf_operations = TRUE;
}
if (recv_sys->n_addrs) {
ut_print_timestamp(stderr);
fprintf(stderr,
" InnoDB: %s" ULINTPF " pages from redo log\n",
allow_ibuf
? "Starting final batch to recover "
: "Starting a batch to recover ",
recv_sys->n_addrs);
}
recv_sys->apply_log_recs = TRUE;
recv_sys->apply_batch_on = TRUE;
......@@ -1786,16 +1797,6 @@ recv_apply_hashed_log_recs(
ulint page_no = recv_addr->page_no;
if (recv_addr->state == RECV_NOT_PROCESSED) {
if (!has_printed) {
ut_print_timestamp(stderr);
fputs(" InnoDB: Starting an"
" apply batch of log records"
" to the database...\n"
"InnoDB: Progress in percents: ",
stderr);
has_printed = TRUE;
}
mutex_exit(&(recv_sys->mutex));
if (buf_page_peek(space, page_no)) {
......@@ -1821,16 +1822,6 @@ recv_apply_hashed_log_recs(
recv_addr = HASH_GET_NEXT(addr_hash, recv_addr);
}
if (has_printed
&& (i * 100) / hash_get_n_cells(recv_sys->addr_hash)
!= ((i + 1) * 100)
/ hash_get_n_cells(recv_sys->addr_hash)) {
fprintf(stderr, "%lu ", (ulong)
((i * 100)
/ hash_get_n_cells(recv_sys->addr_hash)));
}
}
/* Wait until all the pages have been processed */
......@@ -1844,11 +1835,6 @@ recv_apply_hashed_log_recs(
mutex_enter(&(recv_sys->mutex));
}
if (has_printed) {
fprintf(stderr, "\n");
}
if (!allow_ibuf) {
/* Flush all the file pages to disk and invalidate them in
the buffer pool */
......@@ -1876,10 +1862,6 @@ recv_apply_hashed_log_recs(
recv_sys_empty_hash();
if (has_printed) {
fprintf(stderr, "InnoDB: Apply batch completed\n");
}
mutex_exit(&(recv_sys->mutex));
}
#else /* !UNIV_HOTBACKUP */
......@@ -1903,10 +1885,6 @@ recv_apply_log_recs_for_backup(void)
block = back_block1;
fputs("InnoDB: Starting an apply batch of log records"
" to the database...\n"
"InnoDB: Progress in percents: ", stderr);
n_hash_cells = hash_get_n_cells(recv_sys->addr_hash);
for (i = 0; i < n_hash_cells; i++) {
......@@ -2697,10 +2675,10 @@ recv_scan_log_recs(
#ifndef UNIV_HOTBACKUP
if (recv_log_scan_is_startup_type
&& !recv_needed_recovery) {
ut_print_timestamp(stderr);
fprintf(stderr,
"InnoDB: Log scan progressed"
" past the checkpoint lsn %llu\n",
" InnoDB: Starting crash recovery"
" from checkpoint LSN=%llu\n",
recv_sys->scanned_lsn);
recv_init_crash_recovery();
}
......@@ -2751,19 +2729,6 @@ recv_scan_log_recs(
*group_scanned_lsn = scanned_lsn;
if (recv_needed_recovery
|| (recv_is_from_backup && !recv_is_making_a_backup)) {
recv_scan_print_counter++;
if (finished || (recv_scan_print_counter % 80 == 0)) {
fprintf(stderr,
"InnoDB: Doing recovery: scanned up to"
" log sequence number %llu\n",
*group_scanned_lsn);
}
}
if (more_data && !recv_sys->found_corrupt_log) {
/* Try to parse more log records */
......@@ -2854,17 +2819,6 @@ recv_init_crash_recovery(void)
recv_needed_recovery = TRUE;
ut_print_timestamp(stderr);
fprintf(stderr,
" InnoDB: Database was not"
" shut down normally!\n"
"InnoDB: Starting crash recovery.\n");
fprintf(stderr,
"InnoDB: Reading tablespace information"
" from the .ibd files...\n");
fil_load_single_table_tablespaces();
/* If we are using the doublewrite method, we will
......@@ -2877,8 +2831,7 @@ recv_init_crash_recovery(void)
fprintf(stderr,
"InnoDB: Restoring possible"
" half-written data pages from"
" the doublewrite\n"
"InnoDB: buffer...\n");
" the doublewrite buffer...\n");
trx_sys_doublewrite_init_or_restore_pages(TRUE);
}
}
......
storage/xtradb/include/log0recv.h
View file @ 9c47beb8
/*****************************************************************************
Copyright (c) 1997, 2010, Innobase Oy. All Rights Reserved.
Copyright (c) 2017, MariaDB Corporation.
This program is free software; you can redistribute it and/or modify it under
the terms of the GNU General Public License as published by the Free Software
......@@ -465,6 +466,8 @@ struct recv_sys_struct{
scan find a corrupt log block, or a corrupt
log record, or there is a log parsing
buffer overflow */
/** the time when progress was last reported */
ib_time_t progress_time;
#ifdef UNIV_LOG_ARCHIVE
log_group_t* archive_group;
/*!< in archive recovery: the log group whose
......
storage/xtradb/log/log0log.c
View file @ 9c47beb8
......@@ -2,6 +2,7 @@
Copyright (c) 1995, 2010, Oracle and/or its affiliates. All Rights Reserved.
Copyright (c) 2009, Google Inc.
Copyright (c) 2017, MariaDB Corporation.
Portions of this file contain modifications contributed and copyrighted by
Google, Inc. Those modifications are gratefully acknowledged and are described
......@@ -2502,6 +2503,7 @@ log_group_read_log_seg(
ulint len;
ulint source_offset;
ibool sync;
ib_time_t time;
ut_ad(mutex_own(&(log_sys->mutex)));
......@@ -2538,6 +2540,15 @@ log_group_read_log_seg(
start_lsn += len;
buf += len;
time = ut_time();
if (recv_sys->progress_time - time >= 15) {
recv_sys->progress_time = time;
ut_print_timestamp(stderr);
fprintf(stderr, " InnoDB: Read redo log up to LSN=%llu\n",
start_lsn);
}
if (start_lsn != end_lsn) {
if (release_mutex) {
......
storage/xtradb/log/log0recv.c
View file @ 9c47beb8
/*****************************************************************************
Copyright (c) 1997, 2016, Oracle and/or its affiliates. All Rights Reserved.
Copyright (c) 2017, MariaDB Corporation.
This program is free software; you can redistribute it and/or modify it under
the terms of the GNU General Public License as published by the Free Software
......@@ -72,7 +73,7 @@ this must be less than UNIV_PAGE_SIZE as it is stored in the buffer pool */
#define RECV_READ_AHEAD_AREA 32
/** The recovery system */
UNIV_INTERN recv_sys_t* recv_sys = NULL;
UNIV_INTERN recv_sys_t* recv_sys;
/** TRUE when applying redo log records during crash recovery; FALSE
otherwise. Note that this is FALSE while a background thread is
rolling back incomplete transactions. */
......@@ -128,9 +129,6 @@ UNIV_INTERN ibool recv_is_making_a_backup = FALSE;
UNIV_INTERN ibool recv_is_from_backup = FALSE;
# define buf_pool_get_curr_size() (5 * 1024 * 1024)
#endif /* !UNIV_HOTBACKUP */
/** The following counter is used to decide when to print info on
log scan */
static ulint recv_scan_print_counter;
/** The type of the previous parsed redo log record */
static ulint recv_previous_parsed_rec_type;
......@@ -285,8 +283,6 @@ recv_sys_var_init(void)
recv_no_ibuf_operations = FALSE;
recv_scan_print_counter = 0;
recv_previous_parsed_rec_type = 999999;
recv_previous_parsed_rec_offset = 0;
......@@ -357,6 +353,7 @@ recv_sys_init(
recv_sys->last_block = ut_align(recv_sys->last_block_buf_start,
OS_FILE_LOG_BLOCK_SIZE);
recv_sys->found_corrupt_log = FALSE;
recv_sys->progress_time = ut_time();
recv_max_page_lsn = 0;
......@@ -1557,6 +1554,7 @@ recv_recover_page_func(
ibool success;
#endif /* !UNIV_HOTBACKUP */
mtr_t mtr;
ib_time_t time;
mutex_enter(&(recv_sys->mutex));
......@@ -1769,6 +1767,8 @@ recv_recover_page_func(
mtr_commit(&mtr);
time = ut_time();
mutex_enter(&(recv_sys->mutex));
if (recv_max_page_lsn < page_lsn) {
......@@ -1777,11 +1777,16 @@ recv_recover_page_func(
recv_addr->state = RECV_PROCESSED;
ut_a(recv_sys->n_addrs);
recv_sys->n_addrs--;
mutex_exit(&(recv_sys->mutex));
ut_a(recv_sys->n_addrs > 0);
if (--recv_sys->n_addrs && recv_sys->progress_time - time >= 15) {
recv_sys->progress_time = time;
ut_print_timestamp(stderr);
fprintf(stderr,
" InnoDB: To recover: " ULINTPF " pages from log\n",
recv_sys->n_addrs);
}
mutex_exit(&recv_sys->mutex);
}
#ifndef UNIV_HOTBACKUP
......@@ -1834,9 +1839,6 @@ recv_read_in_area(
}
buf_read_recv_pages(FALSE, space, zip_size, page_nos, n);
/*
fprintf(stderr, "Recv pages at %lu n %lu\n", page_nos[0], n);
*/
return(n);
}
......@@ -1860,7 +1862,6 @@ recv_apply_hashed_log_recs(
recv_addr_t* recv_addr;
ulint i;
ulint n_pages;
ibool has_printed = FALSE;
mtr_t mtr;
loop:
mutex_enter(&(recv_sys->mutex));
......@@ -1880,6 +1881,20 @@ recv_apply_hashed_log_recs(
recv_no_ibuf_operations = TRUE;
}
if (recv_sys->n_addrs) {
ut_print_timestamp(stderr);
fprintf(stderr,
" InnoDB: %s" ULINTPF " pages from redo log\n",
allow_ibuf
? "Starting final batch to recover "
: "Starting a batch to recover ",
recv_sys->n_addrs);
if (srv_recovery_stats) {
recv_sys->stats_recv_turns++;
}
}
recv_sys->apply_log_recs = TRUE;
recv_sys->apply_batch_on = TRUE;
......@@ -1893,16 +1908,6 @@ recv_apply_hashed_log_recs(
ulint page_no = recv_addr->page_no;
if (recv_addr->state == RECV_NOT_PROCESSED) {
if (!has_printed) {
ut_print_timestamp(stderr);
fputs(" InnoDB: Starting an"
" apply batch of log records"
" to the database...\n"
"InnoDB: Progress in percents: ",
stderr);
has_printed = TRUE;
}
mutex_exit(&(recv_sys->mutex));
if (buf_page_peek(space, page_no)) {
......@@ -1928,16 +1933,6 @@ recv_apply_hashed_log_recs(
recv_addr = HASH_GET_NEXT(addr_hash, recv_addr);
}
if (has_printed
&& (i * 100) / hash_get_n_cells(recv_sys->addr_hash)
!= ((i + 1) * 100)
/ hash_get_n_cells(recv_sys->addr_hash)) {
fprintf(stderr, "%lu ", (ulong)
((i * 100)
/ hash_get_n_cells(recv_sys->addr_hash)));
}
}
/* Wait until all the pages have been processed */
......@@ -1951,11 +1946,6 @@ recv_apply_hashed_log_recs(
mutex_enter(&(recv_sys->mutex));
}
if (has_printed) {
fprintf(stderr, "\n");
}
if (!allow_ibuf) {
/* Flush all the file pages to disk and invalidate them in
the buffer pool */
......@@ -1983,14 +1973,6 @@ recv_apply_hashed_log_recs(
recv_sys_empty_hash();
if (has_printed) {
fprintf(stderr, "InnoDB: Apply batch completed\n");
if (srv_recovery_stats) {
recv_sys->stats_recv_turns++;
}
}
mutex_exit(&(recv_sys->mutex));
}
#else /* !UNIV_HOTBACKUP */
......@@ -2014,10 +1996,6 @@ recv_apply_log_recs_for_backup(void)
block = back_block1;
fputs("InnoDB: Starting an apply batch of log records"
" to the database...\n"
"InnoDB: Progress in percents: ", stderr);
n_hash_cells = hash_get_n_cells(recv_sys->addr_hash);
for (i = 0; i < n_hash_cells; i++) {
......@@ -2808,10 +2786,10 @@ recv_scan_log_recs(
#ifndef UNIV_HOTBACKUP
if (recv_log_scan_is_startup_type
&& !recv_needed_recovery) {
ut_print_timestamp(stderr);
fprintf(stderr,
"InnoDB: Log scan progressed"
" past the checkpoint lsn %llu\n",
" InnoDB: Starting crash recovery"
" from checkpoint LSN=%llu\n",
recv_sys->scanned_lsn);
recv_init_crash_recovery();
}
......@@ -2862,19 +2840,6 @@ recv_scan_log_recs(
*group_scanned_lsn = scanned_lsn;
if (recv_needed_recovery
|| (recv_is_from_backup && !recv_is_making_a_backup)) {
recv_scan_print_counter++;
if (finished || (recv_scan_print_counter % 80 == 0)) {
fprintf(stderr,
"InnoDB: Doing recovery: scanned up to"
" log sequence number %llu\n",
*group_scanned_lsn);
}
}
if (more_data && !recv_sys->found_corrupt_log) {
/* Try to parse more log records */
......@@ -2965,17 +2930,6 @@ recv_init_crash_recovery(void)
recv_needed_recovery = TRUE;
ut_print_timestamp(stderr);
fprintf(stderr,
" InnoDB: Database was not"
" shut down normally!\n"
"InnoDB: Starting crash recovery.\n");
fprintf(stderr,
"InnoDB: Reading tablespace information"
" from the .ibd files...\n");
fil_load_single_table_tablespaces();
/* If we are using the doublewrite method, we will
......@@ -2988,8 +2942,7 @@ recv_init_crash_recovery(void)
fprintf(stderr,
"InnoDB: Restoring possible"
" half-written data pages from"
" the doublewrite\n"
"InnoDB: buffer...\n");
" the doublewrite buffer...\n");
trx_sys_doublewrite_init_or_restore_pages(TRUE);
}
}
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment
GitLab Nexedi Edition | About GitLab | About Nexedi | 沪ICP备2021021310号-2 | 沪ICP备2021021310号-7