[Box Backup] Re: [Box Backup] error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry

[Chris Wilson]

Hi Johann,

On Fri, 7 Sep 2007, Johann Glaser wrote:

> I've added a FeatureRequest in the Wiki to add this option in the config 
> file template.

Thanks, I've just done it in my tree.

> I've investigated this case more closely. The problem occurs every time 
> with the very same file with a size of (only) 360.724.480 bytes (we have 
> much larger files). I attached an strace to the bbackupd process and 
> found out that all files before this one are only checked using 
> lstat64() and llistxattr() but are never open()ed or ever read(). I 
> think this is because they already have been backuped in the night when 
> the backup ran the first time (approx. 3:50).
>
> The particular file which triggers the problem on the other hand is read 
> quite often. It starts with the following:
>
> ...
> 23240 open("/backup/daily/mysql/mysql-InnoDB.tar", O_RDONLY|O_LARGEFILE) = 6
> 23240 fstat64(6, {st_mode=S_IFREG|0600, st_size=360724480, ...}) = 0
> 23240 _llseek(6, 0, [0], SEEK_CUR)      = 0
> 23240 mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb79e5000
> 23240 mmap2(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb79c4000
> 23240 mmap2(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb79a3000
> 23240 _llseek(6, 0, [0], SEEK_SET)      = 0
> 23240 read(6, "data/mysql/ib_arch_log_000000000"..., 1430) = 1430
> ... many read(6, ..., 1430) = 1430
> 23240 read(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1430) = 1260
>
> Ok, the file was now completely read. There is nothing in between, only
> lots of read()s. Then it starts over again with
>
> 23240 _llseek(6, 0, [0], SEEK_SET)      = 0
> 23240 read(6, "data/mysql/ib_arch_log_000000000"..., 1511) = 1511
> 23240 read(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1511) = 1511
> ... many read(6, ..., 1511) = 1511
> 23240 read(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1511) = 428
>
> So it was read a second time with a 81 bytes larger read buffer. Again
> it reads the very same file with an increased read buffer
>
> 23240 _llseek(6, 0, [0], SEEK_SET)      = 0
> 23240 read(6, "data/mysql/ib_arch_log_000000000"..., 1525) = 1525
> 23240 read(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\302\0\0\0\0\0\n-/"..., 1525) = 1525
> ...
>
> And this continues (until I stopped strace). The read buffer is always
> increased irregularly by 3-152 bytes except once where it went from 2394
> down to 1199 and then up to 2427. In the meantime bbstored already
> compliant about the Protocol_Timeout.
>
> Why is bbackupd reading this file so often?

That is a very good question. If the reads were powers of two, then I'd 
suggest it was due to diffing at different block sizes, but that doesn't 
seem to be the case here. Perhaps this is why your backups are taking 
so long? I'll investigate.

I assume that you're running 0.10 on the client?

Cheers, Chris.
-- 
_____ __     _
\  __/ / ,__(_)_  | Chris Wilson <0000 at qwirx.com> - Cambs UK |
/ (_/ ,\/ _/ /_ \ | Security/C/C++/Java/Perl/SQL/HTML Developer |
\ _/_/_/_//_/___/ | We are GNU-free your mind-and your software |