Mailing-List: contact issues-help@impala.incubator.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@impala.incubator.apache.org
Date: Wed, 22 Mar 2017 12:50:41 +0000 (UTC)
From: "Balazs Jeszenszky (JIRA)" <jira@apache.org>
To: issues@impala.incubator.apache.org
Message-ID: <JIRA.13058210.1490186919000.87774.1490187041706@Atlassian.JIRA>
In-Reply-To: <JIRA.13058210.1490186919000@Atlassian.JIRA>
References: <JIRA.13058210.1490186919000@Atlassian.JIRA> <JIRA.13058210.1490186919924@jira-lw-us.apache.org>
Subject: [jira] [Updated] (IMPALA-5108) idle_session_timeout kicks in later
 than expected
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
archived-at: Wed, 22 Mar 2017 12:50:48 -0000


     [ https://issues.apache.org/jira/browse/IMPALA-5108?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Balazs Jeszenszky updated IMPALA-5108:
--------------------------------------
    Description: 
When using idle_session_timeout value of 120 and submitting a query from Hue, I see the connection being idle from tcpdump since:

05:28:03.474282 IP impalad.21050 > hue.33879: Flags [P.], seq 3261:3368, ack 2107, win 147, options [nop,nop,TS val 512338192 ecr 72619609], length 107
05:28:03.513861 IP hue.33879 > impalad.21050: Flags [.], ack 3368, win 339, options [nop,nop,TS val 72619649 ecr 512338192], length 0

However, the query runs from:

{code:java}
Start Time: 2017-03-22 05:28:01.605899000
End Time: 2017-03-22 05:31:01.505750000
{code}

Query timeline:
{code:java}
Planner Timeline: 14.973ms
       - Analysis finished: 3.904ms (3.904ms)
       - Equivalence classes computed: 4.433ms (529.525us)
       - Single node plan created: 8.165ms (3.732ms)
       - Distributed plan created: 9.340ms (1.174ms)
       - Lineage info computed: 11.319ms (1.978ms)
       - Planning finished: 14.973ms (3.654ms)
    Query Timeline: 2m59s
       - Start execution: 0.000ns (0.000ns)
       - Planning finished: 17.999ms (17.999ms)
       - Child queries finished: 20.999ms (2.999ms)
       - Rows available: 20.999ms (0.000ns)
       - First row fetched: 1s467ms (1s446ms)
       - Unregister query: 2m59s (2m58s)
  ImpalaServer:
     - ClientFetchWaitTimer: 2m59s
     - RowMaterializationTimer: 0.000ns
{code}
It was just a simple select * limit 1. We've had reports of this from various users, noting that while the session is closed eventually, the timings are confusing (and the difference between the configured value and the actual timeout depends on the configured value, it's not a constant 1m offset - with an idle_session_timeout of 180 I had queries timing out only after 4.5 minutes).

From logs:
with value of 120:
{code:java}
I0322 05:31:01.500277 15691 impala-server.cc:1723] Expiring session: 74b43411be11eef:fee3c89065e2f0a2, user:admin, last active: 2017-03-22 12:28:03
{code}

with value of 75:
{code:java}
I0322 05:45:36.058423 17626 impala-server.cc:1723] Expiring session: a442144dff67f1c9:1fe7ecae10a1da4, user:admin, last
 active: 2017-03-22 12:43:46
{code}

  was:
When using idle_session_timeout value of 120 and submitting a query from Hue, I see the connection being idle from tcpdump since:

05:28:03.474282 IP impalad.21050 > hue.33879: Flags [P.], seq 3261:3368, ack 2107, win 147, options [nop,nop,TS val 512338192 ecr 72619609], length 107
05:28:03.513861 IP hue.33879 > impalad.21050: Flags [.], ack 3368, win 339, options [nop,nop,TS val 72619649 ecr 512338192], length 0

However, the query runs from:

{code:java}
Start Time: 2017-03-22 05:28:01.605899000
End Time: 2017-03-22 05:31:01.505750000
{code}

Query timeline:
{code:java}
Planner Timeline: 14.973ms
       - Analysis finished: 3.904ms (3.904ms)
       - Equivalence classes computed: 4.433ms (529.525us)
       - Single node plan created: 8.165ms (3.732ms)
       - Distributed plan created: 9.340ms (1.174ms)
       - Lineage info computed: 11.319ms (1.978ms)
       - Planning finished: 14.973ms (3.654ms)
    Query Timeline: 2m59s
       - Start execution: 0.000ns (0.000ns)
       - Planning finished: 17.999ms (17.999ms)
       - Child queries finished: 20.999ms (2.999ms)
       - Rows available: 20.999ms (0.000ns)
       - First row fetched: 1s467ms (1s446ms)
       - Unregister query: 2m59s (2m58s)
  ImpalaServer:
     - ClientFetchWaitTimer: 2m59s
     - RowMaterializationTimer: 0.000ns
{code}
It was just a simple select * limit 1. We've had reports of this from various users, noting that while the session is closed eventually, the timings are confusing (and the difference between the configured value and the actual timeout depends on the configured value, it's not a constant 1m offset - with an idle_session_timeout of 180 I had queries timing out only after 4.5 minutes).

From logs:
with value of 120:
I0322 05:31:01.500277 15691 impala-server.cc:1723] Expiring session: 74b43411be11eef:fee3c89065e2f0a2, user:admin, last active: 2017-03-22 12:28:03

with value of 75:
I0322 05:45:36.058423 17626 impala-server.cc:1723] Expiring session: a442144dff67f1c9:1fe7ecae10a1da4, user:admin, last
 active: 2017-03-22 12:43:46


> idle_session_timeout kicks in later than expected
> -------------------------------------------------
>
>                 Key: IMPALA-5108
>                 URL: https://issues.apache.org/jira/browse/IMPALA-5108
>             Project: IMPALA
>          Issue Type: Bug
>          Components: be
>    Affects Versions: Impala 2.5.5
>            Reporter: Balazs Jeszenszky
>
> When using idle_session_timeout value of 120 and submitting a query from Hue, I see the connection being idle from tcpdump since:
> 05:28:03.474282 IP impalad.21050 > hue.33879: Flags [P.], seq 3261:3368, ack 2107, win 147, options [nop,nop,TS val 512338192 ecr 72619609], length 107
> 05:28:03.513861 IP hue.33879 > impalad.21050: Flags [.], ack 3368, win 339, options [nop,nop,TS val 72619649 ecr 512338192], length 0
> However, the query runs from:
> {code:java}
> Start Time: 2017-03-22 05:28:01.605899000
> End Time: 2017-03-22 05:31:01.505750000
> {code}
> Query timeline:
> {code:java}
> Planner Timeline: 14.973ms
>        - Analysis finished: 3.904ms (3.904ms)
>        - Equivalence classes computed: 4.433ms (529.525us)
>        - Single node plan created: 8.165ms (3.732ms)
>        - Distributed plan created: 9.340ms (1.174ms)
>        - Lineage info computed: 11.319ms (1.978ms)
>        - Planning finished: 14.973ms (3.654ms)
>     Query Timeline: 2m59s
>        - Start execution: 0.000ns (0.000ns)
>        - Planning finished: 17.999ms (17.999ms)
>        - Child queries finished: 20.999ms (2.999ms)
>        - Rows available: 20.999ms (0.000ns)
>        - First row fetched: 1s467ms (1s446ms)
>        - Unregister query: 2m59s (2m58s)
>   ImpalaServer:
>      - ClientFetchWaitTimer: 2m59s
>      - RowMaterializationTimer: 0.000ns
> {code}
> It was just a simple select * limit 1. We've had reports of this from various users, noting that while the session is closed eventually, the timings are confusing (and the difference between the configured value and the actual timeout depends on the configured value, it's not a constant 1m offset - with an idle_session_timeout of 180 I had queries timing out only after 4.5 minutes).
> From logs:
> with value of 120:
> {code:java}
> I0322 05:31:01.500277 15691 impala-server.cc:1723] Expiring session: 74b43411be11eef:fee3c89065e2f0a2, user:admin, last active: 2017-03-22 12:28:03
> {code}
> with value of 75:
> {code:java}
> I0322 05:45:36.058423 17626 impala-server.cc:1723] Expiring session: a442144dff67f1c9:1fe7ecae10a1da4, user:admin, last
>  active: 2017-03-22 12:43:46
> {code}


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