11.5.1 Win 32: Why is a backup online to an exiting file so slow? - Forum - OpenEdge RDBMS - Progress Community

11.5.1 Win 32: Why is a backup online to an exiting file so slow?

 Forum

11.5.1 Win 32: Why is a backup online to an exiting file so slow?

This question is not answered

I noticed that if I do not delete the backup file before the online backup is running much slower (2-3 times)
It's easy to add a del db.bak in the script but I am interesting about the possible cause.
Does anybody knows it?

All Replies
  • Many years ago I had a customer who set up a backup process, I think direct to tape.  The operator was supposed to rotate the tapes in some fashion like a new tape each day of the week and then save the Friday tape for a while and the end of month tape for longer, but at some point, for reasons unknown, the operator stopped bothering to change the tape at all.  Eventually, the DB failed and it turned out that the last good backup was close to a year old.  Ferocious rekeying!!!

    Consulting in Model-Based Development, Transformation, and Object-Oriented Best Practice  http://www.cintegrity.com

  • If I may add my $0.02CAD:  On WIndows, when probkup starts and fails, it still changes the timestamp on the physical DB file.

    I remember a specific situation where a customer had no more empty AI extents so the backup had been failing for weeks. But every day the existing 400 GB probkup file was touched and the admin was incorrectly relying on the file time stamp to assure himself that his backups were good.  

    Paul Koufalis
    White Star Software

    pk@wss.com
    @oeDBA (https://twitter.com/oeDBA)

    ProTop: The #1 Free OpenEdge DB Monitoring Tool
    http://protop.wss.com
  • Customer's example.

    Backup time of 144.6 GBytes:
    1. 3934.319 sec = 01:05:34.319
    2. 59646.163 sec = 16:34:06.163
    3. 61128.497 sec = 16:58:48.497

    Backup time of 144.6 GBytes:
    1.  3934.319 sec = 01:05:34.319
    2. 59646.163 sec = 16:34:06.163
    3. 61128.497 sec = 16:58:48.497
    
    
    [2015/03/07@00:05:01.551+0300] P-4688       T-3456  I BACKUP 11: (12850) Backup blocks will be written to e:\backup\dbname.bkp.
    [2015/03/07@00:05:01.551+0300] P-4688       T-3456  I BACKUP 11: (1362)  Full backup started.
    [2015/03/07@00:05:01.552+0300] P-4688       T-3456  I BACKUP 11: (6686)  37437691 active blocks out of 45569365 blocks in e:\db\dbname will be dumped.
    [2015/03/07@00:05:01.553+0300] P-4688       T-3456  I BACKUP 11: (6688)  222784 BI blocks will be dumped.
    [2015/03/07@00:05:01.554+0300] P-4688       T-3456  I BACKUP 11: (9285)  Backup requires an estimated 144.8 GBytes of media.
    [2015/03/07@00:05:01.554+0300] P-4688       T-3456  I BACKUP 11: (9286)  Restore would require an estimated 37960087 db blocks using 144.5 GBytes of media.
    [2015/03/07@00:05:02.009+0300] P-4688       T-3456  I BACKUP 11: (16866) Dumped 256 active BI blocks.
    [2015/03/07@00:05:02.010+0300] P-4688       T-3456  I BACKUP 11: (5461)  Begin backup of Data file(s).
    [2015/03/07@01:10:36.329+0300] P-4688       T-3456  I BACKUP 11: (5462)  End backup of Data file(s).
    DATA BACKUP TIME: 3934.319 sec = 01:05:34.319
    [2015/03/07@01:10:36.331+0300] P-4688       T-3456  I BACKUP 11: (13625) Wrote a total of 1103359 backup blocks using 143.1 GBytes of media.
    [2015/03/07@01:10:36.406+0300] P-4688       T-3456  I BACKUP 11: (1364)  Full backup successfully completed.
    
    
    [2015/03/08@00:05:01.301+0300] P-7664       T-6404  I BACKUP 11: (12850) Backup blocks will be written to e:\backup\dbname.bkp.
    [2015/03/08@00:05:01.301+0300] P-7664       T-6404  I BACKUP 11: (1362)  Full backup started.
    [2015/03/08@00:05:01.301+0300] P-7664       T-6404  I BACKUP 11: (6686)  37449527 active blocks out of 45569365 blocks in e:\db\dbname will be dumped.
    [2015/03/08@00:05:01.303+0300] P-7664       T-6404  I BACKUP 11: (6688)  222784 BI blocks will be dumped.
    [2015/03/08@00:05:01.304+0300] P-7664       T-6404  I BACKUP 11: (9285)  Backup requires an estimated 144.9 GBytes of media.
    [2015/03/08@00:05:01.304+0300] P-7664       T-6404  I BACKUP 11: (9286)  Restore would require an estimated 37971947 db blocks using 144.6 GBytes of media.
    [2015/03/08@00:05:01.666+0300] P-7664       T-6404  I BACKUP 11: (16866) Dumped 256 active BI blocks.
    [2015/03/08@00:05:01.667+0300] P-7664       T-6404  I BACKUP 11: (5461)  Begin backup of Data file(s).
    [2015/03/08@16:39:07.830+0300] P-7664       T-6404  I BACKUP 11: (5462)  End backup of Data file(s).
    DATA BACKUP TIME: 59646.163 sec = 16:34:06.163
    [2015/03/08@16:39:07.864+0300] P-7664       T-6404  I BACKUP 11: (13625) Wrote a total of 1103709 backup blocks using 143.2 GBytes of media.
    [2015/03/08@16:39:07.898+0300] P-7664       T-6404  I BACKUP 11: (1364)  Full backup successfully completed.
    
    
    [2015/03/09@00:05:01.020+0300] P-3684       T-1648  I BACKUP 11: (12850) Backup blocks will be written to e:\backup\dbname.bkp.
    [2015/03/09@00:05:01.021+0300] P-3684       T-1648  I BACKUP 11: (1362)  Full backup started.
    [2015/03/09@00:05:01.021+0300] P-3684       T-1648  I BACKUP 11: (6686)  37458573 active blocks out of 45569365 blocks in e:\db\dbname will be dumped.
    [2015/03/09@00:05:01.022+0300] P-3684       T-1648  I BACKUP 11: (6688)  222784 BI blocks will be dumped.
    [2015/03/09@00:05:01.023+0300] P-3684       T-1648  I BACKUP 11: (9285)  Backup requires an estimated 144.9 GBytes of media.
    [2015/03/09@00:05:01.024+0300] P-3684       T-1648  I BACKUP 11: (9286)  Restore would require an estimated 37981012 db blocks using 144.6 GBytes of media.
    [2015/03/09@00:05:01.427+0300] P-3684       T-1648  I BACKUP 11: (16866) Dumped 256 active BI blocks.
    [2015/03/09@00:05:01.428+0300] P-3684       T-1648  I BACKUP 11: (5461)  Begin backup of Data file(s).
    [2015/03/09@17:03:49.925+0300] P-3684       T-1648  I BACKUP 11: (5462)  End backup of Data file(s).
    DATA BACKUP TIME: 61128.497 sec = 16:58:48.497
    [2015/03/09@17:03:49.946+0300] P-3684       T-1648  I BACKUP 11: (13625) Wrote a total of 1103974 backup blocks using 143.2 GBytes of media.
    [2015/03/09@17:03:49.977+0300] P-3684       T-1648  I BACKUP 11: (1364)  Full backup successfully completed.
    
  • yes. we know that this happens on windows. but we do not know why.

  • Comparing the results posted by Stefan and James and the results from our customer I think we can say that the ratio between the times to backup to an existent vs new file is growing as a power of backup's size. And taking into account the units of measurement we, of course, should use a ratio of backup's size to a size of something else. The only candidate that come to my mind is the system memory. James' example: 500MB backup file is, of course, smaller than available RAM and the backup time is the same when it uses an existent or new file. Stefan's example: backup to an exiting file is 2-3 times slower. "20 Minutes to an non existing file" - I guess the size of backup is approximately 40 GB (estimating the backup's writes as 30 MB/sec). Most likely backup's size is a few times larger than RAM. In the case of our customer the size of backup file is almost 150 GB - much bigger than available memory and backup to an exiting file is 16-17 times slower.

    If the issue indeed depends on ratio between the size of backup and system memory then I would say it's not a Progress issue.

    I guess the issue can be reproduced by a simple 4GL program (provided you have 40 GB of free space on your disk and available RAM is a few times smaller than 40 GB):

    OUTPUT TO VALUE(OutputFile) APPEND.
    SEEK OUTPUT TO 0.
    DO  i = 10000000:
      PUT StringWith4KSize.
    END.
    OUTPUT CLOSE.
    
  • some further thought

    - It makes sense that the backup would slow down when the in-memory filesystem cache was exhausted. But that should be so whether we are writing to a new file or an existing one.

    - Writing over an existing file should be /faster/ since disk space has alreay been allocated.

    - If backup blocks are not a multiple of the file system blocksize (and I do not recall what the backup blocksize is) then that could introduce an inefficiency in writing. If a backup block were say 3 and a half filesystem blocks, then writing a backup block would overwrite 3 filesystem blocks and update one, which requires reading it and pasting new data over half of it. That might require waiting for a full rotation of the disk platter. When writing a new file, no reading is necessary. Maybe that is the cause.

  • Yes, I totally forgot that probkup uses "XXL size" backup blocks: the -bf * db blocksize where the default for the blocking factor parameter is 34. IMHO, it would be a good idea to try to run probkup to an existent file with the -bf 1 just for a testing.

    And the -verbose parameter can shed a light if probkup is slow from the beginning or the slowness is increasing over time: probkup will display "Backed up n blocks in hh:mm:ss" every 10 seconds.

    > then writing a backup block would overwrite 3 filesystem blocks and update one, which requires reading it and pasting new data over half of it.

    But it should not be 16 times slower, could it be?

  • -bf 1 with existing file is fast:

    OpenEdge Release 11.5.1 as of Wed May  6 19:01:46 EDT 2015

    11543502 active blocks out of 11669279 blocks in [db] will be dumped. (6686)

    16384 BI blocks will be dumped. (6688)

    Backup requires an estimated 88.3 GBytes of media. (9285)

    Restore would require an estimated 11579658 db blocks using 88.2 GBytes of media. (9286)

    Backed up 11559886 db blocks in 00:21:50

    Wrote a total of 4014039 backup blocks using 61.2 GBytes of media. (13625)

    Backup complete. (3740)

  • Backup to SAN which shall be SSD, so there isn't any rotation of something (hopefully)

  • Hello All,

    I made an article for this in the Progress Knowledgebase siting the two known workarounds.

    I believe the improvement noted when using -bf 1 suggests it is something happening in the buffering of data by the probkup online but this will have to be investigated more internally.

    I'll file a bug for it.

    Thank you


    PROGRESS SOFTWARE CORPORATION
    14 Oak Park Drive | Bedford, MA 01730 | USA
    PHONE +1 781 280-3008
    richards@progress.com

    www.progress.com