Killed process / not used / written incomplete file

Support
#1

Hi all,

my first post, first let me thank you for this genius piece of software, thanks.

Please describe what you are doing to trigger the bug:

initial (crypted) backup of 6TB. duplicacy got killed after 2-3 days runtime (local HDD backup).

/var/log/messages logged: "perf: interrupt took too long (3938 > 3937)

Please describe what you expect to happen (but doesn’t):

After restarting the backup it was not resumed, despite of an existing incomplete file.
ls .duplicacy/cache/default/

-rw------- 1 root root 2.4G May 12 19:47 incomplete_files

But I don’t know if it was there when I restarted the backup. The restarted backup is running and now the file is there.

Please describe what actually happens (the wrong behaviour):
Maybe the incomplete file could be written every x minutes in order to get it written if duplicacy gets killed.

I do not know the reason why duplicacy got killed, yet.

var/log/messages:

May 12 16:22:12 pve kernel: [334711.716011] duplicacy_linux invoked oom-killer: gfp_mask=0x1100dca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), order=0, oom_score_adj=0
May 12 16:22:12 pve kernel: [334711.716020] CPU: 1 PID: 2513679 Comm: duplicacy_linux Tainted: P           O      5.15.149-1-pve #1
May 12 16:22:12 pve kernel: [334711.716024] Hardware name: FUJITSU /D3644-B1, BIOS V5.0.0.13 R1.26.0 for D3644-B1x                    03/08/2021
May 12 16:22:12 pve kernel: [334711.716027] Call Trace:
May 12 16:22:12 pve kernel: [334711.716029]  <TASK>
May 12 16:22:12 pve kernel: [334711.716031]  dump_stack_lvl+0x4a/0x63
May 12 16:22:12 pve kernel: [334711.716036]  dump_stack+0x10/0x16
May 12 16:22:12 pve kernel: [334711.716039]  dump_header+0x53/0x225
May 12 16:22:12 pve kernel: [334711.716042]  oom_kill_process.cold+0xb/0x10
May 12 16:22:12 pve kernel: [334711.716046]  out_of_memory+0x1dc/0x530
May 12 16:22:12 pve kernel: [334711.716050]  __alloc_pages_slowpath.constprop.0+0xd68/0xe80
May 12 16:22:12 pve kernel: [334711.716054]  ? mntput+0x24/0x40
May 12 16:22:12 pve kernel: [334711.716059]  __alloc_pages+0x30c/0x320
May 12 16:22:12 pve kernel: [334711.716062]  alloc_pages_vma+0x9d/0x380
May 12 16:22:12 pve kernel: [334711.716066]  __handle_mm_fault+0xb4b/0x1610
May 12 16:22:12 pve kernel: [334711.716070]  handle_mm_fault+0xd8/0x2c0
May 12 16:22:12 pve kernel: [334711.716072]  do_user_addr_fault+0x1c2/0x660
May 12 16:22:12 pve kernel: [334711.716076]  ? exit_to_user_mode_prepare+0x37/0x1b0
May 12 16:22:12 pve kernel: [334711.716080]  exc_page_fault+0x77/0x170
May 12 16:22:12 pve kernel: [334711.716084]  asm_exc_page_fault+0x27/0x30
May 12 16:22:12 pve kernel: [334711.716087] RIP: 0033:0x46cb99
May 12 16:22:12 pve kernel: [334711.716092] Code: Unable to access opcode bytes at RIP 0x46cb6f.
May 12 16:22:12 pve kernel: [334711.716094] RSP: 002b:000000c087e21570 EFLAGS: 00010246
May 12 16:22:12 pve kernel: [334711.716097] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000002800
May 12 16:22:12 pve kernel: [334711.716100] RDX: 0000000000000001 RSI: 0000000000040000 RDI: 000000c1af982000
May 12 16:22:12 pve kernel: [334711.716102] RBP: 000000c087e21598 R08: 0000000000000001 R09: 0000000000000000
May 12 16:22:12 pve kernel: [334711.716105] R10: 0000000000000001 R11: 00007fc31efdad60 R12: 000000000046be41
May 12 16:22:12 pve kernel: [334711.716107] R13: 000000000046be41 R14: 000000c0004931e0 R15: 0000000000000000
May 12 16:22:12 pve kernel: [334711.716111]  </TASK>
May 12 16:22:12 pve kernel: [334711.716112] Mem-Info:
May 12 16:22:12 pve kernel: [334711.716114] active_anon:217 inactive_anon:1788495 isolated_anon:0
May 12 16:22:12 pve kernel: [334711.716114]  active_file:184 inactive_file:183 isolated_file:0
May 12 16:22:12 pve kernel: [334711.716114]  unevictable:3034 dirty:0 writeback:3
May 12 16:22:12 pve kernel: [334711.716114]  slab_reclaimable:6295 slab_unreclaimable:1060017
May 12 16:22:12 pve kernel: [334711.716114]  mapped:6832 shmem:4238 pagetables:5580 bounce:0
May 12 16:22:12 pve kernel: [334711.716114]  kernel_misc_reclaimable:0
May 12 16:22:12 pve kernel: [334711.716114]  free:55562 free_pcp:296 free_cma:0
May 12 16:22:12 pve kernel: [334711.716124] Node 0 active_anon:868kB inactive_anon:7153980kB active_file:736kB inactive_file:732kB unevictable:12136kB isolated(anon):0kB isolated(file):0kB mapped:27328kB dirty:0kB writeback:12kB shmem:16952kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 1120256kB writeback_tmp:0kB kernel_stack:4680kB pagetables:22320kB all_unreclaimable? no
May 12 16:22:12 pve kernel: [334711.716132] Node 0 DMA free:13312kB min:64kB low:80kB high:96kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15360kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
May 12 16:22:12 pve kernel: [334711.716141] lowmem_reserve[]: 0 1961 15679 15679 15679
May 12 16:22:12 pve kernel: [334711.716145] Node 0 DMA32 free:60532kB min:8444kB low:10552kB high:12660kB reserved_highatomic:0KB active_anon:0kB inactive_anon:1630820kB active_file:44kB inactive_file:612kB unevictable:0kB writepending:0kB present:2135312kB managed:2069644kB mlocked:0kB bounce:0kB free_pcp:256kB local_pcp:256kB free_cma:0kB
May 12 16:22:12 pve kernel: [334711.716153] lowmem_reserve[]: 0 0 13718 13718 13718
May 12 16:22:12 pve kernel: [334711.716156] Node 0 Normal free:148404kB min:188092kB low:202856kB high:217620kB reserved_highatomic:2048KB active_anon:868kB inactive_anon:5523368kB active_file:456kB inactive_file:1804kB unevictable:12136kB writepending:12kB present:14393344kB managed:14056652kB mlocked:12012kB bounce:0kB free_pcp:936kB local_pcp:896kB free_cma:0kB
May 12 16:22:12 pve kernel: [334711.716165] lowmem_reserve[]: 0 0 0 0 0
May 12 16:22:12 pve kernel: [334711.716168] Node 0 DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 1*1024kB (U) 2*2048kB (UM) 2*4096kB (M) = 13312kB
May 12 16:22:12 pve kernel: [334711.716179] Node 0 DMA32: 155*4kB (UM) 81*8kB (UM) 45*16kB (UM) 8*32kB (ME) 3*64kB (UM) 6*128kB (UM) 1*256kB (U) 1*512kB (U) 56*1024kB (U) 0*2048kB 0*4096kB = 61316kB
May 12 16:22:12 pve kernel: [334711.716192] Node 0 Normal: 7782*4kB (UMH) 3026*8kB (UMEH) 4722*16kB (UMEH) 21*32kB (UMH) 18*64kB (UMH) 128*128kB (U) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 149096kB
May 12 16:22:12 pve kernel: [334711.716204] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
May 12 16:22:12 pve kernel: [334711.716207] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
May 12 16:22:12 pve kernel: [334711.716210] 7116 total pagecache pages
May 12 16:22:12 pve kernel: [334711.716212] 0 pages in swap cache
May 12 16:22:12 pve kernel: [334711.716214] Swap cache stats: add 0, delete 0, find 0/0
May 12 16:22:12 pve kernel: [334711.716216] Free swap  = 0kB
May 12 16:22:12 pve kernel: [334711.716217] Total swap = 0kB
May 12 16:22:12 pve kernel: [334711.716218] 4136162 pages RAM
May 12 16:22:12 pve kernel: [334711.716220] 0 pages HighMem/MovableOnly
May 12 16:22:12 pve kernel: [334711.716221] 100748 pages reserved
May 12 16:22:12 pve kernel: [334711.716222] 0 pages hwpoisoned
May 12 16:22:12 pve kernel: [334711.716224] Tasks state (memory values in pages):
May 12 16:22:12 pve kernel: [334711.716225] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
May 12 16:22:12 pve kernel: [334711.716232] [   1342]     0  1342    16199      727   126976        0          -250 systemd-journal
May 12 16:22:12 pve kernel: [334711.716237] [   1491]     0  1491     5814      965    69632        0         -1000 systemd-udevd
May 12 16:22:12 pve kernel: [334711.716241] [   3802]   103  3802     1975      461    53248        0             0 rpcbind
May 12 16:22:12 pve kernel: [334711.716244] [   3834]   102  3834     2068      571    53248        0          -900 dbus-daemon
May 12 16:22:12 pve kernel: [334711.716248] [   3837]     0  3837    37752      269    57344        0         -1000 lxcfs
May 12 16:22:12 pve kernel: [334711.716251] [   3843]     0  3843    69589      380    77824        0             0 pve-lxc-syscall
May 12 16:22:12 pve kernel: [334711.716255] [   3845]     0  3845    55199      765    81920        0             0 rsyslogd
May 12 16:22:12 pve kernel: [334711.716258] [   3850]     0  3850     3032      892    65536        0             0 smartd
May 12 16:22:12 pve kernel: [334711.716261] [   3851]     0  3851     5520      715    69632        0             0 systemd-logind
May 12 16:22:12 pve kernel: [334711.716264] [   3853]     0  3853    59448      862    77824        0             0 zed
May 12 16:22:12 pve kernel: [334711.716267] [   3861]     0  3861     1757      337    49152        0             0 ksmtuned
May 12 16:22:12 pve kernel: [334711.716270] [   3896]     0  3896     1069       33    45056        0             0 qmeventd
May 12 16:22:12 pve kernel: [334711.716274] [   4420]     0  4420     2081      377    49152        0             0 lxc-monitord
May 12 16:22:12 pve kernel: [334711.716277] [   4510]     0  4510     3338      923    61440        0         -1000 sshd
May 12 16:22:12 pve kernel: [334711.716281] [   4514]     0  4514     2887      133    65536        0             0 iscsid
May 12 16:22:12 pve kernel: [334711.716284] [   4515]     0  4515     3013     2967    69632        0           -17 iscsid
May 12 16:22:12 pve kernel: [334711.716287] [   4652]     0  4652     1461      390    45056        0             0 agetty
May 12 16:22:12 pve kernel: [334711.716290] [   4691]   101  4691     4758      573    53248        0             0 chronyd
May 12 16:22:12 pve kernel: [334711.716294] [   4695]   101  4695     2710      522    53248        0             0 chronyd
May 12 16:22:12 pve kernel: [334711.716297] [   4816]     0  4816    10013      585    73728        0             0 master
May 12 16:22:12 pve kernel: [334711.716300] [   4818]   106  4818    10089      532    77824        0             0 qmgr
May 12 16:22:12 pve kernel: [334711.716303] [   5033]     0  5033   126433      606   155648        0             0 rrdcached
May 12 16:22:12 pve kernel: [334711.716306] [   5107]     0  5107   152936     5659   258048        0             0 pmxcfs
May 12 16:22:12 pve kernel: [334711.716310] [   5184]     0  5184     1686      558    49152        0             0 cron
May 12 16:22:12 pve kernel: [334711.716313] [   5819]     0  5819    69622    22928   286720        0             0 pve-firewall
May 12 16:22:12 pve kernel: [334711.716316] [   5843]     0  5843      591      124    49152        0             0 bpfilter_umh
May 12 16:22:12 pve kernel: [334711.716319] [   5852]     0  5852    68323    21835   294912        0             0 pvestatd
May 12 16:22:12 pve kernel: [334711.716322] [   6242]     0  6242    87889    31248   409600        0             0 pvedaemon
May 12 16:22:12 pve kernel: [334711.716326] [   6243]     0  6243    87955    31565   409600        0             0 pvedaemon worke
May 12 16:22:12 pve kernel: [334711.716329] [   6244]     0  6244    87955    31559   409600        0             0 pvedaemon worke
May 12 16:22:12 pve kernel: [334711.716333] [   6245]     0  6245    87955    31571   409600        0             0 pvedaemon worke
May 12 16:22:12 pve kernel: [334711.716336] [   6434]    33  6434    88281    31861   409600        0             0 pveproxy
May 12 16:22:12 pve kernel: [334711.716339] [   6435]    33  6435    88345    32465   413696        0             0 pveproxy worker
May 12 16:22:12 pve kernel: [334711.716343] [   6436]    33  6436    88345    32231   413696        0             0 pveproxy worker
May 12 16:22:12 pve kernel: [334711.716346] [   6437]    33  6437    88345    32449   413696        0             0 pveproxy worker
May 12 16:22:12 pve kernel: [334711.716349] [   6472]    33  6472    19251    12604   184320        0             0 spiceproxy
May 12 16:22:12 pve kernel: [334711.716352] [   6473]    33  6473    19314    12587   184320        0             0 spiceproxy work
May 12 16:22:12 pve kernel: [334711.716355] [   6647]     0  6647    83580    26074   356352        0             0 pvescheduler
May 12 16:22:12 pve kernel: [334711.716361] [3433694]     0 3433694     4123     1369    69632        0             0 systemd
May 12 16:22:12 pve kernel: [334711.716364] [3433695]     0 3433695    41956      911   102400        0             0 (sd-pam)
May 12 16:22:12 pve kernel: [334711.716367] [3655635]     0 3655635     1822      530    53248        0             0 screen
May 12 16:22:12 pve kernel: [334711.716370] [3655636]     0 3655636     1816      572    53248        0             0 bash
May 12 16:22:12 pve kernel: [334711.716374] [2513673]     0 2513673  2202850  1609268 16441344        0             0 duplicacy_linux
May 12 16:22:12 pve kernel: [334711.716377] [1021054]     0 1021054    20052      341    57344        0             0 pvefw-logger
May 12 16:22:12 pve kernel: [334711.716381] [3452780]   106 3452780    10077      606    69632        0             0 pickup
May 12 16:22:12 pve kernel: [334711.716384] [  40694]     0 40694     1341      106    49152        0             0 sleep
May 12 16:22:12 pve kernel: [334711.716387] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=user.slice,mems_allowed=0,global_oom,task_memcg=/user.slice/user-0.slice/session-131.scope,task=duplicacy_linux,pid=2513673,uid=0
Periodically save “incomplete_chunks” during backup
#2

Duplicacy was killed by oom-killer.

How many flies are in the backup set and how much free ram is there? What is duplicacy version?

#3

Hi,
the number of files in the backup set is 10 million:
find backupdir/ -type f | wc -l
9989209

/root/duplicacy_linux_x64_3.2.3
VERSION: 3.2.3 (254953)

ps aux | grep dup
root 73655 52.7 21.3 5292600 3445720 pts/1 Sl+ May12 465:44 /root/duplicacy_linux_x64_3.2.3 backup -stats -t von_bckserver_ohne_snapshot -threads 2

Ram 16GB (now running and skipping):
cat /proc/meminfo

MemTotal: 16141656 kB
MemFree: 5435780 kB
MemAvailable: 5298616 kB
Buffers: 0 kB
Cached: 41960 kB
SwapCached: 0 kB
Active: 9908 kB
Inactive: 4245244 kB
Active(anon): 916 kB
Inactive(anon): 4239572 kB

Now duplicacy is still running (since 12h) and has 1day 11h left at percentage: 28%. It is still skipping all files, because the chunk is there from the interrupted initial backup.

[EDIT]
Do you know how duplicacy writes chunks? Is it safe to be killed during writing a chunk? Say it would not to be save, to create the file with the correct hash-filename and then the content. it must be written and afterword moved or renamed, to only get a valid filename after the content got written without interruption (?)

[EDIT] ->>>> I see you do the rename approach (found lyqkrwes.tmp) I am glad to see this. duplicacy really is a star in the backup world.

Thanks

lopiuh

#4

Ok, I did a Ctrl-C in order to set a “savepoint” and yes now, but only after CTRL-C, the file “incomplete_chunks” got written. So it would be a nice feature to update this file every x minutes.

What I see is that this file (incomplete_chunks) is not a temporary file during the write process and then renamed. What does happen, if during writing this file the process dies and can’t finish its writing? It runs several minutes on my system.
The file “incomplete_snapshot” was not touched during this process… so the message “Incomplete snapshot saved to /DIR/.duplicacy/cache/default/incomplete_snapshot” is a little bit unprecise isn’t it? (as incomplete_chunks got updated)

-rw------- 1 root root 2.2G May 13 15:08 incomplete_chunks
-rw------- 1 root root 2.4G May 12 19:47 incomplete_snapshot

Yours lopiuh