none
IIS 8.5のログの"time-taken"の値について RRS feed

  • 質問

  • お世話になります。

    Windows Server 2012 R2 - IIS 8.5上のWebアプリケーション(ASP.NET)にて、ファイルを生成し、ダウンロードさせる処理を実施しております。

    ダウンロード用のaspxページにアクセスすると、ファイルを生成し、そのファイルをクライアント側にリダイレクトする(クライアント側にはダウンロードダイアログが表示される)仕組になっているため、"time-taken"の値として、「ダウンロード用のページにアクセスしたタイミングから、ダウンロードダイアログが表示されるまでの経過時間」が記録されると想定しておりましたが、体感5秒程度でダウンロードダイアログが表示される場合でも、”time-taken"の値として10秒から30秒と記録されています。

    このような値が表示されることがIISのログの"time-taken"の値の仕様として正常なのでしょうか?
    また、"time-taken"以外で
    サーバーサイドの処理時間を確認する方法はありますでしょうか?

    よろしくお願いいたします。

    2016年6月22日 16:09

すべての返信

  • > ”time-taken"の値として10秒から30秒と記録されています。

    初歩的なことを聞いてすみませんが・・・

    IIS のログでは time-taken は "the length of time that the action took in milliseconds."(単位はミリ秒)とのことですが、上記の「10秒から30秒」というのは "秒" で間違いないですか?

    ログ記録する W3C フィールドを選択する (IIS 7)
    https://technet.microsoft.com/en-us/library/cc754702(v=ws.10).aspx

    > 「ダウンロード用のページにアクセスしたタイミングから、ダウンロードダイアログが表示される
    > までの経過時間」

    上記の TechNet の記事の "the action" というのが具体的に何かはっきりしませんが、もしリダイレクトで「ダウンロードダイアログ」を表示しているとすると、普通に考えて「ダウンロード用のページ」が 301 応答を返すまでしか time-taken には含まれないと思います。

    ブラウザが 301 応答を受けて、ダウンロードダイアログを要求し、サーバーがダウンロードダイアログを応答として返し、それがブラウザに表示されるまでの時間は、どう考えても time-taken に含まれるとは思えません。

    > "time-taken"以外でサーバーサイドの処理時間を確認する方法はありますでしょうか?

    trace 情報を見るとか、Stopwatch クラスを使って調べるという方法はいかがでしょうか?


    • 編集済み SurferOnWww 2016年6月23日 2:00 誤字訂正
    2016年6月23日 1:01
  • SurferOnWww さん

    返信ありがとうございます。回答が遅くなり、申し訳ございません。

    IIS のログでは time-taken は "the length of time that the action took in milliseconds."(単位はミリ秒)とのことですが、上記の「10秒から30秒」というのは "秒" で間違いないですか?

    はい。秒で間違いないです。

    >上記の TechNet の記事の "the action" というのが具体的に何かはっきりしませんが、もしリダイレクトで「ダウンロードダイアログ」を表示しているとすると、普通に考えて「ダウンロード用のページ」が 301 応答を返すまでしか time-taken には含まれないと思います。

    私の記載の仕方が悪く、申し訳ありません。

    リダイレクトと表現してしまいましたが、実際の処理としては、ダウンロード用のaspxページのForm_Loadイベントで、以下の処理を行っています。
    1)データベースからデータを取得
    2)取得したデータを元にメモリ上でExcelファイルを生成
    3)作成したExcelファイルのバイナリデータをクライアントへ送信
       →クライアント側にダウンロードダイアログが表示される

    なお、3)については、以下のようなコード(一部省略)で実施しております。

     private void ShowDownloadDialog(byte[] outputBinary)
     {
        string fileName = "Test.xlsx";
        try
            {
                Response.ClearContent();
                Response.BufferOutput = true;
    
                Response.AddHeader("Content-Disposition", string.Format("attachment;filename={0}", Server.UrlEncode(fileName)));
                Response.AddHeader("Content-Length", outputBinary.Length.ToString());
                Response.AddHeader("X-Download-Options", "normal");
    
                Response.ContentType = "application/vnd.openxmlformats-officedocument.spreadsheetml.sheet";
    
                Response.BinaryWrite(outputBinary);
                Response.Flush();
            }
            catch (Exception)
            {
            }
            finally
            {
                System.Web.HttpContext.Current.Response.SuppressContent = true;
                System.Web.HttpContext.Current.ApplicationInstance.CompleteRequest();
            }
        }

    ちなみに、当処理のIISログのステータスコードは200で返却されております。

    何か情報があれば、ご提供いただけますと幸いです。

    以上、よろしくお願いいたします。


    2016年6月27日 14:02
  • ダウンロードが完了するまでは何秒くらいで、ファイルサイズはどれくらいですか?

    バッファリングしてても完全にバッファリングするのではないと思うので、クライアントに応答が返り始めるまでが5秒程度で、送信完了するまでが10から30秒程度ということはないですか?

    要するに、

    Response.BinaryWrite(outputBinary);

    の途中ですでにクライアントには送信が始まっているのではないかといことです。

    2016年6月27日 15:13
  • そうすると、最初の質問にあった、

    > ダウンロード用のaspxページにアクセスすると、ファイルを生成し、そのファイルをクライアント側に
    > リダイレクトする(クライアント側にはダウンロードダイアログが表示される)仕組になっているため

    は「リダイレクト」ではなく、ソースにある、

    Response.AddHeader("Content-Disposition", string.Format("attachment;filename={0}", Server.UrlEncode(fileName)));

    によって ASP.NET が生成する応答ヘッダをブラウザが見て、ブラウザが表示するダイアログ(IE9+ では通知バー)です。

    実際のダウンロードはその後始るので、

    > "time-taken"の値として、「ダウンロード用のページにアクセスしたタイミングから、ダウンロード
    > ダイアログが表示されるまでの経過時間」が記録されると想定しておりましたが、

    ではなくて、ダウンロードが終わるまでの時間になるはずです。なので、

    > 体感5秒程度でダウンロードダイアログが表示される場合でも、”time-taken"の値として10秒から30秒
    > と記録されています。

    は納得の結果だと思うのですが。


    【追伸】

    本題とは関係ないことですが気になった点を一言。

    Exception を catch すると全ての例外をなかったことにしてしまうので止めるべきだと思います。その理由は以下の記事に詳しく書いてありますので、興味があれば見てください。

    .NETの例外処理 Part.1
    https://blogs.msdn.microsoft.com/nakama/2008/12/29/net-part-1/

    .NETの例外処理 Part.2
    https://blogs.msdn.microsoft.com/nakama/2009/01/02/net-part-2/

    もし、ログを取るという目的であれば、try / catch ブロックで処置しないで、当該ページの Page_Error ハンドラおよび Global.asax の Application_Error ハンドラで処置し、例外を解釈してログを残すという方法を取るべきだと思います。具体例は以下の記事を見てください。

    方法 : アプリケーションレベルのエラーを処理する
    https://msdn.microsoft.com/ja-jp/library/24395wz3(v=VS.100).aspx

    エラー ハンドラの完全なコード例
    https://msdn.microsoft.com/ja-jp/library/bb397417.aspx

    • 編集済み SurferOnWww 2016年6月28日 3:39 【追伸】追加
    2016年6月28日 3:16
  • 質問者さんが出て来ないのに話を続けるのも何ですが、自分が関わったスレッドがこのまま放置されて終わってしまうのも何なので、追加情報など・・・

    自分の最初のレスで、

    > trace 情報を見るとか、Stopwatch クラスを使って調べるという方法はいかがでしょうか?

    と書きましたが、trace 情報は比較的簡単に調べられるので、それとログの time-taken の値を比較してみるのが良いと思います。

    その具体的な方法を書いておきます。

    まず、以下の記事の下の方にあるように web.config に trace 要素を設定します。

    How to: Enable Tracing for an ASP.NET Application
    https://msdn.microsoft.com/en-us/library/0x5wc973(v=vs.140).aspx

    その後「ダウンロード用のページ」にアクセスし、ダウンロードが完了したらトレースビューアを呼び出します。ブラウザのアドレスバーに trace.axd と入力して呼び出せます。

    下の画像のように表示されたら「ダウンロード用のページ」(下の画像の例では 0155-ChunkedDownload.aspx)の[詳細の表示]をクリックしてください。

    すると以下の画像のようにそのページの要求の詳細が表示されます。それの「トレース情報」の End Render までにかかった時間(以下の画像の例では 30.028339 秒)がログの time-taken とほぼ等しいはずです。

    ちなみに、上のページを要求したときの IIS のログは以下の通りで、time-taken は 30032 ミリ秒となっており、トレース情報とほぼ一致しています。

    上に述べたトレース情報とログを取得するため、自分の環境(Vista SP2 32-bit, IIS7, .NET 4, ASP.NET Web Forms, IE9)で検証用に作ったページ(0155-ChunkedDownload.aspx)のソースもご参考にアップしておきます。

    これを要求すると 10 秒後にブラウザにダウンロードのダイアログ(IE9+ は通知バー)が表示され、その後 20 秒でダウンロードが完了するようになっています。

    <%@ Page Language="C#" %>
    <%@ Import Namespace="System.IO" %>
    
    <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" 
    "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
    
    <script runat="server">
        protected void Page_Load(object sender, EventArgs e)
        {
            string folder = "~/images/";
            string filename = "Sig552T8.jpg"; // サイズは 30.1KB
            string path = Server.MapPath(folder + filename);
            FileInfo fileInfo = new FileInfo(path);
    
            if (fileInfo.Exists)
            {
                long chunkSize = 10000;
                Byte[] buffer = new Byte[chunkSize];
                Response.Clear();   
    
                using (FileStream stream = File.OpenRead(path))
                {
                    long length = stream.Length;
                    Response.ContentType = "image/jpeg";
                    Response.AddHeader("Content-Disposition", 
                        "attachment; filename=" + fileInfo.Name);
    
                    // ここで Flush してもダウンロードの通知バーは表示されない
                    Response.Flush();
                    System.Threading.Thread.Sleep(10000);
    
                    // 4 分割で送信
                    while (length > 0 && Response.IsClientConnected)
                    {
                        int lengthRead = stream.Read(buffer, 0, (int)chunkSize);
                        Response.OutputStream.Write(buffer, 0, lengthRead);
    
                        // ここの最初の Flush でダウンロードの通知バーが表示される
                        Response.Flush();
                        length -= lengthRead;
    
                        // そのあとここで 5 秒待たされる。
                        // ダウンロードは完了してないのでファイルは開けない
                        System.Threading.Thread.Sleep(5000);                    
                    }
                }
    
                // <!DOCTYPE html ... 以下の html ソースをダウンロードさせないために設定
                Response.SuppressContent = true;
            }
            
        }
    </script>
    
    <html xmlns="http://www.w3.org/1999/xhtml">
    <head runat="server">
        <title></title>
    </head>
    <body>
        <form id="form1" runat="server">
        </form>
    </body>
    </html>


    • 編集済み SurferOnWww 2016年6月29日 7:31 誤字訂正
    • 回答の候補に設定 星 睦美 2016年11月30日 7:47
    2016年6月29日 6:55
  • たびたびですみませんが、気になる Microsoft の Support の記事(URL 下記)を見つけたので追加情報として書いておきます。

    Description of the time-taken field in IIS 6.0 and IIS 7.0 HTTP logging
    https://support.microsoft.com/en-us/kb/944884

    上の記事の中で "Beginning in IIS 6.0, the time-taken field typically includes network time. ..." 以降が気になったところです。

    要するに最後のパケットに対するクライアントからの ACK を受け取るまでが time-taken に含まれると書いてあります。

    一方で "Time taken does not reflect time across the network." と書いてある Microsoft の別の記事もあります。例えば下記:

    Default Log File Settings for Web Sites <logFile>
    https://www.iis.net/configreference/system.applicationhost/sites/sitedefaults/logfile

    なので、実際何が本当か分かりませんが、もし前者の記事が ASP.NET Web Forms アプリにも当てはまるとすると、サイズの大きなファイルを遅いネットワークでダウンロードしたりするような場合、トレース情報の時間と time-taken の値に大きな差が出るかもしれません。

    それでもトレース情報と time-taken の値を比較すれば、質問者さんのケースで何故 time-taken の値が大きい(or 妥当?)かの理由の見当はつくのではないかと思われます。

    2016年6月30日 3:24
  • たびたびですみませんが、気になる Microsoft の Support の記事(URL 下記)を見つけたので追加情報として書いておきます。

    Description of the time-taken field in IIS 6.0 and IIS 7.0 HTTP logging
    https://support.microsoft.com/en-us/kb/944884

    上の記事の中で "Beginning in IIS 6.0, the time-taken field typically includes network time. ..." 以降が気になったところです。

    要するに最後のパケットに対するクライアントからの ACK を受け取るまでが time-taken に含まれると書いてあります。

    一方で "Time taken does not reflect time across the network." と書いてある Microsoft の別の記事もあります。

    IIS6当初は含まれていた、というだけじゃないですかね…(ネットワークの完了待ちが含まれているという部分に関しては)

    --追記

    すみません、どうやら全然違う感じですね、紛らわしいことを書きました。

    • 編集済み なちゃ 2016年7月1日 4:56
    2016年6月30日 4:26
  • 【追伸】

    もう一つ time-taken が network time を含むようになったという記事を見つけました。

    W3C Extended Log File Format (IIS 6.0)
    https://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/676400bc-8969-4aa7-851a-9319490a9bbb.mspx?mfr=true

    記事の一番下の Note にそのことが書いてあります。

    上のレスで、

    > 実際何が本当か分かりませんが、

    と書きましたが、Support の記事 KB944884 が本当で、"Time taken does not reflect time across the network." と書いてある Microsoft の別の記事は古いままで修正がされてないものと思われます。

    Support の記事 KB944884 を裏付けるような、time-taken の値が executionTimeout を越えているとか、プログラムのコードで実際に計った時間よりはるかに長いという報告もありますし。

    In our IIS logs, why do requests last 5 min and longer when executionTimeout is 110 seconds?
    http://stackoverflow.com/questions/37115984/in-our-iis-logs-why-do-requests-last-5-min-and-longer-when-executiontimeout-is

    Difference in time-taken in IIS and ASP.NET
    http://stackoverflow.com/questions/1091878/difference-in-time-taken-in-iis-and-asp-net

    KB944884 が IIS6, IIS7 限定ということは考えにくいので、質問者さんの IIS8.5 でもそうなっているであろうと考えて検討を進めるのが妥当だと思います。

    2016年7月1日 3:42
  • SurferOnWww さん

    返信が遅くなりすみません。多々、情報を共有いただきありがとうございます。

    当事象は特定の環境のみで発生しており、かつ、こちらで自由に触れない環境の為、検証などが進められておりませんが、共有いただいた情報をもとに検討を進めたいと思います。

    以上、取り急ぎ、御礼まで。

    2016年7月7日 7:46