Re: [Duplicity-talk] What is Duplicity doing during incremental backup?

[Nicholas Sherlock]

Thanks for the link!

I switched to a larger machine so it shouldn't run out of memory, and
it still does this odd 100% CPU thing (64-bit, 7.6GB of RAM and dual
core, Duplicity is currently using 1.5GB virt memory and 100% CPU).
Here's the output from strace:

mremap(0x7f53bf75a000, 324427776, 324431872, MREMAP_MAYMOVE) = 0x7f5401312000
mremap(0x7f5401312000, 324431872, 324435968, MREMAP_MAYMOVE) = 0x7f53bf758000
mremap(0x7f53bf758000, 324435968, 324440064, MREMAP_MAYMOVE) = 0x7f5401310000
mremap(0x7f5401310000, 324440064, 324444160, MREMAP_MAYMOVE) = 0x7f53bf756000
mremap(0x7f53bf756000, 324444160, 324448256, MREMAP_MAYMOVE) = 0x7f540130e000
mremap(0x7f540130e000, 324448256, 324452352, MREMAP_MAYMOVE) = 0x7f53bf754000
mremap(0x7f53bf754000, 324452352, 324456448, MREMAP_MAYMOVE) = 0x7f540130c000
mremap(0x7f540130c000, 324456448, 324460544, MREMAP_MAYMOVE) = 0x7f53bf752000
mremap(0x7f53bf752000, 324460544, 324464640, MREMAP_MAYMOVE) = 0x7f540130a000
mremap(0x7f540130a000, 324464640, 324468736, MREMAP_MAYMOVE) = 0x7f53bf750000
mremap(0x7f53bf750000, 324468736, 324472832, MREMAP_MAYMOVE) = 0x7f5401308000
mremap(0x7f5401308000, 324472832, 324476928, MREMAP_MAYMOVE) = 0x7f53bf74e000
mremap(0x7f53bf74e000, 324476928, 324481024, MREMAP_MAYMOVE) = 0x7f5401306000
mremap(0x7f5401306000, 324481024, 324485120, MREMAP_MAYMOVE) = 0x7f53bf74c000
mremap(0x7f53bf74c000, 324485120, 324489216, MREMAP_MAYMOVE) = 0x7f5401304000
mremap(0x7f5401304000, 324489216, 324493312, MREMAP_MAYMOVE) = 0x7f53bf74a000

Duplicity seems to be slowly increasing the size of a memory mapping
(4K at a time)? Basically it looks like it's slowly appending to some
datastructure. Here's the (pretty gnarly) stacktrace:

#0  0x00007f543a19e0ba in mremap () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007f543a134755 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x00007f543a138f6b in realloc () from /lib/x86_64-linux-gnu/libc.so.6
#3  0x00007f5438f21210 in ?? () from /usr/lib/librsync.so.1
#4  0x00007f5438f1f9ec in rs_job_iter () from /usr/lib/librsync.so.1
#5  0x00007f543912a6c3 in ?? ()
   from /usr/lib/python2.7/dist-packages/duplicity/_librsync.so
#6  0x00000000004b6569 in call_function (oparg=<optimized out>,
pp_stack=0x7fff765947a0)
    at ../Python/ceval.c:4021
#7  PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>)
    at ../Python/ceval.c:2666
#8  0x00000000004bcd2d in PyEval_EvalCodeEx (co=0xbf3d30,
globals=<optimized out>,
    locals=<optimized out>, args=<optimized out>, argcount=<optimized out>,
    kws=<optimized out>, kwcount=0, defs=0x0, defcount=0, closure=0x0)
    at ../Python/ceval.c:3253
#9  0x0000000000448edf in function_call (func=<function at remote
0xc020c8>, arg=
    (<DeltaFile(outbuf=<array.array at remote 0xfe4ea0>,
infile_eof=None, infile_closed=None, closed=None, eof=None,
infile=<FileWithSignature(extra_args=(), callback=<function at remote
0x108b410>, activated_callback=None, sig_gen=<SigGenerator(buffer='',
gotsig=None, sigstring_list=[], sig_maker=<sigmaker at remote
0x109e9d0>) at remote 0x1084d40>,
infile=<FileWithReadCounter(infile=<file at remote 0xfd7810>) at
remote 0x1091bd8>) at remote 0x10844d0>, inbuf='') at remote
0x10849e0>, <_FileObject(name='signature/lib/mysql/ibdata1',
read=<instancemethod at remote 0x10a5fa0>,
tarfile=<TarFile(name='Arbitrary Name', _mode='r',
next_chunk=566431232L, mode=1,
fileobj=<GzipFile(decompress=<zlib.Decompress at remote 0xfb1918>,
extrasize=1899508L,
extrabuf='rs\x016\x00\x00\x08\x00\x00\x00\x00\x08\x84\xdb\xbd\xbdgY2S\xf1T\x1dd\x1d\x16\xd4v\xbd\xc2\x89\xc1^\x93\xfa\xa2\xa1J\xde|\x89M\x0b;9\xd7.\xb3|\xc5\xe6g\xfa\x91\xcbsBK\xe8\x02\xd4\xb3\xddTg.F\x14\x8d\xb11\xc8Z\x120\xd3>\xff}N\xe7\x81\x10m|\x00\xf8\x00\xe7\xb9\xe6\xb0...(truncated),
kw=0x0) at ../Objects/funcobject.c:526
#10 0x000000000041ad2a in PyObject_Call (func=<function at remote 0xc020c8>,
    arg=<optimized out>, kw=<optimized out>) at ../Objects/abstract.c:2529
#11 0x000000000043074e in instancemethod_call (func=<function at
remote 0xc020c8>, arg=
    (<DeltaFile(outbuf=<array.array at remote 0xfe4ea0>,
infile_eof=None, infile_closed=None, closed=None, eof=None,
infile=<FileWithSignature(extra_args=(), callback=<function at remote
0x108b410>, activated_callback=None, sig_gen=<SigGenerator(buffer='',
gotsig=None, sigstring_list=[], sig_maker=<sigmaker at remote
0x109e9d0>) at remote 0x1084d40>,
infile=<FileWithReadCounter(infile=<file at remote 0xfd7810>) at
remote 0x1091bd8>) at remote 0x10844d0>, inbuf='') at remote
0x10849e0>, <_FileObject(name='signature/lib/mysql/ibdata1',
read=<instancemethod at remote 0x10a5fa0>,
tarfile=<TarFile(name='Arbitrary Name', _mode='r',
next_chunk=566431232L, mode=1,
fileobj=<GzipFile(decompress=<zlib.Decompress at remote 0xfb1918>,
extrasize=1899508L,
extrabuf='rs\x016\x00\x00\x08\x00\x00\x00\x00\x08\x84\xdb\xbd\xbdgY2S\xf1T\x1dd\x1d\x16\xd4v\xbd\xc2\x89\xc1^\x93\xfa\xa2\xa1J\xde|\x89M\x0b;9\xd7.\xb3|\xc5\xe6g\xfa\x91\xcbsBK\xe8\x02\xd4\xb3\xddTg.F\x14\x8d\xb11\xc8Z\x120\xd3>\xff}N\xe7\x81\x10m|\x00\xf8\x00\xe7\xb9\xe6\xb0...(truncated),
kw=0x0) at ../Objects/classobject.c:2578
#12 0x000000000041ad2a in PyObject_Call (func=<instancemethod at
remote 0x1083410>,
    arg=<optimized out>, kw=<optimized out>) at ../Objects/abstract.c:2529
#13 0x00000000004b5d76 in PyEval_CallObjectWithKeywords (func=
    <instancemethod at remote 0x1083410>, arg=
    (<_FileObject(name='signature/lib/mysql/ibdata1',
read=<instancemethod at remote 0x10a5fa0>,
tarfile=<TarFile(name='Arbitrary Name', _mode='r',
next_chunk=566431232L, mode=1,
fileobj=<GzipFile(decompress=<zlib.Decompress at remote 0xfb1918>,
extrasize=1899508L,
extrabuf='rs\x016\x00\x00\x08\x00\x00\x00\x00\x08\x84\xdb\xbd\xbdgY2S\xf1T\x1dd\x1d\x16\xd4v\xbd\xc2\x89\xc1^\x93\xfa\xa2\xa1J\xde|\x89M\x0b;9\xd7.\xb3|\xc5\xe6g\xfa\x91\xcbsBK\xe8\x02\xd4\xb3\xddTg.F\x14\x8d\xb11\xc8Z\x120\xd3>\xff}N\xe7\x81\x10m|\x00\xf8\x00\xe7\xb9\xe6\xb0\xe2EN
\x8b 
\xfb$\xac1>\xbb\xf2\xb9U?W\xed\x15\xe4\xf1\xd0\xae\xec\xaa\xb4\xb0\xff\xf5e.6\x90%(\n\x1b3\xe4\x94A)"T\xe7\x06\xfc>\xf8\x0f"\x07\xf1\x02A\x9e`V!3\x12\x17l\x0c\xbd\x80\x08F{\xe5\xb7\xe9\xc6\x05\x15D|\x00\xf8\x00\xe7\xb9\xe6\xb0\xe2EN
|\x00\xf8\x00\xe7\xb9\xe6\xb0\xe2EN
\x86\xb4\xfa\xac\xe4#e\xff\x15\xcc=\xa2\x08}\xe1\x16\x97\x00Q\x1e=\xee\xa5\xa4\x135\xbaQ1\x8e\x05\x86r|5G\x11$Z\xbaW\xbf\xb8k\xa3\xeb\xfa\x83\xdf!?d\x9b\t\xc2\xf4\xb4\x1a\x02n\x8b\xd5\x89\xad\x95\xdf\xd4V*...(truncated),
kw=<optimized out>) at ../Python/ceval.c:3890
#14 0x00000000004349bc in PyInstance_New (klass=<optimized out>, arg=
    (<_FileObject(name='signature/lib/mysql/ibdata1',
read=<instancemethod at remote 0x10a5fa0>,
tarfile=<TarFile(name='Arbitrary Name', _mode='r',
next_chunk=566431232L, mode=1,
fileobj=<GzipFile(decompress=<zlib.Decompress at remote 0xfb1918>,
extrasize=1899508L,
extrabuf='rs\x016\x00\x00\x08\x00\x00\x00\x00\x08\x84\xdb\xbd\xbdgY2S\xf1T\x1dd\x1d\x16\xd4v\xbd\xc2\x89\xc1^\x93\xfa\xa2\xa1J\xde|\x89M\x0b;9\xd7.\xb3|\xc5\xe6g\xfa\x91\xcbsBK\xe8\x02\xd4\xb3\xddTg.F\x14\x8d\xb11\xc8Z\x120\xd3>\xff}N\xe7\x81\x10m|\x00\xf8\x00\xe7\xb9\xe6\xb0\xe2EN
\x8b 
\xfb$\xac1>\xbb\xf2\xb9U?W\xed\x15\xe4\xf1\xd0\xae\xec\xaa\xb4\xb0\xff\xf5e.6\x90%(\n\x1b3\xe4\x94A)"T\xe7\x06\xfc>\xf8\x0f"\x07\xf1\x02A\x9e`V!3\x12\x17l\x0c\xbd\x80\x08F{\xe5\xb7\xe9\xc6\x05\x15D|\x00\xf8\x00\xe7\xb9\xe6\xb0\xe2EN
|\x00\xf8\x00\xe7\xb9\xe6\xb0\xe2EN
\x86\xb4\xfa\xac\xe4#e\xff\x15\xcc=\xa2\x08}\xe1\x16\x97\x00Q\x1e=\xee\xa5\xa4\x135\xbaQ1\x8e\x05\x86r|5G\x11$Z\xbaW\xbf\xb8k\xa3\xeb\xfa\x83\xdf!?d\x9b\t\xc2\xf4\xb4\x1a\x02n\x8b\xd5\x89\xad\x95\xdf\xd4V*...(truncated),
kw=0x0) at ../Objects/classobject.c:571
#15 0x000000000041ad2a in PyObject_Call (func=<classobj at remote 0xbefef0>,
    arg=<optimized out>, kw=<optimized out>) at ../Objects/abstract.c:2529
#16 0x00000000004b6b9e in do_call (nk=<optimized out>, na=<optimized
out>, pp_stack=
    0x7fff76594d70, func=<classobj at remote 0xbefef0>) at
../Python/ceval.c:4239
#17 call_function (oparg=<optimized out>, pp_stack=0x7fff76594d70)
    at ../Python/ceval.c:4044
#18 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>)
    at ../Python/ceval.c:2666
#19 0x00000000004bd325 in PyEval_EvalCodeEx (co=0xd17230,
globals=<optimized out>,
    locals=<optimized out>, args=<optimized out>, argcount=<optimized out>,
    kws=<optimized out>, kwcount=0, defs=0xd21c68, defcount=1, closure=0x0)
    at ../Python/ceval.c:3253
#20 0x0000000000448edf in function_call (func=<function at remote
0xd29578>, arg=
    (<Path(index=('lib', 'mysql', 'ibdata1'), stat=<posix.stat_result
at remote 0xfb1a48>, opened=None, base='/db', mode=416, fileobj=None,
type='reg', name='/db/lib/mysql/ibdata1') at remote 0x1091488>,
<ROPath(index=('lib', 'mysql', 'ibdata1'),
stat=<StatResult(st_uid=106, ---Type <return> to continue, or q
<return> to quit---
st_mtime=1329804914, st_size=564811788L, st_gid=114) at remote
0xfd4bd8>, opened=1, devnums=None, difftype='signature', mode=416,
fileobj=<_FileObject(name='signature/lib/mysql/ibdata1',
read=<instancemethod at remote 0x10a5fa0>,
tarfile=<TarFile(name='Arbitrary Name', _mode='r',
next_chunk=566431232L, mode=1,
fileobj=<GzipFile(decompress=<zlib.Decompress at remote 0xfb1918>,
extrasize=1899508L,
extrabuf='rs\x016\x00\x00\x08\x00\x00\x00\x00\x08\x84\xdb\xbd\xbdgY2S\xf1T\x1dd\x1d\x16\xd4v\xbd\xc2\x89\xc1^\x93\xfa\xa2\xa1J\xde|\x89M\x0b;9\xd7.\xb3|\xc5\xe6g\xfa\x91\xcbsBK\xe8\x02\xd4\xb3\xddTg.F\x14\x8d\xb11\xc8Z\x120\xd3>\xff}N\xe7\x81\x10m|\x00\xf8\x00\xe7\xb9\xe6\xb0\xe2EN
\x8b 
\xfb$\xac1>\xbb\xf2\xb9U?W\xed\x15\xe4\xf1\xd0\xae\xec\xaa\xb4\xb...(truncated),
kw=0x0) at ../Objects/funcobject.c:526
#21 0x000000000041ad2a in PyObject_Call (func=<function at remote 0xd29578>,
    arg=<optimized out>, kw=<optimized out>) at ../Objects/abstract.c:2529
#22 0x00000000004b84b6 in ext_do_call (nk=0, na=0, flags=<optimized
out>, pp_stack=
    0x7fff76595020, func=<function at remote 0xd29578>) at
../Python/ceval.c:4334
#23 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>)
    at ../Python/ceval.c:2705
#24 0x00000000004bcd2d in PyEval_EvalCodeEx (co=0xc33630,
globals=<optimized out>,
    locals=<optimized out>, args=<optimized out>, argcount=<optimized out>,
    kws=<optimized out>, kwcount=0, defs=0xc05628, defcount=1, closure=0x0)
    at ../Python/ceval.c:3253
#25 0x00000000004b6a5b in fast_function (nk=<optimized out>, na=3,
n=<optimized out>,
    pp_stack=0x7fff76595210, func=<function at remote 0xc36488>) at
../Python/ceval.c:4117
#26 call_function (oparg=<optimized out>, pp_stack=0x7fff76595210)
    at ../Python/ceval.c:4042
#27 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>)
    at ../Python/ceval.c:2666
#28 0x000000000043e1df in gen_send_ex (arg=0x0, exc=<optimized out>,
gen=<optimized out>)
    at ../Objects/genobject.c:84
#29 0x000000000047aee0 in wrap_next (self=<generator at remote 0x10a2d20>,
    args=<optimized out>, wrapped=<optimized out>) at
../Objects/typeobject.c:4650
#30 0x000000000041ad2a in PyObject_Call (func=<method-wrapper at
remote 0x10a4f50>,
    arg=<optimized out>, kw=<optimized out>) at ../Objects/abstract.c:2529
#31 0x00000000004b6b9e in do_call (nk=<optimized out>, na=<optimized
out>, pp_stack=
    0x7fff765953e0, func=<method-wrapper at remote 0x10a4f50>) at
../Python/ceval.c:4239
#32 call_function (oparg=<optimized out>, pp_stack=0x7fff765953e0)
    at ../Python/ceval.c:4044
#33 PyEval_EvalFrameEx (f=<optimized out>, throwflag=<optimized out>)
    at ../Python/ceval.c:2666
#34 0x00000000004bcd2d in PyEval_EvalCodeEx (co=0xd1f1b0,
globals=<optimized out>,
    locals=<optimized out>, args=<optimized out>, argcount=<optimized out>,
    kws=<optimized out>, kwcount=0, defs=0xd21da8, defcount=1, closure=0x0)
    at ../Python/ceval.c:3253
#35 0x00000000004b6a5b in fast_function (nk=<optimized out>, na=2,
n=<optimized out>,
    pp_stack=0x7fff765955d0, func=<function at remote 0xd29ed8>) at
../Python/ceval.c:4117
#36 call_function (oparg=<optimized out>, pp_stack=0x7fff765955d0)

I don't know Python. But it looks like the input blocks from the file
are appended one by one to the end of the SigGenerator class's buffer,
right? And then if there is enough in there to be processed by
librsync signature generator, the head of the buffer is consumed, and
substringed away from the front of the buffer?

It seems that this approach must necessarily incur a huge amount of
memory copying and memory reallocation, and that this useless busywork
is what is consuming 100% of the CPU? Would any Python experts like to
comment? It seems that using something like a circular buffer would
remove the need for all of the memory reallocation operations.

Cheers,
Nicholas Sherlock