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