パフォーマンストラブルシューティングガイドIssue この記事では、ServiceNow プラットフォームのパフォーマンスに関する問題をトラブルシューティングする方法を紹介します。存在する可能性のあるあらゆる問題を追跡するために必要な情報をすべて網羅しているわけではありません。Web アプリケーションのパフォーマンスについて考えるための基本的なフレームワークを理解し、ServiceNow アプリケーションのパフォーマンスに関する既知の問題を追跡するためのツールを利用できるようになることが目標です。 目次 はじめに ビジネス測定基準：重要なことに焦点を当てるトラブルシューティングの方法論 問題のスコーピングリソースの制約の特定 パフォーマンスグラフトランザクションログファイルシステムログと Unix ユーティリティメモリにもデータベースにも制約がないと思われる場合 CPUネットワークキャッシュフラッシュブロッキングセマフォと同時実行トランザクション 原因の特定 JVM メモリー JVM メモリーの突然の不足JVM メモリーリークJVM メモリーの全般的な不足 データベースの速度低下 データベースパフォーマンスの突然の低下データベースパフォーマンスチューニング 修正 スレッド スレッドダンプファイルシステムログ内のスレッドのトレース 問題の再現/単一ページのパフォーマンスのデバッグ セッションのデバッグ 変更内容の観点からのパフォーマンスの問題の調査 はじめに パフォーマンスの問題を解決しようとする前に、アプリケーションスタックとシステムの動作についてできるだけ理解しておくことをお勧めします。技術者は ServiceNow プラットフォームがどのように動作するかを理解すればするほど、パフォーマンスタイプの問題の根本原因を突き止める可能性が高くなります。 パフォーマンスの問題は、製品のどこにでも現れる可能性があります。技術者は、すべてを知るのではなく、ServiceNow プラットフォーム、アプリケーション、お客様がどのように使用するかなどについて知る必要があります。新しい概念の掘り下げにかなりの時間を費やす必要があります。パフォーマンスのトラブルシューティングには時間がかかる場合があります。多くの質問をすることは役に立ちますが、最終的に成功を収めるには、自分の学習パスに集中し、意識的に学習に取り組み続ける必要があります。このセクションでは、ServiceNow プラットフォームのパフォーマンスについて考えるための優れた基盤となる、いくつかの抽象的なコンセプトを説明します。 ビジネス測定基準: 重要なことに焦点を当てる ビジネス測定基準は、ユーザーエクスペリエンスと使用状況を直接測定するものです。パフォーマンスと機能停止に関係する主なビジネス測定基準は、応答時間です。ビジネス測定基準の別の例は、1 分あたりのトランザクション数です。ビジネス指標は、ユーザーエクスペリエンスに直接的な見通しを提供するため、ビジネス指標に重点を置いています。これは、メモリ使用量や入出力 (I/O) 待機時間のようなサーバー測定基準とは対照的です。サーバー測定基準ではサービス低下の原因に関するインサイトが得られますが、ビジネス測定基準が与える影響ほどの重要性はありません。 アップタイムは、お客様が確認できるビジネス測定基準のもうひとつの例です。機能停止の大部分はパフォーマンスの低下が原因であるため、トランザクションの応答時間を確認することで、精度と包括性の両方の観点から、ユーザーエクスペリエンスをより的確に把握することができます。 トラブルシューティングの方法論 情報を収集する：解決しようとしている問題を明確に理解します。ユーザーが確認した症状やビジネス測定基準まで遡って把握する必要があります。問題が発生している原因を特定する前に、問題の内容を理解することが重要です。問題が発生している理由を特定する前に、問題の内容を理解することが重要です。処理速度が低下しているのはどのユーザーのところか、そのユーザーは何をしようとしていたのか、問題はどこで発生したのか、正確にいつ発生したのか、などを確認します。理論を構築する：問題の原因となった可能性のある理論を構築します。これは目的を持って行う調査です。やみくもに探すだけでは、見つかるものも見つかりません。パフォーマンスの問題をトラブルシューティングする場合、一般的に適用できる理論がいくつかあります。これらは必ずしも正しいとは限りませんが、常に確認する価値があります。 何かが変わった: パフォーマンスが良かったのに今は悪い場合は、アプリケーションを最初からデバッグするよりも、何が変わったのかを理解する方が速いことがよくあります。既知の問題：お客様に問題が生じた場合、他の誰かが既に同じ問題を経験していると考えてよいでしょう。既知の問題に対してお客様の症状を調査する方法では、パフォーマンス低下の原因となったリソース制約を特定した後、そのタイプのリソース競合に関する既知の問題と照らし合わせて問題を調査します。 理論をテストする：観察と科学捜査的な分析、または制御された方法で問題を再現することにより、理論を確認します。理論を改良し、繰り返す：問題を正確に理解するまで、理論を改良し続けます。ソリューションを開発する：サービスの低下についてお客様をサポートする場合、一定期間にわたって 1 つ以上のソリューションを提供する場合があります。その際は、次の点に注意してください。 お客様は、根本原因の理解に基づいて今後の発生を防止する解決策を期待しています。提供するものが回避策や応急処置的なソリューションである場合は、そのことを事前に伝えるようにしてください。多くの場合、時間が最も重視されます。そのため、短期的なソリューションを利用できる場合は、それを提供しつつも調査を継続する必要があります。根本原因の調査に巻き込まれ、全体像を見失い、困っている顧客になりがちです。 問題のスコーピング パフォーマンスの低下の問題を診断するときに最初に行うことは、次の質問に答えることです。 だれがいつ、何をしたか。ビジネス測定基準の異常やお客様から報告される実際の問題の原因を理解することに、常に焦点を当てる必要があります。 トランザクション応答時間の概要がわかるパフォーマンスグラフは、問題が生じるタイミングを絞り込むのに役立ちます。また、トランザクション応答時間データは、トランザクションログやファイルシステムログでも確認できます。 システムがキャプチャしたトランザクションタイミングデータが、エンドユーザーが報告するパフォーマンスを裏付けていない場合、要注意と見なして以下の質問について考える必要があります。 正しいタイムゾーンで確認しているか。これはネットワーク関連のパフォーマンスの問題ですか? クライアントトランザクションログが有効になっている場合、ネットワークの速度低下によって生じたパフォーマンスの問題の確認に役立つデータが表示されます。クライアントのトランザクション ログ が有効になっていない場合は 、影響を受けるエンド ユーザーへのポイントインタビューが、問題が ネットワークに関連しているかどうかを判断するのに役立ちます。 問題は特定の ServiceNow アプリケーションノードに限定されているか。 パフォーマンスグラフデータはノードごとに表示され、ノードを切り替えることができます。問題が単一のノードにしか影響していない場合、データベースなどの共有リソースをすぐに除外できるため、これを手掛かりにして原因を特定します。 リソースの制約の特定 ほとんどのパフォーマンスの問題は、リソースの競合が原因です。特定のリソースの制約を特定することで、競合に関する既知の原因のいずれか、または未知の問題に根本原因を絞り込むことができます。パフォーマンス低下の原因となる最も一般的なリソース不足は、JVM メモリーとデータベーススループット (I/O) です。 リソース使用率を評価する際は、以下に示すパフォーマンスグラフのような時系列データを確認します。リソースの競合がパフォーマンスの問題をどのように引き起こすかについては、高速道路の交通量に例えるとわかりやすいでしょう。ある時点までは、高速道路上に車が増えても交通速度にほとんど影響しませんが、しきい値に達した後、車が増えると、交通速度は遅くなります。同様に、ホスティング環境で利用可能なリソースを超えると、ServiceNow インスタンスのパフォーマンスがクロール時に低下します。 パフォーマンスグラフ パフォーマンスグラフを確認して、メモリが高くなっているかどうかを調べます。高くなっている場合、問題の原因はおそらくメモリ使用率の高さにあります。そうでない場合、データベース (DB) の処理速度の低下が原因である可能性があります。 ServiceNow パフォーマンスホームページのスレッドグラフでは、特に DB が遅い場合に、どのリソースが制約を受けているかをすばやく把握できます。 トランザクションログ パフォーマンスグラフの代わりにトランザクションログを使用して、どのリソースの制約がパフォーマンスの問題を引き起こしているかを把握することもできます。パフォーマンスグラフではなくトランザクションログを使用する理由には、以下のようなものがあります。 パフォーマンスグラフが機能しない。トランザクションログが提供する時間よりも詳細な時間区分で調べる必要がある。パフォーマンスグラフのみでは結論が出ない。 特定の時間のパフォーマンス低下を検証し、考えられる原因を特定するには： トランザクションログを確認します。システムログアプリケーションでトランザクションモジュールを使用して、処理が遅くなった時間や機能が停止する前の時間を指定してクエリします。注意：トランザクションログで正しいタイムゾーンが参照されていることを確認してください。 リストの計算をカスタマイズして、平均応答時間と平均 SQL 時間を表示します。[応答時間] 列のデータを (z から a) で並べ替えて、応答時間が最も高いものをリストの一番上に表示します。 平均と外れ値の両方について、SQL 時間として分類される合計トランザクション時間の割合を決定します。SQL 時間が占める割合が、 全体のトランザクション時間の約 90% の問題は、サーバーの I/O 待機 (ディスクの読み取りまたは書き込みが遅い) またはテーブルの変更などによって引き起こされるデータベース ロックが原因である可能性があります。トランザクション時間全体の約 50 % の場合、おそらくメモリ不足の状態になっていることが原因です。このような場合、SQL 時間は増加して表示されますが、他のすべての処理も遅くなり、トランザクション時間全体に対する SQL 時間の割合に反映されます。全体のトランザクション時間の約 10% の場合、インシデントは上記以外の何かによって引き起こされた可能性があります。たとえば、CPU などが考えられます。 ファイルシステムログと Unix ユーティリティ 長いトランザクション時間を検証できる場合は、次の手順を実行します。 パフォーマンスの低下が発生した期間をログで確認します。インシデントがログに報告された時刻と一致するタイムスタンプを検索します。grep コマンドで Memory を検索すると、メモリ使用率が表示されます。 メモリ使用率が低い場合は、おそらくメモリの問題ではありません。そうでないことが証明されない限り、問題はデータベースレベルでの速度低下が原因であると考えられます。SQL の速度低下の警告が圧倒的に多い場合は、ディスク I/O に問題があることを示しています。評価とコンパイルが遅いことが優勢である場合、これはメモリの問題を示していますが、キャッシュのフラッシュを示している可能性もあります。 triage-instance.sh スクリプトによってインスタンスが再起動された場合は、triage_*.txt ファイルを確認します。 メモリにもデータベースにも制約がないと思われる場合 パフォーマンスの問題の約 80 % は、JVM メモリーの競合または I/O の競合 (データベースの速度低下) に関連しています。不足によって速度が低下する可能性があるその他のリソースには、CPU、ネットワーク帯域幅、物理メモリなどがあります。これは、システムがスワップ状態になるとデータベースの速度低下として現れます。さらに、リソースの競合以外の問題により、システムが遅くなったり、利用できなくなったりする可能性もあります。 CPU CPU によってパフォーマンスの問題が発生することはまれですが、前例がないわけではありません。CPU 使用率が高くなる一般的な原因は、スクリプト内のループです。ループするスクリプトを 1 回実行すると、コアを 1 つ使い切る可能性があります。サーバーには少なくとも 8 つのコアがあるため、ループするコードを同時に実行するには同じ数のスレッドが必要となります。もうひとつの理由は、いずれかのアプリケーションサーバーの CPU 使用率の上昇です。これは、そのサーバー上に、ガベージコレクションがアグレッシブに実行されているノードがあることを意味します。ps コマンドは、サーバー上の各プロセスの合計 CPU 時間を提供します。このデータはトリアージログに書き込まれます。この現象を捕捉できた場合、top コマンドを使うと、影響を受けるプロセスを確認できます。 ネットワーク エンドユーザーにとって、ネットワークの問題は、他のタイプのパフォーマンスの問題とは表れ方が異なります。サーバーのみが遅い場合、ページが提供されるまでに時間がかかりますが、提供された後はすぐにブラウザーにロードされます。ネットワークの問題がある場合、ブラウザーでのページのレンダリング開始から完了までに時間がかかります。ネットワークパフォーマンスの問題は、サーバーのトランザクション時間が良好であるという事実とは区別されます。クライアントトランザクションログが有効になっている場合、通常はネットワークパフォーマンスの問題を簡単に特定できます。 システムパフォーマンスの観点では、ネットワークとは、アプリケーションサーバーから要求を送信し、エンドユーザーのブラウザーが応答を受信するまでに費やされた時間を指します。ネットワークパフォーマンスは、往復遅延 (ping 時間) と帯域幅 (1 秒あたりのバイト数) で測定できます。ServiceNow アプリケーションの場合、最初のアクセス後に大量のデータが送信されることはありません。そのため、ServiceNow は帯域幅よりも往復遅延を重視する傾向があります。 往復遅延はさまざまですが、実際に予想される一般的な期待値は次のとおりです。 サンディエゴ → ボストン：80 ミリ秒サンディエゴ → ロンドン：150 ミリ秒サンディエゴ → シドニー：250 ミリ秒 世界中にあるさまざまなデータセンターのサーバーに ping を実行すると、これらを自分でテストできます。大学の Web サイトは通常、セルフホスト型であることが多く、コンテンツ配信ネットワーク (CDN) を使用しない傾向があるため、比較対象として適しています。 キャッシュのフラッシュ キャッシュをフラッシュすると、JVM メモリーに保持されているデータをデータベースから取得しなければならないため、パフォーマンスに影響します。キャッシュフラッシュは、データベース内のテーブル [sys_cache_flush] に記録されます。クラスター化されたシステムでは、キャッシュフラッシュ実行時に、キャッシュフラッシュをトリガーしたノードを除くすべてのノードにシステムログが書き込まれます。 注意：sys_cache_flush テーブルを選択しても、キャッシュフラッシュが発生していることはわかりません。 ブロック リソースの制約を除くと、パフォーマンスの問題や機能停止の最も一般的な原因はブロッキングです。ブロッキングは、アプリケーションレイヤーまたはデータベースで同期を実行しているときや、並列アクティビティを人為的に制約していることが原因で発生します。場合によっては、リソースの競合が原因となることもあります。一方、リソースが占有されておらず、ブロッキングによって機能停止が発生する場合もあります。 セマフォと同時実行トランザクション セマフォは、並行して実行できるユーザートランザクションの量を制御することで、共有リソースを保護します。パフォーマンスの問題を初めてトラブルシューティングするエンジニアは、セマフォとセッションシンクロナイザーに関する原因と結果を混同することがよくあります。セマフォは、アプリケーションノードが同時に処理するトランザクションの数を制御します。システムの速度が低下している場合、通常よりトランザクションの実行に時間がかかるため、セマフォが消費されます。 ブロッキングの問題がどのように発生するかを理解するには、まずトランザクションがアプリケーションを通過するパスを確認する必要があります。 ユーザーが実行した要求を、アプリケーションサーバーが受信します。HTTP スレッドが、要求を処理するアクションを取得します。注意：これらの数には上限があります。通常は、1 ノードあたり 50 です。スレッドが実行する最初のアクションは、以下の内容を確認することです。 利用可能なセマフォがあるか。 ある場合、システムは同時実行トランザクション数を人為的に制御します。基本的な前提として、処理する必要があるトランザクションが 100 件ある場合は、すべてのトランザクションを一度に処理しようとするよりも、バッチで処理する方が高速です。(CPU 数に対する) 特定のしきい値を超えると、ジョブ間を移動する作業がオーバーヘッドとなり、すべてのトランザクションが完了するまでの合計時間が長くなります。利用可能なセマフォがある場合、スレッドはそれを要求し、処理を開始します。利用可能なセマフォがない場合、スレッドはセマフォを使用できるようになるまで待機します。 ユーザーが既に別のトランザクションを実行しているか。セッションシンクロナイザーは、1 つのセッションで複数のトランザクションが処理されないようにします。 このモデルでは、すべてのセマフォが長時間待機状態となった場合、リソースが過剰に使われることなく機能停止する可能性があることに注意してください。たとえば、インシデントが送信されるたびに、影響を受ける構成アイテムの詳細を確認するシンプルオブジェクトアクセスプロトコル (SOAP) 要求を、別のシステムに送信するシステムについて考えてみます。不明な理由により外部システムが要求に応答するのに 1 分かかり始めます。セマフォが 8 つあり、10 秒間に 8 つのインシデント送信要求が届いた場合、システムは 50 秒間停止します。 原因の特定 ここまでは、どのリソースに制約があるかを判断することで、トラブルシューティング プロセス中の問題の基本的な理解を得ることに重点が置かれてきました。パフォーマンスの問題の根本原因を突き止める方法論に進む前に、根本原因を構成するもの (および構成しないもの) について簡単に説明します。これらの問題は、ServiceNow またはお客様が作成した、システムの動作に影響を与えるコードが原因で発生します。コードが間違っているだけの可能性もありますが、多くの場合、お客様がシステムを予期しない方法で使っているか、過剰な使い方をしています。これらの問題を追跡することは非常に難しく、忍耐と粘り強さが必要となります。 次のセクションでは、さまざまなタイプの問題を最初から追跡して修正する方法を説明します。これがどのように行われるかに飛び込む前に、深く掘り下げる注目すべき代替案を指摘する価値があります。 自分が扱っている問題が、既に検出され、お客様が使用しているバージョンに存在することがわかっている既知の問題かどうかを確認する。既知のパフォーマンスの問題は、リソースの制約に基づいてカテゴリに分類されています。これを知っていると、問題に照らし合わせてチェックする必要がある既知の問題を大幅に減らすことができます。何が変わったかを確認する。お客様のシステムが何か月も正常に動作していて突然問題が発生した場合は、システムで最近何が変更されたかを確認するとよいでしょう。最近の変更点を調べると、考えられる原因をすばやく絞り込むことができます。問題に関連するインシデントの開始と変更が行われたタイミングが近いほど、それが原因である可能性が高くなります。 JVM メモリー Java 仮想マシン (JVM) メモリーは、タスクを実行するために ServiceNow アプリケーションで使用されます。このリソースはノードに固有ですが、顧客インスタンスは複数のノードで構成される可能性があるため、JVM メモリーのプールも複数になる場合があります。 タスクを実行する JVM はメモリを使用します。そのメモリを使用しているオブジェクトがスコープ内にある (スコープ内の他の何かがそのオブジェクトを参照している) 限り、そのメモリは使用され続けます。参照後のオブジェクトは収集可能となり、その時点で他の場所で使用できるようになります。ガベージコレクションは、パフォーマンスに大きな影響を与える操作です。使用可能なメモリーが減少すると、JVM はガーベッジ・コレクションに費やす時間が長くなり、パフォーマンスがさらに低下します。 ラップトップのメモリが不足すると、メモリからディスクにデータを移すことになります。このオプションは、JVM メモリーには適用されません。代わりに、JVM メモリーは有限であり、使い果たされると、メモリー不足 (OOM) エラーがスローされます。 OOM エラーは現在実行中の操作を強制終了するため、システム全体が機能停止する可能性があります。しかし、場合によっては、OOM エラー後にインスタンスが停止しないこともあります。これは、無視してよいという意味ではありません。どのような場合でも、OOM エラーを受け取ったらインスタンスを再起動する必要があります。そうしないと、動作が不安定になったり、データが失われたりする可能性があります。 JVM メモリーに関連するパフォーマンスの問題は、一般的に以下のカテゴリに分類されます。 JVMメモリの突然の不足 JVM メモリーの突然の不足は、システムが一度に大量のデータを移動しなければならないことによって発生します。これはバグでもあります。プラットフォームはこのタイプの問題に対して多くの保護機能を備えていますが、オープンな ServiceNow プラットフォームの性質上、お客様は今後も予期しない形でメモリ不足に陥ることがあります。 これはパフォーマンスに影響を与えるイベントであり、利用可能なメモリ量が大幅に減少した結果、突然発生します。また、通常は単一のスレッドによって発生します。メモリ使用量は数秒で増加する場合もありますが、多くの場合、数分から 1 時間ほどかかります。空きメモリの数が減少すると、JVMがガベージコレクションプロセスの実行により多くの時間を費やす必要があるため、パフォーマンスが低下します。 トリガースレッドの検出 このタイプのメモリの問題の原因を特定するには、まずメモリをすべて使い果たしているスレッドを見つけます。メモリ使用率をスレッド別に表示できるログ記録がないため、メモリ使用率が上昇し始めるというイベントの開始を、トランザクションまたはスレッドの開始と関連付ける必要があります。この情報を見つけられる場所はいくつかあります。どの方法もすべてのインシデントに対して機能することが保証されていないため、すべての方法に精通しておくことが重要です。 OutOfMemory 例外 このタイプのメモリ使用率の急激な上昇では、OutOfMemory (OOM) 例外が発生する可能性があります。通常は、OOM 例外をスローするスレッドが原因となっています。複数のスレッドが OOM 例外をスローした場合、最後にスローしたスレッドがトリガースレッドである可能性が高くなります。 stats.do を使用したトリガースレッドの検出 メモリが不足しているときに stats.do を実行すると、すべてのセマフォとスケジュールされたワーカーのリストに加え、それらが実行されている期間が表示されます。場合によっては、どのスレッドが原因となっている可能性があるのか、明らかになることもあります。 Semaphore Sets Default Available semaphores: 0 In use semaphores: 0: 43BE29DA354C2040AC091D1C01CE130B: /incident.do (http16004-Processor43) (0:12:43.506) 1: 0BBFE15E354C2040AC091D1C01CE13E3: /incident.do (http16004-Processor36) (0:00:12.604) 2: D6BE611E354C2040AC091D1C01CE13A8: /problem.do (http16004-Processor11) (0:00:39.520) 3: 9343D0CA35C82800AC091D1C01CE1317: /xmlhttp.do (http16004-Processor45) (0:00:12.612) 4: DC976FC6354C6C00AC091D1C01CE13BE: /home.do (http16004-Processor28) (0:00:51.521) 5: FBBE69DA354C2040AC091D1C01CE13F3: /incident.do (http16004-Processor15) (0:02:09.041) 6: 07BF255E354C2040AC091D1C01CE13C5: /home.do (http16004-Processor10) (0:00:39.589) 7: D2962BCE350C6C00AC091D1C01CE131B: /xmlhttp.do (http16004-Processor38) (0:22:11.013) 8: 6A3E499235C42040AC091D1C01CE135A: /home.do (http16004-Processor49) (0:01:56.384) 9: 91BE211E354C2040AC091D1C01CE135E: /incident.do (http16004-Processor30) (0:00:44.420) 10: BBE9BC9E35402040AC091D1C01CE1315: /home.do (http16004-Processor9) (0:01:02.787) 11: A6BF6D1E354C2040AC091D1C01CE13D9: /home.do (http16004-Processor23) (0:00:27.099) 12: B583E09E35C8EC00AC091D1C01CE136C: /sc_task.do (http16004-Processor18) (0:00:10.503) 13: 64EBB22135002000AC091D1C01CE1317: /ecc_queue.do (http16004-Processor41) (0:00:00.012) 14: 49BFE55E354C2040AC091D1C01CE1397: /navpage.do (http16004-Processor39) (0:00:02.644) 15: E72B8AC23544A800AC091D1C01CE1313: /home.do (http16004-Processor3) (0:00:37.070) 上の画像では、セマフォ #7 が他のトランザクションよりもはるかに長く実行されているため、非常に重要です。 トランザクションログを使用したトリガースレッドの検出 トランザクションログでも、原因である可能性があるスレッドを検索することができます。これは、インスタンスを再起動せずに復旧させた場合にのみ機能します。ノードがシャットダウンされたときにスレッドが停止した場合、ノードのエントリはトランザクションログに書き込まれません。 トランザクションログエントリの読み方については、セクション 3.2「トランザクションログ」を参照してください。 ファイルシステムベースのログを使用したトリガースレッドの検出 ファイルシステムベースのログは、システムで何が起こっているかについての最も網羅的な情報源であり、実際には常に、メモリ不足状態を引き起こした可能性のあるスレッドを検索する際の手がかりが含まれています。 Berlin リリースより、ノードはシャットダウン時に threads.do に相当するデータをファイルシステムログにダンプします。これには、セマフォの実行時間やスケジュールされたワーカーなどが含まれます。 実行時間の長いスレッドがセマフォである場合、次に示すように、すべてのトランザクションの開始と終了がファイルシステムログに記録されます。 #Note、ポンド記号に続く数字は、そのトランザクションの連続したUIDです。#Note that the number following the pound sign is a sequential UID for that transaction. 2012-02-09 00:04:51 (362) http-16 64EBB22135002000AC091D1C01CE1317 *** Start #238,599, path: /ecc_queue.do, user: TECMIDSRV 2012-02-09 00:04:51 (409) http-16 64EBB22135002000AC091D1C01CE1317 *** End #238,599, path: /ecc_queue.do, user: TECMIDSRV, time: 0:00:00.051, render: 0:00:00.051, network: 0:00:00.000, chars: 257, SQL time: 25 (count: 5), business rule: 0 (count: 0) 次の画像は、メモリの突然の不足を引き起こしたスレッドについての手掛かりとなり得るログメッセージの例です。 #Compacting 大きな行ブロック: データベースから大量のデータを取得していることを示します。#Compacting large row block: indicates we are retrieving a large chunk of data from the database. 2012-02-09 16:13:50 (829) http-43 43BE29DA354C2040AC091D1C01CE130B [0:00:00.078] Compacting large row block #Long running #Large Result set 根本原因と修正 JVM メモリーの突然の不足を引き起こしたスレッドを特定したら、次のステップでは、システムがメモリ不足になった正確な時間に、スレッドが何を実行していたかを把握します。スレッドダンプが取得されていた場合、調査がはるかに容易になります。スレッドダンプは、次のいずれかの場所にあります。 対応した技術者がインシデントや問題に添付したもの。システムの再起動時に作成されたトリアージログ内。これは Gen1/Gen2 によって異なります。Berlin 以降のリリース：システムの再起動時に取得された localhost ログ内。 注意：スレッドダンプの詳細については、トピック 5.1.1「スレッドダンプ」を参照してください。 JVM メモリーリーク メモリリークとは、利用可能なメモリが徐々に減少していくことです。そのままにしておくと、パフォーマンスが低下し、最終的には OutOfMemory エラーが発生します。リークの兆候は、ガベージコレクション後の JVM メモリー使用率が数日、数週間、または数か月にわたってゆっくりと増加することです。 以下のグラフは、リークの例を示しています。47、48、49 週目にメモリ使用率が増加した後、システムの再起動によってメモリが解放され、増加が止まっていることに注目してください。50 週目でリークが修正され、メモリ使用率が通常の一貫したパターンに戻っていることがわかります。 JVM メモリーリークでは、アクセス可能なメモリが緩やかに減少します。この場合、フルガベージコレクションとキャッシュフラッシュを実行しても、利用可能なメモリへの変換は行われません。 システムの観察、ログの検査などからメモリリークを追跡することは困難です。メモリリークの原因を特定するには、JVM のヒープダンプを取り、YourKit などの既製のデバッグツールを使用して分析する必要があります。 このデバッグ方法に頼る前にまず、調査可能な既知の問題があるかどうかを確認することをお勧めします。既知のメモリリークの問題のリストには、可能な場合は検証手順が用意されています。その内容には通常、リークが生じているスレッドを強制終了する手順が含まれます。 リークを既知の問題として確認できない場合は、 ダンプを取得して分析する必要があります。 JVM メモリーの全般的な不足 次の場合、ノードで JVM メモリの一般的な不足が発生しています。 メモリ使用率が高いために処理速度が低下している。リークの証拠はなく、GC後のメモリフロアが徐々に増加することはありません。キャッシュの強制フラッシュとガベージ コレクションは、使用中のメモリの量を通常の範囲に戻そうとすると成功し、合計の約 1/3 が正常と見なされる可能性があります。 結局のところ、一定量のメモリで多くの作業を (並列で) 行うと、処理速度は低下します。特定のノードに割り当てることができるメモリの最大量は 2 GB です。JVMメモリはノードを追加することで水平方向にスケーリングされるため、解決策は、現在ノードが2ギガ未満の場合はノードに割り当てられるメモリの量を増やすか、ノードを追加することです。 カスタマイズにより、特定の量のメモリで処理できるトランザクションの数にはばらつきがあります。 一般的なサイジングの指針は次のとおりです。 2ギガのサイズの1つのノードがそれを処理できるはずです。1 分あたり 150 件以上のトランザクション (フルページ)。トランザクションが 300 件を超えると、ほぼ確実に不足する。スケジュール済みジョブの処理により、これらの数値は変動する場合がある。 データベースの速度低下 データベースの観点から調査される実際のリソース制約は I/O です。I/O は、ディスクの読み取りと書き込みを指します。ServiceNow では、I/O はほぼ SQL ステートメントの実行のみで構成されています。JVM メモリーとは異なり、I/O 制約はサーバー全体に表れます。I/O はすべて SQL であるため、処理が遅い SQL ステートメントを確認すれば、そのリソースを消費しているものを特定できます。 データベースからクエリを実行する場合は、キャッシュの概念を理解することが重要です。MySQL には、データベース (DB) の頻繁にアクセスされる部分をキャッシュする InnoDB バッファプールというデータベースキャッシュがあります。InnoDB バッファープールは、サーバー、特に専用 DB サーバーのメモリ使用量の大部分を占めています。通常、データベースは、バッファープールにないデータのクエリをほとんど処理しない限り、うまく機能します。 データベースパフォーマンスの突然の低下 データベースのパフォーマンスが突然低下する場合があります。通常は、ロックの競合や高コストなメンテナンス操作が原因です。たとえば、truncate, drop, alter, create indexなどがあります。 データベース レベルのロックは、操作に排他アクセスが必要なために発生します。データセンターで実行されている MySQL バージョン 5 の場合、次のロック動作が存在します。 テーブルの変更/インデックスの作成:変更またはインデックス作成中のテーブルのテーブルロック。Drop/Truncate：DB サーバー全体 (全カタログ) に対するグローバルロック。 データベースのパフォーマンスチューニング 多くの場合、DB レベルの速度低下のトラブルシューティングは、チューニング作業となります。テーブルのサイズが大きくなり、追加の機能が実装されるに伴い、DB にかかる負荷は徐々に増加します。お客様が作成した機能のコードは効率的でない可能性があります。データベースのパフォーマンスをチューニングする場合、パフォーマンスを改善する最も実用的な方法は、最も非効率的なクエリパターン/ソースを見つけて修正することです。つまり、最適化する前に SQL トランザクションのプロファイリングから始めることをお勧めします。 SQL トランザクションのプロファイリング データベーストランザクションをプロファイリングする場合、クエリのコストはクエリの実行にかかる時間に比例して変動すると考えてよいでしょう。以下は、SQL ステートメントのプロファイリングに使用できる便利なモデルです。 Work = Query_execution_time * Query_execution_frequency ServiceNow プラットフォームはすべてのクエリを localhost ログに記録します。これには 100 ミリ秒以上かかります。grepコマンドを使用してSlow SQLのログエントリをフィルタリングすることにより、データベースのパフォーマンスに最も大きな影響を与えている可能性のあるクエリを把握できます。 以下の例は、grep コマンドを使用して SQL ステートメントをプロファイリングする方法を示しています。 #Example 1 #Print all slow SQL statements for all nodes on a server that happened on a given day egrep " Time: .* for: " /glide/instances/*/logs/localhost_log.2012-02-10.txt #Example 2#Count all slow SQL statements for all nodes on a server that happened on a given day egrep " Time: .* for: " /glide/instances/*/logs/localhost_log.2012-02-10.txt | wc -l #Example 3 #Count all slow SQL statements for all nodes on a server that happened on a given day egrep " Time: .* for: " /glide/instances/*/logs/localhost_log.2012-02-10.txt | wc -l #Example 4 #Print all slow SQL statements for all nodes on a server that happened on a given day #and took at least 1 minute to execute egrep " Time: .* for: " /glide/instances/*/logs/localhost_log.2012-02-10.txt | grep -v "0:00" #Example 5 #Print all slow SQL statements for all nodes on a server that happened on a given day #and took at least 10 minutes to execute egrep " Time: .* for: " /glide/instances/*/logs/localhost_log.2012-02-10.txt | grep -v "0:0" #Example 6 #Print slow statements against a particular table egrep " Time: .* for: " /glide/instances/*/logs/localhost_log.2012-02-10.txt | egrep "sysapproval_approver.*WHERE" #Example 7 #Print slow statements against a particular table with a specific where clause. #note we're replacing single quotes with single char wild card "." egrep " Time: .* for: " /glide/instances/*/logs/localhost_log.2012-02-10.txt | egrep "sysapproval_approver.*WHERE sysapproval_approver0..state. != .not_required.*" 最初のステップとして、次のような一連のコマンドを使用し、実行時間でデータセットを分割することをお勧めします：grep -v "0:00" | wc -l, grep -v "0:00"。こうすることで、最適化の効果が最も大きい SQL ステートメントのサブセットに焦点を絞ることができます。次の表は、データを分割して焦点を合わせる方法を示しています。 処理が遅い SQL の数しきい値合計1000010 秒以上2:46:4010001 分以上16:40:0020010 分以上33:20:00 この例では、実行に 10 分以上かかる SQL ステートメントにまず集中することをお勧めします。1分後に>スライスに戻る価値があります。 クエリのパターンに基づき、データセットをさらに分割します。その際、最適化できる最大のブロックを探します。これを実現する最も簡単な方法は、データを手動で検査して、類似したクエリのパターンを検索することです (同じまたは類似の where 句を含む 1 つのテーブルで)。grep コマンドを使用してログファイルをフィルタリングし、カウントしてその数をメモします。たとえば、上記の #Example7 を wc -l にパイプで渡します。grep でマッチングを反転させ (-v を追加)、出力を再度手動で検索して別の共通パターンを探します。上記のステップを繰り返してパターンの数を取得して、除外します。繰り返しパターンのないクエリまで絞り込めたら、次のようなパターンとカウントのリストが出来上がります。 パターンカウントsysapproval_approver WHERE approver=70fx_price WHERE id=30sys_user WHERE u_custom= AND u_one_off20... 注意：これは、おおよその優先順位付きの、最適化すべきクエリのリストとして機能します。 SQL クエリの最適化 ServiceNow 環境で処理速度の遅い SQL トランザクションを最適化する方法は複数あります。 クエリにカバリングインデックスを追加する。既存のインデックスを使うようにクエリを変更する。クエリを完全に削除する。クエリが冗長な場合は、機能を削除しなくてもこれで実現できます。 インデックスを追加する簡単な例 以下は、インデックスを追加してクエリを最適化する方法の簡単な例です。インデックスを追加するとパフォーマンスの問題が発生する可能性があるため、通常はメンテナンス期間を必要とします。 次のようなクエリがあるとします。 SELECT count(*) AS recordcount FROM sysapproval_approver sysapproval_approver0 WHERE sysapproval_approver0.`approver` = 'f42c36d40a0a3c19006435056742f298' AND sysapproval_approver0.`state` = 'requested' まず、sysapproval_approver の既存のインデックスを確認します。 mysql> use swissre_16004 Database changed mysql> snow mysql-showindexes from sysapproval_approver; +----------------------+------------+------------------------------+--------------+-----------------+-----------+------------- | Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality +----------------------+------------+------------------------------+--------------+-----------------+-----------+------------- | sysapproval_approver | 0 | PRIMARY | 1 | sys_id | A | 1655741 | sysapproval_approver | 1 | sysapproval_approver_ref0 | 1 | sysapproval | A | 551913 | sysapproval_approver | 1 | sysapproval_approver_ref1 | 1 | approver | A | 7998 | sysapproval_approver | 1 | sysapproval_approver_ref4 | 1 | state_binding | A | 14 | sysapproval_approver | 1 | sysapproval_approver_ref5 | 1 | process_step | A | 14 | sysapproval_approver | 1 | sysapproval_approver_ref | 1 | u_requested_for | A | 42454 | sysapproval_approver | 1 | sysapproval_approver_ref2 | 1 | u_location | A | 14 | sysapproval_approver | 1 | sysapproval_approver_ref3 | 1 | u_change | A | 48698 | sysapproval_approver | 1 | sysapproval_approver_nor1 | 1 | document_id | A | 275956 +----------------------+------------+------------------------------+--------------+-----------------+-----------+------------- 9 rows in set (2.27 sec) mysql> 次に、カバリングインデックスを作成します。 mysql> snow mysql-createindex jml_cov1 on sysapproval_approver (state, approver); Query OK, 0 rows affected (0.21 sec) Records: 0 Duplicates: 0 Warnings: 0 最後に、snow mysql-explain コマンドを実行して、インデックスが実際に使われていることをテストします。 mysql> snow mysql-explain SELECT count(*) AS recordcount FROM sysapproval_approver sysapproval_approver0 -> WHERE -> sysapproval_approver0.`approver` = 'f42c36d40a0a3c19006435056742f298' -> AND sysapproval_approver0.`state` = 'requested'; +----+-------------+-----------------------+------+-----------------------------------+---------+---------+-------------+------+--------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+-------------+-----------------------+------+-----------------------------------+---------+---------+-------------+------+--------------------------+ | 1 | SIMPLE | sysapproval_approver0 | ref | sysapproval_approver_ref1,jmlcov1 | jmlcov1 | 220 | const,const | 27 | Using where; Using index | +----+-------------+-----------------------+------+-----------------------------------+---------+---------+-------------+------+--------------------------+ 1 row in set (0.02 sec) mysql> 既存のインデックスを使用するようにコードを変更する例 次のようなクエリがあるとします。 SELECT fx_price0.`sys_id` FROM fx_price fx_price0 WHERE fx_price0.`id` IN ('eb887c570a0a3c2c00a6ebe792a1ebbf' , 'eb887ee80a0a3c2c010e614649768988' , 'eb8881400a0a3c2c013580448779a010' , 'eb8883d80a0a3c2c0097ab2facf1047f') AND fx_price0.`field` = 'price' mysql> snow mysql-showindexes from fx_price; +----------+------------+-----------------+--------------+--------------------+-----------+------------- | Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality +----------+------------+-----------------+--------------+--------------------+-----------+------------- | fx_price | 0 | PRIMARY | 1 | sys_id | A | 1196877 | fx_price | 1 | fx_price_index1 | 1 | table | A | 17 | fx_price | 1 | fx_price_index1 | 2 | id | A | 1196877 | fx_price | 1 | fx_price_index1 | 3 | field | A | 1196877 | fx_price | 1 | fx_price_ref3 | 1 | currency | A | 17 | fx_price | 1 | fx_price_ref5 | 1 | reference_currency | A | 17 | fx_price | 1 | fx_price_ref8 | 1 | parent | A | 17 | fx_price | 1 | jmlcov1 | 1 | id | A | 1196877 | fx_price | 1 | jmlcov1 | 2 | field | A | 1196877 +----------+------------+-----------------+--------------+--------------------+-----------+------------- 9 rows in set (0.94 sec) mysql> このクエリを発行するコードは次のとおりです。 *******BEFORE********************************************************************** protected GlideRecord getGlideRecord(int first, int count, String table) { GlideRecordKeySetReader reader = new GlideRecordKeySetReader(fGlideRecord); ArrayList al = reader.getKeys(first, count); GlideRecord gr = new GlideRecord(table); gr.addQuery(ID, al); gr.addQuery(FIELD, fElementNames); gr.setQueryReferences(true); gr.query(); return gr; } ************************************************************************************ クエリをテーブルの追加のクエリに書き換えると、 インデックス fx_price_index1 を使用できます。 *******AFTER********************************************************************** protected GlideRecord getGlideRecord(int first, int count, String table) { GlideRecordKeySetReader reader = new GlideRecordKeySetReader(fGlideRecord); ArrayList al = reader.getKeys(first, count); GlideRecord gr = new GlideRecord(table); gr.addQuery(TABLE, DBObjectManager.get().getAllExtensions(fGlideRecord.getTableName())); gr.addQuery(ID, al); gr.addQuery(FIELD, fElementNames); gr.setQueryReferences(true); gr.query(); return gr; } ************************************************************************************ 是正処置 パフォーマンスの問題のほとんどは、システムの既知の問題まで遡って追跡することで解決します。既知の問題は非常に具体的な場合があります。たとえば、「大量のデータをテーブル x にロードし、特定の URL にアクセスすると、20 分後にシステムが利用できなくなる」などです。また、「お客様は独自のテーブルとフィールドの作成、アドホッククエリの実行はできるが、インデックスを追加できない。その結果、データベースクエリが十分に最適化されていない」のように一般的な問題もあります。製品の単純な不具合には、パッチや回避策を適用できます。一般的なアーキテクチャの課題については、そうした問題への対処方法を判断する標準運用手順を用意しています。 問題の根本原因が既知の問題ではない場合、根本原因分析でさらに詳しい調査が必要になります。 スレッド スレッドとは、アプリケーションサーバーにおける実行の流れのことです。使用されるスレッドは、バックグラウンドとフォアグラウンドの 2 つのカテゴリにグループ化できます。フォアグラウンドスレッドは、アプリケーションサーバーへの HTTP 要求に応答します。通常のユーザー要求を処理してページを提供し、AJAX 要求と SOAP を提供します。バックグラウンドスレッドは、アプリケーションサーバーへの要求に直接応答するのではなく、一定の間隔で動作します。アプリケーションサーバーによって行われる作業はスレッド上で行われるため、コードに影響を与えるパフォーマンスもスレッドによって実行されます。 スレッドダンプ スレッドダンプは、特定の時点で各スレッドが実行しているコードパスを正確に示します。スレッドダンプは、パフォーマンスの問題の原因となっているコードを特定する際、多くの推測を除外するのに役立ちます。 スレッドダンプの各行には、前のコード行によって呼び出された正確なコード行が示されます。 main,glide.scheduler.worker.0,4,ASYNC: Monitoring - Process SNC queue (592 ms) org.mozilla.javascript.regexp.NativeRegExp.executeREBytecode(NativeRegExp.java:1988) org.mozilla.javascript.regexp.NativeRegExp.MatchRegExp(NativeRegExp.java:2443) org.mozilla.javascript.regexp.NativeRegExp.executeRegExp(NativeRegExp.java:2515) org.mozilla.javascript.regexp.RegExpImpl.matchOrReplace(RegExpImpl.java:182) org.mozilla.javascript.regexp.RegExpImpl.match(RegExpImpl.java:66) org.mozilla.javascript.NativeString.execMethod(NativeString.java:238) org.mozilla.javascript.IdFunction.call(IdFunction.java:78) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c911.call(sys_script_include.3ceff5790a0a0bae00e49c7f3c7ced38:91) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c912.call(sys_script_include.3ceff5790a0a0bae00e49c7f3c7ced38:87) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c907.call(sys_script_include.3ceff5790a0a0bae00e49c7f3c7ced38:17) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c729.call(sys_script_include.d2426c9ec0a8016501958bf2ac79c775:132) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.ScriptableObject.callMethod(ScriptableObject.java:1550) com.glide.script.RhinoObject.callFunction(RhinoObject.java:110) com.glide.script.RhinoObject.callFunction_ScriptableObject(RhinoObject.java:147) com.glide.script.GlideRhinoHelper.jsonToObject(GlideRhinoHelper.java:169) com.glide.glideobject.GlideElementNameValue.setFirstTime(GlideElementNameValue.java:129) com.glide.glideobject.GlideElementNameValue.setInitialValue(GlideElementNameValue.java:39) com.glide.script.GlideElement.newGlideElement(GlideElement.java:93) com.glide.script.GlideRecord.loadRow0(GlideRecord.java:2935) com.glide.script.GlideRecord.loadRow(GlideRecord.java:2817) com.glide.script.GlideRecord.next(GlideRecord.java:5055) com.glide.script.GlideRecord.jsFunction_next(GlideRecord.java:4549) inv5.invoke() org.mozilla.javascript.FunctionObject.doInvoke(FunctionObject.java:565) org.mozilla.javascript.FunctionObject.call(FunctionObject.java:480) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c3033.call(sys_script_include.21ad66a10a0a0b7c00180f6799f51780:27) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c3027.call(sys_script_include.a85367d3c0a801020000e98b08941455:11) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.BaseFunction.applyOrCall(BaseFunction.java:431) org.mozilla.javascript.BaseFunction.execMethod(BaseFunction.java:176) org.mozilla.javascript.IdFunction.call(IdFunction.java:78) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c377.call(sys_script_include.d22e7bdbc0a8016500a18e024bfc9aa3:4) org.mozilla.javascript.BaseFunction.construct(BaseFunction.java:217) org.mozilla.javascript.ScriptRuntime.newObject(ScriptRuntime.java:1270) org.mozilla.javascript.gen.c3022.call(sys_script_include.5ff0c9ac0a0a0b0a00a0c2dddbdd36d5:40) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c3025.call(sys_script_include.5ff0c9ac0a0a0b0a00a0c2dddbdd36d5:88) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c3021.call(sys_script_include.5ff0c9ac0a0a0b0a00a0c2dddbdd36d5:17) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c3013.call(sys_script_include.03fafe6bc0a8010300fdf160ba2b9f84:213) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c3372.call(sys_script_include.95b27b39c0a8016500c26d339e44be7c:73) org.mozilla.javascript.ScriptRuntime.call(ScriptRuntime.java:1196) org.mozilla.javascript.gen.c3367.call(sys_trigger.33d43c625c482000957ba8a53a015553:12) org.mozilla.javascript.optimizer.OptRuntime.callSimple(OptRuntime.java:275) org.mozilla.javascript.gen.c3368.call(sys_trigger.33d43c625c482000957ba8a53a015553:2) org.mozilla.javascript.gen.c3368.exec(sys_trigger.33d43c625c482000957ba8a53a015553) com.glide.script.ScriptEvaluator.execute(ScriptEvaluator.java:156) com.glide.script.ScriptEvaluator.evaluateString(ScriptEvaluator.java:56) com.glide.script.Evaluator.evaluateString(Evaluator.java:82) com.glide.script.Evaluator.evaluatePossiblePrefixedString(Evaluator.java:152) com.glide.job.RunScriptJob.evaluateScript(RunScriptJob.java:129) com.glide.job.RunScriptJob.runScript(RunScriptJob.java:107) com.glide.job.RunScriptJob.execute(RunScriptJob.java:76) com.glide.schedule.JobExecutor.execute(JobExecutor.java:72) com.glide.schedule.GlideScheduleWorker.executeJob(GlideScheduleWorker.java:158) com.glide.schedule.GlideScheduleWorker.process(GlideScheduleWorker.java:125) com.glide.schedule.GlideScheduleWorker.run(GlideScheduleWorker.java:55) 前のスタックから、スレッドの実行パスを追跡する方法の例をダンプします。 ... ファイルシステムログ内のスレッドのトレース 既知の根本原因がない問題を処理する場合は、修正を活用して原因となるコードを見つけます。この段階に至る前のトラブルシューティングプロセスで、問題に関連するログファイル内ですでに証拠を特定しているかもしれません。実行中のスレッドの最も一般的なタイプを理解し、ログに書き込まれているデータを把握することで、原因をさらに詳しく調べることができます。 フォアグラウンドトランザクション フォアグラウンドトランザクションは HTTP スレッドで実行され、get または post コマンドに応答して発生します。ほとんどのフォアグラウンドトランザクションは、セマフォとセッションシンクロナイザーによって制御されます。 トランザクションプロセッサー フォアグラウンドトランザクションにはいくつかタイプがあるため、特定の URL における要求の処理方法にもルールがあります。 システム内のテーブルの場合、[table_name].do はそのレコードのフォームを解決し、[table_name]_list.doはテーブル内のレコードリストを解決します。UI ページは [ui_page.name].do を使用して呼び出すことができます。ファイルシステム内の Jelly テンプレート (wizard_view.xml など) は、.xml を .do に置き換えることで呼び出すことができます。パスまたはパラメーターが一致した場合は、プロセッサーを使用して HTTP 要求を実行します。注意：すべてのプロセッサーの中で最も注目すべきなのは xmlhttp です。これは AJAX 要求を処理します。stats.do、threads.do など、複数のハードコードされた URL があります。 一般的なログ記録 一般的なトランザクションを開始するには、次の URL の get を処理します。 /incident.do?sys_id=c92bc7718f4020001c519cfde0f92304&sysparm_view=&sysparm_record_list=active%3Dtrue%5EORDERBYDESCnumber 2012-02-13 12:59:55 (890) http-1 61A9E5A38F4420001C519CFDE0F923ED Parameters ------------------------- sys_id=c92bc7718f4020001c519cfde0f92304 sysparm_record_list=active=true^ORDERBYDESCnumber sysparm_view= 2012-02-13 12:59:55 (890) http-1 61A9E5A38F4420001C519CFDE0F923ED *** Start #355, path: /incident.do, user: jared.laethem 2012-02-13 11:40:19 (925) は、ミリ秒まで表したトランザクションの日付とタイムスタンプです。すべてのデータセンターでタイムゾーンが太平洋であることに注意してください(オンプレミスは異なる場合があります)。UI トランザクションは、1 から最大値まで連続する番号が付けられた HTTP スレッドによって処理されます。この場合は http-15 です。このスレッドがログに書き込むすべての行に、このタグが含まれます。各 UI トランザクションのログエントリには、セッション ID：BE56D9678F4420001C519CFDE0F923C9 もタグ付けされます。トランザクションには連番が与えられます (この場合は #355)。これは、このノードが最後に再起動されてから処理されたトランザクション番号 355 です。各トランザクションの開始時に、URL、incident.do、パラメーターが記録されます。パラメーターは、get 要求から分解された URL パラメーターであることに注意してください。 プロセスが開始されると、特定のトランザクションの追加行が次のように記録されます。 2012-02-13 12:59:56 (500) http-1 61A9E5A38F4420001C519CFDE0F923ED [0:00:00.178] slow evaluate for: var gl = Packages.com.glide.sys.GlideLocale.get(); var g_tz_offset = new Packages.com.glide.glideobject.GlideDateTime().getTZOffset(); var g_max_table_length = Packages.com.glide.db.DBUtil.getMaxTableLength(); 2012-02-13 12:59:57 (096) http-1 61A9E5A38F4420001C519CFDE0F923ED [0:00:00.362] Call of: actions2.xml 2012-02-13 12:59:57 (517) http-1 61A9E5A38F4420001C519CFDE0F923ED [0:00:00.283] Call of: list2_action_banner_buttons.xml 各行にスレッド名とセッション ID が含まれていることに注意してください。開始から終了までの間にトランザクション ログに表示される可能性のあるその他の情報は、トランザクションの詳細によって異なりますが、一般的な規則がいくつかあります。 処理速度が遅いものをログに記録します。これには以下が含まれますが、これらに限定されません。 速度の遅い SQL ステートメント速度の遅いビジネスルールの実行速度の遅いフォームのレンダリング 例外と警告： これらはスタックをダンプするので、デバッグを試みるときに便利です。パフォーマンスのトラブルシューティングを行う際、例外や警告が気になる場合があります。例外がパフォーマンスのボトルネックの原因になっていると考える正当な理由がない場合、その例外が原因であると推測するのはおそらく妥当ではありません。 2012-02-13 12:59:57 (956) http-1 61A9E5A38F4420001C519CFDE0F923ED *** End #355, path: /incident.do, user: jared.laethem, time: 0:00:03.246, render: 0:00:03.246, network: 0:00:00.000, chars: 39,020, SQL time: 165 (count: 115), business rule: 0 (count: 5) 2012-02-13 12:59:57 (958) http-1 61A9E5A38F4420001C519CFDE0F923ED /incident.do -- transaction time: 0:00:03.331, source: 0:0:0:0:0:0:0:1%0 各トランザクションの最後に、次のログを記録します。 実行時間のブレークダウン。通常の (クライアントではない) トランザクションログに表示される数字と同じです。トランザクション番号が再度出力されます。 バックグラウンド処理 スケジュール済みジョブは sys_trigger で定義します。sys_trigger エントリは特定のノードに割り当てることができます。そうしない場合は、利用可能な任意のノードで実行されます。ノードは、スケジュール済みジョブを実行するように設定することも、ノードに厳密に割り当てられたジョブのみを実行するように設定することもできます。 その他のワーカースレッド 進捗ワーカーの拡張機能には、WorkerThread.java、Localhost MidServer などがあります。注意：ここでは Eclipse 検索が便利です。 問題の再現/単一ページのパフォーマンスデバッグ このセクションでは、次のシナリオのトラブルシューティング手順について説明します。 全般的なパフォーマンスの問題：ここまで、このトラブルシューティング記事では、システム上のすべてのユーザーとすべてのページに影響する全般的なパフォーマンスの問題について説明してきました。システムが何をしていたかを示す適切なスタックダンプを運よく取得できれば、問題の根本原因を特定するのに十分な情報が得られるでしょう。そうでない場合は、次のステップとして問題の再現を試みます。問題を再現できない場合は、カスタマイズされていない ServiceNow インスタンスで問題の再現を試みてください。 実行する必要がある構成の変更など、再現に必要な情報を把握するには、実行時に一般的にログに書き込まれる情報よりも多くの情報を取得することが必要になる場合があります。つまり、どうすればお客様のシステムで問題がトリガーされるかはわかっていても (この推測方法がわからない場合は、トランザクションのログ記録のセクションを確認してください)、どうしてシステムでアクション X を実行するとパフォーマンスの問題や機能停止が生じるのかはわからないということです。 個々のページのパフォーマンス：もうひとつのパフォーマンスのトラブルシューティングシナリオは、すべてのユーザーの応答時間が遅くなっていることとは別に、インスタンス内の特定のページが遅くなっている場合です。トラブルシューティングの手順は類似しているため、次のセクションでまとめて説明します。 注意：可能であれば、再現の前に、元の問題が生じたシステムのコピー上での作業に移行してください。 セッションのデバッグ システムには、アクティブ化できるセッション固有のデバッグオプションがいくつかあります。デバッグオプションを有効にすると、ページ全体の移行が発生したときに、ページ処理に関する詳細情報が各ページの下部に書き込まれます。 セッションレベルのデバッグオプションには、次のようなものがあります。 ビジネスルールのデバッグSQL のデバッグセキュリティのデバッグ [すべて有効化 (Enable all)] モジュールを使用して、詳細情報を失わないようにすることをお勧めします。目的は、システムでの処理に時間がかかっている原因を特定することです。各行に正確なタイムスタンプと、特定の項目にかかった時間を示すタイマーがあります。セッションのデバッグデータを読み解く際に重要なのは、特定のページのデバッグ出力には、そのページのレンダリングに関連するデバッグ情報以外の情報が含まれている可能性があることです。 セッションに関連する処理はすべてセッションのデバッグバッファーに格納されますが、次のページ全体がロードされるまで書き込まれません。中でも特に注目すべきなのは、AJAX 要求の処理、フォーム送信の処理、その他のアクションです。ここからわかる重要な点は、セッションのデバッグはページロードのデバッグ以外にも役立つということです。次のように、各トランザクションは区切り文字「>>>」で区切られます。 このような場合、現在のページのレンダリングに関連する出力をデバッグするには、デバッグ出力の「>>> Preceding lines from previous transaction」の最後のインスタンスまでスクロールし、そこから読み込みを続けます。 セッションのデバッグは、フォアグラウンドトランザクションのデバッグにのみ使用できます。バックグラウンドトランザクションをデバッグする際、セッションのデバッグと同じレベルで詳しい情報が必要な場合、通常はバックグラウンドスクリプトでスクリプトを実行することで、バックグラウンドジョブと同等の処理を HTTP スレッドで実行できます。スクリプトの正確な内容はさまざまですが、最も一般的な例は「スクリプトジョブの実行」タイプのスケジュール済みジョブをフォアグラウンドで実行することです。これは、ジョブの sys_trigger エントリからスクリプトをプルして実行するだけで簡単に行えます。 変更内容の観点からのパフォーマンスの問題の調査 トラブルシューティングの理論またはプロセスのうち、根本原因の分析と修正を迅速化できるのは、まず何が変更されたかを調べるやり方です。お客様に質問しても構いませんが、パフォーマンスの問題の原因となる変更があったことをお客様が認識していたり、認めたりすることはほとんどありません。以下のリストでは、システム上の変更の可能性を特定するために検索すべき場所について、問題の発生しやすい順に説明します。 更新セット：更新セットは、sys_update_set と sys_update_xml の 2 つのテーブルで定義されています。ある日にインストールされた更新セット、または特定の日に更新セットがインストールされたことによる更新を探します。以下のスクリーンショットは、インストール日でソートした更新セットの変更の例です。本番システムが直接変更されている場合は、デフォルトの更新セットの最近の変更を確認することも効果的です。 変更要求：ServiceNow の従業員がお客様のシステムに変更を加えた場合、変更要求に記録する必要があります。変更要求がないからといって、変更が発生しなかったとは限りませんが、通常は、この記録に変更が記録されています。 トランザクション量：ユーザーの急激な増加は、パフォーマンスの低下の原因となります。パフォーマンスグラフとトランザクションログは、トランザクション量の傾向を特定するために参照すべき場所です。