[MDEV-8746] max_binlog_size was exceeded Created: 2015-09-04  Updated: 2020-12-07  Resolved: 2020-12-07

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.0.21-galera
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Seppo Jaakola
Resolution: Won't Fix Votes: 0
Labels: galera

Issue Links:
Relates
relates to MDEV-8734 mysqlbinlog --start-position isn't bi... Closed
relates to MDEV-9960 Binary log not rotating Closed
relates to MDEV-11610 Logrotate to only FLUSH LOCAL ERROR L... Closed

 Description   

This was a galera node acting as an async sync slave to another non-galera server. This server had log-slave-updates enabled.

The slave status before the start:

MariaDB [(none)]> show slave status\G
 
*************************** 1. row ***************************
 
               Slave_IO_State: Waiting for master to send event
 
                  Master_Host: localhost
 
                  Master_User: replication
 
                  Master_Port: 63306
 
                Connect_Retry: 60
 
              Master_Log_File: mysql-bin.034995
 
          Read_Master_Log_Pos: 51689463
 
               Relay_Log_File: mysqld-relay-bin.000201
 
                Relay_Log_Pos: 53798956
 
        Relay_Master_Log_File: mysql-bin.034775
 
             Slave_IO_Running: Yes
 
            Slave_SQL_Running: No
 
              Replicate_Do_DB:
 
          Replicate_Ignore_DB:
 
           Replicate_Do_Table:
 
       Replicate_Ignore_Table:
 
      Replicate_Wild_Do_Table:
 
  Replicate_Wild_Ignore_Table:
 
                   Last_Errno: 0
 
                   Last_Error:
 
                 Skip_Counter: 0
 
          Exec_Master_Log_Pos: 53798665
 
              Relay_Log_Space: 22683519000
 
              Until_Condition: None
 
               Until_Log_File:
 
                Until_Log_Pos: 0
 
           Master_SSL_Allowed: No
 
           Master_SSL_CA_File:
 
           Master_SSL_CA_Path:
 
              Master_SSL_Cert:
 
            Master_SSL_Cipher:
 
               Master_SSL_Key:
 
        Seconds_Behind_Master: NULL
 
Master_SSL_Verify_Server_Cert: No
 
                Last_IO_Errno: 0
 
                Last_IO_Error:
 
               Last_SQL_Errno: 0
 
               Last_SQL_Error:
 
  Replicate_Ignore_Server_Ids:
 
             Master_Server_Id: 9
 
               Master_SSL_Crl:
 
           Master_SSL_Crlpath:
 
                   Using_Gtid: No
 
                  Gtid_IO_Pos:
 
1 row in set (0.00 sec)

It was started with:

start slave sql_thread until RELAY_LOG_FILE = 'mysqld-relay-bin.000837', RELAY_LOG_POS = 0;

636 relay log files is quite large amount so I'm assuming the limit is bypassed for this UNTIL RELAY_LOG_FILE options to start slave.

Seems the limit got exceeded in the binary logs

| max_binlog_size                          | 104857600            |
 
 
 
-rw-rw---- 1 mysql mysql   107362623 Aug 28 13:13 mysql-bin.000057
 
-rw-rw---- 1 mysql mysql   104866589 Aug 28 13:13 mysql-bin.000058
 
-rw-rw---- 1 mysql mysql   105813602 Aug 28 13:14 mysql-bin.000059
 
-rw-rw---- 1 mysql mysql   105470582 Aug 28 13:14 mysql-bin.000060
 
-rw-rw---- 1 mysql mysql 35721262759 Sep  3 12:30 mysql-bin.000061
 
-rw-rw---- 1 mysql mysql        1952 Aug 28 13:14 mysql-bin.index
 
 
 
 mysql]# tail  mysql-bin.index
 
/var/lib/mysql/mysql-bin.000052
 
/var/lib/mysql/mysql-bin.000053
 
/var/lib/mysql/mysql-bin.000054
 
/var/lib/mysql/mysql-bin.000055
 
/var/lib/mysql/mysql-bin.000056
 
/var/lib/mysql/mysql-bin.000057
 
/var/lib/mysql/mysql-bin.000058
 
/var/lib/mysql/mysql-bin.000059
 
/var/lib/mysql/mysql-bin.000060
 
/var/lib/mysql/mysql-bin.000061



 Comments   
Comment by Elena Stepanova [ 2015-09-04 ]

danblack,

Are you using parallel slave or any other non-default replication related options?
Could you please provide the cnf file from the slave?

Comment by Daniel Black [ 2015-09-04 ]

normal async slave, parallel thread setting exists though ra and not in gtid mode.

# Server settings.
 
[mysqld_safe]
 
 
 
open_files_limit        = 65536
 
 
 
[mysqld]
 
 
 
#-----------------
 
# System settings.
 
#-----------------
 
user                            = mysql
 
pid-file                        = /var/lib/mysql/mysqld.pid
 
socket                          = /var/lib/mysql/mysql.sock
 
datadir                         = /var/lib/mysql
 
port                            = 3306
 
basedir                         = /usr
 
tmpdir                          = /tmp
 
slave_load_tmpdir               = /tmp
 
 
 
character_set_server            = utf8
 
collation_server                = utf8_general_ci
 
 
 
max_error_count                 = 65535
 
 
 
default_storage_engine          = InnoDB
 
sql_mode                        = NO_ENGINE_SUBSTITUTION
 
 
 
#---------------------------------
 
# Connections
 
#--------------------------------
 
 
 
max_connections                 = 600
 
 
 
thread_cache_size               = 600
 
skip_name_resolve
 
 
 
#---------------------------------
 
# Performance and cache settings.
 
#--------------------------------
 
sort_buffer_size                = 8M
 
bulk_insert_buffer_size         = 16M
 
max_allowed_packet              = 64M
 
 
 
wait_timeout                    = 600
 
open-files-limit                = 40000
 
 
 
table_cache                     = 3000
 
table_definition_cache          = 6000
 
 
 
tmp_table_size                  = 32M
 
max_heap_table_size             = 32M
 
 
 
query_cache_limit               = 128K
 
query_cache_size                = 64M
 
query_cache_strip_comments=ON
 
 
 
#-----------------
 
# Query Planner
 
#-----------------
 
 
 
use_stat_tables                 = complementary
 
histogram_size                  = 255
 
join_cache_level                = 8
 
optimizer_use_condition_selectivity     =4
 
optimizer_switch                = mrr=on,mrr_sort_keys=on,optimize_join_buffer_size=on
 
 
 
#-----------------
 
# MyISAM settings.
 
#-----------------
 
myisam_sort_buffer_size         = 512M
 
myisam_recover                  = QUICK,BACKUP
 
key_buffer_size                 = 128M
 
concurrent_insert               = 2
 
read_buffer_size                = 8M
 
read_rnd_buffer_size            = 1M
 
 
 
#-----------------
 
# InnoDB settings.
 
#-----------------
 
innodb_data_file_path           = ibdata1:100M:autoextend
 
innodb_file_format              = Barracuda
 
 
 
innodb_log_files_in_group       = 8
 
innodb_log_file_size            = 64M
 
innodb_log_buffer_size          = 16M
 
innodb_buffer_pool_instances    = 1
 
innodb_buffer_pool_size         = 12G
 
innodb_max_dirty_pages_pct      = 70
 
innodb_adaptive_flushing        = 1
 
innodb-buffer-pool-dump-at-shutdown = 1
 
innodb-buffer-pool-load-at-startup  = 1
 
innodb_io_capacity        = 2000
 
innodb_read_io_threads          = 8
 
innodb_write_io_threads         = 8
 
innodb_flush_log_at_trx_commit  = 1
 
innodb_flush_method             = O_DIRECT
 
innodb_use_native_aio           = 0
 
innodb_file_per_table           = 1
 
innodb_open_files               = 5000
 
 
 
innodb_stats_traditional        = false
 
 
 
#-------------------
 
# Logging settings.
 
#-------------------
 
log-error                       = /var/log/mysql/error.log
 
log_warnings                    = 2
 
 
 
slow_query_log_file             = /var/log/mysql/slow.log
 
slow_query_log                 = 1
 
long_query_time                 = 1
 
min_examined_row_limit          = 10000
 
log_slow_verbosity              = query_plan,innodb,explain
 
log_queries-not_using_indexes
 
log_slow_admin_statements
 
log_slow_slave_statements
 
 
 
#-------------
 
# Binary Log
 
#-------------
 
 
 
log_bin                         = /var/lib/mysql/mysql-bin
 
sync_binlog                     = 1
 
expire_logs_days                = 3
 
max_binlog_size                 = 100M
 
binlog_format                   = ROW
 
 
 
binlog_checksum = CRC32
 
master_verify_checksum     = 1
 
 
 
binlog_annotate_row_events      = ON
 
replicate_annotate_row_events   = ON
 
 
 
 
 
#-------------
 
# Replication Client
 
#-------------
 
 
 
skip-slave-start
 
log-slave-updates
 
slave-parallel-threads          = 20
 
slave_transaction_retries       = 20
 
slave-skip-errors               = all
 
 
 
server-id=1011
 
 
 
#---------------
 
# Galera Options
 
#---------------
 
 
 
[galera]
 
wsrep_cluster_name = beta
 
wsrep_provider=/usr/lib64/galera/libgalera_smm.so
 
wsrep_cluster_address = gcomm://10.131.27.5:4567,10.131.27.69:4567?pc.wait_prim=no
 
#,10.131.27.6:4567,10.131.27.70:4567,10.131.27.7:4567,10.131.27.71:4567?pc.wait_prim=no
 
#wsrep_sst_method = rsync
 
wsrep_sst_method = xtrabackup-v2
 
wsrep_sst_auth = root:XXXX
 
wsrep_slave_threads = 64
 
wsrep_provider_options='gcache.size=25G;repl.commit_order=1;cert.log_conflicts=1;gcs.fc_limit=1024;repl.key_format=FLAT16A'
 
 
 
wsrep_retry_autocommit = 4
 
 
 
innodb_autoinc_lock_mode=2
 
innodb_locks_unsafe_for_binlog=1

Comment by Elena Stepanova [ 2015-09-04 ]

nirbhay_c,

I'm not getting it right away with the "normal" server, could you please take a look to see if it can be galera-specific?

Comment by Daniel Black [ 2015-09-04 ]

fyi running now with a straight "start slave" and the max_binlog_size is being respected.

-rw-rw---- 1 mysql mysql 104878797 Sep  4 22:58 mysql-bin.000107
 
-rw-rw---- 1 mysql mysql 104871195 Sep  4 23:01 mysql-bin.000108
 
-rw-rw---- 1 mysql mysql 104865248 Sep  4 23:04 mysql-bin.000109
 
-rw-rw---- 1 mysql mysql 105048814 Sep  4 23:05 mysql-bin.000110
 
-rw-rw---- 1 mysql mysql 104885255 Sep  4 23:06 mysql-bin.000111
 
-rw-rw---- 1 mysql mysql 104865257 Sep  4 23:07 mysql-bin.000112
 
-rw-rw---- 1 mysql mysql  97487026 Sep  4 23:09 mysql-bin.000113

Have only changed sst method open-file-limit and slave-skip-errors = all (work around from MDEV-8744 - the highest pri for me).

Comment by Elena Stepanova [ 2015-09-04 ]

Yes, I tried with until RELAY_LOG_FILE <...> RELAY_LOG_POS = 0, although it's no guarantee, maybe there is some specific set of circumstances that triggers it, e.g. to make it faster i tried to reproduce using non-default max_binlog_size=4096 and max_relay_log_size=4096, while maybe it only happens when values are set to hard max (1G), and so on, there can be various "maybe"s. But it's also possible that it's somehow related to wsrep-specific code, so it's worth checking.

Comment by Daniel Black [ 2015-09-25 ]

As pointed out by MG a master with mixed replication may record a binlog as statement however when hitting a binlog_format=ROW its always recorded in the binlog on the slave as a row based event. It seems splitting row based binlog events over multiple files isn't implemented hence getting a larger binlog than the max_binlog_size. It seems is parallel slave operations where in effect multiple versions of these could occur in the same group commit further increasing the size.

| max_binlog_size          | 104857600 |
 
| max_relay_log_size       | 104857600 |
 
 
 
# ls -la mysql-bin.* | more
 
-rw-rw---- 1 mysql mysql 104866493 Sep 25 10:42 mysql-bin.000760
 
-rw-rw---- 1 mysql mysql 104968119 Sep 25 10:43 mysql-bin.000761
 
-rw-rw---- 1 mysql mysql 130866348 Sep 25 10:44 mysql-bin.000762
 
-rw-rw---- 1 mysql mysql 104918131 Sep 25 10:46 mysql-bin.000763
 
-rw-rw---- 1 mysql mysql 104858385 Sep 25 10:47 mysql-bin.000764
 
-rw-rw---- 1 mysql mysql 104874296 Sep 25 10:48 mysql-bin.000765
 
 
 
mysqlbinlog -v mysql-bin.000762 | grep '^#[^#]' | tail -n 4000
 
 
 
#150914 21:00:29 server id 8  end_log_pos 101043363 CRC32 0xd9af389d    Table_map: `video_ugc`.`user_progress_ugc` mapped to number 79
 
#150914 21:00:29 server id 8  end_log_pos 101043559 CRC32 0x082395f7    Update_rows: table id 79 flags: STMT_END_F
 
# at 101043559
 
#150914 21:00:29 server id 8  end_log_pos 101043590 CRC32 0x8ea98410    Xid = 37532706
 
# at 101043590
 
#150914 21:00:13 server id 8  end_log_pos 101043634 CRC32 0x25c1cb0f    GTID 0-8-1533469209 cid=69553706
 
# at 101043634
 
# at 101043706
 
# at 101151443
 
# at 101699590
 
# at 101802058
 
# at 102299625
 
# at 102402093
 
# at 102899663
 
# at 103007400
 
# at 103555555
 
# at 103658023
 
# at 104155582
 
# at 104258050
 
# at 104755621
 
...
 
# at 110476694
 
# at 110477879
 
# at 110581102
 
# at 110600083
 
# at 110617273
 
# at 110624777
 
# at 110641967
 
# at 110649471
 
# at 110684588
 
# at 110921252
 
# at 111018052
 
# at 111457692
 
# at 111555179
 
# at 111993751
 
...
 
# at 115696789
 
# at 115793824
 
# at 116241642
 
# at 116362609
 
# at 116537696
 
# at 116541043
 
# at 116542228
 
# at 116639263
 
..
 
# at 130307157
 
# at 130405243
 
#150914 21:00:13 server id 8  end_log_pos 101043706 CRC32 0x9b2f63b8    Table_map: `drupal_home_prod`.`cache_form` mapped to number 545
 
#150914 21:00:13 server id 8  end_log_pos 101151443 CRC32 0x2d7f5607    Delete_rows: table id 545
 
#150914 21:00:13 server id 8  end_log_pos 101699590 CRC32 0x78322403    Delete_rows: table id 545
 
...
 
#150914 21:00:13 server id 8  end_log_pos 130405243 CRC32 0x1f5b010a    Delete_rows: table id 545
 
#150914 21:00:13 server id 8  end_log_pos 130865968 CRC32 0xdaf57add    Delete_rows: table id 545 flags: STMT_END_F
 
# at 130865968
 
#150914 21:00:13 server id 8  end_log_pos 130865999 CRC32 0x624f85d7    Xid = 37532708
 
# at 130865999
 
#150914 21:00:28 server id 8  end_log_pos 130866043 CRC32 0x1ec9a4fd    GTID 0-8-1533469210 cid=69553706
 
# at 130866043
 
# at 130866124
 
#150914 21:00:28 server id 8  end_log_pos 130866124 CRC32 0xd3fc4aaa    Table_map: `singlesignon`.`device_sessions` mapped to number 80
 
#150914 21:00:28 server id 8  end_log_pos 130866270 CRC32 0x6ee8413d    Write_rows: table id 80 flags: STMT_END_F
 
# at 130866270
 
#150914 21:00:28 server id 8  end_log_pos 130866301 CRC32 0xf53bf2cd    Xid = 37532698
 
# at 130866301
 
#150914 21:00:13 server id 1011  end_log_pos 130866348 CRC32 0xcaa1803e         Rotate to mysql-bin.000763  pos: 4
 
# End of log file

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