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
・
・
こんなログが気が遠くなるくらい延々と出力されます。
ログの採取を開始してから現象を再現させ、少し深呼吸します。
それから一気にそれらしいキーワードを探していくわけです。
具体的な事例については、また改めてブログに記載したいと思います。
まずはツールで色々と流れを見てみましょう。