Binary Load - Super Slow on 11.7.2 - Forum - OpenEdge RDBMS - Progress Community

Binary Load - Super Slow on 11.7.2

 Forum

Binary Load - Super Slow on 11.7.2

  • I have run a binary dump and load on a 280 Gig Database in progress version 11.7.2.

    Dump tmei - 30 Minutes

    Load time - 11:49 Minutes

    Index rebuild - 59 Minutes.

    We have noticed in version 11.7.2 the binary load takes long and this should be the quick part of the load.

    has anybody else experienced this as we are busy doing maintenance on our clients where we are merging DB's and we doing binary dumps from 1 DB to the merged DB.

  • > We have noticed in version 11.7.2 the binary load takes long and this should be the quick part of the load.

    Dump time highly depends from the used indexes if db is hosted on HDD disks (the ones with seek time). Try to use the smallest indexes.

    > Index rebuild - 59 Minutes

    What the pararameters were used to run idxbuild?

  • The following is the Index rebuild

    "proutil hollvalicf -C idxbuild -TB 64 -TM 32 -TMB 4096 -SG 64 -TF 80 -T /valdb/tmp/ -threadnum 4 -merg

    ethreads 4 -datascanthreads 16 -pfactor 80 -rusage -z"

    I think my explanation is not correct. The load is taking 11 hours 49 Minutes. this is the issue.

  • > The load is taking 11 hours 49 Minutes.

    How do you run the binary load?

  • I run this single user via a load.sh script. Example below.

    proutil hollvalicf -C load /dbbackup/dump/gsc_custom_procedure.bd

    proutil hollvalicf -C load /dbbackup/dump/gsc_dataset_entity.bd

    Here is the dump command. Example below

    proutil hollvalicf -RO -index 0  -thread 1  -C dump gsc_custom_procedure /dbbackup/dump

    proutil hollvalicf -RO -index 0  -thread 1  -C dump gsc_dataset_entity /dbbackup/dump

    proutil hollvalicf -RO -index 0  -thread 1  -C dump gsc_data_tag /dbbackup/dump

    I have run a binary load on 2 X 250 Gig DB's and the load took 3 hours total time. Progress version 11.3.3.

  • Obviously the disk you are writing to for the dump is reasonably fast and I assume you are reading from the same disk location when running the binary load, so disk should not be a factor.

    Index rebuild is about what you would expect for a database of this size.  So to echo George's request, how do you perform the binary load?

  • > I run this single user via a load.sh script.

    Can you post all messages of the last load (only from one binary load session)?

    Load in multi-user mode would be faster.

  • Regarding idxbuild. Here is the results of rather random tests run by a customer of us.

    Table size = 982.5G (1.3T with indexes)

    17073.806 sec 04:44:33.806 -TMB  256 -TF 80 -B 512  -datascanthreads 128 -mergethreads 32
    17110.734 sec 04:45:10.734 -TMB  256 -TF 80 -B 5120 -datascanthreads  96 -mergethreads  8 
    17133.188 sec 04:45:33.188 -TMB  256 -TF 80 -B 512  -datascanthreads 128 -mergethreads 16
    17134.440 sec 04:45:34.440 -TMB  256 -TF 80 -B 512  -datascanthreads  96 -mergethreads  8 
    17229.221 sec 04:47:09.221 -TMB  256 -TF 40 -B 512  -datascanthreads  64 -mergethreads  8
    17244.425 sec 04:47:24.425 -TMB  256 -TF 80 -B 512  -datascanthreads 128 -mergethreads  8 
    17419.778 sec 04:50:19.778 -TMB  256 -TF 80 -B 512  -datascanthreads  96 -mergethreads  4 
    17419.839 sec 04:50:19.839 -TMB  256 -TF 40 -B 512  -datascanthreads 128 -mergethreads  8
    17503.518 sec 04:51:43.518 -TMB 1024 -TF 80 -B 512  -datascanthreads 128 -mergethreads 16
    17965.673 sec 04:59:25.673 -TMB  256 -TF 40 -B 512  -datascanthreads  32 -mergethreads  8
    19762.750 sec 05:29:22.750 -TMB  256 -TF 40 -B 512  -datascanthreads  16 -mergethreads  8
    19986.706 sec 05:33:06.706 -TMB  256 -TF 40 -B 512  -datascanthreads  16 -mergethreads  4
    22282.903 sec 06:11:22.903 -TMB  256 -TF 80 -B 512  -datascanthreads   8 -mergethreads  4
    23180.969 sec 06:26:20.969 -TMB  256 -TF 40 -B 512  -datascanthreads   8 -mergethreads  4
    28684.978 sec 07:58:04.978 -TMB  256 -TF 80 -B 512  -datascanthreads   4 -mergethreads  2
    29606.891 sec 08:13:26.891 -TMB  256 -TF 40 -B 512  -datascanthreads   4 -mergethreads  2
    
  • My biggest concern at the moment is why is the load taking a long time.
     
    Here is the log for the load. The size of the file is 146 Gigs.
     
                    Thu Mar  7 18:36:01 2019
    [2019/03/07@18:36:01.453+0200] P-58220      T-140714784515904 I BINLOAD  : (451)   Binary load session begin for root on /dev/pts/2.
    [2019/03/07@18:36:01.453+0200] P-58220      T-140714784515904 I BINLOAD  : (15321) Before Image Log Initialization at block 42  offset 7127.
    [2019/03/07@18:36:01.460+0200] P-58220      T-140714784515904 I BINLOAD  : (7129)  Usr 0 set name to root.
    [2019/03/07@18:36:01.463+0200] P-58220      T-140714784515904 I BINLOAD  : (6203)  Binary Dump created on Thu Mar  7 17:16:10 2019
    from database /valdb/db/hollvalicf.
    [2019/03/07@18:36:01.463+0200] P-58220      T-140714784515904 I BINLOAD  : (6204)  Loading table gst_audit, Table number 93
    starting with record 1, section 1.
     
                    Fri Mar  8 05:58:36 2019
    [2019/03/08@05:58:36.810+0200] P-58220      T-140714784515904 I BINLOAD  : (13633) Table /dbbackup/dump/gst_audit.bd has been loaded.
    [2019/03/08@05:58:36.834+0200] P-58220      T-140714784515904 I BINLOAD  : (15109) At Database close the number of live transactions is 0.
    [2019/03/08@05:58:36.834+0200] P-58220      T-140714784515904 I BINLOAD  : (15743) Before Image Log Completion at Block 40 Offset 602.
    [2019/03/08@05:58:36.878+0200] P-58220      T-140714784515904 I BINLOAD  : (334)   Binary load session end.
     
  • Binary load did 3.65 MB/sec - writing to db files as well as to bi file.

    Can you run the Furgal test?

    proutil empty -C truncate bi -bi 16384

    proutil empty -C bigrow 2 -zextendSyncIO

  • I created test DB using 8k. Below is the results.

                   Fri Mar  8 09:49:01 2019

    [2019/03/08@09:49:01.901+0200] P-10638      T-140587748644672 I DBUTIL   : (451)   Truncate bi session begin for root on /dev/pts/5.

    [2019/03/08@09:49:01.901+0200] P-10638      T-140587748644672 I DBUTIL   : (15321) Before Image Log Initialization at block 0  offset 1004.

    [2019/03/08@09:49:01.905+0200] P-10638      T-140587748644672 I DBUTIL   : (7129)  Usr 0 set name to root.

    [2019/03/08@09:49:01.906+0200] P-10638      T-140587748644672 I DBUTIL   : (1620)  Before-image cluster size set to 16384 kb.

    [2019/03/08@09:49:01.910+0200] P-10638      T-140587748644672 I DBUTIL   : (123)   .bi file truncated.

    [2019/03/08@09:49:01.911+0200] P-10638      T-140587748644672 I DBUTIL   : (15109) At Database close the number of live transactions is 0.

    [2019/03/08@09:49:01.911+0200] P-10638      T-140587748644672 I DBUTIL   : (15743) Before Image Log Completion at Block 0 Offset 1004.

    [2019/03/08@09:49:01.926+0200] P-10638      T-140587748644672 I DBUTIL   : (334)   Truncate bi session end.

                   Fri Mar  8 09:49:25 2019

    [2019/03/08@09:49:25.142+0200] P-11384      T-139803562612544 I DBUTIL   : (451)   Bigrow session begin for root on /dev/pts/5.

    [2019/03/08@09:49:25.142+0200] P-11384      T-139803562612544 I DBUTIL   : (15321) Before Image Log Initialization at block 0  offset 0.

    [2019/03/08@09:49:37.200+0200] P-11384      T-139803562612544 I DBUTIL   : (7129)  Usr 0 set name to root.

    [2019/03/08@09:49:37.200+0200] P-11384      T-139803562612544 I DBUTIL   : (6600)  Adding 2 clusters to the Before Image file.

    [2019/03/08@09:49:43.516+0200] P-11384      T-139803562612544 I DBUTIL   : (15109) At Database close the number of live transactions is 0.

    [2019/03/08@09:49:43.516+0200] P-11384      T-139803562612544 I DBUTIL   : (15743) Before Image Log Completion at Block 0 Offset 235.

    [2019/03/08@09:49:43.529+0200] P-11384      T-139803562612544 I DBUTIL   : (334)   Bigrow session end.

    [root@hssmiplive-ind:tmp]# l

    total 102288

    drwxr-xr-x 2 root root      4096 Mar  8 09:49 .

    drwxr-xr-x 9 root root      4096 Mar  8 06:20 ..

    -rw-r--r-- 1 root root 100794368 Mar  8 09:49 test.b1

    -rw-r--r-- 1 root root   3276800 Mar  8 09:49 test.d1

    -rw-r--r-- 1 root root    655360 Mar  8 09:49 test.db

    -rw-r--r-- 1 root root      3502 Mar  8 09:49 test.lg

    -rw-r--r-- 1 root root        33 Mar  8 09:48 test.st

  • 11 hours 49 minutes to load something that took 30 minutes to dump is certainly not the expected behavior.

    Have you previously executed similarly sized binary loads *on this hardware* with other versions of Progress that performed better?  I ask because you specifically indicated that you think 11.7.2 is the cause of the slowness and I see that you have had faster results with 11.3 but was it the same HW?  (And if it was has anything been changed?)

    My first guess is that the load target is on a SAN, probably with RAID5 (or, worse, 6) and that the disks are saturated.  Although that should have also impacted the index rebuild so that idea may not hold water.

    I think it would be very interesting to run the Furgal test (ProTop automates this with syncio.sh) to either confirm or rule out a write performance issue.

    --
    Tom Bascom
    tom@wss.com

  • > proutil hollvalicf -C load /dbbackup/dump/gsc_custom_procedure.bd

    Try running with -i and -r as well.

  • 4 bi clusters (64 MB) were added in 12.058 sec, 2 bi clusters (32 MB) - in 6.329 sec. In other words, bi wites are 5.06-5.31 MB/sec. Binary load did 3.65 MB/sec. But it wrote to db files as well.

  • > Try running with -i and -r as well.

    Plus in multi-user mode with BIW/APW running.