[IMPALA-5108] idle_session_timeout kicks in later than expected

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: Impala 2.5.5
• Fix Version/s: Impala 2.10.0
• Component/s: Backend
• Labels: ramp-up
• Epic Color: ghx-label-1
• Assignee: Pranay Singh
• Reporter: Balazs Jeszenszky
• Created: 22/Mar/17 12:48
• Updated: 31/Aug/17 19:31
• Resolved: 29/Aug/17 19:13

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:

Start Time: 2017-03-22 05:28:01.605899000
End Time: 2017-03-22 05:31:01.505750000

Query timeline:

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

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