Weird phantom drive writes to USB external

[Makosuke]

I had an odd thing happen to an external hard drive last night and I'm wondering if there are any ideas as to what it might have been.

I've been ripping a bunch of my DVDs, going from an external DVD drive connected via USB to a hard drive in one of those toaster-style docks, also connected via USB (both directly connected to different ports on the Mac--no hubs).

It's run very smoothly through over 2TB of rips across two hard drives, including in the evenings when I turn off the DVD drive, unmount the hard drive, and power its dock off.

Last night, however, after I'd turned off the DVD drive, the external hard drive refused to unmount. What was REALLY weird, though, was that Activity Monitor was showing a constant level of about 32MB/s drive writes (zero drive reads, unless I did something), which I'm pretty sure was entirely to the external--it wasn't seeking, but the dock's access light was on steady, and the speed was around what you'd see maxing out the USB2 bus.

At first I thought it was Spotlight acting up trying to index the DVD images on the drive, but there were NO reads, and NOTHING in Activity Monitor was showing more than 2% CPU. I even killed mds to make sure, and it made no difference. When I tried to use Disk Utility to unmount it, Disk Utility froze, and subsequently refused to respond (I could, however, still access stuff on the external). I tried quitting everything open, which didn't change anything, and I even tried to find out what files were being accessed using What's Keeping Me and lsof, neither of which turned up ANYTHING I could find outside the boot drive. I didn't see anything unexpected in the console log, either.

Ok... time for a reboot. I logged out of my account, which I was a bit surprised DIDN'T hang, but the access light was STILL on steady from the login screen with no users logged in. I shut down, which was a little slow, but succeeded, at which point the external spun down as expected.

Does anybody have any idea what might have been going on there? Ever seen steady phantom drive writes like that?

 

[mulo]

sounds like the drive couldn't keep up, so it ripped to cache instead. so it was emptying the caches before unmount.

 

[Makosuke]

sounds like the drive couldn't keep up, so it ripped to cache instead. so it was emptying the caches before unmount.

Interesting theory, but I'm 99.9% certain this isn't what was happening.

MDRP (the ripping app) doesn't use any cache storage, it just writes directly to a .ripping file on the drive, which converts to an .iso when it's done; rips are only progressing at about 12MB/s, so there's no speed issue there with USB2; I haven't seen this happen in any of the previous 430 rips; there was no drive reads at all, from any drive, so it'd have to have been copying several GB of data from RAM, and there wasn't that much RAM in use (I only have 8GB total); the rip had been done for about 20 minutes anyway, so even if it were doing something like that it had time to copy several full DVDs at 32MB/s; the writes continued even after MDRP had been quit, and I had logged out; and I could find no files listed as open on the drive.

 

[Makosuke]

Follow-up: This just went from "weird glitch" to "what the hell is going on here?!"

I take back my previous post--apparently my 0.1% was the case, and it turns out you were right, mulo. But it makes NO sense to me.

I booted up the computer fresh and did nothing but mount the drives and do one rip. After it finished, the drive was again pinned at ~32MB/s writing, with NO access on the internal drive--reads = 0 bytes/s. I could mount and play the .iso file on the external smoothly, so it was confirmed to be ok. There were some drive reads during that period, and the writes dropped to compensate, confirming that the 32MB/s was the limit of the USB bus.

BUT... the entire 4.4GB disk image was unquestionably in RAM. I could tell, because when I tried to copy it to the internal drive, the copy proceeded happily at about 110MB/s, with NO disk reads registering at all (the external write continued, too). Confirmed that 110MB/s in both Activity Monitor and with my stopwatch. So not only could it not have been coming from the external--no way USB2 could keep up with a SATA internal--but it wasn't even copying from another file on the internal drive, since there was no read access and the write would have been about half that if it was reading at the same time. I tried copying a different ISO to the internal, which immediately started reading data from the external, and the copy only proceeded at about 30MB/s, as you'd expect limited by the USB2 bus. After a few more minutes, the silent writes to the external stopped, presumably when it had emptied that 4.4GB RAM cache onto the drive. The file apparently remained in RAM, because when I tried to copy it to the internal it was still fast and there were no disk reads. After ejecting and re-connecting the external, however, copying the same file behaves as expected--34MB/s reads and writes both, limited by the speed of USB2.

Now, this is baffling to me for two reasons.

One, Activity Monitor reported well under 4.4GB in the sum of Wired, Active, and Inactive memory (I have 8GB RAM, and about 6GB total was free). So while the file HAD to be in RAM, it was simply not showing as such in Activity Monitor as far as I could tell.

Two, when did the MacOS start transparently caching large writes to USB drives in RAM? I've NEVER seen that behavior before.

Also, why didn't I see this any of the previous twenty times over the last two weeks I unmounted the external in the same process? Every time, I'd unmount and turn off the drive the moment it was finished with the last disc, and there was never any kind of delay. I guess there wasn't enough free RAM, since the machine had been on for a while and Photoshop was running. I didn't think I'd quit PS, but if I had perhaps that was the trigger.

Just duplicated, to confirm. This time when the 4.2GB disc finished ripping there was no cache-dumping disk access, but copying the file to the internal still results in >100MB/s speeds with no reads. Yet the used ram is 2.84GzB, Free is 5.19GB, and the most Real Memory used by any process in the list is 323MB by kernel_task, followed by spotlight and Safari; nothing else uses more than 100MB.


Color me utterly confused. Someone with better knowledge of the OS's internals able to shed some light on this behavior for me?

 

[Makosuke]

Final follow up to this, just in case anybody runs across the same thread in the future:

I've pinned down the source of the writes, and it turns out it was not USB caching as I'd originally thought. The OS is, without question, quietly caching huge amounts of data in RAM--there's no way I could have gotten the read/write behavior I saw otherwise--but that wasn't the cause of the ongoing writes to disk I was seeing.

Rather, it turns out, it was Spotlight doing something weird, presumably from trying to index a bunch of .iso files. I saw this again, and poking around some realized that there was a HUGE file--nearly 40GB--being written to in the Spotlight index folder. Disabling Spotlight for that drive stopped the writes entirely and removed the huge file.

What was surprising to me was that mdworker or mds weren't running at the time, and there was no process showing much in the way of CPU activity, which isn't what I'm used to when Spotlight is hard at work. I saw at least one Spotlight indexer crash during the behavior (after which the huge file was deleted, re-created, and the writes resumed), and attempting to add the drive to Spotlight's privacy list failed with a nondescript error until the writes were finished, so it may well have been an indexing bug of some sort, or some sort of partially-crashed failed process. This also explains why I didn't see this happen on the entire first 2TB of DVD rips--I had disabled Spotlight indexing on that drive at the start, but forgotten to on the subsequent drive.