Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Cannot Reproduce
    • Affects Version/s: 10.4.1.3, 10.4.2.0
    • Fix Version/s: None
    • Component/s: SQL
    • Environment:
      OS: Windows Vista
      Application environment: Java 1.5 Swing Application using Derby DB in the embedded mode as part of the application.
    • Urgency:
      Normal
    • Issue & fix info:
      High Value Fix, Repro attached, Workaround attached
    • Bug behavior facts:
      Performance

      Description

      Having the following db schema:
      CREATE TABLE Messaged_Users (ACCOUNT_ID VARCHAR(20) NOT NULL,
      USER_ID VARCHAR(20) NOT NULL,
      DATE TIMESTAMP DEFAULT CURRENT_TIMESTAMP,
      STATUS INT DEFAULT 0,
      CONSTRAINT PK_ACC_USER_ID PRIMARY KEY (ACCOUNT_ID, USER_ID))
      CREATE TABLE Users (USER_ID VARCHAR(20) NOT NULL CONSTRAINT USER_ID_PK PRIMARY KEY,
      USER_NAME VARCHAR(50) NOT NULL)
      with approximately 100,000 records in each table and trying to execute the following query:
      PreparedStatement searchStatement = conn.prepareStatement("SELECT b.USER_ID, b.USER_NAME FROM Users a JOIN Messaged_Users b ON a.USER_ID=b.USER_ID AND a.ACCOUNT_ID=");
      searchStatement.setString(1, "5533232");
      ResultSet foundUsers = searchStatement.executeQuery();
      the executeQuery method actually never ends. I've waited for more than 30 mins and it didn't finish. I've tried it really many times but without any progress the query just hangs. I presume that this is definitely a bug in the derby db which should be fixed. Please note also that this fix is very urgent for us so that we can deliver our application.

      Thanks in advance for looking into this issue.

      1. query_plan.jpg
        44 kB
        Nirmal Fernando
      2. query_plan_derby_3892.pdf
        75 kB
        Nirmal Fernando
      3. Main.java
        5 kB
        Dag H. Wanvik
      4. Main_Updated.java
        6 kB
        Georgi Hristov
      5. Main_Updated.java
        7 kB
        Georgi Hristov
      6. Main_Updated.java
        7 kB
        Bryan Pendleton
      7. Main_Bryan.java
        7 kB
        Bryan Pendleton
      8. derbyTwoDifferentOneHundredKPlans.log
        11 kB
        Bryan Pendleton
      9. derby_50kRows.log
        3 kB
        Bryan Pendleton

        Activity

        Hide
        Bryan Pendleton added a comment -

        Here are some starting points for researching performance problems:
        http://wiki.apache.org/db-derby/PerformanceDiagnosisTips

        Knowing the query plan would be very interesting. To get that, you
        may wish to start by trimming your data set down to a smaller number
        of records, so that the query runs in a more timely fashion.

        You might also wish to post a message to derby-users, rather than
        filing a bug, as that might get you more suggestions for how to
        improve performance.

        Show
        Bryan Pendleton added a comment - Here are some starting points for researching performance problems: http://wiki.apache.org/db-derby/PerformanceDiagnosisTips Knowing the query plan would be very interesting. To get that, you may wish to start by trimming your data set down to a smaller number of records, so that the query runs in a more timely fashion. You might also wish to post a message to derby-users, rather than filing a bug, as that might get you more suggestions for how to improve performance.
        Hide
        Georgi Hristov added a comment -

        Thanks for the quick response and the useful advices. I want to point out that this issue report do not target performance regression as desribed in the provided link but simply demonstrates that the described query just hangs, or lets say that depending on the amount of records in the table, the time needed for the query to finish rises exponentially. I thought that it will be interesting for you to try it out locally as from my point of view it is very easy to set up the environment locally. I've provided the table descriptions, just insert about 100,000 records in each, and run the query. I hoped that by reporting the issue directly to you, instead of trying to analyze the execution plan or even debug derby's code, I'll finally reach to the solution/bug fix, but I thought that you can do it faster than me and this is really important for application delivery date. Please let me know if you will to try it on your side or will leave me to struggle on my own.

        Show
        Georgi Hristov added a comment - Thanks for the quick response and the useful advices. I want to point out that this issue report do not target performance regression as desribed in the provided link but simply demonstrates that the described query just hangs, or lets say that depending on the amount of records in the table, the time needed for the query to finish rises exponentially. I thought that it will be interesting for you to try it out locally as from my point of view it is very easy to set up the environment locally. I've provided the table descriptions, just insert about 100,000 records in each, and run the query. I hoped that by reporting the issue directly to you, instead of trying to analyze the execution plan or even debug derby's code, I'll finally reach to the solution/bug fix, but I thought that you can do it faster than me and this is really important for application delivery date. Please let me know if you will to try it on your side or will leave me to struggle on my own.
        Hide
        Dag H. Wanvik added a comment -

        I tried to reproduce this (see Main.java uploaded), with 100000 rows in each table,
        but it ran in ca a minute on my box, most of the time inserting the data.
        I had to modify the JOIN statement though, switching A and B in places to make it compile.
        Could your cardinality statistics be out of date (commented out call to COMPRESS_TABLE in the
        enclosed would update them)?

        Show
        Dag H. Wanvik added a comment - I tried to reproduce this (see Main.java uploaded), with 100000 rows in each table, but it ran in ca a minute on my box, most of the time inserting the data. I had to modify the JOIN statement though, switching A and B in places to make it compile. Could your cardinality statistics be out of date (commented out call to COMPRESS_TABLE in the enclosed would update them)?
        Hide
        Bryan Pendleton added a comment -

        Main.java ran to completion in about 2 minutes on my computer. For me,
        too, most of the time was spent inserting the data.

        Show
        Bryan Pendleton added a comment - Main.java ran to completion in about 2 minutes on my computer. For me, too, most of the time was spent inserting the data.
        Hide
        Georgi Hristov added a comment -

        Please find attached an updated version of the Main.java (Main_Updated.java) which hangs for real. It turns out that not the query hangs but the ResultSet afterwards used to loop through the retrieved table records. It took me really a lot of time to figure out how exactly the issue I have locally is getting reproduced that's why I want to apologize for my delayed answer to this issue.

        Show
        Georgi Hristov added a comment - Please find attached an updated version of the Main.java (Main_Updated.java) which hangs for real. It turns out that not the query hangs but the ResultSet afterwards used to loop through the retrieved table records. It took me really a lot of time to figure out how exactly the issue I have locally is getting reproduced that's why I want to apologize for my delayed answer to this issue.
        Hide
        Bryan Pendleton added a comment -

        I modified the test program some more:

        • added some more output so I could understand what it was doing
        • made the number of rows configurable.

        Then I ran the program about half a dozen times, gradually increasing
        the data size, to see what it was doing.

        Certainly the times are not growing linearly, but they are not growing
        all that badly either. I can run the program with 40,000 rows in about 10 minutes.

        I also took a look at the query plan, and it seems that the query is
        using a reasonable query plan:

        • scan Messaged_Users
        • for each Messaged_user which matched the account ID
        • query Users for that user id

        Lastly, I looked at the program, and it seems that half the rows in the
        Messaged_users table are for account 5324, and the other half are
        for other accounts. So when we try to run the program with 100,000 rows,
        we are processing 100,000 rows for account 5324, out of the 200,000
        rows in the messaged_users table, and joining each of those 100,000
        rows to the corresponding row in the users table, to get 100,000 rows
        in the result set.

        I'm not sure what the program is trying to do, but I still don't see the
        performance bug yet.

        I'll try running the program with still bigger table sizes, to see if
        there is a "knee" somewhere.

        Here's the output from smaller runs:

        C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main
        Will run with 1000 rows.

        • Testing with org.apache.derby.jdbc.EmbeddedDriver
          Done inserting in 5.734 seconds
          There are 1000 rows in users
          There are 1000 rows in messaged_users
          Done querying in 5.922 seconds
          Retrieved 0 rows total.
          There are 1000 rows in users
          There are 2000 rows in messaged_users
          Done querying in 6.234 seconds
          Retrieved 1000 rows total.

        C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 2000
        Will run with 2000 rows.

        • Testing with org.apache.derby.jdbc.EmbeddedDriver
          Done inserting in 7.625 seconds
          There are 2000 rows in users
          There are 2000 rows in messaged_users
          Done querying in 7.844 seconds
          Retrieved 0 rows total.
          There are 2000 rows in users
          There are 4000 rows in messaged_users
          Done querying in 8.547 seconds
          Retrieved 2000 rows total.

        C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 5000
        Will run with 5000 rows.

        • Testing with org.apache.derby.jdbc.EmbeddedDriver
          Done inserting in 12.016 seconds
          There are 5000 rows in users
          There are 5000 rows in messaged_users
          Done querying in 12.25 seconds
          Retrieved 0 rows total.
          There are 5000 rows in users
          There are 10000 rows in messaged_users
          Done querying in 13.703 seconds
          Retrieved 5000 rows total.

        C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 10000
        Will run with 10000 rows.

        • Testing with org.apache.derby.jdbc.EmbeddedDriver
          Done inserting in 20.984 seconds
          There are 10000 rows in users
          There are 10000 rows in messaged_users
          Done querying in 22.046 seconds
          Retrieved 1 rows total.
          There are 10000 rows in users
          There are 19999 rows in messaged_users
          Done querying in 33.374 seconds
          Retrieved 10000 rows total.

        C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 20000
        Will run with 20000 rows.

        • Testing with org.apache.derby.jdbc.EmbeddedDriver
          Done inserting in 44.64 seconds
          There are 20000 rows in users
          There are 20000 rows in messaged_users
          Done querying in 45.281 seconds
          Retrieved 1 rows total.
          There are 20000 rows in users
          There are 39999 rows in messaged_users
          Done querying in 93.624 seconds
          Retrieved 20000 rows total.

        C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 40000
        Will run with 40000 rows.

        • Testing with org.apache.derby.jdbc.EmbeddedDriver
          Done inserting in 79.406 seconds
          There are 40000 rows in users
          There are 40000 rows in messaged_users
          Done querying in 80.515 seconds
          Retrieved 1 rows total.
          There are 40000 rows in users
          There are 79999 rows in messaged_users
          Done querying in 368.888 seconds
          Retrieved 40000 rows total.
        Show
        Bryan Pendleton added a comment - I modified the test program some more: added some more output so I could understand what it was doing made the number of rows configurable. Then I ran the program about half a dozen times, gradually increasing the data size, to see what it was doing. Certainly the times are not growing linearly, but they are not growing all that badly either. I can run the program with 40,000 rows in about 10 minutes. I also took a look at the query plan, and it seems that the query is using a reasonable query plan: scan Messaged_Users for each Messaged_user which matched the account ID query Users for that user id Lastly, I looked at the program, and it seems that half the rows in the Messaged_users table are for account 5324, and the other half are for other accounts. So when we try to run the program with 100,000 rows, we are processing 100,000 rows for account 5324, out of the 200,000 rows in the messaged_users table, and joining each of those 100,000 rows to the corresponding row in the users table, to get 100,000 rows in the result set. I'm not sure what the program is trying to do, but I still don't see the performance bug yet. I'll try running the program with still bigger table sizes, to see if there is a "knee" somewhere. Here's the output from smaller runs: C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main Will run with 1000 rows. Testing with org.apache.derby.jdbc.EmbeddedDriver Done inserting in 5.734 seconds There are 1000 rows in users There are 1000 rows in messaged_users Done querying in 5.922 seconds Retrieved 0 rows total. There are 1000 rows in users There are 2000 rows in messaged_users Done querying in 6.234 seconds Retrieved 1000 rows total. C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 2000 Will run with 2000 rows. Testing with org.apache.derby.jdbc.EmbeddedDriver Done inserting in 7.625 seconds There are 2000 rows in users There are 2000 rows in messaged_users Done querying in 7.844 seconds Retrieved 0 rows total. There are 2000 rows in users There are 4000 rows in messaged_users Done querying in 8.547 seconds Retrieved 2000 rows total. C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 5000 Will run with 5000 rows. Testing with org.apache.derby.jdbc.EmbeddedDriver Done inserting in 12.016 seconds There are 5000 rows in users There are 5000 rows in messaged_users Done querying in 12.25 seconds Retrieved 0 rows total. There are 5000 rows in users There are 10000 rows in messaged_users Done querying in 13.703 seconds Retrieved 5000 rows total. C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 10000 Will run with 10000 rows. Testing with org.apache.derby.jdbc.EmbeddedDriver Done inserting in 20.984 seconds There are 10000 rows in users There are 10000 rows in messaged_users Done querying in 22.046 seconds Retrieved 1 rows total. There are 10000 rows in users There are 19999 rows in messaged_users Done querying in 33.374 seconds Retrieved 10000 rows total. C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 20000 Will run with 20000 rows. Testing with org.apache.derby.jdbc.EmbeddedDriver Done inserting in 44.64 seconds There are 20000 rows in users There are 20000 rows in messaged_users Done querying in 45.281 seconds Retrieved 1 rows total. There are 20000 rows in users There are 39999 rows in messaged_users Done querying in 93.624 seconds Retrieved 20000 rows total. C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% Main 40000 Will run with 40000 rows. Testing with org.apache.derby.jdbc.EmbeddedDriver Done inserting in 79.406 seconds There are 40000 rows in users There are 40000 rows in messaged_users Done querying in 80.515 seconds Retrieved 1 rows total. There are 40000 rows in users There are 79999 rows in messaged_users Done querying in 368.888 seconds Retrieved 40000 rows total.
        Hide
        Bryan Pendleton added a comment -

        I ran the program with 50,000 rows, and have attached the query plan,
        in case anybody is interested in looking at the query plan.

        Show
        Bryan Pendleton added a comment - I ran the program with 50,000 rows, and have attached the query plan, in case anybody is interested in looking at the query plan.
        Hide
        Bryan Pendleton added a comment -

        I tried setting -Xmx768m to see if it would make any difference,
        and it didn't really make much difference:

        C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% -Dderby.language.logQueryPlan=tr
        ue Main 50000
        Will run with 50000 rows.

        • Testing with org.apache.derby.jdbc.EmbeddedDriver
          Done inserting in 93.015 seconds
          There are 50000 rows in users
          There are 50000 rows in messaged_users
          Done querying in 94.39 seconds
          Retrieved 1 rows total.
          There are 50000 rows in users
          There are 99999 rows in messaged_users
          Done querying in 965.197 seconds
          Retrieved 50000 rows total.

        C:\bryan\src\derby\tests>vim derby.log

        C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% -Xmx768m -Dderby.language.logQue
        ryPlan=true Main 50000
        Will run with 50000 rows.

        • Testing with org.apache.derby.jdbc.EmbeddedDriver
          Done inserting in 98.343 seconds
          There are 50000 rows in users
          There are 50000 rows in messaged_users
          Done querying in 99.625 seconds
          Retrieved 1 rows total.
          There are 50000 rows in users
          There are 99999 rows in messaged_users
          Done querying in 955.01 seconds
          Retrieved 50000 rows total.

        Given that it takes nearly 20 minutes for 50,000 rows, and that the performance
        is definitely getting worse as the number of rows in the result grows, it's a bit
        hard to predict how long it would take to run 100,000 rows. It wouldn't surprise
        me if it took 5 hours or more.

        Unfortunately, I don't have a spare computer right now to let the 100,000 row
        version run overnight. Perhaps the original poster could try letting the test
        program run overnight, and see if it runs to completion in 8 or 10 hours?

        Show
        Bryan Pendleton added a comment - I tried setting -Xmx768m to see if it would make any difference, and it didn't really make much difference: C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% -Dderby.language.logQueryPlan=tr ue Main 50000 Will run with 50000 rows. Testing with org.apache.derby.jdbc.EmbeddedDriver Done inserting in 93.015 seconds There are 50000 rows in users There are 50000 rows in messaged_users Done querying in 94.39 seconds Retrieved 1 rows total. There are 50000 rows in users There are 99999 rows in messaged_users Done querying in 965.197 seconds Retrieved 50000 rows total. C:\bryan\src\derby\tests>vim derby.log C:\bryan\src\derby\tests>java -cp .;%CLASSPATH% -Xmx768m -Dderby.language.logQue ryPlan=true Main 50000 Will run with 50000 rows. Testing with org.apache.derby.jdbc.EmbeddedDriver Done inserting in 98.343 seconds There are 50000 rows in users There are 50000 rows in messaged_users Done querying in 99.625 seconds Retrieved 1 rows total. There are 50000 rows in users There are 99999 rows in messaged_users Done querying in 955.01 seconds Retrieved 50000 rows total. Given that it takes nearly 20 minutes for 50,000 rows, and that the performance is definitely getting worse as the number of rows in the result grows, it's a bit hard to predict how long it would take to run 100,000 rows. It wouldn't surprise me if it took 5 hours or more. Unfortunately, I don't have a spare computer right now to let the 100,000 row version run overnight. Perhaps the original poster could try letting the test program run overnight, and see if it runs to completion in 8 or 10 hours?
        Hide
        Georgi Hristov added a comment -

        Thanks a lot for your detailed analysis I really appreciate it a lot. I can give you one hint with which I manage to execute the query for the 100,000 rows: just remove the first call to doQuery() in the doSingleDriver() method, then the query lasts for not more than 6 seconds. So from my point of view most probably there is some faulty implementation, which maybe caches something, and makes the subsequent calls to the same query, after the data in the target tables has been modified, to take forever.
        Anyway I'm a bit surprised that you accept a behaviour like 50,000 rows for 20 minutes ? Have you ever tried other implementations like Derby, for example HSQLDB ? Do you have any performance benchmarks for Derby DB in embedded mode ? It is really crucial for the application we want to deliver to have a high performance DB which can handle a load of several hundred thousand rows. And moreover we want this DB to be Derby and to add a new successor for Derby DB.

        Show
        Georgi Hristov added a comment - Thanks a lot for your detailed analysis I really appreciate it a lot. I can give you one hint with which I manage to execute the query for the 100,000 rows: just remove the first call to doQuery() in the doSingleDriver() method, then the query lasts for not more than 6 seconds. So from my point of view most probably there is some faulty implementation, which maybe caches something, and makes the subsequent calls to the same query, after the data in the target tables has been modified, to take forever. Anyway I'm a bit surprised that you accept a behaviour like 50,000 rows for 20 minutes ? Have you ever tried other implementations like Derby, for example HSQLDB ? Do you have any performance benchmarks for Derby DB in embedded mode ? It is really crucial for the application we want to deliver to have a high performance DB which can handle a load of several hundred thousand rows. And moreover we want this DB to be Derby and to add a new successor for Derby DB.
        Hide
        Bryan Pendleton added a comment -

        > remove the first call to doQuery() in the doSingleDriver() method,
        > then the query lasts for not more than 6 seconds

        Unfortunately, I can't reproduce this. Removing the first call to doQuery
        doesn't seem to help things for me.

        Can anybody else reproduce this finding?

        Show
        Bryan Pendleton added a comment - > remove the first call to doQuery() in the doSingleDriver() method, > then the query lasts for not more than 6 seconds Unfortunately, I can't reproduce this. Removing the first call to doQuery doesn't seem to help things for me. Can anybody else reproduce this finding?
        Hide
        Bryan Pendleton added a comment -

        One thing I noticed while reading the code is that doQuery() calls
        con.setAutoCommit(false), but insertData2() does not call con.commit().

        So I thought maybe the problem involves having a large uncommitted transaction.

        However, I tried adding a con.commit() to insertData2() , and I also tried
        commenting out the con.setAutoCommit(false) from doQuery(), and
        neither of those changes seemed to help the performance, either.

        Show
        Bryan Pendleton added a comment - One thing I noticed while reading the code is that doQuery() calls con.setAutoCommit(false), but insertData2() does not call con.commit(). So I thought maybe the problem involves having a large uncommitted transaction. However, I tried adding a con.commit() to insertData2() , and I also tried commenting out the con.setAutoCommit(false) from doQuery(), and neither of those changes seemed to help the performance, either.
        Hide
        Georgi Hristov added a comment -

        Please find attached the latest version of Main_Updated which executes the query in about 5 secs. Please give it a try on your side. I have thoroughly investigated the code you initially attached the Main.java and compared it with my local implementation. Therefore I want also to assure you that all strange statements like con.commit() etc. are double and triple checked. The reason why I preserved them in the Main_Updated.java file is just to present you that the same coding you've send me with some small add-ons produces such great performance degradation.

        Show
        Georgi Hristov added a comment - Please find attached the latest version of Main_Updated which executes the query in about 5 secs. Please give it a try on your side. I have thoroughly investigated the code you initially attached the Main.java and compared it with my local implementation. Therefore I want also to assure you that all strange statements like con.commit() etc. are double and triple checked. The reason why I preserved them in the Main_Updated.java file is just to present you that the same coding you've send me with some small add-ons produces such great performance degradation.
        Hide
        Bryan Pendleton added a comment -

        Very interesting!

        With your revised Main_Updated.java, I AM able to reproduce the behavior you see.

        Furthermore, I then had an idea, and I took your Main_Updated.java
        and updated it again:

        • I changed doQuery() so that it took a string of whitespace, and
          inserted that whitespace into the query it runs
        • I changed doSingleDriver so that it called doQuery() twice, passing
          a different string of whitespace each time.

        Now, with the attached Main_Updated.java, I can run doQuery() twice,
        and BOTH queries run very fast.

        By changing the whitespace in the SQL text, I force Derby to re-compile
        the query, and not use the pre-compiled query.

        So, I think, it must be choosing a completely different query plan
        when I trick the whitespace to be different.

        Sure enough, I turned on Query Plan logging, and I can see that Derby
        comes up with two totally different query plans for the same statement:

        • the first time, it chooses a HashExists join with USERS as the left
          result set, and MESSAGED_USERS as the right result set
        • the second time, it chooses a NestedLoopExists join with
          MESSAGED_USERS as the left result set and USERS as the
          right result set.

        I'll attach the query plan logging in a separate comment.

        This makes me think that:
        1) There is an optimizer problem here, where sometimes Derby's
        optimizer is choosing a query plan that works well for the
        current conditions, but would fail badly if the table contents
        change significantly. It would be great if we could teach
        Derby's optimizer that, when it knows it's using such a plan, it
        should avoid caching the query plan forever. Or at least, that
        when re-using an already cached query plan, it should check to
        see if the table sizes/distributions have changed enough that
        it should re-optimize the plan rather than re-using the cached one.
        2) If the optimizer is forced to re-optimize the query with the
        current conditions, it appears to pick a reasonable query plan
        3) You can probably use this as a workaround: simply change your
        application so that, when you issue the query, you provide a
        slightly different string of whitespace in the query text, to
        force Derby to re-compile the query. It's an ugly workaround,
        but maybe you can use it for now.

        Show
        Bryan Pendleton added a comment - Very interesting! With your revised Main_Updated.java, I AM able to reproduce the behavior you see. Furthermore, I then had an idea, and I took your Main_Updated.java and updated it again: I changed doQuery() so that it took a string of whitespace, and inserted that whitespace into the query it runs I changed doSingleDriver so that it called doQuery() twice, passing a different string of whitespace each time. Now, with the attached Main_Updated.java, I can run doQuery() twice, and BOTH queries run very fast. By changing the whitespace in the SQL text, I force Derby to re-compile the query, and not use the pre-compiled query. So, I think, it must be choosing a completely different query plan when I trick the whitespace to be different. Sure enough, I turned on Query Plan logging, and I can see that Derby comes up with two totally different query plans for the same statement: the first time, it chooses a HashExists join with USERS as the left result set, and MESSAGED_USERS as the right result set the second time, it chooses a NestedLoopExists join with MESSAGED_USERS as the left result set and USERS as the right result set. I'll attach the query plan logging in a separate comment. This makes me think that: 1) There is an optimizer problem here, where sometimes Derby's optimizer is choosing a query plan that works well for the current conditions, but would fail badly if the table contents change significantly. It would be great if we could teach Derby's optimizer that, when it knows it's using such a plan, it should avoid caching the query plan forever. Or at least, that when re-using an already cached query plan, it should check to see if the table sizes/distributions have changed enough that it should re-optimize the plan rather than re-using the cached one. 2) If the optimizer is forced to re-optimize the query with the current conditions, it appears to pick a reasonable query plan 3) You can probably use this as a workaround: simply change your application so that, when you issue the query, you provide a slightly different string of whitespace in the query text, to force Derby to re-compile the query. It's an ugly workaround, but maybe you can use it for now.
        Hide
        Bryan Pendleton added a comment -

        "derbyTwoDifferentOneHundredKPlans.log" is the derby.log
        from running Main_Updated with variable whitespace to
        force re-optimization of the second call to doQuery.

        The first SELECT query plan in the log is from the first
        call to doQuery, after the tables had been initially loaded.

        The second SELECT query plan in the logs is from the second
        call to doQuery, after insertData2() has loaded an additional
        set of data into MESSAGED_USERS

        Show
        Bryan Pendleton added a comment - "derbyTwoDifferentOneHundredKPlans.log" is the derby.log from running Main_Updated with variable whitespace to force re-optimization of the second call to doQuery. The first SELECT query plan in the log is from the first call to doQuery, after the tables had been initially loaded. The second SELECT query plan in the logs is from the second call to doQuery, after insertData2() has loaded an additional set of data into MESSAGED_USERS
        Hide
        Dag H. Wanvik added a comment -

        As a workaround, there is also the system procedure
        ("call syscs_util.syscs_empty_statement_cache()") which may do the job.

        Show
        Dag H. Wanvik added a comment - As a workaround, there is also the system procedure ("call syscs_util.syscs_empty_statement_cache()") which may do the job.
        Hide
        Georgi Hristov added a comment -

        Thanks a lot for your comments and I'm happy that we finally localized the issue. Most probably we'll try to adopt the workarounds you've proposed and will wait for the fix to become part of a new Derby release. Can we keep this issue open until the fix is provided and included into a new Derby release ?

        Show
        Georgi Hristov added a comment - Thanks a lot for your comments and I'm happy that we finally localized the issue. Most probably we'll try to adopt the workarounds you've proposed and will wait for the fix to become part of a new Derby release. Can we keep this issue open until the fix is provided and included into a new Derby release ?
        Hide
        Georgi Hristov added a comment -

        Can you give me a rough estimation on how long will it take to fix this issue ?

        Show
        Georgi Hristov added a comment - Can you give me a rough estimation on how long will it take to fix this issue ?
        Hide
        Kristian Waagan added a comment -

        Triaged July 3, 2009: Unticked Release Note Needed. Marked as Repro attached and Workaround attached. I'm keeping the urgency as Urgent, but am uncertain - I'd like a second opinion on this one.
        Based on the description, the problem seems severe for those being hit by it. I haven't checked if the problem is present on trunk or the 10.5 branch.

        Show
        Kristian Waagan added a comment - Triaged July 3, 2009: Unticked Release Note Needed. Marked as Repro attached and Workaround attached. I'm keeping the urgency as Urgent, but am uncertain - I'd like a second opinion on this one. Based on the description, the problem seems severe for those being hit by it. I haven't checked if the problem is present on trunk or the 10.5 branch.
        Hide
        Kathey Marsden added a comment -

        Changing to normal urgency. This won't make it for 10.5.2.

        Show
        Kathey Marsden added a comment - Changing to normal urgency. This won't make it for 10.5.2.
        Hide
        Nirmal Fernando added a comment -

        Hi All,

        I've attached the graphical query plan exported using PlanExporter tool
        (DERBY-4587) as a PDF, for the following query:
        SELECT a.USER_ID, a.USER_NAME, b.account_id FROM Users a JOIN
        Messaged_Users b ON a.USER_ID=b.USER_ID AND b.account_id=
        as requested by Eranda.

        Hope this helps!
        Thanks.

        Show
        Nirmal Fernando added a comment - Hi All, I've attached the graphical query plan exported using PlanExporter tool ( DERBY-4587 ) as a PDF, for the following query: SELECT a.USER_ID, a.USER_NAME, b.account_id FROM Users a JOIN Messaged_Users b ON a.USER_ID=b.USER_ID AND b.account_id= as requested by Eranda. Hope this helps! Thanks.
        Hide
        Kathey Marsden added a comment -

        I cannot reproduce this on trunk at least with the latest Main_Updated.java. Is it possible the automatic index statistics update has corrected the issue?

        Show
        Kathey Marsden added a comment - I cannot reproduce this on trunk at least with the latest Main_Updated.java. Is it possible the automatic index statistics update has corrected the issue?
        Hide
        Kathey Marsden added a comment -

        Cannot reproduce and have not heard back from the user. Issue can be reopened if we get a reproduction.

        Show
        Kathey Marsden added a comment - Cannot reproduce and have not heard back from the user. Issue can be reopened if we get a reproduction.

          People

          • Assignee:
            Unassigned
            Reporter:
            Georgi Hristov
          • Votes:
            1 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development