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