Thread: Why are pg_restore taking that long ?
I have just restored a database about 347GB in size
postgres=# select * from pg_database_size('dbname');
pg_database_size
------------------
346782483256
using this command:
pg_restore -d dbname -O -Fc dbname.backup
It started at 13/5 21:28 and at 14/5 18:47 all user tables were imported
and indexes were build.
It's on a single SATA drive, so I think that's OK.
But the restore wasn't finished until 15/5 08:47
Looking at the files in the database, all files touched after 14/5
18:47, are system tables:
filename relfilenode
11750 pg_constraint_conrelid_index
11752 pg_constraint_oid_index
11735 ?
11736 ?
11733 ?
11757 pg_index
11714 ?
11808 pg_trigger_tgconstraint_index
11810 pg_trigger_oid_index
11751 pg_constraint_contypid_index
11809 pg_trigger_tgrelid_tgname_index
11837 pg_depend_depender_index
11744 pg_constraint
11749 pg_constraint_conname_nsp_index
11803 pg_trigger
11835 pg_depend
11838 pg_depend_reference_index
11826 pg_namespace
autovacuum was disabled.
Why is it working that long on the system tables ?
dbname=# select version();
version
------------------------------------------------------------------------------------------------------------
PostgreSQL 9.1.3 on x86_64-unknown-linux-gnu, compiled by gcc
(Ubuntu/Linaro 4.6.3-1ubuntu2) 4.6.3, 64-bit
Thanks,
Poul
Hi,
Poul Møller Hansen wrote:
> I have just restored a database about 347GB in size
>
> postgres=# select * from pg_database_size('dbname');
> pg_database_size
> ------------------
> 346782483256
>
> using this command:
> pg_restore -d dbname -O -Fc dbname.backup
>
> It started at 13/5 21:28 and at 14/5 18:47 all user tables were imported
> and indexes were build.
> It's on a single SATA drive, so I think that's OK.
>
> But the restore wasn't finished until 15/5 08:47
One thing you may want to look at (if this is PG 8.4.x) is the number of
large objects in pg_largeobjects. If your apps don't use large objects
this is not relevant. If they do, then it may be. I've noticed that
pg_restore no longer reports the restoration of individual LO items. It
used to but no longer. That means that even with multiple '-v' options
specified it appears that the restore has hung even though it is in fact
adding large objects all the while. I've also noticed that I can no longer
see the objects as they are added to the db. I wonder if their restoration
got moved to a single transaction?
Anyway, if you are seeing no activity at the end of the restore for quite
a while you may want to see if large objects are the reason.
Just a thought.
Bosco.
On Fri, May 18, 2012 at 3:11 PM, Bosco Rama <postgres@boscorama.com> wrote: > One thing you may want to look at (if this is PG 8.4.x) is the number of > large objects in pg_largeobjects. If your apps don't use large objects > this is not relevant. If they do, then it may be. I've noticed that > pg_restore no longer reports the restoration of individual LO items. It > used to but no longer. That means that even with multiple '-v' options > specified it appears that the restore has hung even though it is in fact > adding large objects all the while. I've also noticed that I can no longer > see the objects as they are added to the db. I wonder if their restoration > got moved to a single transaction? > > Anyway, if you are seeing no activity at the end of the restore for quite > a while you may want to see if large objects are the reason. Using a recent pg_restore (tested with 9.1.2, verbose mode on) and a custom-format dump containing large objects, you should see messages like this: pg_restore: creating TABLE image pg_restore: executing BLOB 126810 pg_restore: executing BLOB 133157 ... pg_restore: restoring data for table "image" pg_restore: restoring BLOBS pg_restore: restored 1111 large objects ... pg_restore: setting owner and privileges for BLOB 126810 pg_restore: setting owner and privileges for BLOB 133157 ... If you're not seeing those messages, maybe your dump didn't actually include large objects (e.g. because you didn't dump the whole database and left off --blobs). It looks like you are correct that the blobs are restored inside a single transaction, even without the --single-transaction flag. Josh
Hi Josh, Josh Kupershmidt wrote: > > Using a recent pg_restore (tested with 9.1.2, verbose mode on) and a > custom-format dump containing large objects, you should see messages > like this: > > pg_restore: creating TABLE image > pg_restore: executing BLOB 126810 > pg_restore: executing BLOB 133157 > ... > pg_restore: restoring data for table "image" > pg_restore: restoring BLOBS > pg_restore: restored 1111 large objects > ... > pg_restore: setting owner and privileges for BLOB 126810 > pg_restore: setting owner and privileges for BLOB 133157 > ... > > If you're not seeing those messages, maybe your dump didn't actually > include large objects (e.g. because you didn't dump the whole database > and left off --blobs). All our dumps are done like this: pg_dump -Fc -Z4 >filename.dat So we have custom format and full-db dumps whenever we do them. Since the majority of our DB is blobs in compressed file formats we've found that a compression factor of '4' gives us the best 'size vs time' trade-off. And we restore them this way: pg_restore -Ov -j2 -d db_name filename.dat The per-blob messages are missing whether we use the '-j2' or not and also regardless of number of '-v's we use. I'm glad they've reinstated some of the messages. Previously there was a message per blob between the "restoring BLOBS" and "restored NNN large objects" messages. It's a pity they've gone because we used them as a 'progress meter' of sorts. They disappeared somewhere around 8.4.8 or 8.4.9 IIRC and, unfortunately, we are currently restricted to the 8.4.x series. :-( > It looks like you are correct that the blobs are restored inside a > single transaction, even without the --single-transaction flag. *nods* I'm not sure what the motivation there was but I am also sure that the devs had/have a very good reason for it. :-) Bosco.
On Fri, May 18, 2012 at 5:58 PM, Bosco Rama <postgres@boscorama.com> wrote: > The per-blob messages are missing whether we use the '-j2' or not and also > regardless of number of '-v's we use. > > I'm glad they've reinstated some of the messages. Previously there was > a message per blob between the "restoring BLOBS" and "restored NNN large > objects" messages. It's a pity they've gone because we used them as a > 'progress meter' of sorts. They disappeared somewhere around 8.4.8 or > 8.4.9 IIRC and, unfortunately, we are currently restricted to the 8.4.x > series. :-( FYI, some digging with git bisect pointed me to this commit: http://git.postgresql.org/gitweb/?p=postgresql.git;a=commitdiff;h=c0d5be5d6a736d2ee8141e920bc3de8e001bf6d9 which introduced the per-blob message I showed before, e.g. >> pg_restore: executing BLOB 126810 The above commit was made during 9.0dev, and doesn't look to have been backported to 8.4. The 8.4 versions should display something like this in verbose mode: pg_restore: restoring BLOBS pg_restore: restored 10 large objects pg_restore: restoring BLOB COMMENTS ... i.e. no per-blob message. (I've verified the messages above are similar on 8.4.1 and 8.4.11.) Maybe you were using a 9.0+ version of pg_restore when you saw per-blob messages? Josh
Hey Josh,
I found the message I was seeing. It was/is(?) in StartRestoreBlob() and it
looks like this:
ahlog(AH, 2, "restoring large object with OID %u\n", oid);
But I don't know how to find it in the current git tree or how to activate
it from the command-line (assuming it is still part of the release).
Bosco.
On Sat, May 19, 2012 at 10:57 PM, Bosco Rama <postgres@boscorama.com> wrote: > Hey Josh, > > I found the message I was seeing. It was/is(?) in StartRestoreBlob() and it > looks like this: > > ahlog(AH, 2, "restoring large object with OID %u\n", oid); > > But I don't know how to find it in the current git tree or how to activate > it from the command-line (assuming it is still part of the release). Yup, that's still there, see pg_backup_archiver.c in git head: http://git.postgresql.org/gitweb/?p=postgresql.git;a=blob;f=src/bin/pg_dump/pg_backup_archiver.c;h=e29265953d46aa9730eccca41062dfd9b2c45ba3;hb=f1f6737e154f9d00f1565fc08fd7ac677b380822 The reason that message doesn't show up is it's being logged with level=2, and with the "-v" or "--verbose" switch, only messages at level 1 or less get logged. Notice that pg_backup_archiver.c and pg_backup_tar.c use an inconsistent log level for this same message, which might explain where you saw the message previously. If you're using a tar-format backup, you will see the message: pg_restore: restoring large object OID 16388 for each LO in verbose mode. Now, if you're keen on seeing that message for custom-format archives, you could change that "2" to a "1" in the line you posted from pg_backup_archiver.c and recompile, and that should give you the message you're after. Or change this bit in pg_restore.c to assign a 2 instead of a 1: case 'v': /* verbose */ opts->verbose = 1; break; It'd sure be nice to have these programs allow "-vvvv" style switches to signify cranking up the debugLevel, unless I'm missing some other way to do so. Josh
> > One thing you may want to look at (if this is PG 8.4.x) is the number of > large objects in pg_largeobjects. If your apps don't use large objects > this is not relevant. If they do, then it may be. I've noticed that > pg_restore no longer reports the restoration of individual LO items. It > used to but no longer. That means that even with multiple '-v' options > specified it appears that the restore has hung even though it is in fact > adding large objects all the while. I've also noticed that I can no longer > see the objects as they are added to the db. I wonder if their restoration > got moved to a single transaction? > > Anyway, if you are seeing no activity at the end of the restore for quite > a while you may want to see if large objects are the reason. > The dump are from a version 9.0.7 and it's being restored in a version 9.1.3. There are no large objects. I'm now doing another restore with the -v switch, and hopefully it will show what it is doing at the end. There are Bucardo triggers in the database. Perhaps it can be the reason, and it should be restored with the "--disable-triggers" switch ? It would be neat if there was a timestamp on the pg_restore steps in verbose mode. Poul
Josh Kupershmidt <schmiddy@gmail.com> writes:
> ... Notice that pg_backup_archiver.c and
> pg_backup_tar.c use an inconsistent log level for this same message,
> which might explain where you saw the message previously.
Seems like that ought to be fixed.
> ... Or change this bit in pg_restore.c to assign a 2
> instead of a 1:
>
> case 'v': /* verbose */
> opts->verbose = 1;
> break;
"verbose" is used as a boolean, so that wouldn't actually help.
> It'd sure be nice to have these programs allow "-vvvv" style switches
> to signify cranking up the debugLevel, unless I'm missing some other
> way to do so.
Yeah. ahlog() also pays attention to a "debugLevel" value, but AFAICS
that's totally vestigial with no way to set it. It would likely be a
worthwhile activity to rationalize these things into a single
maximum-message-level value that could be ratcheted up with multiple -v
switches.
regards, tom lane
On Sun, May 20, 2012 at 8:39 AM, Poul Møller Hansen <freebsd@pbnet.dk> wrote: >> Anyway, if you are seeing no activity at the end of the restore for quite >> a while you may want to see if large objects are the reason. >> > > The dump are from a version 9.0.7 and it's being restored in a version > 9.1.3. There are no large objects. > > I'm now doing another restore with the -v switch, and hopefully it will show > what it is doing at the end. > There are Bucardo triggers in the database. Perhaps it can be the reason, > and it should be restored with the "--disable-triggers" switch ? Possibly. You should be able to tell what's taking so much time by keeping an eye on your server during the restore. You could set log_statement = 'all' (or just 'ddl' if there is significant other activity in other databases) during the restore, and keep an eye on pg_stat_activity if you need to. Josh
> Possibly. You should be able to tell what's taking so much time by > keeping an eye on your server during the restore. You could set > log_statement = 'all' (or just 'ddl' if there is significant other > activity in other databases) during the restore, and keep an eye on > pg_stat_activity if you need to. > OK, nothing unusual I think. It's the foreign keys that takes that long to generate. I didn't realize that they are in the system tables. Poul