Bacula-users

[Bacula-users] bacula-5.2.6 slow full backup of localhost

2014-04-08 10:09:00
Subject: [Bacula-users] bacula-5.2.6 slow full backup of localhost
From: Anthony Jenkins <ajenkins AT vtilt DOT com>
To: bacula-users AT lists.sourceforge DOT net
Date: Tue, 08 Apr 2014 09:33:38 -0400
I've skimmed the archive for hints, but most complain about remote
backups being slow...hopefully I just did something stupid in the config.

I'm getting 1,149,012 Bytes/sec on a full backup of several () GB of
data on the local Linux machine (dir, sd, fd on one host).  This first
attempt at a backup has been running for about 30 hours and has written
~132 GB to a USB 3.0 external drive formatted with EXT4.

> *status storage
> Automatically selected Storage: File
> Connecting to Storage daemon File at 127.0.0.1:9103
>
> venus.vtilt.com-sd Version: 5.2.6 (21 February 2012)
> x86_64-pc-linux-gnu ubuntu 13.10
> Daemon started 07-Apr-14 00:44. Jobs: run=0, running=0.
>  Heap: heap=270,336 smbytes=172,237 max_bytes=237,811 bufs=117
> max_bufs=123
>  Sizes: boffset_t=8 size_t=8 int32_t=4 int64_t=8 mode=0,0
>
> Running Jobs:
> Writing: Full Backup job BackupVenus-Full JobId=13 Volume="20140407"
>     pool="FullPool" device="FileStorage2" (/media/usb2)
>     spooling=0 despooling=0 despool_wait=0
>     Files=2,930,749 Bytes=132,395,015,432 Bytes/sec=1,149,012
>     FDReadSeqNo=25,659,941 in_msg=17673253 out_msg=5 fd=5
> ====

CPU load on the box is negligible (8-core Intel Core i7-4770K @ 350GHz,
16GB RAM).

> root@venus:/home/ajenkins# cat /proc/meminfo
> MemTotal:       16309728 kB
> MemFree:         1115508 kB
> Buffers:         2702536 kB
> Cached:          4711008 kB
> SwapCached:         9768 kB
> Active:          3552560 kB
> Inactive:        4157596 kB
> ...
> root@venus:/home/ajenkins# vmstat
> procs -----------memory---------- ---swap-- -----io---- -system--
> ----cpu----
>  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us
> sy id wa
>  1  2 202440 1137260 2704460 4704228    0    0    49    88    0    1 
> 1  1 97  1
> root@venus:/home/ajenkins# mpstat
> Linux 3.11.0-18-generic (venus.vtilt.com)     04/08/2014    
> _x86_64_    (8 CPU)
>
> 08:56:22 AM  CPU    %usr   %nice    %sys %iowait    %irq   %soft 
> %steal  %guest  %gnice   %idle
> 08:56:22 AM  all    1.25    0.00    0.82    1.21    0.00    0.00   
> 0.00    0.00    0.00   96.71
> root@venus:/home/ajenkins# ps auxww | grep '\(bacula\|mysql\|PID\)' |
> grep -v grep
> USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
> mysql      346  0.1  0.9 681340 150556 ?       Ssl  Mar31  12:42
> /usr/sbin/mysqld
> bacula   20022  0.3  0.0 211132  1636 ?        Ssl  Apr07   6:48
> /usr/sbin/bacula-sd -c /etc/bacula/bacula-sd.conf -u bacula -g disk
> root     20045  0.3  0.0 287516 15340 ?        Ssl  Apr07   6:31
> /usr/sbin/bacula-fd -c /etc/bacula/bacula-fd.conf
> bacula   20066  0.1  0.0 378976  2520 ?        Ssl  Apr07   2:42
> /usr/sbin/bacula-dir -c /etc/bacula/bacula-dir.conf -u bacula -g bacula

The 'Ssl' says the bacula and mysql processes are asleep (at the time of
the ps(1) snapshot).  I did an strace(1) of the 3 bacula processes; the
sd and fd processes were blocked in a select(2) call for a good while
waiting on descriptor 4, which are sockets connected to other bacula
processes it seems:

> root@venus:/home/ajenkins# strace -p20022 -p20045 -p20066 -t 2>&1 |
> tee bacula.strace
> Process 20022 attached
> Process 20045 attached
> Process 20066 attached
> [pid 20022] 09:15:06 select(4, [3], NULL, NULL, NULL <unfinished ...>
> [pid 20066] 09:15:06 restart_syscall(<... resuming interrupted call
> ...> <unfinished ...>
> [pid 20045] 09:15:06 select(4, [3], NULL, NULL, NULL <unfinished ...>
> [pid 20066] 09:16:00 <... restart_syscall resumed> ) = 0
> [pid 20066] 09:16:00 stat("/etc/localtime", {st_mode=S_IFREG|0644,
> st_size=3519, ...}) = 0
> [pid 20066] 09:16:00 stat("/etc/localtime", {st_mode=S_IFREG|0644,
> st_size=3519, ...}) = 0
> ...
> ajenkins@venus:~$ sudo ls -l /proc/20022/fd | grep '\<4\>'
> lrwx------ 1 root root 64 Apr  8 07:39 4 -> socket:[9896449]
> ajenkins@venus:~$ sudo ls -l /proc/20045/fd | grep '\<4\>'
> lrwx------ 1 root root 64 Apr  8 07:39 4 -> socket:[9896450]
> ajenkins@venus:~$ sudo lsof -p 20022 | grep 98964
> bacula-sd 20022 bacula    3u  IPv4 9896420          0t0     TCP
> localhost:bacula-sd (LISTEN)
> bacula-sd 20022 bacula    4u  IPv4 9896449          0t0     TCP
> localhost:bacula-sd->localhost:45075 (ESTABLISHED)
> bacula-sd 20022 bacula    5u  IPv4 9896451          0t0     TCP
> localhost:bacula-sd->localhost:45077 (ESTABLISHED)
> ajenkins@venus:~$ sudo lsof -p 20045 | grep 98964
> bacula-fd 20045 root    3u  IPv4 9896430      0t0      TCP
> localhost:bacula-fd (LISTEN)
> bacula-fd 20045 root    4u  IPv4 9896450      0t0      TCP
> localhost:bacula-fd->localhost:33953 (ESTABLISHED)
> ajenkins@venus:~$ sudo lsof | grep '4507[57]'
> bacula-sd 20022           bacula    4u     IPv4           
> 9896449          0t0        TCP localhost:bacula-sd->localhost:45075
> (ESTABLISHED)
> bacula-sd 20022           bacula    5u     IPv4           
> 9896451          0t0        TCP localhost:bacula-sd->localhost:45077
> (ESTABLISHED)
> bacula-sd 20022 20027     bacula    4u     IPv4           
> 9896449          0t0        TCP localhost:bacula-sd->localhost:45075
> (ESTABLISHED)
> bacula-sd 20022 20027     bacula    5u     IPv4           
> 9896451          0t0        TCP localhost:bacula-sd->localhost:45077
> (ESTABLISHED)
> bacula-sd 20022 20078     bacula    4u     IPv4           
> 9896449          0t0        TCP localhost:bacula-sd->localhost:45075
> (ESTABLISHED)
> bacula-sd 20022 20078     bacula    5u     IPv4           
> 9896451          0t0        TCP localhost:bacula-sd->localhost:45077
> (ESTABLISHED)
> bacula-fd 20045             root    5u     IPv4           
> 9899062          0t0        TCP localhost:45077->localhost:bacula-sd
> (ESTABLISHED)
> bacula-fd 20045 20047       root    5u     IPv4           
> 9899062          0t0        TCP localhost:45077->localhost:bacula-sd
> (ESTABLISHED)
> bacula-fd 20045 20080       root    5u     IPv4           
> 9899062          0t0        TCP localhost:45077->localhost:bacula-sd
> (ESTABLISHED)
> bacula-fd 20045 20082       root    5u     IPv4           
> 9899062          0t0        TCP localhost:45077->localhost:bacula-sd
> (ESTABLISHED)
> bacula-di 20066           bacula    9u     IPv4           
> 9895396          0t0        TCP localhost:45075->localhost:bacula-sd
> (ESTABLISHED)
> bacula-di 20066 20072     bacula    9u     IPv4           
> 9895396          0t0        TCP localhost:45075->localhost:bacula-sd
> (ESTABLISHED)
> bacula-di 20066 20073     bacula    9u     IPv4           
> 9895396          0t0        TCP localhost:45075->localhost:bacula-sd
> (ESTABLISHED)
> bacula-di 20066 20077     bacula    9u     IPv4           
> 9895396          0t0        TCP localhost:45075->localhost:bacula-sd
> (ESTABLISHED)
> bacula-di 20066 20079     bacula    9u     IPv4           
> 9895396          0t0        TCP localhost:45075->localhost:bacula-sd
> (ESTABLISHED)

How do I increase the logging while the bacula daemons are running? 
bconsole 'setdebug' command?  Any advice on next debugging steps?

Thanks in advance,

-- 
Anthony Jenkins, Software Engineer
VTilt Digital, LLC.

------------------------------------------------------------------------------
Put Bad Developers to Shame
Dominate Development with Jenkins Continuous Integration
Continuously Automate Build, Test & Deployment 
Start a new project now. Try Jenkins in the cloud.
http://p.sf.net/sfu/13600_Cloudbees
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users

<Prev in Thread] Current Thread [Next in Thread>