5 Replies Latest reply on Jan 15, 2008 8:15 AM by mircea.markus

    JDBCCacheLoader bad performance when writing to DB

      I use JDBCCacheLoader (JBossCache 2.0.0GA & Oracle in JBossAS) to persist a cahe to DB. When the cache is big it takes hours to persist.

      It takes a lot of time to write the item into the DB. i loaded YourKit profiler to analyze the problem and learned that most time is spent in running SQL commands. YouKit shows that the time is spent mostly on Oracle driver's executeQuery & pingDatabase commands and that the following SQL commands are run:

      1. 2600 * insert into jbosscache_table (obvious)
      2. 15000 * select node from jbosscache_table where fqn=?
      3. 600 * update jbosscache_table set node=? where fqn=?

      i don't understand why there are 6 times more "select" statements than "insert".

      Is it related to the number of '/' in the item key?

        • 1. Re: JDBCCacheLoader bad performance when writing to DB

          when setting log priority to debug, i get the following. It means that when i add a node to the cache, for each node the same select query is running 4 times. When the cache has thousands of nodes, it's a huge overhead.

          16:59:37,992 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/3-CHILDREN-2-2)
          16:59:38,007 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/3-CHILDREN-2-2)
          16:59:38,007 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/3-CHILDREN-2-2)
          16:59:38,007 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/3-CHILDREN-2-2)
          16:59:38,007 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/1-SIBLINGS-1-1)
          16:59:38,023 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/1-SIBLINGS-1-1)
          16:59:38,023 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/1-SIBLINGS-1-1)
          16:59:38,023 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/1-SIBLINGS-1-1)
          16:59:38,039 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/2-SIBLINGS-440-440)
          16:59:38,039 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/2-SIBLINGS-440-440)
          16:59:38,054 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/2-SIBLINGS-440-440)
          16:59:38,054 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/2-SIBLINGS-440-440)
          16:59:38,070 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/2-LOWER-440-440)
          16:59:38,070 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/2-LOWER-440-440)
          16:59:38,070 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/2-LOWER-440-440)
          16:59:38,085 DEBUG [JDBCCacheLoader] executing sql: select node from jbosscache_1 where fqn=? (/aag/queries/d1-1-d2-0-d3-1347132-d4-0-d5-0-d7-6-d9-109-d14-0-d15-0-24-2/2-LOWER-440-440)
          


          • 2. Re: JDBCCacheLoader bad performance when writing to DB

            Actually, the log above is for nodes that were laready in the DB. New nodes inserted into the DB, result in 8 select qeuries which are exatcly the same.

            here is an exmaple of inserting only 2 nodes:

            for (int i=0 ; i<2 ; i++){
             Address a = new Address();
             a.setCity("a"+i);
             a.setZip(i);
             cache.put("cat","x"+i,a);
             }
            


            result:

            17:55:46,094 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/)
            17:55:46,438 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,438 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,453 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,453 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,453 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,469 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,469 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,485 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,563 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x0/_ID_/5c4oa2y-6zewp7-fb3ro8v8-1-fb3ro8v8-2)
            17:55:46,578 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/__JBossInternal__/cat/x0/_ID_/5c4oa2y-6zewp7-fb3ro8v8-1-fb3ro8v8-2)
            17:55:46,672 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x0/_ID_)
            17:55:46,672 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/__JBossInternal__/cat/x0/_ID_)
            17:55:46,735 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x0)
            17:55:46,735 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/__JBossInternal__/cat/x0)
            17:55:46,750 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat)
            17:55:46,750 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/__JBossInternal__/cat)
            17:55:46,750 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__)
            17:55:46,766 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/__JBossInternal__)
            17:55:46,782 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/)
            17:55:46,782 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/)
            17:55:46,797 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x0/_ID_/5c4oa2y-6zewp7-fb3ro8v8-1-fb3ro8v8-2)
            17:55:46,813 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x0/_ID_/5c4oa2y-6zewp7-fb3ro8v8-1-fb3ro8v8-2)
            17:55:46,829 DEBUG [JDBCCacheLoader] executing sql: update ALLERGAN04.jbosscache_test set node=? where fqn=?
            17:55:46,844 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,860 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x0)
            17:55:46,860 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/cat/x0)
            17:55:46,875 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat)
            17:55:46,875 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/cat)
            17:55:46,891 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/)
            17:55:46,907 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:46,907 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:46,907 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:46,922 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:46,922 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:46,938 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:46,938 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:46,954 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:46,954 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x1/_ID_/5c4oa2y-6zewp7-fb3ro8v8-1-fb3ro96y-3)
            17:55:46,969 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/__JBossInternal__/cat/x1/_ID_/5c4oa2y-6zewp7-fb3ro8v8-1-fb3ro96y-3)
            17:55:46,985 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x1/_ID_)
            17:55:46,985 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/__JBossInternal__/cat/x1/_ID_)
            17:55:46,985 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x1)
            17:55:47,000 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/__JBossInternal__/cat/x1)
            17:55:47,000 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat)
            17:55:47,016 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x1/_ID_/5c4oa2y-6zewp7-fb3ro8v8-1-fb3ro96y-3)
            17:55:47,016 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/__JBossInternal__/cat/x1/_ID_/5c4oa2y-6zewp7-fb3ro8v8-1-fb3ro96y-3)
            17:55:47,032 DEBUG [JDBCCacheLoader] executing sql: update ALLERGAN04.jbosscache_test set node=? where fqn=?
            17:55:47,047 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:47,047 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat/x1)
            17:55:47,063 DEBUG [JDBCCacheLoader] executing sql: insert into ALLERGAN04.jbosscache_test (fqn, node, parent) values (?, ?, ?) (/cat/x1)
            17:55:47,063 DEBUG [JDBCCacheLoader] executing sql: select node from ALLERGAN04.jbosscache_test where fqn=? (/cat)


            • 3. Re: JDBCCacheLoader bad performance when writing to DB
              mircea.markus

              What cache version are you using?
              The logs you sent indicate you are using POJO cache (__JBossInternal__ is POJO cache internal), but the API you are using is Cache specific. Can you supply the entire JAVA class of test

              • 4. Re: JDBCCacheLoader bad performance when writing to DB

                I'm using pojo cache with JBossCache2.0.0GA. I didn't notice I use our own a wrapper in the code above.

                It should be:

                cache.attach("cat/x"+i,"some_data");
                


                which gives the same results.

                • 5. Re: JDBCCacheLoader bad performance when writing to DB
                  mircea.markus

                  please take a look at last comment on http://jira.jboss.org/jira/browse/JBCACHE-1261