Skip to content

Commit

Permalink
MDEV-11623 MariaDB 10.1 fails to start datadir created with
Browse files Browse the repository at this point in the history
MariaDB 10.0/MySQL 5.6 using innodb-page-size!=16K

The storage format of FSP_SPACE_FLAGS was accidentally broken
already in MariaDB 10.1.0. This fix is bringing the format in
line with other MySQL and MariaDB release series.

Please refer to the comments that were added to fsp0fsp.h
for details.

This is an INCOMPATIBLE CHANGE that affects users of
page_compression and non-default innodb_page_size. Upgrading
to this release will correct the flags in the data files.
If you want to downgrade to earlier MariaDB 10.1.x, please refer
to the test innodb.101_compatibility how to reset the
FSP_SPACE_FLAGS in the files.

NOTE: MariaDB 10.1.0 to 10.1.20 can misinterpret
uncompressed data files with innodb_page_size=4k or 64k as
compressed innodb_page_size=16k files, and then probably fail
when trying to access the pages. See the comments in the
function fsp_flags_convert_from_101() for detailed analysis.

Move PAGE_COMPRESSION to FSP_SPACE_FLAGS bit position 16.
In this way, compressed innodb_page_size=16k tablespaces will not
be mistaken for uncompressed ones by MariaDB 10.1.0 to 10.1.20.

Derive PAGE_COMPRESSION_LEVEL, ATOMIC_WRITES and DATA_DIR from the
dict_table_t::flags when the table is available, in
fil_space_for_table_exists_in_mem() or fil_open_single_table_tablespace().
During crash recovery, fil_load_single_table_tablespace() will use
innodb_compression_level for the PAGE_COMPRESSION_LEVEL.

FSP_FLAGS_MEM_MASK: A bitmap of the memory-only fil_space_t::flags
that are not to be written to FSP_SPACE_FLAGS. Currently, these will
include PAGE_COMPRESSION_LEVEL, ATOMIC_WRITES and DATA_DIR.

Introduce the macro FSP_FLAGS_PAGE_SSIZE(). We only support
one innodb_page_size for the whole instance.

When creating a dummy tablespace for the redo log, use
fil_space_t::flags=0. The flags are never written to the redo log files.

Remove many FSP_FLAGS_SET_ macros.

dict_tf_verify_flags(): Remove. This is basically only duplicating
the logic of dict_tf_to_fsp_flags(), used in a debug assertion.

fil_space_t::mark: Remove. This flag was not used for anything.

fil_space_for_table_exists_in_mem(): Remove the unnecessary parameter
mark_space, and add a parameter for table flags. Check that
fil_space_t::flags match the table flags, and adjust the (memory-only)
flags based on the table flags.

fil_node_open_file(): Remove some redundant or unreachable conditions,
do not use stderr for output, and avoid unnecessary server aborts.

fil_user_tablespace_restore_page(): Convert the flags, so that the
correct page_size will be used when restoring a page from the
doublewrite buffer.

fil_space_get_page_compressed(), fsp_flags_is_page_compressed(): Remove.
It suffices to have fil_space_is_page_compressed().

FSP_FLAGS_WIDTH_DATA_DIR, FSP_FLAGS_WIDTH_PAGE_COMPRESSION_LEVEL,
FSP_FLAGS_WIDTH_ATOMIC_WRITES: Remove, because these flags do not
exist in the FSP_SPACE_FLAGS but only in memory.

fsp_flags_try_adjust(): New function, to adjust the FSP_SPACE_FLAGS
in page 0. Called by fil_open_single_table_tablespace(),
fil_space_for_table_exists_in_mem(), innobase_start_or_create_for_mysql()
except if --innodb-read-only is active.

fsp_flags_is_valid(ulint): Reimplement from the scratch, with
accurate comments. Do not display any details of detected
inconsistencies, because the output could be confusing when
dealing with MariaDB 10.1.x data files.

fsp_flags_convert_from_101(ulint): Convert flags from buggy
MariaDB 10.1.x format, or return ULINT_UNDEFINED if the flags
cannot be in MariaDB 10.1.x format.

fsp_flags_match(): Check the flags when probing files.
Implemented based on fsp_flags_is_valid()
and fsp_flags_convert_from_101().

dict_check_tablespaces_and_store_max_id(): Do not access the
page after committing the mini-transaction.

IMPORT TABLESPACE fixes:

AbstractCallback::init(): Convert the flags.

FetchIndexRootPages::operator(): Check that the tablespace flags match the
table flags. Do not attempt to convert tablespace flags to table flags,
because the conversion would necessarily be lossy.

PageConverter::update_header(): Write back the correct flags.
This takes care of the flags in IMPORT TABLESPACE.
  • Loading branch information
dr-m committed Jan 15, 2017
1 parent a9d00db commit ab1e6fe
Show file tree
Hide file tree
Showing 39 changed files with 1,483 additions and 1,497 deletions.
25 changes: 25 additions & 0 deletions mysql-test/suite/innodb/include/ibd_convert.pl
@@ -0,0 +1,25 @@
#!/usr/bin/perl
# Convert tablespace flags to the format understood by MariaDB 10.1.0..10.1.20,
# with the assumption that the flags were correct.

sub convert_to_mariadb_101
{
my ($file, $page_size) = @_;
open(FILE, "+<", $file) or die "Unable to open $file\n";
sysread(FILE, $_, $page_size)==$page_size||die "Unable to read $file\n";
sysseek(FILE, 0, 0)||die "Unable to seek $file\n";

# FIL_PAGE_DATA + FSP_SPACE_FLAGS = 38 + 16 = 54 bytes from the start
my($flags) = unpack "x[54]N";
my $badflags = ($flags & 0x3f);
my $compression_level=6;
$badflags |= 1<<6|$compression_level<<7 if ($flags & 1 << 16);
$badflags |= ($flags & 15 << 6) << 7; # PAGE_SSIZE

substr ($_, 54, 4) = pack("N", $badflags);
# Replace the innodb_checksum_algorithm=none checksum
substr ($_, 0, 4) = pack("N", 0xdeadbeef);
substr ($_, $page_size - 8, 4) = pack("N", 0xdeadbeef);
syswrite(FILE, $_, $page_size)==$page_size||die "Unable to write $file\n";
close(FILE);
}
48 changes: 48 additions & 0 deletions mysql-test/suite/innodb/r/101_compatibility.result
@@ -0,0 +1,48 @@
#
# MDEV-11623 MariaDB 10.1 fails to start datadir created with
# MariaDB 10.0/MySQL 5.6 using innodb-page-size!=16K
#
call mtr.add_suppression("InnoDB: adjusting FSP_SPACE_FLAGS of tablespace");
SET GLOBAL innodb_file_per_table=1;
SET GLOBAL innodb_file_format=Barracuda;
CREATE TABLE tr(a INT)ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
CREATE TABLE tc(a INT)ENGINE=InnoDB ROW_FORMAT=COMPACT;
CREATE TABLE td(a INT)ENGINE=InnoDB ROW_FORMAT=DYNAMIC;
CREATE TABLE tz(a INT)ENGINE=InnoDB ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=1;
CREATE TABLE tdd(a INT) ENGINE=InnoDB, DATA DIRECTORY='MYSQL_TMP_DIR';
CREATE TABLE tp(a INT) ENGINE=InnoDB page_compressed=1;
CREATE TABLE ti(a INT) ENGINE=InnoDB;
FLUSH TABLES ti FOR EXPORT;
backup: ti
UNLOCK TABLES;
ALTER TABLE ti DISCARD TABLESPACE;
restore: ti .ibd and .cfg files
ALTER TABLE ti IMPORT TABLESPACE;
BEGIN;
INSERT INTO tr VALUES(1);
INSERT INTO tc VALUES(1);
INSERT INTO td VALUES(1);
INSERT INTO tz VALUES(1);
INSERT INTO tdd VALUES(1);
INSERT INTO tp VALUES(1);
INSERT INTO ti VALUES(1);
# Kill the server
CHECK TABLE tr,tc,td,tz,tdd,tp,ti;
Table Op Msg_type Msg_text
test.tr check status OK
test.tc check status OK
test.td check status OK
test.tz check status OK
test.tdd check status OK
test.tp check status OK
test.ti check status OK
CHECK TABLE tr,tc,td,tz,tdd,tp,ti;
Table Op Msg_type Msg_text
test.tr check status OK
test.tc check status OK
test.td check status OK
test.tz check status OK
test.tdd check status OK
test.tp check status OK
test.ti check status OK
DROP TABLE tr,tc,td,tz,tdd,tp,ti;
2 changes: 2 additions & 0 deletions mysql-test/suite/innodb/r/doublewrite.result
Expand Up @@ -39,6 +39,8 @@ set global innodb_buf_flush_list_now = 1;
# Kill the server
# Make the first page (page_no=0) of the user tablespace
# full of zeroes.
#
# MDEV-11623: Use old FSP_SPACE_FLAGS in the doublewrite buffer.
check table t1;
Table Op Msg_type Msg_text
test.t1 check status OK
Expand Down
5 changes: 3 additions & 2 deletions mysql-test/suite/innodb/r/innodb-wl5522-debug-zip.result
@@ -1,4 +1,5 @@
call mtr.add_suppression("InnoDB: Page for tablespace .* ");
call mtr.add_suppression("InnoDB: Page for tablespace ");
call mtr.add_suppression("InnoDB: Invalid FSP_SPACE_FLAGS=0x");
FLUSH TABLES;
SET GLOBAL innodb_file_per_table = 1;
SELECT @@innodb_file_per_table;
Expand Down Expand Up @@ -565,7 +566,7 @@ ERROR HY000: Tablespace has been discarded for table 't1'
restore: t1 .ibd and .cfg files
SET SESSION debug_dbug="+d,fsp_flags_is_valid_failure";
ALTER TABLE test_wl5522.t1 IMPORT TABLESPACE;
ERROR HY000: Internal error: Cannot reset LSNs in table '"test_wl5522"."t1"' : Unsupported
ERROR HY000: Internal error: Cannot reset LSNs in table '"test_wl5522"."t1"' : Data structure corruption
SET SESSION debug_dbug="-d,fsp_flags_is_valid_failure";
DROP TABLE test_wl5522.t1;
unlink: t1.ibd
Expand Down
101 changes: 101 additions & 0 deletions mysql-test/suite/innodb/t/101_compatibility.test
@@ -0,0 +1,101 @@
--source include/have_innodb.inc
--source include/not_embedded.inc

-- echo #
-- echo # MDEV-11623 MariaDB 10.1 fails to start datadir created with
-- echo # MariaDB 10.0/MySQL 5.6 using innodb-page-size!=16K
-- echo #

# This is actually testing the opposite: starting the fixed 10.1 with
# buggy 10.1 files (by manually converting the flags in the files).

call mtr.add_suppression("InnoDB: adjusting FSP_SPACE_FLAGS of tablespace");
SET GLOBAL innodb_file_per_table=1;
SET GLOBAL innodb_file_format=Barracuda;
let INNODB_PAGE_SIZE=`select @@innodb_page_size`;
let MYSQLD_DATADIR=`select @@datadir`;

CREATE TABLE tr(a INT)ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
CREATE TABLE tc(a INT)ENGINE=InnoDB ROW_FORMAT=COMPACT;
CREATE TABLE td(a INT)ENGINE=InnoDB ROW_FORMAT=DYNAMIC;
--disable_warnings
CREATE TABLE tz(a INT)ENGINE=InnoDB ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=1;
--enable_warnings

--replace_result $MYSQL_TMP_DIR MYSQL_TMP_DIR
EVAL CREATE TABLE tdd(a INT) ENGINE=InnoDB, DATA DIRECTORY='$MYSQL_TMP_DIR';

CREATE TABLE tp(a INT) ENGINE=InnoDB page_compressed=1;
CREATE TABLE ti(a INT) ENGINE=InnoDB;
FLUSH TABLES ti FOR EXPORT;
perl;
do "$ENV{MTR_SUITE_DIR}/include/innodb-util.pl";
ib_backup_tablespaces("test", "ti");
EOF
UNLOCK TABLES;
ALTER TABLE ti DISCARD TABLESPACE;
perl;
do "$ENV{MTR_SUITE_DIR}/include/innodb-util.pl";
ib_discard_tablespaces("test", "ti");
ib_restore_tablespaces("test", "ti");
do "$ENV{MTR_SUITE_DIR}/include/ibd_convert.pl";
my $ps = $ENV{INNODB_PAGE_SIZE};
my $dd = $ENV{MYSQLD_DATADIR};
convert_to_mariadb_101("$dd/test/ti.ibd", $ps);
EOF

ALTER TABLE ti IMPORT TABLESPACE;

BEGIN;
INSERT INTO tr VALUES(1);
INSERT INTO tc VALUES(1);
INSERT INTO td VALUES(1);
INSERT INTO tz VALUES(1);
INSERT INTO tdd VALUES(1);
INSERT INTO tp VALUES(1);
INSERT INTO ti VALUES(1);

--source include/kill_mysqld.inc

perl;
do "$ENV{MTR_SUITE_DIR}/include/ibd_convert.pl";
my $ps = $ENV{INNODB_PAGE_SIZE};
my $dd = $ENV{MYSQLD_DATADIR};

convert_to_mariadb_101("$dd/ibdata1", $ps);
convert_to_mariadb_101("$dd/test/tr.ibd", $ps);
convert_to_mariadb_101("$dd/test/tc.ibd", $ps);
convert_to_mariadb_101("$dd/test/td.ibd", $ps);
convert_to_mariadb_101("$dd/test/tz.ibd", 1024) if $ps<32768;
convert_to_mariadb_101("$dd/test/tp.ibd", $ps);
convert_to_mariadb_101("$dd/test/ti.ibd", $ps);
convert_to_mariadb_101("$ENV{MYSQL_TMP_DIR}/test/tdd.ibd", $ps);
EOF

--source include/start_mysqld.inc
CHECK TABLE tr,tc,td,tz,tdd,tp,ti;
--source include/shutdown_mysqld.inc

perl;
do "$ENV{MTR_SUITE_DIR}/include/ibd_convert.pl";
my $ps = $ENV{INNODB_PAGE_SIZE};
my $dd = $ENV{MYSQLD_DATADIR};

convert_to_mariadb_101("$dd/ibdata1", $ps);
convert_to_mariadb_101("$dd/test/tr.ibd", $ps);
convert_to_mariadb_101("$dd/test/tc.ibd", $ps);
convert_to_mariadb_101("$dd/test/td.ibd", $ps);
convert_to_mariadb_101("$dd/test/tz.ibd", 1024) if $ps<32768;
convert_to_mariadb_101("$dd/test/tp.ibd", $ps);
convert_to_mariadb_101("$dd/test/ti.ibd", $ps);
convert_to_mariadb_101("$ENV{MYSQL_TMP_DIR}/test/tdd.ibd", $ps);
EOF

--let $restart_parameters=--innodb-read-only
--source include/start_mysqld.inc
CHECK TABLE tr,tc,td,tz,tdd,tp,ti;
--source include/shutdown_mysqld.inc

--let $restart_parameters=
--source include/start_mysqld.inc
DROP TABLE tr,tc,td,tz,tdd,tp,ti;
42 changes: 38 additions & 4 deletions mysql-test/suite/innodb/t/doublewrite.test
Expand Up @@ -17,7 +17,7 @@ call mtr.add_suppression("space header page consists of zero bytes.*test.t1");
call mtr.add_suppression("checksum mismatch in tablespace.*test.t1");
call mtr.add_suppression("Current page size .* != page size on page");
call mtr.add_suppression("innodb-page-size mismatch in tablespace.*test.t1");
call mtr.add_suppression("Database page corruption");
call mtr.add_suppression("Trying to recover page.*from the doublewrite buffer");
--enable_query_log

let INNODB_PAGE_SIZE=`select @@innodb_page_size`;
Expand Down Expand Up @@ -65,14 +65,48 @@ set global innodb_buf_flush_list_now = 1;

--echo # Make the first page (page_no=0) of the user tablespace
--echo # full of zeroes.
--echo #
--echo # MDEV-11623: Use old FSP_SPACE_FLAGS in the doublewrite buffer.

perl;
use IO::Handle;
my $fname= "$ENV{'MYSQLD_DATADIR'}test/t1.ibd";
my $page_size = $ENV{INNODB_PAGE_SIZE};
my $page;
open(FILE, "+<", $fname) or die;
FILE->autoflush(1);
binmode FILE;
print FILE chr(0) x ($ENV{'INNODB_PAGE_SIZE'});
sysread(FILE, $page, $page_size)==$page_size||die "Unable to read $file\n";
sysseek(FILE, 0, 0)||die "Unable to seek $file\n";
die unless syswrite(FILE, chr(0) x $page_size, $page_size) == $page_size;
close FILE;

open(FILE, "+<", "$ENV{MYSQLD_DATADIR}ibdata1")||die "cannot open ibdata1\n";
sysseek(FILE, 6 * $page_size - 190, 0)||die "Unable to seek ibdata1\n";
sysread(FILE, $_, 12) == 12||die "Unable to read TRX_SYS\n";
my($magic,$d1,$d2)=unpack "NNN";
die "magic=$magic, $d1, $d2\n" unless $magic == 536853855 && $d2 >= $d1 + 64;
sysseek(FILE, $d1 * $page_size, 0)||die "Unable to seek ibdata1\n";
# Find the page in the doublewrite buffer
for (my $d = $d1; $d < $d2 + 64; $d++)
{
sysread(FILE, $_, $page_size)==$page_size||die "Cannot read doublewrite\n";
next unless $_ eq $page;
sysseek(FILE, $d * $page_size, 0)||die "Unable to seek ibdata1\n";
# Write buggy MariaDB 10.1.x FSP_SPACE_FLAGS to the doublewrite buffer
my($flags) = unpack "x[54]N";
my $badflags = ($flags & 0x3f);
my $compression_level=6;
$badflags |= 1<<6|$compression_level<<7 if ($flags & 1 << 16);
$badflags |= ($flags & 15 << 6) << 7; # PAGE_SSIZE

substr ($_, 54, 4) = pack("N", $badflags);
# Replace the innodb_checksum_algorithm=none checksum
substr ($_, 0, 4) = pack("N", 0xdeadbeef);
substr ($_, $page_size - 8, 4) = pack("N", 0xdeadbeef);
syswrite(FILE, $_, $page_size)==$page_size||die "Unable to write $file\n";
close(FILE);
exit 0;
}
die "Did not find the page in the doublewrite buffer ($d1,$d2)\n";
EOF

--source include/start_mysqld.inc
Expand Down
3 changes: 2 additions & 1 deletion mysql-test/suite/innodb/t/innodb-wl5522-debug-zip.test
Expand Up @@ -17,7 +17,8 @@
# allow test to run only when innodb-page-size=16
--source include/have_innodb_16k.inc

call mtr.add_suppression("InnoDB: Page for tablespace .* ");
call mtr.add_suppression("InnoDB: Page for tablespace ");
call mtr.add_suppression("InnoDB: Invalid FSP_SPACE_FLAGS=0x");
FLUSH TABLES;

let MYSQLD_DATADIR =`SELECT @@datadir`;
Expand Down
15 changes: 15 additions & 0 deletions storage/innobase/buf/buf0dblwr.cc
Expand Up @@ -589,6 +589,21 @@ buf_dblwr_process()
continue;
}

if (page_no == 0) {
/* Check the FSP_SPACE_FLAGS. */
ulint flags = fsp_header_get_flags(page);
if (!fsp_flags_is_valid(flags)
&& fsp_flags_convert_from_101(flags)
== ULINT_UNDEFINED) {
ib_logf(IB_LOG_LEVEL_WARN,
"Ignoring a doublewrite copy of page "
ULINTPF ":0 due to invalid flags 0x%x",
space_id, int(flags));
continue;
}
/* The flags on the page should be converted later. */
}

/* Write the good page from the doublewrite buffer to
the intended position. */

Expand Down
20 changes: 10 additions & 10 deletions storage/innobase/dict/dict0load.cc
Expand Up @@ -1052,8 +1052,6 @@ dict_check_tablespaces_and_store_max_id(

btr_pcur_store_position(&pcur, &mtr);

mtr_commit(&mtr);

/* For tables created with old versions of InnoDB,
SYS_TABLES.MIX_LEN may contain garbage. Such tables
would always be in ROW_FORMAT=REDUNDANT. Pretend that
Expand Down Expand Up @@ -1087,16 +1085,19 @@ dict_check_tablespaces_and_store_max_id(
if (space_id == 0) {
/* The system tablespace always exists. */
ut_ad(!discarded);
goto next_tablespace;
mem_free(name);
goto loop;
}

mtr_commit(&mtr);

switch (dict_check) {
case DICT_CHECK_ALL_LOADED:
/* All tablespaces should have been found in
fil_load_single_table_tablespaces(). */
if (fil_space_for_table_exists_in_mem(
space_id, name, TRUE, !(is_temp || discarded),
false, NULL, 0)
space_id, name, !(is_temp || discarded),
false, NULL, 0, flags)
&& !(is_temp || discarded)) {
/* If user changes the path of .ibd files in
*.isl files before doing crash recovery ,
Expand Down Expand Up @@ -1128,8 +1129,8 @@ dict_check_tablespaces_and_store_max_id(
/* Some tablespaces may have been opened in
trx_resurrect_table_locks(). */
if (fil_space_for_table_exists_in_mem(
space_id, name, FALSE, FALSE,
false, NULL, 0)) {
space_id, name, false,
false, NULL, 0, flags)) {
break;
}
/* fall through */
Expand Down Expand Up @@ -1191,7 +1192,6 @@ dict_check_tablespaces_and_store_max_id(
max_space_id = space_id;
}

next_tablespace:
mem_free(name);
mtr_start(&mtr);

Expand Down Expand Up @@ -2382,8 +2382,8 @@ dict_load_table(
table->ibd_file_missing = TRUE;

} else if (!fil_space_for_table_exists_in_mem(
table->space, name, FALSE, FALSE, true, heap,
table->id)) {
table->space, name, false, true, heap,
table->id, table->flags)) {

if (DICT_TF2_FLAG_IS_SET(table, DICT_TF2_TEMPORARY)) {
/* Do not bother to retry opening temporary tables. */
Expand Down

15 comments on commit ab1e6fe

@elr0berto
Copy link

@elr0berto elr0berto commented on ab1e6fe Jan 30, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am currently upgrading our server to 10.1.21 and the upgrade seems to be stuck ... It's been doing something for almost 15 minutes now. High disk load (reading and writing) but low cpu usage.
No indication of what is going on in log files...

It looks like ib_logfile0 ib_logfile1 and ibdata1 are being written to. Is this related to this bug/issue,, is mariadb upgrading my database? How long will it take? It's a huge database.
Is there any progress indication somewhere?

root@gimli /h/m/data# ps aux | grep mysql
root 11056 0.0 0.0 21732 4584 pts/11 Ss+ 13:22 0:00 /usr/bin/dpkg --status-fd 62 --configure libssl1.0.0:amd64 libmariadbclient18:amd64 libmysqlclient18:amd64 mariadb-client-core-10.1:amd64 mariadb-client-10.1:amd64 mariadb-server-core-10.1:amd64 mariadb-server-10.1:amd64 mariadb-server:all libdbus-1-3:amd64 dbus:amd64 libpam-systemd:amd64 libnettle4:amd64 libhogweed2:amd64 libgnutls-deb0-28:amd64 libgnutls-openssl27:amd64 libmagic1:amd64 file:amd64 libpng12-0:amd64 libcairo2:amd64 libisc-export95:amd64 libdns-export100:amd64 libisccfg-export90:amd64 libirs-export91:amd64 liblcms2-2:amd64 libtiff5:amd64 libxpm4:amd64 linux-image-3.16.0-4-amd64:amd64 libsystemd-daemon0:amd64 libsystemd-journal0:amd64 libsystemd-login0:amd64 libssl1.0.2:amd64 libisc95:amd64 libdns100:amd64 libisccc90:amd64 libisccfg90:amd64 libbind9-90:amd64 liblwres90:amd64 bind9-host:amd64 host:all dnsutils:amd64 exim4-config:all exim4-base:amd64 exim4-daemon-light:amd64 exim4:all locales:all w3m:amd64 openssl:amd64 ca-certificates:all dbus-x11:amd64 mdadm:amd64
root 20992 0.0 0.0 16436 3224 pts/11 S+ 13:24 0:00 /bin/bash /usr/bin/mysql_install_db --rpm --user=mysql --disable-log-bin
root 20993 0.0 0.0 26728 2400 pts/11 S+ 13:24 0:00 logger -p daemon.err -t mysqld_safe -i
root 21018 0.0 0.0 16436 1912 pts/11 S+ 13:24 0:00 /bin/bash /usr/bin/mysql_install_db --rpm --user=mysql --disable-log-bin
mysql 21021 4.1 5.2 31427516 3409148 pts/11 Dl+ 13:24 0:48 /usr/sbin/mysqld --lc-messages-dir=/usr/share/mysql/english/.. --bootstrap --basedir=/usr --datadir=/home/mariadb/data --log-warnings=0 --enforce-storage-engine= --disable-log-bin --user=mysql --max_allowed_packet=8M --net_buffer_length=16K
root 22023 0.0 0.0 15740 2260 pts/10 S+ 13:43 0:00 grep --color=auto mysql

2017-01-30 13:24:14 140510328833984 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2017-01-30 13:24:14 140510328833984 [Note] InnoDB: The InnoDB memory heap is disabled
2017-01-30 13:24:14 140510328833984 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-01-30 13:24:14 140510328833984 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-01-30 13:24:14 140510328833984 [Note] InnoDB: Compressed tables use zlib 1.2.8
2017-01-30 13:24:14 140510328833984 [Note] InnoDB: Using Linux native AIO
2017-01-30 13:24:14 140510328833984 [Note] InnoDB: Using SSE crc32 instructions
2017-01-30 13:24:14 140510328833984 [Note] InnoDB: Initializing buffer pool, size = 27.0G
2017-01-30 13:24:14 140510328833984 [Note] InnoDB: Completed initialization of buffer pool
2017-01-30 13:24:15 140510328833984 [Note] InnoDB: Highest supported file format is Barracuda.
2017-01-30 13:24:19 140510328833984 [Note] InnoDB: 128 rollback segment(s) are active.
2017-01-30 13:24:19 140510328833984 [Note] InnoDB: Waiting for purge to start
2017-01-30 13:24:19 140510328833984 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 6431834418526

it's now 13:44 .. 20 minutes without any output to log. db is unresponsive to normal client connections.
dpkg is waiting for something to finish

@janlindstrom
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is your database server reachable for example can you do SHOW ENGINE INNODB STATUS ?

@elr0berto
Copy link

@elr0berto elr0berto commented on ab1e6fe Jan 30, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no it's not available, it didn't open the socket nor the port.

The status is the same 45 minutes now.
iotop is showing mysqld reading and writing to disk. ibdata1, ib_logfile1 ib_logfile0 filesystem modified timestamps are continously updated. SO I think it's still working on something :D

root@gimli /h/m/log# mysql -u admin -p
Enter password:
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2 "No such file or directory")
root@gimli /h/m/log# mysql -u admin -p -h 127.0.0.1
Enter password:
ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1' (111 "Connection refused")
root@gimli /h/m/log#

edit i feel guilty for not saying that this server has had issues with really long shutdown times in the past. Now i always run set global innodb_max_dirty_pages_pct = 0; roughly 1 hour before i shut it down..
otherwise it can take 1 hour to shut down..

The data directory is 186GB.. big but not incredibly huge. ... I upgraded another server today with similar size and it went smooth...

@elr0berto
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it seems to modify some tables. When i run ls -latrh in one database at the bottom i see this:

-rw-rw---- 1 mysql mysql 1.6G Jan 30 14:18 offers_filters_values#P#p0.ibd
-rw-rw---- 1 mysql mysql 9.5G Jan 30 14:18 offers_properties.ibd
-rw-rw---- 1 mysql mysql 5.3G Jan 30 14:18 offers.ibd

the time is now 14:18 .. so those table files are being changed. I think i just have to wait and see if it goes on to other tables soon.,...

@janlindstrom
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you have DATA_DIRECTORY, PAGE_COMPRESSED or innodb_page_size != 16K ? If yes, server is doing upgrade for InnoDB tables.

@elr0berto
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i have default innodb_page_size according to docs is 16k

I'm pretty sure that there's no tables with DATA_DIRECTORY (first time i heard about it today)

But there's one table that use mariadb compression page_compressed=1 .. but it's not the table that is being written to on filesystem currently... hmm

how can i check if i am using DATA_DIRECTORY or PAGE_COMPRESSED .. is it possible to set it globally?

@elr0berto
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Still running, 90 minutes downtime with no progress indication

@elr0berto
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

After 2 hours the upgrade seems to have failed with this message:

Setting up mariadb-server-10.1 (10.1.21+maria-1jessie) ...
Job for mariadb.service failed. See 'systemctl status mariadb.service' and 'journalctl -xn' for details.
invoke-rc.d: initscript mysql, action "start" failed.
dpkg: error processing package mariadb-server-10.1 (--configure):
subprocess installed post-installation script returned error exit status 1
dpkg: dependency problems prevent configuration of mariadb-server:
mariadb-server depends on mariadb-server-10.1 (= 10.1.21+maria-1
jessie); however:
Package mariadb-server-10.1 is not configured yet.

dpkg: error processing package mariadb-server (--configure):
dependency problems - leaving unconfigured

@elr0berto
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

actually, the database is fine now. :) Tack som fan för svaren jan.
Sorry for polluting your github :D

@dr-m
Copy link
Contributor Author

@dr-m dr-m commented on ab1e6fe Jan 30, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The only extra I/O caused by this fix would be a write of the first page of each tablespace file. The large number of writes to the system tablespace file (ibdata1) should be explained by something else, but I do not have an idea what that could be. It would have been interesting to run perf top and http://poormansprofiler.org/ during the ‘thrashing’ to see what InnoDB is actually spending its time on and why it was stuck for so long.

@elr0berto
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@dr-m We have issues with slow shutdown times. . even after having set global innodb_max_dirty_pages_pct = 0; on for 1 hour it takes like 15 minutes to shut down... It might be related to what happened today?

@dr-m
Copy link
Contributor Author

@dr-m dr-m commented on ab1e6fe Jan 30, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would be nice if you could get some details for the next slow shutdown.
The only potential relationship between startup and shutdown that I can see is that when there are lots of changes buffered or lots of undo log to purge, and if startup is held back for some other reason (some thread is waiting for something at startup), then the purge and change buffer merge could be going on, causing writes to the system tablespace and the redo log files. Normally purge and change buffer merge should also modify other data files where the affected tables are stored.

@elr0berto
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is from the previous shutdown.
Remember also that I set set global innodb_max_dirty_pages_pct = 0; 1 hour before the shutdown. Otherwise it takes much longer.

2017-01-30 13:03:55 140680038934272 [Note] InnoDB: FTS optimize thread exiting.
2017-01-30 13:03:56 140681388444416 [Note] InnoDB: Starting shutdown...
2017-01-30 13:03:59 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:05:00 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:06:00 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:07:00 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:08:00 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:09:00 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:10:01 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:11:01 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:12:01 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:13:01 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:14:01 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:15:02 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:16:02 140681388444416 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-01-30 13:17:07 140681388444416 [Note] InnoDB: Shutdown completed; log sequence number 6431834418526
2017-01-30 13:17:07 140681388444416 [Note] /usr/sbin/mysqld: Shutdown complete

@elr0berto
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We do have a 30GB buffer pool. So I guess it can be reasonable?

@dr-m
Copy link
Contributor Author

@dr-m dr-m commented on ab1e6fe Jan 30, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, it could be reasonable, and maybe some settings could be adjusted to make the shutdown quicker.
That still does not explain the hang at startup. On startup, there should be no excessive flushing going on, except if a crash recovery (redo log apply) took place.

Please sign in to comment.