drill-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Paul Rogers (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (DRILL-5670) Varchar vector throws an assertion error when allocating a new vector
Date Sat, 09 Sep 2017 01:19:00 GMT

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

Paul Rogers edited comment on DRILL-5670 at 9/9/17 1:18 AM:
------------------------------------------------------------

On the Mac, single-threaded, the batch size is much different, resulting in different behavior:

{code}
  Records: 8096, Total size: 678068224, Data size: 389425696, Gross row width: 83754, Net
row width: 48101, Density: 1%}

Insufficient memory to merge two batches. Incoming batch size: 678068224, available memory:
482344960
{code}

This is because 8096 is the default number of records in the text reader:

{code}
MAX_RECORDS_PER_BATCH = 8096;
{code}

To recreate the original case, changed the hard-coded batch size to 1023. The query now runs
past the above problem (but runs into a problem described later):

{code}
Config: spill file size = 268435456, spill batch size = 1048576, merge batch size = 16777216,
mSort batch size = 65535
Memory config: Allocator limit = 482344960
Config: Resetting allocator to 10% safety margin: 530579456

  Records: 1023, Total size: 86353920, Data size: 49207323, Gross row width: 84413, Net row
width: 48101, Density: 8%}
...
Input Batch Estimates: record size = 48101 bytes; net = 86353920 bytes, gross = 129530880,
records = 1023
Spill batch size: net = 4810100 bytes, gross = 7215150 bytes, records = 100; spill file =
268435456 bytes
Output batch size: net = 16739148 bytes, gross = 25108722 bytes, records = 348
Available memory: 482344960, buffer memory = 463104560, merge memory = 448866664
{code}

Note that actual density is 56%. There seems to be an overflow issue that gives a number of
only 8%.

The above calcs are identical to that seen on the QA cluster.

The log contains many of the following:

{code}
UInt4Vector - Reallocating vector [$offsets$(UINT4:REQUIRED)]. # of bytes: [4096] -> [8192]
{code}

This code seems to come from the text reader which relies on default vector allocation:

{code}
  @Override
  public void allocate(Map<String, ValueVector> vectorMap) throws OutOfMemoryException
{
    for (final ValueVector v : vectorMap.values()) {
      v.allocateNew();
    }
  }
{code}

The above does not say the number of values to allocate. There seems to be some attempt to
allocate the same size as the previous allocation, but this does not explain the offset vector
behavior. Also, if the algorithm is, indeed, "allocate the last amount", then the algorithm
creates a ratchet effect: the vector will only grow in size over batches, retaining the largest
size yet seen. Spikes in data can result in wasted space (low density batches.) This is something
to investigate elsewhere.

Further, the logic does not seem to work with the offset vector, causing reallocations. Something
else to investigate.

The run takes about an hour. Good news, I can reproduce the problem on the Mac:

{code}
Starting merge phase. Runs = 62, Alloc. memory = 0
End of sort. Total write bytes: 82135266715, Total read bytes: 82135266715
Unable to allocate buffer of size 16777216 (rounded from 15834000) due to memory limit. Current
allocation: 525809920
{code}


was (Author: paul.rogers):
On the Mac, single-threaded, the batch size is much different, resulting in different behavior:

{code}
  Records: 8096, Total size: 678068224, Data size: 389425696, Gross row width: 83754, Net
row width: 48101, Density: 1%}

Insufficient memory to merge two batches. Incoming batch size: 678068224, available memory:
482344960
{code}

This is because 8096 is the default number of records in the text reader:

{code}
MAX_RECORDS_PER_BATCH = 8096;
{code}

To recreate the original case, changed the hard-coded batch size to 1023. The query now runs
past the above problem (but runs into a problem described later):

{code}
Config: spill file size = 268435456, spill batch size = 1048576, merge batch size = 16777216,
mSort batch size = 65535
Memory config: Allocator limit = 482344960
Config: Resetting allocator to 10% safety margin: 530579456

  Records: 1023, Total size: 86353920, Data size: 49207323, Gross row width: 84413, Net row
width: 48101, Density: 8%}
...
Input Batch Estimates: record size = 48101 bytes; net = 86353920 bytes, gross = 129530880,
records = 1023
Spill batch size: net = 4810100 bytes, gross = 7215150 bytes, records = 100; spill file =
268435456 bytes
Output batch size: net = 16739148 bytes, gross = 25108722 bytes, records = 348
Available memory: 482344960, buffer memory = 463104560, merge memory = 448866664
{code}

Note that actual density is 56%. There seems to be an overflow issue that gives a number of
only 8%.

The above calcs are identical to that seen on the QA cluster.

Note that the CSV reader is producing low-density batches: this is a problem to be resolved
elsewhere.

The log contains many of the following:

{code}
UInt4Vector - Reallocating vector [$offsets$(UINT4:REQUIRED)]. # of bytes: [4096] -> [8192]
{code}

This code seems to come from the text reader which relies on default vector allocation:

{code}
  @Override
  public void allocate(Map<String, ValueVector> vectorMap) throws OutOfMemoryException
{
    for (final ValueVector v : vectorMap.values()) {
      v.allocateNew();
    }
  }
{code}

The above does not say the number of values to allocate. There seems to be some attempt to
allocate the same size as the previous allocation, but this does not explain the offset vector
behavior. Also, if the algorithm is, indeed, "allocate the last amount", then the algorithm
creates a ratchet effect: the vector will only grow in size over batches, retaining the largest
size yet seen. Spikes in data can result in wasted space (low density batches.) This is something
to investigate elsewhere.

Further, the logic does not seem to work with the offset vector, causing reallocations. Something
else to investigate.

The run takes about an hour. Good news, I can reproduce the problem on the Mac:

{code}
Starting merge phase. Runs = 62, Alloc. memory = 0
End of sort. Total write bytes: 82135266715, Total read bytes: 82135266715
Unable to allocate buffer of size 16777216 (rounded from 15834000) due to memory limit. Current
allocation: 525809920
{code}

> Varchar vector throws an assertion error when allocating a new vector
> ---------------------------------------------------------------------
>
>                 Key: DRILL-5670
>                 URL: https://issues.apache.org/jira/browse/DRILL-5670
>             Project: Apache Drill
>          Issue Type: Bug
>          Components: Execution - Relational Operators
>    Affects Versions: 1.11.0
>            Reporter: Rahul Challapalli
>            Assignee: Paul Rogers
>             Fix For: 1.12.0
>
>         Attachments: 26555749-4d36-10d2-6faf-e403db40c370.sys.drill, 266290f3-5fdc-5873-7372-e9ee053bf867.sys.drill,
269969ca-8d4d-073a-d916-9031e3d3fbf0.sys.drill, drillbit.log, drillbit.log, drillbit.log,
drillbit.log, drillbit.out, drill-override.conf
>
>
> I am running this test on a private branch of [paul's repository|https://github.com/paul-rogers/drill].
Below is the commit info
> {code}
> git.commit.id.abbrev=d86e16c
> git.commit.user.email=progers@maprtech.com
> git.commit.message.full=DRILL-5601\: Rollup of external sort fixes an improvements\n\n-
DRILL-5513\: Managed External Sort \: OOM error during the merge phase\n- DRILL-5519\: Sort
fails to spill and results in an OOM\n- DRILL-5522\: OOM during the merge and spill process
of the managed external sort\n- DRILL-5594\: Excessive buffer reallocations during merge phase
of external sort\n- DRILL-5597\: Incorrect "bits" vector allocation in nullable vectors allocateNew()\n-
DRILL-5602\: Repeated List Vector fails to initialize the offset vector\n\nAll of the bugs
have to do with handling low-memory conditions, and with\ncorrectly estimating the sizes of
vectors, even when those vectors come\nfrom the spill file or from an exchange. Hence, the
changes for all of\nthe above issues are interrelated.\n
> git.commit.id=d86e16c551e7d3553f2cde748a739b1c5a7a7659
> git.commit.message.short=DRILL-5601\: Rollup of external sort fixes an improvements
> git.commit.user.name=Paul Rogers
> git.build.user.name=Rahul Challapalli
> git.commit.id.describe=0.9.0-1078-gd86e16c
> git.build.user.email=challapallirahul@gmail.com
> git.branch=d86e16c551e7d3553f2cde748a739b1c5a7a7659
> git.commit.time=05.07.2017 @ 20\:34\:39 PDT
> git.build.time=12.07.2017 @ 14\:27\:03 PDT
> git.remote.origin.url=git@github.com\:paul-rogers/drill.git
> {code}
> Below query fails with an Assertion Error
> {code}
> 0: jdbc:drill:zk=10.10.100.190:5181> ALTER SESSION SET `exec.sort.disable_managed`
= false;
> +-------+-------------------------------------+
> |  ok   |               summary               |
> +-------+-------------------------------------+
> | true  | exec.sort.disable_managed updated.  |
> +-------+-------------------------------------+
> 1 row selected (1.044 seconds)
> 0: jdbc:drill:zk=10.10.100.190:5181> alter session set `planner.memory.max_query_memory_per_node`
= 482344960;
> +-------+----------------------------------------------------+
> |  ok   |                      summary                       |
> +-------+----------------------------------------------------+
> | true  | planner.memory.max_query_memory_per_node updated.  |
> +-------+----------------------------------------------------+
> 1 row selected (0.372 seconds)
> 0: jdbc:drill:zk=10.10.100.190:5181> alter session set `planner.width.max_per_node`
= 1;
> +-------+--------------------------------------+
> |  ok   |               summary                |
> +-------+--------------------------------------+
> | true  | planner.width.max_per_node updated.  |
> +-------+--------------------------------------+
> 1 row selected (0.292 seconds)
> 0: jdbc:drill:zk=10.10.100.190:5181> alter session set `planner.width.max_per_query`
= 1;
> +-------+---------------------------------------+
> |  ok   |                summary                |
> +-------+---------------------------------------+
> | true  | planner.width.max_per_query updated.  |
> +-------+---------------------------------------+
> 1 row selected (0.25 seconds)
> 0: jdbc:drill:zk=10.10.100.190:5181> select count(*) from (select * from dfs.`/drill/testdata/resource-manager/3500cols.tbl`
order by columns[450],columns[330],columns[230],columns[220],columns[110],columns[90],columns[80],columns[70],columns[40],columns[10],columns[20],columns[30],columns[40],columns[50],
columns[454],columns[413],columns[940],columns[834],columns[73],columns[140],columns[104],columns[2222],columns[30],columns[2420],columns[1520],
columns[1410], columns[1110],columns[1290],columns[2380],columns[705],columns[45],columns[1054],columns[2430],columns[420],columns[404],columns[3350],
columns[3333],columns[153],columns[356],columns[84],columns[745],columns[1450],columns[103],columns[2065],columns[343],columns[3420],columns[530],
columns[3210] ) d where d.col433 = 'sjka skjf';
> Error: RESOURCE ERROR: External Sort encountered an error while spilling to disk
> Fragment 2:0
> [Error Id: 26b55576-1a5c-4756-96d6-fbec25eecf03 on qa-node190.qa.lab:31010]
>   (java.lang.AssertionError) null
>     org.apache.drill.exec.vector.VarCharVector.allocateNew():400
>     org.apache.drill.exec.vector.RepeatedVarCharVector.allocateNew():272
>     org.apache.drill.exec.vector.AllocationHelper.allocatePrecomputedChildCount():37
>     org.apache.drill.exec.vector.AllocationHelper.allocate():44
>     org.apache.drill.exec.record.SmartAllocationHelper.allocateVector():117
>     org.apache.drill.exec.record.SmartAllocationHelper.allocateVector():97
>     org.apache.drill.exec.record.SmartAllocationHelper.allocateBatch():87
>     org.apache.drill.exec.physical.impl.xsort.managed.PriorityQueueCopierWrapper$BatchMerger.next():262
>     org.apache.drill.exec.physical.impl.xsort.managed.SpilledRuns.doMergeAndSpill():171
>     org.apache.drill.exec.physical.impl.xsort.managed.SpilledRuns.safeMergeAndSpill():138
>     org.apache.drill.exec.physical.impl.xsort.managed.SpilledRuns.mergeAndSpill():91
>     org.apache.drill.exec.physical.impl.xsort.managed.SortImpl.spillFromMemory():298
>     org.apache.drill.exec.physical.impl.xsort.managed.SortImpl.addBatch():191
>     org.apache.drill.exec.physical.impl.xsort.managed.ExternalSortBatch.loadBatch():402
>     org.apache.drill.exec.physical.impl.xsort.managed.ExternalSortBatch.load():338
>     org.apache.drill.exec.physical.impl.xsort.managed.ExternalSortBatch.innerNext():290
>     org.apache.drill.exec.record.AbstractRecordBatch.next():162
>     org.apache.drill.exec.physical.impl.validate.IteratorValidatorBatchIterator.next():225
>     org.apache.drill.exec.record.AbstractRecordBatch.next():119
>     org.apache.drill.exec.record.AbstractRecordBatch.next():109
>     org.apache.drill.exec.record.AbstractSingleRecordBatch.innerNext():51
>     org.apache.drill.exec.physical.impl.svremover.RemovingRecordBatch.innerNext():93
>     org.apache.drill.exec.record.AbstractRecordBatch.next():162
>     org.apache.drill.exec.physical.impl.validate.IteratorValidatorBatchIterator.next():225
>     org.apache.drill.exec.physical.impl.BaseRootExec.next():105
>     org.apache.drill.exec.physical.impl.SingleSenderCreator$SingleSenderRootExec.innerNext():92
>     org.apache.drill.exec.physical.impl.BaseRootExec.next():95
>     org.apache.drill.exec.work.fragment.FragmentExecutor$1.run():234
>     org.apache.drill.exec.work.fragment.FragmentExecutor$1.run():227
>     java.security.AccessController.doPrivileged():-2
>     javax.security.auth.Subject.doAs():415
>     org.apache.hadoop.security.UserGroupInformation.doAs():1595
>     org.apache.drill.exec.work.fragment.FragmentExecutor.run():227
>     org.apache.drill.common.SelfCleaningRunnable.run():38
>     java.util.concurrent.ThreadPoolExecutor.runWorker():1145
>     java.util.concurrent.ThreadPoolExecutor$Worker.run():615
>     java.lang.Thread.run():745 (state=,code=0)
> {code}
> The data set is too large to attach here. Logs and profiles are attached



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

Mime
View raw message