Slow query of changed blocks with big disks

[slu-010101]

Hi,

what need so much time (02:51:21 - 03:09:49) between this steps and what "overlap" mean?

[2025-03-18 02:51:19] INFO root checkpoint - create [main]: Checkpoint handling.
[2025-03-18 02:51:19] INFO root checkpoint - create [main]: Next checkpoint id: [1].
[2025-03-18 02:51:19] INFO root checkpoint - create [main]: Parent checkpoint name [virtnbdbackup.0].
[...]
[2025-03-18 02:51:21] INFO nbd client - connect [vda]: Connection to NBD backend succeeded.
[2025-03-18 03:09:49] INFO extenthandler extenthandler - overlap [vda]: Detected [3751608320] sparse bytes for current bitmap.
[2025-03-18 03:09:49] INFO root disk - backup [vda]: Got 8695 extents to backup.
[2025-03-18 03:09:49] INFO root disk - backup [vda]: 858993459200 bytes disk size
[2025-03-18 03:09:49] INFO root disk - backup [vda]: 3751608320 bytes of data extents to backup
[...]
[2025-03-18 03:10:06] INFO root virtnbdbackup - main [main]: Total saved disk data: [3.5GB]
[2025-03-18 03:10:06] INFO root virtnbdbackup - main [main]: Finished successfully

[abbbi]

version with option --no-sparse-detection available for testing:

https://github.com/abbbi/virtnbdbackup/actions/runs/14060801672/artifacts/2815846178

[slu-010101]

Still testing and have no trace:

image: vm1.qcow2
file format: qcow2
virtual size: 1.95 TiB (2147483648000 bytes)
disk size: 1.64 TiB
cluster_size: 65536
Format specific information:
compat: 1.1
compression type: zlib
lazy refcounts: false
refcount bits: 16
corrupt: false
extended l2: false

[2025-03-26 03:22:43] INFO nbd client - connect [vda]: Connection to NBD backend succeeded.
[2025-03-26 04:43:58] INFO extenthandler extenthandler - overlap [vda]: Detected [9918349312] sparse bytes for current bitmap.
[2025-03-26 04:43:58] INFO root disk - backup [vda]: Got 17852 extents to backup.
[2025-03-26 04:43:58] INFO root disk - backup [vda]: 2147483648000 bytes disk size
[2025-03-26 04:43:58] INFO root disk - backup [vda]: 9918349312 bytes of data extents to backup
[...]
[2025-03-26 04:44:41] INFO root virtnbdbackup - main [main]: Total saved disk data: [9.2GB]

Same hypervisor, same destination storage:

image: vm2.qcow2
file format: qcow2
virtual size: 300 GiB (322122547200 bytes)
disk size: 260 GiB
cluster_size: 65536
Format specific information:
compat: 1.1
compression type: zlib
lazy refcounts: false
refcount bits: 16
corrupt: false
extended l2: false

[2025-03-26 02:50:03] INFO nbd client - connect [sda]: Connection to NBD backend succeeded.
[2025-03-26 02:50:06] INFO extenthandler extenthandler - overlap [sda]: Detected [27417247744] sparse bytes for current bitmap.
[2025-03-26 02:50:06] INFO root disk - backup [sda]: Got 485 extents to backup.
[2025-03-26 02:50:06] INFO root disk - backup [sda]: 322122547200 bytes disk size
[2025-03-26 02:50:06] INFO root disk - backup [sda]: 27417247744 bytes of data extents to backup
[...]
[2025-03-26 02:51:49] INFO root virtnbdbackup - main [main]: Total saved disk data: [25.5GB]

Those "485 extents" get less when I use fstrim or I misunderstood it completely?

[abbbi]

[slu-010101]

Now we need again 13 seconds (!) for the backup, thank you @abbbi

[2025-03-28 16:54:03] INFO nbd client - connect [vda]: Connection to NBD backend succeeded.
[2025-03-28 16:54:03] INFO extenthandler extenthandler - queryBlockStatus [vda]: Skipping detection of sparse/fstrimmed blocks.
[2025-03-28 16:54:03] INFO root disk - backup [vda]: Got 14722 extents to backup.
[2025-03-28 16:54:03] INFO root disk - backup [vda]: 858993459200 bytes [800.0GiB] virtual disk size
[2025-03-28 16:54:03] INFO root disk - backup [vda]: 2977890304 bytes [2.8GiB] of data extents to backup
[...]
[2025-03-28 16:54:16] INFO root virtnbdbackup - main [main]: Total saved disk data: [2.8GiB]

And the new disk size logging is perfect :)

[dlunev]

It seems that I have reproduced the situation using this image

#!/bin/bash

# Image file name
IMAGE="test-image.qcow2"
# Image size in KB (300GB converted to KB as an example, adjust if needed)
SIZE_KB=$((300 * 1024 * 1024))
# Block size in KB (64k)
BLOCK_SIZE_KB=64
# Skip size in KB (128k)
SKIP_SIZE_KB=128
# Step size in KB (block + skip = 192k)
STEP_KB=$((BLOCK_SIZE_KB + SKIP_SIZE_KB))
# Starting offset in KB (64k)
START_OFFSET_KB=64

# Create the qcow2 image if it doesn't exist
# Convert size to bytes for qemu-img
SIZE_BYTES=$((SIZE_KB * 1024))
if [ ! -f "$IMAGE" ]; then
    qemu-img create -f qcow2 "$IMAGE" "$SIZE_BYTES"
    if [ $? -ne 0 ]; then
        echo "Failed to create image"
        exit 1
    fi
fi

# Calculate number of iterations
# Account for starting offset in calculation
ITERATIONS=$(((SIZE_KB - START_OFFSET_KB) / STEP_KB))

echo "Starting write operations..."
echo "Image size: $SIZE_KB KB"
echo "Block size: $BLOCK_SIZE_KB KB"
echo "Skip size: $SKIP_SIZE_KB KB"
echo "Starting offset: $START_OFFSET_KB KB"
echo "Total iterations: $ITERATIONS"

# Counter for progress
count=0

# Loop to write 64k blocks of zeroes with 128k skips, starting at 64k
offset_kb=$START_OFFSET_KB
while [ $offset_kb -lt $SIZE_KB ]; do
    # Write 64k of zeroes at current offset
    qemu-io -c "write -z ${offset_kb}k ${BLOCK_SIZE_KB}k" "$IMAGE" > /dev/null 2>&1
    if [ $? -ne 0 ]; then
        echo "Write failed at offset ${offset_kb}k"
        exit 1
    fi
    
    # Show progress every 1000 iterations
    if [ $((count % 1000)) -eq 0 ]; then
        echo "Progress: $count/$ITERATIONS (offset: ${offset_kb}k)"
    fi
    
    # Move to next position
    offset_kb=$((offset_kb + STEP_KB))
    count=$((count + 1))
done

echo "Write operations completed"
echo "Wrote $count blocks of ${BLOCK_SIZE_KB}k zeroes with ${SKIP_SIZE_KB}k skips"

After that the images has been modified using

#!/bin/bash

# Image file name
IMAGE="test-image.qcow2"
# Image size in KB (300GB converted to KB as an example, adjust if needed)
SIZE_KB=$((300 * 1024 * 1024))
# Block size in KB (64k)
BLOCK_SIZE_KB=64
# Skip size in KB (128k)
SKIP_SIZE_KB=128
# Step size in KB (block + skip = 192k)
STEP_KB=$((BLOCK_SIZE_KB + SKIP_SIZE_KB))
# Starting offset in KB (64k)
START_OFFSET_KB=64

# Create the qcow2 image if it doesn't exist
# Convert size to bytes for qemu-img
SIZE_BYTES=$((SIZE_KB * 1024))
if [ ! -f "$IMAGE" ]; then
    qemu-img create -f qcow2 "$IMAGE" "$SIZE_BYTES"
    if [ $? -ne 0 ]; then
        echo "Failed to create image"
        exit 1
    fi
fi

# Calculate number of iterations
# Account for starting offset in calculation
ITERATIONS=$(((SIZE_KB - START_OFFSET_KB) / STEP_KB))

echo "Starting write operations..."
echo "Image size: $SIZE_KB KB"
echo "Block size: $BLOCK_SIZE_KB KB"
echo "Skip size: $SKIP_SIZE_KB KB"
echo "Starting offset: $START_OFFSET_KB KB"
echo "Total iterations: $ITERATIONS"

# Counter for progress
count=0

# Loop to write 64k blocks of zeroes with 128k skips, starting at 64k
offset_kb=$START_OFFSET_KB
while [ $offset_kb -lt $SIZE_KB ]; do
    # Write 64k of zeroes at current offset
    qemu-io -c "write -z ${offset_kb}k ${BLOCK_SIZE_KB}k" "$IMAGE" > /dev/null 2>&1
    if [ $? -ne 0 ]; then
        echo "Write failed at offset ${offset_kb}k"
        exit 1
    fi

    # Show progress every 1000 iterations
    if [ $((count % 1000)) -eq 0 ]; then
        echo "Progress: $count/$ITERATIONS (offset: ${offset_kb}k)"
    fi

    # Move to next position
    offset_kb=$((offset_kb + STEP_KB))
    count=$((count + 1))
done

echo "Write operations completed"
echo "Wrote $count blocks of ${BLOCK_SIZE_KB}k zeroes with ${SKIP_SIZE_KB}k skips"

and used as VM image. Full backup has been created. So far, so good. The idea is to create big amount of extents.
VM stopped and image has been modified one more time using 2.sh

Since that incremental backup becomes VERY slow and the slowness comes from the offsets merge function.

[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10331553792 10331619328 11534336
[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10331619328 10331750400 11534336
[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10331750400 10331815936 11534336
[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10331815936 10331947008 11534336
[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10331947008 10332012544 11534336
[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10332012544 10332143616 11534336
[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10332143616 10332209152 11534336
[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10332209152 10332340224 11534336
[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10332340224 10332405760 11534336
[2025-04-01 22:59:07] DEBUG extenthandler extenthandler - overlap [vda]: add base0 11468800 10332405760 10332536832 11534336

This is something with which I can work now :-)

Smaller image has not been tested yet.

[dlunev]

    def overlap(self, extents: List[Extent]) -> List[Extent]:
        """Find overlaps between base allocation and incremental bitmap to detect zero regions"""
        base_extents = [e for e in extents if e.context == CONTEXT_BASE_ALLOCATION]
        backup_extents = [ 
            e for e in extents if e.context == self._metaContext and e.data
        ]

        selected_extents = []
        totalLength: int = 0

        for backup in backup_extents:
            backup_end = backup.offset + backup.length
            log.debug("check extent backup %d %d", backup.offset, backup_end)
            for base in base_extents:

and this code looks definitely like something of O(N^2) complexity.

[abbbi]

@dlunev

but as a far as we have analyzed, the problem was not within the overlap function, but querying the extents for the base:allocation bitmap?

The time gap is betwen querying the extents, both using the implementation in virtnbdbackup aswell as using
nbdinfo --map=base:allocation nbd:... before the overlap function comes into place.

[2025-03-19 12:14:28] INFO root disk - _getExtentHandler [vda]: Using qemu tools to query extents
[2025-03-19 13:02:15] INFO extenthandler extenthandler - overlap [vda]: Detected [7466188800] spa

[abbbi]

index.txt

anything wrong with that approach?

[abbbi]

it is clear that the overlap function can be optimized. Because the function loops over all base extents for each extent detected during incremental backup, this is not optimal. But i still think this is not the only problem.

1. The Solution by @dlunev looks quite good, but seems to cause data-loss
2. My proposed fix is: https://github.com/user-attachments/files/19564144/index.txt which at least passes my tests, but its not quite clear if it does help.
3. Another one (less optimal) would be to add:

for base in base_extents:
    if base.offset > backup_end:
        continue

in the current implementation.

Im in the process of creating a big 500 GB volume with lots of extents attempting to reproduce the situations to have something to work with.

@slu-010101 Would you mind testing the following version:

• it contains my propsed fix
• it logs detailed start and end of queryBlockStatus function, to see how long it takes for the system to query the extents without the need to create a debug log:

https://github.com/abbbi/virtnbdbackup/actions/runs/14216112206/artifacts/2865995548

Please try incremental backup and post complete logfile.

I'd really have this sorted out in the coming weeks because debian trixie enters freeze soon, and i dont want to have the next debian release include a version that doesnt work for most of the users. If we dont come up with something soon ill just make --no-sparse-detection option default and users can opt-in to use it.

[dlunev]

we should have this function to work as O(L) as we could have 16k extents here. N^2 does not look good. Which means that I have to spend time at evening trying to make a fix.

NOTE: can you suggest how to start tests to make sure that all is fine?

[abbbi]

@dlunev you can start the fstrim related tests by cd t/; make fstrim.tests

Note: it will require working libvirt environment on the system executed.

Or just fork the project and push to your fork, should make it all run in your personal github actions.

[slu-010101]

@slu-010101 Would you mind testing the following version:

* it contains my propsed fix
* it logs detailed start and end of queryBlockStatus function, to see how long it takes for the system to query the extents without the need to create a debug log:

If you can reproduce it, I don't need to test it?
If I have to test it, it only works on the production systems, which will take me about 3-4 hours to move data and create a test vm before.

[abbbi]

ok, so im able to reproduce it. Ive got an image with 498147 base extents, thats sufficient enough to make it
blow.

With master version, it takes ages in the overlap function.

with the version from the optimize_overlap branch containing my reworks:
ba646cd

its much faster:

[2025-04-02 11:51:44] INFO extenthandler extenthandler - queryBlockStatus [vda]:  Start receiving backup extents.
[2025-04-02 11:51:45] INFO extenthandler extenthandler - queryBlockStatus [vda]:  Finished receiving extents.
[2025-04-02 11:51:46] INFO extenthandler extenthandler - overlap [vda]:  Detected [258605056] sparse bytes for current bitmap.

changing between full and inc via image.sh:

Wrote 5 blocks of 64k zeroes with 128k skips

results in:

overlap [vda]: Detected 327680 bytes [320.0KiB] sparse blocks for current bitmap

qemu-io -c "write -z 18000k 64k" /cache/big.qcow2
qemu-io -c "write  8000k 64k" /cache/big.qcow2

shields:

[2025-04-02 12:26:50] INFO extenthandler extenthandler - overlap [vda]:  Detected 65536 bytes [64.0KiB] sparse blocks for current bitmap.
[2025-04-02 12:26:50] INFO root disk - backup [vda]:  Got 1 extents to backup.
[2025-04-02 12:26:50] INFO root disk - backup [vda]:  536870912000 bytes [500.0GiB] virtual disk size
[2025-04-02 12:26:50] INFO root disk - backup [vda]:  65536 bytes [64.0KiB] of data extents to backup

[abbbi]

@dlunev

ive pushed my changes to master branch ive created a new simple testsuite for the extent handling optimization.

Im not quite sure that status quo of the tests is Ok, all it does is basically using qemu-io to change certain block ranges
between vm shutdown and attempts to test if the incremental backup is saving up right amount of data blocks:

https://github.com/abbbi/virtnbdbackup/blob/master/t/fstrimsmall.bats

it can be executed via:

virtnbdbackup/t# make fstrimsmall.tests

I think it makes sense to have this feature tested in-depth, as i fear data-loss.

See also: #263 (comment)

[rmk177]

Tests passed Ok. Thanx.

[slu-010101]

Same machines with 2.28 super fast:

VM1

[2025-04-28 12:15:14] INFO extenthandler extenthandler - queryBlockStatus [vda]: Start receiving backup extents.
[2025-04-28 12:15:20] INFO extenthandler extenthandler - queryBlockStatus [vda]: Finished receiving extents.
[2025-04-28 12:15:21] INFO extenthandler extenthandler - overlap [vda]: Detected 3817340928 bytes [3.6GiB] non-sparse blocks for current bitmap.
[...]
[2025-04-28 12:15:41] INFO root virtnbdbackup - main [main]: Total saved disk data: [3.6GiB]
[2025-04-28 12:15:41] INFO root virtnbdbackup - main [main]: Finished successfully

VM2

[2025-04-28 12:15:50] INFO extenthandler extenthandler - queryBlockStatus [vda]: Start receiving backup extents.
[2025-04-28 12:16:00] INFO extenthandler extenthandler - queryBlockStatus [vda]: Finished receiving extents.
[2025-04-28 12:16:01] INFO extenthandler extenthandler - overlap [vda]: Detected 5652545536 bytes [5.3GiB] non-sparse blocks for current bitmap.
[...]
[2025-04-28 12:16:29] INFO root virtnbdbackup - main [main]: Total saved disk data: [5.3GiB]
[2025-04-28 12:16:29] INFO root virtnbdbackup - main [main]: Finished successfully