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.ArrayIndexOutOfBoundsException\n"],"errorMessage":"ArrayIndexOutOfBoundsException:
(null exception
message)","errorCode":-1,"sqlState":"00000","severity":"UNKNOWN","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.ArrayIndexOutOfBoundsException:
-1
at java.util.ArrayList.fastRemove(ArrayList.java:528)
at java.util.ArrayList.remove(ArrayList.java:511)
at
org.apache.phoenix.jdbc.PhoenixResultSet.close(PhoenixResultSet.java:165)
at
org.apache.calcite.avatica.jdbc.JdbcMeta.closeStatement(JdbcMeta.java:559)
at
org.apache.calcite.avatica.remote.LocalService.apply(LocalService.java:256)
at
org.apache.calcite.avatica.remote.Service$CloseStatementRequest.accept(Service.java:1529)
at
org.apache.calcite.avatica.remote.Service$CloseStatementRequest.accept(Service.java:1511)
at
org.apache.calcite.avatica.remote.AbstractHandler.apply(AbstractHandler.java:102)
at
org.apache.calcite.avatica.remote.JsonHandler.apply(JsonHandler.java:43)
at
org.apache.calcite.avatica.server.AvaticaJsonHandler.handle(AvaticaJsonHandler.java:73)
at
org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.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(HttpConnection.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(AbstractConnection.java:540)
at
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
at
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.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"}
