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 20:10:14 GMT
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>> 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
>         <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>>> 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"}
>
>
>
>

Mime
View raw message