BlackJumboDog .NET Core 性能向上 メモ 2

これの続ぎ

リクエストを処理する中で、遅くなっているものは何か?
よく考えられるもは、ロジックの無駄な処理(処理する必要のないものを処理している)。リソースの使い方。
で、まずはロジックの無駄という意味では、意味のない処理は見つからず。
で、遅くなっているところというのを考えると
リソースの確保の部分。
new byte [ XX ];
これは、ある程度のサイズになったとき、Heapの確保が発生するので、場合によって、数msかかる。これが1か所ならまぁいいのですが、中の処理では、Socketの読み込みバッファから、エンコード用のバッファ、出力用のバッファまで広く使っており、1回のリクエストで、少なくとも5回以上は生成しておりました。

これを何とかできないか?と考えたのが、BufferPoolというクラスを作ることでした。

https://github.com/darkcrash/bjd5/blob/3212cf26eca2f1c90ee545df4b3307fc654abf73/Bjd.Common/Memory/BufferPool.cs

これの役目は・・・

  • byte配列の確保を毎回やらせないことで、GCのコストを抑える。Heapの確保と解放をあまり発生させない。
  • 一定数事前に配列を生成し、領域を確保することで生成のコストを抑える。
  • 必要なサイズに応じたものを返す。
  • 足りなければ、作る。
  • 足りなくて作ったものが、既定の確保しておく領域を上回る場合には、解放する。

これで得られる恩恵は、思ってた以上に大きく、リクエストあたり数ms減りました。

これに対して個人的な見解は・・・・
GCはリソースやメモリの再利用があるので、そこである程度同じことさせているときは、次第に早くなるのですが、HTTPリクエストやら、Socket通信などでは、同じリソースのサイズを要求しないことが多く、メモリの断片化が起きたり。GCが動くことで、CPUリソースを消費したりということではないかなぁと思ったりしたが、それを明確に確認できる方法は思いつかなかった。。。GCの呼び出し回数が減っているというくらいかな。

 

続く・・・

 

BlackJumboDog .NET Core 性能向上 メモ1

BlackJumboDog .NET Coreの性能を向上させようといろいろ模索する中での話。

今やっていた性能向上というのは、WebServerで、クライアントからの接続要求をどれくらい処理できるか?です。
具体的には、Fiddlerを使って、1000回~100000回のリクエストを処理させて、エラーがおきないように、そして500回あたりのリクエスト(FiddlerがTimelineをグラフ化してくれるサイズ)をどれくらい早くできるか?

そんなところで、比較対象がなければということで、MSのIIS(InternetInfomationService)を手っ取り早いところで、相手にしてみました。Hyper-VのゲストOSとして、Windows Server 2016 を。リソースは、4コアのメモリ4GBをあてました。検証で利用するファイルは、BJDの初期で入っているindex.htmlです。サイズは4Kb強

IIS on Windows Server 1

私が注目したのはまず、右上に出ている78msという時間。これはこのグラフ全体が78msということっぽいようで、500回のリクエストを80ms以内にすべて応答しているということです。グラフの色が出ているところが通信中の状態(HTTPリクエストからレスポンスが返るまで)で、空白が、何もしていない時間のようです。こうしてみたとき、空白の領域は多く、Fiddlerが遊んでる状態といいますか、サーバーとクライアントはKeepAliveによってただSocketがつながっているだけの状態。1リクエストは数msで処理されている状態。

 

対して、BlackJumboDog .NET Coreはというと・・・

全体が、500ms。グラフもぎりぎりまで密集しており、空白はほとんどない。リクエストからレスポンスまでの時間が長く、Fiddlerが待っている状態。

リクエスト数に対しての処理時間でいけば、単純に1msとなりますが、並列で動いているために、1リクエストは実際のところ10ms、20msとかそんな感じ。

一日に数回しかないような処理ならば、速いものですが、このリクエストはブラウザ一つで、ページの読み込み、スクリプトの読み込み、画像リソースの読み込みとか考えたとき、1ページ表示するのに重ければ、10回以上はあるでしょう。

これを考えたとき、静的なファイルはダウンロードさせずに、ブラウザにキャッシュ化したり、リクエスト数を減らすためにファイルを結合してみたりとか、トラフィックがネックであれば、GZIP圧縮をかけてみたりといったこともできます。

ですが・・・それでは面白くない。
実際、これだけの差があることを.NET Coreのせいにしてしまうというのも一つなのですが、.NET Coreでも、KestrelというASP.NET Coreを動かすシンプルなアプリケーションサーバーは、ものすごい勢いでリクエストを処理できたりします。(実際はアプリケーションの処理によってはそんなに早くならないですが)

https://github.com/aspnet/KestrelHttpServer

 

そこで、何とか早くならないかと模索してみた・・・つづく

xUnit fail of overload Testmethod on Visual Studio 2017 .NET Core

Visual Studio 2017 が出たぜー!というところで、さっそくBlackJumboDogもアップグレードしていったところ。

xUnitで謎のテストエラーが続発した・・・

System.InvalidOperatrionException
普通に考えたところで、メソッドの呼び出し方を間違えたとのことなのだが、型を動的にしているわけでもないので、あれま・・・とか思っていたところ。

よくよく見ていると、そのメソッドはオーバーロードしていた。

引数3つのTestメソッドと、引数2つのTestメソッドがいる状態
エラーメッセージは

メッセージ: System.InvalidOperationException : The test method expected 3 parameter values, but 2 parameter values were provided.

となっていて「引数が3つあるぞ、でも2つしかないぞ。」という困ったぞーという意味の例外。

なので・・・

オーバーロードをやめて名前を付けた。

というわけで、成功!

ひとまず回避策は見えたが、これが仕様なのか、不具合なのかは調べていない。。。

AppVeyorのテストでエラー

前回のログ出力をがっつり作り替えたところのそもそも理由

AppVeyor Bjd.SmtpServer.CoreCLR.Test  1.1.0-51

で、エラーとなっている部分があるんですが、
これはローカルのWin10、VS2015環境では問題なく通るテストなのです。
このテストケース。
実際にSocketサーバーが動いて、それにクライアントが接続にいって
Pop3クライアントとしてメールを受け取るタスクを検証しているのですが、
メインではなく、裏で動いているPop3サーバーにてメールを開いたときのサイズが変わってしまってました。

AppVeyor(抜粋)

[13:38:12.326][1400][151] Mail.Read C:\projects\bjd5-qqab7\Bjd.SmtpServer.CoreCLR.Test\bin\201702191338066076_9_1333341264_23264094\mailbox\user2\MF_00635026511425888292 300 byte.
[13:38:12.326][1400][151] 16189196 SockTcp.SendNoTrace 151
[13:38:12.935][1400][151] 16189196 SockTcp.SendNoTrace 55
[13:38:13.545][1400][151] 16189196 SockTcp.SendNoTrace 12
[13:38:13.951][1400][151] 16189196 SockTcp.SendNoTrace 38
[13:38:14.154][1400][151] 16189196 SockTcp.SendNoTrace 37
[13:38:14.560][1400][151] 16189196 SockTcp.SendNoTrace 1
[13:38:14.967][1400][151] 16189196 SockTcp.SendNoTrace 5
[13:38:15.576][1400][151] 16189196 SockTcp.SendNoTrace 1
[13:38:15.982][1400][151] 16189196 SockTcp.SendNoTrace 2
[13:38:16.388][1400][151] 16189196 SockTcp.Send 3

ローカル

[23:46:07.939][13628][ 26] Mail.Read C:\Users\[username]\Source\Repos\bjd5\Bjd.SmtpServer.CoreCLR.Test\bin\201702212346077840_5_1610115599_50579406\mailbox\user2\MF_00635026511425888292 308 byte.
[23:46:07.940][13628][ 26] 18701856 SockTcp.SendNoTrace 152
[23:46:07.940][13628][ 26] 18701856 SockTcp.SendNoTrace 56
[23:46:07.940][13628][ 26] 18701856 SockTcp.SendNoTrace 13
[23:46:07.940][13628][ 26] 18701856 SockTcp.SendNoTrace 39
[23:46:07.940][13628][ 26] 18701856 SockTcp.SendNoTrace 38
[23:46:07.940][13628][ 26] 18701856 SockTcp.SendNoTrace 2
[23:46:07.940][13628][ 26] 18701856 SockTcp.SendNoTrace 6
[23:46:07.940][13628][ 26] 18701856 SockTcp.SendNoTrace 2
[23:46:07.941][13628][ 26] 18701856 SockTcp.Send 3

トータル 300 byteに308 byte
さらに1行単位の送信では1バイトづつ違うー!
そして、送信してる行数も違う・・・

そもそも、単体テストを実行するような環境でSocketがっつりかましてるのどうなのか!というところもありますが。

おそらくは、改行コードじゃないかなぁ
・・・というところでここまでっ

How to output log for xUnit

ひさしぶりに BlackJumboDogをいじっていて、
ずーっと気になっていたことがあったので、思わずやってしまった・・・。

xUnitでは、並列テストを前提とした場合標準出力に対する出力をキャプチャしない仕様になっている。そのため、出力させるためには、独自のOutputHelperが必要になる。
※ Capturing Output

これやるにあたって、今のSystem.Diagnostics.Traceを全て置き換える必要が
あった。

なぜかというと、System.Diagnostics.Traceは、コンテキストを持たずアプリケーション内で静的に動作してしまうため、並列で動いたときはどのテストの結果であるかを知ることができない。

そのため、ちゃんとやるなら、System.Diagnostics.Traceを全て独自のものに置き換える必要があったが、それにはかなりの修正量になるのがあってためらっていた。

しかしながら、実際のところテストがエラーになったとき、単純なものであればよいが、複雑なものであれば、どこがどうなっているかというのを追いかける必要がある。そのためには、ログも実行された結果がそのまま出てくれているのが良く、関係のないところの情報が出ていることは、逆に紛らわしい。そのため単独で動かしてその結果が出てくれるならいいがそうではなかったりもする。まぁその時点でテストとしての精度が低いという問題もあるのだけれども。

そこで、ログもすべて自分の実装でコンテキスト化してしまおうというのをやってみた。

・ログは出力先が不特定多数(ファイル、コンソール、xUnit、その他)
・ログは気軽に出すことをできるようにしておき、必要に応じて出力できないようにする
・ログはルートのコンテキストに紐づける

といったような考えで挑んでみたところ。

悪くはないが、そのための影響が大きくやはりやりすぎだったか!と思いつつ、前に進んでいることで何かやる気が出てきている今日だった。

change internal architecture for log. 

独自で実装しておくことは、チューニングしやすくなるので、悪くはない。

もし、今後xUnitを用いた開発をするのであれば、ログを出力する機構を
テストごとにコンテキスト化できるような仕組みをお勧めしたいなぁと思った。

 

AppVeyorのデプロイ先にMicrosoft Azure Blob Storageを使ってみたメモ

AppVeyorのドキュメントを眺めていて、デプロイの先としても使える場所に、AzureのStorageがありました。
Deploying to Azure blob storage

というわけで、AzureStorage(Microsoft Azure Storage の概要)に対して
デプロイしてみるメモです。

Microsoft Azure Storage

で、実際に使うとして、Azure Blob Storageっていうものになりますと、
このBlobには、「ホット」「クール」の種類があります。
Azure Blob Storage: ホット ストレージ層とクール ストレージ層
料金の違い)

ざっくりでいうと、クールは普段アクセスしないバックアップなどの用途に
ホットは、頻繁にアクセスする用途にという私の解釈です。
価格でみても、クールは容量単価が安く、
ホットはトラフィック、操作の単価が安くなっているようです。

デプロイするリソースは、頻繁に不特定多数にアクセスされる前提ですので
ホットにしてみようかと思います。

Azure側の準備

まずは、ポータルでBlobStorageを作ります。
+新規 > データ + ストレージ > ストレージ アカウント

名前:適当に入れますが、ホスト名に相当しインターネット上で一意である必要があります
デプロイモデル:リソースマネージャー
アカウントの種類:BLOBストレージ
アクセスレベル:ホット
ほか、お好みで。また、リソースグループは、その作業、やりたいこと、目的に応じて作っておいたほうが後で管理が楽です。(まとめて消すことができるとか)
作成で、しばらく待ちます・・・数十分もかかったことは今のところない

 

出来上がったら、さっそくコンテナ(実際にファイルを格納するもの)を作ります。
名前は適当にアクセスの種類はBlobです。そのほかのものは、今回使えないかと思います。

 

もう一つ、アクセスキーというのを控えておきます。
これは、書き込み削除のアクセスで、必要となる秘密のカギですので、見せないようにします。

どうでもいい余談ですが、これを間違って、公開してしまってひどい目にあうという話もあったりなかったりします。
過去、GitHubにあげてしまったとき、有志の人が機械的(?)にメール連絡してくれました。
(そのときは、サンプルのものでしたので、リポジトリごと削除した。)
もう一つ、キーを再生成するという方法もあります。

というところで、Azure側は準備完了!

AppVeyor側の準備

大きく2つあるように見えました、
プロジェクトごとのデプロイ先として設定するか、
Environmentとして全体に設定するか。

で、今回はEnvironmentとして設定しました。

Provider:Azure Blob Storage
Environment name:お好み
Storage account name:Azure側で作成したアカウント名
Storage access key:控えておいた秘密キーの1または2どちらか
Container name:Azure側で作成したコンテナ名
Folder:今回は何も入れない
Artifacts:デプロイしたい生成物の定義名

ビルド!

ビルドは成功!そしてアップロードされたらしきログがある!

追記(ここでProjects>[project]>Deployments>New Deployment)

Azureのポータル側でも確認

すっきり!これで、最新のpublish生成物を公開できるようになりました。

 

2016/07/23 追記
どうやら、自動にできたつもりが、手動でやったものが残っていただけらしい・・・(確認怠り
ひとまず、手動で
Projects>[project]>Deployments>New Deployment
でアップロードは確認した。

自動化するために必要なこと。
SettingsのDeploymentにEnvironmentsを設定する

AppVeyorの生成物を定義するメモ

定義するってなんぞや?というところですが、
基本的にビルドが終了するとすべてのものは消えてしまいます。
ビルドで、dllができたりnupkgができたりとするわけですが
これを定義して、リソースとして扱えるようにするもののようです。

公式のPackaging artifacts

で、yaml形式でもかけるようですが、WebUIを使っていきます。

Settings>Artifacts

ビルドコマンドで生成されたパスと、その名前を定義しておきます。
そして、ビルド実行!
結果にArtifactsが出てくれば成功

以下、BlackJumboDogのDockerImageでも利用している生成物と同じようにpublishで生成したリソースが出てきます。
https://ci.appveyor.com/project/darkcrash/bjd5-p6o91/build/artifacts

さぁ・・・これをどうしてくれようか

そしてDeploymentの道に続く・・・

appveyorで、.NET Core を試してみた

ご無沙汰しております。
Blog存在半分忘れかけておりました。
書きたくないわけでもなく、書きたい気持ちはありつつもなかなかタイミングがなかったというところで、実は、取り組んでいるものに節目がうまく出ていないのも一つかなというところです。
その場その場のことを書いていけるようにしていけたらいいのかなとか考えているところです。

というところで、本題です。

経緯

実は、.NET Coreでの開発をしていて、ある程度の規模になってきたときテストコードを自分のところで実行したり、dotnet packでnupkgを作るということをやりたいなと。ただ、継続的インテグレーションを構成したいと考えてましたところ、6月よりちょっと前だと、対応したと目立った情報もなく結構厳しいのかなと思ってました。毎回、手動で実行していければいいのですが、忘れたりまた、テストの結果が見えるようにできていないというのも、何か不透明な感じで面白くないなーと。
最近、@jsakamotoさんより、「appveyor」は「dotnetコマンドも使えるかも!?」と教えていただきまして、試してみました。

結論

使えたー!

設定したこと

既定ではslnファイルを読み込んでうまいことやろうとしてくれますが、
これだとテストも自動的に含まれてしまったり、うまく動作しなかったりとしたために、dotnetコマンドに置き換えました。

最初に、github上からAppVeyorのプロジェクトを作成しました。

  1. 左側リストのGeneral.プロジェクト名の設定 – ProjectName
    Bjd.xxxx
  2. 左側リストのGeneral.ビルドバージョンの設定 – Build version format
    1.0.{build} → 1.0.0-{build}
    ※気持ちの問題
  3. 左側リストのEnviromentは特になし
  4. 左側リストのBuildで、MSBUILDとなっているものをCMDに変更
    dotnet restore
    
    dotnet build Bjd.xxxx -c Release

    としました。

  5. 左側リストのTestで、「Script」「CMD」を選び、Buildと同じようにdotnetコマンドをdotnet test Bjd.xxxx -parallel all -maxthreads 3としました。オプション「-parallel all -maxthreads 3」はXunitに対するオプションです。並列化を有効にして最大スレッド数を設定してますが、設定しなくても動きます。BlackJumboDogでは、テスト実行にもSocket操作・サーバー動作を伴うとか、テスト実行時間が長くなりすぎないようにと考えたすえ、最大数を調整しました。
  6. Badgeの設定
    といっても、リンクをどこかに張り付けるだけです。私はGitHubのreadme.mdにはっつけてみました。
 
 なんか、それっぽい!という気持ちと、いまだにBjd.WebServer.CoreCLR.Testがpassingになったことはない!という現状を報告しておきます。

そのほか

これは、おどろいたことです。わかる人にはわかるとは思いますが、実はpathにperl.exeがいるらしく、cgiのテストが動作しました。
テストのタイムアウトは60分。普通のテストではそうそう、問題にならないような気がしますが、開発機のスペックと同等だと思わないほうがよいかと思います。テストを並列実行してる場合、コア数の違いで、実行時間がそのまま倍になったりしました。体感的に手持ちのSurfacePro4と同じくらいでした。
Slackへの通知もできます。ビルドの結果くらい通知しておくと、Commitの重みを感じつつ励みになります。(passingなら)
また、余談ですが、サーバーのスレッドが停止しないためにテストが終わらずに60分のタイムアウトを経験できたことは伏せておきます。
開発する環境以外での動作は思ったより大変な部分もありましたが、GitHubにプッシュするだけで、自動的にビルド、テストと動く環境があることで、リポジトリの状態を見えるようにできたことは、ぱっと見るだけで、状況を把握できて面白いかなーと思った次第です。

感謝

@jsakamotoさん、情報ありがとうございます!

オープンソースカンファレンス2016北海道にCLR/Hとして登壇させていただきました

こんばんは!

先日 6/18(土曜日)にオープンソースカンファレンス2016北海道がありました。
そこで、CLR/Hとして登壇させていただきましたので、報告レポートです。

「BlackJumboDog」+「.NET Core」で何かやってくださいとのことで
はじまりました。最初はテーマから悩んでましたが、CLR/Hの方と相談して決めたテーマがこれでした。

「Mac でも Linux でも動く! C#製ネットワークサーバーアプリ BlackJumboDog を .NET Core 上に移植した話 」

ということで、.NET Core、BlackJumboDog、クロスプラットフォーム、C#を全面に出したものでした。とはいえ、まだまだ正式リリースされたものでありませんので、
こういうものです!とも言えない状態でした。(当時はRC2さえもリリースされていなかった)

セッションは、BlackJumboDogとは?から始まり、.NET Coreを選んだ理由ということで、私の個人見解を最初に。実際のところ、RC2で劇的な変化があったために動かなくなった話も混ぜつつ、実際の動く環境のデモをさせていただきました。

特に、実際に動くということは大きな意味がありますし、テーマ・タイトルのMac Linuxはもちろん、Dockerというコンテナ仮想化で動くというのは、新しい形でのデプロイメントに何か可能性を感じます。このDockerでの実行開始までの速度が1分どころか、30秒かからないのは私自身驚いたことでもありました。

以下セッションの資料を公開してます。

ソースコード:githubDockerHub

なお、ソースコード、Dockerのイメージはその特性上、サーバーとして悪用されてしまう可能性もありますので、インターネットなど公開した状態で放置にならないようご注意くださいませ。UIが未実装であるため、すべてのサーバーがデフォルトで稼働するようになっております。

CLR/Hのみなさんのおかげで、セッションは無事に終了いたしました。資料の反響がものすごく驚きましたが、この.NET Coreに寄せてる期待は大きいものがあるのかなと感じます。考えていること目指していることがどこまで実現されるかはわかりませんが、.NET Standard Libraryが登場し、.NET Core App、ASP.NET Core App Xamarinなどの標準として動くようになっていけば、WebApp、コンソールアプリケーションに限らない世界が見えてくるかもしれないと期待しています。

BlackJumboDogでは、まだまだ完成したとはいえない状況ですので、継続して開発していきます。特にどこかのLTでも煽られておりますので、WebUIは・・・ASP.NETCoreで実装できないか・・・と妄想はしてます。

実はデモの50%はMicrosoft Azureの成分ができてましたので、そこも後々メモしておきます。

#もうちょっとBlog更新しよう

CoreCLRなBlackJumboDogにするとき仕組みを変更した理由と言訳 動的読み込みから組み立てに

前日からの続きです。日本各地で雪もすごい中、こんながあったりと。個人的にこれ賛成です。ASP.NET5って名称いつまでたっても、.NetFrameworkが5にならないか、いきなり6にいくかとかそういう偶数と奇数みたいなことでもしないとバージョン明記だけは無理があると思ってました。ただまぁ、次世代をいく、置き換えていくっていう願いが込められていたのではないかと思ったりもします。そこで、.Net Coreと同じようにCoreってつけたのいいと思いましたよ!名前と仕組みも一致した感じで。

.Net Core

以前、BlackJumboDogをはじめたところの記事でも書いていますが、GACとかってないんですね。基本すべて、NuGetからダウンロードなんですね。NuGetの参照って、名前とバージョンのみなんですが、これの実体となるDLLは、プラットフォームによって異なることが許されている。つまりDLLは動く環境によって変わる。言い方を変えると、DLLを参照するんじゃなくて、この名前を与えられているパッケージ(バージョンも指定可能)を必要としますっていう感じなんですよね。そうするとプラットフォーム用の実体が自動的に選ばれますよって。何を言いたいかというと、そもそも、実体のDLLに依存したものっていうのが静的(コンパイル)にはできない。また、参照として追加したいなら、DLLの形では難しいということなんですね。今はプロジェクトを参照する形で実現しているのが最初その違いに気づくのに時間がかかりました。NuGetだったので、ASP.NETみたいに、どっかにDLLあってみてるんだろーくらいに思ってたんですね。実行しているときはそうなるわけですが、コンパイル時には見てないってことをちゃんと理解していなかった。。。DLLとかライブラリ作ったならどこかで組み立てるプロジェクトがいないと話にならないなぁって思ったんですね。そこで、Bjd本体と実行イメージを作るプロジェクトを分けてみた(Bjd.Common.CoreCLRとBjd.CoreCLR)という結論を出してみました。これは、将来、BjdがNuGetに上がったりしたときに、利用する側がASPNETホストであるkestrelを動かすのと同じ感覚になることをイメージしてます。

そして、プラグインとしてDLLをReflectionを用いて拾い上げてプラグインを検索していたものを、ランタイム上に読み込まれているものからプラグインを検索する方法にしたというところでした。これはIssuesを見つけるまでどうしたもんかとひたすらネットサーフィンしてました。ここのServiceProviderっていうのを利用して、LibraryManagerなるものを取得、そこからプラグインを検索しています。できてしまえば、大したことないんですけどね。

こうして記事書きながら改めて振り返っているうちにEntryPointExecutor.csからActivatorUtilities.csを経由してMainは初期化されていく様子だということがわかったり。ServiceProvider.csという実体が見つかったりと、いろいろ面白い発見があったりするため、かなり楽しんでいます!ただ、この記事に書いている内容はソースをベースに話を進めているので、将来に渡っての仕様として明確なことではありません。ご了承ください。

それではまた!