"The slave is lagging behind"-mystery



  • I have a testing scenario with one dedicated server (6 vCore x 3.6 GHz AMD Ryzen 5 Pro 3600, RAM: 32 GB, HDD: 2 x 1000 GB Software RAID 1 if that matters) and a MySQL (MariaDB) replication setup with 1 master and 2 replicas on the same machine, just to see how it works. For a production setup this does not make too much sense, but for testing it is ok. It may be interesting to note that I do not use the InnoDB engine for this replication scenario.

    The total data managed by MySQL is 109 GB now, but not all databases are run by the master (49 GB) and not all of the master data is replicated (19 GB each). For example there are databases for a mail server and a search engine which are not replicated, the former not even served by the master. The master manages 3 main databases with 87 tables in one database to be replicated and 2 others which are not replicated, as anything in those can be and is regularly recreated.

    I run a cron job mysql_repl_monitor.sh every minute based on http://datacharmer.blogspot.de/2011/04/refactored-again-poor-mans-mysql.html which works fine with the little traffic in testing mode, but I expect this scenario to handle high loads just as well. Sometimes I get errors, which I first tried to catch with specific repair mechanisms, but after a while and some more experience I reckoned that this is not worth the effort so I fall back to another script mysql_rsync_vx_s.sh which brutally syncronizes the replica in trouble with the master via rsync.

    Of course, I have to lock all tables to do this, but rsync may only have to fix some tables which may only take some seconds depending on the size of the files to be different, seldom it takes up to a minute. In order to not get in trouble when it takes more than a minute, I set a semaphore to prevent invoking mysql_rsync_vx_s.sh more than once. I have some very big tables and partitioned some of these, so I can manage the size of the files somehow and this may help rsync as instead of one or two big files it may only have to cope with a bunch of smaller files. So far I didn't take notes about which tables are affected, which is a pity, I admit it. I write a log file but never looked at it except for debugging the script. I just added a permanent log file for rsync to gather this data.

    By far the most frequent error is The slave xx is lagging behind. I guess this accounts for 95% or even more of all errors. Some days I get none, on other days maybe a dozen without me being able to see a reason. Due to my self-repair mechanism this is not fatal, but it still annoys. I experience this behaviour for a long time now and cannot get a hint of what may be the source of this problem. Remember, it happens all on one dedicated machine running a bunch of docker containers.

    mysql_repl_monitor.sh looks at a LAG_THRESHOLD, which was, as far as I remember, originally set to 1000 by data charmer Giuseppe Maxia. I raised it to 14589, but I recorded a difference of 3750449 for $Master_Position-$Read_Master_Log_Pos which seems to signify that this huge surplus difference is built up within a minute, so very fast.

    Every couple of days I take a dump of my 3 databases of about 41 GB as a simple copy of files at a time where those errors do not occur. My machine runs at extreme minimal loads mostly, but even loads of 15 do not trigger this behavior. Often this lagging affects both replicas, but not always. Sometimes it occurs every couple of minutes for a dozen of minutes, but mostly the fix is quick and lasting. I am really puzzled.

    Has anybody an idea of where to look or what to record? I run a log table of all my queries which is reset at intervals, so I could have a look at what is happening if I knew what and when.

    Addendum

    @danblack First Master, then one slave:

    M:1231014 [ci4]>select version();
    +-------------------------------------------+
    | version()                                 |
    +-------------------------------------------+
    | 10.5.10-MariaDB-1:10.5.10+maria~focal-log |
    +-------------------------------------------+
    1 row in set (0.012 sec)
    

    M:1231014 [ci4]>SHOW VARIABLES LIKE 'binl%';
    +-----------------------------------------+--------+
    | Variable_name | Value |
    +-----------------------------------------+--------+
    | binlog_annotate_row_events | ON |
    | binlog_cache_size | 32768 |
    | binlog_checksum | CRC32 |
    | binlog_commit_wait_count | 0 |
    | binlog_commit_wait_usec | 100000 |
    | binlog_direct_non_transactional_updates | OFF |
    | binlog_file_cache_size | 16384 |
    | binlog_format | ROW |
    | binlog_optimize_thread_scheduling | ON |
    | binlog_row_image | FULL |
    | binlog_row_metadata | NO_LOG |
    | binlog_stmt_cache_size | 32768 |
    +-----------------------------------------+--------+
    12 rows in set (0.001 sec)

    I deleted 346 rows with Value OFF, NONE or 0 from the following list

    S:8120528 [ci4]>show global status;
    +-----------------------------------------------+----------------------+
    | Variable_name                                 | Value                |
    +-----------------------------------------------+----------------------+
    | Acl_database_grants                           | 11                   |
    | Acl_proxy_users                               | 2                    |
    | Acl_table_grants                              | 11                   |
    | Acl_users                                     | 23                   |
    | Aria_pagecache_blocks_unused                  | 15647                |
    | Aria_pagecache_blocks_used                    | 13                   |
    | Aria_pagecache_read_requests                  | 48                   |
    | Aria_pagecache_reads                          | 35                   |
    | Aria_pagecache_writes                         | 15                   |
    | Aria_transaction_log_syncs                    | 1                    |
    | Binlog_snapshot_file                          | mysql-bin.001631     |
    | Binlog_snapshot_position                      | 4662                 |
    | Binlog_bytes_written                          | 1620                 |
    | Busy_time                                     | 0.000000             |
    | Bytes_received                                | 46531353094          |
    | Bytes_sent                                    | 34903772             |
    | Com_alter_table                               | 2                    |
    | Com_begin                                     | 389902               |
    | Com_change_db                                 | 11                   |
    | Com_change_master                             | 11                   |
    | Com_commit                                    | 389897               |
    | Com_create_user                               | 1                    |
    | Com_delete                                    | 1052                 |
    | Com_flush                                     | 10                   |
    | Com_grant                                     | 1                    |
    | Com_insert                                    | 39856                |
    | Com_purge_before_date                         | 19                   |
    | Com_reset                                     | 1                    |
    | Com_select                                    | 24                   |
    | Com_set_option                                | 13                   |
    | Com_show_slave_status                         | 12283                |
    | Com_show_status                               | 4                    |
    | Com_start_slave                               | 15                   |
    | Com_stop_slave                                | 14                   |
    | Com_unlock_tables                             | 9                    |
    | Com_update                                    | 348991               |
    | Compression                                   | OFF                  |
    | Connections                                   | 18504                |
    | Cpu_time                                      | 0.000000             |
    | Created_tmp_files                             | 26                   |
    | Created_tmp_tables                            | 2                    |
    | Feature_check_constraint                      | 3                    |
    | Handler_commit                                | 10                   |
    | Handler_delete                                | 1255714              |
    | Handler_icp_attempts                          | 26                   |
    | Handler_icp_match                             | 26                   |
    | Handler_read_first                            | 3                    |
    | Handler_read_key                              | 1604764              |
    | Handler_read_next                             | 339                  |
    | Handler_read_rnd                              | 26                   |
    | Handler_read_rnd_next                         | 503                  |
    | Handler_tmp_write                             | 457                  |
    | Handler_update                                | 348992               |
    | Handler_write                                 | 1237458              |
    | Key_blocks_not_flushed                        | 0                    |
    | Key_blocks_unused                             | 52745                |
    | Key_blocks_used                               | 105613               |
    | Key_blocks_warm                               | 40905                |
    | Key_read_requests                             | 53155707             |
    | Key_reads                                     | 1041728              |
    | Key_write_requests                            | 12641012             |
    | Key_writes                                    | 4407716              |
    | Last_query_cost                               | 0.000000             |
    | Max_used_connections                          | 2                    |
    | Memory_used                                   | 52306256             |
    | Memory_used_initial                           | 33979576             |
    | Open_files                                    | 34                   |
    | Open_table_definitions                        | 11                   |
    | Open_tables                                   | 12                   |
    | Opened_files                                  | 4056                 |
    | Opened_plugin_libraries                       | 2                    |
    | Opened_table_definitions                      | 242                  |
    | Opened_tables                                 | 186                  |
    | Qcache_free_blocks                            | 1                    |
    | Qcache_free_memory                            | 1031304              |
    | Qcache_total_blocks                           | 1                    |
    | Queries                                       | 1195771              |
    | Questions                                     | 24770                |
    | Rows_read                                     | 1605109              |
    | Rows_sent                                     | 503                  |
    | Rows_tmp_read                                 | 454                  |
    | Rpl_semi_sync_master_status                   | OFF                  |
    | Rpl_semi_sync_slave_status                    | OFF                  |
    | Rpl_status                                    | AUTH_MASTER          |
    | Select_scan                                   | 2                    |
    | Slave_heartbeat_period                        | 30.000               |
    | Slave_received_heartbeats                     | 4878                 |
    | Slave_running                                 | ON                   |
    | Slaves_running                                | 1                    |
    | Sort_range                                    | 1                    |
    | Sort_rows                                     | 26                   |
    | Syncs                                         | 4632                 |
    | Table_locks_immediate                         | 786550               |
    | Table_locks_waited                            | 731                  |
    | Table_open_cache_active_instances             | 1                    |
    | Table_open_cache_hits                         | 787177               |
    | Table_open_cache_misses                       | 157832               |
    | Threads_cached                                | 1                    |
    | Threads_connected                             | 1                    |
    | Threads_created                               | 2                    |
    | Threads_running                               | 3                    |
    | Uptime                                        | 736783               |
    | Uptime_since_flush_status                     | 736783               |
    | wsrep_cluster_conf_id                         | 18446744073709551615 |
    | wsrep_cluster_status                          | Disconnected         |
    | wsrep_local_index                             | 18446744073709551615 |
    +-----------------------------------------------+----------------------+
    454 rows in set (0.001 sec)
    

    Which of these values are significant?



  • (I may be one of the few old-timers around who has used MyISAM with replication.)

    "not use the InnoDB" -- Ouch! Especially for such large tables.

    Testing on single server -- Fine. But I suggest encapsulating them in some form of VM, such as Docker, so you can closer simulate the ultimate configuration, which will probably have port 3306 on all servers.

    binlog_do/ignore_... prevents shipping the indicated things out of the Primary. replicate_do/ignore_... tosses the replicated data after it reaches the replica. Do whichever is needed, being aware of the impact on the network.

    Yeah, the rsync script sounds like a sledgehammer, and slow. Even a one-row change in a table might necessitate megabytes of data to be shipped.

    Galera or InnoDB Cluster is a much better way to deal with the possibility of a crashed server. They take care of themselves without scripts like you describe. (Both require InnoDB, not MyISAM.)

    "Sometimes I get errors" -- can't address this without more details. MyISAM will almost always have errors after a power failure. Furthermore, the data can become inconsistent. Both of these issues do not happen with InnoDB.

    There are many reasons for "slave lagging behind". The table locks of MyISAM is one. Long queries is another. (Galera has two techniques for helping with big ALTERs, depending on the details.) There is even a bogus "slave behind" that might actually be fixed soon, after 20!

    "loads of 15" -- Do you mean "Load Average"? That sounds rather bad. But it sounds wrong since Max_used_connections=2. Do you have the slowlog turned on? It probably indicates which queries are being naughty.

    A glance at the STATUS shows a QPS that is very small. And it looks like you have a lot of queries in stored routines? GLOBAL STATUS is only partially useful without a full listing of VARIABLES.

    I'm pretty sure Docker is better than datacharmer's 11-year-old techniques.

    Oh, did I mention that you should switch to InnoDB? More info: http://mysql.rjweb.org/doc.php/myisam2innodb




Suggested Topics

  • 2
  • 2
  • 2
  • 2
  • 2
  • 2
  • 2
  • 2
  • 2
  • 2
  • 2
  • 2
  • 2
  • 2
  • 2