phoenix-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Josh Elser <josh.el...@gmail.com>
Subject Re: ArrayIndexOutOfBoundsException in PQS
Date Thu, 05 Jan 2017 21:59:21 GMT
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"}
>
>
>
>
>

Mime
View raw message