[pgsql-jp: 41433] Re: ストリーミング・レプリケーションでデータの同期が行われなくなった
Keiji Yoshida
k.yoshida ＠ onemore.co.jp
2013年 6月 17日 (月) 20:23:36 JST
各位
吉田です。
お世話になっております。
＞★ slaveのpg_xlog/archive_status
＞-rw------- 1 postgres postgres 0 6月 16 16:03 2013 00000002.history.ready
朝倉様にご連絡頂きまして、上記より、6月16日の16:03にSlaveがpromoteされた事実が読み取れるとのことでしたので、この時間帯のPostgreSQLログファイルを抜き出しました。
============================================================================================================================================
2013-06-16 16:03:37.022 JST,,,28461,,501e700b.6f2d,6,,2012-08-05 22:07:23 JST,1/0,0,LOG,00000,"trigger file found: /var/log/pgpool/trigger_file",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.022 JST,,,28464,,501e700b.6f30,2,,2012-08-05 22:07:23 JST,,0,FATAL,57P01,"terminating walreceiver process due to administrator command",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.087 JST,,,10077,"",51bd6349.275d,1,"",2013-06-16 16:03:37 JST,,0,LOG,00000,"connection received: host=10.160.161.34 port=42220",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.089 JST,"postgres","postgres",10077,"10.160.161.34:42220",51bd6349.275d,2,"authentication",2013-06-16 16:03:37 JST,2/1708507,0,LOG,00000,"connection authorized: user=postgres database=postgres",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.098 JST,"postgres","postgres",10077,"10.160.161.34:42220",51bd6349.275d,3,"idle",2013-06-16 16:03:37 JST,,0,LOG,00000,"disconnection: session time: 0:00:00.011 user=postgres database=postgres host=10.160.161.34 port=42220",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.130 JST,,,28461,,501e700b.6f2d,7,,2012-08-05 22:07:23 JST,1/0,0,LOG,00000,"invalid record length at 0/47DFE858",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.130 JST,,,28461,,501e700b.6f2d,8,,2012-08-05 22:07:23 JST,1/0,0,LOG,00000,"redo done at 0/47DFE800",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.130 JST,,,28461,,501e700b.6f2d,9,,2012-08-05 22:07:23 JST,1/0,0,LOG,00000,"last completed transaction was at log time 2013-06-16 15:47:02.994388+09",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.131 JST,,,28461,,501e700b.6f2d,10,,2012-08-05 22:07:23 JST,1/0,0,LOG,00000,"selected new timeline ID: 2",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.583 JST,,,28461,,501e700b.6f2d,11,,2012-08-05 22:07:23 JST,1/0,0,LOG,00000,"archive recovery complete",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.607 JST,,,28462,,501e700b.6f2e,135970,,2012-08-05 22:07:23 JST,,0,LOG,00000,"checkpoint starting: end-of-recovery immediate wait",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.632 JST,,,28462,,501e700b.6f2e,135971,,2012-08-05 22:07:23 JST,,0,LOG,00000,"checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.000 s, total=0.029 s; sync files=0, longest=0.000 s, average=0.000 s",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.821 JST,,,10078,"",51bd6349.275e,1,"",2013-06-16 16:03:37 JST,,0,LOG,00000,"connection received: host=10.156.243.93 port=56279",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.823 JST,"postgres","postgres",10078,"10.156.243.93:56279",51bd6349.275e,2,"authentication",2013-06-16 16:03:37 JST,2/1708509,0,LOG,00000,"connection authorized: user=postgres database=postgres",,,,,,,,,"gfdbp010"
2013-06-16 16:03:37.826 JST,"postgres","postgres",10078,"10.156.243.93:56279",51bd6349.275e,3,"idle",2013-06-16 16:03:37 JST,,0,LOG,00000,"disconnection: session time: 0:00:00.005 user=postgres database=postgres host=10.156.243.93 port=56279",,,,,,,,,"gfdbp010"
2013-06-16 16:03:38.169 JST,,,28458,,501e700b.6f2a,2,,2012-08-05 22:07:23 JST,,0,LOG,00000,"database system is ready to accept connections",,,,,,,,,"gfdbp010"
2013-06-16 16:03:38.169 JST,,,10080,,51bd634a.2760,1,,2013-06-16 16:03:38 JST,,0,LOG,00000,"autovacuum launcher started",,,,,,,,,"gfdbp010"
============================================================================================================================================
この時間帯にプロセスの再起動とデータのリカバリが行われているようです。
再起動、リカバリが実行された原因は、調査できるものなのでしょうか？
※「due to administrator command」とあるのですが、この時間帯は作業を行っておりません。
また、レプリケーションが解除されたことが分かりましたので、これからレプリケーションの再構築、及び、
データのリカバリ処理を（手順を確認しながら）実施致します。
作業実施に際し、またご質問、ご相談させて頂くことがあるかもしれませんが、その際はどうぞよろしくお願い申し上げます。
吉田
On 2013/06/17, at 20:02, Keiji Yoshida <k.yoshida ＠ onemore.co.jp> wrote:
> Suzuki様
>
> 吉田です。
> ご返信くださいましてありがとうございます。
>
> 以下、ご回答差し上げます。
>
> ＞Railsはpgpool-IIに更新系SQL＋検索系SQLどちらも発行しているのでしょうか？
> ＞それとも直接PostgreSQLにアクセスする場合もあるのでしょうか？
>
> pgpool-IIに更新系SQL＋検索系SQLどちらも発行しています。
> 直接PostgreSQLにアクセスする場合はございません。
>
> ＞pgpool-IIは1台だけ稼働でしょうか？
> ＞pgpool-IIは(レプリケーションモードではなく)「マスタースレーブモード」で 稼働しているのでしょうか？
>
> アプリケーションサーバが２台あり、pgpool-IIが各サーバ上で１本ずつ動いています。
> pgpool-IIは「マスタースレーブモード」で 稼働しています。
>
>
> ＞(2)slaveサーバのデータベースクラスタに
> ＞recovery.confもしくはrecovery.doneというファイルはあるでしょうか？
>
> ございます。
> ＃自動的にリカバリが走った、ということでしょうか？
>
> ＞(3)masterとslaveの,以下のディレクトリの中身(存在するファイル名)を知るこ とはできるでしょうか？
> ＞ls pg_xlog
> ＞ls pg_xlog/archive_status
>
> 下記の通りです。
> =============================================================================
> ★ masterのpg_xlog
> drwx------ 2 postgres postgres 4096 7月 23 14:10 2012 archive_status
> -rw------- 1 postgres postgres 16777216 6月 12 08:13 2013 000000010000000000000049
> -rw------- 1 postgres postgres 16777216 6月 17 18:09 2013 00000001000000000000004A
> -rw------- 1 postgres postgres 16777216 6月 17 19:58 2013 000000010000000000000048
>
> ★ masterのpg_xlog/archive_status
> （なし）
>
> ★ slaveのpg_xlog
> -rw------- 1 postgres postgres 16777216 6月 12 08:13 2013 000000010000000000000048
> -rw------- 1 postgres postgres 16777216 6月 16 15:58 2013 000000010000000000000047
> -rw------- 1 postgres postgres 56 6月 16 16:03 2013 00000002.history
> drwx------ 2 postgres postgres 4096 6月 16 16:03 2013 archive_status
> -rw------- 1 postgres postgres 16777216 6月 16 16:03 2013 000000020000000000000048
> -rw------- 1 postgres postgres 16777216 6月 17 19:53 2013 000000020000000000000047
>
> ★ slaveのpg_xlog/archive_status
> -rw------- 1 postgres postgres 0 6月 16 16:03 2013 00000002.history.ready
> =============================================================================
>
> 以上、何卒よろしくお願い申し上げます。
>
> 吉田
>
>
> On 2013/06/17, at 19:49, Suzuki Hironobu <hironobu ＠ interdb.jp> wrote:
>
>> こんにちは
>>
>>
>> (1)この説明が気になるので、念のため確認ですが：
>>
>>> 更新系SQLは、両方のサーバへ発行される構造となっておりましたため、
>>
>> Railsはpgpool-IIに更新系SQL＋検索系SQLどちらも発行しているのでしょうか？
>> それとも直接PostgreSQLにアクセスする場合もあるのでしょうか？
>>
>> ついでに確認ですが、
>> pgpool-IIは1台だけ稼働でしょうか？
>> pgpool-IIは(レプリケーションモードではなく)「マスタースレーブモード」で 稼働しているのでしょうか？
>>
>>
>> (2)slaveサーバのデータベースクラスタに
>> recovery.confもしくはrecovery.doneというファイルはあるでしょうか？
>>
>>
>> (3)masterとslaveの,以下のディレクトリの中身(存在するファイル名)を知るこ とはできるでしょうか？
>> ls pg_xlog
>> ls pg_xlog/archive_status
>>
>>
>> 以上、よろしくお願いします。
>>
>>
>>
>> On 2013年06月17日 19:23, Keiji Yoshida wrote:
>>> 朝倉様
>>>
>>> 吉田です。
>>> お世話になります。
>>>
>>> 先ほどのメールに追記させて頂きます。
>>>
>>> ＞②Master側で、「SELECT * FROM pg_stat_replication」を実行して、
>>> ＞レプリケーションの状態を確認する
>>> ＞といった調査方法があると思います。
>>>
>>> Master、Slaveの両方で「SELECT * FROM pg_stat_replication」を実行したところ、
>>> どちらもレコードが存在しませんでした。（0件の結果が返却されました。）
>>>
>>> ＃レプリケーションの状態が解除されてしまっている、ということでしょうか？
>>>
>>> 吉田
>>>
>>>
>>> On 2013/06/17, at 19:11, Keiji Yoshida<k.yoshida ＠ onemore.co.jp> wrote:
>>>
>>>> 朝倉様
>>>>
>>>> 吉田です。
>>>> ご返信くださいまして、誠にありがとうございます。
>>>>
>>>> ＞DBサーバは2台で構成され、1台がMaster、もう1台がSlaveで、
>>>> ＞ストリーミングレプリケーションを組んでいた、
>>>> ＞であっていますか？
>>>>
>>>> はい、おっしゃる通りです。
>>>> アプリケーションサーバからは、pgpool-II（マスタースレーブモード）経由でデータベースサーバへアクセスしております。
>>>>
>>>>
>>>> ＞更新系SQLは、両方のサーバへ発行される構造となっておりましたため、
>>>> ＞この部分が分かりません。
>>>> ＞ストリーミングレプリケーション + ホットスタンバイの構成だと、
>>>> ＞そもそもSlave側は参照専用で、更新はMaster側にだけしか
>>>> ＞発行できないのですが。。。
>>>>
>>>> そもそもMasterへしか発行されないはずの更新系SQLが、現在はSlaveへも発行されるようになってしまっております。
>>>>
>>>> このようなことになってしまったことの原因を突き止めようしておりますが、調査に苦戦している状況でございます。
>>>>
>>>> ご多用のところ大変恐縮でございますが、何卒よろしくお願い申し上げます。
>>>>
>>>>
>>>> 吉田
>>>>
>>>>
>>>> On 2013/06/17, at 18:57, 朝倉 佑貴<asakura.yuuki ＠ nttcom.co.jp> wrote:
>>>>
>>>>> 朝倉と申します。
>>>>>
>>>>> サーバ構成がよくわからないので、教えてください。
>>>>> DBサーバは2台で構成され、1台がMaster、もう1台がSlaveで、
>>>>> ストリーミングレプリケーションを組んでいた、
>>>>> であっていますか？
>>>>>
>>>>>
>>>>>> 更新系SQLは、両方のサーバへ発行される構造となっておりましたため、
>>>>> この部分が分かりません。
>>>>> ストリーミングレプリケーション + ホットスタンバイの構成だと、
>>>>> そもそもSlave側は参照専用で、更新はMaster側にだけしか
>>>>> 発行できないのですが。。。
>>>>>
>>>>>
>>>>> Master側に発行した更新が、Slave側に反映されなくなった、
>>>>> ということなら、Slave側がpromoteされてしまった可能性を
>>>>> 考えます。
>>>>>
>>>>> この線で調査するなら、
>>>>> ①それぞれのサーバで、「pg_controldata<PGDATA>」を実行して、
>>>>> TimeLineIDを確認する
>>>>> ②Master側で、「SELECT * FROM pg_stat_replication」を実行して、
>>>>> レプリケーションの状態を確認する
>>>>> といった調査方法があると思います。
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> (2013/06/17 18:25), Keiji Yoshida wrote:
>>>>>> 吉田と申します。
>>>>>> お世話になります。
>>>>>> 初めて投稿させて頂きます。
>>>>>>
>>>>>> 現在、Rails+PostgreSQL(9.1.4)で構築されたWEBアプリケーションを、約半年間運用しています。
>>>>>>
>>>>>> DBサーバは2台あり、ストリーミング・レプリケーションでデータの同期を行っています。
>>>>>>
>>>>>> 今までは問題なかったのですが、昨日急に、サーバ間でのデータの同期が行われなくなってしまいました（片方のサーバのみデータが更新される状態となってしまいました）。
>>>>>> 更新系SQLは、両方のサーバへ発行される構造となっておりましたため、
>>>>>> あるデータは１号機のみに存在し、またあるデータは２号機のみ存在するという、どちらのDBサーバも、独自のデータを抱える状態となってしまいました。
>>>>>>
>>>>>> どちらのDBサーバへ発行されたSQLも正常終了しているため、両方ともPostgreSQLのプロセスは正常に稼働していると認識しています。
>>>>>>
>>>>>> 現在、以下の不明点を抱えております。
>>>>>>
>>>>>> （１）なぜ同期できなくなったのか？
>>>>>> （２）どのように同期処理を再開させるか？
>>>>>> （３）どのようにデータを復旧させるか？
>>>>>>
>>>>>> 上記不明点の解消を試みておりますが、どのように調査を進めたら良いかが分からず、作業が止まっている状態です。
>>>>>>
>>>>>> 「こう調査すべき」、「このログを確認すべき」、「このようなことが原因として考えられるため、この点を確認すべき」など、もし考えられる点がございましたら、お知恵をお借りできませんでしょうか？
>>>>>>
>>>>>> お忙しいところお手数おかけ致しますが、何卒よろしくお願い申し上げます。
>>>>>>
>>>>>> 吉田
>>>>>>
>>>>>>
>>
>
pgsql-jp メーリングリストの案内