Heroku Postgres​ のログは、アプリケーションのログストリームにまとめられ、公開されます。heroku logs​コマンドを使って​ postgres​ プロセスのフィルタリングを行うことで Heroku Postgres イベントを隔離できます。

$ heroku logs -p postgres -t
2012-11-01T17:41:42+00:00 app[postgres]: [15521-1]  [CHARCOAL] LOG:  checkpoint starting: time
2012-11-01T17:41:43+00:00 app[postgres]: [15522-1]  [CHARCOAL] LOG:  checkpoint complete: wrote 6 buffers (0.0%); 0 transaction log file(s) added, 0 rem...

システムレベルの Postgres アクティビティを見るだけでなく、これらのログはアプリケーションの Postgres 使用を把握する場合やよくあるエラーを診断する場合にも役立ちます。この記事では、よくあるログ文、それぞれの目的、そして取ることができる処置について説明しています。

LOG: 期間: 3.565 s …

[12-1] u8akd9ajka [BRONZE] LOG:  duration: 3.847 s  statement: SELECT  "articles".* FROM "articles"...

2 秒より長くかかっているクエリはログ記録されるため、見つけ出して最適化できます。これらの長時間クエリが少数であればアプリケーションのパフォーマンスに悪影響がありませんが、大量になるとそうといえません。

理想的には、頻繁に使用されるクエリを最適化して実行するときに 10 ms 以上かからないようにする必要があります。クエリを最適化するには、一般にはインデックスを追加​してデータベースが連続してスキャンされないようにします。EXPLAIN​ を使用してクエリを診断します。

LOG: チェックポイント開始…

2012-11-01T17:41:42+00:00 app[postgres]: [15521-1]  [CHARCOAL] LOG:  checkpoint starting: time
2012-11-01T17:41:43+00:00 app[postgres]: [15522-1]  [CHARCOAL] LOG:  checkpoint complete: wrote 6 buffers (0.0%); 0 transaction log file(s) added, 0 rem...

LOG: checkpoint starting​ および対応する LOG: checkpoint complete​ 文は Postgres の Write-Ahead Logging (WAL)​ 機能の一部です。Postgres が自動的にトランザクションログにチェックポイントを時々挿入します。詳細はこちら​をご覧ください。

これらの文は通常動作の一部であり、必要な操作はありません。

LOG: クライアントからデータを受信できませんでした: 接続が切断されました

クライアント接続で予期しない EOF​ を参照してください

LOG: クライアント接続で予期しない EOF

app[postgres]: LOG:  could not receive data from client: Connection reset by peer
app[postgres]: LOG:  unexpected EOF on client connection
heroku[router]: at=error code=H13 desc="Connection closed without response" method=GET path=/crash host=pgeof-1234567890ab.herokuapp.com dyno=web.1 connect=1ms service=10ms status=503 bytes=0
heroku[web.1]: Process exited with status 1
heroku[web.1]: State changed from up to crashed

このログは Postgres から送出されていますが、エラーの原因はデータベースそのものと何の関係もありません。アプリケーションが Postgres との接続中にクラッシュしてしまい、データベースとの接続を除去しませんでした。クライアント (アプリケーション) は接続を正しく終了しないで消えてしまったことを Postgres が認識して、それを伝えるメッセージをログ記録しました。

アプリケーションのバックトレースが表示されない場合は、実際に stdout (ファイルの代わりに) にログしていることと stdout が同期されていることを確認する必要があります。

LOG: [Errno 104] 接続が切断されました

このエラーは、いくつかある断続的なネットワーク接続問題の 1 つが原因で発生します。これが断続的にしか起きない場合は、Connect がエラーを検出してその後すぐに同期操作を再試行します。このエラーメッセージが表示される場合は、根本的原因においてエンジニアによる解決が必要なことがあるため、Heroku サポートにお問い合わせください。

FATAL: ロールの接続が多すぎます

FATAL:  too many connections for role "[role name]"

このエラーはユーザーあたりの最大接続限度が 20 である Essential 層のデータベース​プランで発生します。このエラーを解決するには、データベースへのいくつかの接続を閉じます。バックグラウンド Worker を停止するか、dyno 数を減らしてください。あるいはアプリケーションが長い間に接続リークを作成している場合はこのアプリケーションを再起動してください。Rails アプリケーションで接続を処理する場合の説明は、こちら​を参照してください。

FATAL: データを受け取れませんでした …

FATAL: could not receive data from WAL stream: SSL error: sslv3 alert unexpected message

プライマリデータベースからフォロワーへの複製​が中断しました。原因は、一時的なネットワークエラーか SSL が再ネゴシエーションに失敗したためです。これは一時的な問題であり、Postgres は自動的に復旧します。

フォロワーが遅れている現在のコミット数を調べるには、heroku pg:info​ を使用します。各フォロワーの “Behind By” (残り数) エントリは、フォロワーがマスターに対して遅れているコミット数を示します。

$ heroku pg:info --app example-app
=== HEROKU_POSTGRESQL_WHITE
...
Following    HEROKU_POSTGRESQL_LAVENDER (DATABASE_URL)
Behind By    125 commits

FATAL: ロール “ロール名"…

FATAL: role "u8akd9ajka" is not permitted to log in (PG::Error)

このエラーは、存在しなくなった資格情報を使用してデータベースに接続しようとしている場合に発生します。これは、次のようないくつかの理由で発生することがあります。

• データベースの資格情報がローテーション​されているが、接続するために古い資格情報を引き続き使用している。Essential 層のデータベース​の特定のケースでは、資格情報は定期的なメンテナンスタスクの一部としてローテーションされます。
• Essential 層のデータベース​がプロビジョニング解除されたが、そのデータベースに引き続き接続しようとしている。

FATAL: 管理者コマンドのため接続を中断しています

FATAL: terminating connection due to administrator command

このメッセージは、バックエンド接続が中断されたことを示します。これは、ユーザーが pg:kill​ をコマンドラインクライアントから発行するか、同じように SELECT pg_cancel_backend(pid);​ を psql セッションから実行すると発生することがあります。

FATAL: 残りの接続スロットが非複製のスーパーユーザー接続用に予約されています

FATAL: remaining connection slots are reserved for non-replication superuser connections

各データベースプランの最大可能接続数は、プランにより変わります。このメッセージは、アプリケーションに許可された最大数に到達しており、残りの接続がスーパーユーザーアクセス用に予約されている (Heroku Postgres スタッフに限定) ことを示します。特定のプランの接続限度の詳細は、「Heroku Postgres 本番プランの技術的特性​」を参照してください。

FATAL: ホスト "…"、ユーザー "u…"、データベース "d…” の pg_hba.conf エントリがありません。SSL がオフ

SSL がないデータベース接続を確立しようとしています。SSL はすべての接続で必要です​。postgres ドライバーのドキュメントで暗号化接続の確立方法についてご覧ください。

一時ファイル: パス “ファイルパス"、サイズ "ファイルサイズ”

temporary file: path "base/pgsql_tmp/pgsql_tmp23058.672", size 1073741824

ここでは、一時ファイルのサイズが 10240 キロバイトを超えると Postgres がファイル名とサイズをログ記録するように設定しています。一時ファイルが作成されるのは、ソート、ハッシュを実行しているとき、あるいは一時クエリの結果に対してです。そして、ファイルが削除されるとファイルごとにログエントリが作成されます。

大量の一時ファイルが作成されるとクエリのパフォーマンスに影響が及ぶため、このログエントリを参考にしてください。

PGError: permission denied for relation

​ (PGError: 関係の許可が拒否されました)

PGError: ERROR:  permission denied for relation table-name

Heroku Postgres の Essential 層のデータベース​に行制限がかけられています。行制限を超えて​データを挿入しようとすると、このエラーが表示されます。Standard 層以上のデータベースにアップグレード​してこの制約を除去するか、合計行数を減らしてください。

PGError: operator does not exist

​ (PGError: 演算子が存在しません)

PGError: ERROR:  operator does not exist: character varying = integer

Postgres はデータ型に関して MySQL や SQlite よりセンシティブです。演算子がサポートされていないデータ型に適用されると、Postgres がチェックしてエラーをスローします。たとえば、文字列と整数の比較をキャスティングなしではできません。

演算子がデータ型にとって十分であること、または必要な型キャスト​が適用されていることを確認してください。

PGError: relation “table-name” does not exist

​ (PGError: 関係 “テーブル名” が存在しません)

PGError: ERROR: relation "documents" does not exist

このエラーは、テーブルが存在しないとき Postgres が表示する標準のメッセージです。これは、クエリが参照しているテーブルがデータベースにないことを意味します。

移行が正常に実行されていること、存在するテーブルを参照していることを確認してください。

PGError: column “column-name” cannot…

​(PGError: 列 “列名” が…できません)

PGError: ERROR: column "verified_at" cannot be cast to type "date"

このエラーは、そのテーブル内のすべての行の値を指定した型にキャストする方法を Postgres が知らないときに発生します。ほとんどの場合、これは整数または文字列がその列内にあることを意味します。

影響を受けるすべての列の値を調べて、必要な型に変換できない値を手動で除去するか変換してください。

PGError: SSL SYSCALL error: EOF detected

​ (PGError: SSL SYSCALL エラー: EOF が検出されました)

同様の根本原因を持つエラーとして、以下があります。

• no connection to the server
• SSL error: decryption failed or bad record mac
• could not receive data from server: Connection timed out

これらのエラーは、クライアント側のワイヤプロトコル違反を示します。これが発生する理由は、次の 2 つのうちのいずれかです。

• Postgres 接続が複数のプロセスまたはスレッド間で共有されている。体表的な違反側は Resque Worker または Unicorn です。必ずフォークまたはスレッドが初期化された後で PG 接続を正しく確立​して、この問題を解決してください。
• 突然のクライアント (アプリケーション側) の切断。これは、アプリのクラッシュから、一時的なネットワーク障害まで、さまざまな理由が原因で発生します。アプリが Postgres に対してクエリを再発行しようとすると、接続が失われ、その結果クラッシュします。Heroku がクラッシュを検出したら、その dyno を終了して新しい dyno を起動すると、接続が再確立されます。

PGError: prepared statement “a30” already exists

​ (PGError: プリペアドステートメント “a30” がすでに存在します)

このエラーは、上記と似ています。プロトコル違反はありません。しかし、クライアントが元のプリペアドステートメントを除去せずに、既存のプリペアドステートメントと同じ名前を使用して、誤ってセットアップしようとしています(エラーの中のプリペアドステートメントの名前は変化します)。

この原因も、一般には複数のプロセスまたはスレッド間で Postgres 接続の共有が適正に行われていないこと が挙げられます。

PGError: could not write block blockid of temporary file: No space left of device

​ (PGError: 一時ファイルのブロック blockid を書き込めませんでした: デバイスにスペースが残っていません)

クエリを実行できません。ディスク上のスペースが十分でないので、クエリを実行するために必要な一時テーブルを保管することができません。データベースセッションの終了時に、一時テーブルが自動的に削除されます。

通常の原因は、複雑なサブクエリが多すぎるクエリや DISTINCT​ を使用するクエリです。当社のドキュメント​の中にあるいくつかのヒントが役に立ちます。

Out of memory errors

​ (メモリ不足エラー)

メモリ不足 (OOM) エラーは、一般にはデータベースを動かしているサーバーがデータベース接続やそのキャッシュに新たなメモリを割り当てられなくなったときに発生します。問題が何回発生しても OOM エラーとして表示される可能性があります。Heroku Postgres プランを高いレベルに引き上げる前に、問題診断のあらゆる領域を調べてください。

Extremely complex querying (極端に複雑なクエリ)

結合、ソート、ハッシュベースの操作が Postgres の作業中メモリを圧迫します。どのようなデータベースであっても、同時接続数が多いとこの問題が悪化する可能性があります。ソート操作は ORDER BY​、DISTINCT​、およびマージ結合により定義されています。ハッシュベース操作は、一般には IN​ サブクエリの処理、ハッシュベース集約、ハッシュ結合の結果です。クエリは複雑になればなるほど、これらの操作をより多く使う可能性が高くなります。クエリのボトルネックを理解するには、最初はクエリの説明プランや Heroku Postgres Expensive Query 機能を使用することをお勧めします。

Ruby, ActiveRecord 、and prepared statements (Ruby、ActiveRecord およびプリペアドステートメント)

プリペアドステートメントは、Postgres を使用するときに適したメカニズムです。これらを使うことのメリットは、データベースがステートメントを極めて高い効率で実行できることです。残念ながら、一般向けの Web フレームワークの一部である多くの ORM (すなわち Ruby on Rails フレームワークの ActiveRecord) がプリペアドステートメントを効果的に作成するわけではありません。作成されるクエリが任意の数のパラメータを含むことができる場合、論理的クエリが同一なものに対して複数のプリペアドステートメントが作成されます。たとえば、Heroku アプリケーションがそのユーザーにプロダクトテーブルのプロダクトを ID で選択できるようにするとします。顧客 1 が 2 つのプロダクトを選択すると、ActiveRecord がクエリを定義してプリペアドステートメントを作成します。

SELECT * FROM products WHERE id in ($1, $2);

顧客 2 が、同じアプリケーションの同じクエリで 2 つのプロダクトでなく 4 つのプロダクトを選択するよう決めると、新しいプリペアドステートメントが作成されます。

SELECT * FROM products WHERE id in ($1, $2, $3, $4);

このコードパスに関するアプリケーションの中の問題は、顧客が IN​ 句についてデータを選択する方法についていくつかの変動性があることです。ActiveRecord が IN​ 句の項目数に基づいてクエリをパラメータ化します。この結果として大量のプリペアドステートメントがキャッシュされてしまい、最後はシステム上のメモリを使い過ぎてしまうことになります。これがご使用のアプリケーションに発生している場合は、プリペアドステートメントを無効にするかキャッシュされるプリペアドステートメントの数を調整することを検討してください。

Rails 4.1+

プリペアドステートメントを無効にする​には、config/database.yml​ ファイルを更新して prepared_statements​ パラメータを含むようにしてください。

production:
  adapter: postgresql
  prepared_statements: false

プリペアドステートメントキャッシュのサイズを調整する​には、config/database.yml​ ファイルを更新して statement_limit​ パラメータを含むようにしてください (デフォルトを 1000 にする)。

production:
  adapter: postgresql
  statement_limit: 200

Rails 2、3 および Rails 4.0

Rails 3 でプリペアドステートメントを無効にするには、イニシャライザを使用する必要があります。config/initializers/disable_prepared_statements.rb​と呼ばれるファイルを作成します。このファイル内で、接続オプションを更新してプリペアドステートメントを無効にします。

ActiveRecord::Base.establish_connection(
  ActiveRecord::Base.remove_connection.merge(
    :prepared_statements => false
  )
)

マルチプロセス Web サーバーを使用している場合は、Web サーバーの after fork ブロックのプリペアドステートメントを無効にする​必要もあります。

接続数が多すぎる

Heroku Postgres にはプランタイプに応じた接続制限がありますが、指針​として使用してください。Postgres 内の各接続が相当の RAM を使用します。任意の時点で作成された量が多すぎると、それが原因でデータベースにとって問題になる場合もあります。このような状況になったら、本番グレードの接続プーラを使用して RAM で接続を開いたり閉じたりする際の圧力が起きないようにする必要があります。

データベースプランが小さすぎる

場合によっては、選択したデータベースプランがそこに存在するワークロードにとって小さすぎることがあります。OOM エラーを除去するためのほかの手段をすべて調べている場合は、プライマリデータベースを次のプランレベルまでアップグレード​する必要があるかもしれません。技術的に優れたアプリケーションは、Postgres が管理するキャッシュからほとんどのクエリ結果を返します。一般に、実行しているクエリに基づいてキャッシュヒット率​が低下し始めたら、プランを高くすることを検討する必要があります。