none
SQLServerサーバ移行後遅い RRS feed

  • 質問

  • サーバ移行作業を行っており、SQLServerも移行しております。

    現行
    OS:Windows Server 2012 R2
    DB:SQLServer 2014 Standard SP2
    CPU:intel Xeon CPU E5-2699 v4 @2.20GHz 2.20 GHz(16コア)
    MEM:16GB

    移行後
    OS:Windows Server 2012 R2
    DB:SQLServer 2014 Standard SP3
    CPU:intel Core Processor(Broadwell,IBRS)2.1GHz (16コア)
    MEM:32GB

    移行後にCPU使用率が高くなり・クエリ実行速度も遅くなりました。
    移行方法はBACKUP DATABASEで現行からとってきてRESTORE DATABASEで移行後に入れました。
    移行後にインデックス再構成(構築)や統計情報も更新しております。
    原因はわからず困っております。解決方法をご教授くださいませ。

    2020年3月25日 13:35

回答

すべての返信

  • 以下の問題もあるのでSQLServer2014の更新プログラムを適用してみてはいかがでしょうか。(最新はSQLServer2014SP3 CU4です。)

    https://support.microsoft.com/ja-jp/help/4057280/high-cpu-usage-when-large-index-use-in-query-on-memory-optimized-table



    • 編集済み kaz8629 2020年3月25日 14:01
    2020年3月25日 13:54
  • ありがとうございます。
    更新プログラムが適用されているか確認してみます。

    2020年3月25日 23:59
  • 更新プログラムが適用されていなかったので、適用しましたが、結果はかわらずでした。
    2020年3月26日 1:44
  • CPUが変更になっているのですが、
    単純にCPUがダメということはないですかね。
    CPUとは疎いので、単純にどちらが性能がいいのかわかっておりません。

    2020年3月26日 1:52
  • 電源の設定を高パフォーマンスに変更されてみてはいかがでしょうか。

    これでパフォーマンスが改善したことがございます。

    2020年3月26日 2:18
  • ありがとうございます。
    電源の設定確認してみます。

    2020年3月26日 2:26
  • 高パフォーマンスにしましたが、
    結果かわらずでした。

    2020年3月26日 2:45
  • CPUの性能適には上がってるはずなんですけどね。。。

    後はtempdbの設定が思いあたります。

    https://social.technet.microsoft.com/Forums/ja-JP/de18593d-f9a6-46ad-acb3-c10acf330747/dosdonts-17-tempdb-cpu-?forum=jpbidp

    2020年3月26日 3:39
  • ありがとうございます。
    tembdbを同じように設定しているつもりです。

    tembdbの設定キャプチャを添付しようとしたら、できませんでした。
    0ポイントだからでしょうか。

    2020年3月26日 4:01
  • SQLServerプロファイラーを使用して、新環境と旧環境を比較し、どの部分で遅くなっているのかを確認されてみてはいかがでしょうか。

    ディスクの回転速度が旧が15Kで新が10Kなんてことはないでしょうね?

    • 編集済み Mr.Spock 2020年3月26日 8:27
    2020年3月26日 8:24
  • プロファイラーで確認します。
    2020年3月26日 8:30
  • ディスクの回転速度についてですが、
    クラウドでやっており、ベンダーに確認しましたが、開示できないとのことでした。
    2020年3月26日 9:29
  • EventClass=Audit Logout
    TextData=
    ApplicationName=.Net SqlClient Data Provider
    LoginName=
    CPU=0
    Read=12129728
    Write=3588
    Duration=18446744073709541

    新環境のプロファイラの一行を抜粋したものですが、Durationのこのぐらいの値なのでしょうか。あまりプロファイラを利用したことがないもので

    2020年3月26日 9:44
  • 旧サーバの照合順序がJapanese_CI_AS
    に対して新サーバの照合順序がSQL_Latin1_General_CP1_CI_AIとなっております。こちら関係ありますでしょうか?
    2020年3月26日 12:44
  • その辺りを調べているとSQL_Latin1_General_CP1_CI_ASの方が4~5倍処理速度が速いらしいですよ。環境によってかと思いますが、照合順序も少しは関係してそうですね。。。

    https://www.insight-tec.com/blog/technical/mssql_tune_contest_soneeta_2


    • 編集済み kaz8629 2020年3月26日 13:03
    2020年3月26日 12:57
  • ありがとうございます。
    私もその記事にたどり着きました。

    明日、旧環境に合わせてテストしてみます。

    2020年3月26日 14:52
  • ディスクの読み書き速度の参考としてCrystalDiskMark辺りを使って計測すると新旧の差はわかりそうな気がします。

    サーバーにZIPバージョンを配置できるのであれば新旧で計測してみるのも良いかと思います。

    https://crystalmark.info/ja/download/

    • 回答としてマーク tomomoto_tr 2020年3月27日 5:25
    2020年3月26日 15:05
  • CrystalDiskMark
    確認してみます。

    2020年3月27日 0:11
  • サーバ照合ですが、全体はSQL_Latin1_General_CP1_CI_AIでしたが、
    各DBはJapanese_CI_ASでした。
    この場合どうなるのでしょう?

    2020年3月27日 0:13
  • CrystalDiskMark
    結果張り付けさせていただきます

    2020年3月27日 0:34
  • * MB/s = 1,000,000 bytes/s [SATA/600 = 600,000,000 bytes/s]
    * KB = 1000 bytes, KiB = 1024 bytes

    [Read]
    Sequential 1MiB (Q=  8, T= 1):   577.368 MB/s [    550.6 IOPS] < 14473.47 us>
    Sequential 1MiB (Q=  1, T= 1):   358.017 MB/s [    341.4 IOPS] <  2924.65 us>
        Random 4KiB (Q= 32, T=16):   267.431 MB/s [  65290.8 IOPS] <  7829.05 us>
        Random 4KiB (Q=  1, T= 1):    19.106 MB/s [   4664.6 IOPS] <   213.22 us>

    [Write]
    Sequential 1MiB (Q=  8, T= 1):   704.546 MB/s [    671.9 IOPS] < 11833.75 us>
    Sequential 1MiB (Q=  1, T= 1):   306.363 MB/s [    292.2 IOPS] <  3411.89 us>
        Random 4KiB (Q= 32, T=16):    58.093 MB/s [  14182.9 IOPS] < 32035.90 us>
        Random 4KiB (Q=  1, T= 1):     8.283 MB/s [   2022.2 IOPS] <   492.73 us>

    Profile: Default
       Test: 1 GiB (x5) [Interval: 5 sec] <DefaultAffinity=DISABLED>
       Date: 2020/03/27 9:34:18
         OS: Windows Server 2012 R2 Server Standard (full installation) [6.3 Build 9600] (x64)

    2020年3月27日 0:35

  • * MB/s = 1,000,000 bytes/s [SATA/600 = 600,000,000 bytes/s]
    * KB = 1000 bytes, KiB = 1024 bytes

    [Read]
    Sequential 1MiB (Q=  8, T= 1):    60.189 MB/s [     57.4 IOPS] <137302.64 us>
    Sequential 1MiB (Q=  1, T= 1):    59.761 MB/s [     57.0 IOPS] < 17496.07 us>
        Random 4KiB (Q= 32, T=16):     2.506 MB/s [    611.8 IOPS] <294213.73 us>
        Random 4KiB (Q=  1, T= 1):     2.498 MB/s [    609.9 IOPS] <  1601.18 us>

    [Write]
    Sequential 1MiB (Q=  8, T= 1):    59.345 MB/s [     56.6 IOPS] <137491.56 us>
    Sequential 1MiB (Q=  1, T= 1):    59.975 MB/s [     57.2 IOPS] < 17374.83 us>
        Random 4KiB (Q= 32, T=16):     2.502 MB/s [    610.8 IOPS] <304062.54 us>
        Random 4KiB (Q=  1, T= 1):     2.457 MB/s [    599.9 IOPS] <  1618.35 us>

    Profile: Default
       Test: 1 GiB (x5) [Interval: 5 sec] <DefaultAffinity=DISABLED>
       Date: 2020/03/27 9:35:20
         OS: Windows Server 2012 R2 Server Standard (full installation) [6.3 Build 9600] (x64)

    2020年3月27日 0:35
  • ぱっと見て旧の方が高い(速い)ように思われますが、どうでしょうか?
    2020年3月27日 0:36
  • 軽く10倍くらい旧の方が速いですね。ということは設定で補うことはできなさそうですね。。。

    • 回答としてマーク tomomoto_tr 2020年3月27日 1:07
    2020年3月27日 0:51
  • ありがとうございます。
    ベンダーに確認します。
    2020年3月27日 0:57
  • クエリ実行速度が遅いとのことですが、特定のクエリのみ遅い感じでしょうか、それとも、全体的に遅くなった感じでしょうか?

    特定のクエリのみが遅い場合、以下のコマンドを遅い環境、早い環境で採取することで、比較することが可能です。 特定のクエリのみが遅い場合は、クエリの実行プランが遅い場合、早い場合で異なっている可能性が疑われます。
    また、念のため、データベースの互換性レベルに差異がないかについても、確認されてみると良いかもしれません。

    use <データベース名>
    go
    set statistics io on
    set statistics time on
    set statistics xml on
    go
    
    <クエリを記載>
    
    go
    set statistics io off
    set statistics time off
    set statistics xml off
    go


    • 編集済み NOBTA 2020年3月27日 16:05
    2020年3月27日 16:00
  • 申し訳ございません。
    しばらく見てなかったもので・・。
    データベース互換レベル・クエリ確認してみます。
    ありがとうございます。

    ディスクの回転速度をDドライブのみ上げたのですが(Cドライブは上げれないようでそのままです)、
    結果、早くなっておりませんでした。
    SQLserverをデータ保存先をDドライブしているのですが、
    Cドライブもディスク回転速度を変更しないと意味ないでしょうか。

    2020年3月31日 4:55
  • Dドライブに保存されているのであればDドライブのディスクの回転速度を上げれば大丈夫です。回転速度をあげた後のDドライブのCrystalDiskMarkの速度は旧に近づきましたか?
    2020年3月31日 5:04
  • ありがとうございます。
    結果お知らせします。

    2020年3月31日 5:13

  •  ***********************************************************************
    現行サーバ(Dドライブ)
    ------------------------------------------------------------------------------
    CrystalDiskMark 7.0.0 x64 (C) 2007-2019 hiyohiyo
      ------------------------------------------------------------------------------
    * MB/s = 1,000,000 bytes/s [SATA/600 = 600,000,000 bytes/s]
    * KB = 1000 bytes, KiB = 1024 bytes

    [Read]
    Sequential 1MiB (Q=  8, T= 1):   770.370 MB/s [    734.7 IOPS] < 10872.84 us>
    Sequential 1MiB (Q=  1, T= 1):   411.497 MB/s [    392.4 IOPS] <  2546.64 us>
        Random 4KiB (Q= 32, T=16):   310.042 MB/s [  75693.8 IOPS] <  6747.30 us>
        Random 4KiB (Q=  1, T= 1):    20.648 MB/s [   5041.0 IOPS] <   197.64 us>

    [Write]
    Sequential 1MiB (Q=  8, T= 1):   760.322 MB/s [    725.1 IOPS] < 10975.33 us>
    Sequential 1MiB (Q=  1, T= 1):   350.039 MB/s [    333.8 IOPS] <  2988.57 us>
        Random 4KiB (Q= 32, T=16):    83.986 MB/s [  20504.4 IOPS] < 22732.19 us>
        Random 4KiB (Q=  1, T= 1):     9.927 MB/s [   2423.6 IOPS] <   411.51 us>

    Profile: Default
       Test: 1 GiB (x5) [Interval: 5 sec] <DefaultAffinity=DISABLED>
       Date: 2020/03/30 18:16:54
         OS: Windows Server 2012 R2 Server Standard (full installation) [6.3 Build 9600] (x64)

    ***********************************************************************
    新サーバ(Dドライブ)
    ------------------------------------------------------------------------------
    CrystalDiskMark 7.0.0 x64 (C) 2007-2019 hiyohiyo
      ------------------------------------------------------------------------------
    * MB/s = 1,000,000 bytes/s [SATA/600 = 600,000,000 bytes/s]
    * KB = 1000 bytes, KiB = 1024 bytes

    [Read]
    Sequential 1MiB (Q=  8, T= 1):   148.871 MB/s [    142.0 IOPS] < 55767.75 us>
    Sequential 1MiB (Q=  1, T= 1):    66.477 MB/s [     63.4 IOPS] < 14799.26 us>
        Random 4KiB (Q= 32, T=16):     9.166 MB/s [   2237.8 IOPS] <126495.25 us>
        Random 4KiB (Q=  1, T= 1):     3.484 MB/s [    850.6 IOPS] <  1116.21 us>

    [Write]
    Sequential 1MiB (Q=  8, T= 1):   167.317 MB/s [    159.6 IOPS] < 49072.17 us>
    Sequential 1MiB (Q=  1, T= 1):   121.996 MB/s [    116.3 IOPS] <  8040.41 us>
        Random 4KiB (Q= 32, T=16):     9.372 MB/s [   2288.1 IOPS] <131408.10 us>
        Random 4KiB (Q=  1, T= 1):     4.110 MB/s [   1003.4 IOPS] <   967.84 us>

    Profile: Default
       Test: 1 GiB (x5) [Interval: 5 sec] <DefaultAffinity=DISABLED>
       Date: 2020/03/30 18:17:16
         OS: Windows Server 2012 R2 Server Standard (full installation) [6.3 Build 9600] (x64)

    ***********************************************************************
    新サーバ(Cドライブ)
    ------------------------------------------------------------------------------
    CrystalDiskMark 7.0.0 x64 (C) 2007-2019 hiyohiyo
      ------------------------------------------------------------------------------
    * MB/s = 1,000,000 bytes/s [SATA/600 = 600,000,000 bytes/s]
    * KB = 1000 bytes, KiB = 1024 bytes

    [Read]
    Sequential 1MiB (Q=  8, T= 1):    60.074 MB/s [     57.3 IOPS] <137345.90 us>
    Sequential 1MiB (Q=  1, T= 1):    59.642 MB/s [     56.9 IOPS] < 17498.78 us>
        Random 4KiB (Q= 32, T=16):     2.444 MB/s [    596.7 IOPS] <274744.86 us>
        Random 4KiB (Q=  1, T= 1):     2.346 MB/s [    572.8 IOPS] <  1710.72 us>

    [Write]
    Sequential 1MiB (Q=  8, T= 1):    58.509 MB/s [     55.8 IOPS] <136878.05 us>
    Sequential 1MiB (Q=  1, T= 1):    58.507 MB/s [     55.8 IOPS] < 17540.88 us>
        Random 4KiB (Q= 32, T=16):     2.347 MB/s [    573.0 IOPS] <249567.16 us>
        Random 4KiB (Q=  1, T= 1):     2.293 MB/s [    559.8 IOPS] <  1757.85 us>

    Profile: Default
       Test: 1 GiB (x5) [Interval: 5 sec] <DefaultAffinity=DISABLED>
       Date: 2020/03/30 18:25:17
         OS: Windows Server 2012 R2 Server Standard (full installation) [6.3 Build 9600] (x64)
    ***********************************************************************
    2020年3月31日 5:14
  • ディスク回転数をあげてはもらえたのですが、これが限界のようです。
    結果かわらずでした。
    ベンダーからはストレージを変更したのに、結果がかわっていないのは
    スペックの問題ではなく、中身が悪いと言われています。

    2020年3月31日 5:21
  • 明らかにハードウェア性能に差があるのに酷いですね。確かにDドライブの性能は前回より上がってますが旧に比べれば遅いですよね。。。

    ハードの選定によるものだと思うので、速度を比較した情報をベンダー様にご提示してはいかがでしょうか?

    (それかベンダー様から選定した根拠を出していただくかですね。。。)



    • 編集済み kaz8629 2020年3月31日 7:19
    2020年3月31日 6:59
  • 提示はしているのですが、性能上がったのに、改善されていないのは・・・という感じです。
    ちなみにサービス名をいいますとこちらです。
    nttcomのeclサービスです。
    https://ecl.ntt.com/documents/service-descriptions/block-storage/block_storage.html

    2020年3月31日 7:33
  • データベース物理ファイルを Dドライブに配置されているのであれば、C ドライブのディスク性能を上げたとしても、クエリのパフォーマンスは改善しないのではないかと思います。
    特定のクエリのみ遅い場合は、クエリの実行プランが遅い場合、早い場合とで異なっていることが疑われます。
    もしくは、ブロッキングなどが発生しているのかもしれません。

    遅いクエリと早いクエリとで実行プランの差異が確認できた場合は、クエリヒント、結合ヒント、プランガイドを使用するなどして、チューニングすることが可能です。
    なお、データベースの互換性レベルを念のため確認したらよいとお伝えした理由としては、SQL Server 2014 以降、クエリ実行プランを生成するオプティマイザで新しいカーディナリティを使用されることになり、データベースの互換性レベルにより、本機能の使用有無が変わるためとなります。

    全体的にクエリのパフォーマンスが低下している場合は、本機能の影響についても疑ってみてもよいかもしれません。個人的には、Hash 結合操作のほうが処理が速いのに、Nested Loopが選択され、処理が遅延していたり、非典型的なパラメータによるクエリのコンパイルなどの要因により、最適ではないクエリの実行プランが選択されているのかなぁと考えております。

    カーディナリティ推定 (SQL Server)
    https://docs.microsoft.com/ja-jp/sql/relational-databases/performance/cardinality-estimation-sql-server?view=sql-server-ver15

    2020年3月31日 9:11
  • ありがとうございます。
    データベース物理ファイルを Dドライブにして、Dドライブの性能をあげてもらってます。

    データベース互換レベルは同じでした。
    クエリはまだ確認できていないので、確認いたします。

    2020年3月31日 9:34
  • 全体的に重い(CPU負荷高い)ですが、互換性レベルは一緒です。
    2020年4月1日 6:48
  • 全体的にCPU使用率が高いとのことですが、特定のクエリでCPUを消費しているのか、もしくは、1件1件は重くないクエリだが大量に実行されているのかで言えば、どちらになりますかね?

    CPU使用率が高い期間に sys.dm_exec_requests 情報を採取することで、どのクエリでCPU時間が消費されているかを確認できる可能性があります。パフォーマンスチューニングに向けた情報採取ではありませんが、以下のブログに記載しております定期的に情報を取得するスクリプトを参考に、情報を採取されてみてはいかがでしょう。

    https://www.nobtak.com/entry/tlogs0

    2020年4月1日 8:17
  • ありがとうございます。
    重くないクエリが大量に実行されている形になります。
    sys.dm_exec_requests 情報を確認してみます。

    2020年4月1日 8:44
  • 参考サイトそのままに値を取得したのですが、
    どちらの情報を参照したらよろしいでしょうか。
    申し訳ございませんが、ご教授くださいませ。
    rpt として保存しております。




    2020年4月1日 9:55
  • サーバについて、同じCPU16コアですが違いがあります。
    関係ありますでしょうか。ERRORLOGの値です。

    現行
    SQL Server detected 1 sockets with 16 cores per socket and 16 logical processors per socket, 16 total logical processors; using 16 logical processors based on SQL Server licensing. This is an informational message; no user action is required.


    SQL Server detected 2 sockets with 8 cores per socket and 8 logical processors per socket, 16 total logical processors; using 16 logical processors based on SQL Server licensing. This is an informational message; no user action is required.


    2020年4月1日 10:49
  • 現行、新 ともに 「using 16 logical processors based on SQL Server licensing」 となっていますので、SQL Server プロセスで使用可能な論理プロセス数に差異はなく、今回の現象との関係性は極めて低いかと思います。
    2020年4月2日 3:59
  • 「+++ sys.dm_exec_requests 情報 +++」 の情報で、cpu_time, reads, writes, logical_reads の数が多いもの探し、「+++ キャッシュされているクエリ情報 +++」 で、session_id をもとに該当のクエリ内容を確認すると良いかと思います。

    そして該当のクエリを SSMS から実行できるのであれば、前回もお伝えしましたが、以下のようなコマンドで遅いパターン、早いパータンの両パターンの実行プランを採取し、比較してみると良いかと思います。

    use <データベース名>
    go
    set statistics io on
    set statistics time on
    set statistics xml on
    go
    
    <クエリを記載>
    
    go
    set statistics io off
    set statistics time off
    set statistics xml off
    go

    • 編集済み NOBTA 2020年4月2日 4:07
    2020年4月2日 4:03
  • ありがとうございます。
    確認してみます。
    2020年4月2日 5:02
  • キャッシュされているクエリの値は新サーバで下記のとおりでした。
    一番下クエリは、取得用のクエリなので、その他のクエリはほとんど値が小さいです。
    CPUは30%前後で推移してます。

    cputime,reads,write,logical_reads
    1 0 0 3
    0 0 0 0
    3 0 0 30
    0 0 0 0
    120 0 0 102

    sys.dm_exec_requests 情報も数値が高いものがありませんでした。
    sys.dm_exec_sessions で、statusがsleepingのものが多いのが気になりました。
    290個中に285個はsleepingでした。

    現行サーバでは1000個あって995はsleepingでした。
    関係なさそうですね。


    2020年4月2日 5:59
  • 現状の状態でも遅延が発生している感じでしょうか。 ちなみに、「クエリ実行速度も遅く」 とありますが、現行サーバーと比較して、具体的にどの程度遅い感じでしょうか。
    CPU使用率が 30% 程度であれば、CPU負荷はほとんどない状態と言えますね

    また、sys.dm_os_wait_stats コマンドを実行した場合、待ち時間の多い wait_type は何になりますかね。

    sys.dm_os_wait_stats (Transact-SQL)
    https://docs.microsoft.com/ja-jp/sql/relational-databases/system-dynamic-management-views/sys-dm-os-wait-stats-transact-sql?view=sql-server-ver15

    2020年4月2日 9:46
  • ありがとうございます。
    確認いたします。
    2020年4月3日 0:12
  • SELECT wait_type,wait_time_ms FROM sys.dm_os_wait_stats ORDER BY wait_time_ms desc

    以下、実行結果です。
    SLEEP_TASK 471718308
    BROKER_TASK_STOP 315126237
    HADR_FILESTREAM_IOMGR_IOCOMPLETION 314706928
    QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP 314706912
    SP_SERVER_DIAGNOSTICS_SLEEP 314704630
    QDS_PERSIST_TASK_MAIN_LOOP_SLEEP 314700147
    XE_TIMER_EVENT 314666707
    SQLTRACE_INCREMENTAL_FLUSH_SLEEP 314654447
    DIRTY_PAGE_POLL 314644168
    XE_DISPATCHER_WAIT 314529103
    REQUEST_FOR_DEADLOCK_SEARCH 314445608
    CHECKPOINT_QUEUE 313343557
    LAZYWRITER_SLEEP 313085855
    LOGMGR_QUEUE 312640801
    FT_IFTS_SCHEDULER_IDLE_WAIT 312077618
    BROKER_TO_FLUSH 157354287
    PREEMPTIVE_OS_AUTHENTICATIONOPS 114621926
    PREEMPTIVE_OS_CRYPTOPS 30882847
    PREEMPTIVE_OS_NETVALIDATEPASSWORDPOLICY 15235435
    PREEMPTIVE_OS_CRYPTACQUIRECONTEXT 14065684
    2020年4月3日 0:30
  • 現行サーバでも確認します。
    2020年4月3日 0:31
  • 以下、現行サーバ結果です。
    DBMIRROR_EVENTS_QUEUE 50980920044
    DBMIRRORING_CMD 50947047514
    BROKER_TASK_STOP 22434817019
    CLR_AUTO_EVENT 14375480688
    SLEEP_TASK 10933790797
    QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP 7284671038
    HADR_FILESTREAM_IOMGR_IOCOMPLETION 7284661714
    QDS_PERSIST_TASK_MAIN_LOOP_SLEEP 7284659468
    XE_TIMER_EVENT 7284645122
    DIRTY_PAGE_POLL 7284545690
    SP_SERVER_DIAGNOSTICS_SLEEP 7284457674
    REQUEST_FOR_DEADLOCK_SEARCH 7284120947
    LAZYWRITER_SLEEP 7283881998
    SQLTRACE_INCREMENTAL_FLUSH_SLEEP 7283867840
    CHECKPOINT_QUEUE 7280860332
    XE_DISPATCHER_WAIT 7273165411
    LOGMGR_QUEUE 7268577954
    FT_IFTS_SCHEDULER_IDLE_WAIT 7224286391
    BROKER_TO_FLUSH 3642332831
    PREEMPTIVE_OS_AUTHENTICATIONOPS 1683418907
    2020年4月3日 0:33
  • 現行サーバはミラーリングしており、
    新サーバもミラーリングをしますが、現在調査のため、ミラー処理を止めております。

    上位20を抜粋しております。
    2020年4月3日 0:34
  • >現状の状態でも遅延が発生している感じでしょうか。 ちなみに、「クエリ実行速度も遅く」 とありますが、現行サーバーと比較して、具体的にどの程度遅い感じでしょうか。

    現在、classicASPを使用しており、web(iis)経由でSQLServerとやりとりしており、
    あるaspを実行した際、現行サーバは0~1秒でレスポンスを返すのに、新サーバは3~4秒かかる感じです。
    時間の計測はasp内で行っており、プログラムの始まりと終わりに時間を出力しております。

    新サーバではバックグランドでアプリのみを動かしている
    現行サーバはバックグランドアプリ+ユーザからのアクセス
    という状況ですが、新サーバの方がCPUが高い状況です。
    旧20%前後に対して新30%前後

    2020年4月3日 0:38
  • Wait 情報を確認する限り、問題となりそうな待ち状態は確認できないですね。念のため、以下のコマンドを実行したうえで、遅延発生時の情報を採取してもらえますしょうか。

    DBCC SQLPERF ('sys.dm_os_wait_stats', CLEAR);  
    GO  

    なお、新サーバーのCPU使用率ですが、CPU使用率が高いのは SQL Server プロセス (sqlservr.exe) であり、現行サーバーとひかくしても、CPU使用率が10%程度 高い感じでしょうか?

    また、classicASPで実行されているクエリを抜き出し、現行環境、新環境で、以前に伝えておりますコマンドにて実行プランを採取した場合、実行プランに差異は確認できますでしょうか?

    現在、確認できている情報を確認する限り、SQL Server 側の問題が確認できていないのですが、classicASPの中のどの関数でどの程度時間を要しているかをトレースすることなどは出来る感じでしょうか。

    2020年4月3日 11:29
  • ありがとうございます。
    確認いたします。

    2020年4月6日 0:23
  • >なお、新サーバーのCPU使用率ですが、CPU使用率が高いのは SQL Server プロセス (sqlservr.exe) であり、現行サーバーとひかくしても、CPU使用率が10%程度 高い感じでしょうか?

    SQLServerプロセスが高いです。
    その次に高いのは、Local Security Authority processでこちらも差異がありました。
    旧が2%程度に対して、新が7%程度です。

    2020年4月6日 1:04
  • >classicASPで実行されているクエリを抜き出し、現行環境、新環境で、以前に伝えておりますコマンドにて実行プランを採取した場合、実行プランに差異は確認できますでしょうか?
    実行プラン確認しましたが、差異はありませんでした。

    2020年4月6日 2:38
  • DBCC SQLPERF ('sys.dm_os_wait_stats', CLEAR); 
    GO 
    を実行して、ある程度動作させて
    SELECT wait_type,wait_time_ms FROM sys.dm_os_wait_stats ORDER BY wait_time_ms desc
    という採取の仕方で問題ありませんでしょうか。

    2020年4月6日 2:52
  • >現在、確認できている情報を確認する限り、SQL Server 側の問題が確認できていないのですが、classicASPの中のどの関数でどの程度時間を要しているかをトレースすることなどは出来る感じでしょうか。

    確認します。

    2020年4月6日 4:01
  • はい、ご認識の通り、一旦 wait stats 情報をクリアしたうえで、ある程度動作させた後、再度 wait stats 情報を該当のコマンドで採取してもらえればと思います。
    2020年4月6日 4:38
  • 情報を共有していただき、ありがとうございます。 実行プランに差異がないとすれば、クエリが実行される前のフェーズ (classicASPからSQL Serverへの接続が確立され、クエリが実行されるまでの間)で時間を要しているのかもしれません。
    2020年4月6日 4:40
  • クリアした後の結果、記載します。

    旧サーバ(速いサーバ)
    DBMIRRORING_CMD 80404004
    DBMIRROR_EVENTS_QUEUE 72947705
    BROKER_TASK_STOP 33255616
    SLEEP_TASK 15652130
    SP_SERVER_DIAGNOSTICS_SLEEP 10500237
    QDS_PERSIST_TASK_MAIN_LOOP_SLEEP 10440544
    QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP 10440298
    HADR_FILESTREAM_IOMGR_IOCOMPLETION 10423844
    DIRTY_PAGE_POLL 10423565
    REQUEST_FOR_DEADLOCK_SEARCH 10422709
    LAZYWRITER_SLEEP 10422665
    XE_TIMER_EVENT 10422643
    SQLTRACE_INCREMENTAL_FLUSH_SLEEP 10420258
    LOGMGR_QUEUE 10400550
    XE_DISPATCHER_WAIT 10395912
    CHECKPOINT_QUEUE 10323583
    FT_IFTS_SCHEDULER_IDLE_WAIT 10320531
    BROKER_TO_FLUSH 5211681
    PREEMPTIVE_OS_AUTHENTICATIONOPS 3664562
    PREEMPTIVE_OS_CRYPTOPS 2329151

    新サーバ(遅いサーバ)
    SLEEP_TASK 15429674
    PREEMPTIVE_OS_AUTHENTICATIONOPS 13044111
    QDS_PERSIST_TASK_MAIN_LOOP_SLEEP 10320689
    QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP 10320677
    BROKER_TASK_STOP 10315055
    HADR_FILESTREAM_IOMGR_IOCOMPLETION 10292938
    SQLTRACE_INCREMENTAL_FLUSH_SLEEP 10292173
    DIRTY_PAGE_POLL 10290951
    XE_TIMER_EVENT 10288809
    REQUEST_FOR_DEADLOCK_SEARCH 10286506
    XE_DISPATCHER_WAIT 10282408
    LAZYWRITER_SLEEP 10264749
    FT_IFTS_SCHEDULER_IDLE_WAIT 10201704
    SP_SERVER_DIAGNOSTICS_SLEEP 10199987
    LOGMGR_QUEUE 10111763
    CHECKPOINT_QUEUE 10083047
    BROKER_TO_FLUSH 5146785
    PREEMPTIVE_OS_CRYPTOPS 3726871
    PREEMPTIVE_OS_NETVALIDATEPASSWORDPOLICY 1773310
    PREEMPTIVE_OS_CRYPTACQUIRECONTEXT 1661180


    2020年4月6日 5:15
  • aspではSQLと接続して、SELECTして結果を返すところで遅くなっているようです。

    プログラム内でDBに接続
    Set objConn = Server.CreateObject("ADODB.Connection")
    objConn.ConnectionTimeout = 15
    objConn.Open Provider=SQLNCLI11;Data Source= IP ;Persist Security Info=False;Initial Catalog=***;User ID='***';Password='***'

    クエリを実行
    時間計測開始
    Set objRecord = objConn.Execute( クエリ )
    時間計測終了



    2020年4月6日 5:41
  • SQLNCLI11で接続しているのは、ミラーリングするためです。
    2020年4月6日 6:38
  • SQLNCLI11のバージョンは違います。

    旧 11.2.5058.0
    新 11.4.7001.0

    2020年4月6日 6:57
  • asp側の検証をしていたのですが、
    時間がかかっているクエリをコメントにして実行すると速いのですが、
    時間がかかっているクエリのみを実行すると速いというおかしな現象が出てます。
    2020年4月6日 6:59
  • Wait type を確認して気になったのは 「PREEMPTIVE_OS_AUTHENTICATIONOPS」 待ちでしょうか。
    こちらは認証待ち(Active Directoryなど)なので、SQL ServerからActive Directoryに認証要求をなげて、その結果を待っている状態になるかと思います。

    一般的にPREEMPTIVE_OS_AUTHENTICATIONOPS」 待ちが長くなる要因としては、Active Directory側の負荷が高いなど、何らかの問題が Active Directory側で発生している、もしくは、SQL Server - Active Directory間のネットワークで遅延が発生しているなどが疑われますね。

    しかしながら、時間を要しているクエリを asp 側でコメントにして実行する(SQL Server にはログインするが、クエリは実行しない状態である認識)と、遅延が発生しないというのが不思議ですね。
    旧環境、新環境で、所属しているドメインは同じでしょうか。 また、ネットワークの経路的に新環境のほうが、旧環境と比較し、Active Directory までのネットワークが物理的に離れているなどはありますかね?

    2020年4月6日 9:37
  • また、時間が掛かっているクエリのみを実行したパターン、すべてのクエリを実行したパターン(遅延) の両パターンで、サーバートレースを採取してみて、再度 実行プランを比較してみてはいかがでしょう?

    SQL トレーススクリプトの作成、実行 (SQL Server 2005 以降)
    https://docs.microsoft.com/ja-jp/archive/blogs/jpsql/sql-sql-server-2005-2014

    サーバートレーススクリプトの作成時に指定するイベント。

    ※大量にログが出力される可能性もあるため、該当のASPのクエリが採取できた後、すぐに停止すると良いかと思います。

    ---

    Errors and Warnings
    ※ すべてのイベント

    Performance
     Showplan XML
     Showplan XML Statistics Profile
     
    Sessions
     ExistingConnection

    Stored Procedure
     RPC:Starting
     RPC:Completed
     SP:Starting
     SP:Completed 
     SP:StmtStarting
     SP:StmtCompleted

    TSQL
     SQL:BatchStarting
     SQL:BatchCompleted
     SQL:StmtStarting
     SQL:StmtCompleted

    ---

    2020年4月6日 9:46
  • ありがとうございます。
    Active Directoryは使用しておりません。

    >しかしながら、時間を要しているクエリを asp 側でコメントにして実行する(SQL Server にはログインするが、クエリは実行しない状態である認識)と、遅延が発生しないというのが不思議ですね。

    申し訳ございません書き方が悪かったですね。
    クエリは実行しております。

    トレース確認します。



    2020年4月7日 0:56
  • トレース確認中ですが、一点気になった点が、
    User Error Message データベース コンテキストが ***に変更されました。
    User Error Message 言語設定が 日本語 に変更されました。
    と始めに表示されました。

    2020年4月7日 3:56
  • 旧サーバの環境でも同様のメッセージが出ていますので、関係ないようです。
    2020年4月7日 5:32
  • Performance - Showplan XML Statistics Profile では、実行プランと I/O 情報を確認することができますので、今回確認されている遅いパターン、早いパターンで差異がないかを確認されると良いかと思います。
    2020年4月7日 5:37
  • トレースして、遅い時速い時実行プラン(同じSQL)を確認しましたが、
    結果は同じでした。
    2020年4月7日 5:52
  • Duration も同じ時間になっていましたかね? また、Reads, writes などの I/O には違いはありましたでしょうか?
    2020年4月7日 6:21
  • CPU READS WRITES Duration
    16 3 0 16
    両方上記のような値です。

    2020年4月7日 8:26
  • 申し訳ございません。
    現象が改善しないことから、サーバ移行がなくなりました。

    今までいろいろご教授いただきまして、ありがとうございました。
    サーバ自体もなくなってしましますので、これ以上の検証もできなくなりました。

    NOBTA様、kaz8629様、Mr.Spock様どうもありがとうございました。

    2020年4月7日 8:33
  • 早いパターン、遅いパターンのいずれでも、実行されているクエリの実行プランも同じ、かつ、クエリ実行時のI/Oも同じという感じなのですね。
    そうなると、やはり 「PREEMPTIVE_OS_AUTHENTICATIONOPS」 の待ちが影響しているのかもしれません。 今回はサーバー移行をされないとのことですが、今後 類似の現象が発生した際には、上記の待ちを解消する方法という観点から、サポートにお問い合わせをしてみてもよいかもしれませんね。
    2020年4月7日 14:06
  • ありがとうございました。
    確認してみます。
    2020年4月8日 0:11