[MDEV-7218] ARIA, “File size bigger than expected” Created: 2014-11-26  Updated: 2018-10-30

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - Aria
Affects Version/s: 5.5.40
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Anthony Lieuallen Assignee: Elena Stepanova
Resolution: Unresolved Votes: 0
Labels: None
Environment:

Gentoo Linux, x64


 Description   

On (only) my production server, whenever I wait a while and restart MariaDB, it completely crashes and burns, e.g.:

141110 16:18:26 [Note] /usr/sbin/mysqld: Shutdown complete
 
141110 16:18:26 [ERROR] mysqld: Got error 'File size bigger than expected' when trying to use aria control file '/var/lib/mysql/aria_log_control'
 
141110 16:18:26 [ERROR] Plugin 'Aria' init function returned error.
 
141110 16:18:26 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
 
141110 16:18:26 InnoDB: The InnoDB memory heap is disabled
 
141110 16:18:26 InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
141110 16:18:26 InnoDB: Compressed tables use zlib 1.2.8
 
141110 16:18:26 InnoDB: Initializing buffer pool, size = 1.0G
 
141110 16:18:26 InnoDB: Completed initialization of buffer pool
 
141110 16:18:26 InnoDB: highest supported file format is Barracuda.
 
141110 16:18:26  InnoDB: Waiting for the background threads to start
 
141110 16:18:27 Percona XtraDB (http://www.percona.com) 5.5.40-MariaDB-36.1 started; log sequence number 18387624831
 
141110 16:18:27 [ERROR] Aria engine is not enabled or did not start. The Aria engine must be enabled to continue as mysqld was configured with --with-aria-tmp-tables
 
141110 16:18:27 [ERROR] Aborting
 
141110 16:18:27  InnoDB: Starting shutdown...
 
141110 16:18:28  InnoDB: Shutdown completed; log sequence number 18387624831
 
141110 16:18:28 [Note] /usr/sbin/mysqld: Shutdown complete

Endlessly. Indeed:

$ ls -l /var/lib/mysql/aria*
 
-rw-rw---- 1 mysql mysql      40960 Nov 10 16:03 /var/lib/mysql/aria_log.00000001
 
-rw-rw---- 1 mysql mysql 2554299001 Nov 10 16:03 /var/lib/mysql/aria_log_control

It's large. I don't use ARIA, at least not on purpose. Apparently it was built with "--with-aria-tmp-tables" and I see no way to control that (at least via Gentoo Ebuild).

Each time this happens, I just sudo rm /var/lib/mysql/aria* and get on with my life. But sometimes it takes me a while to realize it's happened. And I'd prefer it just not happen.

Given, as mentioned, this only happens on my production server, I'd prefer to do as little destructive/interfering diagnostics as possible. Could someone guide me through the best steps to get the right information to diagnose this?

 Comments   
Comment by Elena Stepanova [ 2014-11-26 ]

Hi,

Are there any errors (or anything remotely interesting) in the log during the previous server "session", before the shutdown? Could you please paste that part, too?
I assume you made sure you don't have any system IO errors?

Comment by Anthony Lieuallen [ 2014-11-26 ]

Hi. First, the log:

...
 
141122 13:03:21  InnoDB: Starting shutdown...
 
141122 13:03:23  InnoDB: Shutdown completed; log sequence number 21007208625
 
141122 13:03:23 [Note] /usr/sbin/mysqld: Shutdown complete
 
 
 
141122 13:03:23 InnoDB: The InnoDB memory heap is disabled
 
141122 13:03:23 InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
141122 13:03:23 InnoDB: Compressed tables use zlib 1.2.8
 
141122 13:03:23 InnoDB: Initializing buffer pool, size = 1.0G
 
141122 13:03:23 InnoDB: Completed initialization of buffer pool
 
141122 13:03:23 InnoDB: highest supported file format is Barracuda.
 
141122 13:03:23  InnoDB: Waiting for the background threads to start
 
141122 13:03:24 Percona XtraDB (http://www.percona.com) 5.5.40-MariaDB-36.1 started; log sequence number 21007208625
 
141122 13:03:24 [Note] Server socket created on IP: '127.0.0.1'.
 
141122 13:03:24 [Note] Event Scheduler: Loaded 0 events
 
141122 13:03:24 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '5.5.40-MariaDB-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Source distribution

That's where the current log ends. I.E. no errors (or anything else in the log) over the course of 4 days. The ARIA file is currently:

$ ls -l /var/lib/mysql/aria_log_control
 
-rw-rw---- 1 mysql mysql 203032787 Nov 26 11:00 /var/lib/mysql/aria_log_control

About 200 megs, and 

$ strings /var/lib/mysql/aria_log_control | head -n 10
 
/usr/sbin/mysqld, Version: 5.5.40-MariaDB-log (Source distribution). started with:
 
Tcp port: 0  Unix socket: /var/run/mysqld/mysqld.sock
 
Time                 Id Command    Argument
 
# Time: 141122 13:03:25
 
# User@Host: REDACTED[REDACTED] @ localhost []
 
# Thread_id: 3  Schema: REDACTED  QC_hit: No
 
# Query_time: 0.000542  Lock_time: 0.000383  Rows_sent: 3  Rows_examined: 24
 
use REDACTED;
 
SET timestamp=1416679405;
 
SELECT /* ResourceLoader::preloadModuleInfo  */  md_module,md_deps  FROM `module_deps`   WHERE md_module IN ('mediawiki.legacy.commonPrint','mediawiki.legacy.shared','mediawiki.skinning.interface','mediawiki.special','mediawiki.ui','mediawiki.special.search','mediawiki.ui.button','skins.monobook.styles')  AND md_skin = 'monobook';
 
 
 
$ strings /var/lib/mysql/aria_log_control | tail -n 5
 
# User@Host: REDACTED[REDACTED] @ localhost []
 
# Thread_id: 622092  Schema: REDACTED  QC_hit: No
 
# Query_time: 0.000179  Lock_time: 0.000026  Rows_sent: 19  Rows_examined: 59
 
SET timestamp=1417017688;
 
SELECT /* MessageBlobStore::getFromDB  */  mr_blob,mr_resource,mr_timestamp  FROM `msg_resource`   WHERE mr_resource IN ('jquery.checkboxShiftClick','jquery.hidpi','jquery.highlightText','jquery.makeCollapsible','jquery.mw-jump','jquery.placeholder','jquery.suggestions','mediawiki.action.view.postEdit','mediawiki.api','mediawiki.cldr','mediawiki.hidpi','mediawiki.jqueryMsg','mediawiki.language','mediawiki.searchSuggest','mediawiki.user','mediawiki.language.data','mediawiki.language.init','mediawiki.libs.pluralruleparser','mediawiki.page.ready')  AND mr_lang = 'en';

It's got a bunch of query logs in it? (I ran strings after a hexdump showed mostly text content. This is MediaWiki traffic semi-clearly.) Over the same period. So maybe it's only my prod server because it's the only one getting significant traffic to log.

And if it matters, my.cnf:

[mysql]
 
 
 
# CLIENT #
 
port                           = 3306
 
socket                         = /var/run/mysqld/mysqld.sock
 
 
 
[mysqld]
 
 
 
character-set-server           = utf8
 
skip-external-locking
 
bind-address = 127.0.0.1
 
tmpdir                                          = /tmp/
 
 
 
# GENERAL #
 
user                           = mysql
 
default-storage-engine         = InnoDB
 
socket                         = /var/run/mysqld/mysqld.sock
 
pid-file                       = /var/run/mysqld/mysqld.pid
 
 
 
# MyISAM #
 
key-buffer-size                = 32M
 
myisam-recover                 = FORCE,BACKUP
 
 
 
# SAFETY #
 
max-allowed-packet             = 16M
 
max-connect-errors             = 1000000
 
skip-name-resolve
 
sysdate-is-now                 = 1
 
innodb                         = FORCE
 
innodb-strict-mode             = 1
 
 
 
# DATA STORAGE #
 
datadir                        = /var/lib/mysql/
 
 
 
# CACHES AND LIMITS #
 
tmp-table-size                 = 32M
 
max-heap-table-size            = 32M
 
query-cache-type               = 0
 
query-cache-size               = 0
 
max-connections                = 500
 
thread-cache-size              = 50
 
open-files-limit               = 65535
 
table-definition-cache         = 1024
 
table-open-cache               = 2048
 
 
 
# INNODB #
 
#innodb-flush-method            = O_DIRECT
 
innodb-log-files-in-group      = 2
 
innodb-log-file-size           = 128M
 
innodb-flush-log-at-trx-commit = 1
 
innodb-file-per-table          = 1
 
innodb-buffer-pool-size        = 1G
 
innodb_use_native_aio          = False
 
 
 
# LOGGING #
 
#log-error                      = /var/lib/mysql/mysql-error.log
 
log-error                      = /dev/stdout
 
log-queries-not-using-indexes  = 1
 
slow-query-log                 = 1
 
#slow-query-log-file            = /var/lib/mysql/mysql-slow.log
 
slow-query-log-file            = /dev/stdout

(I run under daemontools, which among other things auto-rotates the log data that it receives via stdin.)

Comment by Elena Stepanova [ 2014-11-26 ]

What you pasted here as a result of 'strings /var/lib/mysql/aria_log_control' is in fact a slow query log.
I see in your config that your slow query log is redirected to /dev/stdout (slow-query-log-file option). I suppose it's possible that due to some magic of further wrappers (mysqld_safe, and/or whatever else is used on Gentoo to run the server) it ends up in aria_log_control.
Is it an intentional setting, and if so, how important is it? Would it be too invasive for your production to set the option to a regular file path/name and check if it makes the aria log control problem go away?

Comment by Anthony Lieuallen [ 2014-11-26 ]

No wrappers are involved, just "exec /usr/sbin/mysqld --user=mysql", in an environment that consumes stdout and routes it to the logger.

I have disabled slow query logging (= 0) for now and I'll report back after it's run for a while to see what happens. In case of problems I'll also try setting particular paths.

Perhaps http://bugs.mysql.com/bug.php?id=57690 is related?

Comment by Elena Stepanova [ 2014-11-26 ]

Possibly it's somehow related, yes. We'll need to look into it, but I suppose the important thing now is to return your production to normal operation.

There is also log-error = dev/stdout in the cnf, so if the error happens again, please (again) check the contents of the aria_log_control file (either the same way via strings, or just try to open it – if it's indeed overridden by slow/error log, then it might be a regular text file). Maybe with the absence of slow log it will get log-error contents.

You can also check the intermediate result right away – aria_log_control should be really tiny, like 52 bytes or so. If it's different (and especially if it's growing), then there is still a problem.

Comment by Anthony Lieuallen [ 2014-11-29 ]

So it's a few days later, and the control file is indeed now still 52 bytes. So I'm changing my config:

$ cd /var/lib/mysql
 
$ sudo ln -fs /dev/stdout mysql-error.log
 
$ sudo ln -fs /dev/stdout mysql-slow.log
 
$ tail -n 5 /etc/mysql/my.cnf
 
# LOGGING #
 
log-error                      = /var/lib/mysql/mysql-error.log
 
log-queries-not-using-indexes  = 1
 
slow-query-log                 = 1
 
slow-query-log-file            = /var/lib/mysql/mysql-slow.log

No dice, the control file is instantly growing. Ok, remove the links so that these logs will go to plain files. Now I can watch the log files grow, and the aria control file stays at 52 bytes.

So apparently the bug is: when the slow query log is enabled and sent to stdout, it ends up in the aria control file instead. The error log will go to stdout correctly. (I've just set it to /dev/stdout in my.cnf again and restarted to confirm.)

Comment by Elena Stepanova [ 2014-11-29 ]

Could you please clarify your last comment a bit?
You quoted a config where both logs are sent to regular files, and then said "No dice, the control file is instantly growing", and then "remove the links so that these logs will go to plain files".
Is there a typo somewhere?
Or do you mean that /var/lib/mysql/mysql-slow.log was actually a link to /dev/stdout?
Or...?

That ignored, I'll dig into /dev/stdout + control file issue as described in the last paragraph.

Comment by Anthony Lieuallen [ 2014-11-29 ]

Yes they were symlinks (see first three lines), this was a trick from some MySQL bug or SO post (can't find it anymore) that I figured was worth giving a shot.

Comment by Elena Stepanova [ 2014-11-29 ]

Sorry, right, I missed those completely. Thanks.

Comment by Elena Stepanova [ 2014-11-29 ]

Could you please paste the output of ls -l /dev/stdout* ?
Thanks.

Comment by Anthony Lieuallen [ 2014-11-29 ] 

$ ls -l /dev/std*
 
lrwxrwxrwx 1 root root 15 Nov 22 06:01 /dev/stderr -> /proc/self/fd/2
 
lrwxrwxrwx 1 root root 15 Nov 22 06:01 /dev/stdin -> /proc/self/fd/0
 
lrwxrwxrwx 1 root root 15 Nov 22 06:01 /dev/stdout -> /proc/self/fd/1

Comment by Elena Stepanova [ 2014-11-29 ]

Interesting, thanks...
It's just that, you said previously:

The error log will go to stdout correctly. (I've just set it to /dev/stdout in my.cnf again and restarted to confirm.)

But it should not work...
As the bug http://bugs.mysql.com/bug.php?id=57690 says, if the file name has no extension, .err is added automatically. Only it's done not by mysqld_safe, but the server itself, and is even documented, e.g. here: http://dev.mysql.com/doc/refman/5.5/en/server-options.html#option_mysqld_log-error (and I indeed observe it being added).
So, your error log should have gone to the file /dev/stdout.err. And if you saw it in the stdout would have meant that there was a link /dev/stdout.err pointing at /dev/stdout. But there is none...

It does not seem directly related to the Aria control problem, just adds some more oddities to the whole thing.

Comment by Daniel Black [ 2015-09-22 ] 

17:05 < mdih> @kolbe, sorry i was wrong, it was just about 800mb
 
...
 
17:45 < danblack> mdih: if possibe on docker ls -la /proc/{pid}/fd is an alternate
 
17:51 < mdih> @danblack: with the command above: got this result: lrwx------ 1 root  root  64 Sep 22 07:49 1 -> /var/lib/mysql/aria_log_control

Comment by Michael Widenius [ 2018-10-30 ]

aria_log_control should never be more than 100 bytes or so (on my machine it's 52 bytes).

The aria_log_control table is opened at start and closed when server stops. It holds the current state of transaction id's for Aria

What has apparently happened is that some thread/code has written to the wrong file descriptor.
Finding out what is in the aria_log_file could help us find where the bug is.

Comment by Daniel Black [ 2018-10-30 ]

> Finding out what is in the aria_log_file could help us find where the bug is.

Above indicates slow query log.

Generated at Thu Feb 08 07:17:54 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.