MacOS – What’s expected Time Machine behavior for large folders with few changed files

backupmacostime-machine

How does Time Machine (on a High Sierra MacBook Pro with APFS) know which files in a folder have changed since the last backup? I know that TM relies on FSEvents to watch for directories with changed file(s). What I don't know is what TM does when it learns that 1+ files in a folder have changed. I'm looking for a detailed technical explanation, not high-level info about Time Machine itself. Specifically:

  • What information about each file (e.g. in a folder with 1 changed files and 999 files unchanged since the last backup) does TM use to determine which files are same as the last backed-up version? Does TM look only at file size & modification time? Does it actually read file contents? Does it read file attributes?
  • What filesystem API calls does Time Machine use to check which files have changed? Specifically, does it make one (or a small number) of calls per folder, e.g. to fetch a directory listing? Or will it make 1+ calls per file to pull additional info like file contents, attributes, etc.?
  • If the answers to the questions above vary (e.g. "sometimes TM does XXX, sometimes YYY") then what are the reasons why TM would be making many filesystem calls for each unchanged file in a folder?

I'm asking because I'm trying to diagnose slow Time Machine incremental backups on my late-2015 MacBook Pro running High Sierra. Each "hourly" backup takes 30+ minutes to complete, even though the amount of data backed up each time is under 2GB.

Looking at logs of Time Machine disk activity (using sudo fs_usage -f filesys backupd), the culprit seems to be filesystem access of unchanged message and attachment files associated with Outlook 2016 Mac.

Outlook creates 256 folders for messages and 256 folders for attachments, and it evenly distributes new messages and attachments among these folders. For example, my Outlook profile has about 250K messages, most of which have 1+ attachments. Each of those 512 folders contains about 1,000 messages. I get about 500 new messages per day, so if it's been a day since my last backup, each of those 512 folders will have 1-3 new files and about 1,000 unchanged files.

Looking at the file system logs, Time Machine is making many filesystem calls for each file, even though only a few hundred files have changed out of 500,000+ files in these folders. Filesystem access for each unchanged file is quick (~0.075 seconds in the example log excerpt below) but if you multiply 0.075 seconds by 500K files, that's over 10 hours! Time Machine runs multiple threads so each incremental backup doesn't take 10 hours, but instead takes 30+ minutes for each "hourly" backup.

That's a lot of battery usage and disk access to look at 500,000+ files every hour that haven't changed. Note that 30+ minutes is the TM speed after I've used sudo sysctl debug.lowpri_throttle_enabled=0. Without this change, it's even slower.

I'm trying to figure out the root cause of the problem:

  • Is it how my computer is configured? Is there a change I can make to my files, to Time Machine settings, etc. that would cause TM to stop spending so much time examining unchanged files on every incremental backup?
  • Is the problem fundamental to how Outlook 2016 Mac stores it messages and attachment files, so every Mac user of Outlook with a large and active mailbox will have this problem? For example, does Outlook do something unusual with attributes that may cause TM to spend extra time examining Outlook's files compared to other apps that create lots of small files?
  • Or is the root cause in the design of Time Machine, where it's expected that if any files in a folder have changed then TM will make relatively-expensive filesystem calls for each file in order to verify which files have changed?

Here's a logs sample (for a single file that hasn't been changed since the last backup) that suggest that Time Machine is doing a lot of filesystem access for each unchanged file. I count 11 (!!!) file system accesses for this one 901-byte file that is already backed up and is unchanged since the last backup.

09:14:19.783112  getattrlist                            .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.000027   backupd.944294
09:14:19.783424  fsctl                                  .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.000006   backupd.944294
09:14:19.783428  fsctl                                  .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.000004   backupd.944294
09:14:19.783542  getattrlist                            .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.000057   backupd.944294
09:14:19.783603  listxattr                              .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.000016   backupd.944294
09:14:19.783612  listxattr                              .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.000008   backupd.944294
09:14:19.805903  listxattr                              .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.022290   backupd.944294
09:14:19.806028  listxattr                              .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.000109   backupd.944294
09:14:19.856232    HFS_update               (__M__c__)  .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.000013   backupd.948297
09:14:19.856258  link                                   .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.050019   backupd.948297
09:14:19.856394  getattrlist                            .Office/Outlook/Outlook 15 Profiles/2018-05-11/Data/Message Attachments/137/8969C57E-7F6D-4152-AF11-FDF535486C92.olk15MsgAttachment    0.000051   backupd.948297

I know that I can exclude Outlook folders from Time Machine backups, but I'm hesitant to do this as it might prevent me from restoring messages.

I've already tried deleting the FSEvents logs (via sudo mv /.fseventsd /.fseventsd.bak and a reboot) and allowing them to be re-created, which sped up backups considerably so that they'll only take a few minutes if I haven't started Outlook since the last backup. But after I run Outlook, backups take 30+ mins. I've verified by looking at logs that the extra time is not due to backup data volume– the 1.3GB Outlook.sqllite file is backed up in 1-2 minutes each time– but instead seems to be caused by the 100,000s of files that Time Machine is looking at but not backing up.

It's not a network issue nor a speed issue of my backup NAS drive: when TM is backing up large files, it backs up 10-30 megabytes per second over WiFi (I have fast WiFi!). Also, connecting directly to my gigabit ethernet doesn't improve speed when TM is churning through all those tiny Outlook files.

UPDATE:

As advised by Monomeeth in his answer below, I downloaded and ran Time Machine Mechanic (really helpful tool!). Here's the output for the last 12 hours. 

Analysis from 2018-05-23 19:38:58 +0000 to 2018-05-24 05:38:58 +0000 for 10 hours:
Backing up to /dev/disk2s2: /Volumes/Time Machine Backups/Backups.backupdb
on which there were 411.74 GB, 411.74 GB, 411.74 GB, 411.74 GB, 411.74 GB, 411.74 GB available.
Started 6 auto backups, and 0 manual backups; completed 7 backups successfully,
last backup completed successfully 7.0 minutes ago,
backed up a total of 16417 files, range 639 to 4666 in each backup,
total data for each backup was 2.09 GB, 2.1 GB, 1.89 GB, 1.58 GB, 1.66 GB, 1.59 GB, 1.54 GB.
Times taken for each auto backup were 93.8, 37.8, 29.8, 34.4, 35.4, 87.6 minutes,
intervals between the start of each auto backup were 140.5, 70.8, 63.4, 69.9, 65.9 minutes.
Created 0 new backups, and deleted 7 old backups,
cancelled 4 backups.
7 errors reported:
2018-05-23 13:27:42.967395-0700 Error: Error Domain=NSOSStatusErrorDomain Code=-50 "paramErr: error in user parameter list" deleting backup: /Volumes/Time Machine Backups/Backups.backupdb/Justin’s MacBook Pro/2018-05-23-113921.inProgress/B14EC326-8AE7-4C23-8F37-17BDEFCF9F1C
2018-05-23 20:33:49.535143-0700 Error: Error Domain=NSOSStatusErrorDomain Code=-36 "ioErr: I/O error (bummers)" deleting backup: /Volumes/Time Machine Backups/Backups.backupdb/Justin’s MacBook Pro/2018-05-21-163447
2018-05-23 20:33:49.536821-0700 Error: Error Domain=NSOSStatusErrorDomain Code=-50 "paramErr: error in user parameter list" deleting backup: /Volumes/Time Machine Backups/Backups.backupdb/Justin’s MacBook Pro/2018-05-22-193257
2018-05-23 20:33:49.536960-0700 Error: Error Domain=NSOSStatusErrorDomain Code=-50 "paramErr: error in user parameter list" deleting backup: /Volumes/Time Machine Backups/Backups.backupdb/Justin’s MacBook Pro/2018-05-22-183736
2018-05-23 20:33:49.537620-0700 Error: Error Domain=NSOSStatusErrorDomain Code=-50 "paramErr: error in user parameter list" deleting backup: /Volumes/Time Machine Backups/Backups.backupdb/Justin’s MacBook Pro/2018-05-22-150607
2018-05-23 20:33:49.537704-0700 Error: Error Domain=NSOSStatusErrorDomain Code=-50 "paramErr: error in user parameter list" deleting backup: /Volumes/Time Machine Backups/Backups.backupdb/Justin’s MacBook Pro/2018-05-22-134626
2018-05-23 20:33:49.539118-0700 Error: Error Domain=NSOSStatusErrorDomain Code=-50 "paramErr: error in user parameter list" deleting backup: /Volumes/Time Machine Backups/Backups.backupdb/Justin’s MacBook Pro/2018-05-22-120245

Note that there's no deep scans, and each backup took a minimum of 30 minutes to back up 1.5-2 GB. Most of the size is the single 1.3GB Outlook.sqllite file, which is backed up in about 2 minutes according to the file system logs, which works out about 10 megabytes/sec. But most of the time is taken (again according to file system logs) by reading/checking 100,000's of unchanged files.

Is this normal? It seems unexpected for TM to have knowledge of what files have changed (via FSEvents) but still have to look at every file. Is there something unusual about Outlook's files that causes it to happen with Outlook's files but not with other applications' files? Could it be that Outlook is using extended attributes (e.g. "Author" and "Recipient" attributes on email message files) and those attributes are what are causing the slowdown?

I'm not sure what to make of the errors, but they're referring to deleting backups. Perhaps that's an unrelated issue to my slow backups?

Best Answer

SHORT ANSWER

Yes, this is expected behaviour.

Time Machine only backs up new or modified data, and keeps a record of any deleted data. This includes libraries that can contain tens of thousands of files (e.g. your Photos Library) and other locations (such as directories/folders that contain large numbers of files (such as those used by MS Outlook). It does not do a fresh backup of an entire library/folder each time you make changes to it, but only backs up those items that have been changed. For Time Machine to do this properly, it does needs to check every item to determine what has changed since the last backup.

LONG ANSWER

The way Time Machine works is that it backs up anything that has changed since the last backup. For example, a file that is:

  • Edited since the last backup is backed up again in the next backup
  • Created since the last backup is backed up in the next backup
  • Deleted since the last backup is not included in the next backup (i.e. there is no record of it in that backup, but the file itself is still stored for any older backups it was a part of)

Now, the confusion usually comes from the way Time Machine actually does a backup. I'll try and explain this below.

  1. The initial backup TM does on a new backup drive is a full backup of your Mac. So, if your Mac has used 80GB of a 1TB drive, then the first backup will take up 80GB of space on the new backup drive.
  2. All remaining incremental backups do not do a full backup. Instead TM backs up any new data (i.e. newly added data and any edited data) and keeps a record of any deleted data.
  3. In the case of files such as Packages (e.g. the Photos Library package), TM will identify any:
    • new data (e.g. new photos in the Masters folder within your Photos Library package) and back this up
    • modified data within your Photos Library package (e.g. edited photos) and back this up
    • deleted data within your Photos Library package (e.g. photos you've deleted) and keep a record of the change
  4. When the backup drive runs out of space, TM will delete as many of the oldest backups it needs to in order to be able to do the next backup (and this is where users can lose data that was not part of more recent backups)
  5. Regardless of whether it is the initial full backup or an incremental backup, TM will display this to the user as if they're all separate full backups. This is designed on the basis of User Experience (UX) design so that it's easier for users to browse and find data, and acts to reassure users that it's all there. According to Apple:

This entire process is designed to ensure that Time Machine not only backs up your data, but remembers how it looked at a given point in time so that it's easier for users to find what they're looking for. According to Apple:

...what makes Time Machine different from other backup applications is that it not only keeps a spare copy of every file, it remembers how your system looked on any given day—so you can revisit your Mac as it appeared in the past.

Source: Mac Basics: Time Machine (web archive of Apple knowledge base doc)

So yes, this is expected behaviour. Using the example in your question, although there are 11 instances you're counting, all of those combined took a fraction of a second for Time Machine to process, and from my point of view that's well worth the peace of mind and usability that Time Machine offers.

In a nutshell, I would not recommend trying to interfere with it.

[UPDATE]

This update does not supersede the above high level information, but provides further clarity due to a revision to the OP's question that provides further context around the question.

As you're aware, Time Machine checks with the File System Events (FSEvents) database stored on each volume to identify which files have changed since the last backup.

However, if the FSEvents database is missing, or if Time Machine determines it is corrupted or incomplete, it will perform a deep scan. If it does a deep scan, this means it will check the last modified timestamp of all files (and directories) on the relevant volume. As part of this deep scan Time Machine creates a list of all items that have changed since the last backup. Obviously, if you're backing up to a remote device (especially if it's through Wi-Fi) then this really slows things down.

While you could disable FSEvent recording on a volume, this isn't going to help you because you're wanting to use Time Machine to backup your data and this action would only force it to perform a deep scan.

In light of the additional info you've provided, you have two things to determine:

  1. Is Time Machine performing a deep scan each time it's doing a backup?
  2. If so, why is it doing that?

To answer the first question you can download and install the Time Machine Mechanic (T2M2). This analyses your logs to check if Time Machine backups are running normally or not.

The key thing in your case is to check if T2M2 indicates the following:

started 1 deep traversal scans

completed 1 deep traversal scans

If using the above tool indicates that Time Machine is in fact performing deep scans, this may be cause for concern. Not so much so if it's an occasional thing, as this can happen after certain events anyway (e.g. having recently booted from another volume, after a full restore, following a power loss, etc), but if it's happening all the time then it does ring alarm bells. In that case, I refer you to Time Machine - Troubleshooting Common Backup Messages.

Related Question