I created CALCITE-1565 for this issue.
On Thu, Jan 5, 2017 at 12:10 PM, Josh Elser <josh.el...@gmail.com
<mailto:josh.el...@gmail.com>> 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
<josh.el...@gmail.com <mailto:josh.el...@gmail.com>
<mailto:josh.el...@gmail.com <mailto:josh.el...@gmail.com>>> 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>
<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
<tulasi.krishn...@gmail.com <mailto:tulasi.krishn...@gmail.com>
<mailto:tulasi.krishn...@gmail.com
<mailto:tulasi.krishn...@gmail.com>>
<mailto:tulasi.krishn...@gmail.com
<mailto:tulasi.krishn...@gmail.com>
<mailto:tulasi.krishn...@gmail.com
<mailto:tulasi.krishn...@gmail.com>>>> 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
<josh.el...@gmail.com <mailto:josh.el...@gmail.com>
<mailto:josh.el...@gmail.com <mailto:josh.el...@gmail.com>>
<mailto:josh.el...@gmail.com <mailto:josh.el...@gmail.com>
<mailto:josh.el...@gmail.com <mailto:josh.el...@gmail.com>>>> 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>
<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"}
