Incremental backups slower and bigger than full backups

Tools asbackup & asrestore
1

Hi there,

I’ve been running into a strange issue with incremental backups where backups created with --modified-after appear to be much heavier than the actual full snapshots of our database. We are running a cluster of $6$ Aerospike 4.5.1.5 CE instances over Ubuntu 16.04 LTS.

Now onto the issue. If I run a full backup with:

asbackup -n namespace -C -d ./data

I see in the logs (snippet):

...
020-04-22 13:19:21 GMT [INF] [11630] Namespace contains 26983595 record(s)
2020-04-22 13:19:21 GMT [INF] [11630] Directory ./data prepared for backup
2020-04-22 13:19:21 GMT [INF] [11650] Starting backup for node BB97E00F00A0142
2020-04-22 13:19:21 GMT [INF] [11651] Starting backup for node BB9AF00F00A0142
2020-04-22 13:19:21 GMT [INF] [11652] Starting backup for node BB98C00F00A0142
2020-04-22 13:19:21 GMT [INF] [11650] Created new backup file ./data/BB97E00F00A0142_00000.asb
2020-04-22 13:19:21 GMT [INF] [11651] Created new backup file ./data/BB9AF00F00A0142_00000.asb
2020-04-22 13:19:21 GMT [INF] [11655] Starting backup for node BB9A600F00A0142
2020-04-22 13:19:21 GMT [INF] [11652] Created new backup file ./data/BB98C00F00A0142_00000.asb
2020-04-22 13:19:21 GMT [INF] [11655] Created new backup file ./data/BB9A600F00A0142_00000.asb
2020-04-22 13:19:21 GMT [INF] [11653] Starting backup for node BB9AE00F00A0142
2020-04-22 13:19:21 GMT [INF] [11653] Created new backup file ./data/BB9AE00F00A0142_00000.asb
2020-04-22 13:19:21 GMT [INF] [11654] Starting backup for node BB9AD00F00A0142
2020-04-22 13:19:21 GMT [INF] [11654] Created new backup file ./data/BB9AD00F00A0142_00000.asb
2020-04-22 13:19:21 GMT [INF] [11650] No secondary indexes
2020-04-22 13:19:21 GMT [INF] [11650] Backing up 0 UDF file(s)
2020-04-22 13:19:22 GMT [INF] [11649] 0% complete (~836076 KiB/s, ~119931 rec/s, ~7138 B/rec)
2020-04-22 13:19:22 GMT [INF] [11649] ~3m43s remaining
2020-04-22 13:19:28 GMT [INF] [11650] Created new backup file ./data/BB97E00F00A0142_00001.asb
2020-04-22 13:19:28 GMT [INF] [11652] Created new backup file ./data/BB98C00F00A0142_00001.asb
2020-04-22 13:19:28 GMT [INF] [11653] Created new backup file ./data/BB9AE00F00A0142_00001.asb
2020-04-22 13:19:28 GMT [INF] [11654] Created new backup file ./data/BB9AD00F00A0142_00001.asb
2020-04-22 13:19:28 GMT [INF] [11655] Created new backup file ./data/BB9A600F00A0142_00001.asb
2020-04-22 13:19:31 GMT [INF] [11653] Created new backup file ./data/BB9AE00F00A0142_00002.asb
2020-04-22 13:19:31 GMT [INF] [11650] Created new backup file ./data/BB97E00F00A0142_00002.asb
2020-04-22 13:19:32 GMT [INF] [11649] 1% complete (~296096 KiB/s, ~42715 rec/s, ~7098 B/rec)
2020-04-22 13:19:32 GMT [INF] [11649] ~10m23s remaining
2020-04-22 13:19:49 GMT [INF] [11651] Created new backup file ./data/BB9AF00F00A0142_00002.asb
2020-04-22 13:19:49 GMT [INF] [11654] Created new backup file ./data/BB9AD00F00A0142_00002.asb
2020-04-22 13:19:49 GMT [INF] [11653] Created new backup file ./data/BB9AE00F00A0142_00004.asb
2020-04-22 13:19:49 GMT [INF] [11655] Created new backup file ./data/BB9A600F00A0142_00002.asb
2020-04-22 13:19:49 GMT [INF] [11652] Created new backup file ./data/BB98C00F00A0142_00002.asb
2020-04-22 13:19:49 GMT [INF] [11650] Created new backup file ./data/BB97E00F00A0142_00004.asb
2020-04-22 13:19:51 GMT [INF] [11654] Created new backup file ./data/BB9AD00F00A0142_00003.asb
2020-04-22 13:19:52 GMT [INF] [11649] 2% complete (~180704 KiB/s, ~26168 rec/s, ~7071 B/rec)
2020-04-22 13:19:52 GMT [INF] [11649] ~16m44s remaining
...

in particular, the estimates seem reasonable and the backup progresses relatively quickly:

2020-04-22 13:19:22 GMT [INF] [11649] ~3m43s remaining
2020-04-22 13:19:32 GMT [INF] [11649] ~10m23s remaining
2020-04-22 13:19:52 GMT [INF] [11649] ~16m44s remaining
2020-04-22 13:20:12 GMT [INF] [11649] ~36m42s remaining
2020-04-22 13:20:22 GMT [INF] [11649] ~21m4s remaining
2020-04-22 13:20:32 GMT [INF] [11649] ~25m1s remaining
2020-04-22 13:20:42 GMT [INF] [11649] ~2h1m32s remaining
2020-04-22 13:20:52 GMT [INF] [11649] ~30m30s remaining
2020-04-22 13:21:02 GMT [INF] [11649] ~15m21s remaining
2020-04-22 13:21:12 GMT [INF] [11649] ~50m58s remaining
2020-04-22 13:21:32 GMT [INF] [11649] ~25m16s remaining
2020-04-22 13:21:42 GMT [INF] [11649] ~15m37s remaining
2020-04-22 13:21:52 GMT [INF] [11649] ~29m1s remaining
2020-04-22 13:22:02 GMT [INF] [11649] ~13m45s remaining
2020-04-22 13:22:12 GMT [INF] [11649] ~32m27s remaining
2020-04-22 13:22:22 GMT [INF] [11649] ~10m56s remaining
2020-04-22 13:22:32 GMT [INF] [11649] ~19m3s remaining
2020-04-22 13:22:42 GMT [INF] [11649] ~54m48s remaining

Now, if I run the incremental backup:

asbackup -n namespace -C --modified-after 2020-04-21_21:43:16 --modified-before 2020-04-22_12:21:26 -d ./data

I get:

2020-04-22 13:26:49 GMT [INF] [11976] ~30m16s remaining
2020-04-22 13:26:59 GMT [INF] [11976] ~2h55m55s remaining
2020-04-22 13:27:19 GMT [INF] [11976] ~7h44m14s remaining
2020-04-22 13:27:29 GMT [INF] [11976] ~2h58m3s remaining
2020-04-22 13:27:39 GMT [INF] [11976] ~4d2h6m13s remaining
2020-04-22 13:27:49 GMT [INF] [11976] ~3h2m8s remaining
2020-04-22 13:27:59 GMT [INF] [11976] ~1h47m20s remaining
2020-04-22 13:28:09 GMT [INF] [11976] ~8h45m35s remaining
2020-04-22 13:28:19 GMT [INF] [11976] ~1d6h42m3s remaining
2020-04-22 13:28:39 GMT [INF] [11976] ~2h10m19s remaining
2020-04-22 13:28:59 GMT [INF] [11976] ~1d13h35m0s remaining
2020-04-22 13:29:09 GMT [INF] [11976] ~2h49m14s remaining

Plus, my logs get filled with warnings about insufficient disk space:

...
2020-04-22 13:26:48 GMT [INF] [11957] Namespace contains 26971154 record(s)
2020-04-22 13:26:48 GMT [INF] [11957] Directory ./data prepared for backup
2020-04-22 13:26:48 GMT [INF] [11981] Starting backup for node BB97E00F00A0142
2020-04-22 13:26:48 GMT [INF] [11982] Starting backup for node BB9AF00F00A0142
2020-04-22 13:26:48 GMT [INF] [11981] Created new backup file ./data/BB97E00F00A0142_00000.asb
2020-04-22 13:26:48 GMT [INF] [11982] Created new backup file ./data/BB9AF00F00A0142_00000.asb
2020-04-22 13:26:48 GMT [INF] [11980] Starting backup for node BB98C00F00A0142
2020-04-22 13:26:48 GMT [INF] [11980] Created new backup file ./data/BB98C00F00A0142_00000.asb
2020-04-22 13:26:48 GMT [INF] [11979] Starting backup for node BB9A600F00A0142
2020-04-22 13:26:48 GMT [INF] [11979] Created new backup file ./data/BB9A600F00A0142_00000.asb
2020-04-22 13:26:48 GMT [INF] [11978] Starting backup for node BB9AD00F00A0142
2020-04-22 13:26:48 GMT [INF] [11978] Created new backup file ./data/BB9AD00F00A0142_00000.asb
2020-04-22 13:26:48 GMT [INF] [11977] Starting backup for node BB9AE00F00A0142
2020-04-22 13:26:48 GMT [INF] [11977] Created new backup file ./data/BB9AE00F00A0142_00000.asb
2020-04-22 13:26:48 GMT [INF] [11981] No secondary indexes
2020-04-22 13:26:48 GMT [INF] [11981] Backing up 0 UDF file(s)
2020-04-22 13:26:49 GMT [INF] [11976] 0% complete (~715998 KiB/s, ~14840 rec/s, ~49404 B/rec)
2020-04-22 13:26:49 GMT [INF] [11976] ~30m16s remaining
2020-04-22 13:26:59 GMT [ERR] [11979] Running out of disk space, less than 1336250053278 bytes available (299171090432)
2020-04-22 13:26:59 GMT [ERR] [11977] Running out of disk space, less than 1336250053278 bytes available (299171090432)
2020-04-22 13:26:59 GMT [INF] [11977] Created new backup file ./data/BB9AE00F00A0142_00001.asb
2020-04-22 13:26:59 GMT [ERR] [11981] Running out of disk space, less than 1336250053278 bytes available (299171090432)
2020-04-22 13:26:59 GMT [INF] [11981] Created new backup file ./data/BB97E00F00A0142_00001.asb
2020-04-22 13:26:59 GMT [ERR] [11982] Running out of disk space, less than 1336250053278 bytes available (299171090432)
2020-04-22 13:26:59 GMT [INF] [11982] Created new backup file ./data/BB9AF00F00A0142_00001.asb
2020-04-22 13:26:59 GMT [INF] [11979] Created new backup file ./data/BB9A600F00A0142_00001.asb
2020-04-22 13:26:59 GMT [ERR] [11980] Running out of disk space, less than 1336250053278 bytes available (299171090432)
2020-04-22 13:26:59 GMT [INF] [11980] Created new backup file ./data/BB98C00F00A0142_00001.asb
2020-04-22 13:26:59 GMT [ERR] [11978] Running out of disk space, less than 1336250053278 bytes available (299171090432)
2020-04-22 13:26:59 GMT [INF] [11978] Created new backup file ./data/BB9AD00F00A0142_00001.asb
2020-04-22 13:26:59 GMT [INF] [11976] 0% complete (~130194 KiB/s, ~2552 rec/s, ~52240 B/rec)
2020-04-22 13:26:59 GMT [INF] [11976] ~2h55m55s remaining
2020-04-22 13:27:09 GMT [INF] [11976] 0% complete (~0 KiB/s, ~0 rec/s, ~0 B/rec)
2020-04-22 13:27:12 GMT [ERR] [11977] Running out of disk space, less than 1343982117255 bytes available (297598042112)
2020-04-22 13:27:12 GMT [INF] [11977] Created new backup file ./data/BB9AE00F00A0142_00002.asb
2020-04-22 13:27:12 GMT [ERR] [11982] Running out of disk space, less than 1343954759576 bytes available (297598042112)
2020-04-22 13:27:12 GMT [INF] [11982] Created new backup file ./data/BB9AF00F00A0142_00002.asb
2020-04-22 13:27:12 GMT [ERR] [11981] Running out of disk space, less than 1343982117255 bytes available (297598042112)
2020-04-22 13:27:12 GMT [INF] [11981] Created new backup file ./data/BB97E00F00A0142_00002.asb
2020-04-22 13:27:12 GMT [ERR] [11978] Running out of disk space, less than 1344750709680 bytes available (297598042112)
2020-04-22 13:27:12 GMT [INF] [11978] Created new backup file ./data/BB9AD00F00A0142_00002.asb
2020-04-22 13:27:12 GMT [ERR] [11979] Running out of disk space, less than 1344336099310 bytes available (297598042112)
2020-04-22 13:27:12 GMT [INF] [11979] Created new backup file ./data/BB9A600F00A0142_00002.asb
2020-04-22 13:27:12 GMT [ERR] [11980] Running out of disk space, less than 1344141650952 bytes available (297598042112)
2020-04-22 13:27:12 GMT [INF] [11980] Created new backup file ./data/BB98C00F00A0142_00002.asb

...

which were not there before.

I ran the same lines as before with --estimate to see if could see anything and, indeed, for the full backup I get:

2020-04-22 13:55:31 GMT [INF] [13119] Estimated overall record size is 7687 byte(s)

whereas for the incremental, I get:

2020-04-22 13:54:52 GMT [INF] [13075] Estimated overall record size is 45310 byte(s)

So, my questions are:

  1. Am I doing anything wrong here?
  2. If not, how come my incremental backups turn out to be much larger than a full backup? And;
  3. is there anything I can do to make them smaller?

Thanks!

Giuliano

1 Like
2

Any progress on this issue? Would love a response from the Aerospike team.

3

In response we have raised the issue internally to attempt to reproduce.

What happens when you use only --modified-after or only --modified-before?

4

Hi… a few questions:

  • Is it possible for your data set that average record size happens to be bigger during the time range specified?

  • Do you notice any other clues from the backup file records themselves that might indicate a problem, i.e invalid record data that shouldn’t be there? Or do they look valid, i.e larger, but expected values?

  • Can you try to compare the “x byte(s) in total” output value between your estimated incremental backups (the sum if possible) and the full backup?

  • Can you confirm that you start with the same amount of free disk space when you do the full vs incremental backups?

Thanks for reporting the potential issue.