Postgresロギングエクスペリエンス

PostgreSQLロギングシステムを開発しました...はい、ElasticSearchのアドオン（GrayLog2、Logstash）があり、他の同様のツールがあり、知らないものがあることを知っています。 ただし、このツールは現在PostgreSQL上に構築されており、動作します。



週の作業中、クラウド内のすべてのVLSIサービスから1日あたり110億件以上のレコードを受け取り、3日間保存します。同時に占有されるスペースの総量は32 Tbを超えません。 これはすべて、PostgreSQL 9.6で8台のサーバーを処理します。 各サーバーには、24のコア、16 GBのRAM、および4つの1 TB SSDドライブがあります。

誰がこれを必要としますか？

当社のサービスは、40％Python、50％C ++、9％SQL、1％Javascriptで記述されています。 200を超えるサービスがありますが、多くの場合、さまざまな種類の問題（登録済みエラーの分析や論理的な問題の分析）を迅速に整理する必要があります。 作業を監視するだけで、意図したシナリオに従ってすべてが進行しているかどうかを確認する必要がある場合があります。 異種グループは、開発者、テスター、サーバー管理者、場合によっては管理者など、すべてをこのようにして実現できます。 したがって、これらすべてのグループに理解できるツールが必要です。 独自のロギングシステム、またはWebサービスへのhttpリクエストをトレースするシステムを作成しました。 これは一般的なロギングの普遍的なソリューションではありませんが、作業モデルに適しています。 実際にログを表示することに加えて、収集したデータの他の用途があります-これについては次のセクションで詳しく説明します。

ログの他のアプリケーション

Webサービスへのhttpリクエストは、分析の便宜上、コールツリーとして提示できます。 簡略化すると、このツリーは次のように表すことができます。



サービスAのリクエスト

|- スレッドハンドラー番号1

| |-SQLデータベースクエリX

| |- 内部サブクエリ1

| | |-Redis Yへのリクエスト

| | |-同期HTTPサービス要求B

| |- 内部サブクエリ2

| | |-SQLデータベースクエリX

| | |-同期HTTPサービス要求C

|- ストリーム番号2

|-非同期サービス要求W



画面レポートは図を参照してください。 1、そのような木を表し、より雄弁に話す。 各ノードで、実行にかかった時間、親からの割合が表示されます。 リクエストでボトルネックを検索できます。 リンクを使用すると、他のサービスのサブクエリのログを表示できます。 レポートは非​​常に便利で、ほぼ瞬時に作成されます。 もちろん、コールツリーに何百万ものレコードが含まれる場合は例外があります（そうです、いくつかあります）。 ここではプロセスに時間がかかりますが、ツリー内のエントリは最大500万件取得できます。 このレポートは、ジョブプロファイリングの目的で最もよく使用されるため、「シングルコールプロファイリング」と呼びます。





画像はクリック可能で、ウェブブラウザの現在のタブで開きます。

図 1.単一の呼び出しのプロファイリング



単一の呼び出しではなく、同じ種類の呼び出しの統計サンプルで一般的なクエリのプロファイリングを実行する必要がある場合があります。 これを行うために、そのような呼び出しを1つのツリーに結合し、そのノードと葉を親呼び出しの時間の％での面積を持つ正方形の形で表示するレポートがあります。 図の画面を参照してください。 2





画像はクリック可能で、ウェブブラウザの現在のタブで開きます。

図 2.複数のサンプル呼び出しのプロファイリング



ネットワーク遅延の存在をキャッチできるレポートがあります。 これは、サービスAが別のサービスBに要求を送信し、応答が100ミリ秒で受信され、サービスBの要求が10ミリ秒実行され、90ミリ秒がどこかで消えた場合です。 この欠落時間を「ラグ」と呼びます。 遅延レポート画面を以下の図に示します。 3。





図 3.ログレポート



これらのログレポートに加えて、他のレポートを使用しますが、それらは特定のレポートほど広くはありません。

すべての仕組み

Webサービスは、ピアに依存しないノードで構成されています。 各サービスノードは、制御プロセスといくつかのワークプロセスで構成されています。 制御プロセスは、クライアントのhttp-requestsを受け入れて処理待ちのキューに入れ、クライアントに応答を送信します。 ワークフローは、制御プロセスキューからリクエストを取得し、実際の処理を実行します。 PostgreSQLデータベース、別のWebサービス、Redisなどにアクセスできます。





図 4.プロセスレベルでのWebサービスノードのアーキテクチャ



サービスへの各リクエストには次の属性セットがあり、これらをログに書き込む必要があります。

• リクエストの一意の名前、「サービスメソッド」と呼びます
• リクエストが最終的に到着したサービスノード
• イニシエーターIPを要求する
• ユーザーセッションID
• 要求カスケードのUUID（要求カスケードは、サービスの外部からの1つの要求が他のサービスへの一連の要求を生成するときです）
• サービスノードのリクエスト番号-サービスが再起動されると、リクエスト番号はリセットされます
• リクエストを処理したワークフローの番号

クエリ内でさまざまなイベントが発生します。PostgreSQL、Redis、lickHouse、RabbitMQへの呼び出し、他のサービスへの呼び出し、サービスの内部メソッドへの呼び出し。 これらのイベントを次の属性で記録します。

• イベントが発生した日時（ミリ秒単位）
• イベントのテキストは最も重要な部分であり、他の属性に適合しないすべてのものがそこに書き込まれます：SQLクエリのテキスト、Redisへの呼び出しコマンド、別のサービスからの呼び出しのパラメーター、RabbitMQを介した非同期呼び出しのパラメーターなど
• ミリ秒のイベント期間
• イベントが発生したストリーム番号
• プロセッサティック-同じ日付と時刻、最大ミリ秒の精度を持つイベントのシーケンスを決定するために必要
• イベントタイプ：正常、警告またはエラー

したがって、データ構造は下図のように最初の近似に見えます。





図5 ログを保存するための基本構造の最初のバージョン



ここに写真で：



サービス - サービスの名前を持つテーブル、それらのいくつか、数百があります

ServiceNode-サービスノードを持つテーブル。数千のレコードが含まれ、複数のノードを1つのサービスに関連付けることができます

メソッド - メソッドの名前を持つテーブル、数千もあります

ログ -ログ-実際には、要求データとそのイベントが書き込まれるメインテーブル。 テーブルは、クエリで大きなテーブルを結合するのに時間を無駄にせず、余分なインデックスを保持しないように、意図的に非正規化されています。 たとえば、クエリ属性を別のテーブルに配置できますが、データを追加および取得するロジックはより複雑になります。 UUIDとユーザーセッション識別子を作成することは可能ですが、フィールドごとに新しいテーブルの新しいフィールドにインデックスを作成し、ログテーブルに外部キーを使用してインデックスを作成し、新しいテーブルに不要なプライマリキーを作成する必要があります。



Webサービスは、http、nginx（バランシング用）を介してログを送信します。 サービスログのノードはそれらを処理し、データベースに書き込みます。 スキームを以下に示します。





図 6.ログサービスにログを送信するためのスキーム



図7は、モスクワサービスのfix-osr-bl17.unix.tensor.ruノードにリクエストが記録される画面を示しています。 要求は「VLSI。Perform Action」と呼ばれ、その番号は15155です。UUIDは提供しません。要求の名前の上に表示されます。 最初は、「[m] [start] Edo→EDOCertCheckAttorney」という形式のメッセージを持つレコードです。これは、引数のないサービスの内部メソッドへの呼び出しの開始イベントの固定です。 それに続いて、2番目のサブコール「[m] [start] Document.Incoming / 1（234394;）」が値234394の1つの引数とともに開始されます。次に、キャッシングサービスのノードから呼び出しが行われ、行はこの[[rpc call] ...など





画像はクリック可能で、ウェブブラウザの現在のタブで開きます。

図 7.ノード「fix-osr-bl17.unix.tensor.ru」の「VLSI.FollowAction」メソッドに応じたログ画面の画面



存在してから1年半の間、このデータベースとサービススキームは大きな変更を受けていません。 どのような問題に遭遇しましたか？ 最初に、1つのデータベースに書き込みを行いましたが、最初の数日から次の事実に遭遇しました。

• INSERTを使用して通常の方法でデータベースに書き込むことはできず、COPY命令のみに切り替えました。
• 古いデータをDELETEを介して通常の方法で削除するのは非現実的であり、TRUNCATEに切り替えました。 この命令は、テーブル全体に対して十分に迅速に動作し、ファイルをほぼゼロサイズに切り捨てます。 ただし、無関係なデータのみが削除されるように、月の各日に独自のテーブルセクションを用意する必要がありました。 とにかくTRUNCATEには不快な瞬間が1つあります-PostgreSQLサーバーがプレート上のラップアラウンドプロセスを防ぐために自動バキュームを開始することを決定した場合、TRUNCATEはラップアラウンドを防ぐための自動バキュームが終了するまで実行されず、かなりの時間動作します。 したがって、クリーニングの前に、このプロセスを打ちます。
• トランザクションログは必要ありません。CREATEUNLOGGEDを使用してテーブルを作成し始めました。
• ディスクへの同期書き込みは不要です-fsync = offおよびfull_page_writes = offを実行しました。これは許容されます。もちろん、ディスクによるデータベースの停止は可能ですが、非常にまれです。

これらの操作は、PostgreSQLサーバーをかなりよくオーバークロックしました。 synchronous_commitおよびcommit_delayパラメータも変更しようとしましたが、この場合、それらはパフォーマンスに顕著な影響を与えませんでした。



月の各日ごとにテーブルをデータセクションに分割すると、新しいデータベーススキームは次のようになります。





図 8.毎月のテーブルを備えたベースのスキーム



時間がたつにつれて、ログのボリュームが絶えず増大しているため、1つのデータベースにデータを保存できなくなりました。 また、ログサービスの最初のプロトタイプは、分散バージョン用にやり直されました。 これで、ログサービスの各ノードがいくつかのデータベースの1つに書き込み、ラウンドロビンアルゴリズムに従って記録のベースを選択しました。 十分便利でした。 統計的に、各データベースは同じ負荷を受け、負荷は水平方向にスケーリングされ、データベース上のデータボリュームはGB以内に一致しました。 1つのPostgreSQLサーバーの代わりに、5がログに対して機能するようになりました。ログサービスのノードのスキームは次のようになりました。





図 9.複数のデータベースを使用するログサービスのスキーム



図から、各サービスノードが複数のデータベースへの接続を保持していることがわかります。 もちろん、このようなスキームには欠点があります。 ベースに障害が発生した場合、または「バカ」になった場合、サービス全体が機能しなくなりました。 新しいサービスノードを追加すると、PostgreSQLサーバーへの接続数が増加しました。



多数の接続を介して同じテーブルに同時に書き込むと、ロックの数が多くなり、書き込みプロセスが遅くなります。 ベースあたりの接続数の増加は、TRANSACTON MODEモードでpgBouncerを使用して制御できます。 ただし、奇跡はありません。この場合、リクエストを完了する時間はわずかに長くなります。 それでも、作業は追加のリンクを経由します。 さて、TRANSACTONモードでは、データベースへの接続が頻繁に切り替えられますが、これも最適な方法で作業に影響を与えることはありません。



私たちはこのオプションにもう1年間取り組み、最終的には1つのサービスノードがpgBouncerを使用せずに1つのデータベースと直接連携するスキームに移行しました。 2倍の効果があり、その時点でさらに3つの拠点が追加され、8つの拠点がありました。今日まで生きている私たちは非常に多くいます。



このスキームから、さらにいくつかのプラスを得ました。 新しいノードが追加されても、データベースへの接続数は増加しません。 データベースが鈍化し始めると、nginxは他のサービスノードに負荷を分散します。





図 10.現在のログサービススキーム：1つのノード-1つのデータベース



さらに、PostrgeSQLサーバーの最高のパフォーマンスを実現し、Centos 7で実行するために、デッドラインスケジューラーをインストールしました。 また、ダーティキャッシュのサイズも削減しました。 このパラメーターはvm.dirty_background_bytesであり、キャッシュのサイズを設定します。システムは、キャッシュのサイズを設定して、システムがディスクにフラッシュするバックグラウンドプロセスを開始します。 ボリュームが大きすぎる場合、ピーク負荷がディスクに到達します-平滑化されるようにパラメーターを選択する必要があります。



パフォーマンスの問題に加えて、ストレージスペースの不足という深刻な問題があります。 現在、32 TBの費用がかかります。 これで3日間は十分です。 ただし、ログ記録で数回のピークバーストが発生することがあり、その場所はより早く終了します。 スペースを増やすことなくこれに対処する方法は？ 私たちは次のようにタスクを定式化しました。詳細が損なわれますが、少なくともいくつかのログを残す必要があります。



これに従って、1日あたりのログテーブルを3つのテーブルに分割しました。 最初は0時間から8までの期間、2番目は8から16まで、3番目は16から24までの期間のデータを保存します。 これらの各テーブルは、さらに3つのセクションに分割されました。 セクションは、ログの3つの重要度レベルに対応しています。 最初のレベルには、リクエストのファクト、その期間（詳細なし）、およびリクエスト中に発生したエラーのファクトに関する基本情報が格納されます。 2番目のレベルには、サブコールとSQLクエリに関する情報が格納されます。 3番目のレベルには、最初の2つに含まれていないすべてのものが格納されます。 ログサービスノードは、記録用に残っている空き領域が15％未満であることを認識すると、3番目のレベルで最も古いセクションのクリーニングを開始します。 録音するのに十分なスペースができるまで続きます。 3番目のレベルのセクションがなくなっても、まだ十分なスペースがない場合は、2番目のレベルのセクションのクリーニングが最初の最悪の場合に開始されますが、これは発生していません。



それ以前は、ログの記録についてでしたが、後で読むために記録を行います。 一般に、読み取りのために、期間に応じて、テーブルの必要なセクションが計算され、クエリに代入されます。 セクションを操作するPostgreSQLの現在のメカニズムは動作不能で不便です。使用しません。 ログへのクエリの結果はどのように見えるか、図に示しました。 7.リクエストの基本要件：

• それは可能な限り高速でなければなりません
• クエリの結果はナビゲーションになります

両方の要件を満たすことは100％不可能ですが、要求の80％に実装できます。 これが私たちがしたことです。 Logテーブルの11のインデックスに適合する約20のクエリプロファイルが判明しました。 残念ながら、インデックスはエントリの追加を遅くし、スペースを盗みます。 このバージョンでは、これらのインデックスはデータの場所に匹敵する場所を取り去ります。



ログを受信するためにユーザーが指定した期間全体のデータを選択することはありません。これは非効率的です。 多くの場合、クエリの最初または最後のページを表示するだけで十分です。 まれに、ユーザーは次のページに移動できます。 例を使用して、ログ選択アルゴリズムを検討してください。 1ページに500レコードの出力で1時間のデータをリクエストしましょう：



最初に、1 msの期間クエリを作成し、すべてのログデータベースと並行して試行します。 すべてのデータベースから結果を受け取った後、リクエストを結合し、そのデータを時間でソートします。 500レコードが蓄積されない場合、1ミリ秒シフトし、期間を2倍に増やして、表示に必要な500レコードを収集するまで手順を繰り返します。



多くの場合、この単純なアルゴリズムでデータをすばやく取得できます。 ただし、期間全体で数百万件のレコードを選択できるフィルタリング条件があり、その中のいくつかを必要とする場合、たとえば、ログイベントの「メッセージ」フィールドで特定の、めったに見られない行を探している場合、結果はすぐには返されません。



すべてがバラ色ですか？ 残念ながら、すべてではありません...長時間にわたって結果が得られないようにクエリを設計し、そのようなクエリをデータベースサーバーに入力して、それらが機能しないようにすることができます。 これは内部的に使用されるため、意図的なブロックを除外します-そのような人々を簡単に計算し、ランダムなブロックのみが残ります。 PostgreSQLコマンド「SET LOCAL statement_timeout TO ...」により、クエリのタイムアウトによって事故から身を守ります。1つのデータベースに対するすべてのクエリの合計時間には1200秒の時間が与えられます。 データベースへの最初のクエリには1200秒、2番目には1200秒、最初のクエリに費やした時間を引いたタイムアウトなどが設定されます。期限に間に合わなかった場合は、フィルタリング条件を絞り込むようにエラーが返されます。

他のログストレージシステムにアクセスしようとする

ClickHouseのログの保存に真剣に取り組みました。 MergeTreeエンジンと連携しました。 予備テストは素晴らしく、システムを実稼働前に展開しました。 ここでは記録速度に関する質問はまったくありませんでした-保管場所でのゲインは最大7倍でした。 2つのClickHouseノードがデータを処理し、それぞれが20コアと64 GBのメモリを備えていました。 ちなみに、運用前のPostgreSQLは要件が少し控えめで、サーバーあたり8コアと32 GBのメモリがありました。 しかし、ClickHouseのストレージの減少が賄われたとしても、PostgreSQLに比べてClickHouseへの読み取り要求が多少低下することを許す用意ができていました。



ClickHouseサーバーへのデータ選択要求の数が特定の数を超えるとすぐに、それらは急激に減速しました。 これを打ち負かすことはできませんでした。 ClickHouseは放棄されなければなりませんでした。 おそらく、読み取り要求が遅くなる理由は、ClickHouseテーブルに作成できるインデックスが1つだけだったためです。 多くのログクエリプロファイルがこのインデックスに適合せず、データの読み取りが遅くなりました。



ClickHouseに加えて、彼らはElasticSearchを狙い、1つのPostgreSQLログデータベースから本番（〜4Tb）のデータを注ぎ込みました。これは、PostgreSQLに比べて約15％の利益をもたらしました。エラスティックで。



著者：アレクセイ・テレンティエフ