SCVMM DebugView ログ トレースについて

こんにちは。

Windows テクノロジー サポートの大羽です。

SCVMM(Sytem Center Virtual Machine Manager)ネタについても記載して

いきたいと思います。

製品についてご存知ない方は、以下のサイトをご確認ください。

SCVMM Technet Home

https://technet.microsoft.com/ja-jp/scvmm/default.aspx

SCVMM は Hyper-V や VMware の統合管理や P2V など、仮想環境における

様々な機能が盛り込まれた製品です。

OS 上の様々なコンポーネントを利用して、多くの機能を実現しているわけ

ですが、高機能だけにトラブルが発生したときは大変です。

そんなトラブルが発生したときに、どのようなツールが使えるのか、という

テーマで記載したいと思います。

今回は DebugView を利用したトレースを採取する方法です。

英語版の手順は、以下のサイトにありますが、何故か日本語で説明している

サイトが見受けられないので、記載しておきます。

How to collect SCVMM traces

https://blogs.technet.com/chengw/archive/2008/05/08/how-to-collect-scvmm-traces.aspx

DebugView は以下のサイトからダウンロードいただけます。

DebugView for Windows v4.76

https://technet.microsoft.com/en-us/sysinternals/bb896647.aspx

事前準備

----------

1. 以下のコードを Text ファイルに記述し、ファイル名を "odsflags.cmd"に

   変更します。

@echo off

echo ODS control flags - only trace with set flags will go to ODS

if (%1)==() goto :HELP

if (%1)==(-?) goto :HELP

if (%1)==(/?) goto :HELP

echo Setting flag to %1...

reg ADD "HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Tracing\Microsoft\Carmine" /v ODSFLAGS /t REG_DWORD /d %1 /f

echo Done.

goto :EXIT

:HELP

echo Usage: odsflags [flag], where flag is

echo TRACE_ERROR = 0x2,

echo TRACE_DBG_NORMAL = 0x4,

echo TRACE_DBG_VERBOSE = 0x8,

echo TRACE_PERF = 0x10,

echo TRACE_TEST_INFO = 0x20,

echo TRACE_TEST_WARNING = 0x40,

echo TRACE_TEST_ERROR = 0x80,

:EXIT

2. 以下のコードを Text ファイルに記述し、ファイル名を "odson.reg"に

   変更します。

Windows Registry Editor Version 5.00

[HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Tracing\Microsoft\Carmine]

"ODS"=dword:00000001

3. 以下のコードを Text ファイルに記述し、ファイル名を "odsoff.reg"に

   変更します。

Windows Registry Editor Version 5.00

[HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Tracing\Microsoft\Carmine]

"ODS"=dword:00000000

上記作成したファイルを、SCVMM ホスト上の任意のフォルダに纏めてコピー

します。

これで準備完了です。

DebugView 採取手順

----------------------

さて、それでは情報を収集してみましょう。

※管理者権限で実施してください。

1. SCVMM ホスト上でコマンド プロンプトを起動します。

2. コマンド プロンプト上で、先ほどコピーした "odson.reg" を実行します。

3. 同じくプロンプト上で、先ほどコピーした "odsflags.cmd 255" を実行します。

4. DebugView を起動します。

5. [Capture] メニュー内の "Capture Win32" と "Capture Global Win32" の

   両方の項目にチェックをいれます。

これでトレース開始です。

虫めがねボタンで起動・停止の制御ができます。

採取を終了するときは、ツールを停止してコマンドプロンプトから"odsoff.reg"を

実行します。

レジストリの Tracing フラグがオフになり、トレースが終了します。

で、どんな情報が採取できるかと言いますと、こんな感じです。

DebugView ログ

------------------

[3788] 0ECC.0C68::05/15-11:50:38.759#04:WsmanAPIWrapper.cs(492): HostSessionCache: elements for [S-1-5-18-MSCS.test.microsoft.com]: [15]

[3788] 0ECC.0C68::05/15-11:50:38.790#04:WsmanAPIWrapper.cs(906): WSMAN: URL: [https://MSCS.test.microsoft.com:80] Verb: [GET], resource: [https://schemas.microsoft.com/wbem/wsman/1/wmi/root/virtualization/Msvm_VirtualSystemGlobalSettingData?InstanceID=Microsoft:F658FDFE-752E-4414-B98D-A967D3391429\Global]

[3788] 0ECC.0C68::05/15-11:50:38.790#04:WsmanAPIWrapper.cs(492): HostSessionCache: elements for [S-1-5-18-MSCS.test.microsoft.com]: [15]

[3788] 0ECC.0C68::05/15-11:50:38.790#26:PerfRefresher.cs(375): Getting VM perf counters for C:\ProgramData\Microsoft\Windows\Hyper-V\test2\Virtual Machines\F658FDFE-752E-4414-B98D-A967D3391429.xml = 0 , 0,0, 0,0

[3788] 0ECC.0C68::05/15-11:50:38.790#21:EventManager.cs(100): PublishUpdateForPerfData 5cdacb70-0254-44ce-93a9-52578025c374

[3788] 0ECC.0C68::05/15-11:50:38.805#20:ObjectAuthorizationManager.cs(94): Accessibile=True, Profile=Administrator, Object Type=VM, ID=5cdacb70-0254-44ce-93a9-52578025c374

[3788] 0ECC.0C68::05/15-11:50:38.805#21:EventClientConnection.cs(142): Publish uuid:558d8ef6-0811-4f0d-9aab-8fa195f9f88b;id=4 VM Update

[3788] 0ECC.0C68::05/15-11:50:38.805#04:tieredPerfCounters.cs(380): GetNextTierDatapoint: Average value for the next tier: 0 [tier: 7]

[3788] 0ECC.0C68::05/15-11:50:38.805#18:PlacementHelpers.cs(140): PlacementHelpers: ScaleProcessorUtilization, CPU util [0]

[3788] 0ECC.0C68::05/15-11:50:38.805#18:PlacementHelpers.cs(344): GetHostRatings: GetSourceProcessorWorkload, looking up processor []

[3788] 0ECC.0C68::05/15-11:50:38.805#18:PlacementHelpers.cs(789): GetHostRatings: GetProcessorConfiguration, Manufacturer: Intel, Model: [Pentium 4], Physical ProcessorCount: [1], Logical ProcessorCount: [4], Cores per Processor: [4], L2CacheSize: [12288] KB, L3CacheSize: [0] KB, Speed: [2833] Mhz, Bus Speed: [1333] Mhz

[3788] 0ECC.0C68::05/15-11:50:38.805#18:PlacementHelpers.cs(344): GetHostRatings: GetSourceProcessorWorkload, looking up processor [359c1234-add2-4e7f-92da-f1fa384c2f5a]

[3788] 0ECC.0C68::05/15-11:50:38.805#18:PlacementHelpers.cs(161): PlacementHelpers: ScaleProcessorUtilization, CPU orig: [0], CPU target: [0] (raw value was [0])

[3788] 0ECC.0C68::05/15-11:50:38.805#04:tieredPerfCounters.cs(380): GetNextTierDatapoint: Average value for the next tier: 0 [tier: 7]

[3788] 0ECC.0C68::05/15-11:50:38.805#04:tieredPerfCounters.cs(380): GetNextTierDatapoint: Average value for the next tier: 0 [tier: 7]

[3788] 0ECC.0C68::05/15-11:50:38.805#04:tieredPerfCounters.cs(380): GetNextTierDatapoint: Average value for the next tier: 0 [tier: 7]

[3788] 0ECC.0C68::05/15-11:50:38.805#04:tieredPerfCounters.cs(380): GetNextTierDatapoint: Average value for the next tier: 0 [tier: 7]

[3788] 0ECC.0C68::05/15-11:50:38.805#21:EventManager.cs(94): PublishUpdate 5cdacb25-0254-44ce-93a9-52578025c374

[3788] 0ECC.0C68::05/15-11:50:38.805#20:ObjectAuthorizationManager.cs(94): Accessibile=True, Profile=Administrator, Object Type=TieredPerfData, ID=5cdacb25-0254-44ce-93a9-52578025c374

[3788] 0ECC.0C68::05/15-11:50:38.805#21:EventClientConnection.cs(142): Publish uuid:558d8ef6-0811-4f0d-9aab-8fa195f9f88b;id=4 TieredPerfData Update

[3788] 0ECC.0C68::05/15-11:50:38.805#04:CarmineObjectLock.cs(158): CarmineObjectLock, Task b1f8526d-0a67-4813-8a76-3ae9735f8278 Releasing Read lock on OperatingSystem object with ID fd1b1d5a-8ce9-41f2-9d1d-33655579157c|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#04:CarmineObjectLock.cs(106): CarmineObjectLock, Non Running Task b1f8526d-0a67-4813-8a76-3ae9735f8278 requested lock on VM object with ID 81ff6bb9-66a2-46c5-80cd-8d9cf78d8ba7|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#14:WLCDBAccessHelper.cs(94): Reading object 81ff6bb9-66a2-46c5-80cd-8d9cf78d8ba7 of type VM

[3788] 0ECC.0C68::05/15-11:50:38.805#14:ImgLibOM.cs(66): VM object test3 instanciated with ID 81ff6bb9-66a2-46c5-80cd-8d9cf78d8ba7 lock NoLock|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#04:CarmineObjectLock.cs(106): CarmineObjectLock, Non Running Task b1f8526d-0a67-4813-8a76-3ae9735f8278 requested lock on VMHost object with ID 3f6a0784-712c-46d9-9e32-5a8ad96549a2|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#20:UserRoleAuthorizationHelper.cs(163): Get: Running SP prc_ADHC_HostDisk_GetByHost

[3788] 0ECC.0C68::05/15-11:50:38.805#09:HostDisk.cs(239): Retrieved all HostDisk rows for serverID=3f6a0784-712c-46d9-9e32-5a8ad96549a2, serverType=VMHost

[3788] 0ECC.0C68::05/15-11:50:38.805#20:UserRoleAuthorizationHelper.cs(163): Get: Running SP prc_ADHC_HostVolume_GetByHost

[3788] 0ECC.0C68::05/15-11:50:38.805#09:HostVolume.cs(254): Retrieved all HostVolume rows for hostID=3f6a0784-712c-46d9-9e32-5a8ad96549a2

[3788] 0ECC.0C68::05/15-11:50:38.805#04:CarmineObjectLock.cs(106): CarmineObjectLock, Non Running Task b1f8526d-0a67-4813-8a76-3ae9735f8278 requested lock on VirtualDVDDrive object with ID ef58abae-ea2b-4952-ba68-7109ebdf11cb|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#14:WLCDBAccessHelper.cs(94): Reading object ef58abae-ea2b-4952-ba68-7109ebdf11cb of type VirtualDVDDrive

[3788] 0ECC.0C68::05/15-11:50:38.805#14:ImgLibOM.cs(66): VirtualDVDDrive object test3 instanciated with ID ef58abae-ea2b-4952-ba68-7109ebdf11cb lock NoLock|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#04:CarmineObjectLock.cs(106): CarmineObjectLock, Non Running Task b1f8526d-0a67-4813-8a76-3ae9735f8278 requested lock on VirtualFloppyDrive object with ID 14424183-912a-4757-8bf5-1a06a257e605|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#14:WLCDBAccessHelper.cs(94): Reading object 14424183-912a-4757-8bf5-1a06a257e605 of type VirtualFloppyDrive

[3788] 0ECC.0C68::05/15-11:50:38.805#14:ImgLibOM.cs(66): VirtualFloppyDrive object test3 instanciated with ID 14424183-912a-4757-8bf5-1a06a257e605 lock NoLock|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#04:CarmineObjectLock.cs(106): CarmineObjectLock, Non Running Task b1f8526d-0a67-4813-8a76-3ae9735f8278 requested lock on VirtualNetworkAdapter object with ID e22adf44-568e-43c2-bd04-6e88b5e0887e|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#14:WLCDBAccessHelper.cs(94): Reading object e22adf44-568e-43c2-bd04-6e88b5e0887e of type VirtualNetworkAdapter

[3788] 0ECC.0C68::05/15-11:50:38.805#14:ImgLibOM.cs(66): VirtualNetworkAdapter object test3 instanciated with ID e22adf44-568e-43c2-bd04-6e88b5e0887e lock NoLock|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#04:CarmineObjectLock.cs(106): CarmineObjectLock, Non Running Task b1f8526d-0a67-4813-8a76-3ae9735f8278 requested lock on VirtualDiskDrive object with ID e666a5aa-497e-4f4d-acf9-081a929350e8|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#14:WLCDBAccessHelper.cs(94): Reading object e666a5aa-497e-4f4d-acf9-081a929350e8 of type VirtualDiskDrive

[3788] 0ECC.0C68::05/15-11:50:38.805#14:ImgLibOM.cs(66): VirtualDiskDrive object test3 instanciated with ID e666a5aa-497e-4f4d-acf9-081a929350e8 lock NoLock|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.805#04:CarmineObjectLock.cs(106): CarmineObjectLock, Non Running Task b1f8526d-0a67-4813-8a76-3ae9735f8278 requested lock on VirtualHardDisk object with ID 62badfa7-9fdb-4302-90a5-24f27f7b3d40|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.821#14:WLCDBAccessHelper.cs(94): Reading object 62badfa7-9fdb-4302-90a5-24f27f7b3d40 of type VirtualHardDisk

[3788] 0ECC.0EF0::05/15-11:50:38.821#21:EventClientConnection.cs(239): Server session uuid:558d8ef6-0811-4f0d-9aab-8fa195f9f88b;id=4 - Sending 2 events

[3788] 0ECC.0C68::05/15-11:50:38.821#14:ImgLibOM.cs(66): VirtualHardDisk object test3_disk_1 instanciated with ID 62badfa7-9fdb-4302-90a5-24f27f7b3d40 lock NoLock|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

[3788] 0ECC.0C68::05/15-11:50:38.821#04:CarmineObjectLock.cs(106): CarmineObjectLock, Non Running Task b1f8526d-0a67-4813-8a76-3ae9735f8278 requested lock on VMHost object with ID 3f6a0784-712c-46d9-9e32-5a8ad96549a2|TaskID=B1F8526D-0A67-4813-8A76-3AE9735F8278

こんなログが気が遠くなるくらい延々と出力されます。

ログの採取を開始してから現象を再現させ、少し深呼吸します。

それから一気にそれらしいキーワードを探していくわけです。

具体的な事例については、また改めてブログに記載したいと思います。

まずはツールで色々と流れを見てみましょう。