TraceSource を使用して WCF が自分自身を撃つ方法

並列プログラミングの問題について何かを書く機会はめったにありません。今回は「ラッキー」でした。 TraceEvent 標準メソッドには、いくつかの実装上の特徴があります。複数のスレッドがブロックされているというエラーが発生しました。そのため、このニュアンスについてユーザーに警告し、ユーザーサポートの実践からこの興味深い事例を取り上げたいと思います。なぜ私たちのサポートが関わったのですか？読み続けて調べてください。読んで楽しんでください!

裏話

PVS-Studio ディストリビューションには CLMonitor.exe が含まれていますユーティリティまたはコンパイル監視システム。 C および C++ の PVS-Studio 静的解析を任意のビルドシステムにシームレスに統合するのに役立ちます。ビルドシステムは、PVS-Studio がサポートするコンパイラの 1 つを使用してファイルをビルドする必要があります。例:gcc、clang、cl、その他。

この Windows ユーティリティの標準的なシナリオは非常に単純です – わずか 3 ステップです:

「CLMonitor.exe モニター」を実行します。
プロジェクトをビルドします。
「CLMonitor.exe analyze」を実行します。

最初のステップでは、サーバーが停止するまでシステム内のすべてのコンパイラプロセスを監視する「サーバー」を実行します。サーバーを起動したら、分析したいプロジェクトをビルドします。ビルドが成功したら、解析を実行する必要があります。これを行うには、3 番目のステップに進みます。「CLMonitor.exe analyze」は「クライアント」を実行し、サーバーに「以上です。シャットダウンして、ここでプロセスの監視結果を提供してください」と伝えます。この時点で、サーバーは作業を完了する必要があり、クライアントは分析を開始します。後で、監視システムがどのように動作するか、サーバーがどのようにプロセスを収集するかについての洞察を学びます。

ある晴れた日、上記のシナリオはうまくいかず、分析が開始されませんでした。さらに、この問題が発生したのは私たちではなく、サポートに連絡したユーザーです。これが何が起こっていたかです。分析が実行され、サーバーが 10 分間応答せず、プログラムが タイムアウト で終了しました .この理由は謎でした。問題を再現できませんでした。ダブルトラブル！ ダンプをリクエストする必要がありました内部で何が起こっているかを確認するためのユーティリティプロセスのファイル。

注意 . CLMonitor.exe Windows ユーティリティの使用時に問題が発生しました。したがって、これ以降の例はすべて Windows に関連します。

CLMonitor.exe の仕組み

この部分を飛ばさないでください。ユーザーの問題に関する私のさらなる推論を理解するのに役立ちます。クライアントとサーバーがどのようにやり取りするかを説明しましょう。

ここに表示されているすべてのソースコードは、ユーティリティの動作をシミュレートするミニプロジェクトから取得したものです。私はあなたがケースをより明確にするために特別にそれを書きました.すべてのソースコードは、記事の最後に記載されています。

なぜプロセスをキャッチするのでしょうか?

ストーリーは、すべてのプロセスをキャッチするサーバーを実行する必要があることから始まります。それには理由があります。 C++ プロジェクトを分析するより便利な方法は、PVS-Studio_Cmd コマンドラインユーティリティを使用してアナライザーを直接実行することです。ただし、これには重大な制約があります。Visual Studio のプロジェクトしかチェックできません。チェック対象のソースファイルを処理するために、コンパイラを呼び出す必要があります。結局、アナライザーは前処理されたファイルで動作します。次に、プリプロセッサを呼び出すには、次のことを知る必要があります:

どのコンパイラを呼び出すか;
前処理するファイル;
パラメータの前処理

PVS-Studio_CMD ユーティリティは、プロジェクトファイル (*.vcxproj) から必要なものをすべて学習します。ただし、これは「通常の」MSBuild でのみ機能します Visual Studio プロジェクト。 NMake でもアナライザーが必要とする情報を取得できませんプロジェクト。これは、プロジェクトファイル自体に情報が格納されていないためです。そしてそれは、 NMake という事実にもかかわらずです。 .vcxproj でもあります。プロジェクト自体は、別のビルドシステムの一種のラッパーです。そこでは、あらゆる種類のスマートが活躍します。 Unreal Engine の分析についてプロジェクトでは、Unreal Build Tool との直接統合を使用しています – 内部で使用されるビルドシステム。詳細はこちら

CLMonitor.exe を使用すると、ビルドシステムに関係なく PVS-Studio を使用できます。プロジェクトのビルド中にすべてのプロセスを監視し、コンパイラの呼び出しをキャッチします。次に、コンパイラ呼び出しから、さらに前処理と分析に必要なすべての情報を取得します。プロセスを監視する必要がある理由がわかりました。

クライアントが分析を実行する方法

サーバーとクライアント間でデータを共有するために、WCF (Windows Communication Foundation) ソフトウェアフレームワークを使用します。私たちがそれをどのように扱っているかを簡単に説明しましょう。

ServiceHost クラスは、クライアントプロセスとサーバープロセス間でメッセージを交換する名前付きチャネルを作成します。サーバー側では次のようになります:

static ErrorLevels PerformMonitoring(....) 
{
  using (ServiceHost host = new ServiceHost(
                       typeof(CLMonitoringContract),   
                       new Uri[]{new Uri(PipeCredentials.PipeRoot)})) 
  {
    ....
    host.AddServiceEndpoint(typeof(ICLMonitoringContract), 
                            pipe, 
                            PipeCredentials.PipeName);
    host.Open();     
    ....
  }
}

ここで 2 つのことに注意してください: ClMonitoringContact およびIclMonitoringContact .

IClMonitoringContract サービス契約です。 ClMonitoringContract サービス契約の実装です。次のようになります:

[ServiceContract(SessionMode = SessionMode.Required, 
                 CallbackContract = typeof(ICLMonitoringContractCallback))]
interface ICLMonitoringContract
{
  [OperationContract]
  void StopMonitoring(string dumpPath = null);
} 

[ServiceBehavior(InstanceContextMode = InstanceContextMode.Single)]
class CLMonitoringContract : ICLMonitoringContract
{
  public void StopMonitoring(string dumpPath = null)
  {
    ....
    CLMonitoringServer.CompilerMonitor.StopMonitoring(dumpPath);
  } 
}

クライアントを起動したら、サーバーを停止して必要なデータをすべて取得する必要があります。このインターフェイスは、これを行うのに役立ちます。クライアント側のサーバー停止は次のようになります:

public void FinishMonitor()
{
  CLMonitoringContractCallback callback = new CLMonitoringContractCallback();
  var pipeFactory = new DuplexChannelFactory<ICLMonitoringContract>(
           callback, 
           pipe, 
           new EndpointAddress(....));

  ICLMonitoringContract pipeProxy = pipeFactory.CreateChannel();
  ((IContextChannel)pipeProxy).OperationTimeout = new TimeSpan(24, 0, 0);
  ((IContextChannel)pipeProxy).Faulted += CLMonitoringServer_Faulted;

  pipeProxy.StopMonitoring(dumpPath);
}

クライアントが StopMonitoring を実行したときメソッドを実行すると、実際にサーバーで実行され、停止します。クライアントは分析を実行するためのデータを取得します。

これで、CLMonitor.exe の内部動作を把握できました。

ファイルをダンプして問題を特定する

さて、肉に戻りましょう。どこにいたんだっけ？ユーザーは ダンプ を送信していましたプロセスからのファイル。ユーザーが分析を実行しようとしたときにハングアップしたことを覚えていますか?クライアントとサーバーのプロセスはハングしたままで、サーバーの閉鎖はありませんでした。ちょうど 10 分後、次のメッセージが表示されました:

興味深い 事実その10分はどこから来たのですか？実際には、サーバーが応答するまでの待機時間を大幅に長く設定しています。上記のコード例に見られるように、それは 24 時間です。ただし、一部の操作では、フレームワーク自体が多すぎると判断し、より迅速に管理します。したがって、初期値の一部しかかかりません。

クライアントが起動してから 5 分後に 2 つのプロセス (クライアントとサーバー) からダンプを取得して、そこで何が起こっているかを確認するようユーザーに依頼しました。

効果のために一時停止します。同僚のポールに正直に言いたいのですが、この問題に対処したのは彼でした。私はちょうどそれを修正していた。そして今、私はそれについての話を書いています:) 一時停止の終わり.

「クライアントの」ダンプ

クライアントのダンプを開いたときファイル、次のスレッドリストが表示されました:

メインスレッドに興味があります。サーバーの停止を要求するメソッドでハングアップします:

public void FinishMonitor()
{
  ....
  ICLMonitoringContract pipeProxy = pipeFactory.CreateChannel();
  ((IContextChannel)pipeProxy).OperationTimeout = new TimeSpan(24, 0, 0);
  ((IContextChannel)pipeProxy).Faulted += CLMonitoringServer_Faulted;

  pipeProxy.StopMonitoring(dumpPath);            // <=
  ....
}

クライアントはサーバーにシャットダウンを要求しましたが、応答はありませんでした。この動作は奇妙です。通常、これは一瞬の操作です。この場合、ダンプ を取得するのに 5 分かかりましたクライアント起動後。では、サーバーの動作を見てみましょう。

「サーバーの」ダンプ

それを開くと、次のスレッドリストが表示されました:

うわー、なぜそんなに多くの TraceEvents?スクリーンショットはそれらすべてに収まりませんでしたが、50 以上ありました。ブレインストーミングの時間です。このメソッドを使用して、さまざまな情報をログに記録します。たとえば、サポートしていないコンパイラのプロセスを検出しました。これによりエラーが発生しました - プロセスパラメータの読み取りに失敗しました。スレッドデータスタックを詳しく調べました。これらはすべて、コード内の同じメソッドにつながっています。私たちのユーティリティはプロセスをキャッチします。このメソッドは、このプロセスがコンパイラか別のものかをチェックします。このような興味のないプロセスを見つけた場合、この情報をログに記録します。

ユーザーは、私たちにとって「ゴミ」である多くのプロセスを実行していることがわかりました。よし、それで行きましょう。全体の状況はまだ疑わしいようです。なんでこんなスレが多いの？理論的には、ロギングは迅速に行われるはずです。これらのスレッドはすべて、同期点またはクリティカルセクションでフリーズし、何かを待っているようです。 ReferenceSource に行きましょう TraceEvent メソッドのソースコードを参照してください。

次に、ソースファイルを開くと、ロック が実際に表示されます。 TraceEvent の演算子メソッド:

このように多数の TraceEvent をメソッド (TraceInternal.critSec を待つ) release) は、一定の同期とログのおかげです。うーん、そうしよう。しかし、これはサーバーが沈黙している理由をまだ説明していません。サーバーをもう一度見てから ダンプ DiagnosticsConfiguration.Initialize で 1 つのスレッドが停止していることに気付きましたメソッド:

NegotiateStream.AuthenticateAsServer からこのメソッドに到達しますクライアント/サーバー接続でサーバー側認証を実行するメソッド:

この場合、クライアントとサーバーのやり取りは WCF で行われます。さらに、クライアントはまだサーバーからの応答を待ちます。このスタックは、DiagnosticsConfiguration.Initialize メソッドはクライアントからの要求に応じて呼び出され、現在はハングアップして待機しています。うーん…ソースコードに行きましょう:

ここで、このメソッドにはクリティカルセクションがあることに気付きます上記の同じ変数に対して。この CritSec を調べると、次のことがわかります。

結論を導き出すのに十分な情報が得られました。

興味深い事実 . TraceEvent を使用して、この問題に関する情報を求めてインターネットをサーフィンする GitHub で興味深い問題が発生しました。実際には別の問題を扱っていますが、マイクロソフトの従業員からの興味深いコメントが 1 つあります。

また、ロックの 1 つである TraceInternal.critSec は、TraceListener が要求した場合にのみ存在します。一般的に言えば、このような「グローバル」ロックは、高パフォーマンスのログシステムには適していません (実際、高パフォーマンスのログには TraceSource をお勧めしません)。まったく、実際には互換性の理由でのみ存在します)。

Microsoft チームは、高負荷システムにコード実行トレースコンポーネントを使用することをお勧めしません。チーム自体は、信頼性が高く、重い負荷に耐性があると思われる IPC フレームワークでそれを使用していますが…

分析結果のダンプ

これが私たちが持っているものです：

クライアントは、WCF フレームワークを使用してサーバーとやり取りします。
クライアントがサーバーから応答を取得できません。 10 分間待った後、クライアントはタイムアウトでクラッシュします。
TraceEvent でサーバー上で多くのスレッドがフリーズするメソッドと 1 つだけ – Initialize メソッド。
どちらの方法も、クリティカルセクションの同じ変数に依存しています .
TraceEvent が発生するスレッドメソッドが実行され、無限に表示され続けます。 ロックのため彼らはすぐに自分のことをすることができず、姿を消します。これが、ロックからオブジェクトを解放しない理由です。
初期化 メソッドは、クライアントがサーバーを終了しようとし、ロックで無期限にダウンしたときに発生します .

これは、サーバーがクライアントから完了コマンドを受信したことを認識するのに役立ちます。サーバーのシャットダウン方法には接続と初期化が必要ですメソッドの実行。このメソッドが実行できない理由は次のとおりです。 TraceEvent この時点でサーバー上で実行されているメソッドは、オブジェクトを クリティカルセクション に保持します .新しい TraceEvents サーバーが実行され続け、新しい「ゴミ」プロセスをキャッチするため、表示され続けます。サーバーは TraceEvent で遅延プロセスを無限にログに記録するため、クライアントはサーバーから応答を受け取ることはありません。 .問題が見つかりました!

本当に 事項これがクリティカルセクションのオブジェクトです静的変数です。これは、ロガーのインスタンスが単一のプロセスに存在するまで、エラーが繰り返されることを意味します。私たちと WCF の両方がロガーの異なるインスタンスを使用することは問題ではありません — 一見独立したオブジェクトが、クリティカルセクションの静的変数により相互ロックを作成します。

問題を再現して修正する時間です。

ケースの再現方法

この問題は、実際には簡単に再現できます。必要なのは、サーバーが常に何かを記録していることを確認することだけです。そこで、CrazyLogging という名前のメソッドを作成します。

private void CrazyLogging()
{
  for (var i = 0; i < 30; i++)
  {
    var j = i;
    new Thread(new ThreadStart(() =>
    {
      while (!Program.isStopMonitor)
        Logger.TraceEvent(TraceEventType.Error, 0, j.ToString());
    })).Start();
  }
}

トレース メソッドはサーバー操作を担当するため、ログを追加します。たとえば、ここにあります:

public void Trace()
{
  ListenersInitialization();
  CrazyLogging();
  ....
}

終わり！次に、サーバーを起動し (私の場合は Visual Studio 2019 を使用)、5 秒後にプロセスを一時停止し、スレッドの動作を確認します:

すごい！クライアントを起動します (TestTraceSource.exe analyze ）。サーバーに接続して停止する必要があります。

クライアントの起動後、分析は実行されません。もう一度、Visual Studio でスレッドを停止し、サーバー dump から同じ画像を確認します。ファイル。つまり、DiagnosticsConfiguration.initialize でハングアップするスレッドがありました。方法。問題を再現しました。

修正方法は？ TraceSource に注意する価値があります。アプリがコード実行をトレースし、トレースメッセージをソースにリンクできるようにするメソッドとプロパティのセットを提供するクラスです。サーバーがコンソールに接続されていない可能性があるため、これを使用します。このように、コンソールのログは無意味です。この場合、TraceSource.TraceEvent を使用して、オペレーティングシステムのイベントにすべてを記録しました。メソッド。

この問題を次のように「解決」しました。デフォルトでは、すべての情報は Console.WriteLine を使用してコンソールに記録されます方法。このログ情報は、コンソールが接続されていないために失われる可能性があります。ほとんどの場合、ユーティリティのタスクを実行する必要はありません。とにかく、問題はなくなりました。さらに、変更には数分しかかかりませんでした。ただし、特別な EnableLogger を使用する前と同じようにログを記録するオプションは残しました。

問題を再現するコード

以下は、問題を簡単に再現できるソースコードの一部です。

サーバーのシミュレーションを実行するには、.exe を実行します。痕跡で国旗。分析フラグを使用してクライアントを開始します。

注: CrazyLogging のスレッド数個別に選択する必要があります。問題が解決しない場合は、この値をいじってみてください。このプロジェクトは、Visual Studio でデバッグモードで実行することもできます。

プログラムのエントリポイント:

using System.Linq;

namespace TestTraceSource
{
  class Program
  {
    public static bool isStopMonitor = false;

    static void Main(string[] args)
    {
      if (!args.Any())
        return;

      if (args[0] == "trace")
      {
        Server server = new Server();
        server.Trace();
      }
      if (args[0] == "analyze")
      {
        Client client = new Client();
        client.FinishMonitor();
      }
    }  
  }
}

サーバー:

using System;
using System.Diagnostics;
using System.ServiceModel;
using System.Threading;

namespace TestTraceSource
{
  class Server
  {
    private static TraceSource Logger;

    public void Trace()
    {
      ListenersInitialization();
      CrazyLogging();
      using (ServiceHost host = new ServiceHost(
                          typeof(TestTraceContract), 
                          new Uri[]{new Uri(PipeCredentials.PipeRoot)}))
      {
        host.AddServiceEndpoint(typeof(IContract), 
                                new NetNamedPipeBinding(), 
                                PipeCredentials.PipeName);
        host.Open();

        while (!Program.isStopMonitor)
        {
          // We catch all processes, process them, and so on
        }

        host.Close();
      }

      Console.WriteLine("Complited.");
    }

    private void ListenersInitialization()
    {
      Logger = new TraceSource("PVS-Studio CLMonitoring");
      Logger.Switch.Level = SourceLevels.Verbose;
      Logger.Listeners.Add(new ConsoleTraceListener());

      String EventSourceName = "PVS-Studio CL Monitoring";

      EventLog log = new EventLog();
      log.Source = EventSourceName;
      Logger.Listeners.Add(new EventLogTraceListener(log));
    }

    private void CrazyLogging()
    {
      for (var i = 0; i < 30; i++)
      {
        var j = i;
        new Thread(new ThreadStart(() =>
        {
          var start = DateTime.Now;
          while (!Program.isStopMonitor)
            Logger.TraceEvent(TraceEventType.Error, 0, j.ToString());
        })).Start();
      }
    } 
  }
}

クライアント:

using System;
using System.ServiceModel;

namespace TestTraceSource
{
  class Client
  {
    public void FinishMonitor()
    {
      TestTraceContractCallback callback = new TestTraceContractCallback();
      var pipeFactory = new DuplexChannelFactory<IContract>(
                                callback,
                                new NetNamedPipeBinding(),
                                new EndpointAddress(PipeCredentials.PipeRoot 
                                                  + PipeCredentials.PipeName));
      IContract pipeProxy = pipeFactory.CreateChannel();
      pipeProxy.StopServer();

      Console.WriteLine("Complited.");    
    }
  }
}

プロキシ:

using System;
using System.ServiceModel;

namespace TestTraceSource
{
  class PipeCredentials
  {
    public const String PipeName = "PipeCLMonitoring";
    public const String PipeRoot = "net.pipe://localhost/";
    public const long MaxMessageSize = 500 * 1024 * 1024; //bytes
  }

  class TestTraceContractCallback : IContractCallback
  {
    public void JobComplete()
    {
      Console.WriteLine("Job Completed.");
    }
  }

  [ServiceContract(SessionMode = SessionMode.Required, 
                   CallbackContract = typeof(IContractCallback))]
  interface IContract
  {
    [OperationContract]
    void StopServer();
  }

  interface IContractCallback
  {
    [OperationContract(IsOneWay = true)]
    void JobComplete();
  }

  [ServiceBehavior(InstanceContextMode = InstanceContextMode.Single)]
  class TestTraceContract : IContract
  {
    public void StopServer()
    {
      Program.isStopMonitor = true;
    }
  }
}

結論

標準の TraceSource.TraceEvent には注意してください方法。プログラムでこの方法を頻繁に使用している場合、同様の問題に直面する可能性があります。特に高負荷システムの場合。この場合、開発者自身は、TraceSource に関連するものを使用することをお勧めしません。クラス。以前にこのようなことに遭遇したことがある場合は、お気軽にコメントでお知らせください。

読んでくれてありがとう！ Twitter をチェックすることをお勧めします。