レプリカで気づいたタイムゾーンの問題

またまた、前回に引き続きMySQLのレプリカの話です。しかし、今回はLaravelの設定も関係してきます。

timestampのデータが非同期している

MySQLのデータタイプの１つに、timestampがあります。通常はレコードの作成や更新の日時の記録に使います。Laravelでは、Modelのクラスにおいて、デフォルトでcreated_atとupdated_atの項目がtimestampのデータタイプです。それらの項目が対応するDBテーブルにあるなら、

<?php

namespace App\Models;

use Illuminate\Database\Eloquent\Model;

class User extends Model
{
    public $timestamps = true; //デフォルト設定なので、この行は要らなくともよい
...

と設定しておけば、保存時にいちいち値をセットしなくとも自動にLaravelが面倒見てくれます。

しかし、レプリカの複製を使い始めて気づいたのは、timestampの項目のデータがマスターとレプリカが同期していないことです。

まず、マスターでtinkerを使用してレコードを更新します。

Psy Shell v0.9.3 (PHP 7.1.23 — cli) by Justin Hileman
>>> $user = User::find(1);
[!] Aliasing 'User' to 'App\User' for this Tinker session.
=> App\User {#2309
     id: 1,
     name: "山田太郎",
     email: "test@lotsofbytes.com",
     created_at: "2017-01-19 04:57:48",
     updated_at: "2018-11-08 05:05:24",
   }
>>> $user->update(['name' => 'John Doe']);
=> true
>>> $user = User::find(1);
=> App\User {#2314
     id: 1,
     name: "John Doe",
     email: "test@lotsofbytes.com",
     created_at: "2017-01-19 04:57:48",
     updated_at: "2018-12-30 03:28:42",
   }

nameとupdated_atが変更されていますね。
ここで、pt-table-checksumを実行すると、usersのテーブルでマスターとレプリカで値が異なることが報告されるのです。

Checking if all tables can be checksummed ...
Starting checksum ...
            TS ERRORS  DIFFS     ROWS  DIFF_ROWS  CHUNKS SKIPPED    TIME TABLE
12-30T03:30:31      0      0        2          0       1       0   1.020 larajapan.migrations
12-30T03:30:31      0      0        1          0       1       0   0.021 larajapan.password_resets
12-30T03:30:31      0      1        5          0       1       0   0.017 larajapan.users

謎です。

謎をひも解く

いろいろと探ってみると、知っておくべきなのに知らなかったことがぽろぽろと出てきました。

まず、知らなかったこと、その１として、

timestampのデータタイプの項目では、値が入るとUTCの時間に変更されて保存される。

例えば、MySQLのセッションが日本のタイムゾーンなら、

created_atの項目に、2018-12-30 03:00:00と入れれば、2018-12-29 18:00:00とＤＢに保存されます。日本のタイムゾーンは、UTCより9時間先です（この時間差を理解するには、このサイトhttps://www.worldtimebuddy.com/japan-tokyo-to-utcチェックしてみてください）。

そして、SELECTでこの値を引き出すときは、そのときのセッションのタイムゾーンに変換してMySQLは出力します。つまり、同じ時間を世界のどのタイムゾーンに合わせて表示が可能なわけです。

次に、知らなかったこと、その2は、

MySQLのセッションのタイムゾーンは、DBを使用するアプリで指定していないなら、アプリをホストするサーバーの設定となる。

使用しているサーバーはAWSのEC2で、そこでインストールしたMySQLのサーバーでは、特別に設定しない限り、SYSTEMつまりサーバーのシステムのタイムゾーンの設定となります。

マスターのタイムゾーンをチェックしてみると、

mysql>  SELECT @@SESSION.time_zone, @@GLOBAL.system_time_zone;
+---------------------+---------------------------+
| @@SESSION.time_zone | @@GLOBAL.system_time_zone |
+---------------------+---------------------------+
| SYSTEM              | JST                       |
+---------------------+---------------------------+

で、このSYSTEMはマシンのOSが設定するタイムゾーンJST(Japan Standard Time)になります。

さて、AWS RDSのレプリカの方は、

mysql>  SELECT @@SESSION.time_zone, @@GLOBAL.system_time_zone;
+---------------------+---------------------------+
| @@SESSION.time_zone | @@GLOBAL.system_time_zone |
+---------------------+---------------------------+
| UTC                 | UTC                       |
+---------------------+---------------------------+

もしかして、この違いが問題？

実際どんなログがレプリカで受け取られているのでしょう。MySQLが作成しているログファイルを読んでみましょう。

ログを読むには、mysqlbinlogを使用します。

$ mysqlbinlog --no-defaults -v mysql-bin.000004

この出力から、先ほどのtinkerで実行したSQLを探します。

...
# at 35339
#181230  3:28:42 server id 1  end_log_pos 35420     Query   thread_id=492197    exec_time=0 error_code=0
SET TIMESTAMP=1546108122/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=224,@@session.collation_connection=224,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
BEGIN
/*!*/;
# at 35420
#181230  3:28:42 server id 1  end_log_pos 35587     Query   thread_id=492197    exec_time=0 error_code=0
SET TIMESTAMP=1546108122/*!*/;
update `users` set `name` = 'John Doe', `updated_at` = '2018-12-30 03:28:42' where `id` = 1
/*!*/;
...

updateのSQL文ありましたね！そして、その前に実行されている、SET @@session.time_zone='SYSTEM'は、タイムゾーンをSYSTEMと設定しています。つまり、レプリカがこのログを受け取り実行するときに、タイムゾーンをSYSTEMとセットしてからレプリカのレコードを更新します。しかし、レプリカにとってはSYSTEMはマスターと違って、JSTではなくUTCです。日本時間をUTCに変更することなく更新しているのです。それゆえに、pt-table-checksumの実行では非同期となるわけです。

非同期の解決方法

非同期の理由がわかったら、この非同期を解決するのは簡単です。マスターにおいて、タイムゾーンをSYSTEMではなく、Asia/Tokyoを使うようにすればよいだけです（私の環境では、MySQLではJSTの設定ではエラーとなりました。多分にJSTはOSが返す値？）。

サーバーでのアプリがすべて日本時間帯なら、/etc/my.cnfで設定可能です。しかし、my.cnfが編集できない共有ホストの環境、あるいは同じサーバーに違うタイムゾーン向けのアプリがあるなら、使用するアプリでの設定がベストです。

Laravelのプロジェクトでの設定は簡単で、config/database.phpで以下のようにtimezoneの行を追加します。

...
    'connections' => [
        'mysql' => [
            'driver' => 'mysql',
            'host' => env('DB_HOST', '127.0.0.1'),
            'port' => env('DB_PORT', '3306'),
            'database' => env('DB_DATABASE', 'forge'),
            'username' => env('DB_USERNAME', 'forge'),
            'password' => env('DB_PASSWORD', ''),
            'unix_socket' => env('DB_SOCKET', ''),
            'charset' => 'utf8mb4',
            'collation' => 'utf8mb4_unicode_ci',
            'prefix' => '',
            'strict' => true,
            'engine' => null,
            'timezone' => 'Asia/Tokyo'
        ],
...

tinkerで確認して、前回非同期となったレコードを再度更新します。

Psy Shell v0.9.3 (PHP 7.1.23 — cli) by Justin Hileman
>>> DB::select(DB::raw("SELECT @@SESSION.time_zone, @@GLOBAL.system_time_zone"));
=> [
     {#2316
       +"@@SESSION.time_zone": "Asia/Tokyo",
       +"@@GLOBAL.system_time_zone": "JST",
     },
   ]
>>> $user = User::find(1);
[!] Aliasing 'User' to 'App\User' for this Tinker session.
=> App\User {#2307
     id: 1,
     name: "John Doe",
     email: "test@lotsofbytes.com",
     created_at: "2017-01-19 04:57:48",
     updated_at: "2018-12-30 03:28:42",
   }
>>> $user->update(['name' => 'Tarou Yamada']);
=> true
>>> $user = User::find(1);
=> App\User {#2309
     id: 1,
     name: "Tarou Yamada",
     email: "test@lotsofbytes.com",
     created_at: "2017-01-19 04:57:48",
     updated_at: "2018-12-30 04:50:48",
   }

pt-table-checksumを実行すると、結果は、差分なし！

Checking if all tables can be checksummed ...
Starting checksum ...
            TS ERRORS  DIFFS     ROWS  DIFF_ROWS  CHUNKS SKIPPED    TIME TABLE
12-30T04:51:09      0      0        2          0       1       0   0.019 larajapan.migrations
12-30T04:51:09      0      0        1          0       1       0   0.017 larajapan.password_resets
12-30T04:51:09      0      0        5          0       1       0   0.017 larajapan.users

最後に、MySQLのログを見てみます。タイムゾーンは、正しくAsia/Tokyoの設定となっていますね。

# at 38550
#181230  4:50:48 server id 1  end_log_pos 38635     Query   thread_id=492757    exec_time=0 error_code=0
SET TIMESTAMP=1546113048/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=224,@@session.collation_connection=224,@@session.collation_server=8/*!*/;
SET @@session.time_zone='Asia/Tokyo'/*!*/;
BEGIN
/*!*/;
# at 38635
#181230  4:50:48 server id 1  end_log_pos 38810     Query   thread_id=492757    exec_time=0 error_code=0
SET TIMESTAMP=1546113048/*!*/;
update `users` set `name` = 'Tarou Yamada', `updated_at` = '2018-12-30 04:50:48' where `id` = 1
/*!*/;