Long compilation time for a Prepared Statement

[Jose Ventura <jo...@gmail.com>]

Hello, list!

I'm using Derby 10.6.1.0, running on Java 1.6.0, on Ubuntu and Windows
7 machines, both 64-bit.

I have a view (VW_WORKFLOW_PENDING_BY_OBJ) which is defined over a
query with 10 joins [1]. At this time, I can't change that definition,
though I realize that design is horribly flawed.

When I try to execute a simple select statement on that view [2], or
even a SELECT * on it, the statement compiler takes about 2 minutes to
complete. The relevant section of the log file is below [3].

The query execution itself does not take long (the view only has about
300 records in my test database, in which I am reproducing the
problem).

I have a few questions:

1. Does the compiler take the amount of records in consideration when
compiling the query?
2. Am I right to assume the cause of the delay is in the excessive
amount of joins, that is causing the compiler (and optimizer) to have
a hard time figuring out the best query plan?
3. Is there any parameter that controls the timeout for that
optimization? Since the view does not actually have many records to
begin with, I think it's acceptable to go with a non-optimal query
plan.
4. Is there any other information I can provide to help debug? There
are no stack traces in the log, but I'm not seeing that much info on
it anyway: I see a line where compilation begins and the next one, two
minutes later, is when the compilation ends. I have also attached my
derby.properties below [4].

Thank you!
- José

[1] View definition:
SELECT    EVENT.TXT_LOGIN AS LOGIN,
        EVENT.DT_CREATED_EVENT AS CREATION_DATE,
        VALUE2.TXT_VALUE AS SUMMARY,
        VALUE2.FK_OBJECT_ID AS EVENT_ID,
        VALUE3.TXT_VALUE AS ACTION,
        VALUE1.TXT_VALUE AS OBJECT_ID,
        VALUE4.TXT_VALUE AS OBJECT_TYPE
FROM    T_AUD_EVENT EVENT, T_AUD_EVENT_TYPE TYPE, T_META_FIELD FIELD1,
        T_META_VALUE VALUE1, T_META_VALUE VALUE2, T_META_VALUE VALUE3,
T_META_VALUE VALUE4,
        T_META_FIELD FIELD2, T_META_FIELD FIELD3, T_META_FIELD FIELD4
WHERE    EVENT.FK_AUD_EVENT_TYPE_ID = TYPE.ID
AND     TYPE.FK_META_TEMPLATE_ID = FIELD1.FK_TEMPLATE_ID
AND     TYPE.FK_META_TEMPLATE_ID = FIELD2.FK_TEMPLATE_ID
AND     TYPE.FK_META_TEMPLATE_ID = FIELD3.FK_TEMPLATE_ID
AND     TYPE.FK_META_TEMPLATE_ID = FIELD4.FK_TEMPLATE_ID
AND     CAST (EVENT.ID AS CHAR(250)) = VALUE1.FK_OBJECT_ID
AND     CAST (EVENT.ID AS CHAR(250)) = VALUE2.FK_OBJECT_ID
AND     CAST (EVENT.ID AS CHAR(250)) = VALUE3.FK_OBJECT_ID
AND     CAST (EVENT.ID AS CHAR(250)) = VALUE4.FK_OBJECT_ID
AND     FIELD1.ID = VALUE1.FK_FIELD_ID
AND     FIELD2.ID = VALUE2.FK_FIELD_ID
AND     FIELD3.ID = VALUE3.FK_FIELD_ID
AND     FIELD1.TXT_NAME = 'targetId'
AND     FIELD2.TXT_NAME = 'summary'
AND     FIELD3.TXT_NAME = 'action'
AND     FIELD4.TXT_NAME = 'targetType'
AND     TYPE.TXT_EVENT_CLASS IN (
'com.sensedia.components.workflow.services.events.WorkflowInstanceCreatedEvent',

'com.sensedia.components.workflow.services.events.WorkflowInstanceDeleteEvent',

'com.sensedia.components.workflow.services.events.WorkflowInstanceTransitedEvent'
)

[2] Statement:
SELECT VW_WORKFLOW_PENDING_BY_OBJ.LOGIN,
VW_WORKFLOW_PENDING_BY_OBJ.CREATION_DATE,
   VW_WORKFLOW_PENDING_BY_OBJ.SUMMARY, VW_WORKFLOW_PENDING_BY_OBJ.EVENT_ID,
   VW_WORKFLOW_PENDING_BY_OBJ.ACTION, VW_WORKFLOW_PENDING_BY_OBJ.OBJECT_ID,
   VW_WORKFLOW_PENDING_BY_OBJ.OBJECT_TYPE
FROM VW_WORKFLOW_PENDING_BY_OBJ VW_WORKFLOW_PENDING_BY_OBJ
WHERE  OBJECT_ID = ? AND  OBJECT_TYPE = ?

[3] Log file:
2011-07-13 19:09:23.867 GMT Thread[DRDAConnThread_3,5,main] (XID =
18336), (SESSIONID = 1), (DATABASE = db), (DRDAID =
NF000001.B01D-1025693504549598387{1}), Begin compiling prepared
statement: SELECT VW_WORKFLOW_PENDING_BY_OBJ.LOGIN,
VW_WORKFLOW_PENDING_BY_OBJ.CREATION_DATE,
VW_WORKFLOW_PENDING_BY_OBJ.SUMMARY,
VW_WORKFLOW_PENDING_BY_OBJ.EVENT_ID,
VW_WORKFLOW_PENDING_BY_OBJ.ACTION,
VW_WORKFLOW_PENDING_BY_OBJ.OBJECT_ID,
VW_WORKFLOW_PENDING_BY_OBJ.OBJECT_TYPE
FROM VW_WORKFLOW_PENDING_BY_OBJ VW_WORKFLOW_PENDING_BY_OBJ WHERE
OBJECT_ID = '2002' AND  OBJECT_TYPE = 'ASSET' :End prepared statement

2011-07-13 19:10:58.348 GMT Thread[DRDAConnThread_3,5,main] (XID =
18336), (SESSIONID = 1), (DATABASE = db), (DRDAID =
NF000001.B01D-1025693504549598387{1}), End compiling prepared
statement: SELECT VW_WORKFLOW_PENDING_BY_OBJ.LOGIN,
VW_WORKFLOW_PENDING_BY_OBJ.CREATION_DATE,
VW_WORKFLOW_PENDING_BY_OBJ.SUMMARY,
VW_WORKFLOW_PENDING_BY_OBJ.EVENT_ID,
VW_WORKFLOW_PENDING_BY_OBJ.ACTION,
VW_WORKFLOW_PENDING_BY_OBJ.OBJECT_ID,
VW_WORKFLOW_PENDING_BY_OBJ.OBJECT_TYPE
FROM VW_WORKFLOW_PENDING_BY_OBJ VW_WORKFLOW_PENDING_BY_OBJ WHERE
OBJECT_ID = '2002' AND  OBJECT_TYPE = 'ASSET' :End prepared statement

2011-07-13 19:10:58.365 GMT Thread[DRDAConnThread_3,5,main] (XID =
18336), (SESSIONID = 1), (DATABASE = db), (DRDAID =
NF000001.B01D-1025693504549598387{1}), Executing prepared statement:
SELECT VW_WORKFLOW_PENDING_BY_OBJ.LOGIN,
VW_WORKFLOW_PENDING_BY_OBJ.CREATION_DATE,
VW_WORKFLOW_PENDING_BY_OBJ.SUMMARY,
VW_WORKFLOW_PENDING_BY_OBJ.EVENT_ID,
VW_WORKFLOW_PENDING_BY_OBJ.ACTION,
VW_WORKFLOW_PENDING_BY_OBJ.OBJECT_ID,
VW_WORKFLOW_PENDING_BY_OBJ.OBJECT_TYPE
FROM VW_WORKFLOW_PENDING_BY_OBJ VW_WORKFLOW_PENDING_BY_OBJ WHERE
OBJECT_ID = '2002' AND  OBJECT_TYPE = 'ASSET' :End prepared statement

[4] Derby.properties:
derby.language.logStatementText=true
derby.locks.deadlockTrace=true
derby.locks.monitor=true
derby.stream.error.logSeverityLevel=0
derby.stream.error.file=error.txt

Re: Long compilation time for a Prepared Statement

[Bryan Pendleton <bp...@gmail.com>]

> 1. Does the compiler take the amount of records in consideration when
> compiling the query?

Yes. The optimizer has statistical information about the size of
the various tables, and about their keying structures, etc.

> 2. Am I right to assume the cause of the delay is in the excessive
> amount of joins, that is causing the compiler (and optimizer) to have
> a hard time figuring out the best query plan?

Possibly. There are extreme combinatorics here, for sure; some of
the search space exploration is factorial in complexity.

I had some similar problems, and opened a job with my findings:
https://issues.apache.org/jira/browse/DERBY-2130

In the details of that job are references to other related jobs.

> 3. Is there any parameter that controls the timeout for that
> optimization? Since the view does not actually have many records to
> begin with, I think it's acceptable to go with a non-optimal query
> plan.

As you'll see in my notes on DERBY-2130, I followed a similar
line of reasoning, and found that by forcing an early termination
of the search, I got a reasonable query plan.

> 4. Is there any other information I can provide to help debug? There
> are no stack traces in the log, but I'm not seeing that much info on
> it anyway: I see a line where compilation begins and the next one, two
> minutes later, is when the compilation ends. I have also attached my
> derby.properties below [4].

This is hard stuff. I'm not sure what to suggest. Although Derby
has powerful algorithms in this area, there are a few weak spots,
and it's possible you've hit one of them.

Since it's open source, we as a community can all work together to
try to improve Derby's implementation in this area.

thanks,

bryan