vSAN - VM Creation Workflow
Article ID: 326497
Updated On:
Products
Issue/Introduction
This article provides detailed information on the process of virtual machines creation for VM's residing on a VMware vSAN datastore. Although the examples given here describe the successful creation of a VM on a vSAN, there is also information included which may be useful for diagnosing failures in deployment of such virtual machines.
Environment
VMware vSAN
Resolution
Overview
-
Create Operation goes to the DOM_CLIENT.
-
DOM_CLIENT identifies the DOM_OWNER.
-
DOM_OWNER then sends the storage policy (SP) to the CLOM (DOM_OWNER doesn't process SP).
-
CLOM returns the configuration needed to be used for the SP of the virtual machine.
-
DOM_OWNER now knows where to create all the components to satisfy the SP of the virtual machine. It knows in which hosts and MDs to create the object's components.
-
DOM_OWNER sends the create tasks to each of the Component Managers of the hosts.
-
Component Managers then send the requests to the local LSOM of the host.
-
LSOM writes the data to the MDs.
-
MD stands for Magnetic Disk / Capacity drive.
-
DOM stands for Distributed Object Manager.
-
CLOM stands for Cluster-Level Object Manager
-
LSOM stands for Local Log-Structured Object Manager
The VM Creation Workflow
1. Open the vpxd.log file in the vCenter Server
1:43.094-07:00 [13072 info 'VmProv' opID=2408fce-ee] Setting the VM config path to ds:///vmfs/volumes/vsan:5257a7e0dd6f860e-bxxxxxxxxa/4028e354-2319-9031-af04-0xxxxxb/WorkFlowVM.vmx 2015-03-06T04:01:43.419-07:00 [13072 info 'Vpxd::Vm' opID=2408fce-ee] [VmMo::InitMinEVCKeyIfNecessary] Initializing min EVC key for VM WorkFlowVM [vim.VirtualMachine:vm-157] 2015-03-06T04:01:43.855-07:00 [13072 info 'vpxdvpxdVmomi' opID=2408fce-ee] [ClientAdapterBase::InvokeOnSoap] Invoke done (esxi1vsan.vcloud.local, vpxapi.VpxaService.createVm)--> This is Step 1 of the Creation Workflow.[...]2015-03-06T04:02:00.975-07:00 [13072 info 'commonvpxLro' opID=2408fce-ee] [VpxLRO] -- FINISH task-internal-36643 -- -- VmprovWorkflow --
You can see that the VM will be created on host esxi1vsan. This is the DOM_CLIENT.
Note: A very useful trick is to identify the opID (Operation ID) that relates to the task. You can easily track all the steps using the opID.In this example, the opID = 2408fce-ee.
2. Check vpxa.log of the DOM_CLIENT Host
3. Check hostd.log of the DOM_CLIENT Host
Note: These log messages come from the creation of a different virtual machine, WorkFlowVM2. The logs in the previous steps were for WorkFlowVM. The workflow is the same and shows the same messages, however.
4. Use CMMDS to Identify the Elements Related to the VM
/var/log/vmkernel.log file of the DOM_CLIENT. Use the less command and search for the string "DOM: ": less /var/log/vmkernel.logYou see entries like this:
2015-02-17T11:44:01.247582 [113321423] [cpu1] [4b7b218d csn=1 lsn=2 readPolicy] DOMTrace2PCProcessResponse:3555: {'desc-32': 0x505088c8, 'state': 'PREPARING', 'protocol': 'NO_COMMIT', 'listType': 'QueriesList', 'completed': False, 'ownerUuid': '4028e354-2319-9031-af04-0xxxxxxb', 'status': 'VMK_OK'}
cmmds utility for objects of type DOM_OBJECT:cmmds-tool find -t DOM_OBJECT --format json | lesscmmds-tool find -t HOSTNAME --format json | less
}
5. Trace the creation workflow in the CLOMD log
2015-02-17T11:38:40Z clomd[1000014566]: I120: CLOMFetchDOMEvent:Read an additional 248 bytes from DOM
2015-02-17T11:38:40Z clomd[1000014566]: I120: CLOMExpressionToPolicy:expression: (("stripeWidth" i1) ("proportionalCapacity" (i0 i100)) ("hostFailuresToTolerate" i1) ("spbmProfileId" "b7e59bef-f95f-4576-8ee1-0xxxxxxx3") ("spbmProfileGenerationNumber" l+0))
2015-02-17T11:38:40Z clomd[1000014566]: I120: CLOM_PostWorkItem:Posted a work item for 4028e354-2319-9031-af04-005056010e6b Type: PLACEMENT delay 0 (Success)
2015-02-17T11:38:40Z clomd[1000014566]: W110: Object size 273804165120 bytes with policy: (("stripeWidth" i1) ("proportionalCapacity" (i0 i100)) ("hostFailuresToTolerate" i1) ("spbmProfileId" "b7e59bef-f95f-4576-8ee1-06xxxxxx3") ("spbmProfileGenerationNumber" l+0))
2015-02-17T11:38:40Z clomd[1000014566]: W110: Object size 273804165120 bytes with policy: (("readOPS" (i0 i200)) ("stripeWidth" i1) ("capacity" (l0 l273804165120)) ("proportionalCapacity" (i0 i100)) ("hostFailuresToTolerate" i1) ("availability" i99999992) ("reliabilityExponent" i30) "reliabilityBase" i100) ("affinity" [ UUID_NULL UUID_NULL UUID_NULL UUID_NULL]))
2015-02-17T11:38:40Z clomd[1000014566]: I120: CLOMChooseFromEnumeration:Cost 547608330242 sane compliant 1
2015-02-17T11:38:40Z clomd[1000014566]: I120: CLOMMarshalConfiguration:Marshaling config for UUID 4028e354-2319-9031-af04-0xxxxxxxb
2015-02-17T11:38:40Z clomd[1000014566]: I120: CLOM_LogDomMessage:referent 4028e354-2319-9031-af04-0xxxxxxxb length 1312 object size: 273804165120 type: 2
2015-02-17T11:38:40Z clomd[1000014566]: I120: CLOM_LogDomMessage:expression ("Configuration" (("addressSpace" l273804165120) ("compositeUuid" 4028e354-2319-9031-af04-005056010e6b)) ("RAID_1" () ("Component" (("capacity" (l0 l273804165120)) ("addressSpace" l273804165120) ("faultDomainId" 54550ed6-79de-4420-d3b5-0xxxxxxxc)) UUID_NULL 526e9132-e3f0-97f6-b30a-axxxxxx3) ("Component" (("capacity" (l0 l273804165120)) ("addressSpace" l273804165120) ("faultDomainId" 545521a8-49ff-63f1-30d9-0xxxxxxe)) UUID_NULL 526cc8b1-6c03-2cd6-b64e-6xxxxxxx1)) ("Witness" (("isWitness" i1) ("faultDomainId" 54550cb9-cb59-c7bc-8ffd-0xxxxxxxb)) UUID_NULL 5268e5a8-51f0-dc1e-9901-fxxxxxxb))
6. Verify the Completion of the creation workflow on the DOM_OWNER
/var/log/vmkernel.log file.egrep command and search for the UUID of the DOM_OWNER:7. Investigate the LSOM operations with vsanTraceReader
vsanTraceReader command to read a vSAN trace file, and filter that output for the diskUuid. In this case, the diskUuid is 525cd69a-b083-660c-deb8-4568e3b1bcaa. Execute this command to read and filter the vSAN trace file:2014-12-15T18:20:07.099791 [65] [cpu1] [DISK] DOMTraceObjectSetState:2873: {'obj': 0x412ed052d640, 'objUuid': '525cd69a-b083-660c-deb8-4xxxxxxxxxa', 'curState': 'initialize', 'prevState': 'none'}
2014-12-15T18:20:07.099798 [66] [cpu1] [6e847a3a DISK] DOMTraceObjectInitObject:311: {'obj': 0x412ed052d640, 'objUuid': '525cd69a-b083-660c-deb8-4xxxxxxxxxa', 'status': 'VMK_OK'}
2014-12-15T18:20:07.099799 [67] [cpu1] [6e847a3a DISK] DOMTraceObjectInitRootObjectComplete:906: {'objUuid': '525cd69a-b083-660c-deb8-4xxxxxxxxxa', 'obj': 0x412ed052d640, 'status': 'VMK_OK'}
2014-12-15T18:20:07.099800 [68] [cpu1] [6e847a3a DISK ROOT_OBJ_FACTORY] DOMTraceRootObjFactoryInitObj:195: {'newObjUuid': '525cd69a-b083-660c-deb8-4xxxxxxxxxa', 'newAssoc': 0x0, 'newObj': 0x412ed052d640, 'returnStatus': 'VMK_OK', 'opStatus': 'VMK_OK'}
2014-12-15T18:20:07.099805 [69] [cpu1] [6e847a3a DISK ROOT_OBJ_FACTORY] DOMTraceRootObjFactoryDispatchCompleted:575: {'obj': 0x0, 'newObjUuid': '525cd69a-b083-660c-deb8-4xxxxxxxxxa', 'newAssoc': 0x0, 'status': 'VMK_OK', 'factoryOpState': 'CALL_CALLBACK', 'newObjType': 'DISK'}
2014-12-15T18:20:07.099821 [70] [cpu1] [6e847a39 DOM_EVENT] DOMTraceEventHandleDiskArrival:714: {'baseOp': 0x412ed021e280, 'diskType': 0, 'arrivalOpState': 'PUBLISH_DISK_HEALTH', 'errorCode': 'VMK_OK', 'diskUUID': '525cd69a-b083-660c-deb8-4xxxxxxxxxa'}
2014-12-15T18:20:07.099833 [71] [cpu1] [6e847a3b DOM_EVENT] DOMTraceEventHandleHealth:372: {'baseOp': 0x412ed021dec0, 'healthOpState': 'FIRST', 'errorCode': 'VMK_OK', 'uuid': '525cd69a-b083-660c-deb8-4xxxxxxxxxa', 'healthFlags': 0x0}
2014-12-15T18:20:07.422317 [94] [cpu1] [6e847a3b DOM_EVENT] DOMTraceEventHandleHealth:372: {'baseOp': 0x412ed021dec0, 'healthOpState': 'DONE', 'errorCode': 'VMK_OK', 'uuid': '525cd69a-b083-660c-deb8-4xxxxxxxxxa', 'healthFlags': 0x0}
2014-12-15T18:20:07.422342 [96] [cpu1] [6e847a39 DOM_EVENT] DOMTraceEventHandleDiskArrival:822: {'baseOp': 0x412ed021e280, 'diskType': 0, 'arrivalOpState': 'WAIT_FOR_DISK_STATUS', 'errorCode': 'VMK_OK', 'diskUUID': '525cd69a-b083-660c-deb8-4xxxxxxxxxa'}
2014-12-15T18:20:07.422349 [98] [cpu1] [6e847a39 DOM_EVENT] DOMTraceEventHandleDiskArrival:1948: {'baseOp': 0x412ed021e280, 'diskType': 0, 'arrivalOpState': 'WAIT_FOR_DISK_STATUS', 'errorCode': 'VMK_OK', 'diskUUID': '525cd69a-b083-660c-deb8-4xxxxxxxxxa'}
2014-12-15T18:20:07.547727 [110] [cpu1] [410b4ded09b0] CMMDSTraceInitUpdate:707: {'updateType': 'Add', 'type': 4, 'revision': 0, 'srcUUID': '54550cb9-cb59-c7bc-8ffd-005056010e6b', 'uuid': '525cd69a-b083-660c-deb8-4xxxxxxxxxa'}
2014-12-15T18:20:07.547736 [111] [cpu1] [6e847a39 DOM_EVENT] DOMTraceEventHandleDiskArrival:1948: {'baseOp': 0x412ed021e280, 'diskType': 0, 'arrivalOpState': 'WAIT_FOR_DISK_STATUS', 'errorCode': 'VMK_OK', 'diskUUID': '525cd69a-b083-660c-deb8-4xxxxxxxxxa'}
2014-12-15T18:20:07.647857 [113] [cpu1] [6e847a39 DOM_EVENT] DOMTraceEventHandleDiskArrival:1948: {'baseOp': 0x412ed021e280, 'diskType': 0, 'arrivalOpState': 'WAIT_FOR_DISK_STATUS', 'errorCode':
2014-12-15T18:20:08.365682 [127] [cpu0] [6e847a39 DOM_EVENT] DOMTraceEventHandleDiskArrival:1948: {'baseOp': 0x412ed021e280, 'diskType': 0, 'arrivalOpState': 'WAIT_FOR_DISK_STATUS', 'errorCode': 'VMK_OK', 'diskUUID': '525cd69a-b083-660c-deb8-4xxxxxxxxxa'}
2014-12-15T18:20:08.466445 [139] [cpu1] [6e847a39 DOM_EVENT] DOMTraceEventHandleDiskArrival:1649: {'baseOp': 0x412ed021e280, 'diskType': 0, 'arrivalOpState': 'INSTANTIATE_COMPONENTS', 'errorCode': 'VMK_OK', 'diskUUID': '525cd69a-b083-660c-deb8-4xxxxxxxxxa'}
2014-12-15T18:20:08.466582 [145] [cpu0] [6e847a39 COMP DOM_EVENT] DOMTraceEventHandleComponentArrival:3162: {'errorCode': 'VMK_OK', 'diskUUID': '525cd69a-b083-660c-deb8-4xxxxxxxxxa', 'compUUID': '18018b54-e0ef-c1dc-b196-0xxxxxxxxxxe'}
2014-12-15T18:20:08.466656 [168] [cpu0] [6e847a39 DOM_EVENT] DOMTraceEventHandleDiskArrival:2055: {'baseOp': 0x412ed021e280, 'diskType': 0, 'arrivalOpState': 'DONE', 'errorCode': 'VMK_OK', 'diskUUID': '525cd69a-b083-660c-deb8-4xxxxxxxxxa'}
8. Summary
This workflow covers all the steps involved when creating a VM on the vSAN Datastore.Feedback
