Personal vDisk (PVD) was shipped as part of XenDesktop 5.6 last March. In the months since then, we’ve presented PVD to both internal audiences as well as at Synergy last month in San Francisco. One of the topics that seems to come up frequently is troubleshooting and logging.

PVD keeps two kinds of logs – one for the PVD filesystem driver and one for the user mode service. The filesystem driver is the core part of PVD that performs the I/O interception and redirection, providing persistent personalization for XenDesktop VDI VMs. The user mode service performs the merging of base image updates into PVD disks as needed, and manages the PVD disk.

I’d like to take some time today to walk through the contents of one of the PVD log files, namely the PVD filesystem driver log. This log contains information that is useful when troubleshooting/diagnosing PVD VMs that won’t start, and also when diagnosing possible application compatibility issues. In the next installment, I’ll cover PVD’s user mode service log.

The PVD filesystem driver log is kept at the root of the PVD disk (by default, this will appear as P:\ in your pool VMs unless you changed the drive letter during catalog creation.) The log is named IvmSupervisor.log (Ivm being the name of the PVD filesystem driver).

Let’s start by looking at the log, one section at a time. For the sake of brevity, I’ve excluded logfile entries that aren’t relevant:

 

20120628 23:48:56.258 00000001 1 07 0 0 00 0004 0008: IvmLog initialization complete
20120628 23:48:56.258 00000002 1 07 0 0 00 0004 0008: Ivm REL built at Fri Nov  4 00:36:44 2011. (Note that is different from last modified time)
20120628 23:48:56.258 00000003 1 05 0 0 00 0004 0008: Registry filtering initialized

1. The section shown above is logged during the start of a new pool VM boot. Since PVD will continually append to this file (and rotate the contents after it reaches 10MB in size), you can quickly identify a VM boot by looking for the lines above. Another way to tell when a new boot occurred is to look at the third field in the log entry – the first log entry is indexed 00000001, the next 00000002, and so forth. These counters reset on each boot.

 

20120628 23:48:56.258 00000007 1 23 0 0 00 0004 0008: IvmNativeStart: started the thread to wait for the VHD and start the session
20120628 23:48:56.258 00000008 2 02 0 0 00 0004 0008: IvmStateChange: current driver state StateRunning, status 0x0
20120628 23:48:56.258 00000009 2 02 0 0 00 0004 0008: DriverEntry: driver load successful, status 0x0
20120628 23:48:56.273 0000000A 1 07 0 0 00 0004 00DC: Timer manager started with 32 timers
20120628 23:48:56.273 0000000B 1 02 0 0 00 0004 00E4: volume processing WI function started, waiting for boot driver to start...
20120628 23:48:56.476 0000000C 1 02 1 0 00 0004 0038: PNP notification for volume [\??\STORAGE#Volume#{80ce1f02-4150-11e0-9ce2-806e6f6e6963}#0000000000100000#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b}]
20120628 23:48:56.710 0000000D 1 02 1 0 00 0004 0038: PNP notification for volume [\??\STORAGE#Volume#{80ce1f02-4150-11e0-9ce2-806e6f6e6963}#0000000006500000#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b}]
20120628 23:48:56.710 0000000E 1 02 1 0 00 0004 0038: PNP notification for volume [\??\STORAGE#Volume#{7ebbc0e7-c1b6-11e1-b653-806e6f6e6963}#0000000000010000#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b}]
20120628 23:48:56.726 0000000F 1 02 1 0 00 0004 0038: PNP notification for volume [\??\STORAGE#Volume#{7ebbc0e8-c1b6-11e1-b653-806e6f6e6963}#0000000000100000#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b}]

2. The first thing PVD does when it starts is to try to locate its volume (this is created and attached to the VM and stores the user’s personalization data).To do this, PVD registers for notification for each volume in the system, so that it can examine each one to determine if it’s the right one (more on how this is done shortly…) In this particular system, there are four volumes.

 

20120628 23:48:57.911 00000012 1 02 0 0 00 0004 00E4: volume processing WI function now processing notifications...
20120628 23:48:57.911 00000013 1 02 0 0 00 0004 00E4: volume processing WI function dequeued volume [\??\STORAGE#Volume#{7ebbc0e8-c1b6-11e1-b653-806e6f6e6963}#0000000000100000#{53f5630d-b6bf-11d0-94f2-00a0c9
1efb8b}]
20120628 23:48:57.911 00000014 1 02 0 0 00 0004 00E4: volume processing WI function checking volume [\??\STORAGE#Volume#{7ebbc0e8-c1b6-11e1-b653-806e6f6e6963}#0000000000100000#{53f5630d-b6bf-11d0-94f2-00a0c9
1efb8b}]
20120628 23:48:57.989 00000016 1 03 1 0 00 0004 00E4: attached to volume [\Ntfs][\Device\HarddiskVolume4] on \\?\Volume{7ebbc0ee-c1b6-11e1-b653-806e6f6e6963}

3. Next, PVD inspects each volume, looking for a “PVD fingerprint” – namely, the presence of a special GUID file located at the root of the volume, and a VHD file called “UserData.vhd” – this is the VHD file that contains the user’s installed applications (but not their profile).

 

20120628 23:48:58.020 00000017 1 02 0 0 00 0004 00E4: previous PUD size was 10737418240
20120628 23:48:58.020 00000018 1 02 0 0 00 0004 00E4: drive letter from file is V
20120628 23:48:58.020 00000019 1 02 0 0 00 0004 00E4: PUDSplit from file is 5000
20120628 23:48:58.020 0000001A 1 02 0 0 00 0004 00E4: IvmBootpCheckAndStartIvm:found the recomposition guard file
20120628 23:48:58.020 0000001B 1 02 0 0 00 0004 00E4: our volume starts at offset 1048576 and is 10736369664 bytes long, on disk 2
20120628 23:48:58.036 0000001C 1 02 0 0 00 0004 00E4: saved new PUD size of 10737418240

4. If PVD finds a proper volume (eg, one that fits the above characteristics), it then checks to see if the file system on that volume needs to be resized. In this case, the “desired” size (10GB) matches the previous size (10GB), so no resize needs to occur. If a new size were to be desired (say, for example, the administrator had opened the hypervisor console and increased the disk size), PVD would instruct NTFS to resize the file systems in use (in the PVD disk as well as the application area VHD).

 

20120628 23:48:58.036 0000001D 1 02 0 0 00 0004 00E4: IvmBootpCheckAndStartIvm:try to mount the VHD
20120628 23:48:58.036 0000001E 1 02 0 1 01 0004 00E4: IvmBootpMountAndCheckVhdFile:mark that we found a VHD so we should wait longer...
20120628 23:48:58.067 00000020 1 02 0 0 00 0004 00E4: IvmBootpMountAndCheckVhdFile: VHD is mounted, check if it's a good one.
20120628 23:49:01.000 00000025 1 02 0 0 00 0004 00E4: IvmBootpCheckAndStartIvm: loaded reg hives, creating volume symlinks
20120628 23:49:01.000 00000026 1 02 0 0 00 0004 00E4: IvmBootpCheckAndStartIvm: setting the event to signal the session can be started

5. If the volume was successfully resized (or if no resize was desired), PVD will mount the application VHD and let the machine continue booting (remember, everything we’ve described so far is occurring very early in the Windows boot sequence – in the case of Windows 7, these operations are occurring just after the Windows logo starts its ‘pulse’ animation during boot.)

 

20120628 23:49:01.000 00000027 1 23 0 0 00 0004 00E8: IvmpNativeSessionCreationFunction: trying to start session...
20120628 23:49:01.000 00000028 1 06 1 0 00 0004 00E8: Starting NativeMode session
20120628 23:49:01.000 00000029 1 03 1 0 00 0004 00E8: Layer 0 -> Real volume {7ebbc0ef-c1b6-11e1-b653-806e6f6e6963} [\Device\HarddiskVolume2]
20120628 23:49:01.000 0000002A 1 03 1 0 00 0004 00E8: Layer 1 -> Real volume {7ebbc0f6-c1b6-11e1-b653-806e6f6e6963} [\Device\IvmVhdDisk00000001]
20120628 23:49:01.016 0000002B 1 23 0 0 00 0004 00E8: IvmpNativeSessionCreationFunction: started the session!
20120628 23:49:01.016 0000002C 1 07 0 0 00 0004 00E4: IvmLogSwitchToFile: relocating log to file \??\STORAGE#Volume#{7ebbc0e8-c1b6-11e1-b653-806e6f6e6963}#0000000000100000#{53f5630d-b6bf-11d0-94f2-00a0c91efb
8b}\IvmSupervisor.log, see you there!
20120628 23:49:01.016 0000002D 1 07 0 0 00 0004 00E4: IvmLogSwitchToFile: after switching the log file...
20120628 23:49:01.016 0000002E 1 02 0 0 00 0004 00E4: moved log file to PUD volume...
20120628 23:49:01.016 0000002F 1 02 0 0 00 0004 00E4: found the right volume, exit volume processing loop
20120628 23:49:01.016 00000030 1 02 0 0 00 0004 00E4: IvmBootpVolumeProcessingWIFunction: unregistering volume notification...

6. PVD then relocates its logs to the PVD disk – until we determined which one was the right one to use, the logs were being buffered in memory. The last bit of work that happens is for PVD to begin intercepting I/O requests as part of its normal operation. The way in which this occurs (represented above by the two layer indicators) is beyond the scope of this blog entry but you can learn more about it if you’re interested by watching the SYN119 video recording from last month’s Synergy (available on CitrixTV.)

If you look at the timestamps on the log entries, you’ll see that the total time to perform all the operations is slightly less than 5 seconds.

The above log walkthrough illustrates a successful, normal boot. In cases where errors occur, you’ll see appropriate error messages displayed. In early boot failures, the typical cause is a missing disk – PVD will wait for up to 30 seconds for all the volumes to ‘appear’ on the machine before it gives up and lets the boot proceed (albeit without PVD/personalization enabled). If you see two log entries that have a 30s jump between the time stamps, chances are good that your provisioner (MCS or PVS) failed to attach the volume properly and PVD timed out waiting for the disk to appear. That, or perhaps you have slow hardware. The 30s boot timeout can be configured either higher or lower in the base VM (see the SYN119 video for the location of this configuration parameter.)

Another error you might see in this log file would be an error when resizing the volume, but this is less frequently seen and usually attributed to misconfiguration.

After boot, this logfile is ideally silent. However, it is possible that under certain circumstances you might see some additional log entries after the VM has successfully booted PVD. These log entries are made by PVD when it encounters a registry key/value or file that it cannot operate on for some reason (corruption, improper ACLs, etc). We’ll usually see a few of these appear in the log when customers are having application compatibility issues, and these log entries usually help us track down where the issue might lie.

Next time, we’ll walk through the PVD user mode service log, which contains information about image update and difference application operations. See you then!