Subsequent backups (both full and incremental) slow.

Your thinking is correct, subsequent backups should be much faster. Can you submit your logs to me for review? The easiest way to do this is from within CCC:

1. Choose "Report a problem" from the Help menu
2. Click on the "Submit Logs" tab and review the information presented
3. Click on the "Submit Logs" button
4. Update this discussion to let us know that you've submitted your logs.

Thanks,
Mike

Thanks for the fast response! Logs submitted.

That's really strange... I don't see anything in the log that would indicate that the data should be recopied. CCC uses file size and modification date to determine if it should copy a file. Can you compare a few files on the source and destination and see if those attributes differ?

Also, I see that you have reformatted the destination volume several times, so I wouldn't expect any filesystem trouble there, but does Disk Utility report any filesystem issues with the source volume?

Thanks,
Mike

The files I've checked look identical with respect to size and modification date.

I've verified the source disk and found no problems, same with the destination volume.

For what it's worth, a similar thing happens with another piece of cloning software I've tried. It copies most (not all) of the files again when I do a subsequent clone. It copies maybe 145gb of 160gb used disk space and recognises about 15gb as unchanged. This is right after the inital clone when very little should have changed.

Any thoughts?

Heh, yeah, I saw you loaded up SD. That's OK, that the same thing is happening there is a good data point.

If you hadn't reformatted the destination so many times, that would be the first thing I'd recommend... Can you reproduce this behavior with another source volume? For example, a thumb drive or even a CD would work (though it would be kinda slow).

Actually, let's try this. The attached version of CCC has some additional debugging enabled, I'm curious what will turn up in the logs. Use this on a fairly small subset of files -- for example, deselect everything in the list of items to be copied, then enable just a couple items in the Applications folder. For every file, CCC will print out a line about whether it's the size or mod time that it sees as differing, and what the values are. If it reports that the files are identical but they're still being copied, then there's a bug somewhere that I need to track down.

After you've run the task, you can submit the logs directly from within CCC:

1. Choose "Report a problem" from the Help menu
2. Click on the "Submit Logs" tab and review the information presented
3. Click on the "Submit Logs" button
4. Update this discussion to let us know that you've submitted your logs (please make a note of the submission ID noted at the bottom of the window).

Thanks,
Mike

Logs submitted (ID: 3752).
After a full cIone, I selected a few items in the applications folder.

This time it looks like no data was copied! It correctly recognised that there were no changes.

When I try a full clone again, it copies lots of data. I didn't wait for it to complete but submitted logs again after cancelling it.

Let me know what turns up!

Update: I used my original copy of CCC to "backup everything" over the original full clone again. This time, it started very quickly, not copying much data but when it got to my itunes library, after about 10 minutes, it seemed to start copying loads more again and slowed right down.

Update 2: I figured the data was coming from my home folder so I selected a some items from there, which your attached version of CCC (with additional debugging) did copy. I submitted more logs which hopefully will turn up something.

This is intriguing, some of the items get their modification date set just fine, but some files' mod dates are set to the current time (e.g. 11:22 this morning, whenever the file was copied -- presumably). The modification time is the only thing that is differing, so this is entirely a problem of the modification time not getting set properly. Or, I suppose it's possible that the modification date is getting altered shortly after the files are getting copied. I'm only throwing that out there as a possibility because I've never seen CCC not set the modification date properly without throwing an error.

It's so strange how sporadic this is. You'll have a string of files that are fine, then a few that aren't, then more than are fine, then gobs that aren't. I don't see any pattern at all...

The attached version of CCC has some additional debugging enabled around the setting of the modification date on the file on the destination. Can you try the following:

1. Delete /Library/Application Support/GarageBand from the destination volume
2. Deselect everything except for that folder in the list of items to be copied and run a backup task
3. Repeat the backup task immediately
4. Resubmit your logs

In addition to showing what the modification date is that CCC is applying to the file, CCC will immediately "stat" the file after setting the modification date to verify that it "stuck".

Thanks,
Mike

Logs resubmitted (ID: 3752 again).

Thanks!

Doh, I need to have the CCC.0.log too. Long story on why that was excluded from the log submission, but can you do this to get that file to me:

1. Navigate to /Library/Logs
2. Right-click on the CCC.0.log file and choose "Compress CCC.0.log"
3. Attach the zipped file here.

Thanks. Looking at the last run, I can see that about 1/3 of the files were recopied because the modification time was incorrect. What I need to figure out next is whether CCC set the modification time correctly in the first run. I can see that for each file that was copied the second time, the modification time was set properly on the file that was copied, e.g.:

07/08 17:05:36 unchanged_file: mod time differs on /wurli1.caf: dest: 1310141108, source: 1181005657
07/08 17:05:42 set_file_attrs: mod time on /.wurli1.caf.8oFtUt: dest: 1310141142, source: 1181005657
07/08 17:05:42 set_file_attrs: Setting mod time on "/.wurli1.caf.8oFtUt": 1181005657
07/08 17:05:42 set_file_attrs: Restat of /.wurli1.caf.8oFtUt, new modtime: 1181005657

".wurli1.caf.8oFtUt" is the temporary name for the new backup file. You can see that it starts out with a modification time that is equal to the current time (1310141142 = Fri Jul 8 16:05:42 UTC 2011), and then the mod time is set to 1181005657 (Tue Jun 5 01:07:37 UTC 2007 -- you're +0100 GMT, so the hours are behind by one hour). CCC then re-stats the file and confirms that the mod time was set correctly.

Thanks,
Mike

Zip file attached.

OK, terrific. From the first run:

07/08 17:04:43  set_file_attrs: mod time on /.TEXAS LEAD#2.caf.5MplFg: dest: 1310141083, source: 1181005559 (10001)
07/08 17:04:43  set_file_attrs: Setting mod time on "/.TEXAS LEAD#2.caf.5MplFg": 1181005559 (10001)
07/08 17:04:43  set_file_attrs: Restat of/.TEXAS LEAD#2.caf.5MplFg, new modtime: 1181005559 (10001)

Second run:

07/08 17:05:36  unchanged_file: mod time differs on /TEXAS LEAD#2.caf: dest: 1310141108, source: 1181005559 (10001)
07/08 17:05:42  set_file_attrs: mod time on /.TEXAS LEAD#2.caf.itdKhY: dest: 1310141142, source: 1181005559 (10001)
07/08 17:05:42  set_file_attrs: Setting mod time on "/.TEXAS LEAD#2.caf.itdKhY": 1181005559 (10001)
07/08 17:05:42  set_file_attrs: Restat of /.TEXAS LEAD#2.caf.itdKhY, new modtime: 1181005559 (10001)

So the modification time did get set correctly, but it was changed by something between the two tasks. Let me double check that CCC isn't touching a file again after the the "set_file_attrs" function. That was an issue for an edge case in the past.

<< Sorry for the delay, I got distracted at this point and forgot to actually hit the "Comment" button. I'm looking at this right now... >>

Mike

In the attached version, I moved the "restat" to right after the very last touch that I make on a file, so we should be able to see what the modification date is on each file when CCC is completely finished touching any files. The last thing that I do is set the fileflags on a file (I wouldn't want to lock it before writing data to it, for example). Can you try the same steps again:

1. Delete /Library/Application Support/GarageBand from the destination volume
2. Deselect everything except for that folder in the list of items to be copied and run a backup task
3. Repeat the backup task immediately
4. Resubmit your logs (the attached version will zip and upload both CCC.log and CCC.0.log)

I actually installed iLife '09 onto my test machine, though, and was able to set up the same scenario with the same test data. I don't see anything unusual about these files, and I don't see the recopying behavior. This is definitely an odd situation...

Thanks,
Mike

Thanks. Logs resubmitted once again (ID: 3752).

Something is definitely happening to these files after the transfer. After the very last touch I make on a file, the modification date is correct. From the first run:

07/12 17:10:51 DEBUG: finish_transfer(): Restat of Library/Application Support/GarageBand/Magic GarageBand/09. Slow Blues.wand/Media/TEXAS LEAD#1.caf after move, new modtime: 1181005481 (10001)

Then this file gets transferred again in the second run:

07/12 17:11:45 DEBUG: finish_transfer(): Restat of Library/Application Support/GarageBand/Magic GarageBand/09. Slow Blues.wand/Media/TEXAS LEAD#1.caf after move, new modtime: 1181005481 (10001)

1181005481 = Tue Jun 5 01:04:41 UTC 2007, which is the correct modification date for that file. I'm curious what the modification date is on that file right now, is it again set to today (e.g. 07/12 17:11:45)?

I haven't ever encountered this kind of situation before, so I'm not quite sure what to make of it. Do you have any system utilities installed that do any sort of indexing or scanning of files? Maybe anti-virus software? Are there any processes that are particularly active after the backup task (e.g. as seen in the Activity Monitor application)?

Mike

According to the finder, the mod date on that file right now is: 4th September 2009 03:54 on both the source and destination disks.

I'm using McAfee security. It did seem pretty active (together with a process called 'vshield scanner') during and after the backup task (with only garageband selected) so I disabled the on-access scanner and, sure enough the task completed in a fraction of the time, no data copied. However, with a backup of everything, the issue persists, even with McAfee disabled - CCC starts copying a lot of data.

Other processes called 'kextchache' and 'directoryservice' were active at the time.

Any thoughts?

Update: It turned out to be the antivirus software interfering. In case anyone else has the same issue I found that the first full clone should be performed with antivirus on-access scanning disabled. It can then be enabled during the incremental backups without any decreased performance. Or you could try excluding the destination volume from the files to be scanned.

Many thanks to Mike for looking into this so thoroughly.

Thanks for the followup! I'm glad we nailed that one down.

Mike