Intermittent error on VM start

Discussion in 'Windows Virtual Machine' started by RobertB22, Dec 28, 2017.

  1. RobertB22

    RobertB22 Bit poster

    Messages:
    2
    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')
    ********************
     
    RobertB22, Dec 28, 2017
    #1
  2. Arno1

    Arno1 Parallels Developers

    Messages:
    23
    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.
     
    Arno1, Dec 29, 2017
    #2
  3. RobertB22

    RobertB22 Bit poster

    Messages:
    2
    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
     
    RobertB22, Dec 29, 2017
    #3

Share This Page