I’ve noticed that on my Win 7 machine, the indexing phase of an incremental file backup is far slower than that on my wife’s Win 7 computer. Her machine is backing up more files (533K vs 436K on mine), but the indexing phase on her machine usually takes 3 minutes (max 16), while my machine usually takes 40 to 60 minutes (max 73). She does have a much more recent CPU (i7-4770, I believe), while mine is an old i7-920. We’ve got similar setups other than that - SSD C drives, spinning D and E drives.
Is the indexing doing something so CPU-intensive that it runs that much faster on her more recent machine? Or is there likely something else going on?
BTW, I’m grabbing the indexing times directly from the backup_server.db file under sqlite3 (select indexing_time_ms from backups). It would be nice if that value was displayed in the activities page in the GUI.
UrBackup runs as background process. There may be a foreground process having priority using all available IO. For me this happens when my software RAID is being rebuild on Windows
You have client side hashing enabled for that client
You have a lot of changes/lookups. You can see that in the log. It says how often it had to look at the filesystem.
Doesn’t seem to be any of those. Same virus scanner on both systems. Both systems have 4 core 8 thread CPUs. Nothing else interesting or intensive is happening during the indexing phase - CPU usage for the whole machine runs about 12-15%, with a single thread in UrBackupClientBackend pegging its core and very little else happening. Both systems are using the same server-side settings, and I don’t see client-side hashing enabled. That’s assuming you’re referring to “Verify file backups using client side hashes”, which is disabled, and not “Trust client hashes during incremental file backups”, which is enabled on both systems. And according to logs, the slow system has these lookups:
C: 43737 filesystem lookups 0 db lookups and 0 db updates
D: 2 filesystem lookups 10890 db lookups and 2 db updates
E: 2 filesystem lookups 2198 db lookups and 2 db updates
while the fast system has these:
C: 169 filesystem lookups 9977 db lookups and 131 db updates
D: 2 filesystem lookups 28023 db lookups and 2 db updates
E: 2 filesystem lookups 7536 db lookups and 2 db updates
I just manually ran an incremental file backup while logging info in Sysinternals Process Monitor. The indexing phase took about an hour. I used the default logging filter with the addition of “Process Name begins with urbackup”. The results are curious. The drives were indexed in the order D, E, C. I don’t see queries to the shadow copy of D until 30 minutes into the indexing. Those queries then took less than a minute. There was a 12 minute gap, then 2 seconds of queries to the shadow copy of E. Finally, another 12 minute gap, then 6 minutes of queries to the shadow copy of C.
I can’t tell from the procmon log what’s happening in the thread that’s running at 100%. The only log entries for that thread are FileSystemControl FSCTL_READ_USN_JOURNAL entries for the D: and E: drives every ten seconds. So whatever is taking so much time isn’t leaving a trail in procmon.
Unless you’ve got an idea where else to look, I’ll probably try building the client backend with debug info so I can get some useful stack traces.
Hmm, just noticed something weird. On the slow system, there’s lots of filesystem lookups on the C: drive, which is reasonable (lots of activity in temporary files and browser caches). But there are 0 db looksups and 0 db updates. Why isn’t the db being used for the C drive?
I had such a case, not sure if so much relevant, but before enabling Background Intelligent Transfer and Volume Shadow services, I was getting the same “error” on the server and also the backup was taken repeatedly. Stopped the backup from server, enabled services, restarted the client service and now is all running quite fast and well.
The problem I mentioned turns out to be, in effect, an internal leak that causes the indexing phase of incremental backups to take longer the longer it’s been since the last reboot (and not just restart of the client service). On my machine, what should take about 4 minutes was taking an hour ten days after the last reboot. I’ve got a pull request pending on the UrBackup repo at GitHub with a fix, which I’ve been running locally for the past couple weeks. The leak was introduced in version 1.4.4, I think.