percona-server sending ioctl to a partition

[Adrian Swift]

Hello I am running the percona-server v5.5.20-rel24.1-217.squeeze on a server with linux 3.2.6, and I bumped into some syslogs

kernel: [ 263.412115] mysqld: sending ioctl 4004fecd to a partition!

I found an explanation on the linux-scsi mailing list pertaining to zfs-fuse where it was said that software would fail: http://www.digipedia.pl/usenet/thread/19288/72219/

> "If I'm not mistaken, the whole point of a series of patches titled:
> "fail SCSI passthrough ioctls on partition devices" was to flag and
> ultimately break any user space code that attempted to use the SG_IO
> ioctl on a partition block device (e.g. send a SCSI INQUIRY via
> SG_IO to /dev/sda2). This is for security reasons. So when the
> kernel enforces that, zfs-fuse will break. Please alert the zfs-fuse
> maintainers."

I didn't see any mention of it for the milestone set for 03.20 release. So I thought best to check here since I don't know what exactly percona-server wants to do and if failing is benign, or may cause problems. Thanks.

[Adrian Swift (g55c-adrian)]

It appears to be the result of a fsync on a partition. That wouldn't cause a crash. Thanks.

[Alexey Kopytov (akopytov)]

Adrian,

Can you give us more details on this issue so we could investigate and fix it? Currently I don't see any scenario where Percona Server would call fsync on a partition. So some steps to reproduce the problem, or an strace output (at least the part before the crash occurred) would be very useful. Thank you!

[Tony (l6-postmaster-qh)]

For me it happens when i'm trying to connect one server to another via defined wsrep_cluster_address=gcomm://10.10.0.5
.

 uname -a
Linux pu2b 3.2.0-23-virtual #36-Ubuntu SMP Tue Apr 10 22:29:03 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux

dpkg -l | grep percona
ii percona-xtrabackup 2.0.0-417.lucid Open source backup tool for InnoDB and XtraDB
ii percona-xtradb-cluster-client-5.5 5.5.20-23.4-3748.lucid Percona Server database client binaries
ii percona-xtradb-cluster-common-5.5 5.5.20-23.4-3748.lucid Percona Server database common files (e.g. /etc/mysql/my.cnf)
ii percona-xtradb-cluster-galera-2.x 109.lucid Galera components of Percona XtraDB Cluster
ii percona-xtradb-cluster-server-5.5 5.5.20-23.4-3748.lucid Percona Server database server binaries

mysql.conf is default + added next :

wsrep_provider=/usr/lib/libgalera_smm.so
wsrep_slave_threads=2
wsrep_sst_method=rsync
wsrep_cluster_address=gcomm://10.10.0.5
#wsrep_sst_method=xtrabackup
wsrep_cluster_name="hey"
binlog_format=ROW
default_storage_engine=InnoDB
innodb_locks_unsafe_for_binlog=1
innodb_autoinc_lock_mode=2

mysql logs:
120511 14:18:04 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
120511 14:18:09 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
120511 14:18:09 [Note] Flashcache bypass: disabled
120511 14:18:09 [Note] Flashcache setup error is : ioctl failed

120511 14:18:09 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/libgalera_smm.so'
120511 14:18:09 [Note] WSREP: wsrep_load(): Galera 2.1dev(r109) by Codership Oy <email address hidden> loaded succesfully.
120511 14:18:09 [Note] WSREP: Reusing existing '/var/lib/mysql//galera.cache'.
120511 14:18:09 [Note] WSREP: Passing config to GCS: gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 0.5; gcs.fc_limit = 16; gcs.fc_master_slave = NO; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; replicator.causal_read_timeout = PT30S; replicator.commit_order = 3
120511 14:18:09 [Note] WSREP: wsrep_sst_grab()
120511 14:18:09 [Note] WSREP: Start replication
120511 14:18:09 [Note] WSREP: Found saved state: 8a79c005-9b62-11e1-0800-d9bcd6797e7f:1
120511 14:18:09 [Note] WSREP: Assign initial position for certification: 1, protocol version: -1
120511 14:18:09 [Note] WSREP: Setting initial position to 8a79c005-9b62-11e1-0800-d9bcd6797e7f:1
120511 14:18:09 [Note] WSREP: protonet asio version 0
120511 14:18:09 [Note] WSREP: backend: asio
120511 14:18:09 [Note] WSREP: GMCast version 0
120511 14:18:09 [Note] WSREP: (229f11e5-9b74-11e1-0800-23b97aa65211, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
120511 14:18:09 [Note] WSREP: (229f11e5-9b74-11e1-0800-23b97aa65211, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
120511 14:18:09 [Note] WSREP: EVS version 0
120511 14:18:09 [Note] WSREP: PC version 0
120511 14:18:09 [Note] WSREP: gcomm: connecting to group 'hey', peer '192.168.1.1...

[Olivier Doucet (odoucet)]

I'm also experiencing this "bug". This is not an fsync but an ioctl call when MySQLD is launched.

Using CentOS 6.2 + Percona Server (GPL), Release rel25.3, Revision 240

With strace I get the following :
$ strace /usr/bin/mysqld_safe --datadir=/mnt/test/mysql --pid-file=/var/run/mysqld.pid
[...]
open("/usr/bin/mysqld_safe", O_RDONLY) = 3
ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fff9bc0f180) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(3, 0, SEEK_CUR) = 0
read(3, "#!/bin/sh\n# Copyright Abandoned "..., 80) = 80
lseek(3, 0, SEEK_SET) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=4*1024}) = 0
[...]

Full strace : http://pastebin.com/raw.php?i=UNHC2gEj

Log in dmesg :

[241445.237406] mysqld: sending ioctl 4004fecd to a partition!

[Alexey Kopytov (akopytov)]

Olivier,

I don't think that ioctl() from the strace output has anything to do with the dmesg warning. ioctl(..., TCGETS, ...) is used by the shell interpreter to check if the input is a terminal or a file.

The dmesg warning apparently comes from the mysqld binary and has a different ioctl command.

[PavelVD (pdobryakov)]

I also see such strings in message log

Jun 5 02:21:25 mg29 kernel: [2968419.012753] mysqld: sending ioctl 4004fecd to a partition!
Jun 5 02:21:25 mg29 kernel: [2968419.012757] mysqld: sending ioctl 4004fecd to a partition!
Jun 5 02:32:13 mg29 kernel: [2969065.804185] mysqld D 0000000000000000 0 25362 23876 0x00000000
Jun 5 02:32:13 mg29 kernel: [2969065.804190] ffff881839cb3880 0000000000000086 0000000000000000 ffffffff8104a4ba
Jun 5 02:32:13 mg29 kernel: [2969065.804195] 0007ffffffffffff 0000000000000001 000000000000f9e0 ffff8818253b9fd8
Jun 5 02:32:13 mg29 kernel: [2969065.804200] 0000000000015780 0000000000015780 ffff880c6a9669f0 ffff880c6a966ce8
Jun 5 02:32:13 mg29 kernel: [2969065.804204] Call Trace:
Jun 5 02:32:13 mg29 kernel: [2969065.804214] [<ffffffff8104a4ba>] ? try_to_wake_up+0x289/0x29b
Jun 5 02:32:13 mg29 kernel: [2969065.804221] [<ffffffff81065033>] ? autoremove_wake_function+0x9/0x2e
Jun 5 02:32:13 mg29 kernel: [2969065.804244] [<ffffffffa01302b3>] ? jbd2_log_wait_commit+0xbf/0x112 [jbd2]
Jun 5 02:32:13 mg29 kernel: [2969065.804249] [<ffffffff8106502a>] ? autoremove_wake_function+0x0/0x2e
Jun 5 02:32:13 mg29 kernel: [2969065.804264] [<ffffffffa014eb41>] ? ext4_sync_file+0x199/0x25c [ext4]
Jun 5 02:32:13 mg29 kernel: [2969065.804272] [<ffffffff8110c058>] ? vfs_fsync_range+0x73/0x9e
Jun 5 02:32:13 mg29 kernel: [2969065.804277] [<ffffffff8110c102>] ? do_fsync+0x28/0x39
Jun 5 02:32:13 mg29 kernel: [2969065.804282] [<ffffffff8110c131>] ? sys_fsync+0xb/0x10
Jun 5 02:32:13 mg29 kernel: [2969065.804288] [<ffffffff81010b42>] ? system_call_fastpath+0x16/0x1b
Jun 5 02:36:13 mg29 kernel: [2969305.370339] mysqld D ffff88165b5ffec0 0 25861 23876 0x00000000
Jun 5 02:36:13 mg29 kernel: [2969305.370345] ffff881839fc8710 0000000000000086 0000000000000092 ffffffff8104a4ba
Jun 5 02:36:13 mg29 kernel: [2969305.370350] 0007ffffffffffff 0000000000000001 000000000000f9e0 ffff88165b5fffd8
Jun 5 02:36:13 mg29 kernel: [2969305.370354] 0000000000015780 0000000000015780 ffff881838450e20 ffff881838451118
Jun 5 02:36:13 mg29 kernel: [2969305.370358] Call Trace:
Jun 5 02:36:13 mg29 kernel: [2969305.370367] [<ffffffff8104a4ba>] ? try_to_wake_up+0x289/0x29b
Jun 5 02:36:13 mg29 kernel: [2969305.370373] [<ffffffff81065033>] ? autoremove_wake_function+0x9/0x2e
Jun 5 02:36:13 mg29 kernel: [2969305.370390] [<ffffffffa01302b3>] ? jbd2_log_wait_commit+0xbf/0x112 [jbd2]
Jun 5 02:36:13 mg29 kernel: [2969305.370394] [<ffffffff8106502a>] ? autoremove_wake_function+0x0/0x2e
Jun 5 02:36:13 mg29 kernel: [2969305.370405] [<ffffffffa014eb41>] ? ext4_sync_file+0x199/0x25c [ext4]
Jun 5 02:36:13 mg29 kernel: [2969305.370411] [<ffffffff8110c058>] ? vfs_fsync_range+0x73/0x9e
Jun 5 02:36:13 mg29 kernel: [2969305.370415] [<ffffffff8110c102>] ? do_fsync+0x28/0x39
Jun 5 02:36:13 mg29 kernel: [2969305.370418] [<ffffffff8110c131>] ? sys_fsync+0xb/0x10
Jun 5 02:36:13 mg29 kernel: [2969305.370422] [<ffffffff81010b42>] ? system_call_fastpath+0x16/0x1b
Jun 5 03:12:31 mg29 kernel: [2971480.224737] mysqld: sending ioctl 4004fecd to a partition!
Jun 5 03:12:31 mg29 kernel: [2971480.224741] mysqld: sending ioctl 400...

[PavelVD (pdobryakov)]

And this happened at a fairly large number of operations with heavy partitions. (reorganize, remove ....)

[Stewart Smith (stewart)]

I think this is FlashCache again, and it should instead better check if FlashCache is supported on a system.

[Raghavendra D Prabhu (raghavendra-prabhu)]

--flashcache has been added to mysqld / flashcache to options, so flashcache detection is done only when that is passed.

Also, note that, flashcache detection may have been the reason for other errors like permission denied (for raw access to device), apparmor / selinux killing mysqld (again for raw access / ioctl to device).

[Raghavendra D Prabhu (raghavendra-prabhu)]

Fix released in 5.5.27-29.0 -- https://launchpad.net/percona-server/+milestone/5.5.27-29.0

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1905