Bug #21952 SLOW LOG KILLING MYSQLD PROCESS
Submitted: 31 Aug 2006 18:46 Modified: 29 Mar 2011 18:43
Reporter: Roberto Spadim (Basic Quality Contributor) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:5.1.11-beta OS:Linux (LINUX 2.6.10)
Assigned to: CPU Architecture:Any

[31 Aug 2006 18:46] Roberto Spadim
Description:
a crashed slow log kill mysqld process, see /home/mysql/err.log file:

060824 22:24:35  mysqld ended

060824 22:24:38  mysqld started
060824 22:24:39 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.1.11-beta'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
060824 22:24:39 [Note] SCHEDULER: Manager thread booting
060824 22:24:39 [Note] SCHEDULER: Loaded 0 events
060824 22:24:39 [Note] SCHEDULER: Suspending operations
060825  9:05:01 [Note] /usr/local/mysql/bin/mysqld: Normal shutdown

060825  9:05:01 [Note] SCHEDULER: Killing manager thread 1
060825  9:05:01 [Note] SCHEDULER: Waiting the manager thread to reply
060825  9:05:01 [Note] SCHEDULER: Resuming operations
060825  9:05:01 [Note] SCHEDULER: Manager thread started with id 1
060825  9:05:01 [Note] SCHEDULER: Shutting down
060825  9:05:01 [Note] SCHEDULER: Waiting for worker threads to finish
060825  9:05:01 [Note] SCHEDULER: Emptying the queue
060825  9:05:01 [Note] SCHEDULER: Stopped
060825  9:05:01 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete

060825 09:05:01  mysqld ended

060825 09:06:34  mysqld started
060825  9:06:35 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.1.11-beta'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
060825  9:06:35 [Note] SCHEDULER: Manager thread booting
060825  9:06:35 [Note] SCHEDULER: Loaded 0 events
060825  9:06:35 [Note] SCHEDULER: Suspending operations
060825 11:43:01  mysqld started
/usr/local/mysql/bin/mysqld: Table 'general_log' is marked as crashed and should be repaired
/usr/local/mysql/bin/mysqld: Table 'slow_log' is marked as crashed and should be repaired

==================== HERE CRASHED!!!! SEE DATE TIME!!! 11:43:01 CRASH, 11:43:02 STARTED!!!

060825 11:43:02 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.1.11-beta'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
060825 11:43:02 [Note] SCHEDULER: Manager thread booting
060825 11:43:02 [Note] SCHEDULER: Loaded 0 events
060825 11:43:02 [Note] SCHEDULER: Suspending operations
060825 11:43:27 [Note] /usr/local/mysql/bin/mysqld: Normal shutdown

060825 11:43:27 [Note] SCHEDULER: Killing manager thread 1
060825 11:43:27 [Note] SCHEDULER: Waiting the manager thread to reply
060825 11:43:27 [Note] SCHEDULER: Resuming operations
060825 11:43:27 [Note] SCHEDULER: Manager thread started with id 1
060825 11:43:27 [Note] SCHEDULER: Shutting down
060825 11:43:27 [Note] SCHEDULER: Waiting for worker threads to finish
060825 11:43:27 [Note] SCHEDULER: Emptying the queue
060825 11:43:27 [Note] SCHEDULER: Stopped
060825 11:43:27 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete

060825 11:43:27  mysqld ended

060825 11:45:00  mysqld started
060825 11:45:01 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.1.11-beta'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
060825 11:45:01 [Note] SCHEDULER: Manager thread booting
060825 11:45:01 [Note] SCHEDULER: Loaded 0 events
060825 11:45:01 [Note] SCHEDULER: Suspending operations
060829 17:27:53  mysqld started
/usr/local/mysql/bin/mysqld: Table 'general_log' is marked as crashed and should be repaired
/usr/local/mysql/bin/mysqld: Table 'slow_log' is marked as crashed and should be repaired
060829 17:27:54 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.1.11-beta'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
060829 17:27:54 [Note] SCHEDULER: Manager thread booting
060829 17:27:54 [Note] SCHEDULER: Loaded 0 events
060829 17:27:54 [Note] SCHEDULER: Suspending operations
060829 17:36:16  mysqld started
/usr/local/mysql/bin/mysqld: Table 'general_log' is marked as crashed and should be repaired
/usr/local/mysql/bin/mysqld: Table 'slow_log' is marked as crashed and should be repaired
060829 17:36:17 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.1.11-beta'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
060829 17:36:17 [Note] SCHEDULER: Manager thread booting
060829 17:36:17 [Note] SCHEDULER: Loaded 0 events
060829 17:36:17 [Note] SCHEDULER: Suspending operations
060831 14:37:40  mysqld started
/usr/local/mysql/bin/mysqld: Table 'general_log' is marked as crashed and should be repaired
/usr/local/mysql/bin/mysqld: Table 'slow_log' is marked as crashed and should be repaired
060831 14:37:41 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.1.11-beta'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
060831 14:37:41 [Note] SCHEDULER: Manager thread booting
060831 14:37:41 [Note] SCHEDULER: Loaded 0 events
060831 14:37:41 [Note] SCHEDULER: Suspending operations
060831 14:37:44 [Note] /usr/local/mysql/bin/mysqld: Normal shutdown

060831 14:37:44 [Note] SCHEDULER: Killing manager thread 1
060831 14:37:44 [Note] SCHEDULER: Waiting the manager thread to reply
060831 14:37:44 [Note] SCHEDULER: Resuming operations
060831 14:37:44 [Note] SCHEDULER: Manager thread started with id 1
060831 14:37:44 [Note] SCHEDULER: Shutting down
060831 14:37:44 [Note] SCHEDULER: Waiting for worker threads to finish
060831 14:37:44 [Note] SCHEDULER: Emptying the queue
060831 14:37:44 [Note] SCHEDULER: Stopped
060831 14:37:44 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete

060831 14:37:44  mysqld ended

How to repeat:
CRASHED TABLE

Suggested fix:
???
[31 Aug 2006 20:13] Sveta Smirnova
Thank you for the report.

Could you please upload corrupted general_log.CSM, general_log.CSV, general_log.frm, slow_log.CSM, slow_log.CSV, slow_log.frm you can find in mysql directory inside your datadir?
[31 Aug 2006 20:25] Roberto Spadim
o can't cause i clean to start mysql again, next time it get error i will send
(no disk full error ocurring)
[5 Sep 2006 8:12] Sveta Smirnova
OK, Roberto, will wait feedback from you. Also is interesting how you got corrupt these tables. You may set --log-output=TABLE,FILE to have copy of queries in old format logs to indicate what was cause of the problem.
[5 Sep 2006 11:56] Roberto Spadim
hello i will put err.log and mysql folder without user table ;)
[5 Sep 2006 11:58] Roberto Spadim
sorry i will put log-output=TABLE,FILE now
[5 Sep 2006 16:14] Sveta Smirnova
I checked your archive and it does not contain broken tables, isn't it? Please, upload broken tables to we can examine what was broken.
[5 Sep 2006 19:26] Roberto Spadim
i saw that but if i don't delete the files and touch again mysql server don't start
i'm using mysqld_safe script to load mysql server, so the server could never stop just if script die and after server, but it don't occur in my machine cause just i use it
any idea of what is going on?
[5 Sep 2006 19:33] Roberto Spadim
i changed to noncritical cause i don't undestand why mysql is been killed
[5 Sep 2006 19:37] Sveta Smirnova
Roberto, do not delete broken tables. Simple move them out from mysql directory and send us.
[14 Sep 2006 2:33] Roberto Spadim
file with error data dir uploaded
[14 Sep 2006 19:48] Sveta Smirnova
I examined again the error log and found what mysqld stops not immediately after start, but after any hours in some cases. Are you sure corrupted log tables is cause of the crash?

Anyway current mysql 5.1.12-BK repaired log tables after start as you can see from the test error log:

060914 21:24:08  InnoDB: Started; log sequence number 0 53481
libexec/mysqld: Table 'general_log' is marked as crashed and should be repaired
libexec/mysqld: Table 'slow_log' is marked as crashed and should be repaired
060914 21:24:08 [Note] libexec/mysqld: ready for connections.
Version: '5.1.12-beta-debug-log'  socket: '/tmp/mysql.sock'  port: 0  Source distribution
060914 21:24:08 [Note] SCHEDULER: Manager thread booting
060914 21:24:08 [Note] SCHEDULER: Loaded 0 events
060914 21:24:08 [Note] SCHEDULER: Suspending operations
060914 21:43:34 [Note] Got signal 15 to shutdown mysqld
060914 21:43:34 [Note] libexec/mysqld: Normal shutdown

060914 21:43:34 [Note] SCHEDULER: Killing manager thread 1
060914 21:43:34 [Note] SCHEDULER: Waiting the manager thread to reply
060914 21:43:34 [Note] SCHEDULER: Resuming operations
060914 21:43:34 [Note] SCHEDULER: Manager thread started with id 1
060914 21:43:34 [Note] SCHEDULER: Shutting down
060914 21:43:34 [Note] SCHEDULER: Waiting for worker threads to finish
060914 21:43:34 [Note] SCHEDULER: Emptying the queue
060914 21:43:34 [Note] SCHEDULER: Stopped
060914 21:43:35  InnoDB: Starting shutdown...
060914 21:43:38  InnoDB: Shutdown completed; log sequence number 0 61483
060914 21:43:38 [Note] libexec/mysqld: Shutdown complete

060914 21:43:45  InnoDB: Started; log sequence number 0 61483
060914 21:43:45 [Note] libexec/mysqld: ready for connections.
Version: '5.1.12-beta-debug-log'  socket: '/tmp/mysql.sock'  port: 0  Source distribution
060914 21:43:45 [Note] SCHEDULER: Manager thread booting
060914 21:43:45 [Note] SCHEDULER: Loaded 0 events
060914 21:43:45 [Note] SCHEDULER: Suspending operations
060914 21:44:23 [Note] Got signal 15 to shutdown mysqld
060914 21:44:23 [Note] libexec/mysqld: Normal shutdown

060914 21:44:23 [Note] SCHEDULER: Killing manager thread 1
060914 21:44:23 [Note] SCHEDULER: Waiting the manager thread to reply
060914 21:44:23 [Note] SCHEDULER: Resuming operations
060914 21:44:23 [Note] SCHEDULER: Manager thread started with id 1
060914 21:44:23 [Note] SCHEDULER: Shutting down
060914 21:44:23 [Note] SCHEDULER: Waiting for worker threads to finish
060914 21:44:23 [Note] SCHEDULER: Emptying the queue
060914 21:44:23 [Note] SCHEDULER: Stopped
060914 21:44:23  InnoDB: Starting shutdown...
060914 21:44:25  InnoDB: Shutdown completed; log sequence number 0 61483
060914 21:44:25 [Note] libexec/mysqld: Shutdown complete
[14 Sep 2006 19:57] Roberto Spadim
i'm not sure cause if mysqld crash mysqld_safe should make it run again, but when it crash and i run
ps ax | grep mysql

no process is showed
can i run mysql in production use with some error log to crash and log what make it crash? i can run mysql debug? the server is big not very, but have some tables (5 or 6) that have +- 300000 rows and they are used
can i run mysql with debug option? how can i do it?
[21 Sep 2006 6:36] USAF LEE
Description:
060920 15:31:00  mysqld restarted
InnoDB: Error: log file ./ib_logfile0 is of different size 0 5242880 bytes
InnoDB: than specified in the .cnf file 0 268435456 bytes!
060920 15:31:04 [Note] Starting MySQL Cluster Binlog Thread
/usr/sbin/mysqld: Table 'general_log' is marked as crashed and should be repaired
/usr/sbin/mysqld: Woops, blew up opening a mapped file
/usr/sbin/mysqld: Out of memory; check if mysqld or some other process uses all available memory; if not, you may have to use 'ulimit' to allow mysqld to use more memory or you can add more swap space
060920 15:31:04 [ERROR] Failed to initialize log tables. Falling back to the old-fashioned logs
060920 15:31:05 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.11-beta-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
060920 15:31:05 [Note] SCHEDULER: Manager thread booting
060920 15:31:05 [Note] SCHEDULER: Loaded 0 events
060920 15:31:05 [Note] SCHEDULER: Suspending operations
060920 15:31:06 [ERROR] /usr/sbin/mysqld: Table './cluster/binlog_index' is marked as crashed and should be repaired
060920 15:31:06 [Warning] Checking table:   './cluster/binlog_index'
060920 15:31:06 [ERROR] 1 client is using or hasn't closed the table properly
060920 15:31:08 [ERROR] NDB Binlog: logging of table ./promisedata2006/company_setting with BLOB attribute and no PK is not supported
060920 15:31:08 [ERROR] NDB Binlog: FAILED CREATE (DISCOVER) TABLE Event: REPL$promisedata2006/company_setting

What is the error,how to resolve?
[29 Mar 2011 18:43] Roberto Spadim
working without problems now, using mysql 5.5