Derby
  1. Derby
  2. DERBY-3714

Significant performance degradation if Hibernate creates different order of attributes

    Details

    • Type: Bug Bug
    • Status: Open
    • Priority: Critical Critical
    • Resolution: Unresolved
    • Affects Version/s: 10.3.2.1, 10.4.1.3
    • Fix Version/s: None
    • Component/s: SQL
    • Environment:
      Windows XP with Java 6u5 (JavaDB de-installed!), various hardware (single + dual core processors)
    • Urgency:
      Normal
    • Bug behavior facts:
      Performance

      Description

      In our project we use Derby 10.4.1.3 in combination with the latest Hibernate Core 3.2.6.

      When we migrated from Java 5 to 6, we noticed a huge performance hit.

      After thorough analysis, we managed to pin down the problem to the order of the attributes in a select statement created by Hibernate. The order seems to make a huge impact on the performance, which is really strange.

      A (very simplified) example of the problem is shown below. If more attributes and more joins are added, the performance difference increases:

      Bad Performance (5 result set entries in 3672ms) :
      =======================================
      select
      logevent0_.clazz_ as clazz_ from (
      select
      nullif('x','x') as RECEIVER,
      TEST_RUN_ID,
      2 as clazz_ from USER_LOG_EVENT
      union all select
      RECEIVER,
      TEST_RUN_ID,
      4 as clazz_ from DATA_FLOW_LOG_EVENT )
      logevent0_ where logevent0_.TEST_RUN_ID=?

      Good Performance (5 entries in 610ms) :
      =======================================
      select
      logevent0_.clazz_ as clazz_ from (
      select
      TEST_RUN_ID,
      nullif('x','x') as RECEIVER,
      2 as clazz_ from USER_LOG_EVENT
      union all select
      TEST_RUN_ID,
      RECEIVER,
      4 as clazz_ from DATA_FLOW_LOG_EVENT )
      logevent0_ where logevent0_.TEST_RUN_ID=?

      Table DATA_FLOW_LOG_EVENT has the attributes
      TEST_RUN_ID BIGINT,
      RECEIVER VARCHAR,...

      wheras table USER_LOG_EVENT does NOT have the attribute RECEIVER.

      As hibernate generates these select statements automatically, we are not able the change the order of the attributes.

      The real question is why there is such a difference in the execution speed, and how to avoid this problem. (The complete query takes about 1-2sec in the fast version, and more than 50sec in the slow version). This makes it impossible for us to use Derby+Hibernate with Java 6!

      Any ideas?

      Kind regards,

      Michael

        Activity

        Hide
        Knut Anders Hatlen added a comment -

        It would be helpful if you could post

        1) the complete schema for the tables involved in the query (you could use dblook: http://db.apache.org/derby/docs/10.4/tools/ctoolsdblook.html)

        2) the query plans for the two queries (you can make Derby write query plans to derby.log by setting the derby.language.logQueryPlan property, see http://db.apache.org/derby/docs/10.4/tuning/rtunproper43414.html)

        This problem might be caused by outdated index cardinality statistics, see DERBY-269. You may want to try the work-around mentioned there (alter table ... compress) to see if the problem is related to that issue.

        Show
        Knut Anders Hatlen added a comment - It would be helpful if you could post 1) the complete schema for the tables involved in the query (you could use dblook: http://db.apache.org/derby/docs/10.4/tools/ctoolsdblook.html ) 2) the query plans for the two queries (you can make Derby write query plans to derby.log by setting the derby.language.logQueryPlan property, see http://db.apache.org/derby/docs/10.4/tuning/rtunproper43414.html ) This problem might be caused by outdated index cardinality statistics, see DERBY-269 . You may want to try the work-around mentioned there (alter table ... compress) to see if the problem is related to that issue.
        Hide
        Michael Gerz added a comment -

        AFAICS, Derby does not have an "alter table <tableName> compress;" command. "ij" always rejects the command with a syntax error.

        However, I applied the following command to all tables in my database

        call SYSCS_UTIL.SYSCS_COMPRESS_TABLE('APP', '<tableName>', 1);

        Unfortunately, there was no real difference in performance

        Show
        Michael Gerz added a comment - AFAICS, Derby does not have an "alter table <tableName> compress;" command. "ij" always rejects the command with a syntax error. However, I applied the following command to all tables in my database call SYSCS_UTIL.SYSCS_COMPRESS_TABLE('APP', '<tableName>', 1); Unfortunately, there was no real difference in performance
        Hide
        Michael Gerz added a comment -

        Below please find the relevant part of our database schema. Please note that DATA_FLOW_LOG_EVENT has about 800,000 entries and USER_LOG_EVENT has about 225,000 entries.

        CREATE TABLE "APP"."USER_LOG_EVENT" ("ID" BIGINT NOT NULL, "INDEX_SENT" INTEGER NOT NULL, "TEST_RUN_ID" BIGINT NOT NULL, "SENDER" VARCHAR(255) NOT NULL, "TIME_SENT" TIMESTAMP NOT NULL, "MESSAGE" VARCHAR(32672) NOT NULL, "SEVERITY" VARCHAR(255) NOT NULL);

        ALTER TABLE "APP"."USER_LOG_EVENT" ADD CONSTRAINT "SQL070821150850480" PRIMARY KEY ("ID");

        ALTER TABLE "APP"."USER_LOG_EVENT" ADD CONSTRAINT "FK64B9199FD4311151AB41192233BF62B" FOREIGN KEY ("TEST_RUN_ID") REFERENCES "APP"."TEST_RUN" ("ID") ON DELETE CASCADE ON UPDATE NO ACTION;

        CREATE TABLE "APP"."DATA_FLOW_LOG_EVENT" ("ID" BIGINT NOT NULL, "INDEX_SENT" INTEGER NOT NULL, "TEST_RUN_ID" BIGINT NOT NULL, "SENDER" VARCHAR(255) NOT NULL, "TIME_SENT" TIMESTAMP NOT NULL, "RECEIVER" VARCHAR(255) NOT NULL, "TIME_RECEIVED" TIMESTAMP NOT NULL, "INDEX_RECEIVED" INTEGER NOT NULL, "SERIALIZED_CONTENT" VARCHAR(32672));

        ALTER TABLE "APP"."DATA_FLOW_LOG_EVENT" ADD CONSTRAINT "SQL070821150848360" PRIMARY KEY ("ID");

        ALTER TABLE "APP"."DATA_FLOW_LOG_EVENT" ADD CONSTRAINT "FK64B9199FD431115378EE903" FOREIGN KEY ("TEST_RUN_ID") REFERENCES "APP"."TEST_RUN" ("ID") ON DELETE CASCADE ON UPDATE NO ACTION;

        CREATE TABLE "APP"."TEST_RUN" ("ID" BIGINT NOT NULL, "C2IS_ID" BIGINT, "TEST_CASE_ID" BIGINT, "STATUS" VARCHAR (255) FOR BIT DATA NOT NULL, "VERDICT" VARCHAR (255) FOR BIT DATA NOT NULL, "START_DATE" TIMESTAMP, "DURATION" BIGINT, "SUT_VERSION" VARCHAR(255), "TEST_CASE_VERSION" VARCHAR(255), "TEST_SYSTEM_VERSION" VARCHAR(255), "TEST_OPERATOR_NAME" VARCHAR(255), "COMMENTS" VARCHAR(2047));

        ALTER TABLE "APP"."TEST_RUN" ADD CONSTRAINT "SQL070821150849890" PRIMARY KEY ("ID");

        Show
        Michael Gerz added a comment - Below please find the relevant part of our database schema. Please note that DATA_FLOW_LOG_EVENT has about 800,000 entries and USER_LOG_EVENT has about 225,000 entries. CREATE TABLE "APP"."USER_LOG_EVENT" ("ID" BIGINT NOT NULL, "INDEX_SENT" INTEGER NOT NULL, "TEST_RUN_ID" BIGINT NOT NULL, "SENDER" VARCHAR(255) NOT NULL, "TIME_SENT" TIMESTAMP NOT NULL, "MESSAGE" VARCHAR(32672) NOT NULL, "SEVERITY" VARCHAR(255) NOT NULL); ALTER TABLE "APP"."USER_LOG_EVENT" ADD CONSTRAINT "SQL070821150850480" PRIMARY KEY ("ID"); ALTER TABLE "APP"."USER_LOG_EVENT" ADD CONSTRAINT "FK64B9199FD4311151AB41192233BF62B" FOREIGN KEY ("TEST_RUN_ID") REFERENCES "APP"."TEST_RUN" ("ID") ON DELETE CASCADE ON UPDATE NO ACTION; CREATE TABLE "APP"."DATA_FLOW_LOG_EVENT" ("ID" BIGINT NOT NULL, "INDEX_SENT" INTEGER NOT NULL, "TEST_RUN_ID" BIGINT NOT NULL, "SENDER" VARCHAR(255) NOT NULL, "TIME_SENT" TIMESTAMP NOT NULL, "RECEIVER" VARCHAR(255) NOT NULL, "TIME_RECEIVED" TIMESTAMP NOT NULL, "INDEX_RECEIVED" INTEGER NOT NULL, "SERIALIZED_CONTENT" VARCHAR(32672)); ALTER TABLE "APP"."DATA_FLOW_LOG_EVENT" ADD CONSTRAINT "SQL070821150848360" PRIMARY KEY ("ID"); ALTER TABLE "APP"."DATA_FLOW_LOG_EVENT" ADD CONSTRAINT "FK64B9199FD431115378EE903" FOREIGN KEY ("TEST_RUN_ID") REFERENCES "APP"."TEST_RUN" ("ID") ON DELETE CASCADE ON UPDATE NO ACTION; CREATE TABLE "APP"."TEST_RUN" ("ID" BIGINT NOT NULL, "C2IS_ID" BIGINT, "TEST_CASE_ID" BIGINT, "STATUS" VARCHAR (255) FOR BIT DATA NOT NULL, "VERDICT" VARCHAR (255) FOR BIT DATA NOT NULL, "START_DATE" TIMESTAMP, "DURATION" BIGINT, "SUT_VERSION" VARCHAR(255), "TEST_CASE_VERSION" VARCHAR(255), "TEST_SYSTEM_VERSION" VARCHAR(255), "TEST_OPERATOR_NAME" VARCHAR(255), "COMMENTS" VARCHAR(2047)); ALTER TABLE "APP"."TEST_RUN" ADD CONSTRAINT "SQL070821150849890" PRIMARY KEY ("ID");
        Hide
        Michael Gerz added a comment -

        Bad-performance query plan (for the simplified query above):

        ----------------------------------------------------------------
        Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.1.3 - (648739): instance a816c00e-011a-67ed-c85e-0000000ceb90
        on database directory XXX

        Database Class Loader started - derby.database.classpath=''
        2008-06-08 11:27:12.406 GMT Thread[main,5,main] (XID = 3462628), (SESSIONID = 0), select
        logevent0_.clazz_ as clazz_ from (
        select
        nullif('x','x') as RECEIVER,
        TEST_RUN_ID,
        2 as clazz_ from USER_LOG_EVENT
        union all select
        RECEIVER,
        TEST_RUN_ID,
        4 as clazz_ from DATA_FLOW_LOG_EVENT )
        logevent0_ where logevent0_.TEST_RUN_ID=16188523 ******* Project-Restrict ResultSet (9):
        Number of opens = 1
        Rows seen = 33
        Rows filtered = 0
        restriction = false
        projection = true
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count: 225417,00
        optimizer estimated cost: 53055,62

        Source result set:
        Project-Restrict ResultSet (8):
        Number of opens = 1
        Rows seen = 225338
        Rows filtered = 225305
        restriction = true
        projection = false
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count: 225417,00
        optimizer estimated cost: 53055,62

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 225313
        Rows seen from the right = 25
        Rows returned = 225338
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 225417,00
        optimizer estimated cost: 53055,62

        Left result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 225313
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 225417,00
        optimizer estimated cost: 53055,62

        Source result set:
        Project-Restrict ResultSet (3):
        Number of opens = 1
        Rows seen = 225313
        Rows filtered = 0
        restriction = false
        projection = true
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count: 225318,00
        optimizer estimated cost: 52493,51

        Source result set:
        Index Scan ResultSet for USER_LOG_EVENT using constraint FK64B9199FD4311151AB41192233BF62B at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 225313
        Rows filtered = 0
        Fetch Size = 1
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        next time in milliseconds/row = 0

        scan information:
        Bit set of columns fetched=

        {0}

        Number of columns fetched=1
        Number of deleted rows visited=0
        Number of pages visited=1450
        Number of rows qualified=225313
        Number of rows visited=225313
        Scan type=btree
        Tree height=3
        start position:
        None
        stop position:
        None
        qualifiers:
        None
        optimizer estimated row count: 225318,00
        optimizer estimated cost: 52493,51

        Right result set:
        Project-Restrict ResultSet (7):
        Number of opens = 1
        Rows seen = 25
        Rows filtered = 0
        restriction = false
        projection = true
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count: 99,00
        optimizer estimated cost: 562,12

        Source result set:
        Index Row to Base Row ResultSet for DATA_FLOW_LOG_EVENT:
        Number of opens = 1
        Rows seen = 25
        Columns accessed from heap =

        {5}

        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 99,00
        optimizer estimated cost: 562,12

        Index Scan ResultSet for DATA_FLOW_LOG_EVENT using constraint FK64B9199FD431115378EE903 at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 25
        Rows filtered = 0
        Fetch Size = 1
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        next time in milliseconds/row = 0

        scan information:
        Bit set of columns fetched=All
        Number of columns fetched=2
        Number of deleted rows visited=0
        Number of pages visited=3
        Number of rows qualified=25
        Number of rows visited=26
        Scan type=btree
        Tree height=-1
        start position:
        >= on first 1 column(s).
        Ordered null semantics on the following columns:
        0
        stop position:
        > on first 1 column(s).
        Ordered null semantics on the following columns:
        0
        qualifiers:
        None
        optimizer estimated row count: 99,00
        optimizer estimated cost: 562,12

        Show
        Michael Gerz added a comment - Bad-performance query plan (for the simplified query above): ---------------------------------------------------------------- Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.1.3 - (648739): instance a816c00e-011a-67ed-c85e-0000000ceb90 on database directory XXX Database Class Loader started - derby.database.classpath='' 2008-06-08 11:27:12.406 GMT Thread [main,5,main] (XID = 3462628), (SESSIONID = 0), select logevent0_.clazz_ as clazz_ from ( select nullif('x','x') as RECEIVER, TEST_RUN_ID, 2 as clazz_ from USER_LOG_EVENT union all select RECEIVER, TEST_RUN_ID, 4 as clazz_ from DATA_FLOW_LOG_EVENT ) logevent0_ where logevent0_.TEST_RUN_ID=16188523 ******* Project-Restrict ResultSet (9): Number of opens = 1 Rows seen = 33 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 225417,00 optimizer estimated cost: 53055,62 Source result set: Project-Restrict ResultSet (8): Number of opens = 1 Rows seen = 225338 Rows filtered = 225305 restriction = true projection = false constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 225417,00 optimizer estimated cost: 53055,62 Source result set: Union ResultSet: Number of opens = 1 Rows seen from the left = 225313 Rows seen from the right = 25 Rows returned = 225338 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 225417,00 optimizer estimated cost: 53055,62 Left result set: Normalize ResultSet: Number of opens = 1 Rows seen = 225313 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 225417,00 optimizer estimated cost: 53055,62 Source result set: Project-Restrict ResultSet (3): Number of opens = 1 Rows seen = 225313 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 225318,00 optimizer estimated cost: 52493,51 Source result set: Index Scan ResultSet for USER_LOG_EVENT using constraint FK64B9199FD4311151AB41192233BF62B at read committed isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 225313 Rows filtered = 0 Fetch Size = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched= {0} Number of columns fetched=1 Number of deleted rows visited=0 Number of pages visited=1450 Number of rows qualified=225313 Number of rows visited=225313 Scan type=btree Tree height=3 start position: None stop position: None qualifiers: None optimizer estimated row count: 225318,00 optimizer estimated cost: 52493,51 Right result set: Project-Restrict ResultSet (7): Number of opens = 1 Rows seen = 25 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 99,00 optimizer estimated cost: 562,12 Source result set: Index Row to Base Row ResultSet for DATA_FLOW_LOG_EVENT: Number of opens = 1 Rows seen = 25 Columns accessed from heap = {5} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 99,00 optimizer estimated cost: 562,12 Index Scan ResultSet for DATA_FLOW_LOG_EVENT using constraint FK64B9199FD431115378EE903 at read committed isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 25 Rows filtered = 0 Fetch Size = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=2 Number of deleted rows visited=0 Number of pages visited=3 Number of rows qualified=25 Number of rows visited=26 Scan type=btree Tree height=-1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: 0 stop position: > on first 1 column(s). Ordered null semantics on the following columns: 0 qualifiers: None optimizer estimated row count: 99,00 optimizer estimated cost: 562,12
        Hide
        Michael Gerz added a comment -

        Good-performance query plan (for simplified query):

        ----------------------------------------------------------------
        2008-06-08 11:31:19.406 GMT:
        Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.1.3 - (648739): instance a816c00e-011a-67f1-d490-0000000ceb90
        on database directory XXX

        Database Class Loader started - derby.database.classpath=''
        2008-06-08 11:31:52.328 GMT Thread[main,5,main] (XID = 3462637), (SESSIONID = 0), select
        logevent0_.clazz_ as clazz_ from (
        select
        TEST_RUN_ID,
        nullif('x','x') as RECEIVER,
        2 as clazz_ from USER_LOG_EVENT
        union all select
        TEST_RUN_ID,
        RECEIVER,
        4 as clazz_ from DATA_FLOW_LOG_EVENT )
        logevent0_ where logevent0_.TEST_RUN_ID=16188523 ******* Project-Restrict ResultSet (9):
        Number of opens = 1
        Rows seen = 33
        Rows filtered = 0
        restriction = false
        projection = true
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count: 110,00
        optimizer estimated cost: 568,03

        Source result set:
        Project-Restrict ResultSet (8):
        Number of opens = 1
        Rows seen = 33
        Rows filtered = 0
        restriction = true
        projection = false
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count: 110,00
        optimizer estimated cost: 568,03

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 8
        Rows seen from the right = 25
        Rows returned = 33
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 110,00
        optimizer estimated cost: 568,03

        Left result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 8
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 110,00
        optimizer estimated cost: 568,03

        Source result set:
        Project-Restrict ResultSet (3):
        Number of opens = 1
        Rows seen = 8
        Rows filtered = 0
        restriction = false
        projection = true
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count: 11,00
        optimizer estimated cost: 5,91

        Source result set:
        Index Scan ResultSet for USER_LOG_EVENT using constraint FK64B9199FD4311151AB41192233BF62B at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 8
        Rows filtered = 0
        Fetch Size = 1
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        next time in milliseconds/row = 0

        scan information:
        Bit set of columns fetched=

        {0}

        Number of columns fetched=1
        Number of deleted rows visited=0
        Number of pages visited=3
        Number of rows qualified=8
        Number of rows visited=9
        Scan type=btree
        Tree height=3
        start position:
        >= on first 1 column(s).
        Ordered null semantics on the following columns:
        0
        stop position:
        > on first 1 column(s).
        Ordered null semantics on the following columns:
        0
        qualifiers:
        None
        optimizer estimated row count: 11,00
        optimizer estimated cost: 5,91

        Right result set:
        Project-Restrict ResultSet (7):
        Number of opens = 1
        Rows seen = 25
        Rows filtered = 0
        restriction = false
        projection = true
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        restriction time (milliseconds) = 0
        projection time (milliseconds) = 0
        optimizer estimated row count: 99,00
        optimizer estimated cost: 562,12

        Source result set:
        Index Row to Base Row ResultSet for DATA_FLOW_LOG_EVENT:
        Number of opens = 1
        Rows seen = 25
        Columns accessed from heap =

        {5}

        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 99,00
        optimizer estimated cost: 562,12

        Index Scan ResultSet for DATA_FLOW_LOG_EVENT using constraint FK64B9199FD431115378EE903 at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 25
        Rows filtered = 0
        Fetch Size = 1
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        next time in milliseconds/row = 0

        scan information:
        Bit set of columns fetched=All
        Number of columns fetched=2
        Number of deleted rows visited=0
        Number of pages visited=3
        Number of rows qualified=25
        Number of rows visited=26
        Scan type=btree
        Tree height=-1
        start position:
        >= on first 1 column(s).
        Ordered null semantics on the following columns:
        0
        stop position:
        > on first 1 column(s).
        Ordered null semantics on the following columns:
        0
        qualifiers:
        None
        optimizer estimated row count: 99,00
        optimizer estimated cost: 562,12

        Show
        Michael Gerz added a comment - Good-performance query plan (for simplified query): ---------------------------------------------------------------- 2008-06-08 11:31:19.406 GMT: Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.1.3 - (648739): instance a816c00e-011a-67f1-d490-0000000ceb90 on database directory XXX Database Class Loader started - derby.database.classpath='' 2008-06-08 11:31:52.328 GMT Thread [main,5,main] (XID = 3462637), (SESSIONID = 0), select logevent0_.clazz_ as clazz_ from ( select TEST_RUN_ID, nullif('x','x') as RECEIVER, 2 as clazz_ from USER_LOG_EVENT union all select TEST_RUN_ID, RECEIVER, 4 as clazz_ from DATA_FLOW_LOG_EVENT ) logevent0_ where logevent0_.TEST_RUN_ID=16188523 ******* Project-Restrict ResultSet (9): Number of opens = 1 Rows seen = 33 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 110,00 optimizer estimated cost: 568,03 Source result set: Project-Restrict ResultSet (8): Number of opens = 1 Rows seen = 33 Rows filtered = 0 restriction = true projection = false constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 110,00 optimizer estimated cost: 568,03 Source result set: Union ResultSet: Number of opens = 1 Rows seen from the left = 8 Rows seen from the right = 25 Rows returned = 33 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 110,00 optimizer estimated cost: 568,03 Left result set: Normalize ResultSet: Number of opens = 1 Rows seen = 8 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 110,00 optimizer estimated cost: 568,03 Source result set: Project-Restrict ResultSet (3): Number of opens = 1 Rows seen = 8 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 11,00 optimizer estimated cost: 5,91 Source result set: Index Scan ResultSet for USER_LOG_EVENT using constraint FK64B9199FD4311151AB41192233BF62B at read committed isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 8 Rows filtered = 0 Fetch Size = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched= {0} Number of columns fetched=1 Number of deleted rows visited=0 Number of pages visited=3 Number of rows qualified=8 Number of rows visited=9 Scan type=btree Tree height=3 start position: >= on first 1 column(s). Ordered null semantics on the following columns: 0 stop position: > on first 1 column(s). Ordered null semantics on the following columns: 0 qualifiers: None optimizer estimated row count: 11,00 optimizer estimated cost: 5,91 Right result set: Project-Restrict ResultSet (7): Number of opens = 1 Rows seen = 25 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 99,00 optimizer estimated cost: 562,12 Source result set: Index Row to Base Row ResultSet for DATA_FLOW_LOG_EVENT: Number of opens = 1 Rows seen = 25 Columns accessed from heap = {5} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 99,00 optimizer estimated cost: 562,12 Index Scan ResultSet for DATA_FLOW_LOG_EVENT using constraint FK64B9199FD431115378EE903 at read committed isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 25 Rows filtered = 0 Fetch Size = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=2 Number of deleted rows visited=0 Number of pages visited=3 Number of rows qualified=25 Number of rows visited=26 Scan type=btree Tree height=-1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: 0 stop position: > on first 1 column(s). Ordered null semantics on the following columns: 0 qualifiers: None optimizer estimated row count: 99,00 optimizer estimated cost: 562,12
        Hide
        Michael Gerz added a comment -

        Note: The query plans above refer to queries with 33 results. I wasn't able to re-run the example given in the initial description, because I did not remember the TEST_RUN_ID used before. However, the performance problem is independent from any concrete TEST_RUN_ID.

        Do you need any other information?

        Thanks in advance,

        Michael

        Show
        Michael Gerz added a comment - Note: The query plans above refer to queries with 33 results. I wasn't able to re-run the example given in the initial description, because I did not remember the TEST_RUN_ID used before. However, the performance problem is independent from any concrete TEST_RUN_ID. Do you need any other information? Thanks in advance, Michael
        Hide
        Bryan Pendleton added a comment -

        The predicate (logevent0_.TEST_RUN_ID=16188523) isn't getting
        "pushed down" into the union properly, so it's isn't being used in
        the index scan, and the entire base table is being fetched and union'ed
        together, and then qualified at the top level.

        I'm not sure why this isn't happening. We have a number of tests which
        demonstrate that, in general, predicate pushdown occurs correctly.

        Do we have a reproducible test case? Can you attach your database to
        the issue as a ZIP file?

        Show
        Bryan Pendleton added a comment - The predicate (logevent0_.TEST_RUN_ID=16188523) isn't getting "pushed down" into the union properly, so it's isn't being used in the index scan, and the entire base table is being fetched and union'ed together, and then qualified at the top level. I'm not sure why this isn't happening. We have a number of tests which demonstrate that, in general, predicate pushdown occurs correctly. Do we have a reproducible test case? Can you attach your database to the issue as a ZIP file?
        Hide
        Michael Gerz added a comment -

        Unfortunately, I am not allowed to publish our database.

        Maybe it helps to create a new database based on the schema above and fill it with some random values.

        Show
        Michael Gerz added a comment - Unfortunately, I am not allowed to publish our database. Maybe it helps to create a new database based on the schema above and fill it with some random values.
        Hide
        Knut Anders Hatlen added a comment -

        Triaged for 10.5.2.

        Show
        Knut Anders Hatlen added a comment - Triaged for 10.5.2.

          People

          • Assignee:
            Unassigned
            Reporter:
            Michael Gerz
          • Votes:
            1 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:

              Development