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?
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
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 ;)