I'm trying to figure out why the reporting of slave lag is different in SHOW SLAVE STATUS and SHOW PROCESSLIST, in MySQL 5.5.13. The only difference to other slaves of this master is that it is replicating over a relatively slow connection, about 10Mb/sec (cross site).

SHOW SLAVE STATUS reports a slave lag of 0, or occasionally, the real slave lag, once every 5-10 requests. (I'm looking at Seconds_Behind_Master)

SHOW PROCESSLIST, shows the slave lag under the system_user's time column (the one that belongs to the replication sql thread), like so:

mysql> show processlist \G
*************************** 1. row ***************************
     Id: 1
   User: system user
     db: NULL
Command: Connect
   Time: 63953
  State: Waiting for master to send event
   Info: NULL
*************************** 2. row ***************************
     Id: 2
   User: system user
     db: NULL
Command: Connect
   Time: 61077
  State: Slave has read all relay log; waiting for the slave I/O thread to update it
   Info: NULL

Why would these differ? Or rather, why would SHOW SLAVE STATUS lie? The monitoring system is looking at this command, and goes crazy due to "spikes" once in a while. I know for a fact the right number is what SHOW PROCESSLIST reports, since the slave took a good few days to be initialized, and is catching up slowly.


The "Time" in the SQL thread is (I think) identical to Seconds_behind_master. It is "How long ago did this query start on the Master ".

All other Times are indicate when the query started on the Slave.

Some fluctuation is caused by what it is measuring (the Master's start time).

Sometimes (rarely), I see the value (both places) bouncing between 0 and some large value. I have yet to track this down. I have seen it on 4.0, 4.1, and 5.1. It eventually goes away, and becomes civilized.

There may be cases where no traffic leads to strange values. But I don't have any Master-Slave setups with little enough traffic for me to comment.

Suppose you do ALTER on the Master, and it took 1 hour (3600 seconds). Also, suppose not much else is going on. The ALTER replicates and starts running. Immediately, the Seconds_behind_master will be about 3600. After the ALTER finishes on the Slave (say, 3600 more seconds later), subsequent replication items will execute with (probably) smaller Times. Eventually replication catches up.

  • "How long ago did this query start on the Master" actually makes the best sense... Thanks for clearing it up. Is there a documentation somewhere pointing to it as well? Because I couldn't find any... – shlomoid Jul 21 '11 at 10:27

SHOW PROCESSLIST, shows the slave lag under the system_user's time column (the one that belongs to the replication sql thread)

No. It's the time that the Slave sql thread has been in its current state.

  • I used to think so too. It's supposed to be, for all other threads- but it isn't. The time is constantly changing, and actually decreasing in subsequent refreshes. – shlomoid Jul 14 '11 at 9:10
  • I agree with @quanta in this, +1 !!! – RolandoMySQLDBA Jul 18 '11 at 11:50
  • If you would have asked me before, that what I would also say :) But it's not really behaving this way. – shlomoid Jul 18 '11 at 13:05

The SQL thread has a time of 61077 seconds. This is actaully the length of time the SQL thread has been alive. The I/O Thread has been alive for 63953 seconds.

I recently wrote an explanation as to how replication calculates Seconds_Behind_Master.

The reason they could differ? Here is one possiblility:

If you encountered a SQL error in the SQL Thread, the I/O thread would still continue collecting SQL statements from the Master. Once you skip the error, the SQL thread's life starts from zero and increases from there. Something like this would have happened 2876 (63953 - 61077) Seconds after starting replication.

  • There was no error. It was a fresh slave cloned from another slave. There were no errors till now, and it continued running smoothly since start. I don't think that the show processlist command is showing "time in current state" or "time alive" for the slave thread. Usually, on a slave, the time column sorta matches "seconds behind master". Here, when refreshing "show slave status", the "seconds behind.." was jumping between 61,00 and 0 seconds... Obviously the calculation was broken somehow...? – shlomoid Jul 18 '11 at 13:06
  • I might add, that the network is slow, and the sql thread might be spending most of it's time waiting for the io thread... Another thing to note, is that since the first moment the slave came online, it was 210k seconds behind, and show processlist showed this number. It can't be "time in this state" or "time alive" since the server was just started. – shlomoid Jul 18 '11 at 13:08
  • Interestingly, if the I/O is off and the slave was behind 20000 seconds, then the Time column of the SQL thread in SHOW PROCESSLIST would say 20000 and would be decreasing. During that time, Seconds_Behind_Master would be NULL because replication requires both both threads to be alive to calculate the time. – RolandoMySQLDBA Jul 18 '11 at 14:50
  • Is this true right after server startup? And it never showed NULL, it always showed 0 or 61000 (or whatever number). Also, I could see the master_log_position advancing every refresh. – shlomoid Jul 18 '11 at 14:58
  • Pretty weird ha? – shlomoid Jul 18 '11 at 14:59

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.