Intermittent error on VM start

R

RobertB22

Bit poster
I've been troubleshooting an intermittent slow startup of two separate Windows guests (Windows 7 and Windows Server 2012). Sometimes they start immediately. Other times they pause for several minutes saying "Resuming..." (with no % counter). I have disabled all folder sharing, app sharing, shut off the network and bluetooth, and it still happens intermittently, maybe 50% of the time. It happens both from a "Stopped" state and a "Paused" state.

I captured the logs for a "fast" startup and a "slow" startup, pasted below. The slow startup clearly shows an error message: "Can't get device type from vm's event". But I'm not sure how to interpret it or figure out what I can do to fix it. Can anyone suggest what I can try?

Here is a log (fragment) from a "slow" startup. (In this case a Resume from Pause). Note the error "Can't get device type from vm's event" right before the ParallelsEvent XML:
********************
12-28 21:45:46.682 F /disp:1174:2c8b/ Processing command 'DspCmdVmStart' 1001 (PJOC_VM_START)
12-28 21:45:46.710 F /disp:1174:2c8b/ Processing command 'DspCmdVmStart' 1001 for vm_uuid='{8573a04d-21e4-419d-948d-54faa4c828d5}'
12-28 21:45:46.750 F /disp:1174:2c8b/ Vm state was changed from VMS_SUSPENDED to VMS_RESUMING for vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7'), to powerState 0(vpsNormal)
12-28 21:45:46.775 F /disp:1174:2c8b/ Creating process name '/Applications/Parallels Desktop.app/Contents/MacOS//Parallels VM.app/Contents/MacOS/prl_vm_app' dir '/Applications/Parallels Desktop.app/Contents/MacOS/Parallels VM.app/Contents/MacOS' environment '' arguments '"\Applications\Parallels Desktop.app\Contents\MacOS\\Parallels VM.app\Contents\MacOS\prl_vm_app" --uuid {8573a04d-21e4-419d-948d-54faa4c828d5} --dir-uuid {2da84a45-594e-4490-bcf2-0365f6bd0337} --mode pdfm'
12-28 21:45:46.813 F /disp:1174:2c8b/ Processing command 'DspCmdVmGetSuspendedScreen' 1029 (PJOC_VM_GET_SUSPENDED_SCREEN)
12-28 21:45:46.852 F /disp:1174:2c8b/ Processing command 'DspCmdVmGetStatistics' 2079 (PJOC_VM_GET_STATISTICS)
12-28 21:45:47.032 F /disp:1174:2c8b/ Processing command 'DspCmdVmStorageSetValue' 2131 (PJOC_VM_STORE_VALUE_BY_KEY)
12-28 21:45:47.032 F /disp:1174:2c8b/ k=252a, vm={8573a04d-21e4-419d-948d-54faa4c828d5}
12-28 21:45:47.070 F /vm:1338:307/ [CMacApp::CMacApp]
12-28 21:45:47.073 F /vm:1338:5903/ *****************************************************************
12-28 21:45:47.073 F /vm:1338:5903/ started "/Applications/Parallels Desktop.app/Contents/MacOS//Parallels VM.app/Contents/MacOS/prl_vm_app --uuid {8573a04d-21e4-419d-948d-54faa4c828d5} --dir-uuid {2da84a45-594e-4490-bcf2-0365f6bd0337} --mode pdfm"
12-28 21:45:47.073 F /vm:1338:5903/ *****************************************************************
12-28 21:45:47.074 F /cmn_utils:1338:5903/ ParallelsDirs::Init( ) was called. Current app mode = 1 ( DESKTOP_MAC ) initOpts = 0 build version: 10.4.0 (29337) rev 0 Wed, 06 Apr 2016 07:27:26
12-28 21:45:47.074 F /vm:1338:5903/ Parallels Virtual Machine Constructed
12-28 21:45:47.075 F /BattWatcher:1338:6e0b/ BattWatcher: using notifications
12-28 21:45:47.078 F /IOCommunication:1338:6f0b/ TCP_NODELAY setting failed
12-28 21:45:47.078 F /IOCommunication:1174:11df/ TCP_NODELAY setting failed
12-28 21:45:47.084 W /disp:1174:11df/ handleClientConnected
12-28 21:45:47.087 F /vm:1338:5903/ SARE state(unknown): initialized to SareStateStart
12-28 21:45:47.087 F /vm:1338:5903/ VM state(unknown): initialized to VmStateNone
12-28 21:45:47.161 F /vm:1338:5903/ VM state(VmStateNone): enqueued 'VmLocalCmdStart'(20001) command
12-28 21:45:47.333 F /disp:1174:11df/ Recieved event PET_DSP_EVT_VM_DEV_STATE_CHANGED (100003) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:45:47.334 F /disp:1174:11df/ Can't get device type from vm's event! (<ParallelsEvent id="-1" dyn_lists="">
<EventType>100003</EventType>
<EventLevel>0</EventLevel>
<EventCode>100000</EventCode>
<EventNeedResponse>0</EventNeedResponse>
<EventIssuerType>0</EventIssuerType>
<EventIssuerId>{8573a04d-21e4-419d-948d-54faa4c828d5}</EventIssuerId>
<EventSource></EventSource>
<EventInitialRequestId>{c255206e-428d-4b5f-bee6-ba7b2db98293}</EventInitialRequestId>
<EventParameters dyn_lists="EventParameter 1">
<EventParameter id="0" dyn_lists="">
<Name>op_rc</Name>
<Type>0</Type>
<Value>0</Value>
</EventParameter>
</EventParameters>
<EventId>0</EventId>
</ParallelsEvent>
)
12-28 21:45:47.335 F /disp:1174:11df/ Recieved event PET_DSP_EVT_VM_RESUMING (100013) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:46:00.964 F /disp:1174:11df/ Recieved event PET_DSP_EVT_VM_ABOUT_TO_START_INIT (100040) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:46:01.162 F /disp:1174:11df/ Recieved event PET_DSP_EVT_VM_DEV_STATE_CHANGED (100003) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:46:10.985 F /disp:1174:11df/ Recieved event PET_VM_EVT_TIS_BACKUP_WRITE (101600) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
(...and then the VM sits here for a few minutes, seemingly doing nothing, but eventually starts...)
********************

And here is a log (fragment, same section) for a "fast" startup. Note it has the event "Recieved event PET_DSP_EVT_VM_ABOUT_TO_START_INIT" that was not present in the "slow" log above.
********************
12-28 21:42:56.318 F /disp:1174:2c8b/ Processing command 'DspCmdVmStart' 1001 (PJOC_VM_START)
12-28 21:42:56.339 F /disp:1174:2c8b/ Processing command 'DspCmdVmStart' 1001 for vm_uuid='{8573a04d-21e4-419d-948d-54faa4c828d5}'
12-28 21:42:56.380 F /disp:1174:2c8b/ Vm state was changed from VMS_STOPPED to VMS_STARTING for vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7'), to powerState 0(vpsNormal)
12-28 21:42:56.383 F /BCToolHelper:1174:2c8b/ BootCamp volume '/Volumes/Untitled' not found
12-28 21:42:56.383 F /BCToolHelper:1174:2c8b/ BootCamp volume '/Volumes/BOOTCAMP' not found
12-28 21:42:56.402 F /disp:1174:2c8b/ Creating process name '/Applications/Parallels Desktop.app/Contents/MacOS//Parallels VM.app/Contents/MacOS/prl_vm_app' dir '/Applications/Parallels Desktop.app/Contents/MacOS/Parallels VM.app/Contents/MacOS' environment '' arguments '"\Applications\Parallels Desktop.app\Contents\MacOS\\Parallels VM.app\Contents\MacOS\prl_vm_app" --uuid {8573a04d-21e4-419d-948d-54faa4c828d5} --dir-uuid {2da84a45-594e-4490-bcf2-0365f6bd0337} --mode pdfm'
12-28 21:42:56.431 F /disp:1174:2c8b/ Processing command 'DspCmdGetVmToolsInfo' 2100 (PJOC_VM_GET_TOOLS_STATE)
12-28 21:42:56.434 F /disp:1174:2c8b/ Processing command 'DspCmdVmGetStatistics' 2079 (PJOC_VM_GET_STATISTICS)
12-28 21:42:56.601 F /vm:1294:307/ [CMacApp::CMacApp]
12-28 21:42:56.605 F /vm:1294:5703/ *****************************************************************
12-28 21:42:56.605 F /vm:1294:5703/ started "/Applications/Parallels Desktop.app/Contents/MacOS//Parallels VM.app/Contents/MacOS/prl_vm_app --uuid {8573a04d-21e4-419d-948d-54faa4c828d5} --dir-uuid {2da84a45-594e-4490-bcf2-0365f6bd0337} --mode pdfm"
12-28 21:42:56.605 F /vm:1294:5703/ *****************************************************************
12-28 21:42:56.612 F /cmn_utils:1294:5703/ ParallelsDirs::Init( ) was called. Current app mode = 1 ( DESKTOP_MAC ) initOpts = 0 build version: 10.4.0 (29337) rev 0 Wed, 06 Apr 2016 07:27:26
12-28 21:42:56.612 F /vm:1294:5703/ Parallels Virtual Machine Constructed
12-28 21:42:56.616 F /BattWatcher:1294:7507/ BattWatcher: using notifications
12-28 21:42:56.632 F /IOCommunication:1294:7703/ TCP_NODELAY setting failed
12-28 21:42:56.633 F /IOCommunication:1174:11e0f/ TCP_NODELAY setting failed
12-28 21:42:56.642 W /disp:1174:11e0f/ handleClientConnected
12-28 21:42:56.726 F /vm:1294:5703/ SARE state(unknown): initialized to SareStateStart
12-28 21:42:56.727 F /vm:1294:5703/ VM state(unknown): initialized to VmStateNone
12-28 21:42:56.735 F /vm:1294:5703/ VM state(VmStateNone): enqueued 'VmLocalCmdStart'(20001) command
12-28 21:42:57.184 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_ABOUT_TO_START_INIT (100040) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.403 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_DEV_STATE_CHANGED (100003) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.569 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_TOOLS_STATE_CHANGED (100800) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.569 F /disp:1174:11e0f/ VM tools changed state on 0 00000000
12-28 21:42:57.640 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_STARTED (100007) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.670 F /disp:1174:11e0f/ Vm state was changed from VMS_STARTING to VMS_RUNNING for vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7'), to powerState 0(vpsNormal)
12-28 21:42:57.671 F /disp:1174:11e0f/ Received response PRL_ERR_SUCCESS (0) for DspCmdVmStart(1001) request from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.672 F /disp:1174:11e0f/ Response package was successfully routed to client
12-28 21:42:57.674 F /disp:1174:2c8b/ Processing command 'DspCmdVmInitiateDevStateNotifications' 1024 (PJOC_VM_INITIATE_DEV_STATE_NOTIFICATIONS)
12-28 21:42:57.674 F /disp:1174:2c8b/ Processing command 'DspCmdVmInitiateDevStateNotifications' 1024 for vm_uuid='{8573a04d-21e4-419d-948d-54faa4c828d5}'
12-28 21:42:57.676 F /IOCommunication:1174:12713/ TCP_NODELAY setting failed
12-28 21:42:57.679 F /disp:1174:2c8b/ Processing command 'DspCmdGetVmToolsInfo' 2100 (PJOC_VM_GET_TOOLS_STATE)
12-28 21:42:57.683 F /disp:1174:2c8b/ Processing command 'DspCmdVmStorageSetValue' 2131 (PJOC_VM_STORE_VALUE_BY_KEY)
12-28 21:42:57.683 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_DEV_STATE_CHANGED (100003) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.684 F /disp:1174:2c8b/ k=2b44, vm={8573a04d-21e4-419d-948d-54faa4c828d5}
12-28 21:42:57.684 W /disp:1174:12713/ handleClientConnected
12-28 21:42:57.687 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_DEV_STATE_CHANGED (100003) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.689 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_DEV_STATE_CHANGED (100003) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.691 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_DEV_STATE_CHANGED (100003) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.693 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_DEV_STATE_CHANGED (100003) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.695 F /disp:1174:11e0f/ Received response PRL_ERR_SUCCESS (0) for DspCmdVmInitiateDevStateNotifications(1024) request from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.696 F /disp:1174:11e0f/ Response package was successfully routed to client
12-28 21:42:57.698 W /disp:1174:12713/ handleClientDisconnected
12-28 21:42:57.705 F /disp:1174:2c8b/ Processing command 'DspCmdVmGetStatistics' 2079 (PJOC_VM_GET_STATISTICS)
12-28 21:42:57.716 F /disp:1174:11e0f/ Recieved event PET_VM_READY_TO_BOOT (101200) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.746 F /disp:1174:2c8b/ Processing command 'DspCmdVmSubscribeToGuestStatistics' 2086 (PJOC_VM_SUBSCRIBE_TO_GUEST_STATISTICS)
12-28 21:42:57.748 F /disp:1174:2c8b/ Processing command 'DspCmdPerfomanceStatistics' 2107 (PJOC_UNKNOWN)
12-28 21:42:57.833 F /disp:1174:11e0f/ Recieved event PET_DSP_COHERENCE_FAKE_STUB_NOTIFICATION (101401) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.834 F /disp:1174:1260f/ Task '27Task_ParentalControlAddStub' with uuid = {2f4bbb86-e8f7-4f04-b849-8b01cee096a6} was started. Flags = 0
12-28 21:42:57.834 F /disp:1174:1260f/ Task '27Task_ParentalControlAddStub' with uuid = {2f4bbb86-e8f7-4f04-b849-8b01cee096a6} was finished with result PRL_ERR_SUCCESS (0) )
12-28 21:42:57.834 F /disp:1174:11e0f/ Recieved event PET_DSP_COHERENCE_FAKE_STUB_NOTIFICATION (101401) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
12-28 21:42:57.835 F /disp:1174:12613/ Task '27Task_ParentalControlAddStub' with uuid = {a198b31c-94d1-4b75-8b80-43b1524f6f26} was started. Flags = 0
12-28 21:42:57.835 F /disp:1174:12613/ Task '27Task_ParentalControlAddStub' with uuid = {a198b31c-94d1-4b75-8b80-43b1524f6f26} was finished with result PRL_ERR_SUCCESS (0) )
12-28 21:42:57.935 F /cmn_utils:1296:307/ ParallelsDirs::Init( ) was called. Current app mode = 1 ( DESKTOP_MAC ) initOpts = 0 build version: 10.4.0 (29337) rev 0 Wed, 06 Apr 2016 07:27:26
12-28 21:42:57.935 F /cmn_utils:1297:307/ ParallelsDirs::Init( ) was called. Current app mode = 1 ( DESKTOP_MAC ) initOpts = 0 build version: 10.4.0 (29337) rev 0 Wed, 06 Apr 2016 07:27:26
12-28 21:42:57.945 W /cmn_utils:1297:307/ SBA mode rejected, no vm app was found (/Users/Robert/Documents/Parallels/Windows 7.pvm/Windows 7.app)
12-28 21:42:57.945 W /cmn_utils:1296:307/ SBA mode rejected, no vm app was found (/Users/Robert/Documents/Parallels/Windows 7.pvm/Windows 7.app)
12-28 21:42:58.927 F /disp:1174:11e0f/ Recieved event PET_DSP_EVT_VM_DEV_STATE_CHANGED (100003) from vm {8573a04d-21e4-419d-948d-54faa4c828d5} (name='Windows 7')
********************
 
Hi,

One of the logs looks to be attributed to the VM resume, and the other to the conventional start. One may observe PET_DSP_EVT_VM_RESUMING event is present in the first log only. For PD 10, the "Can't get device type from vm's event" message on resume or restore from snapshot seems to be expected.

Please note, that there is a known issue with Avira blocking VM bootstrapping. The workaround is described in http://kb.parallels.com/en/124336

If it is not the case, I believe, that it would be necessary to generate and send a Problem Report (as per http://kb.parallels.com/en/9058) and post its ID in this thread, since the culprit is more likely to be found in a different log, which resides in the VM bundle.
 
Hey Arno,
Adding the Parallels VM folder to the Avira exclusion list seems to have fixed the problem. I tested a number of times both resuming from suspend and fresh startups of the guest OS and it was fast every time.
Thanks very much for the quick response!
RBL
 
You must log in or register to reply here.
Back
Top