[jira] [Created] (KYLIN-4432) duplicated queries with sytax error take unexpect long time when lazy query enabled

["Congling Xia (Jira)" <ji...@apache.org>]

Congling Xia created KYLIN-4432:
-----------------------------------

             Summary: duplicated queries with sytax error take unexpect long time when lazy query enabled
                 Key: KYLIN-4432
                 URL: https://issues.apache.org/jira/browse/KYLIN-4432
             Project: Kylin
          Issue Type: Bug
            Reporter: Congling Xia


Hi! Our Kylin server becomes unresponsive recently. All query threads were being TIMED_WAITING so that no more thread in the thread pool of Tomcat could response new requests. The server logs are full of "Duplicate SQL request"s, and many requests retrying for so long time:
{code:java}
$ cat kylin.log.25 | grep 14db5fa0-78e0-4ca6-5d04-92995b2b8367-3133991 | head -3
2020-03-23 12:15:32,279 INFO [Query 14db5fa0-78e0-4ca6-5d04-92995b2b8367-3133991] service.QueryService:571 : Duplicated SQL request is running, waiting...
2020-03-23 12:15:32,379 INFO [Query 14db5fa0-78e0-4ca6-5d04-92995b2b8367-3133991] service.QueryService:571 : Duplicated SQL request is running, waiting...
2020-03-23 12:15:32,479 INFO [Query 14db5fa0-78e0-4ca6-5d04-92995b2b8367-3133991] service.QueryService:571 : Duplicated SQL request is running, waiting...

$ cat kylin.log.25 | grep 14db5fa0-78e0-4ca6-5d04-92995b2b8367-3133991 | tail -3
2020-03-23 12:26:56,920 INFO [Query 14db5fa0-78e0-4ca6-5d04-92995b2b8367-3133991] service.QueryService:571 : Duplicated SQL request is running, waiting...
2020-03-23 12:26:57,020 INFO [Query 14db5fa0-78e0-4ca6-5d04-92995b2b8367-3133991] service.QueryService:571 : Duplicated SQL request is running, waiting...
2020-03-23 12:26:57,121 INFO [Query 14db5fa0-78e0-4ca6-5d04-92995b2b8367-3133991] service.QueryService:571 : Duplicated SQL request is running, waiting...
{code}
This can be re-produced easily:
 * enable lazy query (KYLIN-2897) by setting environment variable kylin.query.cache-enabled=true and kylin.query.lazy-query-enabled=true
 * send the same query with syntax error many times in several minutes

The first query will quickly response with error message, and the following queries will executing for long time and will repeatly output "Duplicated SQL request is running, waiting...".

The code in org.apache.kylin.rest.service.QueryService#searchQueryInCache indicates duplicated query will wait at most one minute with default setting of LazyQueryWaitingTimeoutMilliSeconds but in fact it waits quite longer than that.
{code:java}
while (response.isRunning()) {
    // Wait at most one minute
    if (System.currentTimeMillis() - response.getLazyQueryStartTime() >= getConfig()
            .getLazyQueryWaitingTimeoutMilliSeconds()) {
        cache.evict(sqlRequest.getCacheKey());
        return null;
    }
    logger.info("Duplicated SQL request is running, waiting...");
    try {
        Thread.sleep(100L);
    } catch (InterruptedException e) {
    }
    wrapper = cache.get(sqlRequest.getCacheKey());
    if (wrapper == null) {
        return null;
    }
    response = (SQLResponse) wrapper.get();
    if (response == null) {
        return null;
    }
}
{code}
After some work-around, I find that the dummy response status remains unchanged after execution with exception. So the 2nd query will wait LazyQueryWaitingTimeoutMilliSeconds, evict the dummy response created by the 1st query from cache, and put a new dummy response into the cache. And the 3rd query may use the new dummy response's start time to compute timeout, and will wait for another LazyQueryWaitingTimeoutMilliSeconds.

Suppose we send _n_ identical bad queries to the server quickly. The last query may wait for nearly _(n-1)_ times of LazyQueryWaitingTimeoutMilliSeconds. That's why the Web container's thread pool was exhausted – user program uses bad queries to check availability of Kylin service and retries many times in a short time.



--
This message was sent by Atlassian Jira
(v8.3.4#803005)