Thread: 5 minutes to pg_dump nothing
Hi all, I'm seeing a problem where pg_dump takes at least 5 minutes to execute no matter what I ask it to dump -- even a non-existent or empty table. One possible red flag is that pg_type contains 56508 rows. This doesn't seem excessive to me, but perhaps it should. I've looked through the source code and a system trace and I can see where the execution time disappears, but I can't pinpoint the source of the problem. Some background: the database contains about 1200 schemas with 30+ tables and 20+ custom types in each. The whole database is only about 12G. An empty table created in another database on the same machine pg_dumps in < .1sec, as expected. PG version is 8.1.4, OS is FreeBSD. When I run pg_dump in verbose mode, it stalls after printing "reading user-defined types". In the systrace, I can see the pg_types query at the top of getTypes() in pgdump.c followed by 628 reads of 4k blocks (= 2512k) which only takes a second or so in total. I guess this is the loop through the tuples in getTypes(). There's then four calls to getDomainConstraints() followed by a 129-second delay during which nothing appears in the system trace. After that, there's 124 pairs of these: 72263 pg_dump 135.956209 CALL break(0x9b37000) 72263 pg_dump 135.956222 RET break 0 They consume another 118 seconds, and then pg_dump moves on to "reading procedural languages". I've VACUUM FULL ANALYZEd everything I can think of. I'd really appreciate any further hints or help. PS - Thanks for Postgres; it works like a dream for me except for infrequent bumps. =) -- Philip http://NikitaTheSpider.com/ Whole-site HTML validation, link checking and more
"Nikita The Spider The Spider" <nikitathespider@gmail.com> writes: > I'm seeing a problem where pg_dump takes at least 5 minutes to execute > no matter what I ask it to dump -- even a non-existent or empty table. > One possible red flag is that pg_type contains 56508 rows. This > doesn't seem excessive to me, but perhaps it should. That does seem like a lot --- what sort of types are they? Scalar, composite, what? It's fairly likely that no one has tried to optimize pg_dump for such a case. It'd be helpful if you could recompile pg_dump with profiling enabled (-pg compiler switch) and get a gprof profile to show where the time is going. regards, tom lane
On 9/21/07, Tom Lane <tgl@sss.pgh.pa.us> wrote: > "Nikita The Spider The Spider" <nikitathespider@gmail.com> writes: > > I'm seeing a problem where pg_dump takes at least 5 minutes to execute > > no matter what I ask it to dump -- even a non-existent or empty table. > > One possible red flag is that pg_type contains 56508 rows. This > > doesn't seem excessive to me, but perhaps it should. > > That does seem like a lot --- what sort of types are they? Scalar, > composite, what? It's fairly likely that no one has tried to optimize > pg_dump for such a case. Aha, thanks. Didn't realize I was pushing the bounds of what was reasonable. Here's the type counts: typrelkind | the_count ------------+----------- | 114 sequence | 11496 composite | 12290 ordinary | 13844 TOAST | 9215 view | 9699 (6 rows) > It'd be helpful if you could recompile pg_dump with profiling enabled > (-pg compiler switch) and get a gprof profile to show where the time > is going. Will do. I'm going to try to recreate the problem in my development environment where I have a bit more freedom to tinker. -- Philip http://NikitaTheSpider.com/ Whole-site HTML validation, link checking and more
On 9/21/07, Nikita The Spider The Spider <nikitathespider@gmail.com> wrote: > On 9/21/07, Tom Lane <tgl@sss.pgh.pa.us> wrote: > > "Nikita The Spider The Spider" <nikitathespider@gmail.com> writes: > > > I'm seeing a problem where pg_dump takes at least 5 minutes to execute > > > no matter what I ask it to dump -- even a non-existent or empty table. > > > One possible red flag is that pg_type contains 56508 rows. This > > > doesn't seem excessive to me, but perhaps it should. > > > > That does seem like a lot --- what sort of types are they? Scalar, > > composite, what? It's fairly likely that no one has tried to optimize > > pg_dump for such a case. > > Aha, thanks. Didn't realize I was pushing the bounds of what was > reasonable. Here's the type counts: > typrelkind | the_count > ------------+----------- > | 114 > sequence | 11496 > composite | 12290 > ordinary | 13844 > TOAST | 9215 > view | 9699 > (6 rows) I think I found the problem. getTypes() calls findFuncByOid() twice for each item it sees. A comment at the top of findFuncByOid() says, "should hash this, but just do linear search for now". So that funtion is O(n)/2 where n = the # of functions found by the query in getFuncs(), and since it's called twice for each item in getTypes, the overall performance is O(m * n) where n = # of functions and m = # of types. As I said before, I have ~56000 items in pg_type and the query at the top of getFuncs returns ~98000 rows so for me performance is O(5.4 billion)-ish. Some experimentation backs up my assertion that this is the performance bottleneck. I created another database on the same machine with 10k each of tables, views and custom types. The tables contained a SERIAL PRIMARY KEY and a text column so that PG created indexes and TOAST tables to go along with them. The result was ~50000 items in pg_type. When I run pg_dump against this database, it completes in 4 seconds so simply having a lot of items in pg_type is not enough to recreate my problem. I added 100k functions to that database and pg_dump took several minutes to run (again, trying to dump a non-existent table), which is what I'm seeing on my production database. My database design aimed to make each of my 1600 or so schemas its own little self-sufficent world, hence the proliferation of types and functions. I didn't realize that at some level they're all effectively in the same namespace. Now I know. Sorry I can't offer a patch. It'd be fun to write C code again but my skills are pretty rusty and I'm afraid I'd butcher it. :-P Thanks for your help! Given that this problem seems to be triggered by a sort of edge case and the fix is non-trivial, I guess I should not expect a new version of pg_dump soon? Cheers -- Philip http://NikitaTheSpider.com/ Whole-site HTML validation, link checking and more
"Nikita The Spider The Spider" <nikitathespider@gmail.com> writes: > I think I found the problem. getTypes() calls findFuncByOid() twice > for each item it sees. A comment at the top of findFuncByOid() says, > "should hash this, but just do linear search for now". So that funtion > is O(n)/2 where n = the # of functions found by the query in > getFuncs(), and since it's called twice for each item in getTypes, the > overall performance is O(m * n) where n = # of functions and m = # of > types. As I said before, I have ~56000 items in pg_type and the query > at the top of getFuncs returns ~98000 rows so for me performance is > O(5.4 billion)-ish. Hah, so you need *both* a lot of types and a lot of functions to have a problem. > Thanks for your help! Given that this problem seems to be triggered by > a sort of edge case and the fix is non-trivial, I guess I should not > expect a new version of pg_dump soon? We might look into fixing it for 8.3, but I doubt we'd risk back-patching such a change to older branches. regards, tom lane
I wrote: > "Nikita The Spider The Spider" <nikitathespider@gmail.com> writes: >> Thanks for your help! Given that this problem seems to be triggered by >> a sort of edge case and the fix is non-trivial, I guess I should not >> expect a new version of pg_dump soon? > We might look into fixing it for 8.3, but I doubt we'd risk back-patching > such a change to older branches. Actually, it doesn't look that hard --- want to try the attached patch? I couldn't measure any speed difference at all on the standard PG regression-test database, but there are not huge numbers of objects in that. regards, tom lane Index: common.c =================================================================== RCS file: /cvsroot/pgsql/src/bin/pg_dump/common.c,v retrieving revision 1.97 diff -c -r1.97 common.c *** common.c 21 Aug 2007 01:11:20 -0000 1.97 --- common.c 23 Sep 2007 23:37:32 -0000 *************** *** 41,47 **** /* * These variables are static to avoid the notational cruft of having to pass ! * them into findTableByOid() and friends. */ static TableInfo *tblinfo; static TypeInfo *typinfo; --- 41,51 ---- /* * These variables are static to avoid the notational cruft of having to pass ! * them into findTableByOid() and friends. For each of these arrays, we ! * build a sorted-by-OID index array immediately after it's built, and then ! * we use binary search in findTableByOid() and friends. (qsort'ing the base ! * arrays themselves would be simpler, but it doesn't work because pg_dump.c ! * may have already established pointers between items.) */ static TableInfo *tblinfo; static TypeInfo *typinfo; *************** *** 51,62 **** --- 55,72 ---- static int numTypes; static int numFuncs; static int numOperators; + static DumpableObject **tblinfoindex; + static DumpableObject **typinfoindex; + static DumpableObject **funinfoindex; + static DumpableObject **oprinfoindex; static void flagInhTables(TableInfo *tbinfo, int numTables, InhInfo *inhinfo, int numInherits); static void flagInhAttrs(TableInfo *tbinfo, int numTables, InhInfo *inhinfo, int numInherits); + static DumpableObject **buildIndexArray(void *objArray, int numObjs, + Size objSize); static int DOCatalogIdCompare(const void *p1, const void *p2); static void findParentsByOid(TableInfo *self, InhInfo *inhinfo, int numInherits); *************** *** 104,114 **** --- 114,126 ---- if (g_verbose) write_msg(NULL, "reading user-defined functions\n"); funinfo = getFuncs(&numFuncs); + funinfoindex = buildIndexArray(funinfo, numFuncs, sizeof(FuncInfo)); /* this must be after getFuncs */ if (g_verbose) write_msg(NULL, "reading user-defined types\n"); typinfo = getTypes(&numTypes); + typinfoindex = buildIndexArray(typinfo, numTypes, sizeof(TypeInfo)); /* this must be after getFuncs, too */ if (g_verbose) *************** *** 122,127 **** --- 134,140 ---- if (g_verbose) write_msg(NULL, "reading user-defined operators\n"); oprinfo = getOperators(&numOperators); + oprinfoindex = buildIndexArray(oprinfo, numOperators, sizeof(OprInfo)); if (g_verbose) write_msg(NULL, "reading user-defined operator classes\n"); *************** *** 154,159 **** --- 167,173 ---- if (g_verbose) write_msg(NULL, "reading user-defined tables\n"); tblinfo = getTables(&numTables); + tblinfoindex = buildIndexArray(tblinfo, numTables, sizeof(TableInfo)); if (g_verbose) write_msg(NULL, "reading table inheritance information\n"); *************** *** 540,545 **** --- 554,623 ---- return NULL; } + /* + * Find a DumpableObject by OID, in a pre-sorted array of one type of object + * + * Returns NULL for unknown OID + */ + static DumpableObject * + findObjectByOid(Oid oid, DumpableObject **indexArray, int numObjs) + { + DumpableObject **low; + DumpableObject **high; + + /* + * This is the same as findObjectByCatalogId except we assume we need + * not look at table OID because the objects are all the same type. + * + * We could use bsearch() here, but the notational cruft of calling + * bsearch is nearly as bad as doing it ourselves; and the generalized + * bsearch function is noticeably slower as well. + */ + if (numObjs <= 0) + return NULL; + low = indexArray; + high = indexArray + (numObjs - 1); + while (low <= high) + { + DumpableObject **middle; + int difference; + + middle = low + (high - low) / 2; + difference = oidcmp((*middle)->catId.oid, oid); + if (difference == 0) + return *middle; + else if (difference < 0) + low = middle + 1; + else + high = middle - 1; + } + return NULL; + } + + /* + * Build an index array of DumpableObject pointers, sorted by OID + */ + static DumpableObject ** + buildIndexArray(void *objArray, int numObjs, Size objSize) + { + DumpableObject **ptrs; + int i; + + ptrs = (DumpableObject **) malloc(numObjs * sizeof(DumpableObject *)); + for (i = 0; i < numObjs; i++) + ptrs[i] = (DumpableObject *) ((char *) objArray + i * objSize); + + /* We can use DOCatalogIdCompare to sort since its first key is OID */ + if (numObjs > 1) + qsort((void *) ptrs, numObjs, sizeof(DumpableObject *), + DOCatalogIdCompare); + + return ptrs; + } + + /* + * qsort comparator for pointers to DumpableObjects + */ static int DOCatalogIdCompare(const void *p1, const void *p2) { *************** *** 630,709 **** * findTableByOid * finds the entry (in tblinfo) of the table with the given oid * returns NULL if not found - * - * NOTE: should hash this, but just do linear search for now */ TableInfo * findTableByOid(Oid oid) { ! int i; ! ! for (i = 0; i < numTables; i++) ! { ! if (tblinfo[i].dobj.catId.oid == oid) ! return &tblinfo[i]; ! } ! return NULL; } /* * findTypeByOid * finds the entry (in typinfo) of the type with the given oid * returns NULL if not found - * - * NOTE: should hash this, but just do linear search for now */ TypeInfo * findTypeByOid(Oid oid) { ! int i; ! ! for (i = 0; i < numTypes; i++) ! { ! if (typinfo[i].dobj.catId.oid == oid) ! return &typinfo[i]; ! } ! return NULL; } /* * findFuncByOid * finds the entry (in funinfo) of the function with the given oid * returns NULL if not found - * - * NOTE: should hash this, but just do linear search for now */ FuncInfo * findFuncByOid(Oid oid) { ! int i; ! ! for (i = 0; i < numFuncs; i++) ! { ! if (funinfo[i].dobj.catId.oid == oid) ! return &funinfo[i]; ! } ! return NULL; } /* * findOprByOid * finds the entry (in oprinfo) of the operator with the given oid * returns NULL if not found - * - * NOTE: should hash this, but just do linear search for now */ OprInfo * findOprByOid(Oid oid) { ! int i; ! ! for (i = 0; i < numOperators; i++) ! { ! if (oprinfo[i].dobj.catId.oid == oid) ! return &oprinfo[i]; ! } ! return NULL; } --- 708,751 ---- * findTableByOid * finds the entry (in tblinfo) of the table with the given oid * returns NULL if not found */ TableInfo * findTableByOid(Oid oid) { ! return (TableInfo *) findObjectByOid(oid, tblinfoindex, numTables); } /* * findTypeByOid * finds the entry (in typinfo) of the type with the given oid * returns NULL if not found */ TypeInfo * findTypeByOid(Oid oid) { ! return (TypeInfo *) findObjectByOid(oid, typinfoindex, numTypes); } /* * findFuncByOid * finds the entry (in funinfo) of the function with the given oid * returns NULL if not found */ FuncInfo * findFuncByOid(Oid oid) { ! return (FuncInfo *) findObjectByOid(oid, funinfoindex, numFuncs); } /* * findOprByOid * finds the entry (in oprinfo) of the operator with the given oid * returns NULL if not found */ OprInfo * findOprByOid(Oid oid) { ! return (OprInfo *) findObjectByOid(oid, oprinfoindex, numOperators); }
On 9/23/07, Tom Lane <tgl@sss.pgh.pa.us> wrote: > I wrote: > > "Nikita The Spider The Spider" <nikitathespider@gmail.com> writes: > >> Thanks for your help! Given that this problem seems to be triggered by > >> a sort of edge case and the fix is non-trivial, I guess I should not > >> expect a new version of pg_dump soon? > > > We might look into fixing it for 8.3, but I doubt we'd risk back-patching > > such a change to older branches. > > Actually, it doesn't look that hard --- want to try the attached patch? > I couldn't measure any speed difference at all on the standard PG > regression-test database, but there are not huge numbers of objects > in that. Tom, Your patch decreases the runtime of pg_dump by an order of magnitude for me which means I don't have to roll my own table dumper. Thanks very much for the swift turnaround and for a great database. -- Philip http://NikitaTheSpider.com/ Whole-site HTML validation, link checking and more