I created CALCITE-1565 for this issue.
On Thu, Jan 5, 2017 at 12:10 PM, Josh Elser <[email protected]> wrote:
> Hrm, that's frustrating. No stack trace is a bug. I remember there being
> one of these I fixed in the past -- hopefully it's not a new issue. I guess
> the version of Phoenix you're using has a rather out-dated version of
> Avatica by now (1.6.0 vs 1.9.0).
>
> Yes, the EXPLICIT is that the caller (PQS) made a call to remove the
> element from the cache. This lines up with what we'd expect since the
> closeStatement request was sent by the thin-client.
>
> Taking a look at the original stack trace portion in ArrayList, it looks
> even more like a race condition:
>
> for (int index = 0; index < size; index++)
> if (o.equals(elementData[index])) {
> fastRemove(index);
> return true;
> }
>
> The ArrayList found the element we asked it to remove and then tried to
> remove the element at that index. But, by the time it went to remove that
> element, the index was invalid. It doesn't look like Phoenix has any
> synchronization around closing the ResultSet.
>
> So, that makes me think there are two potential causes:
>
> 1) You have multiple clients issuing a closeStatement() at the same time
> and trying to close the ResultSet.
> 2) One client issuing a closeStatement() is racing against PQS closing the
> statement, both trying to close the ResultSet.
>
> This is sounding more and more like an Avatica bug to me. Any chance you
> can share more of the TRACE logging that you've turned on and maybe open up
> a JIRA issue under the CALCITE project (and ping me), please?
>
> I really appreciate your help so far.
>
> Tulasi Paradarami wrote:
>
>> Unfortunately, there's no error stack other than:
>> ArrayIndexOutOfBoundsException: (null exception message)
>>
>> I've set org.apache.calcite.avatica=TRACE
>>
>> jdbc.jdbcMeta has following messages:
>>
>> 17/01/05 18:47:49 TRACE server.AvaticaJsonHandler: request:
>> {"connectionId": "68b4686a-c51e-4e82-b9df-a55eeb6188d4", "request":
>> "closeStatement", "statementId": 15251}
>> 17/01/05 18:47:49 TRACE jdbc.JdbcMeta: closing statement
>> 68b4686a-c51e-4e82-b9df-a55eeb6188d4::15251
>> 17/01/05 18:47:49 DEBUG jdbc.JdbcMeta: Expiring statement 15251 because
>> EXPLICIT
>>
>> EXPLICIT implies statement has been closed and not evicted?
>>
>> On Thu, Jan 5, 2017 at 11:03 AM, Josh Elser <[email protected]
>> <mailto:[email protected]>> wrote:
>>
>> No, PQS itself is not instrumented with the HTrace library, only
>> (parts of?) the thick Phoenix JDBC inside of PQS.
>>
>> There is some support for metrics that I built into Avatica, but,
>> sadly, I've not had the time to spend to focus on how we expose
>> those downstream in Phoenix. That would be the "easiest" way to
>> monitor it, but I think it'd require modifying Phoenix and
>> re-building it (which is likely not something you want to do).
>>
>> You can try setting org.apache.calcite.avatica.jdbc.JdbcMeta=DEBUG
>> in the $PHOENIX_HOME/bin/log4j.properties file. That will print some
>> messages when a statement or connection is automatically evicted
>> from the respective cache.
>>
>> Finally, no stack trace on the ErrorResponse you showed for fetch()?
>>
>> Tulasi Paradarami wrote:
>>
>> Another question: does enabling tracing
>> (https://phoenix.apache.org/tracing.html
>> <https://phoenix.apache.org/tracing.html>) on phoenix help
>> monitor
>> following properties used by PQS?
>>
>> avatica.connectioncache.concurrency
>> avatica.connectioncache.initialcapacity
>> avatica.connectioncache.maxcapacity
>> avatica.connectioncache.expiryduration
>> avatica.connectioncache.expiryunit
>>
>> avatica.statementcache.concurrency
>> avatica.statementcache.initialcapacity
>> avatica.statementcache.maxcapacity
>> avatica.statementcache.expiryduration
>> avatica.statementcache.expiryunit
>>
>> On Thu, Jan 5, 2017 at 10:04 AM, Tulasi Paradarami
>> <[email protected] <mailto:[email protected]>
>> <mailto:[email protected]
>>
>> <mailto:[email protected]>>> wrote:
>>
>> Yes, I mean 4.7.0.
>> Since PQS restart, we are seeing the error raised during
>> fetch
>> instead of closeStatement.
>>
>> Here is the latest trace:
>>
>> TRACE server.AvaticaJsonHandler: request: {"connectionId":
>> "0359595b-509a-41e2-9348-d3f8fcec65df", "request": "fetch",
>> "fetchMaxRowCount": 2000, "offset": 100, "statementId": 181894}
>> TRACE jdbc.JdbcMeta: fetching
>> 0359595b-509a-41e2-9348-d3f8fcec65df::181894 offset:100
>> fetchMaxRowCount:2000
>> TRACE server.AvaticaJsonHandler: response: Response:
>>
>> {"response":"error","exceptions":["java.lang.ArrayIndexOutOf
>> BoundsException\n"],"errorMessage":"ArrayIndexOutOfBoundsException:
>> (null exception
>>
>> message)","errorCode":-1,"sqlState":"00000","severity":"UNKN
>> OWN","rpcMetadata":{"response":"rpcMetadata","serverAddress"
>> :"pqs_hostname:8765"}},
>> Status:500
>> DEBUG server.Server: RESPONSE / 500 handled=true
>>
>>
>> I also noticed that as the number concurrent connections on
>> the
>> server increases, we are hitting this exception more
>> frequently.
>> Note that, we are using default values for following
>> parameters.
>>
>> *Configurations relating to the server statement cache.*
>> *Property* *Description* *Default*
>> avatica.statementcache.concurrency Statement cache
>> concurrency
>> level. Default is 100. 100
>> avatica.statementcache.initialcapacity Statement cache
>> initial
>> capacity. Default is 1000. 1000
>> avatica.statementcache.maxcapacity Statement cache maximum
>> capacity.
>> Approaching this point, the cache will start to evict least
>> recently
>> used statement objects. Default is 10000. 10000
>> avatica.statementcache.expiryduration Statement cache
>> expiration
>> duration. Any statements older than this value will be
>> discarded.
>> Default is 5 minutes. 5
>> avatica.statementcache.expiryunit Statement cache
>> expiration unit.
>> Unit modifier applied to the value provided in
>> avatica.statementcache.expiryunit. Default is minutes.
>> MINUTES
>>
>>
>>
>> On Thu, Jan 5, 2017 at 9:44 AM, Josh Elser
>> <[email protected] <mailto:[email protected]>
>> <mailto:[email protected] <mailto:[email protected]>>>
>> wrote:
>>
>> Interesting! I haven't come across this one myself.
>>
>> By Phoenix 4.7, am I to assume you mean 4.7.0? Phoenix
>> version
>> strings are 3 "digits", not 2.
>>
>> My first guess would be that it might be a race
>> condition around
>> the closeStatement call (either from multiple callers)
>> or the
>> automatic-closing logic inside of PQS itself (by
>> default, PQS
>> will close statements that haven't been used for
>> 10mins, IIRC).
>>
>> Any more information on the context in which you see
>> this would
>> be very helpful.
>>
>> Tulasi Paradarami wrote:
>>
>> We noticed that PQS started raising
>> ArrayIndexOutOfBoundsException in
>> our production cluster. This exception is raised
>> sporadically and goes
>> away when PQS is restarted. Does anyone know what
>> might be
>> causing this
>> exception? Are there any configuration (PQS and/or
>> Avatica)
>> parameters
>> that we can modify to prevent it from recurring?
>>
>> CDH 5.7.2
>> HBase: 1.2.0
>> Phoenix: 4.7
>>
>> Here is an error stack for "closeStatement" request:
>>
>> {"level":"TRACE","message":"
>> server.AvaticaJsonHandler:
>> response:
>> Response:
>>
>> {"response":"error","exceptions":["java.lang.ArrayIndexOutOf
>> BoundsException:
>> -1
>> at java.util.ArrayList.fastRemove
>> (ArrayList.java:528)
>> at java.util.ArrayList.remove(ArrayList.java:511)
>> at
>>
>> org.apache.phoenix.jdbc.PhoenixResultSet.close(PhoenixResult
>> Set.java:165)
>> at
>>
>> org.apache.calcite.avatica.jdbc.JdbcMeta.closeStatement(Jdbc
>> Meta.java:559)
>> at
>>
>> org.apache.calcite.avatica.remote.LocalService.apply(LocalSe
>> rvice.java:256)
>> at
>>
>> org.apache.calcite.avatica.remote.Service$CloseStatementRequ
>> est.accept(Service.java:1529)
>> at
>>
>> org.apache.calcite.avatica.remote.Service$CloseStatementRequ
>> est.accept(Service.java:1511)
>> at
>>
>> org.apache.calcite.avatica.remote.AbstractHandler.apply(Abst
>> ractHandler.java:102)
>> at
>>
>> org.apache.calcite.avatica.remote.JsonHandler.apply(JsonHand
>> ler.java:43)
>> at
>>
>> org.apache.calcite.avatica.server.AvaticaJsonHandler.handle(
>> AvaticaJsonHandler.java:73)
>> at
>>
>> org.eclipse.jetty.server.handler.HandlerList.handle(HandlerL
>> ist.java:52)
>> at
>>
>> org.eclipse.jetty.server.handler.HandlerWrapper.handle(Handl
>> erWrapper.java:97)
>> at
>> org.eclipse.jetty.server.Server.handle(Server.java:497)
>> at
>>
>> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
>> at
>>
>> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConne
>> ction.java:245)
>> at org.eclipse.jetty.io
>> <http://org.eclipse.jetty.io> <http://org.eclipse.jetty.io>
>> <http://org.eclipse.jetty.io>.AbstractConnection$2.run(Abstr
>> actConnection.java:540)
>> at
>>
>> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(Queued
>> ThreadPool.java:635)
>> at
>>
>> org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedT
>> hreadPool.java:555)
>> at java.lang.Thread.run(Thread.java:745)
>> "],"errorMessage":"ArrayIndexOutOfBoundsException:
>>
>> -1","errorCode":-1,"sqlState":"00000","severity":"UNKNOWN","
>> rpcMetadata":{"response":"rpcMetadata","serverAddress":"pqs_
>> hostname:8765"}},
>> Status:500"}
>>
>>
>>
>>
>>
