phoenix-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Tulasi Paradarami <tulasi.krishn...@gmail.com>
Subject Re: ArrayIndexOutOfBoundsException in PQS
Date Thu, 05 Jan 2017 20:34:44 GMT
I created CALCITE-1565 for this issue.

On Thu, Jan 5, 2017 at 12:10 PM, Josh Elser <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>> 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.ArrayIndexOutOf
>> BoundsException\n"],"errorMessage":"ArrayIndexOutOfBoundsException:
>>              (null exception
>>
>>         message)","errorCode":-1,"sqlState":"00000","severity":"UNKN
>> OWN","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.ArrayIndexOutOf
>> BoundsException:
>>                      -1
>>                      at java.util.ArrayList.fastRemove
>> (ArrayList.java:528)
>>                      at java.util.ArrayList.remove(ArrayList.java:511)
>>                      at
>>
>>         org.apache.phoenix.jdbc.PhoenixResultSet.close(PhoenixResult
>> Set.java:165)
>>                      at
>>
>>         org.apache.calcite.avatica.jdbc.JdbcMeta.closeStatement(Jdbc
>> Meta.java:559)
>>                      at
>>
>>         org.apache.calcite.avatica.remote.LocalService.apply(LocalSe
>> rvice.java:256)
>>                      at
>>
>>         org.apache.calcite.avatica.remote.Service$CloseStatementRequ
>> est.accept(Service.java:1529)
>>                      at
>>
>>         org.apache.calcite.avatica.remote.Service$CloseStatementRequ
>> est.accept(Service.java:1511)
>>                      at
>>
>>         org.apache.calcite.avatica.remote.AbstractHandler.apply(Abst
>> ractHandler.java:102)
>>                      at
>>
>>         org.apache.calcite.avatica.remote.JsonHandler.apply(JsonHand
>> ler.java:43)
>>                      at
>>
>>         org.apache.calcite.avatica.server.AvaticaJsonHandler.handle(
>> AvaticaJsonHandler.java:73)
>>                      at
>>
>>         org.eclipse.jetty.server.handler.HandlerList.handle(HandlerL
>> ist.java:52)
>>                      at
>>
>>         org.eclipse.jetty.server.handler.HandlerWrapper.handle(Handl
>> erWrapper.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(HttpConne
>> ction.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(Abstr
>> actConnection.java:540)
>>                      at
>>
>>         org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(Queued
>> ThreadPool.java:635)
>>                      at
>>
>>         org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedT
>> hreadPool.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