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]> 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) 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]>> 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]>> 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>.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"}
>>
>>
>>
>>
