[Closed] lockup during usb transfer, other bad usb behavior

[arQon]

An rsync between an internal HDD and an external USB3 one (both mounted as shared folders) caused one of my Ubuntu 16.04 VMs to lock up, after about 30s of transfer. Since I just updated to 5.2.14 I'm considering that the culprit right now, but it's entirely possible that the problem has been around for a while since I haven't done this particular operation in several months.

There's nothing particularly interesting in the log:

Code: Select all

00:00:11.228086 DSound: Guest source 'Line In' is using host recording device with GUID '{Default device}'
00:30:46.652027 VMMDev: vmmDevHeartbeatFlatlinedTimer: Guest seems to be unresponsive. Last heartbeat received 4 seconds ago
00:33:29.151014 Console: Machine state changed to 'Stopping'
00:33:29.151347 Console::powerDown(): A request to power off the VM has been issued (mMachineState=Stopping, InUninit=0)

The VM was using about 25% of the CPU (which makes sense, since it has 4 cores allocated to it, but I'm mentioning it to make it clear that neither the guest nor the host were straining), with pretty much all of it IOWait, as you'd expect.

After forcibly closing the guest, I restarted it with just two VCPUs just for the hell of it (host is a 4C/8T Xeon) and re-ran the rsync, which then succeeded (roughly 175GB). However, when shutting it down (cleanly, i.e. from the guest) afterwards, the shutdown, which usually takes a couple of seconds at most, was much much slower:

Code: Select all

26:20:24.553297 VMMDev: Guest Log: 07:55:50.970914 main     Ended.
26:20:24.553358 GUI: UISession::sltAdditionsChange: GA state change event came, notifying listeners.
26:20:24.553402 GUI: UISession::sltAdditionsChange: GA state change event came, notifying listeners.
26:21:54.309488 xHCI: USB Suspended
26:21:54.311355 TM: Switching TSC mode from 'RealTscOffset' to 'VirtTscEmulated'
26:21:54.312475 ACPI: Entering S5 power state (power down)
26:21:54.312514 Changing the VM state from 'RUNNING' to 'POWERING_OFF'

That 90s to shut down the USB is a little suspicious, and I suspect it may have reached a kill timeout rather than actually shutting down successfully, but either way it's not good.

I'm going to change the guest back to 4 cores and see if I can reproduce the lockup, and will revert to 5.2.8 and try that there as well if either the lockup or the slow shutdown happen again.

(note: this is similar to, but not the same as, viewtopic.php?f=3&t=87166 - that user was accessing the USB device by capturing it, rather than just mounting it).

[andyp73]

Judging by your post count you have been around these parts for a while and so you should know that snippets from log files aren't going to help anyone give you any useful advice. Please zip and post the whole of the log file.

Also, if you have read (m)any of the posts on the forum you will know what allocating all 4 physical cores of your host to the guest is a bad idea. You should always leave at least 1 for the host.

-Andy.

[arQon]

Yeah, I know - I deliberately didn't upload the whole log, because I didn't want anyone to spend their time wading through it unless I could get it to happen again. I'd rather save that assistance for after I've already explored as much as I can myself.

And yes, I'm also aware of the physical core allocation guideline. And while I'm certainly willing to believe that it has merit, a scenario where less than one of physical cores is actually in use is not one that I believe is going to trigger the - incredibly rare - cases where it causes problems. I could of course be wrong about that , and it might well be that heavy IO is exactly the case that DOES fail. (And if so, I'll consider that knowledge a win).

Annoyingly / happily, the second rsync (different data) has completed: only 6GB in about 16K files, but the one that locked up didn't even manage 1GB. I'll keep poking at it, and I'll shut the guest down in a second to check that part as well.

sidenote: the USB drive has been ejected from the host and reattached since the problem events.

edit> the shutdown was also back to its usual self: it took it ~3s, and although pretty much all of that was for the xHCI Suspend again it's a long way from 90.

[arQon]

Running the rsync again with the original dataset, I notice that there's actually NO iowait at all (from the guest's perspective).
I'm leaning slightly towards the host being at fault - but even so, the total lockup of the guest is too critical a failure to just hand-wave away like that.

Until I can reproduce it though (or someone else runs into it) I don't think there's anything to be gained here. I've kept the log from the session that locked up, in case anyone's feeling especially keen and thinks there might be something to be gleaned from it, but otherwise I don't want to burn anyone's time right now.