Wednesday, May 16, 2007

Finding problems in binaries

Since 5.0.34 of mySQL, something changed that is not compatible with my generic all static build of a mySQL RPM I can get it to work if I use mysqlmanager, but executing mysqld at the command line blocks waiting for a signal. The steps below shows how to track down problems with mysql binaries.



/usr/sbin/mysqld-debug --basedir=/ --datadir=/var/lib/mysql --user=mysql --pid-file=/var/lib/mysql/db.pid --skip-external-locking --console --debug --log --one-thread


This will create a mysql.trace file in /tmp

the output of the trace file suspends just like the mysqld process, this is post innodb setup phase.


T@16384: | | | >_mymalloc
T@16384: | | | | enter: Size: 24
T@16384: | | | | exit: ptr: 0x1d1cc5c8
T@16384: | | | <_mymalloc
T@16384: | | | exit: fd: 8
T@16384: | | T@16384: | | >my_close
T@16384: | | | my: fd: 8 MyFlags: 16
T@16384: | | | >_myfree
T@16384: | | | | enter: ptr: 0x1d1cc5c8
T@16384: | | | <_myfree
T@16384: | |



So since this wasn't any help, lets start the process under strace


open("/var/lib/mysql/ibdata1", O_RDWR) = 8
fcntl(8, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
open("/var/lib/mysql/ib_logfile0", O_RDWR) = 13
fcntl(13, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
open("/var/lib/mysql/ib_logfile1", O_RDWR) = 14
fcntl(14, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
mmap(NULL, 2101248, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2d4e9c4000
mmap(NULL, 1359986688, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2d4ebc5000
pread(13, "\0\0\0\0\0\7GX\0\0\0\25d\352\r@$\357M@\1\0\0\0\377\377"..., 512, 512) = 512
pread(13, "\0\0\0\0\0\7GY\0\0\0\25d\352\r@$\357M@\1\0\0\0\377\377"..., 512, 1536) = 512
pread(13, "\0\0\0\0\0\7GY\0\0\0\25d\352\r@$\357M@\1\0\0\0\377\377"..., 512, 1536) = 512
pread(13, "\0\0\0\0\0\0\0\25?\372\320\0\0\0\0\0 \0\0\0\0\0\0\0"..., 2048, 0) = 2048
pread(8, "\341W\7n\0\0\0\5\0\0\0\0\0\0\0\0\0\0\0\25d\352\r@\0\0\0"..., 16384, 81920) = 16384
mmap(NULL, 2117632, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2d9fcc1000
pread(8, "\341W\7n\0\0\0\5\0\0\0\0\0\0\0\0\0\0\0\25d\352\r@\0\0\0"..., 1048576, 1048576) = 1048576
pread(8, "\r@\215W\0\0\3q\0\0\3m\377\377\377\377\0\0\0\25d\314\216"..., 1048576, 2097152) = 1048576
pread(14, "\212\262u\7\1@\0/\0\7GSnfo\1\0\0\0\0\0\0\0\0vern.fs@"..., 65536, 82791424) = 65536
pread(14, "\212\262u\7\1@\0/\0\7GSnfo\1\0\0\0\0\0\0\0\0vern.fs@"..., 512, 82791424) = 512
time(NULL) = 1179341853
kill(28977, SIGRTMIN) = -1 EPERM (Operation not permitted)
sched_yield() = 0
time(NULL) = 1179341853
rt_sigprocmask(SIG_SETMASK, NULL, [HUP INT QUIT PIPE TERM TSTP RTMIN], 8) = 0
rt_sigsuspend([HUP INT QUIT PIPE TERM TSTP]



rt_sigsuspend - Replace the signal mask for a value with the unewset value until a signal is received



This makes sense now, mysqlmanager sends a signal, while safe_mysqld and the command line doesn't, so until I am told different I think I found a bug in mysqld introduced 5.0.34


Here is my bug report

http://bugs.mysql.com/bug.php?id=28791

No comments: