Apple Event: May 7th at 7 am PT

Looks like no one’s replied in a while. To start the conversation again, simply ask a new question.

Level 1

98 points

Two Time Machine Mysteries

Yesterday, after a successful Time Machine backup I noticed there were two temporary folders on my Desktop, which I should have deleted BEFORE the backup. Hence I entered Time Machine. First I clicked on the second folder in list view to select it, then on the first one (which deselected the other one) so that only the first folder was selected, right clicked on it and deleted that backup. Unfortunately, after a while, BOTH ( ! ) folders had disappeared! I'm 100% sure that just ONE ( ! ) was selected.

I closed TM. Opened it again (I thought refreshing the view would make the one folder (which I didn't select & delete) visible again, but it really was gone.

A few minutes later, because I had modified a small, but important file, I ran Time Machine backup again and noticed a strange behaviour:

First it said , backing up 100MB of 500MB, then just before reaching the 500MB it said backing up 450MB of 800MB, then before reaching the 800MB it said backing up 750MB of 1.2GB and so on (the target backup size got permanently corrected) until 15GB ( ! ) were copied.

I hope someone can explain these two strange incidents, because otherwise I would question the reliability of my backups.

Many thanks.

iMac (27-inch Mid 2010), OS X Mountain Lion (10.8.2)

Posted on May 1, 2013 12:24 AM

Best reply

Linc Davis

Level 10

209,547 points

Posted on May 1, 2013 7:29 AM

First, start a second backup on another external drive. One backup is not enough to be safe.

Then repair the backup volume in Disk Utility. If any problems are found, repeat. If there's ever another problem with the drive, replace it.

View in context

34 replies

Pondini

Level 8

38,863 points

May 5, 2013 9:44 AM in response to coxorange

coxorange wrote:

One thing I forgot - just to be absolutely sure:

> "Delete All Backups of..."

This refers solely to previous backups of the selected file or folder, right?

Correct.

coxorange Author

Level 1

98 points

May 5, 2013 9:47 AM in response to Pondini

Thanks again.

coxorange Author

Level 1

98 points

May 10, 2013 12:12 AM in response to coxorange

As initially suggested, I'm using a new backup drive since May 3. Now it happened again, that a backup of which I thought it would take about 5 or 10 minutes, took 2 hours. Is something wrong here? Please can somepone check the log:

03:08:39 - Starting manual backup

03:08:57 - Backing up to: /Volumes/MyBook/Backups.backupdb

03:09:08 - Using file event preflight for Macintosh HD

03:11:33 - Will copy (933.2 MB) from Macintosh HD

03:11:34 - Found 1712 files (968.6 MB) needing backup

03:11:34 - 2.15 GB required (including padding), 537.38 GB available

04:09:11 - Copied 470.9 MB of 968.6 MB, 8482 of 8482 items

05:01:53 - Copied 19212 files (790.4 MB) from volume Macintosh HD.

05:01:55 - Using file event preflight for Macintosh HD

05:01:56 - Will copy (83.2 MB) from Macintosh HD

05:01:56 - Found 29 files (83.2 MB) needing backup

05:01:56 - 1.09 GB required (including padding), 536.75 GB available

05:03:55 - Copied 1980 files (83.2 MB) from volume Macintosh HD.

05:04:00 - Created new backup: 2013-05-10-050356

05:04:06 - Starting post-backup thinning

05:04:06 - No post-back up thinning needed: no expired backups exist

05:04:07 - Backup completed successfully.

Thanks.

Pondini

Level 8

38,863 points

May 10, 2013 8:16 AM in response to coxorange

Yes, very slow in both "copying" phases, although the "preparing" phase did take 2 minutes, without a "deep scan," which sounds a bit slow, too.

Western Digital uses the "MyBook" name for a bunch of different drives. What is yours, and is it newly purchased, or one you've had for a while and is just recently being used for your backups?

Was anything else going on at the time? You might want to look at the logs, and see if there are other messages (besides the ones from backupd above) that might indicate any sort of problems.

Is your Mac normally pretty responsive?

You might want to try the things in the green box of #D2 in Time Machine - Troubleshooting.

coxorange Author

Level 1

98 points

May 10, 2013 12:50 PM in response to Pondini

Thanks for your help!

Pondini wrote:

What is yours, and is it newly purchased, or one you've had for a while and is just recently being used for your backups?

It's a WD 2x1TB MyBook Mirror Edition (USB2) which I'm using with RAID 1 configuration. I have two of these drives, both bought about 1 year ago, but nearly unused. About a week ago I started using it (again) - freshly formatted, The TM backups were all fast and there was no problem. I don't think there's a problem with the drive. I had other MyBooks for other Macs (FireWire) for many years and never had a problem.

Pondini wrote:

Was anything else going on at the time? You might want to look at the logs, and see if there are other messages (besides the ones from backupd above) that might indicate any sort of problems.

Is your Mac normally pretty responsive?

1. One app (Acorn) crashed when I tried to export a large file about 2 hours befor the backup started..

2. I disconnected two external USB cameras an hour before the backup started. Unfortunately USB cameras can't be safely "ejected" - you can only pull the plug - could this be a problem...?

3. I noticed that Spotlight started to rebuild its index (expected duration: 5 days) I restarted my Mac and the index was ready in about 20 minutes.

Yes, normally my Mac is pretty responsive.

Because I don't have enough time this evening to read your Troubleshooting documentation, but I need to backup tonight, I decided to use my other MyBook (mentioned above) for making a new complete TM backup. I will see if it works.

BTW Which other logs would you recommend to check?

Thanks again.

Pondini

Level 8

38,863 points

May 10, 2013 1:12 PM in response to coxorange

coxorange wrote:

. . .

It's a WD 2x1TB MyBook Mirror Edition (USB2) which I'm using with RAID 1 configuration.

I don't have any direct experience with RAID drives on a Mac, but I'm far from sure that's a good idea. Most RAID setups are for data that must be available at all times, not backups. If there's a problem with one drive, it will keep working, but writing to it may be much slower while the mirrored drive is being re-synced or even rebuilt entirely.

For redundant backups (always a good idea), it's better to use two separate drives, and even better to use two different backup apps. See Time Machine - Frequently Asked Question #27 for some suggestions.

I don't think there's a problem with the drive. I had other MyBooks for other Macs (FireWire) for many years and never had a problem.

There can be problems that aren't apparent -- again, the whole idea is for it to keep running. If there's a problem with one of the drives, or even the controller, there may be little or no outside indication of that.

1. One app (Acorn) crashed when I tried to export a large file about 2 hours befor the backup started..

2. I disconnected two external USB cameras an hour before the backup started. Unfortunately USB cameras can't be safely "ejected" - you can only pull the plug - could this be a problem...?

Doubtful.

3. I noticed that Spotlight started to rebuild its index (expected duration: 5 days) I restarted my Mac and the index was ready in about 20 minutes.

Yes, that could be the problem if the backup was running at the same time. TM backups are supposed to be relatively low-priority, so as not to disrupt your system; usually there's no significant difference, but if Spotlight is indexing your internal HD, that can make backups slow to a crawl. See the first item in the yellow box of #D2 in the Time Machine - Troubleshooting link.

BTW Which other logs would you recommend to check?

I'm not sure how you got the log you posted, but those are the messages sent by the backupd process to your system.log.

Probably the best thing to do is locate your system.log and open it via the Console app, per the tan box in OSX Log Files. Then see the blue box on that same page to decipher it.

You can "filter" for a character string (such as backupd) via the box in the toolbar, but for this purpose your best bet will be to navigate to the date & time of the backup and see what other messages might be there at the same time the backup was running. Look for anything that sounds dire, such as failed, exited with code, exited abnormally, I/O error, or especially anything that might be coming from the RAID box (I don't know what those will look like).

Messages relating to Spotlight indexing will come from the mds, mdworker, or mdhelper processes.

coxorange Author

Level 1

98 points

May 10, 2013 4:36 PM in response to Pondini

Pondini wrote:

If there's a problem with one of the drives, or even the controller, there may be little or no outside indication of that.

If there's a problem with one of the drives (of couse this could happen) or the controller (*very* rare), the drive would inform th euser with highly visible LED signals. (For OS X such a drive looks like a normal drive, not a RAID 1 drive - the drive itsself manages to backup everything two times to the two included drives.)

Pondini wrote:

3. I noticed that Spotlight started to rebuild its index (expected duration: 5 days) I restarted my Mac and the index was ready in about 20 minutes.

Yes, that could be the problem if the backup was running at the same time. TM backups are supposed to be relatively low-priority, so as not to disrupt your system; usually there's no significant difference, but if Spotlight is indexing your internal HD, that can make backups slow to a crawl. See the first item in the yellow box of #D2 in the Time Machine - Troubleshooting link.

Do you have an idea what could cause Spotlight to re-index the internal HD?

(I've checked system.log, but couldn't find errors during the TM backup time period.)

Pondini

Level 8

38,863 points

May 10, 2013 4:56 PM in response to coxorange

coxorange wrote:

Pondini wrote:

If there's a problem with one of the drives, or even the controller, there may be little or no outside indication of that.

If there's a problem with one of the drives (of couse this could happen) or the controller (*very* rare), the drive would inform th euser with highly visible LED signals. (For OS X such a drive looks like a normal drive, not a RAID 1 drive - the drive itsself manages to backup everything two times to the two included drives.)

Yes, I understand that. What I mean is, even on a "normal" (ie, non-RAID) drive, if there's a problem the controller can handle, such as needing an occasional retry, that's not usually reported. I don't know how many retries drives will do these days without reporting a problem (on some of the IBM equipment I worked with a few decades ago, it was 10). If a drive starts to need frequent retries, but not enough to trigger a message, it can slow things down fairly significantly, and that can go on for quite a while before it finally reports a failure.

Do you have an idea what could cause Spotlight to re-index the internal HD?

(I've checked system.log, but couldn't find errors during the TM backup time period.)

Other than telling Spotlight not to index it, then reversing that, via System Prefs > Spotlight > Privacy; or using the mdutilUNIX command, as far as I know anything else should result in some sort of message. It might have been sent before the backup started, though. And if a drive is near-full, sometimes indexing will be delayed until space is available. That's pretty rare, too.

Are you sure it was indexing your internal HD? That's what usually happens, but often it's hard to tell which drive is being indexed. It's possible it was the TM drive, and you can't exclude TM backups from indexing to narrow down such a problem (you can exclude the drive/partition, and that will exclude anything else, but the actual backups will still be indexed). But again, there really should have been a message.

coxorange Author

Level 1

98 points

May 11, 2013 2:05 AM in response to Pondini

Thanks for your reply!

Pondini wrote:

Are you sure it was indexing your internal HD?

There was only the internal drive and the TM drive.

As mentioned above, I have now used my other MyBook drive which was completely empty.

I got the following log (I'm using a small app called "LogViewer for Time Machine" to get this information extracted):

03:27:48 - Starting manual backup

03:36:18 - User continued after being warned of changed destination volume identity

03:36:18 - Backing up to: /Volumes/MyBook/Backups.backupdb

03:36:18 - Ownership is disabled on the backup destination volume. Enabling.

03:36:20 - Forcing deep traversal on source: "Macintosh HD" (mount: '/' fsUUID: 4E6B5B79-D92B-3CB7-8FFA-271C457FD2A9 eventDBUUID: 405D7145-8C49-4A52-AC5A-C42F309878A0)

03:36:44 - Backup content size: 528.08 GB excluded items size: 49.22 GB for volume Macintosh HD

03:36:44 - Found 1342535 files (478.85 GB) needing backup

03:36:44 - 574.63 GB required (including padding), 999.19 GB available

03:36:44 - Waiting for index to be ready (100)

04:36:21 - Copied 88.14 GB of 478.85 GB, 668965 of 1342535 items

05:36:21 - Copied 154.06 GB of 478.85 GB, 1109407 of 1342535 items

06:36:21 - Copied 246.32 GB of 478.85 GB, 1204045 of 1342535 items

07:36:22 - Copied 350.19 GB of 478.85 GB, 1213095 of 1342535 items

08:36:23 - Copied 450.94 GB of 478.85 GB, 1240802 of 1342535 items

08:49:37 - Copied 1275231 files (468.53 GB) from volume Macintosh HD.

08:49:38 - Using file event preflight for Macintosh HD

08:49:38 - Will copy (806 KB) from Macintosh HD

08:49:38 - Found 25 files (806 KB) needing backup

08:49:38 - 1.09 GB required (including padding), 537.26 GB available

08:49:57 - Copied 1722 files (806 KB) from volume Macintosh HD.

08:49:57 - Created new backup: 2013-05-11-084957

08:49:58 - Copying OS X Recovery set

08:50:27 - Starting post-backup thinning

08:50:27 - No post-back up thinning needed: no expired backups exist

08:50:27 - Backup completed successfully.

Does this log look acceptable?

(Again, an index was created (03:36:44-04:36:21) - which one...?)

Pondini

Level 8

38,863 points

May 11, 2013 7:21 AM in response to coxorange

coxorange wrote:

. . .

I got the following log (I'm using a small app called "LogViewer for Time Machine"

I'm not familiar with that; looks like it's similar to the Time Machine Buddy widget, per #A1 in Time Machine - Troubleshooting. If so, it just extracts the messages sent by the backupd process.

Does this log look acceptable?

Yes, completely normal for a backup to an empty drive. The whole thing ran in about 5 1/2 hours, including setup, deep scan, copying the Recovery HD, etc., which works out to about 85 GB per hour. That's actually quite fast for USB2.

(Again, an index was created (03:36:44-04:36:21) - which one...?)

That's the index on the backup drive (it was actually created when the drive was formatted or erased). That message was sent when TM was making sure it was up-to-date, so took only a moment; the "Copied" messages following that are sent hourly while it's copying, so at 4:36:21 TM had already backed-up 88 GB.

As you do subsequent backups, you may see one (or a few) of those at the beginning of a backup, or sometimes before the second "pass." If you see a lot of them, that may indicate a problem.

coxorange Author

Level 1

98 points

May 11, 2013 4:45 PM in response to Pondini

Thanks again, the second backup was also successful and fast. Everything's normal again.

coxorange Author

Level 1

98 points

Jul 3, 2013 5:32 PM in response to Pondini

Today Finder became unresponsive and I had to relauch Finder.

The following TM backup took plenty of time and I got the following log:

11:37:15 - Starting manual backup

11:38:16 - Backing up to: /Volumes/MyBook/Backups.backupdb

11:45:28 - Using file event preflight for Macintosh HD

11:58:13 - Will copy (1.27 GB) from Macintosh HD

11:58:14 - Found 2409 files (1.34 GB) needing backup

11:58:24 - 3.18 GB required (including padding), 482.61 GB available

13:20:06 - Copied 287 MB of 1.34 GB, 2089 of 2409 items

14:20:18 - Copied 528.7 MB of 1.34 GB, 19155 of 19155 items

15:02:46 - Copied 20998 files (1.2 GB) from volume Macintosh HD.

15:02:48 - Using file event preflight for Macintosh HD

15:02:48 - Will copy (7 bytes) from Macintosh HD

15:02:48 - Found 29 files (7 bytes) needing backup

15:02:48 - 1.57 GB required (including padding), 481.54 GB available

15:03:17 - Copied 949 files (220 bytes) from volume Macintosh HD.

15:03:27 - Created new backup: 2013-07-03-150318

15:03:55 - Starting post-backup thinning

15:03:59 - Error: Error Domain=NSOSStatusErrorDomain Code=-50 "The operation couldn’t be completed. (OSStatus error -50.)" (paramErr: error in user parameter list) deleting backup: /Volumes/MyBook/Backups.backupdb/uome’s iMac/2013-07-01-032209.inProgress/382C2D25-4CEA-4CBC-9343-BA3A775E33D8

15:14:44 - Deleted /Volumes/MyBook/Backups.backupdb/uome’s iMac/2013-06-03-032741 (148.2 MB)

15:14:44 - Post-back up thinning complete: 1 expired backups removed

15:14:46 - Backup completed successfully.

What does the red message mean and why has it happened?

Many thanks!

Pondini

Level 8

38,863 points

Jul 3, 2013 5:45 PM in response to coxorange

coxorange wrote:

. . .

15:03:59 - Error: Error Domain=NSOSStatusErrorDomain Code=-50 "The operation couldn’t be completed. (OSStatus error -50.)" (paramErr: error in user parameter list) deleting backup: /Volumes/MyBook/Backups.backupdb/uome’s iMac/2013-07-01-032209.inProgress/382C2D25-4CEA-4CBC-9343-BA3A775E33D8

. . .

What does the red message mean and why has it happened?

That's not really a problem -- TM was trying to delete the remains of a previous failed or cancelled backup, from the ".inProgress" package. It may have been deleted already.

But the backup was terribly slow, in both the preflight and copying phases. Could be any number of things. See what happens on the next backup; if it's slow, too, see the green box in #D2 of Time Machine - Troubleshooting

coxorange Author

Level 1

98 points

Jul 3, 2013 7:34 PM in response to Pondini

Thanks for your answer.

Pondini wrote:

But the backup was terribly slow, in both the preflight and copying phases. Could be any number of things.

Maybe because I repaired permissions before that backup?

Pondini wrote:

See what happens on the next backup...

Here is the log of the next one:

03:20:22 - Starting manual backup

03:20:23 - Backing up to: /Volumes/MyBook/Backups.backupdb

03:20:26 - Using file event preflight for Macintosh HD

03:20:29 - Will copy (881.8 MB) from Macintosh HD

03:20:29 - Found 2688 files (996.2 MB) needing backup

03:20:29 - 2.77 GB required (including padding), 481.11 GB available

03:23:36 - Copied 17795 files (914.5 MB) from volume Macintosh HD.

03:23:36 - Using file event preflight for Macintosh HD

03:23:36 - Will copy (343 KB) from Macintosh HD

03:23:36 - Found 11 files (343 KB) needing backup

03:23:36 - 1.57 GB required (including padding), 480.24 GB available

03:23:42 - Copied 483 files (343 KB) from volume Macintosh HD.

03:23:43 - Created new backup: 2013-07-04-032342

03:23:44 - Starting post-backup thinning

03:24:20 - Deleted /Volumes/MyBook/Backups.backupdb/uome’s iMac/2013-06-04-021931 (148.1 MB)

03:24:20 - Post-back up thinning complete: 1 expired backups removed

03:24:20 - Backup completed successfully.

This looks better to me.

Pondini

Level 8

38,863 points

Jul 3, 2013 7:50 PM in response to coxorange

coxorange wrote:

Thanks for your answer.

Pondini wrote:

But the backup was terribly slow, in both the preflight and copying phases. Could be any number of things.

Maybe because I repaired permissions before that backup?

Shouldn't make a noticeable difference.

Here is the log of the next one:

. . .

This looks better to me.

Yup. 🙂 But keep an eye on it.

Two Time Machine Mysteries