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 maintCo24_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
