Previous 1 2 3 Next 33 Replies Latest reply: Jan 27, 2009 8:17 AM by Pondini
wchlm Level 1 Level 1 (5 points)
I'm using TM to back up a 150 Gb drive to a 591 Gb partition (Mac OS Extended (Journaled)) on a 1 Tb Lacie D2 Quadro connected via Firewire 800.

A TM backup usually takes more than 1 hour. Due to this, I decreased frequency to every 6 hours, but even so, during the 1+ hours the backup takes, the machine is only marginally usable.

Below is an excerpt from my system.log file bracketing a TM backup.

In contrast, I occasionally use Silverkeeper (a free backup tool provided by Lacie) to create a bootable backup to another partition on the same drive. Even though I only do this every week or so, the Silverkeeper backup only takes about 3/4 hour.

--
Jan 11 11:10:58 shenkin /System/Library/CoreServices/backupd[75466]: Starting standard backup
Jan 11 11:10:58 shenkin /System/Library/CoreServices/backupd[75466]: Backing up to: /Volumes/Time Machine Bak/Backups.backupdb
Jan 11 11:16:48 shenkin /System/Library/CoreServices/backupd[75466]: No pre-backup thinning needed: 741.5 MB requested (including padding), 446.50 GB available
Jan 11 12:10:09 shenkin /System/Library/CoreServices/backupd[75466]: Copied 214541 files (18.9 MB) from volume Macintosh HD.
Jan 11 12:10:20 shenkin /System/Library/CoreServices/backupd[75466]: No pre-backup thinning needed: 740.2 MB requested (including padding), 446.48 GB available
Jan 11 12:11:42 shenkin /System/Library/CoreServices/backupd[75466]: Copied 5400 files (17.8 MB) from volume Macintosh HD.
Jan 11 12:11:47 shenkin /System/Library/CoreServices/backupd[75466]: Starting post-backup thinning
Jan 11 12:32:02 shenkin /System/Library/CoreServices/backupd[75466]: Deleted backup /Volumes/Time Machine Bak/Backups.backupdb/shenkin /2009-01-10-055318: 446.50 GB now available
Jan 11 12:32:02 shenkin /System/Library/CoreServices/backupd[75466]: Post-back up thinning complete: 1 expired backups removed
Jan 11 12:32:02 shenkin /System/Library/CoreServices/backupd[75466]: Backup completed successfully.
--

PowerMac G5, Mac OS X (10.5.6), iPod shuffle, Treo 650, Linux, W*****s
  • Pondini Level 8 Level 8 (38,715 points)
    At first glance, I'd say yes, that's far too long for about 20 mb of data.

    But then I see that it's backing-up over 200,000 files! Small ones, obviously, in the area of 200 bytes each.

    As I recall my first TM backup, was in the neighborhood of 500,000 files (mostly the OS) and took perhaps an hour and a half, so perhaps yours isn't all that bad. TM may, I suppose, be spending most of it's time creating files & folders instead of actually copying data.

    I can only guess -- are you running an app that's adding/updating a whole passel of files?

    If you don't know what these files are, you might want to download the (free) app TimeTracker, from VersionTracker. It will show you what was backed-up on each TM backup.
  • wchlm Level 1 Level 1 (5 points)
    I will try TimeTracker. But I should mention that when I did a recent Silverkeeper backup (for the first time in a few weeks), its log file showed only 11000 files backed up. So I very much doubt that the 200,000-file number in the log file is correct.

    And why are there two entries -- one for 215,000 files and one for 5400 files? Maybe this is normal... but it still comes to my eye.

    I will report after trying TimeTracker.

    I know of no app I'm running that could be touching such a large number of files.

    Thanks... I'll report back when I have TimeTracker info.

    -P.
  • Pondini Level 8 Level 8 (38,715 points)
    wchlm wrote:
    And why are there two entries -- one for 215,000 files and one for 5400 files? Maybe this is normal... but it still comes to my eye.


    This is not uncommon, and is yet another TM mystery. TM does use an internal OSX event file that logs changes, in contrast to most backup apps that examine every file -- that's why it's usually so much faster.

    My completely-uneducated guess is, when a backup starts, TM gets the changes from the event file that's been written to disk, and copies those files. Then it forces a "flush" of changes made but not yet written to the event file on disk, thus including any last-minute changes as well, and copies the new files. This is, of course, probably 100% wrong!

    But whatever the reason, it is fairly common, and doesn't seem to be a problem.
  • wchlm Level 1 Level 1 (5 points)
    wchlm wrote:
    I know of no app I'm running that could be touching such a large number of files.

    Thanks... I'll report back when I have TimeTracker info.


    TimeTracker from VersionTracker has nothing to do with Time Machine; rather, it's a personal productivity/time-reporting tool. There is a TimeTracker from charlessoft.com that I found a link to on the web; that appears to be what you're thinking of; but charlessoft.com no longer exists.

    However, I did find "timedog", a Perl script that does the following (to quote its top-level comment):

    # Display the files which time machine backed up in its most recent
    # backup (or any of your choosing). Uses the fact that Time Machine
    # creates hard links for unchanged files and directories. Reports old
    # and new sizes, along with the total file count and backup size.


    timedog run on the latest backup reports the following summary, after listing all the files:

    ==> Total Backup: 1042 changed files, 69.27MB

    This latest backup was subsequent to the one I first reported; in the syslog, the latest backup shows the following. There appears to be a huge discrepancy between what Time Machine claims it is backing up and what timedog claims Time Machine is backing up.

    --
    Jan 11 17:10:56 shenkin /System/Library/CoreServices/backupd[76902]: Starting standard backup
    Jan 11 17:10:56 shenkin /System/Library/CoreServices/backupd[76902]: Backing up to: /Volumes/Time Machine Bak/Backups.backupdb
    Jan 11 17:16:23 shenkin /System/Library/CoreServices/backupd[76902]: No pre-backup thinning needed: 796.2 MB requested (including padding), 446.50 GB available
    Jan 11 17:57:22 shenkin /System/Library/CoreServices/backupd[76902]: Copied 219685 files (62.0 MB) from volume Macintosh HD.
    Jan 11 18:03:27 shenkin /System/Library/CoreServices/backupd[76902]: No pre-backup thinning needed: 739.9 MB requested (including padding), 446.43 GB available
    Jan 11 18:39:46 shenkin /System/Library/CoreServices/backupd[76902]: Copied 187369 files (17.7 MB) from volume Macintosh HD.
    Jan 11 18:52:43 shenkin /System/Library/CoreServices/backupd[76902]: Starting post-backup thinning
    Jan 11 19:14:46 shenkin /System/Library/CoreServices/backupd[76902]: Deleted backup /Volumes/Time Machine Bak/Backups.backupdb/shenkin /2009-01-10-120628: 446.39 GB now available
    Jan 11 19:14:46 shenkin /System/Library/CoreServices/backupd[76902]: Post-back up thinning complete: 1 expired backups removed
    Jan 11 19:14:47 shenkin /System/Library/CoreServices/backupd[76902]: Backup completed successfully.
  • Pondini Level 8 Level 8 (38,715 points)
    wchlm wrote:
    TimeTracker from VersionTracker has nothing to do with Time Machine; rather, it's a personal productivity/time-reporting tool. There is a TimeTracker from charlessoft.com that I found a link to on the web; that appears to be what you're thinking of; but charlessoft.com no longer exists.


    So I see. I just got it a month or so ago, a great little app, and does just exactly what you need. Perhaps a trade name problem -- maybe it'll be back under a new name.


    timedog run on the latest backup reports the following summary, after listing all the files:

    ==> Total Backup: 1042 changed files, 69.27MB

    This latest backup was subsequent to the one I first reported; in the syslog, the latest backup shows the following. There appears to be a huge discrepancy between what Time Machine claims it is backing up and what timedog claims Time Machine is backing up.


    Very odd indeed. Do the 1042 files listed seem correct?

    If so, then the only thing I can think of is, how are you limiting TM to run every 6 hours? I know there are some apps that will do that, also instructions on how to edit TM's preference file, but I've not used them. Perhaps that has somehow confused it mightily?

    To run that long, and post those wildly spurious messages, it's apparently spending a whole lot of time trying to do something!

    If you haven't already, you might try just turning it off, then back on, and see if that will somehow reset it.
  • Pondini Level 8 Level 8 (38,715 points)
    One other thought: How long have you been on 10.5.6, and how did you install it?

    A different, but equally-strange problem in another thread was solved by downloading and installing the Combo update.

    Might be worth a try in your case, as well.
  • wchlm Level 1 Level 1 (5 points)
    Pondini wrote:
    One other thought: How long have you been on 10.5.6,


    Some months.

    and how did you install it?


    Downloaded software update.

    I didn't start using TM till quite a while after the update.

    A different, but equally-strange problem in another thread was solved by downloading and installing the Combo update.

    Might be worth a try in your case, as well.


    What is the Combo update, and where do I get it?

    Thanks,
    -P.
  • Pondini Level 8 Level 8 (38,715 points)
    The "combo" update contains all the changes from the original issue of Leopard in one big package. Thus loading it should fix anything that went wrong in any previous update.

    It's possible that some small item was missed or somehow messed-up (pardon the technical term!) on one of your past updates, but never caused a problem because you weren't using TM.

    The update and info are at: http://support.apple.com/downloads/MacOS_X_10-5-6_ComboUpdate

    It's a big one (668 mb), so allow yourself plenty of time.
  • wchlm Level 1 Level 1 (5 points)
    Pondini wrote:
    The "combo" update contains all the changes from the original issue of Leopard in one big package. Thus loading it should fix anything that went wrong in any previous update.

    It's possible that some small item was missed or somehow messed-up (pardon the technical term!) on one of your past updates, but never caused a problem because you weren't using TM.

    The update and info are at: http://support.apple.com/downloads/MacOS_X_10-5-6_ComboUpdate

    It's a big one (668 mb), so allow yourself plenty of time.


    Thanks. That's useful. By the way, when I did the upgrade, the "tar" utility disappeared -- others have seen this as well. I had to install it from some other place (I forget where -- the original Leopard disk, maybe).

    Since my current system disk is nearly full, I will probably wait about a week before I do this. I want to add a drive.
  • Pondini Level 8 Level 8 (38,715 points)
    TimeTracker is back!

    Very neat little app, shows what was backed-up (hidden files and all) on each TM backup.

    http://www.charlessoft.com/
  • wchlm Level 1 Level 1 (5 points)
    Pondini wrote:
    TimeTracker is back!

    Very neat little app, shows what was backed-up (hidden files and all) on each TM backup.

    http://www.charlessoft.com/



    Thanks. I've downloaded and installed it. TimeTracker shows 31.9 Mb backed up in the most recent backup; system log shows the following; the way I read the system log, it seems to say that 31.7+17.8 = 49.5 Mb were backed up. System log is still claiming 200000+ files backed up; though TimeTracker doesn't give a summary wit the number backed up, going through the folders it displays makes it clear that it's nothing like that; maybe 1000 at the most.

    The good news here is that this latest backup took a half hour -- less than earlier ones.

    --
    Jan 17 21:20:50 shenkin /System/Library/CoreServices/backupd[10924]: Backing up to: /Volumes/Time Machi
    ne Bak/Backups.backupdb
    Jan 17 21:24:52 shenkin /System/Library/CoreServices/backupd[10924]: No pre-backup thinning needed: 767
    .0 MB requested (including padding), 444.38 GB available
    Jan 17 21:50:15 shenkin /System/Library/CoreServices/backupd[10924]: Copied 204564 files (31.7 MB) from
    volume Macintosh HD.
    Jan 17 21:50:22 shenkin /System/Library/CoreServices/backupd[10924]: No pre-backup thinning needed: 750
    .2 MB requested (including padding), 444.35 GB available
    Jan 17 21:50:42 shenkin /System/Library/CoreServices/backupd[10924]: Copied 763 files (17.8 MB) from vo
    lume Macintosh HD.
    Jan 17 21:50:47 shenkin /System/Library/CoreServices/backupd[10924]: Starting post-backup thinning
    Jan 17 21:50:47 shenkin /System/Library/CoreServices/backupd[10924]: No post-back up thinning needed: n
    o expired backups exist
    Jan 17 21:50:47 shenkin /System/Library/CoreServices/backupd[10924]: Backup completed successfully.
  • wchlm Level 1 Level 1 (5 points)
    By the way, for this same backup, timedog's summary shows the following:

    ==> Total Backup: 189 changed files, 38.37MB

    -P.
  • Pondini Level 8 Level 8 (38,715 points)
    Glad to hear it's improved, but you've still got something wrong. If it's really only backing-up 35-40 mb, half an hour is far too long, even if it were wireless. If you're on FW800, it's ridiculous.

    Since most of the time appears to have been spent copying the first group of files (21:24 to 21:50), it calculates to about 32 mb in 25 minutes! You could fax it faster!

    And the huge file counts make no sense either. Mine are high, but "only" 2 or 3 times what I see in TimeTracker. I suspect the difference is the metadata associated with OSX files being counted separately by TM.

    Yes, TM's "requested" space always seem high, often quite high. The speculation is, TM makes a quick estimate based on what's in the File System Event Log. Apparently this could include things like counting the same file more than once if it was updated multiple times since the last backup, etc., so nobody really worries about it.

    Are there any other messages in your log for this period?

    Are you running File Vault?

    Have you watched CPU usage while a backup is in progress (seems unlikely, but something unrelated might be going on).

    Just to rule it out, you might try doing a simple copy of a file or files totalling perhaps 30 mb to the other partition on that same disk, and time it. Again it seems unlikely, but perhaps there's something strange happening with the drive and/or cable.

    How weird.
  • wchlm Level 1 Level 1 (5 points)
    Pondini wrote:
    Glad to hear it's improved, but you've still got something wrong.

    ...
    Since most of the time appears to have been spent copying the first group of files (21:24 to 21:50), it calculates to about 32 mb in 25 minutes! You could fax it faster!

    And the huge file counts make no sense either.

    ...
    Are there any other messages in your log for this period?


    Do you mean while TM is running? Generally not at all. I get sporadic messages like the following, and occasionally one or two will occur while backups are going on, but I presume this is benign; and besides, even when none of these occurs during the operation of TM, I still see the problem.

    Jan 18 09:32:59 shenkin Mail[12651]: * Failed to decode 8-bit data, treating as binary
    Jan 18 09:33:03 shenkin mdworker[12647]: * Failed to decode 8-bit data, treating as binary


    Are you running File Vault?


    No.

    Have you watched CPU usage while a backup is in progress (seems unlikely, but something unrelated might be going on).


    Yes. Time Machine basically takes up all unused CPU cycles. I usually have Firefox and Mail running in background. I should try it one time with nothing at all running. (I think I've done this and observed no change in behavior, but I should try again to be sure.)

    Just to rule it out, you might try doing a simple copy of a file or files totalling perhaps 30 mb to the other partition on that same disk, and time it. Again it seems unlikely, but perhaps there's something strange happening with the drive and/or cable.


    "time cp foo /Volumes/Time\ Machine\ Bak" shows 13 sec real time when foo is a 404-Mb file. If I got the full 800 Mbit/sec transfer speed, it would have transferred in 4 sec, but 13 sec isn't so bad. There's nothing wrong with raw file xfer speed.

    In a previous posting, you asked how I increased the TM interval to 6 hours from 1 hr. I did this by editing /System/Library/LaunchDaemons/com.apple.backupd-auto.plist, changing the value of StartInterval from 3600 to 216000. This suggestion came from another discussion thread in this forum. However, I doubt this is the culprit, because the whole reason I changed from 1- to 6-hr intervals was because TM was running all the time and the computer was always unusable.
Previous 1 2 3 Next