This discussion is archived
6 Replies Latest reply: Mar 1, 2012 1:42 PM by mikereiche RSS

ODSI Runtime Performance Evaluation Question

895498 Newbie
Currently Being Moderated
Hi, I am in need to review and improve ODSI response times . On some occasion the ODSI call take too much time top process.
Can someone help me understand the log entries related to performance and what do they mean?

Can we analyze the example below and help me to understand what these numbers mean in detail

query/performance
{
compiletime: 2081
}

rows: 1
time: 2
}

}
query/performance {
evaltime: 60
}

common/time
{
timestamp: Mon Feb 27 21:33:21 EST 2012
duration: 2143
}


Thanks Peter
------------------------------Example--------------------------------------------------------------------------------


####<Feb 27, 2012 9:33:23 PM EST> <Info> <ODSI> <ei00m72> <dataserver2> <[ACTIVE] ExecuteThread: '5' for queue: 'weblogic.kernel.Default (self-tuning)'> <<anonymous>> <> <> <1330396403967> <BEA-000000> <producerinquiryv2> <DSPAuditEvent timestamp: Mon Feb 27 21:33:21 EST 2012 severity: WARNING id: producerinquiryv2:314:Mon Feb 27 21:33:21 EST 2012 {
common/application {
user: <anonymous>
name: producerinquiryv2
eventkind: evaluation
principals:
server: dataserver2
}
query/cache/queryplan {
type: XQUERY_PLAN_CACHE
found: false
}
query/cache/queryplan {
type: XQUERY_PLAN_CACHE
inserted: true
}
query/performance {
compiletime: 2081
}
query/wrappers/relational {
source: oracleods
sql: SELECT t3.c1
FROM (
SELECT ROWNUM AS c2, t2.c1
FROM (
SELECT t1."REGISTERED_CRD_NO" AS c1
FROM "MKRD01"."MARKETER" t1
WHERE ((t1."MARKETER_ID" = ?) AND (t1."REGISTERED_CRD_NO" IS NOT NULL) AND (
t1."REGISTERED_CRD_NO" IS NOT NULL))
) t2
WHERE (ROWNUM < 2)
) t3
WHERE (t3.c2 = 1)
parameters: 0000289
basesql: SELECT t3.c1
FROM (
SELECT ROWNUM AS c2, t2.c1
FROM (
SELECT t1."REGISTERED_CRD_NO" AS c1
FROM {MKRD01}.{MARKETER} t1
WHERE ((t1."MARKETER_ID" = ?) AND (t1."REGISTERED_CRD_NO" IS NOT NULL) AND (
t1."REGISTERED_CRD_NO" IS NOT NULL))
) t2
WHERE (ROWNUM < 2)
) t3
WHERE (t3.c2 = 1)
rows: 1
time: 2
}
query/wrappers/relational {
source: oracleods
sql: SELECT TRUNC(t1."NASD_CAN_DT") AS c1, TRUNC(t1."NASD_SRS_APRV_DT") AS c2, t1."MARKETER_ID" AS c3,
t1."NASD_SRS_APRV_DT" AS c4, t1."NASD_SRS_TP_CD" AS c5, t2."NASD_EXAM_DN" AS c6,
t2."NASD_EXAM_NM" AS c7, t2."NASD_EXAM_SERIES_CD" AS c8, t2."NASD_EXAM_TYP_CD" AS c9
FROM "MKRD01"."NASD_EX" t1
LEFT OUTER JOIN "CPRF01"."NASD_RGSTRN_EXAM_TP" t2
ON (t2."NASD_EXAM_TYP_CD" = t1."NASD_SRS_TP_CD")
WHERE (? = t1."MARKETER_ID")
ORDER BY t1."MARKETER_ID" ASC, t1."NASD_SRS_TP_CD" ASC, t1."NASD_SRS_APRV_DT" ASC
parameters: 0000289
basesql: SELECT TRUNC(t1."NASD_CAN_DT") AS c1, TRUNC(t1."NASD_SRS_APRV_DT") AS c2, t1."MARKETER_ID" AS c3,
t1."NASD_SRS_APRV_DT" AS c4, t1."NASD_SRS_TP_CD" AS c5, t2."NASD_EXAM_DN" AS c6,
t2."NASD_EXAM_NM" AS c7, t2."NASD_EXAM_SERIES_CD" AS c8, t2."NASD_EXAM_TYP_CD" AS c9
FROM {MKRD01}.{NASD_EX} t1
LEFT OUTER JOIN {CPRF01}.{NASD_RGSTRN_EXAM_TP} t2
ON (t2."NASD_EXAM_TYP_CD" = t1."NASD_SRS_TP_CD")
WHERE (? = t1."MARKETER_ID")
ORDER BY t1."MARKETER_ID" ASC, t1."NASD_SRS_TP_CD" ASC, t1."NASD_SRS_APRV_DT" ASC
rows: 2
time: 6
}
query/performance {
evaltime: 60
}
query/service {
function: retrieveProducerNasdExams
arity: 1
dataservice: ld:dataservices/producernasdexamsinquiry.ds
parameters: [producerrequests:ProducerRequest]
query: declare namespace ns0="ld:dataservices/producernasdexamsinquiry";
declare namespace ns1="http://newyorklife.com/services/data/producer/producerrequests";
declare variable $__fparam0 as element(ns1:ProducerRequest) external;
ns0:retrieveProducerNasdExams($__fparam0)
}
common/time {
timestamp: Mon Feb 27 21:33:21 EST 2012
duration: 2143
}
}>
  • 1. Re: ODSI Runtime Performance Evaluation Question
    mikereiche Pro
    Currently Being Moderated
    Run the query 50 times or so, then measure the execution time. (the very first execution, classes are loaded and the query is compiled, beyond that, the JVM does more optimization depending on the number of times a method is executed). Without knowing any details of your query, I'd guess it should run in the 10ms range.

    The audit information is pretty much self-explanatory. The time is all in milliseconds. Compiled query plans are cached (in memory), so after the first execution of a query, there will not be a "compiletime". The "duration" includes the compilation and evaluation (plus cloning of the query plan which is not in the audit). System.currentTimeMillis() is used for the timer, so it is not super-accurate. All the time is measurements are on the server, so if you make measurements yourself on the client, they will be slightly longer.

    Also - since the query is executed as the results are pulled by the client, if the client initiates the query, then does something else before reading back the result, the "duration" will not be a measure of how quickly the query could have been executed.
  • 2. Re: ODSI Runtime Performance Evaluation Question
    895498 Newbie
    Currently Being Moderated
    Hi, Thanks for the answer, but I have noticed that this query compilation time is affecting my reponse times in production daily. We are calling data service methods in low volumes like 500 per day and compile time is affecting the response times ,,
    How long the plan is cashed in ODSI ? Is there any possibility we can force ODSI to hold the execution plan as long as possible.
    Less times I call the service longer it takes, affecting the average response time and customers r complaining.
    I think ODSI is clearing the cash after some time of no activity.

    There is a setting in the console "Max Number of Query Plan Cached" this is per dataspace ,,, can I use this to help my problem?
    Peter
  • 3. Re: ODSI Runtime Performance Evaluation Question
    895498 Newbie
    Currently Being Moderated
    Hi , just to add mor information ,some compile times in our case take as much as 20 seconds and the client application calls are timing out. I agree that these are very complex queries but 20 seconds to create as query plan that is long time.

    Peter
  • 4. Re: ODSI Runtime Performance Evaluation Question
    mikereiche Pro
    Currently Being Moderated
    There's no time-limit to cached query plans. The only limit is the cache size. The least-recently-used plan will be discarded as necessary.

    The cache is per-server so that executing the same query on two different servers will result in compiles for each.

    The cache is within the application's memory, so that redeploying the application will result in the cache being cleared for that application.

    Also restarting a server will result in the cache being cleared.

    Also keep in mind that if you are using constant arguments in filters, each execution with a different value will result in a different query and query plan (these should be parameterized).

    Also ad-hoc queries will fill up your query plan cache. There is a request config setting ( DO_NOT_CACHE_QUERY_PLAN ) to not cache the query plan.

    If, after all that, you still have unexplained instances of recompilation, open a case with customer support and attach all the server logs from the last server restart up until the recompilations - and note the file and line number where the first and second compilations occur.
  • 5. Re: ODSI Runtime Performance Evaluation Question
    895498 Newbie
    Currently Being Moderated
    Hi, thanks again for your help. , what I have noticed is that the every Monday in ODSI there is a major increase in response time. What really happens is that every Monday ODSI is creating new query plans and cashes them. Now this puzzles me because we don't recycle ODSI environment during the weekend,,, but only the databases that we use as source are recycled every Sunday.
    Is it possible that the Xquery plans are cleaned because of the databases are restarted?
    May be the JVM garbage collection is clearing the memory once all the db connections are closed?



    Also you have said that the Xquery cash one per Weblogic instance not one per dataspace, do I this understand right?
    Because settings are per dataspace...

    Thanks Peter
  • 6. Re: ODSI Runtime Performance Evaluation Question
    mikereiche Pro
    Currently Being Moderated
    Is it possible that the Xquery plans are cleaned because of the databases are restarted?
    That's an interesting observation. But losing cache entries wouldn't occur like that in any way I can think of. A cached query plan has no connection/relation to database connections. The database connections are only open on the executing plan (which is cloned from the cached plan).
    May be the JVM garbage collection is clearing the memory once all the db connections are closed?
    The query plan cache is (essentially) a HashMap. It is not SoftReferences that the JVM could clean up at will.
    Also you have said that the Xquery cash one per Weblogic instance not one per dataspace
    The maximum number of entries is per dataspace. The cache entries are exist and are counted (separately) on each server - they are not summed across servers. So if you have max 100 cache entries, and you have three servers, you could have 100 + 100 + 100 cache entries across the three servers (but these could be only 100 distinct query plans). I think I was trying to get across that restarting a server or redeploying a dataspace on a server would clear all the cache entries on that server. But if you're not redeploying dataspaces or restarting servers, this is not relevant.

    I'm kind of out of ideas about what could be going on. From the information you've provided I cannot tell if the query compilations are compilations of new queries, or recompilation of previous ones, or if the servers have been restarted, the dataspaces have been updated etc (yes, you said they aren't, but I always like to see). If you want to quickly get to the bottom of this, open an SR and attach the logs.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points