MySQL Bugs: #34459: MySQL 5.0.51a suiciding on FreeBSD (Error: semaphore wait has lasted

Bug #34459	MySQL 5.0.51a suiciding on FreeBSD (Error: semaphore wait has lasted > 600)
Submitted:	11 Feb 2008 14:13	Modified:	30 Nov 2009 21:25
Reporter:	Hugo Silva	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.0.51a	OS:	Any (amd64)
Assigned to:	Heikki Tuuri	CPU Architecture:	Any
Tags:	freebsd freebsd7 mysql mysql5 innodb crash

Description:
Getting daily crashes with MySQL (compiled without any optimizations / CFLAGS) on a quad core server w/ 4GB of RAM.

This server is in production, and it happens consistently, hence S1.

8 webservers contact this MySQL servers over a gigabit network.

InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
080210 22:46:36InnoDB: Assertion failure in thread 2170559280 in file srv0srv.c line 2095
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
080210 22:46:36 - 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=67108864
read_buffer_size=126976
max_used_connections=198
max_connections=256
threads_connected=198
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 621566 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

080210 22:46:36 mysqld restarted
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
080210 22:46:37 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.

How to repeat:
Threads: 4 Questions: 8878121 Slow queries: 12 Opens: 6781 Flush tables: 1 Open tables: 1020 Queries per second avg: 1237.541

(This server peaks at about 1800 queries/sec)

I have tried various things to eliminate the crashes, to no avail so far. Interestingly enough, lowering innodb buffer pool size (1536M->768M) seemed to produce crashes more often.

Please post the entire .err log.

Is the platform AMD or Intel?

Regards,

Heikki

This frequent hang bug was fixed in 5.0.54:

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

I will perform an update to .54 asap and will post the results after it's running for a few days.

Still need the .err log ?

Hugo,

please send the .err log if it still hangs.

--Heikki

Hmm... yes, it is:

http://dev.mysql.com/doc/refman/5.0/en/releasenotes-es-5-0.html

The public bk repo of 5.0 probably already has the source. Please look for the source.

Currently recompiling mysql 5.0.51a with http://bugs.mysql.com/file.php?id=7470

I'll post my experience with this patch as soon as I have info to provide.

Thanks for the pointers.

Got another crash today with the patch applied.

error log:

080212 16:27:06 - 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=67108864
read_buffer_size=126976
max_used_connections=71
max_connections=256
threads_connected=36
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 621566 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

080212 16:27:51  mysqld restarted
InnoDB: Log scan progressed past the checkpoint lsn 15 1486074162
080212 16:27:53  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 15 1491316736
InnoDB: Doing recovery: scanned up to log sequence number 15 1496559616
InnoDB: Doing recovery: scanned up to log sequence number 15 1501802496
InnoDB: Doing recovery: scanned up to log sequence number 15 1507045376
InnoDB: Doing recovery: scanned up to log sequence number 15 1512288256
InnoDB: Doing recovery: scanned up to log sequence number 15 1517531136
InnoDB: Doing recovery: scanned up to log sequence number 15 1522774016
InnoDB: Doing recovery: scanned up to log sequence number 15 1528016896
InnoDB: Doing recovery: scanned up to log sequence number 15 1533259776
InnoDB: Doing recovery: scanned up to log sequence number 15 1538502656
InnoDB: Doing recovery: scanned up to log sequence number 15 1543745536
InnoDB: Doing recovery: scanned up to log sequence number 15 1548988416
InnoDB: Doing recovery: scanned up to log sequence number 15 1554231296
InnoDB: Doing recovery: scanned up to log sequence number 15 1559474176
InnoDB: Doing recovery: scanned up to log sequence number 15 1564717056
InnoDB: Doing recovery: scanned up to log sequence number 15 1569959936
InnoDB: Doing recovery: scanned up to log sequence number 15 1575202816
InnoDB: Doing recovery: scanned up to log sequence number 15 1580445696
InnoDB: Doing recovery: scanned up to log sequence number 15 1585688576
InnoDB: Doing recovery: scanned up to log sequence number 15 1590931456
InnoDB: Doing recovery: scanned up to log sequence number 15 1596174336
InnoDB: Doing recovery: scanned up to log sequence number 15 1601417216
InnoDB: Doing recovery: scanned up to log sequence number 15 1606660096
InnoDB: Doing recovery: scanned up to log sequence number 15 1611902976
InnoDB: Doing recovery: scanned up to log sequence number 15 1617145856
InnoDB: Doing recovery: scanned up to log sequence number 15 1622388736
InnoDB: Doing recovery: scanned up to log sequence number 15 1627631616
InnoDB: Doing recovery: scanned up to log sequence number 15 1632874496
InnoDB: Doing recovery: scanned up to log sequence number 15 1638117376
InnoDB: Doing recovery: scanned up to log sequence number 15 1643360256
InnoDB: Doing recovery: scanned up to log sequence number 15 1648603136
InnoDB: Doing recovery: scanned up to log sequence number 15 1653846016
InnoDB: Doing recovery: scanned up to log sequence number 15 1659088896
InnoDB: Doing recovery: scanned up to log sequence number 15 1664331776
InnoDB: Doing recovery: scanned up to log sequence number 15 1669574656
InnoDB: Doing recovery: scanned up to log sequence number 15 1674817536
InnoDB: Doing recovery: scanned up to log sequence number 15 1680060416
InnoDB: Doing recovery: scanned up to log sequence number 15 1685303296
InnoDB: Doing recovery: scanned up to log sequence number 15 1690101156
080212 16:28:34  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
InnoDB: Apply batch completed
080212 16:29:30  InnoDB: Started; log sequence number 15 1690101156
080212 16:29:30 [Note] /usr/local/libexec/mysqld: ready for connections.
Version: '5.0.51a'  socket: '/tmp/mysql.sock'  port: 3306  FreeBSD port: mysql-server-5.0.51a

Hugo,

please post the entire .err log.

--Heikki

Many thanks for writing a bug report.

I just changed the version to 5.0.51a.

Please correct me: Because you wrote 7.0-RC1 as version instead of the MySQL version, I think you use FreeBSD 7.0-RC1 amd64.

Heikki asked you, if the hardware is Intel or AMD?

Also it could be interesting, if you install MySQL by using ports or packages or by compiling on your own.

a)
Yes, I'm on FreeBSD 7.0-RC1 amd64.

b)
CPU: Intel(R) Xeon(R) CPU            5110  @ 1.60GHz (1597.53-MHz K8-class CPU)
FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs

c)
Installing from ports, with BUILD_OPTIMIZED=yes,  CFLAGS=-O2 -fno-strict-aliasing -pipe and CPUTYPE=k8 + aforementioned patch

As you probably noticed, in the last crash the innodb error was not present. I might have pinpointed why it was still crashing (process size limits), will update this report in a few days or in the next crash (I shrinked the process to around 1400M now, the limit is 2048)

The patch fixes the original error, but I am still getting segfaults. I will try to compile without optimizations, and if the problem persists I'll open a new bug report.

Hugo,

ok, let us close this bug report as a duplicate. Please open a new bug report if the segfaults persist.

--Heikki

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".