drill-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From François Méthot <fmetho...@gmail.com>
Subject Re: ZK lost connectivity issue on large cluster
Date Thu, 27 Oct 2016 01:06:27 GMT
Hi,

Sorry it took so long, lost the origin picture, had to go to a ms paint
training
here we go:

https://github.com/fmethot/imagine/blob/master/affinity_factor.png



On Thu, Oct 20, 2016 at 12:57 PM, Sudheesh Katkam <skatkam@maprtech.com>
wrote:

> The mailing list does not seem to allow for images. Can you put the image
> elsewhere (Github or Dropbox), and reply with a link to it?
>
> - Sudheesh
>
> > On Oct 19, 2016, at 5:37 PM, François Méthot <fmethot78@gmail.com>
> wrote:
> >
> > We had problem on the 220 nodes cluster. No problem on the 12 nodes
> cluster.
> >
> > I agree that the data may not be distributed evenly. It would be a long
> and tedious process for me to produce a report.
> >
> > Here is a drawing  of the fragments overview before and after the
> changes of the affinity factory on a sample query ran on the 220 nodes
> cluster.  max_width_per_node=8 on both, but it turned out to be irrelevant
> to the issue.
> >
> >
> >
> >
> >
> >
> > Before: SYSTEM ERROR: ForemanException: One more more nodes lost
> connectivity during query.  Identified nodes were [server121:31010].
> >
> > After: error is gone
> >
> > Before: low disk io, high network io on the bottom part of the graph
> > after : high disk io, low network io on the bottom part of the graph
> >
> >
> >
> >
> >
> >
> >
> > On Tue, Oct 18, 2016 at 12:58 AM, Padma Penumarthy <
> ppenumarthy@maprtech.com <mailto:ppenumarthy@maprtech.com>> wrote:
> > Hi Francois,
> >
> > It would be good to understand how increasing affinity_factor helped in
> your case
> > so we can better document and also use that knowledge to improve things
> in future release.
> >
> > If you have two clusters,  it is not clear whether you had the problem
> on 12 node cluster
> > or 220 node cluster or both. Is the dataset same on both ? Is
> max_width_per_node=8 in both clusters ?
> >
> > Increasing affinity factor will lower remote reads  by scheduling more
> fragments/doing more work
> > on nodes which have data available locally.  So, there seem to be some
> kind of non uniform
> > data distribution for sure. It would be good if you can provide more
> details i.e. how the data is
> > distributed in the cluster and how the load on the nodes changed when
> affinity factor was increased.
> >
> > Thanks,
> > Padma
> >
> >
> > > On Oct 14, 2016, at 6:45 PM, François Méthot <fmethot78@gmail.com
> <mailto:fmethot78@gmail.com>> wrote:
> > >
> > > We have  a 12 nodes cluster and a 220 nodes cluster, but they do not
> talk
> > > to each other. So Padma's analysis do not apply but thanks for your
> > > comments. Our goal had been to run Drill on the 220 nodes cluster
> after it
> > > proved worthy of it on the small cluster.
> > >
> > > planner.width.max_per_node was eventually reduced to 2 when we were
> trying
> > > to figure this out, it would still fail. After we figured out the
> > > affinity_factor, we put it back to its original value and it would work
> > > fine.
> > >
> > >
> > >
> > > Sudheesh: Indeed, The Zk/drill services use the same network on our
> bigger
> > > cluster.
> > >
> > > potential improvements:
> > > - planner.affinity_factor should be better documented.
> > > - When ZK disconnected, the running queries systematically failed.
> When we
> > > disabled the ForemanException thrown in the QueryManager.
> > > drillbitUnregistered method, most of our query started to run
> successfully,
> > > we would sometime get Drillbit Disconnected error within the rpc work
> bus.
> > > It did confirm that we still had something on our network going on,
> but it
> > > also showed that the RPC bus between drillbits was more resilient to
> > > network hiccup. I could not prove it, but I think under certain
> condition,
> > > the ZK session gets recreated, which cause a Query Manager unregistered
> > > (query fail) and register call right after, but the RPC
> > > bus  would remains connected.
> > >
> > >
> > > We really appreciate your feedback and we hope to contribute to this
> great
> > > project in the future.
> > > Thanks
> > > Francois
> > >
> > >
> > >
> > >
> > >
> > >
> > > On Fri, Oct 14, 2016 at 3:00 PM, Padma Penumarthy <
> ppenumarthy@maprtech.com <mailto:ppenumarthy@maprtech.com>>
> > > wrote:
> > >
> > >>
> > >> Seems like you have 215 nodes, but the data for your query is there on
> > >> only 12 nodes.
> > >> Drill tries to distribute the scan fragments across the cluster more
> > >> uniformly (trying to utilize all CPU resources).
> > >> That is why you have lot of remote reads going on and increasing
> affinity
> > >> factor eliminates running scan
> > >> fragments on the other (215-12) nodes.
> > >>
> > >> you also mentioned planner.width.max_per_node is set to 8.
> > >> So, with increased affinity factor,  you have 8 scan fragments doing
> a lot
> > >> more work on these 12 nodes.
> > >> Still, you got 10X improvement. Seems like your network is the obvious
> > >> bottleneck. Is it a 10G or 1G ?
> > >>
> > >> Also, increasing affinity factor helped in your case because there is
> no
> > >> data on other nodes.
> > >> But, if you have data non uniformly distributed across more nodes, you
> > >> might still have the problem.
> > >>
> > >> Thanks,
> > >> Padma
> > >>
> > >>> On Oct 14, 2016, at 11:18 AM, Sudheesh Katkam <skatkam@maprtech.com
> <mailto:skatkam@maprtech.com>>
> > >> wrote:
> > >>>
> > >>> Hi Francois,
> > >>>
> > >>> Thank you for posting your findings! Glad to see a 10X improvement.
> > >>>
> > >>> By increasing affinity factor, looks like Drill’s parallelizer is
> forced
> > >> to assign fragments on nodes with data i.e. with high favorability
> for data
> > >> locality.
> > >>>
> > >>> Regarding the random disconnection, I agree with your guess that the
> > >> network bandwidth is being used up by remote reads which causes lags
> in
> > >> drillbit to ZooKeeper heartbeats (since these services use the same
> > >> network)? Maybe others can comment here.
> > >>>
> > >>> Thank you,
> > >>> Sudheesh
> > >>>
> > >>>> On Oct 12, 2016, at 6:06 PM, François Méthot <fmethot78@gmail.com
> <mailto:fmethot78@gmail.com>>
> > >> wrote:
> > >>>>
> > >>>> Hi,
> > >>>>
> > >>>> We finally got rid of this error. We have tried many, many things
> (like
> > >>>> modifying drill to ignore the error!), it ultimately came down
to
> this
> > >>>> change:
> > >>>>
> > >>>> from default
> > >>>> planner.affinity_factor=1.2
> > >>>> to
> > >>>> planner.affinity_factor=100
> > >>>>
> > >>>> Basically this encourages fragment to only care about locally stored
> > >> files.
> > >>>> We looked at the code that used that property and figured that
100
> would
> > >>>> have strong impact.
> > >>>>
> > >>>> What led us to this property is the fact that 1/4 of our fragments
> would
> > >>>> take a lot more time to complete their scan, up to  10x the time
of
> the
> > >>>> fastest nodes.  On the slower nodes, Cloudera Manager would show
> very
> > >> low
> > >>>> Disk IOPS with high Network IO compare to our faster nodes. We
had
> > >> noticed
> > >>>> that before but figured it would be some optimization to be done
> later
> > >> when
> > >>>> more pressing issue would be fixed, like Zk disconnection and OOM.
> We
> > >> were
> > >>>> desperate and decided to fix anything that  would look unusual.
> > >>>>
> > >>>> After this change, query ran up to 10x faster.
> > >>>>
> > >>>> We no longer get random disconnection between node and Zookeeper.
> > >>>>
> > >>>> We are still wondering why exactly. Network should not be a
> bottleneck.
> > >>>> Could high network traffic between a Drillbit and HDFS causes the
> > >> Drillbit
> > >>>> to timeout with zookeeper?
> > >>>>
> > >>>>
> > >>>> On Fri, Sep 30, 2016 at 4:21 PM, François Méthot <
> fmethot78@gmail.com <mailto:fmethot78@gmail.com>>
> > >>>> wrote:
> > >>>>
> > >>>>> After the 30 seconds gap, all the Drill nodes receives the
> following:
> > >>>>>
> > >>>>> 2016-09-26 20:07:38,629 [Curator-ServiceCache-0] Debug Active
> drillbit
> > >> set
> > >>>>> changed. Now includes 220 total bits. New Active drill bits....
> > >>>>> ...faulty node is not on the list...
> > >>>>> 2016-09-26 20:07:38,897 [Curator-ServiceCache-0] Debug Active
> drillbit
> > >> set
> > >>>>> changed. Now includes 221 total bits. New Active drill bits....
> > >>>>> ...faulty node is back on the list...
> > >>>>>
> > >>>>>
> > >>>>> So the faulty Drill node get unregistered and registered right
> after.
> > >>>>>
> > >>>>> Drill is using the low level API for registering and
> unregistering, and
> > >>>>> the only place with unregistering occurs is when the drillbit
is
> > >> closed at
> > >>>>> shutdown.
> > >>>>>
> > >>>>> That particular drillbit is still up and running after those
log,
> it
> > >> could
> > >>>>> not have trigger the unregistering process through a shutdown.
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>> Would you have an idea what else could cause a Drillbit to
be
> > >> unregistered
> > >>>>> from the DiscoveryService and registered again right after?
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>> We are using Zookeeper 3.4.5
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>>
> > >>>>> On Wed, Sep 28, 2016 at 10:36 AM, François Méthot <
> fmethot78@gmail.com <mailto:fmethot78@gmail.com>
> > >>>
> > >>>>> wrote:
> > >>>>>
> > >>>>>> Hi,
> > >>>>>>
> > >>>>>> We have switched to 1.8 and we are still getting node
> disconnection.
> > >>>>>>
> > >>>>>> We did many tests, we thought initially our stand alone
parquet
> > >> converter
> > >>>>>> was generating parquet files with problematic data (like
10K
> > >> characters
> > >>>>>> string), but we were able to reproduce it with employee
data from
> the
> > >>>>>> tutorial.
> > >>>>>>
> > >>>>>> For example,  we duplicated the Drill Tutorial "Employee"
data to
> > >> reach
> > >>>>>> 500 M records spread over 130 parquet files.
> > >>>>>> Each files is ~60 MB.
> > >>>>>>
> > >>>>>>
> > >>>>>> We ran this query over and over on 5 different sessions
using a
> > >> script:
> > >>>>>> select * from hdfs.tmp.`PARQUET_EMPLOYEE` where full_name
like
> '%does
> > >>>>>> not exist%';
> > >>>>>>
> > >>>>>> Query return no rows and would take ~35 to 45 seconds to
return.
> > >>>>>>
> > >>>>>> Leaving the script running on each node, we eventually
hit the
> "nodes
> > >>>>>> lost connectivity during query" error.
> > >>>>>>
> > >>>>>> One the done that failed,
> > >>>>>>
> > >>>>>> We see those log:
> > >>>>>> 2016-09-26 20:07:09,029 [...uuid...frag:1:10] INFO
> > >>>>>> o.a.d.e.w.f.FragmentStatusReporter - ...uuid...:1:10: State
to
> > >> report:
> > >>>>>> RUNNING
> > >>>>>> 2016-09-26 20:07:09,029 [...uuid...frag:1:10] DEBUG
> > >>>>>> o.a.d.e.w.FragmentExecutor - Starting fragment 1:10 on
> server064:31010
> > >>>>>>
> > >>>>>> <--- 30 seconds gap for that fragment --->
> > >>>>>>
> > >>>>>> 2016-09-26 20:37:09,976 [BitServer-2] WARN o.a.d.exec.rpc.control.
> > >> ControlServer
> > >>>>>> - Message of mode REQUEST of rpc type 2 took longer then
500 ms.
> > >> Actual
> > >>>>>> duration was 23617ms.
> > >>>>>>
> > >>>>>> 2016-09-26 20:07:38,211 [...uuid...frag:1:10] DEBUG
> > >>>>>> o.a.d.e.p.i.s.RemovingRecordBatch - doWork(): 0 records
copied
> out
> > >> of 0,
> > >>>>>> remaining: 0 incoming schema BatchSchema [....,
> > >> selectionVector=TWO_BYTE]
> > >>>>>> 2016-09-26 20:07:38,211 [...uuid...frag:1:10] DEBUG
> > >>>>>> o.a.d.exec.rpc.control.WorkEventBus - Cancelling and removing
> > >> fragment
> > >>>>>> manager : ...uuid...
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>> For the same query on a working node:
> > >>>>>> 2016-09-26 20:07:09,056 [...uuid...frag:1:2] INFO
> > >>>>>> o.a.d.e.w.f.FragmentStatusReporter - ...uuid...:1:2: State
to
> report:
> > >>>>>> RUNNING
> > >>>>>> 2016-09-26 20:07:09,056 [...uuid...frag:1:2] DEBUG
> > >>>>>> o.a.d.e.w.FragmentExecutor - Starting fragment 1:2 on
> server125:31010
> > >>>>>> 2016-09-26 20:07:09,749 [...uuid...frag:1:2] DEBUG
> > >>>>>> o.a.d.e.p.i.s.RemovingRecordBatch - doWork(): 0 records
copied
> out
> > >> of 0,
> > >>>>>> remaining: 0 incoming schema BatchSchema [....,
> > >> selectionVector=TWO_BYTE]
> > >>>>>> 2016-09-26 20:07:09,749 [...uuid...frag:1:2] DEBUG
> > >>>>>> o.a.d.e.p.i.s.RemovingRecordBatch - doWork(): 0 records
copied
> out
> > >> of 0,
> > >>>>>> remaining: 0 incoming schema BatchSchema [....,
> > >> selectionVector=TWO_BYTE]
> > >>>>>> 2016-09-26 20:07:11,005 [...uuid...frag:1:2] DEBUG
> > >>>>>> o.a.d.e.s.p.c.ParquetRecordReader - Read 87573 records
out of row
> > >>>>>> groups(0) in file `/data/drill/tmp/PARQUET_
> EMPLOYEE/0_0_14.parquet
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>> We are investigating what could get cause that 30 seconds
gap for
> that
> > >>>>>> fragment.
> > >>>>>>
> > >>>>>> Any idea let us know
> > >>>>>>
> > >>>>>> Thanks
> > >>>>>> Francois
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>>
> > >>>>>> On Mon, Sep 19, 2016 at 2:59 PM, François Méthot <
> fmethot78@gmail.com <mailto:fmethot78@gmail.com>
> > >>>
> > >>>>>> wrote:
> > >>>>>>
> > >>>>>>> Hi Sudheesh,
> > >>>>>>>
> > >>>>>>> If I add selection filter so that no row are returned,
the same
> > >>>>>>> problem occur. I also simplified the query to include
only few
> > >> integer
> > >>>>>>> columns.
> > >>>>>>>
> > >>>>>>> That particular data repo is ~200+ Billions records
spread over
> ~50
> > >> 000
> > >>>>>>> parquet files.
> > >>>>>>>
> > >>>>>>> We have other CSV data repo that are 100x smaller that
does not
> > >> trigger
> > >>>>>>> this issue.
> > >>>>>>>
> > >>>>>>>
> > >>>>>>> + Is atsqa4-133.qa.lab [1] the Foreman node for the
query in this
> > >> case?
> > >>>>>>> There is also a bizarre case where the node that is
reported as
> lost
> > >> is the
> > >>>>>>> node itself.
> > >>>>>>> Yes, the stack trace is from the ticket, It did occurred
once or
> > >> twice
> > >>>>>>> (in the many many attempts) that it was the node itself.
> > >>>>>>>
> > >>>>>>> + Is there a spike in memory usage of the Drillbit
this is the
> > >> Foreman
> > >>>>>>> for the query (process memory, not just heap)?
> > >>>>>>> We don't notice any unusual spike, each nodes gets
busy in the
> same
> > >>>>>>> range when query is running.
> > >>>>>>>
> > >>>>>>> I tried running with 8GB/20GB and 4GB/24GB heap/off-heap,
did
> not see
> > >>>>>>> any improvement.
> > >>>>>>>
> > >>>>>>>
> > >>>>>>> We will update from 1.7 to 1.8 before going ahead with
more
> > >>>>>>> investigation.
> > >>>>>>>
> > >>>>>>> Thanks a lot.
> > >>>>>>>
> > >>>>>>>
> > >>>>>>>
> > >>>>>>>
> > >>>>>>>
> > >>>>>>>
> > >>>>>>>
> > >>>>>>>
> > >>>>>>>
> > >>>>>>>
> > >>>>>>> On Mon, Sep 19, 2016 at 1:19 PM, Sudheesh Katkam <
> > >> skatkam@maprtech.com <mailto:skatkam@maprtech.com>>
> > >>>>>>> wrote:
> > >>>>>>>
> > >>>>>>>> Hi Francois,
> > >>>>>>>>
> > >>>>>>>> A simple query with only projections is not an
“ideal” use case,
> > >> since
> > >>>>>>>> Drill is bound by how fast the client can consume
records. There
> > >> are 1000
> > >>>>>>>> scanners sending data to 1 client (vs far fewer
scanners sending
> > >> data in
> > >>>>>>>> the 12 node case).
> > >>>>>>>>
> > >>>>>>>> This might increase the load on the Drillbit that
is the
> Foreman for
> > >>>>>>>> the query. In the query profile, the scanners should
be
> spending a
> > >> lot more
> > >>>>>>>> time “waiting” to send records to the client
(via root
> fragment).
> > >>>>>>>> + Is atsqa4-133.qa.lab [1] the Foreman node for
the query in
> this
> > >> case?
> > >>>>>>>> There is also a bizarre case where the node that
is reported as
> > >> lost is the
> > >>>>>>>> node itself.
> > >>>>>>>> + Is there a spike in memory usage of the Drillbit
this is the
> > >> Foreman
> > >>>>>>>> for the query (process memory, not just heap)?
> > >>>>>>>>
> > >>>>>>>> Regarding the warnings ...
> > >>>>>>>>
> > >>>>>>>>> 2016-09-19 13:31:56,866 [BitServer-7] WARN
> > >>>>>>>>> o.a.d.exec.rpc.control.ControlServer - Message
of mode
> REQUEST of
> > >>>>>>>> rpc type
> > >>>>>>>>> 6 took longer than 500 ms. Actual Duration
was 16053ms.
> > >>>>>>>>
> > >>>>>>>>
> > >>>>>>>> RPC type 6 is a cancellation request; DRILL-4766
[2] should
> help in
> > >>>>>>>> this case, which is resolved in the latest version
of Drill. So
> as
> > >> Chun
> > >>>>>>>> suggested, upgrade the cluster to the latest version
of Drill.
> > >>>>>>>>
> > >>>>>>>>> 2016-09-19 14:15:33,357 [BitServer-4] WARN
> > >>>>>>>>> o.a.d.exec.rpc.control.ControlClient - Message
of mode
> RESPONSE of
> > >>>>>>>> rpc type
> > >>>>>>>>> 1 took longer than 500 ms. Actual Duration
was 981ms.
> > >>>>>>>>
> > >>>>>>>> I am surprised that responses are taking that long
to handle.
> > >>>>>>>> + Are both messages on the same Drillbit?
> > >>>>>>>>
> > >>>>>>>> The other warnings can be ignored.
> > >>>>>>>>
> > >>>>>>>> Thank you,
> > >>>>>>>> Sudheesh
> > >>>>>>>>
> > >>>>>>>> [1] I just realized that atsqa4-133.qa.lab is in
one of our test
> > >>>>>>>> environments :)
> > >>>>>>>> [2] https://issues.apache.org/jira/browse/DRILL-4766
<
> https://issues.apache.org/jira/browse/DRILL-4766> <
> > >>>>>>>> https://issues.apache.org/jira/browse/DRILL-4766
<
> https://issues.apache.org/jira/browse/DRILL-4766>>
> > >>>>>>>>
> > >>>>>>>>> On Sep 19, 2016, at 9:15 AM, François Méthot
<
> fmethot78@gmail.com <mailto:fmethot78@gmail.com>>
> > >>>>>>>> wrote:
> > >>>>>>>>>
> > >>>>>>>>> Hi Sudheesh,
> > >>>>>>>>>
> > >>>>>>>>>
> > >>>>>>>>> + Does the query involve any aggregations or
filters? Or is
> this a
> > >>>>>>>> select
> > >>>>>>>>> query with only projections?
> > >>>>>>>>> Simple query with only projections
> > >>>>>>>>>
> > >>>>>>>>> + Any suspicious timings in the query profile?
> > >>>>>>>>> Nothing specially different than our working
query on our small
> > >>>>>>>> cluster.
> > >>>>>>>>>
> > >>>>>>>>> + Any suspicious warning messages in the logs
around the time
> of
> > >>>>>>>> failure on
> > >>>>>>>>> any of the drillbits? Specially on atsqa4-133.qa.lab?
Specially
> > >> this
> > >>>>>>>> one
> > >>>>>>>>> (“..” are place holders):
> > >>>>>>>>> Message of mode .. of rpc type .. took longer
than ..ms.
> Actual
> > >>>>>>>> duration
> > >>>>>>>>> was ..ms.
> > >>>>>>>>>
> > >>>>>>>>> Well we do see this warning on the failing
node (on my last
> test),
> > >> I
> > >>>>>>>> found
> > >>>>>>>>> this WARNING in our log for the past month
for pretty much
> every
> > >> node
> > >>>>>>>> I
> > >>>>>>>>> checked.
> > >>>>>>>>> 2016-09-19 13:31:56,866 [BitServer-7] WARN
> > >>>>>>>>> o.a.d.exec.rpc.control.ControlServer - Message
of mode
> REQUEST of
> > >>>>>>>> rpc type
> > >>>>>>>>> 6 took longer than 500 ms. Actual Duration
was 16053ms.
> > >>>>>>>>> 2016-09-19 14:15:33,357 [BitServer-4] WARN
> > >>>>>>>>> o.a.d.exec.rpc.control.ControlClient - Message
of mode
> RESPONSE of
> > >>>>>>>> rpc type
> > >>>>>>>>> 1 took longer than 500 ms. Actual Duration
was 981ms.
> > >>>>>>>>>
> > >>>>>>>>> We really appreciate your help. I will dig
in the source code
> for
> > >>>>>>>> when and
> > >>>>>>>>> why this error happen.
> > >>>>>>>>>
> > >>>>>>>>>
> > >>>>>>>>> Francois
> > >>>>>>>>>
> > >>>>>>>>> P.S.:
> > >>>>>>>>> We do see this also:
> > >>>>>>>>> 2016-09-19 14:48:23,444 [drill-executor-9]
WARN
> > >>>>>>>>> o.a.d.exec.rpc.control.WorkEventBus - Fragment
......:1:2 not
> > >> found
> > >>>>>>>> in the
> > >>>>>>>>> work bus.
> > >>>>>>>>> 2016-09-19 14:48:23,444 [drill-executor-11]
WARN
> > >>>>>>>>> o.a.d.exec.rpc.control.WorkEventBus - Fragment
....:1:222 not
> > >> found
> > >>>>>>>> in the
> > >>>>>>>>> work bus.
> > >>>>>>>>> 2016-09-19 14:48:23,444 [drill-executor-12]
WARN
> > >>>>>>>>> o.a.d.exec.rpc.control.WorkEventBus - Fragment
....:1:442 not
> > >> found
> > >>>>>>>> in the
> > >>>>>>>>> work bus.
> > >>>>>>>>> 2016-09-19 14:48:23,444 [drill-executor-10]
WARN
> > >>>>>>>>> o.a.d.exec.rpc.control.WorkEventBus - Fragment
....:1:662 not
> > >> found
> > >>>>>>>> in the
> > >>>>>>>>> work bus.
> > >>>>>>>>>
> > >>>>>>>>>
> > >>>>>>>>>
> > >>>>>>>>>
> > >>>>>>>>> On Sun, Sep 18, 2016 at 2:57 PM, Sudheesh Katkam
<
> > >>>>>>>> skatkam@maprtech.com <mailto:skatkam@maprtech.com>>
> > >>>>>>>>> wrote:
> > >>>>>>>>>
> > >>>>>>>>>> Hi Francois,
> > >>>>>>>>>>
> > >>>>>>>>>> More questions..
> > >>>>>>>>>>
> > >>>>>>>>>>> + Can you share the query profile?
> > >>>>>>>>>>> I will sum it up:
> > >>>>>>>>>>> It is a select on 18 columns: 9 string,
9 integers.
> > >>>>>>>>>>> Scan is done on 13862 parquet files
spread  on 1000
> fragments.
> > >>>>>>>>>>> Fragments are spread accross 215 nodes.
> > >>>>>>>>>>
> > >>>>>>>>>> So ~5 leaf fragments (or scanners) per
Drillbit seems fine.
> > >>>>>>>>>>
> > >>>>>>>>>> + Does the query involve any aggregations
or filters? Or is
> this a
> > >>>>>>>> select
> > >>>>>>>>>> query with only projections?
> > >>>>>>>>>> + Any suspicious timings in the query profile?
> > >>>>>>>>>> + Any suspicious warning messages in the
logs around the time
> of
> > >>>>>>>> failure
> > >>>>>>>>>> on any of the drillbits? Specially on atsqa4-133.qa.lab?
> Specially
> > >>>>>>>> this one
> > >>>>>>>>>> (“..” are place holders):
> > >>>>>>>>>> Message of mode .. of rpc type .. took
longer than ..ms.
> Actual
> > >>>>>>>>>> duration was ..ms.
> > >>>>>>>>>>
> > >>>>>>>>>> Thank you,
> > >>>>>>>>>> Sudheesh
> > >>>>>>>>>>
> > >>>>>>>>>>> On Sep 15, 2016, at 11:27 AM, François
Méthot <
> > >> fmethot78@gmail.com <mailto:fmethot78@gmail.com>>
> > >>>>>>>>>> wrote:
> > >>>>>>>>>>>
> > >>>>>>>>>>> Hi Sudheesh,
> > >>>>>>>>>>>
> > >>>>>>>>>>> + How many zookeeper servers in the
quorum?
> > >>>>>>>>>>> The quorum has 3 servers, everything
looks healthy
> > >>>>>>>>>>>
> > >>>>>>>>>>> + What is the load on atsqa4-133.qa.lab
when this happens?
> Any
> > >> other
> > >>>>>>>>>>> applications running on that node?
How many threads is the
> Drill
> > >>>>>>>> process
> > >>>>>>>>>>> using?
> > >>>>>>>>>>> The load on the failing node(8 cores)
is 14, when Drill is
> > >> running.
> > >>>>>>>> Which
> > >>>>>>>>>>> is nothing out of the ordinary according
to our admin.
> > >>>>>>>>>>> HBase is also running.
> > >>>>>>>>>>> planner.width.max_per_node is set to
8
> > >>>>>>>>>>>
> > >>>>>>>>>>> + When running the same query on 12
nodes, is the data size
> same?
> > >>>>>>>>>>> Yes
> > >>>>>>>>>>>
> > >>>>>>>>>>> + Can you share the query profile?
> > >>>>>>>>>>> I will sum it up:
> > >>>>>>>>>>> It is a select on 18 columns: 9 string,
9 integers.
> > >>>>>>>>>>> Scan is done on 13862 parquet files
spread  on 1000
> fragments.
> > >>>>>>>>>>> Fragments are spread accross 215 nodes.
> > >>>>>>>>>>>
> > >>>>>>>>>>>
> > >>>>>>>>>>> We are in process of increasing our
Zookeeper session timeout
> > >>>>>>>> config to
> > >>>>>>>>>> see
> > >>>>>>>>>>> if it helps.
> > >>>>>>>>>>>
> > >>>>>>>>>>> thanks
> > >>>>>>>>>>>
> > >>>>>>>>>>> Francois
> > >>>>>>>>>>>
> > >>>>>>>>>>>
> > >>>>>>>>>>>
> > >>>>>>>>>>>
> > >>>>>>>>>>>
> > >>>>>>>>>>>
> > >>>>>>>>>>>
> > >>>>>>>>>>> On Wed, Sep 14, 2016 at 4:40 PM, Sudheesh
Katkam <
> > >>>>>>>> skatkam@maprtech.com <mailto:skatkam@maprtech.com>>
> > >>>>>>>>>>> wrote:
> > >>>>>>>>>>>
> > >>>>>>>>>>>> Hi Francois,
> > >>>>>>>>>>>>
> > >>>>>>>>>>>> Few questions:
> > >>>>>>>>>>>> + How many zookeeper servers in
the quorum?
> > >>>>>>>>>>>> + What is the load on atsqa4-133.qa.lab
when this happens?
> Any
> > >>>>>>>> other
> > >>>>>>>>>>>> applications running on that node?
How many threads is the
> Drill
> > >>>>>>>> process
> > >>>>>>>>>>>> using?
> > >>>>>>>>>>>> + When running the same query on
12 nodes, is the data size
> > >> same?
> > >>>>>>>>>>>> + Can you share the query profile?
> > >>>>>>>>>>>>
> > >>>>>>>>>>>> This may not be the right thing
to do, but for now, If the
> > >> cluster
> > >>>>>>>> is
> > >>>>>>>>>>>> heavily loaded, increase the zk
timeout.
> > >>>>>>>>>>>>
> > >>>>>>>>>>>> Thank you,
> > >>>>>>>>>>>> Sudheesh
> > >>>>>>>>>>>>
> > >>>>>>>>>>>>> On Sep 14, 2016, at 11:53 AM,
François Méthot <
> > >>>>>>>> fmethot78@gmail.com <mailto:fmethot78@gmail.com>>
> > >>>>>>>>>>>> wrote:
> > >>>>>>>>>>>>>
> > >>>>>>>>>>>>> We are running 1.7.
> > >>>>>>>>>>>>> The log were taken from the
jira tickets.
> > >>>>>>>>>>>>>
> > >>>>>>>>>>>>> We will try out 1.8 soon.
> > >>>>>>>>>>>>>
> > >>>>>>>>>>>>>
> > >>>>>>>>>>>>>
> > >>>>>>>>>>>>>
> > >>>>>>>>>>>>> On Wed, Sep 14, 2016 at 2:52
PM, Chun Chang <
> > >> cchang@maprtech.com <mailto:cchang@maprtech.com>>
> > >>>>>>>>>> wrote:
> > >>>>>>>>>>>>>
> > >>>>>>>>>>>>>> Looks like you are running
1.5. I believe there are some
> work
> > >>>>>>>> done in
> > >>>>>>>>>>>> that
> > >>>>>>>>>>>>>> area and the newer release
should behave better.
> > >>>>>>>>>>>>>>
> > >>>>>>>>>>>>>> On Wed, Sep 14, 2016 at
11:43 AM, François Méthot <
> > >>>>>>>>>> fmethot78@gmail.com <mailto:fmethot78@gmail.com>>
> > >>>>>>>>>>>>>> wrote:
> > >>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> Hi,
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> We are trying to find
a solution/workaround to issue:
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> 2016-01-28 16:36:14,367
[Curator-ServiceCache-0] ERROR
> > >>>>>>>>>>>>>>> o.a.drill.exec.work.foreman.Fo
<
> http://o.a.drill.exec.work.foreman.fo/>reman - SYSTEM ERROR:
> > >>>>>>>>>> ForemanException:
> > >>>>>>>>>>>>>>> One more more nodes
lost connectivity during query.
> > >> Identified
> > >>>>>>>> nodes
> > >>>>>>>>>>>>>>> were [atsqa4-133.qa.lab:31010].
> > >>>>>>>>>>>>>>> org.apache.drill.common.exceptions.UserException:
SYSTEM
> > >> ERROR:
> > >>>>>>>>>>>>>>> ForemanException: One
more more nodes lost connectivity
> > >> during
> > >>>>>>>> query.
> > >>>>>>>>>>>>>>> Identified nodes were
[atsqa4-133.qa.lab:31010].
> > >>>>>>>>>>>>>>>   at org.apache.drill.exec.work.for
> > >>>>>>>> eman.Foreman$ForemanResult.
> > >>>>>>>>>>>>>>> close(Foreman.java:746)
> > >>>>>>>>>>>>>>> [drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
> > >>>>>>>>>>>>>>>   at org.apache.drill.exec.work.
> > >> foreman.Foreman$StateSwitch.
> > >>>>>>>>>>>>>>> processEvent(Foreman.java:858)
> > >>>>>>>>>>>>>>> [drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
> > >>>>>>>>>>>>>>>   at org.apache.drill.exec.work.
> > >> foreman.Foreman$StateSwitch.
> > >>>>>>>>>>>>>>> processEvent(Foreman.java:790)
> > >>>>>>>>>>>>>>> [drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
> > >>>>>>>>>>>>>>>   at org.apache.drill.exec.work.
> > >> foreman.Foreman$StateSwitch.
> > >>>>>>>>>>>>>>> moveToState(Foreman.java:792)
> > >>>>>>>>>>>>>>> [drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
> > >>>>>>>>>>>>>>>   at org.apache.drill.exec.work.
> > >> foreman.Foreman.moveToState(
> > >>>>>>>>>>>>>>> Foreman.java:909)
> > >>>>>>>>>>>>>>> [drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
> > >>>>>>>>>>>>>>>   at org.apache.drill.exec.work.
> > >> foreman.Foreman.access$2700(
> > >>>>>>>>>>>>>>> Foreman.java:110)
> > >>>>>>>>>>>>>>> [drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
> > >>>>>>>>>>>>>>>   at org.apache.drill.exec.work.for
> > >>>>>>>> eman.Foreman$StateListener.
> > >>>>>>>>>>>>>>> moveToState(Foreman.java:1183)
> > >>>>>>>>>>>>>>> [drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> DRILL-4325  <https://issues.apache.org/
<
> https://issues.apache.org/>
> > >> jira/browse/DRILL-4325>
> > >>>>>>>>>>>>>>> ForemanException:
> > >>>>>>>>>>>>>>> One or more nodes lost
connectivity during query
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> Any one experienced
this issue ?
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> It happens when running
query involving many parquet
> files
> > >> on a
> > >>>>>>>>>> cluster
> > >>>>>>>>>>>>>> of
> > >>>>>>>>>>>>>>> 200 nodes. Same query
on a smaller cluster of 12 nodes
> runs
> > >>>>>>>> fine.
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> It is not caused by
garbage collection, (checked on both
> ZK
> > >>>>>>>> node and
> > >>>>>>>>>>>> the
> > >>>>>>>>>>>>>>> involved drill bit).
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> Negotiated max session
timeout is 40 seconds.
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> The sequence seems:
> > >>>>>>>>>>>>>>> - Drill Query begins,
using an existing ZK session.
> > >>>>>>>>>>>>>>> - Drill Zk session
timeouts
> > >>>>>>>>>>>>>>> - perhaps it was writing
something that took too long
> > >>>>>>>>>>>>>>> - Drill attempts to
renew session
> > >>>>>>>>>>>>>>>  - drill believes that
the write operation failed, so it
> > >>>>>>>> attempts
> > >>>>>>>>>>>>>> to
> > >>>>>>>>>>>>>>> re-create the zk node,
which trigger another exception.
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> We are open to any
suggestion. We will report any
> finding.
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>> Thanks
> > >>>>>>>>>>>>>>> Francois
> > >>>>>>>>>>>>>>>
> > >>>>>>>>>>>>>>
> > >>>>>>>>>>>>
> > >>>>>>>>>>>>
> > >>>>>>>>>>
> > >>>>>>>>>>
> > >>>>>>>>
> > >>>>>>>>
> > >>>>>>>
> > >>>>>>
> > >>>>>
> > >>>
> > >>
> > >>
> >
> >
>
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message