Mailing-List: contact dev-help@phoenix.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@phoenix.apache.org
Date: Fri, 9 Jun 2017 05:18:18 +0000 (UTC)
From: "Karan Mehta (JIRA)" <jira@apache.org>
To: dev@phoenix.apache.org
Message-ID: <JIRA.13065589.1492703644000.35958.1496985498076@Atlassian.JIRA>
In-Reply-To: <JIRA.13065589.1492703644000@Atlassian.JIRA>
References: <JIRA.13065589.1492703644000@Atlassian.JIRA> <JIRA.13065589.1492703644375@jira-lw-us.apache.org>
Subject: [jira] [Commented] (PHOENIX-3799) Error on tracing query with
 "union all"
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
archived-at: Fri, 09 Jun 2017 05:18:25 -0000


    [ https://issues.apache.org/jira/browse/PHOENIX-3799?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16043949#comment-16043949 ] 

Karan Mehta commented on PHOENIX-3799:
--------------------------------------

Hey Marco, 
Could you confirm the Phoenix version number as well as HTrace version number that it is using? Till now, Phoenix uses the version of HTrace which doesn't throw an exception on this error.

[~samarthjain] I looked into the issue. For a union query, we try tracing individual iterators for all the queries involved. Since this happens in a single thread, the parent span of each new iterator is equal to previous iterator's span, but in fact it should not be tied to it, since both of them are independent iterators altogether. For example, in the query {{SELECT K FROM TABLEA UNION ALL SELECT K FROM TABLEB UNION ALL SELECT K FROM TABLEC}}, three separate iterators are created for all the three queries involved in the same thread. Hence, the spans look something like this
{code}
Parent Span
  + TABLEA Iterator Span
      + TABLEB Iterator Span
          + TABLEC Iterator Span
                + HBase Spans for TABLEC
                + HBase Spans for TABLEB
                + HBase Spans for TABLEA
{code}
and hence when these iterators are closed, the span in threadlocal will not match the span in the current scope, resulting in this exception. 

What we really want is something like this
{code}
Parent Span
  + TABLEA Iterator Span
      + HBase Spans for TABLEA
  + TABLEB Iterator Span
      + HBase Spans for TABLEA
  + TABLEC Iterator Span
      + HBase Spans for TABLEA
{code}
However such a thing is not possible unless we initialize the iterators parallely. Please suggest as to how we should handle this. For now, we don't have any parent span with a TraceScope of complete query. 

> Error on tracing query with "union all" 
> ----------------------------------------
>
>                 Key: PHOENIX-3799
>                 URL: https://issues.apache.org/jira/browse/PHOENIX-3799
>             Project: Phoenix
>          Issue Type: Bug
>    Affects Versions: 4.7.0
>         Environment: Phoenix on Cloudera 5.8
>            Reporter: Marco
>              Labels: TRACING
>
> When i try to enable tracing for query with a "union all" clause, I receive an error  and the process stop the execution.
> Error: 
> 0: jdbc:phoenix:xxxxxxxxx> select sum(1) as num from (
> . . . . . . . . . . . . . . > select count(1) as num from my_tab where meas_ym ='201601'
> . . . . . . . . . . . . . . > union all
> . . . . . . . . . . . . . . > select count(1) as num from my_tab where meas_ym ='201602');
> 17/04/20 15:39:38 ERROR htrace.Tracer: Tried to close trace span {"i":"7a2caddba3cc1d5d","s":"f262306696ff7120","b":1492702777540,"d":"Creating basic query for [CLIENT 10-CHUNK 9560319 ROWS 2516584015 BYTES PARALLEL 1-WAY RANGE SCAN OVER MY_TAB ['201601'],     SERVER FILTER BY FIRST KEY ONLY,     SERVER AGGREGATE INTO SINGLE ROW]","p":["f6e9e018136584b0"],"t":[{"t":1492702777542,"m":"First request completed"}]} but it is not the current span for the main thread.  You have probably forgotten to close or detach {"i":"7a2caddba3cc1d5d","s":"f1a3a546476f1c94","b":1492702777541,"d":"Creating basic query for [CLIENT 36-CHUNK 40590914 ROWS 10380911994 BYTES PARALLEL 1-WAY RANGE SCAN OVER MY_TAB ['201602'],     SERVER FILTER BY FIRST KEY ONLY,     SERVER AGGREGATE INTO SINGLE ROW]","p":["f262306696ff7120"]}
> java.lang.RuntimeException: Tried to close trace span {"i":"7a2caddba3cc1d5d","s":"f262306696ff7120","b":1492702777540,"d":"Creating basic query for [CLIENT 10-CHUNK 9560319 ROWS 2516584015 BYTES PARALLEL 1-WAY RANGE SCAN OVER MY_TAB ['201601'],     SERVER FILTER BY FIRST KEY ONLY,     SERVER AGGREGATE INTO SINGLE ROW]","p":["f6e9e018136584b0"],"t":[{"t":1492702777542,"m":"First request completed"}]} but it is not the current span for the main thread.  You have probably forgotten to close or detach {"i":"7a2caddba3cc1d5d","s":"f1a3a546476f1c94","b":1492702777541,"d":"Creating basic query for [CLIENT 36-CHUNK 40590914 ROWS 10380911994 BYTES PARALLEL 1-WAY RANGE SCAN OVER MY_TAB ['201602'],     SERVER FILTER BY FIRST KEY ONLY,     SERVER AGGREGATE INTO SINGLE ROW]","p":["f262306696ff7120"]}
>         at org.apache.htrace.Tracer.clientError(Tracer.java:60)
>         at org.apache.htrace.TraceScope.close(TraceScope.java:90)
>         at org.apache.phoenix.trace.TracingIterator.close(TracingIterator.java:46)
>         at org.apache.phoenix.iterate.DelegateResultIterator.close(DelegateResultIterator.java:39)
>         at org.apache.phoenix.iterate.LookAheadResultIterator$1.close(LookAheadResultIterator.java:42)
>         at org.apache.phoenix.iterate.ConcatResultIterator.currentIterator(ConcatResultIterator.java:104)
>         at org.apache.phoenix.iterate.ConcatResultIterator.next(ConcatResultIterator.java:117)
>         at org.apache.phoenix.iterate.DelegateResultIterator.next(DelegateResultIterator.java:44)
>         at org.apache.phoenix.execute.TupleProjectionPlan$1.next(TupleProjectionPlan.java:67)
>         at org.apache.phoenix.iterate.LookAheadResultIterator$1.advance(LookAheadResultIterator.java:47)
>         at org.apache.phoenix.iterate.LookAheadResultIterator.next(LookAheadResultIterator.java:67)
>         at org.apache.phoenix.iterate.BaseGroupedAggregatingResultIterator.next(BaseGroupedAggregatingResultIterator.java:64)
>         at org.apache.phoenix.iterate.LookAheadResultIterator$1.advance(LookAheadResultIterator.java:47)
>         at org.apache.phoenix.iterate.LookAheadResultIterator.init(LookAheadResultIterator.java:59)
>         at org.apache.phoenix.iterate.LookAheadResultIterator.next(LookAheadResultIterator.java:65)
>         at org.apache.phoenix.iterate.BaseGroupedAggregatingResultIterator.next(BaseGroupedAggregatingResultIterator.java:64)
>         at org.apache.phoenix.iterate.UngroupedAggregatingResultIterator.next(UngroupedAggregatingResultIterator.java:39)
>         at org.apache.phoenix.jdbc.PhoenixResultSet.next(PhoenixResultSet.java:778)
>         at sqlline.BufferedRows.<init>(BufferedRows.java:37)
>         at sqlline.SqlLine.print(SqlLine.java:1650)
>         at sqlline.Commands.execute(Commands.java:833)
>         at sqlline.Commands.sql(Commands.java:732)
>         at sqlline.SqlLine.dispatch(SqlLine.java:808)
>         at sqlline.SqlLine.begin(SqlLine.java:681)
>         at sqlline.SqlLine.start(SqlLine.java:398)
>         at sqlline.SqlLine.main(SqlLine.java:292)
> Without tracing, the query works fine:
> 0: jdbc:phoenix:xxxxxxxxx> select sum(1) as num from (
> . . . . . . . . . . . . . . > select count(1) as num from my_tab where meas_ym ='201601'
> . . . . . . . . . . . . . . > union all
> . . . . . . . . . . . . . . > select count(1) as num from my_tab where meas_ym ='201602');
> +------+
> | NUM  |
> +------+
> | 2    |
> +------+
> 1 row selected (8.507 seconds)


--
This message was sent by Atlassian JIRA
(v6.3.15#6346)