Michael, Thanks for bringing this to our attention and sharing some great data.
What you are seeing are calls that Hibernate makes. Hibernate is the Object-Relational Mapper (ORM) system much (not not yet all) of OpenNMS uses to map between Java objects and SQL. Both are very simple (albeit long) queries that get row(s) from the assets or ipInterface table and converts it/them into OnmsAsset or OnmsIpInterface objects, respectively. See create.sql for the SQL for the tables in question. And you can see the model objects in the source tree. http://opennms.git.sourceforge.net/git/gitweb.cgi?p=opennms/opennms;a=blob;f=opennms-base-assembly/src/main/filtered/etc/create.sql;h=6f6cbfec8bd197d9f31b9aef76fdbda65da583f8;hb=HEAD http://opennms.git.sourceforge.net/git/gitweb.cgi?p=opennms/opennms;a=tree;f=opennms-model/src/main/java/org/opennms/netmgt/model;h=e50ba1939d52390970ac090d4303f8e057a7a1bf;hb=HEAD I don't know if we can have Hibernate or our connection cache implementation cache prepared statements, but I hope that PostgreSQL is doing some caching of them. I'd be more curious about how much time is spent on creating the prepared statement relative to actually executing the statement so we can answer the question: do we get a significant (enough) performance benefit by reducing prepared statement creation to improve overall execution time of getting data from the database? What I'd be more interested in knowing is what in OpenNMS is making these calls. Can you get stack backtraces? What do you see in the logs when this is going on? Can you tie the startup slowdowns to a specific daemon? Specific startup activities based on what you see in the logs? Can you share the KSC graphs that are slow? There are some possible solutions once we get more details on what is causing these queries. Assets table rows are effectively an extension to the node rows, and in code that uses Hibernate, the assets data is loaded "lazily"--that is, only if it is actually accessed. If we have code that always needs to access the asset data for nodes, we can override that configuration for specific queries so that the asset data is loaded "eagerly." We can do a similar thing to load ipInterface data, if needed. But we need to know exactly where to enable it, otherwise we'll hurt performance everywhere else. Lastly, I think found one possible problem with our database schema: it looks like the nodeID column in the assets table does not have a unique index, so I think it might be possible for there to be multiple rows in the assets table for a single node. The OnmsAssets and OnmsNode objects both are annotated as having a OneToOne mapping with each other, so that's correct, at least. Thanks again, - djg PS: Hibernate always uses prepared statements since it is a best practice to minimize the chances of SQL injection attacks and other problems that are created when embedding data directly in SQL queries. On Wed, 01 Sep 2010 17:01 +0200, "Michael Seibold" <michael.seib...@barmer-gek.de> wrote: > Hi all, > > as our database grows -and probably also related to recent upgrades of > opennms from 1.7.10 -> 1.8.1 -> 1.8.3 - we get some performance issues > when starting opennms (about 7 minutes) and when using KSC graphs (3-5 > minutes). > > Using a trace tool we traced down two points where a lot of time gets > lost. Attached are the trace results. I'm no db guru but to me it seems > as if a method designed to prepare database queries is used in a wrong > place. Instead of preparing the statement once and then using it it seems > to me as if the prepare-method is called very often. > > First example: > > ------------------------------ > > Node Details > Method: prepareStatement(java.lang.String) > Class: $Proxy38 > Argument: select onmsassetr0_.id as id1_0_, onmsassetr0_.address1 > as address2_1_0_, onmsassetr0_.address2 as address3_1_0_, > onmsassetr0_.assetNumber as assetNum4_1_0_, onmsassetr0_.autoenable as > autoenable1_0_, onmsassetr0_.building as building1_0_, > onmsassetr0_.category as category1_0_, onmsassetr0_.circuitId as > circuitId1_0_, onmsassetr0_.city as city1_0_, onmsassetr0_.comment as > comment1_0_, onmsassetr0_.connection as connection1_0_, > onmsassetr0_.dateInstalled as dateIns12_1_0_, onmsassetr0_.department as > department1_0_, onmsassetr0_.description as descrip14_1_0_, > onmsassetr0_.displayCategory as display15_1_0_, onmsassetr0_.division as > division1_0_, onmsassetr0_.enable as enable1_0_, onmsassetr0_.floor as > floor1_0_, onmsassetr0_.userLastModified as userLas19_1_0_, > onmsassetr0_.lastModifiedDate as lastMod20_1_0_, onmsassetr0_.lease as > lease1_0_, onmsassetr0_.leaseExpires as leaseEx22_1_0_, > onmsassetr0_.maintContractExpires as maintCo23_1_0_, > onmsassetr0_.maintContract as ma > intCo24_1_0_, onmsassetr0_.managedObjectInstance as managed25_1_0_, > onmsassetr0_.managedObjectType as managed26_1_0_, > onmsassetr0_.manufacturer as manufac27_1_0_, onmsassetr0_.modelNumber as > modelNu28_1_0_, onmsassetr0_.nodeId as nodeId1_0_, > onmsassetr0_.notifyCategory as notifyC29_1_0_, > onmsassetr0_.operatingSystem as operati30_1_0_, onmsassetr0_.password as > password1_0_, onmsassetr0_.pollerCategory as pollerC32_1_0_, > onmsassetr0_.port as port1_0_, onmsassetr0_.rack as rack1_0_, > onmsassetr0_.region as region1_0_, onmsassetr0_.room as room1_0_, > onmsassetr0_.serialNumber as serialN37_1_0_, onmsassetr0_.slot as > slot1_0_, onmsassetr0_.state as state1_0_, onmsassetr0_.supportPhone as > support40_1_0_, onmsassetr0_.thresholdCategory as thresho41_1_0_, > onmsassetr0_.username as username1_0_, onmsassetr0_.vendor as > vendor1_0_, onmsassetr0_.vendorAssetNumber as vendorA44_1_0_, > onmsassetr0_.vendorFax as vendorFax1_0_, onmsassetr0_.vendorPhone as > vendorP46_1_0_, onmsassetr0_.zip as zip1_ > 0_ from assets onmsassetr0_ where onmsassetr0_.nodeId=? > Return: > Agent: open...@xxxxxx:7014 > API: JDBC > Thread Name: 741098...@qtp-1124264703-10 <741098834> > Time [ms]: 327427.78 Level: 19 Entry Hops: 5701 > Exit Hops: 5702 > > Time Details Total Exec % > Execution Time [ms]: 0.54 0.54 0.00 > Execution CPU Time [ms]: 0.54 0.54 0.00 > Sync Time [ms]: - - - > Wait Time [ms]: - - - > Runtime Suspension Time [ms]: - - - > Virtualization Suspension Time [ms]: - - - > > Source Information > File Name: - Line: - > > =============== > > This rather complex statement was called about 5,700 times using 327 > seconds. The execution time of each statement was about 0.54 ms which is > not too bad, i think. > > ------------------------------ > > Second example: > > > Node Details > Method: prepareStatement(java.lang.String) > Class: $Proxy38 > Argument: select ipinterfac0_.nodeId as nodeId1_, ipinterfac0_.id > as id1_, ipinterfac0_.id as id4_0_, ipinterfac0_.ipAddr as ipAddr4_0_, > ipinterfac0_.ipHostName as ipHostName4_0_, ipinterfac0_.ipLastCapsdPoll > as ipLastCa4_4_0_, ipinterfac0_.isManaged as isManaged4_0_, > ipinterfac0_.isSnmpPrimary as isSnmpPr6_4_0_, ipinterfac0_.nodeId as > nodeId4_0_, ipinterfac0_.snmpInterfaceId as snmpInte8_4_0_ from > ipInterface ipinterfac0_ where ipinterfac0_.nodeId=? > Return: > Agent: open...@xxxxxx:7014 > API: JDBC > Thread Name: 741098...@qtp-1124264703-10 <741098834> > Time [ms]: 398295.94 Level: 18 Entry Hops: 90880 > Exit Hops: 90881 > > Time Details Total Exec % > Execution Time [ms]: 0.15 0.15 0.00 > Execution CPU Time [ms]: 0.15 0.15 0.00 > Sync Time [ms]: - - - > Wait Time [ms]: - - - > Runtime Suspension Time [ms]: - - - > Virtualization Suspension Time [ms]: - - - > > Source Information > File Name: - Line: - > > > =============== > > This rather simple statement was called about 91,000 times using 398 > seconds. This number might be about 4 times the number of entries in > ipinterface table. The execution time of each statement was about 0.15 > ms so I believe the database is in a good condition. > > ------------------------------ > > > The trace was done on a solaris 10 with 64bit JVM and OpenNMS 1.8.3. > Trace tool was dynatrace. > > I already searched around in the source code but couldn't find the method > calling this prepare statements (as preparation is in several steps it's > a bit tricky). Maybe someone with more experience with the source code > can find it. > > Any help is appreciated. If needed we can trace again (out of office > time). > > - Michael > > ------------------------------------------------------------------------------ > This SF.net Dev2Dev email is sponsored by: > > Show off your parallel programming skills. > Enter the Intel(R) Threading Challenge 2010. > http://p.sf.net/sfu/intel-thread-sfd > _______________________________________________ > Please read the OpenNMS Mailing List FAQ: > http://www.opennms.org/index.php/Mailing_List_FAQ > > opennms-devel mailing list > > To *unsubscribe* or change your subscription options, see the bottom of > this page: > https://lists.sourceforge.net/lists/listinfo/opennms-devel > ------------------------------------------------------------------------------ This SF.net Dev2Dev email is sponsored by: Show off your parallel programming skills. Enter the Intel(R) Threading Challenge 2010. http://p.sf.net/sfu/intel-thread-sfd _______________________________________________ Please read the OpenNMS Mailing List FAQ: http://www.opennms.org/index.php/Mailing_List_FAQ opennms-devel mailing list To *unsubscribe* or change your subscription options, see the bottom of this page: https://lists.sourceforge.net/lists/listinfo/opennms-devel
