Ask CORE

Microsoft Japan Windows Technology Support

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

こんにちは。


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


 


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


いきたいと思います。


 


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


 


SCVMM Technet Home


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


 


 


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


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


 


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


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


 


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


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


 


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


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


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


 


How to collect SCVMM traces


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


 


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


 


DebugView for Windows v4.76


http://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: [http://MSCS.test.microsoft.com:80] Verb: [GET],  resource: [http://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


                              


                               


 


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

 


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


 


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


 


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


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