server won't start when flush_method=ALL_O_DIRECT and track_changed_pages=TRUE

[George Ormond Lorch III]

Server fails to start with:
InnoDB: Error: tried to read 65536 bytes at offset 0 2048.
InnoDB: Was only able to read 0.

my.cnf:
[client]
port=10031
socket=/data/dev/allo/mysql.sock
[mysqld]
basedir=/data/bin/ps-5.5-16274-mk3
datadir=/data/dev/allo/data
tmpdir=/data/dev/allo/tmp
port=10031
socket=/data/dev/allo/mysql.sock
pid-file=/data/dev/allo/mysql.pid
console
user=root
server-id=1
innodb_track_changed_pages=TRUE
innodb_flush_method=ALL_O_DIRECT

Using branch:
  parent branch: bzr+ssh://bazaar.launchpad.net/~laurynas-biveinis/percona-server/QA-16274-5.5-3/

[Laurynas Biveinis (laurynas-biveinis)]

George -

I cannot reproduce this locally. Could you please
1) attach the full error log for the failed run;
2) set a breakpoint at these InnoDB diagnostics you get and provide a stacktrace leading either to the diagnostics or the failing call itself?

[George Ormond Lorch III (gl-az)]

Sure Laurynas, in fact, I'll even go a little further and see if I can
debug/fix it for you, should be pretty straightforward.

On 5/27/2013 10:50 AM, Laurynas Biveinis wrote:
> George -
>
> I cannot reproduce this locally. Could you please
> 1) attach the full error log for the failed run;
> 2) set a breakpoint at these InnoDB diagnostics you get and provide a stacktrace leading either to the diagnostics or the failing call itself?
>
> ** Changed in: percona-server/5.1
> Status: In Progress => Triaged
>
> ** Changed in: percona-server/5.5
> Assignee: Laurynas Biveinis (laurynas-biveinis) => George Ormond Lorch III (gl-az)
>
> ** Changed in: percona-server/5.1
> Assignee: Laurynas Biveinis (laurynas-biveinis) => George Ormond Lorch III (gl-az)
>
> ** Changed in: percona-server/5.6
> Assignee: Laurynas Biveinis (laurynas-biveinis) => George Ormond Lorch III (gl-az)
>

--
George O. Lorch III
Software Engineer, Percona
[phone] x542 US/Arizona (GMT -7)
skype: george.ormond.lorch.iii

[George Ormond Lorch III (gl-az)]

Looks like it is unaligned i/o on log file

Backtrace:
(gdb) bt
#0 _os_file_read (file=12, buf=0x7fffa8966010, offset=2048, offset_high=0, n=65536, trx=0x0) at os/os0file.c:2525
#1 0x0000000000865fc0 in os_aio (type=10, mode=24, name=0x3a948b8 "./ib_logfile0", file=12, buf=0x7fffa8966010, offset=2048, offset_high=0, n=65536, message1=0x3a947b8, message2=0x0, space_id=4294967280, trx=0x0) at os/os0file.c:3823
#2 0x0000000000935d58 in _fil_io (type=10, sync=1, space_id=4294967280, zip_size=0, block_offset=0, byte_offset=2048, len=65536, buf=0x7fffa8966010, message=0x0, trx=0x0) at fil/fil0fil.c:5341
#3 0x0000000000853f7b in log_group_read_log_seg (type=98887331, buf=0x7fffa8966010 "", group=0x3a94948, start_lsn=8192, end_lsn=73728) at log/log0log.c:2326
#4 0x0000000000856504 in log_online_follow_log_seg (group=0x3a94948, block_start_lsn=8192, block_end_lsn=73728) at log/log0online.c:973
#5 0x0000000000856697 in log_online_follow_log_group (group=0x3a94948, contiguous_lsn=8192) at log/log0online.c:1042
#6 0x0000000000856ba9 in log_online_follow_redo_log () at log/log0online.c:1212
#7 0x00000000008b514d in srv_redo_log_follow_thread (arg=0x0) at srv/srv0srv.c:2751
#8 0x000000391b007851 in start_thread () from /lib64/libpthread.so.0
#9 0x000000391a8e811d in clone () from /lib64/libc.so.6

[Laurynas Biveinis (laurynas-biveinis)]

5.6 does not have the option to set O_DIRECT for log files. Will merge the fix of aligning the read buffer at OS_FILE_LOG_BLOCK_SIZE anyway, since that's what InnoDB does for the log write buffer.