Re: Dar architecture questions

Kevin Wormington <[email protected]> Mon, 15 Oct 2012 17:30:07 -0500
Newsgroups gmane.comp.sysutils.backup.dar.general
Message-ID <[email protected]>
I strace'd the small backup (14k files) both with and without 
--disable-special-alloc and it appears the difference is in the huge 
number of rt_sigprocmask calls made by special-alloc.  Am I correct that 
the amount of memory used by dar is mostly related to the number of 
files backed up and not the sizes of the files backed up?  Ie, I wonder 
if a different workload of small number of large files would be effected 
by the use of special-malloc.   If it could be confirmed that it's a win 
to disable special-malloc I would suggest that you consider disabling it 
by default.  I only have recent ubuntu and debian servers to test with 
so I'm not sure what the result would be on the other flavors of linux 
and/or different os platforms.  Perhaps someone else on the list that 
makes large backups either in size or number of files could confirm if 
they see the same behavior.

run with --disable-special-alloc:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  71.72    0.000208           0     14067           lstat
  19.31    0.000056           0      2679           read
   8.97    0.000026           0      1053           lseek
   0.00    0.000000           0       216           write
   0.00    0.000000           0       440        28 open
   0.00    0.000000           0       412           close
   0.00    0.000000           0       409           fstat
   0.00    0.000000           0        48           mmap
   0.00    0.000000           0        26           mprotect
   0.00    0.000000           0         9           munmap
   0.00    0.000000           0       208           brk
   0.00    0.000000           0         9           rt_sigaction
   0.00    0.000000           0        47           rt_sigprocmask
   0.00    0.000000           0        10           ioctl
   0.00    0.000000           0        15        15 access
   0.00    0.000000           0         1           nanosleep
   0.00    0.000000           0         1           execve
   0.00    0.000000           0       775           fcntl
   0.00    0.000000           0       800           getdents
   0.00    0.000000           0         8           getcwd
   0.00    0.000000           0         1           getrlimit
   0.00    0.000000           0         5           getuid
   0.00    0.000000           0         1           getppid
   0.00    0.000000           0         1           mlock
   0.00    0.000000           0         1           arch_prctl
   0.00    0.000000           0         5         1 futex
   0.00    0.000000           0         1           set_tid_address
   0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.000290                 21249        44 total

Here is the same set using special-alloc:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  96.79    0.032938           0   1622329           rt_sigprocmask
   2.80    0.000953           0     14066           lstat
   0.20    0.000067           0      2679           read
   0.15    0.000051           0       800           getdents
   0.06    0.000021           0      1053           lseek
   0.00    0.000000           0       216           write
   0.00    0.000000           0       440        28 open
   0.00    0.000000           0       412           close
   0.00    0.000000           0       409           fstat
   0.00    0.000000           0        48           mmap
   0.00    0.000000           0        26           mprotect
   0.00    0.000000           0         9           munmap
   0.00    0.000000           0       140           brk
   0.00    0.000000           0         9           rt_sigaction
   0.00    0.000000           0        10           ioctl
   0.00    0.000000           0        15        15 access
   0.00    0.000000           0         1           nanosleep
   0.00    0.000000           0         1           execve
   0.00    0.000000           0       775           fcntl
   0.00    0.000000           0         8           getcwd
   0.00    0.000000           0         1           getrlimit
   0.00    0.000000           0         5           getuid
   0.00    0.000000           0         1           getppid
   0.00    0.000000           0         1           mlock
   0.00    0.000000           0         1           arch_prctl
   0.00    0.000000           0         5         1 futex
   0.00    0.000000           0         1           set_tid_address
   0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.034030               1643462        44 total

On 10/15/2012 04:36 PM, Kevin Wormington wrote:
>
>
> On 10/15/2012 02:21 PM, Denis Corbin wrote:
>> -----BEGIN PGP SIGNED MESSAGE-----
>> Hash: SHA1
>>
>> On 14/10/2012 22:37, Kevin Wormington wrote:
>>> Dennis,
>>>
>>> Thank you for the detailed reply.  I have done some more testing and you
>>> are correct that memory deallocation consumes a considerable amount of
>>> time after the stats are displayed.  I re-configured with
>>> --disable-special-alloc and the results (below) are quite dramatic.
>>> There was a ~600MB increase in memory usage but the execution time is
>>> down to less than 10 minutes.
>>
>> Well I'm surprised by this result. The objective was rather to speedup
>> the memory allocation than to reducing its usage! When it had been
>> implemented, it did reduce execution time on the available systems...
>>
>
> I re-ran my full backup and it ran in 7.9 hours with special-alloc
> disabled so there was a gain of about 20% vs the 10 hours it took before.
>
> I also ran a small backup (1.2GB, 14,000 files; ran each twice and used
> the lowest number always from the 2nd run where everything was likely in
> read cache) with the results:
>
> 		special-alloc		disable-special-alloc
> full		1 min 53 secs		1 min 53 secs
> incremental	3.329 secs		2.925 secs
>
> So the smaller backup is about even between the two.
>
> I'm going to try and fire it up in gdb and see if I can catch it in the
> deletes.  I speculate that the standard library version is make a single
> (or very few) calls to free() when it sees that the entire object is
> being deleted.
>
> Kevin
>
>>>    It appears that memory allocation must be
>>> playing a significant part in the total backup time as well.  I am going
>>> to re-run the full backup and see what kind of improvement is has as
>>> well.  Hopefully I will also get a chance in the next few days to see if
>>> I can determine what it is about the special_alloc that causes the
>>> slowdown vs system libraries at least for my use case.
>>
>> I will double check on my side using a gprof. Thanks for your feedbacks!
>>
>>>
>>> Kevin
>>>
>>
>> Regards,
>> Denis.
>>
>>
>> -----BEGIN PGP SIGNATURE-----
>> Version: GnuPG v1.4.10 (GNU/Linux)
>> Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
>>
>> iQIVAwUBUHxiQAgxsL0D2LGCAQKJeg/6AyoSxurS3E+olrYjqjjOQBS1mywXz6Cs
>> EC5Dv3vvO7xo4r8WYx/dT5IjMG7FUmRLTTYedtEiR3cp+TFokcQ4cjk9voN4EjVv
>> 27rzXLvAn5d/9kv5a4QEGWYnp4RH3R/ybcWXdAlk2RVnAqJikgwtLi/otI1X1Ayg
>> Sv100cbw+nBTwuK60ZqjAY1pXYXC4vQ03ZGRmY9XfvXZ/Eo6e7Shcy3dY+k6aPjB
>> LP33BarjiACsbtaI88pSv+9shdOqvpqJOrzEzXFYxzbpz9McKgirRaYhCz12SDFM
>> IBUV+8iyvdclLLfizW08SyKl7348xCYF2FkikzhlSBrE5qdMqDSvo+7FU5CuSRWV
>> 445YrgdP2Fs7UU+ed1T5irRchlsaWgLelVTepqvRF6bqr8y1OWPg3ZxnNSAcGjPy
>> UvnCLDr6OFuM94Wml9KRQCLWYyW8UlFB6Lpezo/CXL/hlUIkcJGiu8jZfHr6x+00
>> 0VcRMAdEx+JrOSgxysWsgm2mb+XQQICVSk3n41HUhf7C/QzmQvuKM/fd1axmeacJ
>> axDXt+r1mH0pGXjwob/08Nwr67kNmefHIbiqiUePjydIaWXeJYeP0AGbixkujxui
>> JZWlz9hCRUuapa3pxpOf5DHGj5Y0SzB9u+4ko/KYzGElrPMwtpLWKTUcuUOD7KZE
>> zZpnOPWYQoQ=
>> =58FQ
>> -----END PGP SIGNATURE-----
>>
>> ------------------------------------------------------------------------------
>> Don't let slow site performance ruin your business. Deploy New Relic APM
>> Deploy New Relic app performance management and know exactly
>> what is happening inside your Ruby, Python, PHP, Java, and .NET app
>> Try New Relic at no cost today and get our sweet Data Nerd shirt too!
>> http://p.sf.net/sfu/newrelic-dev2dev
>> _______________________________________________
>> Dar-discussions mailing list
>> Dar-discussions-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org
>> https://lists.sourceforge.net/lists/listinfo/dar-discussions
>>
>
> ------------------------------------------------------------------------------
> Don't let slow site performance ruin your business. Deploy New Relic APM
> Deploy New Relic app performance management and know exactly
> what is happening inside your Ruby, Python, PHP, Java, and .NET app
> Try New Relic at no cost today and get our sweet Data Nerd shirt too!
> http://p.sf.net/sfu/newrelic-dev2dev
> _______________________________________________
> Dar-discussions mailing list
> Dar-discussions-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org
> https://lists.sourceforge.net/lists/listinfo/dar-discussions
>

------------------------------------------------------------------------------
Don't let slow site performance ruin your business. Deploy New Relic APM
Deploy New Relic app performance management and know exactly
what is happening inside your Ruby, Python, PHP, Java, and .NET app
Try New Relic at no cost today and get our sweet Data Nerd shirt too!
http://p.sf.net/sfu/newrelic-dev2dev