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

Replicated TIMESTAMP fields given wrong value near DST change

Details

    Description

      I have a MariaDB 10.1.22 server as a row-based replication slave from a MariaDB 5.5.55 server. I believe that the problem is internal to the MariaDB 10.1.22 server.

      A few rows on the slave have a TIMESTAMP column which is storing the wrong value.

      Both systems have their system timezones set to America/Chicago. My application will set the MariaDB session timezone appropriately for whatever it's doing. This ranges across the timezones in the USA, for example, EST5EDT, CST6CDT, MST, etc. The affected rows all would have had their session timezones set to PST8PDT.

      Percona's pt-table-checksum identified these inconsistent rows. At first glance, there is no problem. I'll take as my example the row with ID 88809874. Selecting the "created" column (type TIMESTAMP) for that row shows '2016-11-06 01:01:27' both on the master and the slave. Fine.

      But that's with the default timezone (Central). When I switch my session to PST8PDT and look again, I see: '2016-11-06 00:01:27' on the master and '2016-11-05 23:01:27' on the slave. [The master's version, shortly after midnight Pacific time, is correct.]

      UNIX_TIMESTAMP(created) gives 1478415687 on the master and 1478412087 on the slave. One hour off.

      I attempted to fix it by updating the master to increment the created timestamp by one second. Since I'm doing row-based replication, that should cause the right value to propagate to the slave. But it doesn't: on both master and slave the value is incremented by one second, but the hour offset remains.

      I checked the master binary log both on the server and the relay log on the slave. In both logs, the created column's value goes from 1478415687 to 1478415688. But SELECT UNIX_TIMESTAMP(created) on the slave still gives 1478412088.

      This is why I believe the problem is not related to the master: the relay log does have the correct UNIX timestamp.

      The system's timezone (America/Chicago) was undergoing a Daylight Saving shift during that timestamp. '2016-11-06 01:01:28' is ambiguous in the system's timezone: it could refer to either 1478415688 or 1478412088. But in the session timezone, PST8PDT, the correct UNIX time (1478415688) is '2016-11-06 00:01:28', which is unambiguous.

      It looks as though the fact that the system's time was ambiguous is "leaking" into the handling of the UNIX timestamp given via replication. But now I'm into the realm of speculation.

      This is only happening to a handful of rows out of countless rows that would seem to fit all the criteria. It currently seems to be an issue in 7 rows of one table, and 27 rows of another. I could fix all these problem by setting the timestamp manually on the slave, but I have no problem leaving them as-is in case it's helpful to track down what's going on.

      Please let me know what other information I can provide.

      Attachments

        Issue Links

          Activity

            Here is what I think happened, which explains most of the story above.

            Episode 1: Master, 2016-11-06, some time after 1 AM

            MariaDB [test]> select @@time_zone;
            +-----------------+
            | @@time_zone     |
            +-----------------+
            | America/Chicago |
            +-----------------+
            1 row in set (0.00 sec)
             
            set timestamp = 1478415687; # back to past
             
            MariaDB [test]> create table t1 (t timestamp not null default current_timestamp);
            Query OK, 0 rows affected (0.02 sec)
             
            MariaDB [test]> insert into t1 values (null);
            Query OK, 1 row affected (0.03 sec)
             
            MariaDB [test]> select t, unix_timestamp(t) from t1;
            +---------------------+-------------------+
            | t                   | unix_timestamp(t) |
            +---------------------+-------------------+
            | 2016-11-06 01:01:27 |        1478415687 |
            +---------------------+-------------------+
            1 row in set (0.00 sec)
            

            Episode 2: Master binary log, right afterwards

            SET TIMESTAMP=1478415687/*!*/;
            ...
            create table t1 (t timestamp not null default current_timestamp)
            /*!*/;
            # at 372
            #161106  1:01:27 server id 1  end_log_pos 440   Query   thread_id=12    exec_time=15445981      error_code=0
            SET TIMESTAMP=1478415687/*!*/;
            BEGIN
            /*!*/;
            # at 440
            # at 481
            #161106  1:01:27 server id 1  end_log_pos 481   Table_map: `test`.`t1` mapped to number 55
            #161106  1:01:27 server id 1  end_log_pos 515   Write_rows: table id 55 flags: STMT_END_F
            ### INSERT INTO `test`.`t1`
            ### SET
            ###   @1=1478415687
            # at 515
            #161106  1:01:27 server id 1  end_log_pos 542   Xid = 244
            COMMIT/*!*/;
            

            Episode 3: Slave, same time, after catching up with master

            MariaDB [test]> select @@time_zone;
            +-----------------+
            | @@time_zone     |
            +-----------------+
            | America/Chicago |
            +-----------------+
            1 row in set (0.00 sec)
             
            MariaDB [test]> select t, unix_timestamp(t) from t1;
            +---------------------+-------------------+
            | t                   | unix_timestamp(t) |
            +---------------------+-------------------+
            | 2016-11-06 01:01:27 |        1478412087 |
            +---------------------+-------------------+
            1 row in set (0.00 sec)
            

            So, no special magic is involved, and the timestamp already differs. In fact, it's not that easy to squeeze 1478415687 into the table. If instead of relying on the default value on the master, we would try to insert it explicitly, we'd see the difference on the master already:

            Episode 4: Master again

            MariaDB [test]> create table t2 like t1;
            Query OK, 0 rows affected (0.00 sec)
             
            MariaDB [test]> insert into t2 values(from_unixtime('1478415687'));
            Query OK, 1 row affected (0.01 sec)
             
            MariaDB [test]> select t, unix_timestamp(t) from t2;
            +---------------------+-------------------+
            | t                   | unix_timestamp(t) |
            +---------------------+-------------------+
            | 2016-11-06 01:01:27 |        1478412087 |
            +---------------------+-------------------+
            1 row in set (0.00 sec)
            

            So, the value 1478412087 inserted on the slave in the episode 3 is not surprising. As you said, indeed, 1478415687 and 1478412087 in this timezone mean the same time.

            Why mysqlbinlog shows 1478415687 while in fact 1478412087 is inserted – it's a question to internals, my guess is there are too many conversions from/to UNIX timestamp happening on the way. I'll pass it over to serg to decide whether it's wrong, maybe it is.

            One thing that you mentioned that I couldn't reproduce right away was this:

            "I attempted to fix it by updating the master to increment the created timestamp by one second. Since I'm doing row-based replication, that should cause the right value to propagate to the slave. But it doesn't: on both master and slave the value is incremented by one second, but the hour offset remains."

            I was trying to do it via UPDATE t1 SET t = t+1.

            Depending on the combination of the current time/zones, it would either cause the master to have 1478412088 (and the slave, consequently), or it would make the replication abort due to the "row not found" error. However, there are many combinations and more than one way to increment the timestamp, it's quite possible that you did it the way that caused the result that you've described. In any case, it's not particularly important since the problem has started long time before that.

            elenst Elena Stepanova added a comment - Here is what I think happened, which explains most of the story above. Episode 1: Master, 2016-11-06, some time after 1 AM MariaDB [test]> select @@time_zone; +-----------------+ | @@time_zone | +-----------------+ | America/Chicago | +-----------------+ 1 row in set (0.00 sec)   set timestamp = 1478415687; # back to past   MariaDB [test]> create table t1 (t timestamp not null default current_timestamp); Query OK, 0 rows affected (0.02 sec)   MariaDB [test]> insert into t1 values (null); Query OK, 1 row affected (0.03 sec)   MariaDB [test]> select t, unix_timestamp(t) from t1; +---------------------+-------------------+ | t | unix_timestamp(t) | +---------------------+-------------------+ | 2016-11-06 01:01:27 | 1478415687 | +---------------------+-------------------+ 1 row in set (0.00 sec) Episode 2: Master binary log, right afterwards SET TIMESTAMP=1478415687/*!*/; ... create table t1 (t timestamp not null default current_timestamp) /*!*/; # at 372 #161106 1:01:27 server id 1 end_log_pos 440 Query thread_id=12 exec_time=15445981 error_code=0 SET TIMESTAMP=1478415687/*!*/; BEGIN /*!*/; # at 440 # at 481 #161106 1:01:27 server id 1 end_log_pos 481 Table_map: `test`.`t1` mapped to number 55 #161106 1:01:27 server id 1 end_log_pos 515 Write_rows: table id 55 flags: STMT_END_F ### INSERT INTO `test`.`t1` ### SET ### @1=1478415687 # at 515 #161106 1:01:27 server id 1 end_log_pos 542 Xid = 244 COMMIT/*!*/; Episode 3: Slave, same time, after catching up with master MariaDB [test]> select @@time_zone; +-----------------+ | @@time_zone | +-----------------+ | America/Chicago | +-----------------+ 1 row in set (0.00 sec)   MariaDB [test]> select t, unix_timestamp(t) from t1; +---------------------+-------------------+ | t | unix_timestamp(t) | +---------------------+-------------------+ | 2016-11-06 01:01:27 | 1478412087 | +---------------------+-------------------+ 1 row in set (0.00 sec) So, no special magic is involved, and the timestamp already differs. In fact, it's not that easy to squeeze 1478415687 into the table. If instead of relying on the default value on the master, we would try to insert it explicitly, we'd see the difference on the master already: Episode 4: Master again MariaDB [test]> create table t2 like t1; Query OK, 0 rows affected (0.00 sec)   MariaDB [test]> insert into t2 values(from_unixtime('1478415687')); Query OK, 1 row affected (0.01 sec)   MariaDB [test]> select t, unix_timestamp(t) from t2; +---------------------+-------------------+ | t | unix_timestamp(t) | +---------------------+-------------------+ | 2016-11-06 01:01:27 | 1478412087 | +---------------------+-------------------+ 1 row in set (0.00 sec) So, the value 1478412087 inserted on the slave in the episode 3 is not surprising. As you said, indeed, 1478415687 and 1478412087 in this timezone mean the same time. Why mysqlbinlog shows 1478415687 while in fact 1478412087 is inserted – it's a question to internals, my guess is there are too many conversions from/to UNIX timestamp happening on the way. I'll pass it over to serg to decide whether it's wrong, maybe it is. One thing that you mentioned that I couldn't reproduce right away was this: "I attempted to fix it by updating the master to increment the created timestamp by one second. Since I'm doing row-based replication, that should cause the right value to propagate to the slave. But it doesn't: on both master and slave the value is incremented by one second, but the hour offset remains." I was trying to do it via UPDATE t1 SET t = t+1 . Depending on the combination of the current time/zones, it would either cause the master to have 1478412088 (and the slave, consequently), or it would make the replication abort due to the "row not found" error. However, there are many combinations and more than one way to increment the timestamp, it's quite possible that you did it the way that caused the result that you've described. In any case, it's not particularly important since the problem has started long time before that.

            Elena,

            Thank you very much for taking a look at this!

            The extra bit that I think your analysis is missing is that the session time zone was "PST8PDT" when this timestamp was inserted. So in the session timezone, 1478415687 is not a weird timestamp, and there shouldn't be any problem squeezing that value into a table. The problem seems to be a result of the system's timezone being weird at that moment. I agree that 1478415687 might be hard to squeeze into a table in "America/Chicago"/"CST6CDT". But in "PST8PDT", it shouldn't be. Or am I wrong?

            For the part where I was unable to fix it by incrementing the timestamp: I'm not sure that's so easily dismissed. It sounds to me like it may actually be the same problem happening again. If the binlog contains a specific UNIX timestamp, and what gets recorded in the slave is a different UNIX timestamp, simply because the system was undergoing a DST change at the time, then something is very weird and wrong. And it sounds almost exactly like the "main" problem.

            I was updating the timestamp via "created = created + INTERVAL 1 SECOND". But I don't think that should matter, as long as the row-based binlog shows the correct UNIX time, which it does. It's the slave that's doing something weird with it.

            xan@biblionix.com Xan Charbonnet added a comment - Elena, Thank you very much for taking a look at this! The extra bit that I think your analysis is missing is that the session time zone was "PST8PDT" when this timestamp was inserted. So in the session timezone, 1478415687 is not a weird timestamp, and there shouldn't be any problem squeezing that value into a table. The problem seems to be a result of the system's timezone being weird at that moment. I agree that 1478415687 might be hard to squeeze into a table in "America/Chicago"/"CST6CDT". But in "PST8PDT", it shouldn't be. Or am I wrong? For the part where I was unable to fix it by incrementing the timestamp: I'm not sure that's so easily dismissed. It sounds to me like it may actually be the same problem happening again. If the binlog contains a specific UNIX timestamp, and what gets recorded in the slave is a different UNIX timestamp, simply because the system was undergoing a DST change at the time, then something is very weird and wrong. And it sounds almost exactly like the "main" problem. I was updating the timestamp via "created = created + INTERVAL 1 SECOND". But I don't think that should matter, as long as the row-based binlog shows the correct UNIX time, which it does. It's the slave that's doing something weird with it.

            Hmm, I cannot repeat it. Here's what I tried:

            On the master

            set global time_zone='Europe/Moscow';
            set time_zone='Europe/Moscow';
            -- now, use a session time_zone on the master where timestamp is unambiguous
            set time_zone='UTC';
            create table t1 (a timestamp);
            -- 1288477526 == 2010-10-31 02:25:26 Europe/Moscow
            set timestamp=1288477526;
            insert t1 values ();
            set timestamp=1288477526+3600;
            insert t1 values ();
            -- note, inserted values differ
            select * from t1;
            

            On the slave

            set global time_zone='Europe/Moscow';
            set time_zone='Europe/Moscow';
            -- this starts slave thread with the time_zone = Europe/Moscow
            start slave;
             
            -- wait until it catches up
            -- note, values on the slave *look* identical
            select * from t1;
            set time_zone='UTC';
            -- but in a different time zone they're not
            select * from t1;
            

            serg Sergei Golubchik added a comment - Hmm, I cannot repeat it. Here's what I tried: On the master set global time_zone= 'Europe/Moscow' ; set time_zone= 'Europe/Moscow' ; -- now, use a session time_zone on the master where timestamp is unambiguous set time_zone= 'UTC' ; create table t1 (a timestamp ); -- 1288477526 == 2010-10-31 02:25:26 Europe/Moscow set timestamp =1288477526; insert t1 values (); set timestamp =1288477526+3600; insert t1 values (); -- note, inserted values differ select * from t1; On the slave set global time_zone= 'Europe/Moscow' ; set time_zone= 'Europe/Moscow' ; -- this starts slave thread with the time_zone = Europe/Moscow start slave;   -- wait until it catches up -- note, values on the slave *look* identical select * from t1; set time_zone= 'UTC' ; -- but in a different time zone they're not select * from t1;

            Hello Sergei,

            Thank you for looking into this.

            I also can't re-create this problem. And for the most part, it didn't take place: virtually all timestamps in this situation were handled correctly.

            But there are something like a couple of dozen rows which were bitten by this behavior. And not only that, but the behavior continues: when the binary log tells the slave to update to a new timestamp (a specific timestamp, not an offset), then it still handles the timestamp incorrectly.

            That's what makes me think it's worth digging into further. I can fix my slave by manually setting the timestamp, and that would very likely be the end of my problem. I'm leaving it unfixed for now in case it's helpful for diagnosing this.

            Please let me know what other information I can provide, or if you don't think it's worth investigating further, I'll just fix my data and move on.

            xan@biblionix.com Xan Charbonnet added a comment - Hello Sergei, Thank you for looking into this. I also can't re-create this problem. And for the most part, it didn't take place: virtually all timestamps in this situation were handled correctly. But there are something like a couple of dozen rows which were bitten by this behavior. And not only that, but the behavior continues: when the binary log tells the slave to update to a new timestamp (a specific timestamp, not an offset), then it still handles the timestamp incorrectly. That's what makes me think it's worth digging into further. I can fix my slave by manually setting the timestamp, and that would very likely be the end of my problem. I'm leaving it unfixed for now in case it's helpful for diagnosing this. Please let me know what other information I can provide, or if you don't think it's worth investigating further, I'll just fix my data and move on.
            elenst Elena Stepanova added a comment - - edited

            It appears to be important which server versions participate in replication. 5.5 => 10.1 and 10.0 => 10.1 exhibit the problem; 5.5 => 5.5, 5.5 => 10.0, 10.0 => 10.1 and 10.1 => 10.1 don't. I might have made a mistake in one or two combinations, but there is certainly a dependency on the versions.

            My scenario below is for 5.5 => 10.1 combination, as in the initial description, but with current 5.5 and 10.1 builds. Maybe some steps are excessive, but executing all of them seems to trigger the result reliably.

            • start 5.5 server with default settings on a clean datadir
            • load the timezone data, on my machine it's /data/bld/5.5/bin/mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql -uroot --protocol=tcp --port=3306 mysql
            • restart 5.5 server on the same datadir, now with --server-id=1 --port=3306 --log-bin --binlog-format=row --default-time-zone='America/Chicago'
            • start 10.1 server with default settings and --port=3307 on a clean datadir
            • load the timezone data, /data/bld/10.1/bin/mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql -uroot --protocol=tcp --port=3307 mysql
            • restart 10.1 server on the same datadir, now with --server-id=2 --port=3307 --default-time-zone='America/Chicago'
            • connect to 10.1 slave, run

              MariaDB [test]> change master to master_host='127.0.0.1', master_port=3306, master_user='root';
              Query OK, 0 rows affected (0.18 sec)
               
              MariaDB [test]> start slave;
              Query OK, 0 rows affected (0.00 sec)
              

            • connect to 5.5 master, run

              drop table if exists t1;
              set time_zone = 'PST8PDT';
              set timestamp = 1478415687;
              create table t1 (pk int primary key, t timestamp not null default current_timestamp on update current_timestamp);
              insert into t1 values (1,null);
              select pk, t, unix_timestamp(t) from t1;
              

              MariaDB [test]> select pk, t, unix_timestamp(t) from t1;
              +----+---------------------+-------------------+
              | pk | t                   | unix_timestamp(t) |
              +----+---------------------+-------------------+
              |  1 | 2016-11-06 00:01:27 |        1478415687 |
              +----+---------------------+-------------------+
              1 row in set (0.00 sec)
              

            • connect to 10.1 slave, check the data:

              MariaDB [test]> select pk, t, unix_timestamp(t) from t1;
              +----+---------------------+-------------------+
              | pk | t                   | unix_timestamp(t) |
              +----+---------------------+-------------------+
              |  1 | 2016-11-06 01:01:27 |        1478412087 |
              +----+---------------------+-------------------+
              1 row in set (0.00 sec)
              

            • connect to 5.5 master, run

              MariaDB [test]> set time_zone = 'PST8PDT';
              Query OK, 0 rows affected (0.00 sec)
               
              MariaDB [test]> begin;
              Query OK, 0 rows affected (0.00 sec)
               
              MariaDB [test]> update t1 set t = t + INTERVAL 1 SECOND;
              Query OK, 1 row affected (0.00 sec)
              Rows matched: 1  Changed: 1  Warnings: 0
               
              MariaDB [test]> commit;
              Query OK, 0 rows affected (0.02 sec)
               
              MariaDB [test]> select pk, t, unix_timestamp(t) from t1;
              +----+---------------------+-------------------+
              | pk | t                   | unix_timestamp(t) |
              +----+---------------------+-------------------+
              |  1 | 2016-11-06 00:01:28 |        1478415688 |
              +----+---------------------+-------------------+
              1 row in set (0.00 sec)
              

            • connect to 10.1 slave, check the data:

              MariaDB [test]> select pk, t, unix_timestamp(t) from t1;
              +----+---------------------+-------------------+
              | pk | t                   | unix_timestamp(t) |
              +----+---------------------+-------------------+
              |  1 | 2016-11-06 01:01:28 |        1478412088 |
              +----+---------------------+-------------------+
              1 row in set (0.00 sec)
              

            Please note that with this scenario, even though we set PST8PDT on the master both times, it's not seen in the binary log:

            $ bin/mysqlbinlog --verbose --base64-output=DECODE-ROWS data/ws-bin.000001 
            /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
            /*!40019 SET @@session.max_insert_delayed_threads=0*/;
            /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
            DELIMITER /*!*/;
            # at 4
            #170623 17:38:50 server id 1  end_log_pos 245 	Start: binlog v 4, server v 5.5.57-MariaDB-debug created 170623 17:38:50 at startup
            # Warning: this binlog is either in use or was not closed properly.
            ROLLBACK/*!*/;
            # at 245
            #170623 17:41:38 server id 1  end_log_pos 359 	Query	thread_id=4	exec_time=0	error_code=0
            use `test`/*!*/;
            SET TIMESTAMP=1498228898/*!*/;
            SET @@session.pseudo_thread_id=4/*!*/;
            SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
            SET @@session.sql_mode=0/*!*/;
            SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
            /*!\C utf8 *//*!*/;
            SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
            SET @@session.lc_time_names=0/*!*/;
            SET @@session.collation_database=DEFAULT/*!*/;
            DROP TABLE IF EXISTS `t1` /* generated by server */
            /*!*/;
            # at 359
            #161106  9:01:27 server id 1  end_log_pos 534 	Query	thread_id=4	exec_time=19813211	error_code=0
            SET TIMESTAMP=1478415687/*!*/;
            create table t1 (pk int primary key, t timestamp not null default current_timestamp on update current_timestamp)
            /*!*/;
            # at 534
            #161106  9:01:27 server id 1  end_log_pos 602 	Query	thread_id=4	exec_time=19813211	error_code=0
            SET TIMESTAMP=1478415687/*!*/;
            BEGIN
            /*!*/;
            # at 602
            # at 644
            #161106  9:01:27 server id 1  end_log_pos 644 	Table_map: `test`.`t1` mapped to number 33
            #161106  9:01:27 server id 1  end_log_pos 682 	Write_rows: table id 33 flags: STMT_END_F
            ### INSERT INTO `test`.`t1`
            ### SET
            ###   @1=1
            ###   @2=1478415687
            # at 682
            #161106  9:01:27 server id 1  end_log_pos 709 	Xid = 23
            COMMIT/*!*/;
            # at 709
            #170623 17:43:24 server id 1  end_log_pos 777 	Query	thread_id=6	exec_time=0	error_code=0
            SET TIMESTAMP=1498229004/*!*/;
            BEGIN
            /*!*/;
            # at 777
            # at 819
            #170623 17:43:22 server id 1  end_log_pos 819 	Table_map: `test`.`t1` mapped to number 33
            #170623 17:43:22 server id 1  end_log_pos 867 	Update_rows: table id 33 flags: STMT_END_F
            ### UPDATE `test`.`t1`
            ### WHERE
            ###   @1=1
            ###   @2=1478415687
            ### SET
            ###   @1=1
            ###   @2=1478415688
            # at 867
            #170623 17:43:24 server id 1  end_log_pos 894 	Xid = 38
            COMMIT/*!*/;
            DELIMITER ;
            # End of log file
            ROLLBACK /* added by mysqlbinlog */;
            /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
            /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
            

            elenst Elena Stepanova added a comment - - edited It appears to be important which server versions participate in replication. 5.5 => 10.1 and 10.0 => 10.1 exhibit the problem; 5.5 => 5.5, 5.5 => 10.0, 10.0 => 10.1 and 10.1 => 10.1 don't. I might have made a mistake in one or two combinations, but there is certainly a dependency on the versions. My scenario below is for 5.5 => 10.1 combination, as in the initial description, but with current 5.5 and 10.1 builds. Maybe some steps are excessive, but executing all of them seems to trigger the result reliably. start 5.5 server with default settings on a clean datadir load the timezone data, on my machine it's /data/bld/5.5/bin/mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql -uroot --protocol=tcp --port=3306 mysql restart 5.5 server on the same datadir, now with --server-id=1 --port=3306 --log-bin --binlog-format=row --default-time-zone='America/Chicago' start 10.1 server with default settings and --port=3307 on a clean datadir load the timezone data, /data/bld/10.1/bin/mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql -uroot --protocol=tcp --port=3307 mysql restart 10.1 server on the same datadir, now with --server-id=2 --port=3307 --default-time-zone='America/Chicago' connect to 10.1 slave, run MariaDB [test]> change master to master_host= '127.0.0.1' , master_port=3306, master_user= 'root' ; Query OK, 0 rows affected (0.18 sec)   MariaDB [test]> start slave; Query OK, 0 rows affected (0.00 sec) connect to 5.5 master, run drop table if exists t1; set time_zone = 'PST8PDT' ; set timestamp = 1478415687; create table t1 (pk int primary key , t timestamp not null default current_timestamp on update current_timestamp ); insert into t1 values (1, null ); select pk, t, unix_timestamp(t) from t1; MariaDB [test]> select pk, t, unix_timestamp(t) from t1; + ----+---------------------+-------------------+ | pk | t | unix_timestamp(t) | + ----+---------------------+-------------------+ | 1 | 2016-11-06 00:01:27 | 1478415687 | + ----+---------------------+-------------------+ 1 row in set (0.00 sec) connect to 10.1 slave, check the data: MariaDB [test]> select pk, t, unix_timestamp(t) from t1; + ----+---------------------+-------------------+ | pk | t | unix_timestamp(t) | + ----+---------------------+-------------------+ | 1 | 2016-11-06 01:01:27 | 1478412087 | + ----+---------------------+-------------------+ 1 row in set (0.00 sec) connect to 5.5 master, run MariaDB [test]> set time_zone = 'PST8PDT' ; Query OK, 0 rows affected (0.00 sec)   MariaDB [test]> begin ; Query OK, 0 rows affected (0.00 sec)   MariaDB [test]> update t1 set t = t + INTERVAL 1 SECOND ; Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0   MariaDB [test]> commit ; Query OK, 0 rows affected (0.02 sec)   MariaDB [test]> select pk, t, unix_timestamp(t) from t1; + ----+---------------------+-------------------+ | pk | t | unix_timestamp(t) | + ----+---------------------+-------------------+ | 1 | 2016-11-06 00:01:28 | 1478415688 | + ----+---------------------+-------------------+ 1 row in set (0.00 sec) connect to 10.1 slave, check the data: MariaDB [test]> select pk, t, unix_timestamp(t) from t1; + ----+---------------------+-------------------+ | pk | t | unix_timestamp(t) | + ----+---------------------+-------------------+ | 1 | 2016-11-06 01:01:28 | 1478412088 | + ----+---------------------+-------------------+ 1 row in set (0.00 sec) Please note that with this scenario, even though we set PST8PDT on the master both times, it's not seen in the binary log: $ bin/mysqlbinlog --verbose --base64-output=DECODE-ROWS data/ws-bin.000001 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #170623 17:38:50 server id 1 end_log_pos 245 Start: binlog v 4, server v 5.5.57-MariaDB-debug created 170623 17:38:50 at startup # Warning: this binlog is either in use or was not closed properly. ROLLBACK/*!*/; # at 245 #170623 17:41:38 server id 1 end_log_pos 359 Query thread_id=4 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1498228898/*!*/; SET @@session.pseudo_thread_id=4/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=0/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/; /*!\C utf8 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; DROP TABLE IF EXISTS `t1` /* generated by server */ /*!*/; # at 359 #161106 9:01:27 server id 1 end_log_pos 534 Query thread_id=4 exec_time=19813211 error_code=0 SET TIMESTAMP=1478415687/*!*/; create table t1 (pk int primary key, t timestamp not null default current_timestamp on update current_timestamp) /*!*/; # at 534 #161106 9:01:27 server id 1 end_log_pos 602 Query thread_id=4 exec_time=19813211 error_code=0 SET TIMESTAMP=1478415687/*!*/; BEGIN /*!*/; # at 602 # at 644 #161106 9:01:27 server id 1 end_log_pos 644 Table_map: `test`.`t1` mapped to number 33 #161106 9:01:27 server id 1 end_log_pos 682 Write_rows: table id 33 flags: STMT_END_F ### INSERT INTO `test`.`t1` ### SET ### @1=1 ### @2=1478415687 # at 682 #161106 9:01:27 server id 1 end_log_pos 709 Xid = 23 COMMIT/*!*/; # at 709 #170623 17:43:24 server id 1 end_log_pos 777 Query thread_id=6 exec_time=0 error_code=0 SET TIMESTAMP=1498229004/*!*/; BEGIN /*!*/; # at 777 # at 819 #170623 17:43:22 server id 1 end_log_pos 819 Table_map: `test`.`t1` mapped to number 33 #170623 17:43:22 server id 1 end_log_pos 867 Update_rows: table id 33 flags: STMT_END_F ### UPDATE `test`.`t1` ### WHERE ### @1=1 ### @2=1478415687 ### SET ### @1=1 ### @2=1478415688 # at 867 #170623 17:43:24 server id 1 end_log_pos 894 Xid = 38 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

            I've also repeated it by running this in 5.5:

            source include/have_binlog_format_row.inc;
            set global time_zone='Europe/Moscow';
            set time_zone='Europe/Moscow';
            set time_zone='UTC';
            create table t1 (pk int primary key, t timestamp not null default current_timestamp on update current_timestamp);
            set timestamp = 1288477526;
            insert into t1 values (1,null);
            set timestamp = 1288481126;
            insert into t1 values (2,null);
            

            And loading the binlog into 10.1 with

            source include/have_binlog_format_row.inc;
            set global time_zone='Europe/Moscow';
            set time_zone='Europe/Moscow';
            set time_zone='UTC';
            --exec $MYSQL_BINLOG /path/to/5.5/mysql-test/var/mysqld.1/data/master-bin.000001 | $MYSQL
            select pk, t, unix_timestamp(t) from t1;
            set time_zone=default;
            select pk, t, unix_timestamp(t) from t1;
            

            What happens here, 5.5 creates a table with MYSQL_TYPE_TIMESTAMP field, Field_timestamp. But 10.1 creates for the same CREATE TABLE statement a MYSQL_TYPE_TIMESTAMP2 field, Field_timestampf. And table_def::compatible_with() notices that field types differ and creates a conversion table. When a conversion table exists, unpack_row() uses Copy_field interface, and do_field_temporal() works via MYSQL_TIME structure.

            serg Sergei Golubchik added a comment - I've also repeated it by running this in 5.5: source include/have_binlog_format_row.inc; set global time_zone= 'Europe/Moscow' ; set time_zone= 'Europe/Moscow' ; set time_zone= 'UTC' ; create table t1 (pk int primary key , t timestamp not null default current_timestamp on update current_timestamp ); set timestamp = 1288477526; insert into t1 values (1, null ); set timestamp = 1288481126; insert into t1 values (2, null ); And loading the binlog into 10.1 with source include/have_binlog_format_row.inc; set global time_zone= 'Europe/Moscow' ; set time_zone= 'Europe/Moscow' ; set time_zone= 'UTC' ; --exec $MYSQL_BINLOG /path/to/5.5/mysql-test/var/mysqld.1/data/master-bin.000001 | $MYSQL select pk, t, unix_timestamp(t) from t1; set time_zone= default ; select pk, t, unix_timestamp(t) from t1; What happens here, 5.5 creates a table with MYSQL_TYPE_TIMESTAMP field, Field_timestamp . But 10.1 creates for the same CREATE TABLE statement a MYSQL_TYPE_TIMESTAMP2 field, Field_timestampf . And table_def::compatible_with() notices that field types differ and creates a conversion table. When a conversion table exists, unpack_row() uses Copy_field interface, and do_field_temporal() works via MYSQL_TIME structure.

            Sent review suggestion to maria-developers@

            bar Alexander Barkov added a comment - Sent review suggestion to maria-developers@

            People

              serg Sergei Golubchik
              xan@biblionix.com Xan Charbonnet
              Votes:
              1 Vote for this issue
              Watchers:
              6 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.