Why does this take 3 hours?
During which time the disk has read activity. Does it read the entire data on disk?
| 10/15/23 10:32 | INFO | Starting scheduled incremental file backup… |
|---|---|---|
| 10/15/23 10:32 | DEBUG | PC: Doing backup with hashes… |
| 10/15/23 10:32 | DEBUG | PC: Doing backup with intra file diffs… |
| 10/15/23 10:32 | DEBUG | PC: Connecting for filelist… |
| 10/15/23 10:32 | DEBUG | PC: Waiting for filelist |
| 10/15/23 10:32 | DEBUG | PC: Connecting for filelist (async)… |
This looks like the server log, is this correct? Check the client log, it should tell you what your client is currently working on.
From the client log:
Starting scheduled incremental file backup…
Scanning for changed hard links on volume of "E:"…
It doesn’t make sense to wait 3 hours for every incremental files backup…
It wasn’t like this before, I’m not sure when it started. Probably after I deleted all backups and started fresh on btrfs.
Before, it took around 5 minutes in total (and most of it was spent on creating hard links on the server side).
Since the chances of getting support here are close to none, I decided to start fresh again, but this time doing it differently. Last time what I did was deleting all the backups from the web interface, keeping the user settings. But maybe that wasn’t good enough.
What’s the recommended way to start fresh? Deleting all files in /var/urbackup?
Maybe the problem is on the client side? I’m using version 2.5.23-cbt (on Windows), which worked beautifully before the aforementioned server changes (although it could be unrelated).
Edit: I upgraded to 2.5.25-cbt, but it didn’t change a thing.
I used Process Monitor to check the reason for the disk access. The UrBackupClientBackend.exe process reads all the file contents, over and over again each incremental files backup. This means that if I backup 1TB of files, and even not a single byte changed since the last backup, 1TB of files is still being read from disk.
Why isn’t it using the NTFS journal to monitor changes?
Then, it writes to C:\Program Files\UrBackup\urbackup\data\filelist_new_0.ub. Does it mean it detects all of them as “new”, and that’s why it reads their contents?
Another file, filelist.ub, also exists and is much bigger, so I assume filelist_new_0.ub is merged into it at some point.
[Edit: after looking at the code, I see it just renames filelist_new_0.ub to filelist.ub]
CBT status shows all volumes are supported, but I assume CBT is used just for image backups (which indeed reads just the changed blocks).
What else can I do?
Regarding NTFS journaling, I confirmed it is enabled and working.
C:\>fsutil usn queryjournal e:
Usn Journal ID : 0x01d396f9c9a7fe3d
First Usn : 0x00000000da200000
Next Usn : 0x00000000ded9baa8
Lowest Valid Usn : 0x0000000000000000
Max Usn : 0x00000fffffff0000
Maximum Size : 0x0000000004600000 (70.0 MB)
Allocation Delta : 0x0000000000a00000 (10.0 MB)
Minimum record version supported : 2
Maximum record version supported : 4
Write range tracking: Disabled
I created a file on the drive and saw the Next Usn value increase.
Interestingly, the journal_data table in backup_client.db is empty. Could this be the problem?
I may have found the solution. I tested it on 2 other drives and it seems to be working. Tomorrow I will test it on the problematic drive. If it works, I will update here.
Here is the update. Interesting finding. The first time an incremental files backup is run, this appears in the log:
Indexing of “E” done. 3265 filesystem lookups 0 db lookups and 0 db updates
The next time:
Indexing of “E” done. 1 filesystem lookups 3264 db lookups and 1 db updates
So the first time it reads all the files from the disk, presumably stores them in its internal database, and the following times it reads them from there.
Excellent! But… it only lasts till the next reboot, after which the files are read again from the disk.
I tried deleting C:\Program Files\UrBackup\urbackup\{backup_client.db*|hdat_file*}. They are successfully recreated, the described behavior does not change.
@uroni Maybe you have an idea what might cause this? I sent you the debug.log file by email. Looks like an error with journaling? Thanks!
It is this here:
2023-10-18 14:01:15: ERROR: Unknown error for Volume 'e:' - watchDir ec: 87
2023-10-18 14:01:15: ERROR: Could not open path in os_get_final_path for "E:\"
2023-10-18 15:43:27: WARNING: Info not found at 'e:' - reindexing
2023-10-18 15:43:36: WARNING: Stopped indexing process
2023-10-18 15:43:36: WARNING: Indexing was not finished at 'e:' - reindexing
Now what could be different with the E:\ drive or with the OS?
Code 87 is ERROR_INVALID_PARAMETER to FSCTL_QUERY_USN_JOURNAL - Win32 apps | Microsoft Learn
Thanks for your reply! The following factors have changed in the last couple of weeks:
ASRock B150M Pro4S to Asus PRIME B760M-A-CSMI tried rebuilding the journal using:
fsutil usn deletejournal /d E:
fsutil usn createjournal m=73400320 a=10485760 E:
fsutil usn queryjournal e:
Usn Journal ID : 0x01da025d80d9976a
First Usn : 0x0000000000000000
Next Usn : 0x0000000000000000
Lowest Valid Usn : 0x0000000000000000
Max Usn : 0x00000fffffff0000
Maximum Size : 0x0000000004600000 (70.0 MB)
Allocation Delta : 0x0000000000a00000 (10.0 MB)
Minimum record version supported : 2
Maximum record version supported : 4
Write range tracking: Disabled
I also tried disabling the VSS service (to simulate the previous behavior), but to no avail.
chkdsk reports no errors on drive.
It’s worth mentioning that this is a 2TB USB drive, which is NTFS formatted and constantly connected to the computer. I emphasize that journaling worked before on this same drive, and I did not find any reports that journaling does not work on USB drives.
Any ideas?
I ran the following program:
#include <windows.h>
#include <stdio.h>
void testJournaling(const char* driveLetter) {
char volumePath[MAX_PATH];
sprintf(volumePath, "\\\\.\\%s:", driveLetter);
HANDLE hVolume = CreateFileA(volumePath, GENERIC_READ | GENERIC_WRITE,
FILE_SHARE_READ | FILE_SHARE_WRITE, NULL,
OPEN_EXISTING, 0, NULL);
if (hVolume == INVALID_HANDLE_VALUE) {
printf("Failed to open volume %s with error code %lu\n", driveLetter, GetLastError());
return;
}
USN_JOURNAL_DATA journalData;
DWORD bytesReturned;
BOOL result = DeviceIoControl(hVolume, FSCTL_QUERY_USN_JOURNAL, NULL, 0,
&journalData, sizeof(journalData), &bytesReturned, NULL);
if (result) {
printf("USN Journal exists on volume %s with ID: %llu\n", driveLetter, journalData.UsnJournalID);
} else {
printf("Failed to query USN Journal on volume %s with error code %lu\n", driveLetter, GetLastError());
}
CloseHandle(hVolume);
}
int main() {
printf("Testing journaling on drives D: and E:\n");
testJournaling("D");
testJournaling("E");
return 0;
}
and got this output:
Testing journaling on drives D: and E:
USN Journal exists on volume D with ID: 132848022929451360
USN Journal exists on volume E with ID: 133421739577808746
Cool thanks for investigating with this level of detail.
Could you try using USN_JOURNAL_DATA_V1 instead of USN_JOURNAL_DATA. That is what USN_JOURNAL_DATA points at for me. Maybe it needs to use USN_JOURNAL_DATA_V2 instead.
All versions work and give the same result (I tried USN_JOURNAL_DATA_V0, USN_JOURNAL_DATA_V1, USN_JOURNAL_DATA_V2). 
Maybe you have some more codes that I can try?
Only thing currently that I can think of is that the content matters, what if you initialize it with e.g.
memset(&journalData, 0xFF, sizeof(journalData);
before the DeviceIoControl?
(or with 0x00? )
In combination with different structure lengths…
I found this question winapi - Walking the NTFS Change Journal on Windows 10 - Stack Overflow but that is about FSCTL_READ_USN_JOURNAL and says FSCTL_QUERY_USN_JOURNAL succeeds…
I think we found the problem by joining forces. 
This code fails:
#include <windows.h>
#include <stdio.h>
void testJournaling(const char* driveLetter) {
char volumePath[MAX_PATH];
sprintf_s(volumePath, "\\\\.\\%s:", driveLetter);
HANDLE hVolume = CreateFileA(volumePath, GENERIC_READ | GENERIC_WRITE,
FILE_SHARE_READ | FILE_SHARE_WRITE, NULL,
OPEN_EXISTING, 0, NULL);
if (hVolume == INVALID_HANDLE_VALUE) {
printf_s("Failed to open volume %s with error code %lu\n", driveLetter, GetLastError());
return;
}
USN_JOURNAL_DATA journalData;
DWORD bytesReturned;
BOOL result = DeviceIoControl(hVolume, FSCTL_QUERY_USN_JOURNAL, NULL, 0,
&journalData, sizeof(journalData), &bytesReturned, NULL);
if (result) {
printf("USN Journal exists on volume %s with ID: %llu\n", driveLetter, journalData.UsnJournalID);
// Now testing reading USN journal data
READ_USN_JOURNAL_DATA readData = { 0 };
readData.UsnJournalID = journalData.UsnJournalID;
readData.StartUsn = 0;
readData.ReasonMask = 0xFFFFFFFF;
readData.ReturnOnlyOnClose = FALSE;
readData.Timeout = 0;
readData.BytesToWaitFor = 0;
char buffer[1024];
result = DeviceIoControl(hVolume, FSCTL_READ_USN_JOURNAL, &readData,
sizeof(readData), &buffer, sizeof(buffer), &bytesReturned, NULL);
if (result) {
printf("Successfully read USN journal entries on volume %s\n", driveLetter);
} else {
printf("Failed to read USN journal entries on volume %s with error code %lu\n", driveLetter, GetLastError());
}
}
else {
printf("Failed to query USN Journal on volume %s with error code %lu\n", driveLetter, GetLastError());
}
CloseHandle(hVolume);
}
int main() {
printf("Testing journaling on drives D: and E:\n");
testJournaling("D");
testJournaling("E");
return 0;
}
Result:
Testing journaling on drives D: and E:
USN Journal exists on volume D with ID: 132848022929451360
Failed to read USN journal entries on volume D with error code 87
USN Journal exists on volume E with ID: 133421739577808746
Failed to read USN journal entries on volume E with error code 87
I think RbMm’s comment may be a hint in the right direction. Since you mentioned that USN_JOURNAL_DATA translates to USN_JOURNAL_DATA_V1, and MinMajorVersion and MaxMajorVersion are not initialized.
If we initialize them, e.g.:
readData.MinMajorVersion = 2; // Windows 2000 and later
readData.MaxMajorVersion = 3; // Windows 8 and later
It now works:
Testing journaling on drives D: and E:
USN Journal exists on volume D with ID: 132848022929451360
Successfully read USN journal entries on volume D
USN Journal exists on volume E with ID: 133421739577808746
Successfully read USN journal entries on volume E
No, it logs the error occuring at FSCTL_QUERY_USN_JOURNAL. It would log something different (containing update err=) if FSCTL_READ_USN_JOURNAL fails.
Additionally it is explicitly using READ_USN_JOURNAL_DATA_V0 there.
#include <windows.h>
#include <iostream>
void testJournaling(const char* volumeLetter, void* initData, size_t dataSize, size_t querySize) {
char volumePath[MAX_PATH];
sprintf_s(volumePath, sizeof(volumePath), "\\\\.\\%s", volumeLetter);
HANDLE hVolume = CreateFileA(volumePath, GENERIC_READ | GENERIC_WRITE,
FILE_SHARE_READ | FILE_SHARE_WRITE, NULL,
OPEN_EXISTING, 0, NULL);
if (hVolume == INVALID_HANDLE_VALUE) {
std::cerr << "Failed to open volume " << volumeLetter << " with error code: " << GetLastError() << std::endl;
return;
}
USN_JOURNAL_DATA journalData;
memset(&journalData, (int)(intptr_t)initData, dataSize);
DWORD bytesReturned;
BOOL result = DeviceIoControl(hVolume, FSCTL_QUERY_USN_JOURNAL,
NULL, 0,
&journalData, querySize,
&bytesReturned, NULL);
if (result) {
std::cout << "DeviceIoControl operation for volume " << volumeLetter << " succeeded." << std::endl;
} else {
DWORD error = GetLastError();
std::cerr << "Failed to query USN Journal on volume " << volumeLetter << " with error code: " << error << std::endl;
}
CloseHandle(hVolume);
}
int main() {
const char* volumeLetter = "E:";
std::cout << "Testing journaling on volume " << volumeLetter << std::endl;
testJournaling(volumeLetter, (void*)0xFF, sizeof(USN_JOURNAL_DATA), sizeof(USN_JOURNAL_DATA));
testJournaling(volumeLetter, (void*)0x00, sizeof(USN_JOURNAL_DATA), sizeof(USN_JOURNAL_DATA));
// Passing less bytes than expected
testJournaling(volumeLetter, (void*)0xFF, sizeof(USN_JOURNAL_DATA), sizeof(USN_JOURNAL_DATA) - 4);
testJournaling(volumeLetter, (void*)0x00, sizeof(USN_JOURNAL_DATA), sizeof(USN_JOURNAL_DATA) - 4);
// Passing more bytes than expected
testJournaling(volumeLetter, (void*)0xFF, sizeof(USN_JOURNAL_DATA), sizeof(USN_JOURNAL_DATA) + 4);
testJournaling(volumeLetter, (void*)0x00, sizeof(USN_JOURNAL_DATA), sizeof(USN_JOURNAL_DATA) + 4);
return 0;
}
Result:
Testing journaling on volume E:
DeviceIoControl operation for volume E: succeeded.
DeviceIoControl operation for volume E: succeeded.
DeviceIoControl operation for volume E: succeeded.
DeviceIoControl operation for volume E: succeeded.
DeviceIoControl operation for volume E: succeeded.
DeviceIoControl operation for volume E: succeeded.
Can you maybe print the parameters to the debug log? This way we’ll be able to reproduce it.
Hmm, yeah, that’d probably just show everything is as usual.
The pdb for urbackupclient.dll if you want to debug this:
urbackupclient.7z (4.5 MB)
I doubt that there is much actually info in a procmon trace, but perhaps worth a look…
Finally, it is perhaps difficult, but compile yourself and debug into it then?