MySQL's ib_logfile1 cannot be created properly

[tomposmiko]

System information

Type	Version/Name
Distribution Name	Ubuntu
Distribution Version	22.04 and 18.04
Kernel Version	5.15 and 5.4
Architecture	amd64
OpenZFS Version	zfs-2.1.2-1ubuntu3 and zfs-2.1.4-0york0~18.04

Describe the problem you're observing

I'm not sure, if it's caused by ZFS, though its probability is quite high.

If I start Percona MySQL Server 8.0 backed with ZFS, I get the following error:

2022-04-14T21:10:15.443147Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27-18) starting as process 2259
2022-04-14T21:10:15.463221Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-04-14T21:10:15.547437Z 1 [ERROR] [MY-012963] [InnoDB] Log file ./ib_logfile1 is of different size 0 bytes than other log files 17793024 bytes!
2022-04-14T21:10:15.547485Z 1 [ERROR] [MY-012930] [InnoDB] Plugin initialization aborted with error Generic error.
2022-04-14T21:10:16.534037Z 1 [ERROR] [MY-010334] [Server] Failed to initialize DD Storage Engine
2022-04-14T21:10:16.534204Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed.
2022-04-14T21:10:16.534296Z 0 [ERROR] [MY-010119] [Server] Aborting

Describe how to reproduce the problem

Create a dataset with recent ZFS version, get it mounted to /var/lib/mysql and initialize a database instance on it (eg. apt install percona-server-server). Version 5.7 works properly.
I tested Percona only, did not test classic MySQL.

I am pretty sure, it worked with a previous version from York's repository, just don't know, which was that, because I restarted that machine with the recent version.
MySQL works well if the database is created somewhere else, eg. on xfs or ext4 and migrated to ZFS.

[tomposmiko]

The version, that worked properly was probably 2.1.1-0york0~20.04. I just don't know, how should I test it, because that version is already not in that repository.

[rincebrain]

Maybe fallout from #12724, as a wild guess?

You could adjust the tunable mentioned in there - I think it's the case that dmu_offset_next_sync defaults to 0 and was planned to be 1 in 2.1.5... - and try again?

[tomposmiko]

root@csepcsop:~# echo 1 > /sys/module/zfs/parameters/zfs_dmu_offset_next_sync
root@csepcsop:~# 

And it still the same.

[rincebrain]

My three guesses were either the aforementioned thing, they're checking the filesize too soon after creating the file in some exciting fashion (ZFS will, IIUC, actually tell you it's 0 bytes until it winds up flushed out, which can surprise the hell out of things which expect otherwise despite not having forced it to sync), or some as-yet-unknown bug in either Percona or ZFS.

You could try fiddling with innodb_use_native_aio in Percona, and if that works, then we have somewhere specific to focus on; otherwise, I'll see about testing it when I get a chance, though I personally am likely to be busy the next couple days.

edit: All the results I find from searching that error are from running MySQL versions in containers - is this on baremetal, in a VM, or a container?

[tomposmiko]

log.tar.gz

I attached the strace output of mysqld --user=mysql after removing ib_logfile* files.
I tested it in LXD and on KVM machines too. The above comes from a KVM.

[rincebrain]

The above appears to be a different error from the one you mentioned before:

write(2, "2022-04-15T04:50:15.111962Z 1 [ERROR] [MY-012642] [InnoDB] Tried to read 65536 bytes at offset 17792000, but was only able to read 512 of FD 8, filename /var/lib/mysql/ib_logfile0\n", 180) = 180
mprotect(0x7f13ba67d000, 4096, PROT_READ|PROT_WRITE) = 0
write(2, "2022-04-15T04:50:15.112038Z 1 [ERROR] [MY-012592] [InnoDB] Operating system error number 2 in a file operation.\n", 112) = 112
write(2, "2022-04-15T04:50:15.112101Z 1 [ERROR] [MY-012593] [InnoDB] The error means the system cannot find the path specified.\n", 118) = 118
mprotect(0x7f13ba67e000, 8192, PROT_READ|PROT_WRITE) = 0
write(2, "2022-04-15T04:50:15.112159Z 1 [ERROR] [MY-012594] [InnoDB] If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.\n", 170) = 170
write(2, "2022-04-15T04:50:15.112195Z 1 [ERROR] [MY-012646] [InnoDB] File ./ib_logfile0: 'read' returned OS error 71. Cannot continue operation\n", 134) = 134
mprotect(0x7f13ba680000, 4096, PROT_READ|PROT_WRITE) = 0
write(2, "2022-04-15T04:50:15.112254Z 1 [ERROR] [MY-012981] [InnoDB] Cannot continue operation.\n", 86) = 86

edit to add: I am also now suspicious it is fallout from/related to the thing I mentioned before, once again, because:

openat(AT_FDCWD, "./ib_logfile101", O_RDWR|O_CREAT|O_EXCL, 0640) = 4
[...]
fallocate(4, FALLOC_FL_ZERO_RANGE, 0, 50331648) = 0
[...]
rename("./ib_logfile101", "./ib_logfile0") = 0

[tomposmiko]

Now I am a bit confused. So I deleted the mysql datadir.
And did it from scratch:

strace -ff -s 388888 -o /root/1/log mysqld --initialize --user=mysql
strace -ff -s 388888 -o /root/2/log mysqld --user=mysql
log:

2022-04-15T05:26:03.617017Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.27-18) initializing of server in progress as process 1649
2022-04-15T05:26:03.641552Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-04-15T05:26:05.021629Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2022-04-15T05:26:06.828908Z 0 [Warning] [MY-013746] [Server] A deprecated TLS version TLSv1 is enabled for channel mysql_main
2022-04-15T05:26:06.828946Z 0 [Warning] [MY-013746] [Server] A deprecated TLS version TLSv1.1 is enabled for channel mysql_main
2022-04-15T05:26:06.887280Z 6 [Note] [MY-010454] [Server] A temporary password is generated for root@localhost: BgJ(qe<wh1#p
2022-04-15T05:28:25.055731Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.27-18) starting as process 1762
2022-04-15T05:28:25.080524Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-04-15T05:28:25.192897Z 1 [ERROR] [MY-012963] [InnoDB] Log file ./ib_logfile1 is of different size 0 bytes than other log files 17793024 bytes!
2022-04-15T05:28:25.192975Z 1 [ERROR] [MY-012930] [InnoDB] Plugin initialization aborted with error Generic error.
2022-04-15T05:28:26.172563Z 1 [ERROR] [MY-010334] [Server] Failed to initialize DD Storage Engine
2022-04-15T05:28:26.172802Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed.
2022-04-15T05:28:26.172914Z 0 [ERROR] [MY-010119] [Server] Aborting
2022-04-15T05:28:26.173413Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.27-18)  Percona Server (GPL), Release '18', Revision '24801e21b45'.

strace files:

init.tar.gz
run.tar.gz

[tomposmiko]

Also tried with this setting:

root@b:/var/lib/mysql# cat /sys/module/zfs/parameters/zfs_dmu_offset_next_sync 
1

It can be changed online, right?

[rincebrain]

Sure, changing it online should do the right thing - it certainly did in testing the fix before.

[tomposmiko]

I also tested it with innodb_use_native_aio on and off, the outcome is the same as well as with classic mysql from ubuntu (so no Percona is needed for reproducing).

[rincebrain]

Having gone digging, this really seems like the case in #12745, but that should really be dealt with correctly in 2.1.3 and 2.1.4 (though, notably, not in 2.1.2).

So are you absolutely sure both userland and kernel module are 2.1.4 when you're testing? (e.g. "what two lines does zfs version report?")

e: no, actually, that commit is listed in 2.1.2 too, I just can't use ^F apparently, so even then it should be applying...

edit 2: yup, I sure am running 2.1.4 in this Ubuntu 20.04 VM, and it sure is failing like this...

[tomposmiko]

So no double checking and more confirmation needed?

[rincebrain]

Not particularly, no, probably until someone comes up with a good solution.

Excitingly, it reproduces on git master (0dd34a1).

CC @behlendorf since he wrote the original fix, I'm not sure I'll have time to look into this myself in the next couple days, and "MySQL on ZFS isn't working sometimes" seems bad - tl;dr it seems like doing mysqld --initialize with /var/lib/mysql as a ZFS dataset on at least Ubuntu is producing things that smell awfully like the later bugs in #11900 - on my 20.04 testbed, ib_logfile0 is ending up variable sizes on different runs and failing on startup because they're not multiples of pagesize, and even if that succeeds, ib_logfile1 is ending up 0b...

[tomposmiko]

thanks so much for your efforts!

[rincebrain]

A couple of data points.

• Someone on IRC reported they couldn't reproduce it with the official MySQL Docker images (based on Debian 10, it looks like) running 8.0.27-1debian10 on a Gentoo host and 5.15.32 kernel.
• On stock Debian 11 running 5.10.0-13-amd64, 2.1.4 works fine with MariaDB but fails with Percona MySQL 8.0.27-18-1.bullseye and MySQL 8.0.28-1debian11.
• Fails with zfs_dmu_offset_next_sync=0 or 1, as the reporter said.

e: Uh-oh, my bisect doesn't have either of the ones from #11900 in the possible culprits, but it does have 4372e96 ...

e2: I see something I overlooked in 4372e96, I'll be testing a change after I double-check that this patch is the cause. (It's adding |FALLOC_FL_KEEP_SIZE to the second check modified in that patch - e.g. if (mode & (test_mode | FALLOC_FL_KEEP_SIZE)) { - since while FALLOC_FL_KEEP_SIZE is mandatory for use with PUNCH_HOLE, it is not with ZERO_RANGE.)

e3: No, I see a better fix, I think... - and it is that patch.

[rincebrain]

Okay, I'm about to turn into a pumpkin for most of the day at least, but this corrects the problem at a glance, though it hasn't been run through the test suite yet or had a test added for this failure mode...

rincebrain@c03b64c

[panlinux]

Maybe I missed it in the above conversation, but this seems to be a simple reproducer and easy checker.

Working:

root@nsn7:~# touch foo.img
root@nsn7:~# fallocate -z -l 10M foo.img
root@nsn7:~# l foo.img 
-rw-r--r-- 1 root root 10M abr 18 15:12 foo.img

Incorrect:

root@j1:~# touch foo.img
root@j1:~# fallocate -z -l 10M foo.img
root@j1:~# ll foo.img 
-rw-r--r-- 1 root root 0 Apr 18 18:06 foo.img

[rincebrain]

You will find something very much like that in the new test case in the linked PR.

…

On Mon, Apr 18, 2022, 2:24 PM Andreas Hasenack ***@***.***> wrote: Maybe I missed it in the above conversation, but this seems to be a simple reproducer and easy checker. Working: ***@***.***:~# touch foo.img ***@***.***:~# fallocate -z -l 10M foo.img ***@***.***:~# l foo.img -rw-r--r-- 1 root root 10M abr 18 15:12 foo.img Incorrect: ***@***.***:~# touch foo.img ***@***.***:~# fallocate -z -l 10M foo.img ***@***.***:~# ll foo.img -rw-r--r-- 1 root root 0 Apr 18 18:06 foo.img — Reply to this email directly, view it on GitHub <#13329 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AABUI7KE2DITTVE2NWYOLSDVFWSD3ANCNFSM5TO5X5SQ> . You are receiving this because you commented.Message ID: ***@***.***>

[tomposmiko]

@rincebrain Do you have any information on the release date?

[behlendorf]

We don't expect to tag 2.1.5 for a month or so. However, it may be cherry-picked in to the Ubuntu release sooner, #13338 (comment).

[tomposmiko]

What's the release policy, when do you release a new version?

Unfortunately, I still need to stay on Bionic for a while.
So ppa is in use:
https://launchpad.net/~jonathonf/+archive/ubuntu/zfs.

@jonathonf my understanding is that you do not cherry pick commits, just automatically build packages upon github releases. Is that correct?
Or is there any chance, would you mind include this fix?

[stevenj]

I just hit this issue. As a temporary workaround until 2.1.5 drops, I made a sparse zvol, partitioned it and formatted it as ext4. MySQL works properly in this configuration.

[Eurythmax]

@stevenj can you give me some guide for your temp fix? I would need that too.

Installing this didnt helped me: https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/4831

[nicodier]

@obazda20 please delete ./#innodb_redo/#ib_redo0 if it is smaller than 65536 bytes. afterwards restart mysql, then it will throw another error, you should now truncate it to 48M and restart mysql again. This worked for me without data loss.

[kamzata]

This worked for me:

truncate -s 48M /var/lib/mysql/#innodb_redo/#ib_redo*

[lflare]

With ZFS 1.2.5, you only need to truncate it back to size once, and it should work on subsequent restarts

Just noticed this bug when my Ubuntu LXC's upgraded the MySQL package tonight. I'm on Proxmox 7.2-7 (Linux pve2 5.15.39-2-pve #1 SMP PVE 5.15.39-2 (Wed, 20 Jul 2022 17:22:19 +0200) x86_64 GNU/Linux) hypervisor with: libzfs4linux/stable,now 2.1.5-pve1 amd64 [installed,automatic] zfs-initramfs/stable,now 2.1.5-pve1 all [installed] zfs-zed/stable,now 2.1.5-pve1 amd64 [installed] zfsutils-linux/stable,now 2.1.5-pve1 amd64 [installed]

2022-07-29T08:13:25.733986Z 1 [ERROR] [MY-012962] [InnoDB] The redo log file ./#innodb_redo/#ib_redo5 size 2940928 is not a multiple of innodb_page_size

Temporary fix for me:

apt dist-upgrade Do you want to continue? [Y/n] Setting up mysql-server-8.0 (8.0.30-0ubuntu0.20.04.2) ... mysqld will log errors to /var/log/mysql/error.log mysqld is running as pid 2836797 dpkg: error processing package mysql-server-8.0 (--configure): installed mysql-server-8.0 package post-installation script subprocess returned error exit status 1 dpkg: dependency problems prevent configuration of mysql-server: mysql-server depends on mysql-server-8.0; however: Package mysql-server-8.0 is not configured yet.

dpkg: error processing package mysql-server (--configure): dependency problems - leaving unconfigured Errors were encountered while processing: mysql-server-8.0 mysql-server E: Sub-process /usr/bin/dpkg returned an error code (1)

# truncate -s 48M /var/lib/mysql/#innodb_redo/#ib_redo5 # truncate -s 48M /var/lib/mysql/#innodb_redo/#ib_redo0

apt dist-upgrade Do you want to continue? [Y/n] Setting up mysql-server-8.0 (8.0.30-0ubuntu0.20.04.2) ... mysqld will log errors to /var/log/mysql/error.log mysqld is running as pid 2837347 Skipping profile in /etc/apparmor.d/disable: usr.sbin.mysqld Setting up mysql-server (8.0.30-0ubuntu0.20.04.2) ...

Check that you are actually running ZFS 2.1.5. Updating it alone isn't enough I believe, you have to reboot the system too.

❯ zfs version
zfs-2.1.5-pve1
zfs-kmod-2.1.5-pve1

[sk0le]

Hi, im new to this, sorry if i did not explain something good.

So i've had same error, ive fixed it with truncate.

Now, when i try to lets say install git on my machine i get this

Ubuntu 20.04 using ZFS file system.