MySQL Bugs: #82394: Frequent "Out of event buffer" messages after upgrade to MySQL Cluster 7.4.11

Bug #82394	Frequent "Out of event buffer" messages after upgrade to MySQL Cluster 7.4.11
Submitted:	1 Aug 2016 8:24	Modified:	18 Oct 2016 8:53
Reporter:	Daniel Cornak	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Cluster: NDB API	Severity:	S3 (Non-critical)
Version:	5.6.29-ndb-7.4.11-cluster-gpl-log	OS:	SUSE (SUSE Linux Enterprise Server 11 (x86_64))
Assigned to:	MySQL Verification Team	CPU Architecture:	Any

Description:
We have Upgraded MySQL cluster from 7.2.19 to 7.4.11 version.
Since then, we have following lines (really frequently) in ndb_init.log (3 times every 1 second).

2016-07-29 11:49:43 [MgmtSrvr] INFO -- Node 12: Out of event buffer: nodefailure will cause event failures, consider increasing MaxBufferedEpoc
2016-07-29 11:49:43 [MgmtSrvr] INFO -- Node 12: Highest epoch 188683045799198722, oldest epoch 188683045799198722
2016-07-29 11:49:43 [MgmtSrvr] INFO -- Node 12: Pending nodes '0000000000000000000000000000000000000000000000000000000001800000', epoch 1886830
2016-07-29 11:49:43 [MgmtSrvr] INFO -- Node 12: Reenable event buffer

No others messages or problems in logs.
Database and cluster itself running withour problems.
We have already increased MaxBufferedEpochBytes + MaxBufferedEpochs to max 100000 but it doesn't help.

How to repeat:
Upgrade to 7.4.11 version

ndb error report

Attachment: ndb_error_report_20160801103251.7z (application/octet-stream, text), 2.98 MiB.

Same Behaviour after downgrade to 7.4.10 version !

ndb_config --config-file=/var/lib/mysql-cluster/config.ini node=24 --fields='\'' '\'' --rows='\''\n'\'' --query=id,type,MaxBufferedEpochs,MaxBufferedEpochBytes

2016-08-01 12:50:23 [ndb_config] WARNING  -- at line 24: [DB] DiskCheckpointspeedinrestart is deprecated, use Maximum bytes per second allowed to be written by checkpointsduring restarts instead
2016-08-01 12:50:23 [ndb_config] WARNING  -- at line 25: [DB] DiskCheckpointSpeed is deprecated, use Minimum bytes per second allowed to be written by checkpoint instead
1 ndb_mgmd
2 ndb_mgmd
23 mysqld
24 mysqld
12 ndbd 100000 262144000
14 ndbd 100000 262144000

Hi,

I doubt this is a bug.

Your log show that your mysqld nodes 23 and 24 are lagging. Why they lag I can't say but you should check load on sql servers. Also I'd suggest you add few more api slots in your config and make sure ndb-cluster-connection-pool is > 1 and that you have enough slots for sql nodes to fit ndb-cluster-connection-pool number of connections from each sql nodes.

Restarting those nodes would clear the log but can't say for how long.

Reducing MaxBufferedEpochs could also help

Going further you should really consider getting a support contract as then we should go trough your server details and get all this ironed out.

MaxBufferedEpochs is in-place to avoid excessive event buffering in the data nodes, if it is exceeded, then lagging API nodes are disconnected. This is a self-protection mechanism to remove laggards. Setting this to 100,000 is effectively disabling it, so that laggards have on average 100,000 * 100 millis = 2.7 hours to acknowledge receipt of an epoch before they are disconnected...

MaxBufferedEpochBytes sets the max size of the data node buffering, after which data is no longer buffered. Note that when the max is reached, subscribing APIs are *not* disconnected. Note also that the maximum value here is MAX_INT_RNIL (0xffff0000 / 4,294,901,760).

So probably what is happening is :
1. Some API node(s) are lagging for some reason / the rate of change is high
2. The MaxBufferedEpochBytes (256M) is exceeded, so many error messages
3. The MaxBufferedEpochs is not yet reached, so no client disconnections.

kind regards
Bogdan Kecman

Hi,

We have tried to use 7.4.10 and also 7.4.12 version, but having same behaviour.
Each 1 second we have additional 40 rows in ndb_init.log (messages below are repeating continuously):

=========================================================================================================================
...

2016-08-16 11:51:00 [MgmtSrvr] INFO     -- Node 14: Reenable event buffer
2016-08-16 11:51:01 [MgmtSrvr] INFO     -- Node 12: Reenable event buffer
2016-08-16 11:51:01 [MgmtSrvr] INFO     -- Node 14: Reenable event buffer
2016-08-16 11:51:01 [MgmtSrvr] INFO     -- Node 12: Out of event buffer: nodefailure will cause event failures, consider increasing MaxBufferedEpoc
2016-08-16 11:51:01 [MgmtSrvr] INFO     -- Node 12: Highest epoch 191912985759842315, oldest epoch 191912985759842315
2016-08-16 11:51:01 [MgmtSrvr] INFO     -- Node 12: Pending nodes '0000000000000000000000000000000000000000000000000000000001800000', epoch 1919129
2016-08-16 11:51:01 [MgmtSrvr] INFO     -- Node 12: Reenable event buffer
2016-08-16 11:51:01 [MgmtSrvr] INFO     -- Node 14: Out of event buffer: nodefailure will cause event failures, consider increasing MaxBufferedEpoc
2016-08-16 11:51:01 [MgmtSrvr] INFO     -- Node 14: Highest epoch 191912985759842315, oldest epoch 191912985759842315
2016-08-16 11:51:01 [MgmtSrvr] INFO     -- Node 14: Pending nodes '0000000000000000000000000000000000000000000000000000000001800000', epoch 1919129

...

=========================================================================================================================

What can we do further ? 
We have also decreased MaxBufferedEpochs to 1000, and increased MaxBufferedEpochBytes to its max value 4294967039.

What have you meant with getting support contract ? 
We already have contract either with Oracle either with Mariadb support.

Thanks a lot

Best Regards
Daniel

This looks like another case where this warning suddenly showed up after an upgrade without any apparent change of the load pattern, this time when upgrading from 7.2.x to 7.3.x:

http://forums.mysql.com/read.php?25,591468,591468#msg-591468

"Reducing MaxBufferedEpochs could also help"

Unfortunately the error message text seems to suggest the opposite. It actually suggests to raise MaxBufferedEpochBytes, not MaxBufferedEpochs, but gets mangled by truncation:

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

Also the next line suggest that number of epochs isn't an issue:

  Highest epoch 188683045799198722, oldest epoch 188683045799198722

although it is not clear whether highest and oldest refer to buffered Epochs here, or some other Epoch count ...?

The epoch number in the next line might shed light on this, but unfortunately it is subject to truncation, too :(

  Pending nodes '0000[...]00001800000', epoch 1886830

Hi Daniel,

> We have tried to use 7.4.10 and also 7.4.12 version, but having same behaviour.

I doubt new version will change anything as I said I doubt this is a bug and our dev team doubts it also.

> Each 1 second we have additional 40 rows in ndb_init.log 
> (messages below are repeating continuously):

this is a bug (Hartmut reported, I verified, migrated... ) that logs are filled this much but it's not very high priority bug so ..

> What have you meant with getting support contract ? 

As I said, you should figure out why your sql nodes are lagging. This investigation is part of support process not part of bug report process so whoever you have support contract with, you open ticket there and go about solving the situation. I suggest you test turning off binlogging, adding a new sql node that's not loaded etc .. to see how things will behave, as from the log it's visible that nodes 23 and 24 are lagging behind. Checking io and cpu load on those nodes etc etc... your support engineer will surely know what to do. 

The two mentioned bugs (the overflowing log and the truncation of the messages) are making figuring out what's in the log harder for sure.. but are not making this report a bug too..

> Unfortunately the error message text seems to suggest the opposite.

Hey Hartmut :) 
YES, the message is suggesting the opposite, as we know it's being truncated.

After talking to Frazer this "reduction" is suggested as here your client is hitting MaxBufferedEpochBytes before MaxBufferedEpochs so instead of increasing MaxBufferedEpochBytes (as error message is universally advising) and allowing it to lag even more I suggested reducing MaxBufferedEpochs so that it's hit before MaxBufferedEpochBytes. 

So if you follow my chain of thought hitting MaxBufferedEpochs should at least show exactly where the problem is ... it might lead to few api node reconnections and then "settle down" or it might lead to constant api node reconnects which means api nodes are improperly sized (or that we have another bug somewhere..)

makes any sense to you?

take care
bogdan

This has been reproduced now by the following steps:

* take mysqldump of 7.4.x installation

* set up a fresh 7.2.x cluster, import data from mysql dump

  -> no "out of event buffer" messages seen

* upgrade cluster to 7.4.x

  -> "out of event buffer" messages seen again, even though there aren't any clients connected to the API nodes yet

So "you should figure out why your sql nodes are lagging" doesn't really make sense here ...

Unfortunately the mysqldump can't be shared ...

we did following:

1. Downgrade Cluster to version 7.2.19 using mysqldump and complete SHUTDOWN of Cluster.

- this time we started ndb managment with multithreads:
/usr/sbin/ndbmtd --initial

After that we had NO MORE "Out of event buffer" messages coming into logs.

2. Then we have upgraded again to 7.4.12 version:

- Messages "Out of event buffer" came AGAIN into our logs.

During whole procedure was application stopped, so no load or proceeses were running at that time.

3. So finally we downgraded Cluster back to 7.2.19 version.

- Now we are running Cluster without any errors.

So now we are sure:
- that we have such a behaviour only in 7.4.* versions.
- it is not related to load or processes running in database

Hi,

Last few notes are confusing me sorry. Are you saying that you load your DB into blank 7.4 and without any clients hitting the cluster, just your data nodes and your mgm nodes and your api/sql nodes ... no clients, noone doing inserts/updates/deletes/selects .. and your log is filled with "out of events" message? 'cause that's how I read your last few messages and that makes no sense at all?

@Hartmut, discussed for a while with Frazer, none of them seen it on 7.4 and he's pretty sure it's hitting the sql node "a lot" ... 

By any chance some FK's in that sqldump?

all best
Bogdan

Hallo Bogdan,

Thanks for your comments.
To you questions:

1. ...no clients, noone doing inserts/updates/deletes/selects .. and your log is filled with "out of events" message?
> Yes, for me it doesn't make a sense either. Or I am missing something at all ...

During whole downgrade/upgrade, application was shutdown so nothing were connected (also "show processlist" listed nothing at that time). Our application collaegues started all applications after it.

2. We do not have FK's in the cluster, as it's in fact still 7.2 version.

Regards
Daniel

Hi Bogdan,

a "blind educated guess" idea:

could node upgrades maybe generate change events themselves while migrating data? And so flood and overflow buffers even though there are no actual API-node initiated data changes at all?

This could probably be tested by not having the SQL nodes up at all
during the rolling upgrade of data nodes? 

Does this make some sort of sense, or am I totally of track with this?

Hi Daniel,

> During whole downgrade/upgrade, application was shutdown 
> so nothing were connected (also "show processlist" listed 
> nothing at that time). Our application collaegues started 
> all applications after it.

and the logs fill indefinitely with this ?!

as for FK's, you can execute FK's on 7.2 it will just ignore it, so if you by some chance / history artifact, have FK's in your db model, 7.2 would ignore them while 7.4 could behave weirdly

Hi Hartmut,

> This could probably be tested by not having the SQL nodes
> up at all during the rolling upgrade of data nodes? 

Does it make sense, at the moment nothing in this bug makes sense really so I'd try this. But the problem is - when I use "normal" database model I don't have this problem so I can't try this, only you can try as you have customer's database.

What I'd also try is.
 - setup clean 7.2
 - create and fill table1 trough n/2
 - upgrade to 7.4
 - if it does not fail, repeat from scratch but with tablen/2+1 - tablen
 etc etc ... so try to find the smallest number of tables necesary to reproduce the problem, as this most probably is a bug and it's a bug with "something" wrt data model IMO that's raking havoc with 7.4 ..  

all best
bogdan

Hi Bogdan,

Thank you for your comments.
To your first question:
and the logs fill indefinitely with this ?!
> Yes, messages were filling up the logs several times in second.
  Even there were zero loading or accesing.

I will try now to rebuild Cluster from the scratch, but this time also with "fresh" datadir using mysqldump ( so no rolling method). Then, if problem won't disapear, I will do it as you propose, step by step uploading tables in sequence.
Will let you know the results.

Best Regards
Daniel

I hope we solved it.

We did last Friday upgrade to 7.4.12 version, first with rolling fashion and then by building up the new cluster from the scratch.
We had always those messages again and again. But that made no sense because we had exactly same Test clone system with same data's and without failures.
So we started to play with all parameters and finally we have figured it out.

We had too small Memory(free) on the system !
In details original state before changes:
# top
Mem:   4057004k total,  3002956k used,  1054048k free,    92672k buffers

# grep Memory config.ini

DataMemory    = 2000MB
IndexMemory   = 400MB

 
When we have changed DataMemory and IndexMemory to smaller values:
DataMemory    = 1000MB
IndexMemory   = 100MB
and started managment nodes with --skip-config-cache, messages disapeared.
From some reason this leak of memory doesn't matter for 7.2 version, 
but once you have new 7.4. version then it is complaining with "Out of event buffer" messages.

Please let me know how and with what conclusion we could close this Bug Report.

Best Regards
Daniel

Hi Daniel,

it would make sense if your system was swapping with original settings. Whether 7.4 use bit more resources then 7.2, well it does, it's expected, it have lot more features, but we are talking about fairly small changes.. Furthermore if you are using ndbmtd the config values are using bit more ram then on 7.2 and especially ndbd.

What I see is you were using 2G datadir and dropped to 1G .. it's a fairly small amount of RAM for a datanode (you have 4G in total) .. I was not expecting that. So while we do have few related bugs (how that log is filling up, how the lines are truncated..) this I'll close with "not a bug" (as it's actually just a missconfiguration) and leave you in capable Hartmut's hands configuring that system properly.

take care
Bogdan

Hi Bogdan,

Yes you're right, it's not a bug but leak of resources in our case.
I already did all changes and will know in next environments where to focus in such a behaviour.

Best Regards
Daniel

Looks as if those "capable hands" have failed ... we can see the same effect on another instance upgraded to 7.4.x now, and the data nodes clearly still have more than 1GB of free RAM, with ndbmtd fully in memory and no swap space used at all yet, and Data/IndexMemory at even with the lowered memory sizes (1GB Data, 256M Index memory, 4GB machine, ~1GB memory still free, zero swapped used, ndbmtd completely in memory):

2016-12-13 09:28:10 [MgmtSrvr] INFO -- Node 12: Data usage is 11%(3726 32K pages of total 32000)
2016-12-13 09:28:10 [MgmtSrvr] INFO -- Node 12: Index usage is 5%(1786 8K pages of total 32064)

top - 10:55:46 up 22:07, 3 users, load average: 0.57, 0.45, 0.36
Tasks: 88 total, 1 running, 87 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.9%us, 1.7%sy, 0.0%ni, 96.9%id, 0.0%wa, 0.0%hi, 0.5%si, 0.0%st
Mem: 3862960k total, 2429168k used, 1433792k free, 44972k buffers
Swap: 2096476k total, 0k used, 2096476k free, 380736k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2540 root 20 0 1871m 1.8g 3700 S 5 48.6 59:54.06 ndbmtd