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

        Michael Gerz created issue -
        Michael Gerz made changes -
        Field Original Value New Value
        Comment [ Query plan for bad-performance query (Java 6). Have fun!

        2008-06-08 10:41:00.781 GMT Thread[RMI TCP Connection(3)-192.168.1.33,5,RMI Runtime] (XID = 3462556), (SESSIONID = 0), select logevent0_.ID as ID7_, logevent0_.INDEX_SENT as INDEX2_7_, logevent0_.TEST_RUN_ID as TEST3_7_, logevent0_.SENDER as SENDER7_, logevent0_.TIME_SENT as TIME5_7_, logevent0_.MESSAGE as MESSAGE8_, logevent0_.SEVERITY as SEVERITY8_, logevent0_.SERIALIZED_CONTENT as SERIALIZED1_11_, logevent0_.RECEIVER as RECEIVER11_, logevent0_.TIME_RECEIVED as TIME3_11_, logevent0_.INDEX_RECEIVED as INDEX4_11_, logevent0_.ACTION_REQUEST as ACTION1_13_, logevent0_.ACTION_REPLY as ACTION1_14_, logevent0_.clazz_ as clazz_ from ( select nullif('x','x') as RECEIVER, TIME_SENT, SEVERITY, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID, SENDER, MESSAGE, TEST_RUN_ID, nullif('x','x') as SERIALIZED_CONTENT, INDEX_SENT, nullif(0,0) as INDEX_RECEIVED, nullif('x','x') as ACTION_REQUEST, nullif('x','x') as ACTION_REPLY, 2 as clazz_ from USER_LOG_EVENT union all select nullif('x','x') as RECEIVER, TIME_SENT, SEVERITY, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID, SENDER, MESSAGE, TEST_RUN_ID, nullif('x','x') as SERIALIZED_CONTENT, INDEX_SENT, nullif(0,0) as INDEX_RECEIVED, nullif('x','x') as ACTION_REQUEST, nullif('x','x') as ACTION_REPLY, 3 as clazz_ from DEVEL_LOG_EVENT union all select nullif('x','x') as RECEIVER, TIME_SENT, nullif('x','x') as SEVERITY, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID, SENDER, nullif('x','x') as MESSAGE, TEST_RUN_ID, nullif('x','x') as SERIALIZED_CONTENT, INDEX_SENT, nullif(0,0) as INDEX_RECEIVED, ACTION_REQUEST, nullif('x','x') as ACTION_REPLY, 6 as clazz_ from ACTION_REQUEST_LOG_EVENT union all select nullif('x','x') as RECEIVER, TIME_SENT, nullif('x','x') as SEVERITY, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID, SENDER, nullif('x','x') as MESSAGE, TEST_RUN_ID, nullif('x','x') as SERIALIZED_CONTENT, INDEX_SENT, nullif(0,0) as INDEX_RECEIVED, nullif('x','x') as ACTION_REQUEST, ACTION_REPLY, 7 as clazz_ from ACTION_REPLY_LOG_EVENT union all select RECEIVER, TIME_SENT, nullif('x','x') as SEVERITY, TIME_RECEIVED, ID, SENDER, nullif('x','x') as MESSAGE, TEST_RUN_ID, SERIALIZED_CONTENT, INDEX_SENT, INDEX_RECEIVED, nullif('x','x') as ACTION_REQUEST, nullif('x','x') as ACTION_REPLY, 4 as clazz_ from DATA_FLOW_LOG_EVENT ) logevent0_ where logevent0_.TEST_RUN_ID=? ******* Project-Restrict ResultSet (22):
        Number of opens = 1
        Rows seen = 6
        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: 1112389,00
        optimizer estimated cost: 4047453,42

        Source result set:
        Project-Restrict ResultSet (21):
        Number of opens = 1
        Rows seen = 1112364
        Rows filtered = 1112358
        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: 1112389,00
        optimizer estimated cost: 4047453,42

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 271467
        Rows seen from the right = 840897
        Rows returned = 1112364
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 1112389,00
        optimizer estimated cost: 4047453,42

        Left result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 271467
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 1112389,00
        optimizer estimated cost: 4047453,42

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 270962
        Rows seen from the right = 505
        Rows returned = 271467
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 271487,00
        optimizer estimated cost: 288473,90

        Left result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 270962
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 271487,00
        optimizer estimated cost: 288473,90

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 228943
        Rows seen from the right = 42019
        Rows returned = 270962
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 270977,00
        optimizer estimated cost: 287878,82

        Left result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 228943
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 270977,00
        optimizer estimated cost: 287878,82

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 225313
        Rows seen from the right = 3630
        Rows returned = 228943
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 228953,00
        optimizer estimated cost: 250730,46

        Left result set:
        Project-Restrict ResultSet (6):
        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: 243799,96

        Source result set:
        Table Scan ResultSet for USER_LOG_EVENT 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=All
        Number of columns fetched=7
        Number of pages visited=1634
        Number of rows qualified=225313
        Number of rows visited=225313
        Scan type=heap
        start position:
        null stop position:
        null qualifiers:
        None
        optimizer estimated row count: 225318,00
        optimizer estimated cost: 243799,96

        Right result set:
        Project-Restrict ResultSet (8):
        Number of opens = 1
        Rows seen = 3630
        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: 3635,00
        optimizer estimated cost: 6930,50

        Source result set:
        Table Scan ResultSet for DEVEL_LOG_EVENT at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 3630
        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=7
        Number of pages visited=46
        Number of rows qualified=3630
        Number of rows visited=3630
        Scan type=heap
        start position:
        null stop position:
        null qualifiers:
        None
        optimizer estimated row count: 3635,00
        optimizer estimated cost: 6930,50



        Right result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 42019
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 270977,00
        optimizer estimated cost: 287878,82

        Source result set:
        Project-Restrict ResultSet (11):
        Number of opens = 1
        Rows seen = 42019
        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: 42024,00
        optimizer estimated cost: 37148,36

        Source result set:
        Table Scan ResultSet for ACTION_REQUEST_LOG_EVENT at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 42019
        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=6
        Number of pages visited=243
        Number of rows qualified=42019
        Number of rows visited=42019
        Scan type=heap
        start position:
        null stop position:
        null qualifiers:
        None
        optimizer estimated row count: 42024,00
        optimizer estimated cost: 37148,36




        Right result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 505
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 271487,00
        optimizer estimated cost: 288473,90

        Source result set:
        Project-Restrict ResultSet (15):
        Number of opens = 1
        Rows seen = 505
        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: 510,00
        optimizer estimated cost: 595,08

        Source result set:
        Table Scan ResultSet for ACTION_REPLY_LOG_EVENT at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 505
        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=6
        Number of pages visited=4
        Number of rows qualified=505
        Number of rows visited=505
        Scan type=heap
        start position:
        null stop position:
        null qualifiers:
        None
        optimizer estimated row count: 510,00
        optimizer estimated cost: 595,08




        Right result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 840897
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 1112389,00
        optimizer estimated cost: 4047453,42

        Source result set:
        Project-Restrict ResultSet (19):
        Number of opens = 1
        Rows seen = 840897
        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: 840902,00
        optimizer estimated cost: 3758979,52

        Source result set:
        Table Scan ResultSet for DATA_FLOW_LOG_EVENT at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 840897
        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=9
        Number of pages visited=140486
        Number of rows qualified=840897
        Number of rows visited=840897
        Scan type=heap
        start position:
        null stop position:
        null qualifiers:
        None
        optimizer estimated row count: 840902,00
        optimizer estimated cost: 3758979,52



        ]
        Michael Gerz made changes -
        Comment [ Good-performance query plan (Java 5):

        2008-06-08 10:47:29.656 GMT Thread[RMI TCP Connection(2)-192.168.1.33,5,RMI Runtime] (XID = 3462592), (SESSIONID = 0), select logevent0_.ID as ID7_, logevent0_.INDEX_SENT as INDEX2_7_, logevent0_.TEST_RUN_ID as TEST3_7_, logevent0_.SENDER as SENDER7_, logevent0_.TIME_SENT as TIME5_7_, logevent0_.MESSAGE as MESSAGE8_, logevent0_.SEVERITY as SEVERITY8_, logevent0_.SERIALIZED_CONTENT as SERIALIZED1_11_, logevent0_.RECEIVER as RECEIVER11_, logevent0_.TIME_RECEIVED as TIME3_11_, logevent0_.INDEX_RECEIVED as INDEX4_11_, logevent0_.ACTION_REQUEST as ACTION1_13_, logevent0_.ACTION_REPLY as ACTION1_14_, logevent0_.clazz_ as clazz_ from ( select TEST_RUN_ID, SENDER, MESSAGE, SEVERITY, nullif('x','x') as SERIALIZED_CONTENT, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID, nullif('x','x') as ACTION_REQUEST, TIME_SENT, nullif('x','x') as ACTION_REPLY, nullif('x','x') as RECEIVER, nullif(0,0) as INDEX_RECEIVED, INDEX_SENT, 2 as clazz_ from USER_LOG_EVENT union all select TEST_RUN_ID, SENDER, MESSAGE, SEVERITY, nullif('x','x') as SERIALIZED_CONTENT, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID, nullif('x','x') as ACTION_REQUEST, TIME_SENT, nullif('x','x') as ACTION_REPLY, nullif('x','x') as RECEIVER, nullif(0,0) as INDEX_RECEIVED, INDEX_SENT, 3 as clazz_ from DEVEL_LOG_EVENT union all select TEST_RUN_ID, SENDER, nullif('x','x') as MESSAGE, nullif('x','x') as SEVERITY, nullif('x','x') as SERIALIZED_CONTENT, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID, ACTION_REQUEST, TIME_SENT, nullif('x','x') as ACTION_REPLY, nullif('x','x') as RECEIVER, nullif(0,0) as INDEX_RECEIVED, INDEX_SENT, 6 as clazz_ from ACTION_REQUEST_LOG_EVENT union all select TEST_RUN_ID, SENDER, nullif('x','x') as MESSAGE, nullif('x','x') as SEVERITY, nullif('x','x') as SERIALIZED_CONTENT, nullif('2000-1-1 00:00:00','2000-1-1 00:00:00') as TIME_RECEIVED, ID, nullif('x','x') as ACTION_REQUEST, TIME_SENT, ACTION_REPLY, nullif('x','x') as RECEIVER, nullif(0,0) as INDEX_RECEIVED, INDEX_SENT, 7 as clazz_ from ACTION_REPLY_LOG_EVENT union all select TEST_RUN_ID, SENDER, nullif('x','x') as MESSAGE, nullif('x','x') as SEVERITY, SERIALIZED_CONTENT, TIME_RECEIVED, ID, nullif('x','x') as ACTION_REQUEST, TIME_SENT, nullif('x','x') as ACTION_REPLY, RECEIVER, INDEX_RECEIVED, INDEX_SENT, 4 as clazz_ from DATA_FLOW_LOG_EVENT ) logevent0_ where logevent0_.TEST_RUN_ID=? ******* Project-Restrict ResultSet (27):
        Number of opens = 1
        Rows seen = 6
        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: 109,81
        optimizer estimated cost: 564,97

        Source result set:
        Project-Restrict ResultSet (26):
        Number of opens = 1
        Rows seen = 6
        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: 109,81
        optimizer estimated cost: 564,97

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 6
        Rows seen from the right = 0
        Rows returned = 6
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 109,81
        optimizer estimated cost: 564,97

        Left result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 6
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 109,81
        optimizer estimated cost: 564,97

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 5
        Rows seen from the right = 1
        Rows returned = 6
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 28,86
        optimizer estimated cost: 94,85

        Left result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 5
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 28,86
        optimizer estimated cost: 94,85

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 2
        Rows seen from the right = 3
        Rows returned = 5
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 27,48
        optimizer estimated cost: 87,79

        Left result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 2
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 27,48
        optimizer estimated cost: 87,79

        Source result set:
        Union ResultSet:
        Number of opens = 1
        Rows seen from the left = 2
        Rows seen from the right = 0
        Rows returned = 2
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 23,56
        optimizer estimated cost: 73,32

        Left result set:
        Project-Restrict ResultSet (7):
        Number of opens = 1
        Rows seen = 2
        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: 20,88
        optimizer estimated cost: 60,78

        Source result set:
        Index Row to Base Row ResultSet for USER_LOG_EVENT:
        Number of opens = 1
        Rows seen = 2
        Columns accessed from heap = {0, 1, 3, 4, 5, 6}
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 20,88
        optimizer estimated cost: 60,78

        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 = 2
        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=2
        Number of rows visited=3
        Scan type=btree
        Tree height=3
        start position:
        >= on first 1 column(s).
        Ordered null semantics on the following columns:

        stop position:
        > on first 1 column(s).
        Ordered null semantics on the following columns:

        qualifiers:
        None
        optimizer estimated row count: 20,88
        optimizer estimated cost: 60,78


        Right result set:
        Project-Restrict ResultSet (10):
        Number of opens = 1
        Rows seen = 0
        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: 2,68
        optimizer estimated cost: 12,54

        Source result set:
        Index Row to Base Row ResultSet for DEVEL_LOG_EVENT:
        Number of opens = 1
        Rows seen = 0
        Columns accessed from heap = {0, 1, 3, 4, 5, 6}
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 2,68
        optimizer estimated cost: 12,54

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

        scan information:
        Bit set of columns fetched=All
        Number of columns fetched=2
        Number of deleted rows visited=0
        Number of pages visited=2
        Number of rows qualified=0
        Number of rows visited=1
        Scan type=btree
        Tree height=2
        start position:
        >= on first 1 column(s).
        Ordered null semantics on the following columns:

        stop position:
        > on first 1 column(s).
        Ordered null semantics on the following columns:

        qualifiers:
        None
        optimizer estimated row count: 2,68
        optimizer estimated cost: 12,54




        Right result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 3
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 27,48
        optimizer estimated cost: 87,79

        Source result set:
        Project-Restrict ResultSet (14):
        Number of opens = 1
        Rows seen = 3
        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: 3,92
        optimizer estimated cost: 14,47

        Source result set:
        Index Row to Base Row ResultSet for ACTION_REQUEST_LOG_EVENT:
        Number of opens = 1
        Rows seen = 3
        Columns accessed from heap = {0, 1, 3, 4, 5}
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 3,92
        optimizer estimated cost: 14,47

        Index Scan ResultSet for ACTION_REQUEST_LOG_EVENT using constraint FK64B9199FD431115B413BAD6F8960E06 at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 3
        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=3
        Number of rows visited=4
        Scan type=btree
        Tree height=3
        start position:
        >= on first 1 column(s).
        Ordered null semantics on the following columns:

        stop position:
        > on first 1 column(s).
        Ordered null semantics on the following columns:

        qualifiers:
        None
        optimizer estimated row count: 3,92
        optimizer estimated cost: 14,47





        Right result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 1
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 28,86
        optimizer estimated cost: 94,85

        Source result set:
        Project-Restrict ResultSet (19):
        Number of opens = 1
        Rows seen = 1
        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: 1,38
        optimizer estimated cost: 7,05

        Source result set:
        Index Row to Base Row ResultSet for ACTION_REPLY_LOG_EVENT:
        Number of opens = 1
        Rows seen = 1
        Columns accessed from heap = {0, 1, 3, 4, 5}
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 1,38
        optimizer estimated cost: 7,05

        Index Scan ResultSet for ACTION_REPLY_LOG_EVENT using constraint FK64B9199FD431115B413BAD656CF5661 at read committed isolation level using share row locking chosen by the optimizer
        Number of opens = 1
        Rows seen = 1
        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=2
        Number of rows qualified=1
        Number of rows visited=2
        Scan type=btree
        Tree height=2
        start position:
        >= on first 1 column(s).
        Ordered null semantics on the following columns:

        stop position:
        > on first 1 column(s).
        Ordered null semantics on the following columns:

        qualifiers:
        None
        optimizer estimated row count: 1,38
        optimizer estimated cost: 7,05





        Right result set:
        Normalize ResultSet:
        Number of opens = 1
        Rows seen = 0
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 109,81
        optimizer estimated cost: 564,97

        Source result set:
        Project-Restrict ResultSet (24):
        Number of opens = 1
        Rows seen = 0
        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: 80,95
        optimizer estimated cost: 470,12

        Source result set:
        Index Row to Base Row ResultSet for DATA_FLOW_LOG_EVENT:
        Number of opens = 1
        Rows seen = 0
        Columns accessed from heap = {0, 1, 3, 4, 5, 6, 7, 8}
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 0
        optimizer estimated row count: 80,95
        optimizer estimated cost: 470,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 = 0
        Rows filtered = 0
        Fetch Size = 1
        constructor time (milliseconds) = 0
        open time (milliseconds) = 0
        next time (milliseconds) = 0
        close time (milliseconds) = 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=0
        Number of rows visited=1
        Scan type=btree
        Tree height=3
        start position:
        >= on first 1 column(s).
        Ordered null semantics on the following columns:

        stop position:
        > on first 1 column(s).
        Ordered null semantics on the following columns:

        qualifiers:
        None
        optimizer estimated row count: 80,95
        optimizer estimated cost: 470,12




        ]
        Dag H. Wanvik made changes -
        Component/s Performance [ 11709 ]
        Dag H. Wanvik made changes -
        Derby Categories [Performance]
        Dag H. Wanvik made changes -
        Component/s SQL [ 11408 ]
        Knut Anders Hatlen made changes -
        Urgency Urgent Normal
        Kathey Marsden made changes -
        Labels derby_triage10_5_2
        Gavin made changes -
        Workflow jira [ 12432778 ] Default workflow, editable Closed status [ 12798800 ]

          People

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

            Dates

            • Created:
              Updated:

              Development