Emile, thank you for sending the whole .err log directly to me.
This is probably the file i/o starvation bug which I have fixed in 4.0.14. In this case a big insert buffer merge causes sequential reads which seem to make requests by other threads to starve. I hope 4.0.14 will be out in two weeks. http://www.innodb.com/ibman.html#InnoDB_history " Fixed a bug: if there were big index scans then a file read request could starve and InnoDB could assert because of a very long semaphore wait. " If we look at the file i/o during the hang, we see it is actually doing a lot of file i/o: " -------- FILE I/O -------- I/O thread 0 state: waiting for i/o request I/O thread 1 state: waiting for i/o request I/O thread 2 state: complete io for buf page I/O thread 3 state: waiting for i/o request Pending normal aio reads: 248, aio writes: 0, ibuf aio reads: 0, log i/o's: 1, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 214679 OS file reads, 22316300 OS file writes, 556601 OS fsyncs 35.50 reads/s, 26998 avg bytes/read, 131.18 writes/s, 16.19 fsyncs/s ------------------------------------- ... -------- FILE I/O -------- I/O thread 0 state: waiting for i/o request I/O thread 1 state: waiting for i/o request I/O thread 2 state: complete io for buf page I/O thread 3 state: waiting for i/o request Pending normal aio reads: 253, aio writes: 0, ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 215218 OS file reads, 22318224 OS file writes, 556832 OS fsyncs 31.70 reads/s, 26627 avg bytes/read, 113.17 writes/s, 13.59 fsyncs/s " So, there is no general hang in the server, but a lot of reads pending. " [mysqld] datadir=/var/lib/mysql socket=/var/lib/mysql/mysql.sock set-variable = innodb buffer pool size=1400M set-variable = innodb additional mem pool size=80M " Your my.cnf is far from optimal. You should make ib_logfiles and the log buffer much bigger than the default http://www.innodb.com/ibman.html#InnoDB_start: " # Set the log file size to about # 25 % of the buffer pool size set-variable = innodb_log_file_size=... set-variable = innodb_log_buffer_size=8M " See http://www.innodb.com/ibman.html#Adding_and_removing about changing the size of the ib_logfiles. Regards, Heikki ----- Original Message ----- From: ""Emile Bourquin"" <[EMAIL PROTECTED]> Newsgroups: mailing.database.mysql Sent: Thursday, July 03, 2003 9:01 AM Subject: mysqld crashes during long index build > ------=_NextPart_000_007B_01C340ED.B86BB880 > Content-Type: text/plain; > charset="iso-8859-1" > Content-Transfer-Encoding: quoted-printable > > Dual Xeon 2.8 GHz, hyperthreaded, 533 MHz FSB > 2 GB RAM > Red Hat, kernel-2.4.20-18.9 SMP > mysql 4.0.13, InnoDB table holding 32 million+ records, building an = > index using: > > create index BY_NAME on PROFILE_NAMES (LAST_NAME,FIRST_NAME) > > my.cnf contains: > > [mysqld] > datadir=3D/var/lib/mysql > socket=3D/var/lib/mysql/mysql.sock > > set-variable =3D innodb_buffer_pool_size=3D1400M > set-variable =3D innodb_additional_mem_pool_size=3D80M > > [mysql.server] > user=3Dmysql > basedir=3D/var/lib > > [safe_mysqld] > err-log=3D/var/log/mysqld.log > pid-file=3D/var/run/mysqld/mysqld.pid > > [client] > socket=3D/var/lib/mysql/mysql.sock > > > > tail of mysqld.lg contains: > > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= > =3D=3D=3D > InnoDB: Warning: a long semaphore wait: > --Thread 1103449392 has waited at btr0cur.c line 390 for 625.00 seconds = > the semaphore: > X-lock on RW-latch at 9edf8384 created in file buf0buf.c line 369 > a writer (thread id 1103449392) has reserved it in mode exclusive > number of readers 0, waiters flag 1 > Last time read locked in file buf0flu.c line 461 > Last time write locked in file buf0buf.c line 1329 > InnoDB: Error: semaphore wait has lasted > 600 seconds > InnoDB: We intentionally crash the server, because it appears to be = > hung. > 030702 10:41:11 InnoDB: Assertion failure in thread 2771143984 in file = > sync0arr.c line 934 > InnoDB: Failing assertion: 0 > InnoDB: We intentionally generate a memory trap. > InnoDB: Send a detailed bug report to [EMAIL PROTECTED] > InnoDB: Thread 2745965872 stopped in file os0file.c line 2386 > InnoDB: Thread 2779536688 stopped in file = > ../../innobase/include/sync0sync.ic line 109 > mysqld got signal 11; > This could be because you hit a bug. It is also possible that this = > binary > or one of the libraries it was linked against is corrupt, improperly = > built, > or misconfigured. This error can also be caused by malfunctioning = > hardware. > We will try our best to scrape up some info that will hopefully help = > diagnose > the problem, but since we have already crashed, something is definitely = > wrong > and this may fail. > > key_buffer_size=3D8388600 > read_buffer_size=3D131072 > > Number of processes running now: 0 > 030702 10:41:13 mysqld restarted > 030702 10:41:14 InnoDB: Database was not shut down normally. > InnoDB: Starting recovery from log files... > InnoDB: Starting log scan based on checkpoint at > InnoDB: log sequence number 15 4169734769 > InnoDB: Doing recovery: scanned up to log sequence number 15 4169757455 > InnoDB: 1 transaction(s) which must be rolled back or cleaned up > InnoDB: in total 30820473 row operations to undo > InnoDB: Trx id counter is 0 146424832 > 030702 10:41:14 InnoDB: Starting an apply batch of log records to the = > database... > InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 = > 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 = > 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 = > 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 = > 90 91 92 93 94 95 96 97 98 99=20 > InnoDB: Apply batch completed > InnoDB: Starting rollback of uncommitted transactions > InnoDB: Rolling back trx with id 0 146424065, 30820473 rows to undo > InnoDB: Progress in percents: 1 2030702 14:20:22 mysqld started > 030702 14:20:24 InnoDB: Database was not shut down normally. > InnoDB: Starting recovery from log files... > InnoDB: Starting log scan based on checkpoint at > InnoDB: log sequence number 15 4237789310 > InnoDB: Doing recovery: scanned up to log sequence number 15 4243032064 > InnoDB: Doing recovery: scanned up to log sequence number 15 4247158606 > InnoDB: 1 transaction(s) which must be rolled back or cleaned up > InnoDB: in total 30221929 row operations to undo > InnoDB: Trx id counter is 0 146424832 > 030702 14:20:25 InnoDB: Starting an apply batch of log records to the = > database... > InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 = > 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 = > 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 = > 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 = > 89 90 91 92 93 94 95 96 97 98 99=20 > InnoDB: Apply batch completed > InnoDB: Starting rollback of uncommitted transactions > InnoDB: Rolling back trx with id 0 146424065, 30221929 rows to undo > InnoDB: Progress in percents: 1 2 3 4 > > ------=_NextPart_000_007B_01C340ED.B86BB880-- > > -- MySQL General Mailing List For list archives: http://lists.mysql.com/mysql To unsubscribe: http://lists.mysql.com/[EMAIL PROTECTED]
