I recently moved a medium sized web project (50 normalized tables in the database) from mysql to postgres (latest version, 7.4.2 I think). Getting 90% of the functionality to work was fairly easy to do in a few hours and in two work days, I did the following:

- I modified all the hibernate mappings to do sequences and I had to fix how some of the sets were mapped
- I changed some of the dao and service code to respect the new foreign keys that I added into the data definition script, such as cleaning up my delete code and so on
- I created indexs for all the where clauses for every query done by the application.

Now that I have tested all the functionality in the system, I believe that the conversion is complete and working 99.5% (There is bound to be something that doesn't work, but I'm satisfied for right now since performance is a bigger issue).

Anyway, I noticed that the speed has dropped considerably. I had already implemented lazy-loading when mysql was used, so I'm not really sure what else I can do to speed it up. I guess this is sort of hard to ask why it is going slow, but it usually takes between 1 to 5 seconds to load a page (and this is with fine-grained loading to ensure that many domain objects will not be loaded if they are not needed).

The only thing I can think of is to select specific fields out of the database instead of domain objects, but that sort of defeats the purpose of hibernate, doesn't it? I wish I could just load a sub-set of fields into a domain object, but it seems that hibernate wants to return a list of objects instead for each field selected, forcing me to map them back into a hashmap to make it easy for the upper layers to work with it. While I can why this was done since domain logic might fail when the fields are initialized, this makes it harder for me :) Oh well, I don't really want to do this approach anyway if it's not necessary...

Since mysql was working fairly well once the lazy-loading was implemented, I'm surprised to see postgres work so much slower. I mean, this is not half the performance - I think it's really going 1500% slower than before.

Since I don't expect anyone to fully answer my question since this problem could be very specific to my application design, I was wondering if anyone could direct me to a few links/articles that can help me tune postgres/hibernate. So basically I need someone to help me help myself :)

Oh yeah, I'm using the following tools:
- Spring, Hibernate, velocity
- resin

Thank you very much for your help. I'm not an expert at postgres (although I have read the many and most of the important chapers in the addison wesley postgres book), so whatever help you can give me would be great.

Regards,
Ken Egervari

In an environment with low concurrency, postgres is usually significantly slower than MySQL.

Are you sure you aren't doing too much laziness? It is usually more important to keep the number of round trips to the database under control. Usually we use outer-join fetching to achieve this.

Instead of looking at the big picture, figure out what is actually causing the slowdown.

1. Enable SQL logging and for each page (or better, use case), write down what SQL is executed. How many Selects, how many joins, too much data fetched, etc.

2. Figure out if you can reduce the number of SQL queries for each use case by tuning lazy and eager fetching. First in the mapping files, then runtime queries that use eager and/or lazy fetching.

3. Think about your database optimization again. Simply setting indexes for all "where clause columns" is going to kill your performance! There is no simple and easy answer, but instead of doing ad hoc optimization, consider reading "SQL Tuning" by Dan Tow. Excellent book.

Thank you so much for the speedy replies. I'm going to try out some of this advice and buy that book. Just a test, I wanted to see how long some queries were taking in milliseconds, so I looped it several times and here are the results.

I suspect that caching is actually working because the provider isn't giving any errors and the first one took longer than the others. Also, I think the third query is relatively the same because it's using cached objects from the second one. I kind of wished that the caching wasn't working so I'd have something blame it on, but as it stands, the performance is just too slow :/

findAllPagesByName took: 266
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findRootMenuItemWithLanguage took: 531
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllRootMenuItems took: 172

- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllPagesByName took: 187
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findRootMenuItemWithLanguage took: 172
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllRootMenuItems took: 235

- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllPagesByName took: 125
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findRootMenuItemWithLanguage took: 234
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllRootMenuItems took: 156

- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllPagesByName took: 172
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findRootMenuItemWithLanguage took: 172
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllRootMenuItems took: 218

- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllPagesByName took: 110
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findRootMenuItemWithLanguage took: 156
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllRootMenuItems took: 172

- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllPagesByName took: 109
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findRootMenuItemWithLanguage took: 157
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllRootMenuItems took: 140

- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllPagesByName took: 125
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findRootMenuItemWithLanguage took: 156
- Creating new JDBC connection to [jdbc:postgresql://localhost:5432/customshelpcms]
findAllRootMenuItems took: 157

I also did a fully populated Page domain object and the range was between 1100 and 1700 milliseconds - it's a good thing I never have to ever call that thing, but I think that's insane regardless.

The machine I'm on right now is just a plain athlon xp 2100 with 512mb ram, but I think this kind of performance on even a slower machine would cause some people to cringe :/

Seeing all the " Creating new JDBC connection" messages makes me think your session management is wrong. You should be getting a session from the factory for each thread, not each time you access Hibernate and the database. Try ThreadLocal if this is the problem.


Sherman

That makes a lot of sense, but I sort of thought Spring would be doing that for me :/ I'll google to see how I can change that with spring.

Also, I did some sql debug outputs. Here is the second pass, after the items are cached. I'm guessing that generating sql output in Idea probably slows the queries down by 300% - probably has something to do with the speed that it writes/directs output that gui window within IDEA. Anyway, here they are... they are freaking massive :((((

---

23:30:37,046 DEBUG SQL:237 - select page0_.id as id, page0_.pageAbstractionId as pageAbst2_, page0_.parentPageId as parentPa3_, page0_.languageId as languageId, page0_.ownerId as ownerId, page0_.viewId as viewId, page0_.name as name, page0_.headerName as headerName, page0_.title as title, page0_.content as content, page0_.keywords as keywords, page0_.isPublished as isPubli12_, page0_.publishedOn as publish13_, page0_.hideOnSitemap as hideOnS14_, page0_.allowComments as allowCo15_, page0_.createdOn as createdOn, page0_.isActive as isActive from page page0_ where (name=? )and(languageId=? )

---

findAllPagesByName took: 469

---

23:30:37,187 DEBUG SQL:237 - select menuitem0_.id as id, menuitem0_.parentId as parentId, menuitem0_.languageId as languageId, menuitem0_.name as name, menuitem0_.pageId as pageId, menuitem0_.orderIndex as orderIndex, menuitem0_.graphicHeight as graphicH7_, menuitem0_.graphicWidth as graphicW8_, menuitem0_.onGraphic as onGraphic, menuitem0_.offGraphic as offGraphic, menuitem0_.headerGraphic as headerG11_, menuitem0_.createdOn as createdOn, menuitem0_.isActive as isActive from menu_item menuitem0_ where (parentId is null )and(languageId=? )

23:30:37,203 DEBUG SQL:237 - select language0_.id as id0_, language0_.name as name0_, language0_.code as code0_, language0_.createdOn as createdOn0_, language0_.isActive as isActive0_ from language language0_ where language0_.id=?

23:30:37,203 DEBUG SQL:237 - select pageabstra0_.id as id0_, pageabstra0_.name as name0_, pageabstra0_.createdOn as createdOn0_, pageabstra0_.isActive as isActive0_ from page_abstraction pageabstra0_ where pageabstra0_.id=?

23:30:37,203 DEBUG SQL:237 - select user0_.id as id2_, user0_.firstName as firstName2_, user0_.lastName as lastName2_, user0_.username as username2_, user0_.password as password2_, user0_.sessionId as sessionId2_, user0_.userRoleId as userRoleId2_, user0_.createdOn as createdOn2_, user0_.isActive as isActive2_, session1_.id as id0_, session1_.sessionId as sessionId0_, session1_.createdOn as createdOn0_, session1_.isActive as isActive0_, userrole2_.id as id1_, userrole2_.name as name1_, userrole2_.level as level1_, userrole2_.createdOn as createdOn1_, userrole2_.isActive as isActive1_ from user_account user0_ left outer join session session1_ on user0_.sessionId=session1_.id left outer join user_role userrole2_ on user0_.userRoleId=userrole2_.id where user0_.id=?

23:30:37,218 DEBUG SQL:237 - select view0_.id as id1_, view0_.name as name1_, view0_.description as descript3_1_, view0_.decoratorPage as decorato4_1_, view0_.viewTypeId as viewTypeId1_, view0_.createdOn as createdOn1_, view0_.isActive as isActive1_, viewtype1_.id as id0_, viewtype1_.name as name0_, viewtype1_.description as descript3_0_, viewtype1_.createdOn as createdOn0_, viewtype1_.isActive as isActive0_ from view view0_ left outer join view_type viewtype1_ on view0_.viewTypeId=viewtype1_.id where view0_.id=?

23:30:37,234 DEBUG SQL:237 - select components0_.id as id__, components0_.viewId as viewId__, components0_.id as id3_, components0_.name as name3_, components0_.viewTypeId as viewTypeId3_, components0_.defaultIsVisible as defaultI4_3_, components0_.defaultViewId as defaultV5_3_, components0_.createdOn as createdOn3_, components0_.isActive as isActive3_, viewtype1_.id as id0_, viewtype1_.name as name0_, viewtype1_.description as descript3_0_, viewtype1_.createdOn as createdOn0_, viewtype1_.isActive as isActive0_, view2_.id as id1_, view2_.name as name1_, view2_.description as descript3_1_, view2_.decoratorPage as decorato4_1_, view2_.viewTypeId as viewTypeId1_, view2_.createdOn as createdOn1_, view2_.isActive as isActive1_, viewtype3_.id as id2_, viewtype3_.name as name2_, viewtype3_.description as descript3_2_, viewtype3_.createdOn as createdOn2_, viewtype3_.isActive as isActive2_ from view_component components0_ left outer join view_type viewtype1_ on components0_.viewTypeId=viewtype1_.id left outer join view view2_ on components0_.defaultViewId=view2_.id left outer join view_type viewtype3_ on view2_.viewTypeId=viewtype3_.id where components0_.viewId=? order by components0_.name

23:30:37,328 DEBUG SQL:237 - select components0_.id as id__, components0_.viewId as viewId__, components0_.id as id3_, components0_.name as name3_, components0_.viewTypeId as viewTypeId3_, components0_.defaultIsVisible as defaultI4_3_, components0_.defaultViewId as defaultV5_3_, components0_.createdOn as createdOn3_, components0_.isActive as isActive3_, viewtype1_.id as id0_, viewtype1_.name as name0_, viewtype1_.description as descript3_0_, viewtype1_.createdOn as createdOn0_, viewtype1_.isActive as isActive0_, view2_.id as id1_, view2_.name as name1_, view2_.description as descript3_1_, view2_.decoratorPage as decorato4_1_, view2_.viewTypeId as viewTypeId1_, view2_.createdOn as createdOn1_, view2_.isActive as isActive1_, viewtype3_.id as id2_, viewtype3_.name as name2_, viewtype3_.description as descript3_2_, viewtype3_.createdOn as createdOn2_, viewtype3_.isActive as isActive2_ from view_component components0_ left outer join view_type viewtype1_ on components0_.viewTypeId=viewtype1_.id left outer join view view2_ on components0_.defaultViewId=view2_.id left outer join view_type viewtype3_ on view2_.viewTypeId=viewtype3_.id where components0_.viewId=? order by components0_.name

23:30:37,343 DEBUG SQL:237 - select attributes0_.id as id__, attributes0_.viewId as viewId__, attributes0_.id as id0_, attributes0_.name as name0_, attributes0_.type as type0_, attributes0_.defaultValue as defaultV4_0_, attributes0_.createdOn as createdOn0_, attributes0_.isActive as isActive0_ from view_attribute attributes0_ where attributes0_.viewId=? order by attributes0_.name

23:30:37,453 DEBUG SQL:237 - select attributes0_.id as id__, attributes0_.viewId as viewId__, attributes0_.id as id0_, attributes0_.name as name0_, attributes0_.type as type0_, attributes0_.defaultValue as defaultV4_0_, attributes0_.createdOn as createdOn0_, attributes0_.isActive as isActive0_ from view_attribute attributes0_ where attributes0_.viewId=? order by attributes0_.name

23:30:37,453 DEBUG SQL:237 - select privileges0_.userPrivilegeId as userPriv2___, privileges0_.userId as userId__, userprivil1_.id as id0_, userprivil1_.name as name0_, userprivil1_.description as descript3_0_, userprivil1_.createdOn as createdOn0_, userprivil1_.isActive as isActive0_ from user_privilege_relation privileges0_ inner join user_privilege userprivil1_ on privileges0_.userPrivilegeId=userprivil1_.id where privileges0_.userId=?

23:30:37,468 DEBUG SQL:237 - select groups0_.userGroupId as userGrou2___, groups0_.userId as userId__, usergroup1_.id as id0_, usergroup1_.name as name0_, usergroup1_.level as level0_, usergroup1_.createdOn as createdOn0_, usergroup1_.isActive as isActive0_ from user_group_relation groups0_ inner join user_group usergroup1_ on groups0_.userGroupId=usergroup1_.id where groups0_.userId=?

---

findRootMenuItemWithLanguage took: 406

---

23:30:37,781 DEBUG SQL:237 - select menuitem0_.id as id, menuitem0_.parentId as parentId, menuitem0_.languageId as languageId, menuitem0_.name as name, menuitem0_.pageId as pageId, menuitem0_.orderIndex as orderIndex, menuitem0_.graphicHeight as graphicH7_, menuitem0_.graphicWidth as graphicW8_, menuitem0_.onGraphic as onGraphic, menuitem0_.offGraphic as offGraphic, menuitem0_.headerGraphic as headerG11_, menuitem0_.createdOn as createdOn, menuitem0_.isActive as isActive from menu_item menuitem0_ where (parentId is null )

23:30:37,796 DEBUG SQL:237 - select language0_.id as id0_, language0_.name as name0_, language0_.code as code0_, language0_.createdOn as createdOn0_, language0_.isActive as isActive0_ from language language0_ where language0_.id=?

23:30:37,796 DEBUG SQL:237 - select pageabstra0_.id as id0_, pageabstra0_.name as name0_, pageabstra0_.createdOn as createdOn0_, pageabstra0_.isActive as isActive0_ from page_abstraction pageabstra0_ where pageabstra0_.id=?

23:30:37,796 DEBUG SQL:237 - select user0_.id as id2_, user0_.firstName as firstName2_, user0_.lastName as lastName2_, user0_.username as username2_, user0_.password as password2_, user0_.sessionId as sessionId2_, user0_.userRoleId as userRoleId2_, user0_.createdOn as createdOn2_, user0_.isActive as isActive2_, session1_.id as id0_, session1_.sessionId as sessionId0_, session1_.createdOn as createdOn0_, session1_.isActive as isActive0_, userrole2_.id as id1_, userrole2_.name as name1_, userrole2_.level as level1_, userrole2_.createdOn as createdOn1_, userrole2_.isActive as isActive1_ from user_account user0_ left outer join session session1_ on user0_.sessionId=session1_.id left outer join user_role userrole2_ on user0_.userRoleId=userrole2_.id where user0_.id=?

23:30:37,812 DEBUG SQL:237 - select view0_.id as id1_, view0_.name as name1_, view0_.description as descript3_1_, view0_.decoratorPage as decorato4_1_, view0_.viewTypeId as viewTypeId1_, view0_.createdOn as createdOn1_, view0_.isActive as isActive1_, viewtype1_.id as id0_, viewtype1_.name as name0_, viewtype1_.description as descript3_0_, viewtype1_.createdOn as createdOn0_, viewtype1_.isActive as isActive0_ from view view0_ left outer join view_type viewtype1_ on view0_.viewTypeId=viewtype1_.id where view0_.id=?

23:30:37,828 DEBUG SQL:237 - select components0_.id as id__, components0_.viewId as viewId__, components0_.id as id3_, components0_.name as name3_, components0_.viewTypeId as viewTypeId3_, components0_.defaultIsVisible as defaultI4_3_, components0_.defaultViewId as defaultV5_3_, components0_.createdOn as createdOn3_, components0_.isActive as isActive3_, viewtype1_.id as id0_, viewtype1_.name as name0_, viewtype1_.description as descript3_0_, viewtype1_.createdOn as createdOn0_, viewtype1_.isActive as isActive0_, view2_.id as id1_, view2_.name as name1_, view2_.description as descript3_1_, view2_.decoratorPage as decorato4_1_, view2_.viewTypeId as viewTypeId1_, view2_.createdOn as createdOn1_, view2_.isActive as isActive1_, viewtype3_.id as id2_, viewtype3_.name as name2_, viewtype3_.description as descript3_2_, viewtype3_.createdOn as createdOn2_, viewtype3_.isActive as isActive2_ from view_component components0_ left outer join view_type viewtype1_ on components0_.viewTypeId=viewtype1_.id left outer join view view2_ on components0_.defaultViewId=view2_.id left outer join view_type viewtype3_ on view2_.viewTypeId=viewtype3_.id where components0_.viewId=? order by components0_.name

23:30:37,968 DEBUG SQL:237 - select components0_.id as id__, components0_.viewId as viewId__, components0_.id as id3_, components0_.name as name3_, components0_.viewTypeId as viewTypeId3_, components0_.defaultIsVisible as defaultI4_3_, components0_.defaultViewId as defaultV5_3_, components0_.createdOn as createdOn3_, components0_.isActive as isActive3_, viewtype1_.id as id0_, viewtype1_.name as name0_, viewtype1_.description as descript3_0_, viewtype1_.createdOn as createdOn0_, viewtype1_.isActive as isActive0_, view2_.id as id1_, view2_.name as name1_, view2_.description as descript3_1_, view2_.decoratorPage as decorato4_1_, view2_.viewTypeId as viewTypeId1_, view2_.createdOn as createdOn1_, view2_.isActive as isActive1_, viewtype3_.id as id2_, viewtype3_.name as name2_, viewtype3_.description as descript3_2_, viewtype3_.createdOn as createdOn2_, viewtype3_.isActive as isActive2_ from view_component components0_ left outer join view_type viewtype1_ on components0_.viewTypeId=viewtype1_.id left outer join view view2_ on components0_.defaultViewId=view2_.id left outer join view_type viewtype3_ on view2_.viewTypeId=viewtype3_.id where components0_.viewId=? order by components0_.name

23:30:37,968 DEBUG SQL:237 - select attributes0_.id as id__, attributes0_.viewId as viewId__, attributes0_.id as id0_, attributes0_.name as name0_, attributes0_.type as type0_, attributes0_.defaultValue as defaultV4_0_, attributes0_.createdOn as createdOn0_, attributes0_.isActive as isActive0_ from view_attribute attributes0_ where attributes0_.viewId=? order by attributes0_.name

23:30:37,984 DEBUG SQL:237 - select attributes0_.id as id__, attributes0_.viewId as viewId__, attributes0_.id as id0_, attributes0_.name as name0_, attributes0_.type as type0_, attributes0_.defaultValue as defaultV4_0_, attributes0_.createdOn as createdOn0_, attributes0_.isActive as isActive0_ from view_attribute attributes0_ where attributes0_.viewId=? order by attributes0_.name

23:30:38,000 DEBUG SQL:237 - select privileges0_.userPrivilegeId as userPriv2___, privileges0_.userId as userId__, userprivil1_.id as id0_, userprivil1_.name as name0_, userprivil1_.description as descript3_0_, userprivil1_.createdOn as createdOn0_, userprivil1_.isActive as isActive0_ from user_privilege_relation privileges0_ inner join user_privilege userprivil1_ on privileges0_.userPrivilegeId=userprivil1_.id where privileges0_.userId=?

23:30:38,000 DEBUG SQL:237 - select groups0_.userGroupId as userGrou2___, groups0_.userId as userId__, usergroup1_.id as id0_, usergroup1_.name as name0_, usergroup1_.level as level0_, usergroup1_.createdOn as createdOn0_, usergroup1_.isActive as isActive0_ from user_group_relation groups0_ inner join user_group usergroup1_ on groups0_.userGroupId=usergroup1_.id where groups0_.userId=?

findAllRootMenuItems took: 547

---

The weird thing is that they all take the same amount of time, which means the connection thingy is definately the issue here ;/ Anyone with threadlocal configuration for spring?

WOOT!

00:02:40,234 INFO SessionFactoryObjectFactory:82 - no JNDI name configured
findAllPagesByName took: 172
findRootMenuItemWithLanguage took: 141
findAllRootMenuItems took: 47

findAllPagesByName took: 78
findRootMenuItemWithLanguage took: 47
findAllRootMenuItems took: 31

=)

I just changed from org.springframework.jdbc.datasource.DriverManagerDataSource to org.apache.commons.dbcp.BasicDataSource and added the commons-pool and commons-dbcp packages and the speed difference is really something! Yay!

Thanks to everyone for helping me solve this. You guys rock.

Well, I did some more testing and the values started to stablize, albeit after several times of running my little test program. Here is what the values came out to be (below). Notice that cache is still turned on, significantly improving the speed of the queries.

So something tells me I can still get those other 2 test queries (and there are 50-60 others like those too) to be more efficient. However, I sort of need most of that data. Thoughts based on the select queries above?

findAllPagesByName took: 282
findRootMenuItemWithLanguage took: 453
findAllRootMenuItems took: 594

findAllPagesByName took: 15
findRootMenuItemWithLanguage took: 235
findAllRootMenuItems took: 218

findAllPagesByName took: 0
findRootMenuItemWithLanguage took: 297
findAllRootMenuItems took: 313

findAllPagesByName took: 0
findRootMenuItemWithLanguage took: 484
findAllRootMenuItems took: 297

findAllPagesByName took: 16
findRootMenuItemWithLanguage took: 250
findAllRootMenuItems took: 312

findAllPagesByName took: 16
findRootMenuItemWithLanguage took: 218
findAllRootMenuItems took: 250

findAllPagesByName took: 0
findRootMenuItemWithLanguage took: 391
findAllRootMenuItems took: 218

findAllPagesByName took: 0
findRootMenuItemWithLanguage took: 297
findAllRootMenuItems took: 219

findAllPagesByName took: 31
findRootMenuItemWithLanguage took: 250
findAllRootMenuItems took: 203

findAllPagesByName took: 0
findRootMenuItemWithLanguage took: 407
findAllRootMenuItems took: 203

1. dissable app logging.
2. enable SQL logging on postgres, stsistics collection, try to increase buffer count and sort memory (there are a lot of usefull parameters in postgresql.conf file).
3. trace query plan for queries you found "slow" or "popular" (open psql client and paste SQL with prefix "EXPLAIN ANALYSE " or do it for all queries in log with awk)

This is a very bad result for postgresql, as I understand tables like "menu" are very small, it must be possible to run this kind of queries 15 - 20 ms on PC.
BTW try to run script vacuumdb -a -z -f, drop TEXT fields and use varchar with limit if possible. It will not be much slow than mysql after you will tune it and it will be faster for "large" tables and it must scale better on high concurency.

I implemented a web-tier caching solution to store the results of commonly used (and expensive) service methods. This literally speed up my app by a trillion % =) While I have some pretty expensive queries running at acceptable speeds (10-40 ms), the caching brings it down to 0 ms. I figured with the eager loading and only 1 session being used for each query, I wasn't going to make it *that much* better with little piddle stuff. So, I just cache common stuff in my intercepters and controllers and update the cache when they are either updated or they time out. This seems to be very acceptable solution to the problem.