procopy - "...Copy complete. (6722)" - Forum - OpenEdge RDBMS - Progress Community

procopy - "...Copy complete. (6722)"

 Forum

procopy - "...Copy complete. (6722)"

This question is answered

I'm curious -- what is going on?

When you do a procopy there is a long pause after:

...Copy complete. (6722)

and before:
Database copied from /usr/dlc117/empty. (1365)
Procopy session end. (334)

This is especially noticeable if the target db structure is large (I just waited 5+ minutes for one, the target structure is just shy of 1TB) but even when copying "sports" on top of a trivial structure there is a perceptible pause.

So *something* seems to be happening after the copy is supposedly "complete".  Does anyone know what it is?

--
Tom Bascom
tom@wss.com

Verified Answer
  • write(1, "Database copied from /u/DLC/11.7"..., 51) = 51
    pwrite(20, "\2400\0\0\3\1\1\0\0\0\0\0-\0\0\0\31\7\350\t\316\17\233\17h\17\364*\5\0175\17"..., 4096, 1593344) = 4096
    pwrite(20, "\340\4\0\0\2\177\1\0\0\0\0\0\4\0\0\0\1\1*\4\0\0\0\0\3\0(\0\0\0\0\0"..., 4096, 159744) = 4096
    fdatasync(20)                           = 0
    fdatasync(23)                           = 0
    fdatasync(24)                           = 0
    fdatasync(25)                           = 0
    fdatasync(27)                           = 0
    fdatasync(29)                           = 0
    fdatasync(31)                           = 0
    fdatasync(33)                           = 0
    pwrite(21, " \0\0\0\1\177\1\0\0\0\0\0\25\0\0\0\255\20\0\0\0\0\0\0\0\0\0\0\1\0\0\0"..., 4096, 4096) = 4096
    fdatasync(20)                           = 0
    fdatasync(23)                           = 0
    fdatasync(24)                           = 0
    fdatasync(25)                           = 0
    fdatasync(27)                           = 0
    fdatasync(29)                           = 0
    fdatasync(31)                           = 0
    fdatasync(33)                           = 0
    lseek(4, 1223829, SEEK_SET)             = 1223829
    read(4, "%LAt Database close the number o"..., 81) = 81
    write(17, "[2018/06/27@11:59:43.417-0400] P"..., 140) = 140
    lseek(4, 1275183, SEEK_SET)             = 1275183
    read(4, "%LBefore Image Log Completion at"..., 81) = 81
    write(17, "[2018/06/27@11:59:43.418-0400] P"..., 135) = 135
    pwrite(21, " \0\0\0\1\177\1\0\0\0\0\0\25\0\0\0\255\20\0\0\0\0\0\0\0\0\0\0\2\0\0\0"..., 4096, 4096) = 4096
    close(15)                               = 0
    unlink("sp.lk")                         = 0
    close(16)                               = 0
    close(18)                               = 0
    close(19)                               = 0
    close(20)                               = 0
    close(21)                               = 0
    close(22)                               = 0
    close(23)                               = 0
    close(24)                               = 0
    close(25)                               = 0
    close(26)                               = 0
    close(27)                               = 0
    close(28)                               = 0
    close(29)                               = 0
    close(30)                               = 0
    close(31)                               = 0
    close(32)                               = 0
    close(33)                               = 0
    close(34)                               = 0
    write(17, "[2018/06/27@11:59:43.425-0400] P"..., 125) = 125
    close(17)                               = 0
    close(5)                                = 0
    close(7)                                = 0
    close(8)                                = 0
    close(9)                                = 0
    close(10)                               = 0
    close(11)                               = 0
    close(12)                               = 0
    close(13)                               = 0
    close(14)                               = 0
    write(1, "Procopy session end. (334)\n", 27) = 27
    
All Replies
  • After "...Copy complete." (334 in lg file), it does a series of fdatasyncs.  So maybe the delay you're seeing is due to I/O queuing?

  • write(1, "Database copied from /u/DLC/11.7"..., 51) = 51
    pwrite(20, "\2400\0\0\3\1\1\0\0\0\0\0-\0\0\0\31\7\350\t\316\17\233\17h\17\364*\5\0175\17"..., 4096, 1593344) = 4096
    pwrite(20, "\340\4\0\0\2\177\1\0\0\0\0\0\4\0\0\0\1\1*\4\0\0\0\0\3\0(\0\0\0\0\0"..., 4096, 159744) = 4096
    fdatasync(20)                           = 0
    fdatasync(23)                           = 0
    fdatasync(24)                           = 0
    fdatasync(25)                           = 0
    fdatasync(27)                           = 0
    fdatasync(29)                           = 0
    fdatasync(31)                           = 0
    fdatasync(33)                           = 0
    pwrite(21, " \0\0\0\1\177\1\0\0\0\0\0\25\0\0\0\255\20\0\0\0\0\0\0\0\0\0\0\1\0\0\0"..., 4096, 4096) = 4096
    fdatasync(20)                           = 0
    fdatasync(23)                           = 0
    fdatasync(24)                           = 0
    fdatasync(25)                           = 0
    fdatasync(27)                           = 0
    fdatasync(29)                           = 0
    fdatasync(31)                           = 0
    fdatasync(33)                           = 0
    lseek(4, 1223829, SEEK_SET)             = 1223829
    read(4, "%LAt Database close the number o"..., 81) = 81
    write(17, "[2018/06/27@11:59:43.417-0400] P"..., 140) = 140
    lseek(4, 1275183, SEEK_SET)             = 1275183
    read(4, "%LBefore Image Log Completion at"..., 81) = 81
    write(17, "[2018/06/27@11:59:43.418-0400] P"..., 135) = 135
    pwrite(21, " \0\0\0\1\177\1\0\0\0\0\0\25\0\0\0\255\20\0\0\0\0\0\0\0\0\0\0\2\0\0\0"..., 4096, 4096) = 4096
    close(15)                               = 0
    unlink("sp.lk")                         = 0
    close(16)                               = 0
    close(18)                               = 0
    close(19)                               = 0
    close(20)                               = 0
    close(21)                               = 0
    close(22)                               = 0
    close(23)                               = 0
    close(24)                               = 0
    close(25)                               = 0
    close(26)                               = 0
    close(27)                               = 0
    close(28)                               = 0
    close(29)                               = 0
    close(30)                               = 0
    close(31)                               = 0
    close(32)                               = 0
    close(33)                               = 0
    close(34)                               = 0
    write(17, "[2018/06/27@11:59:43.425-0400] P"..., 125) = 125
    close(17)                               = 0
    close(5)                                = 0
    close(7)                                = 0
    close(8)                                = 0
    close(9)                                = 0
    close(10)                               = 0
    close(11)                               = 0
    close(12)                               = 0
    close(13)                               = 0
    close(14)                               = 0
    write(1, "Procopy session end. (334)\n", 27) = 27
    
  • That explains it!

    A "please wait for synchronization" message might help to avoid panic ;)

    --
    Tom Bascom
    tom@wss.com