Thread: pg_dump incredibly slow dumping a single schema from a large db

Mike Roest <mike.roest@replicon.com> writes:
> This dump is currently taking around 8 minutes.  While dumping the pg_dump
> process is using 100% of one core in the server (24 core machine).  Doing a
> -v pg_dump I found that the following stages are taking the majority of the
> time

> reading user_defined tables (2 minutes and 20 seconds)
> reading dependency data (5 minutes and 30 seconds)

Can you get an execution profile with oprofile or gprof or similar tool?
It doesn't surprise me a lot that pg_dump might have some issues with
large numbers of objects, but guessing which inefficiencies are hurting
you is difficult without more info.

            regards, tom lane

Mike Roest <mike.roest@replicon.com> writes:
> Ok I just realized that's probably not going to be much help :)

gmon.out would be of no value to anybody else anyway --- making sense of
it requires the exact executable you took the measurements with.

>   0.00      0.00     0.00        5     0.00     0.00  canonicalize_path
>   0.00      0.00     0.00        5     0.00     0.00
>  trim_trailing_separator
>   0.00      0.00     0.00        3     0.00     0.00  strlcpy

Ugh.  There are some platforms on which gprof is busted to various
degrees; you may have one.  What platform is this exactly?

            regards, tom lane

Mike Roest <mike.roest@replicon.com> writes:
> That was on the CentOS 5.8 x64 machine.  The one I'm trying it from now is
> Ubuntu 11.10 x64

Hm.  On current Red-Hat-derived systems I'd recommend oprofile, although
you need root privileges to use that.  Not real sure what is available
on Ubuntu, but our crib sheet for oprofile says it doesn't currently
work there:
http://wiki.postgresql.org/wiki/Profiling_with_OProfile
That could be out-of-date info though.  Here's some info about
another possibility:
http://wiki.postgresql.org/wiki/Profiling_with_perf

            regards, tom lane

Mike Roest <mike.roest@replicon.com> writes:
> The file is 6 megs so I've dropped it here.
> That was doing perf for the length of the pg_dump command and then a perf
> report -n
> http://dl.dropbox.com/u/13153/output.txt

Hmm ... that's a remarkably verbose output format, but the useful part
of this info seems to be just

# Events: 2M cpu-clock
#
# Overhead  Samples            Command                  Shared Object
Symbol
# ........ ..........  ...............  .............................
.................................................
#
    65.96%    1635392          pg_dump  pg_dump                        [.] findLoop
              |
              --- findLoop
                 |
                 |--69.66%-- findDependencyLoops
                 |          sortDumpableObjects
                 |          main
                 |          __libc_start_main
                 |
                 |--30.34%-- findLoop
                 |          findDependencyLoops
                 |          sortDumpableObjects
                 |          main
                 |          __libc_start_main
                  --0.00%-- [...]

    10.16%     251955          pg_dump  pg_dump                        [.] getTables
              |
              --- getTables
                  getSchemaData
                  main
                  __libc_start_main


The file also shows that findObjectByDumpId() accounts for only a
negligible percentage of runtime, which means that the recursion path in
findLoop() is being executed hardly at all.  After staring at that for
awhile I realized that what is the O(N^2) part is the initial "is the
object in the workspace?" test.  The actual dependency chains are
probably never very long, but as we run through the collection of
objects we gradually add all of them to the front of the workspace.
So this is dumb; we should manage the "is the object already processed"
component of that with an O(1) check, like a bool array or some such,
rather than an O(N) search loop.

As for the getTables slowdown, the only part of that I can see that
looks to be both significant and entirely contained in getTables()
itself is the nested loop near the end that's trying to copy
the dumpable flags for owned sequences from their owning tables.
Do you have a whole lot of owned sequences?  Maybe we could postpone
that work until we have the fast table lookup array constructed,
which should reduce this from O(M*N) to O(M*logN).

            regards, tom lane

I wrote:
> So this is dumb; we should manage the "is the object already processed"
> component of that with an O(1) check, like a bool array or some such,
> rather than an O(N) search loop.

> As for the getTables slowdown, the only part of that I can see that
> looks to be both significant and entirely contained in getTables()
> itself is the nested loop near the end that's trying to copy
> the dumpable flags for owned sequences from their owning tables.
> Do you have a whole lot of owned sequences?  Maybe we could postpone
> that work until we have the fast table lookup array constructed,
> which should reduce this from O(M*N) to O(M*logN).

I've committed fixes for both these issues.  If you are in a position to
test with 9.1 branch tip from git, it'd be nice to have confirmation
that these patches actually cure your problem.  For both of them, the
issue seems to only show up in a subset of cases, which may explain why
we'd not identified the problem before.

            regards, tom lane

Mike Roest <mike.roest@replicon.com> writes:
> Any idea when 9.1.4 with this change will be out so we can pull the cluster
> up.

Well, we just did some releases last month, so unless somebody finds a
really nasty security or data-loss issue, I'd think it will be a couple
of months before the next set.

            regards, tom lane