Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-10222

When replication starts, slave reports seconds_behind_master 0 for a few seconds

    XMLWordPrintable

Details

    Description

      After performing maintenance for a few hours on a host, I start replication again on a 10.0.23 host and execute SHOW SLAVE STATUS;

      In the time it takes me to write manually on console START SLAVE; <ENTER> SHOW SLAVE STATUS\G, it shows me once: Seconds_Behind_Master: 0 (not NULL) even if some queries have been already executed by the SQL thread (see SQL executed), as you can see on the following output:

      Welcome to the MariaDB monitor.  Commands end with ; or \g.
      Your MariaDB connection id is 7
      Server version: 10.0.23-MariaDB-log MariaDB Server
       
      Copyright (c) 2000, 2015, Oracle, MariaDB Corporation Ab and others.
       
      Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
       
      MariaDB PRODUCTION s1 localhost (none) > SHOW SLAVE STATUS\G
      *************************** 1. row ***************************
                     Slave_IO_State:
                        Master_Host: db1057.eqiad.wmnet
                        Master_User: repl
                        Master_Port: 3306
                      Connect_Retry: 60
                    Master_Log_File: db1057-bin.002176
                Read_Master_Log_Pos: 730476185
                     Relay_Log_File: db1052-relay-bin.000334
                      Relay_Log_Pos: 730476473
              Relay_Master_Log_File: db1057-bin.002176
                   Slave_IO_Running: No
                  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: 730476185
                    Relay_Log_Space: 730477082
                    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
      1 row in set (0.00 sec)
       
      MariaDB PRODUCTION s1 localhost (none) > START SLAVE;
      Query OK, 0 rows affected (0.01 sec)
       
      MariaDB PRODUCTION s1 localhost (none) > SHOW SLAVE STATUS\G
      *************************** 1. row ***************************
                     Slave_IO_State: Waiting for master to send event
                        Master_Host: db1057.eqiad.wmnet
                        Master_User: repl
                        Master_Port: 3306
                      Connect_Retry: 60
                    Master_Log_File: db1057-bin.002176
                Read_Master_Log_Pos: 730476185 
                     Relay_Log_File: db1052-relay-bin.000001
                      Relay_Log_Pos: 4
              Relay_Master_Log_File: db1057-bin.002176
                   Slave_IO_Running: Yes
                  Slave_SQL_Running: Yes
                    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: 730476185 
                    Relay_Log_Space: 248
                    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: 0
      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: 171974683 
                     Master_SSL_Crl:
                 Master_SSL_Crlpath:
                         Using_Gtid: Slave_Pos 
                        Gtid_IO_Pos: 0-171974683-4085514800
      1 row in set (0.00 sec)
       
      MariaDB PRODUCTION s1 localhost (none) > SHOW SLAVE STATUS\G
      *************************** 1. row ***************************
                     Slave_IO_State: Queueing master event to the relay log
                        Master_Host: db1057.eqiad.wmnet
                        Master_User: repl
                        Master_Port: 3306
                      Connect_Retry: 60
                    Master_Log_File: db1057-bin.002177
                Read_Master_Log_Pos: 192678779 
                     Relay_Log_File: db1052-relay-bin.000002
                      Relay_Log_Pos: 135917
              Relay_Master_Log_File: db1057-bin.002176
                   Slave_IO_Running: Yes
                  Slave_SQL_Running: Yes
                    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: 730611360 
                    Relay_Log_Space: 510782336 
                    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: 14944
      Master_SSL_Verify_Server_Cert: No
                      Last_IO_Errno: 0
                      Last_IO_Error:
      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: 171974683 
                     Master_SSL_Crl:
                 Master_SSL_Crlpath:
                         Using_Gtid: Slave_Pos 
                        Gtid_IO_Pos: 0-171974683-4086305686
      1 row in set (0.00 sec)
       
      MariaDB PRODUCTION s1 localhost (none) > STOP SLAVE; CHANGE MASTER TO MASTER_SSL=1; START SLAVE;
      Query OK, 0 rows affected (0.02 sec)
       
      Query OK, 0 rows affected (0.14 sec)
       
      Query OK, 0 rows affected (0.00 sec)
       
      MariaDB PRODUCTION s1 localhost (none) > SHOW SLAVE STATUS\G
      *************************** 1. row ***************************
                     Slave_IO_State: Waiting for master to send event
                        Master_Host: db1057.eqiad.wmnet
                        Master_User: repl
                        Master_Port: 3306
                      Connect_Retry: 60
                    Master_Log_File: db1057-bin.002176
                Read_Master_Log_Pos: 736578634 
                     Relay_Log_File: db1052-relay-bin.000001
                      Relay_Log_Pos: 4
              Relay_Master_Log_File: db1057-bin.002176
                   Slave_IO_Running: Yes
                  Slave_SQL_Running: Yes
                    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: 736578634 
                    Relay_Log_Space: 248
                    Until_Condition: None
                     Until_Log_File:
                      Until_Log_Pos: 0
                 Master_SSL_Allowed: Yes
                 Master_SSL_CA_File:
                 Master_SSL_CA_Path:
                    Master_SSL_Cert:
                  Master_SSL_Cipher:
                     Master_SSL_Key:
              Seconds_Behind_Master: 0
      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: 171974683 
                     Master_SSL_Crl:
                 Master_SSL_Crlpath:
                         Using_Gtid: Slave_Pos 
                        Gtid_IO_Pos: 0-171974683-4085527450
      1 row in set (0.00 sec)
       
      MariaDB PRODUCTION s1 localhost (none) > SHOW SLAVE STATUS\G
      *************************** 1. row ***************************
                     Slave_IO_State: Waiting for master to send event
                        Master_Host: db1057.eqiad.wmnet
                        Master_User: repl
                        Master_Port: 3306
                      Connect_Retry: 60
                    Master_Log_File: db1057-bin.002176
                Read_Master_Log_Pos: 988725783 
                     Relay_Log_File: db1052-relay-bin.000002
                      Relay_Log_Pos: 113531
              Relay_Master_Log_File: db1057-bin.002176
                   Slave_IO_Running: Yes
                  Slave_SQL_Running: Yes
                    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: 736691423 
                    Relay_Log_Space: 252148189 
                    Until_Condition: None
                     Until_Log_File:
                      Until_Log_Pos: 0
                 Master_SSL_Allowed: Yes
                 Master_SSL_CA_File:
                 Master_SSL_CA_Path:
                    Master_SSL_Cert:
                  Master_SSL_Cipher:
                     Master_SSL_Key:
              Seconds_Behind_Master: 14811
      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: 171974683 
                     Master_SSL_Crl:
                 Master_SSL_Crlpath:
                         Using_Gtid: Slave_Pos 
                        Gtid_IO_Pos: 0-180359172-4085945305
      1 row in set (0.00 sec)
      

      This seems similar to MDEV-5114, but we are using a higher version. As the only particularities is that we are using GTID and SSL (TLS). I would expect it to be NULL until it is reliably calculated.

      We understand the shortcomings of using Seconds_Behind_Master to measure lag, and we have a pt-heartbeat table, but this looks like a bug or something to be documented as "it can return 0 at random".

      Attachments

        Issue Links

          Activity

            People

              Unassigned Unassigned
              jcrespo Jaime Crespo
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.