[jira] [Commented] (HIVE-9324) Reduce side joins failing with IOException from RowContainer.nextBlock

[Amareshwari Sriramadasu (JIRA)]

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

Amareshwari Sriramadasu commented on HIVE-9324:
---

After doing some code walkthrough, here is what i found,

On JoinOperator, whenever any key as more values than BLOCKSIZE(hardcoded to 
25000), it spills the values to a file on disk, and spill uses SequenceFile 
format. 

Here is the table description for spill (from 
org.apache.hadoop.hive.ql.exec.JoinUtil.java)
{noformat}
  TableDesc tblDesc = new TableDesc(
  SequenceFileInputFormat.class, HiveSequenceFileOutputFormat.class,
  Utilities.makeProperties(
  org.apache.hadoop.hive.serde.serdeConstants.SERIALIZATION_FORMAT, ""
  + Utilities.ctrlaCode,
  org.apache.hadoop.hive.serde.serdeConstants.LIST_COLUMNS, colNames
  .toString(),
  org.apache.hadoop.hive.serde.serdeConstants.LIST_COLUMN_TYPES,
  colTypes.toString(),
  serdeConstants.SERIALIZATION_LIB,LazyBinarySerDe.class.getName()));
  spillTableDesc[tag] = tblDesc;
{noformat}
>From the exception:
{noformat}
Caused by: java.io.IOException: 
org.apache.hadoop.hive.ql.io.RCFile$KeyBuffer@42610e8 read 1 bytes, should read 
27264
at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:2435)
at 
org.apache.hadoop.mapred.SequenceFileRecordReader.next(SequenceFileRecordReader.java:76)
at 
org.apache.hadoop.hive.ql.exec.persistence.RowContainer.nextBlock(RowContainer.java:360)
... 13 more
{noformat}

I see that the value in SequenceFile is RCFile$KeyBuffer, dont know why. Also 
couldnt figure out the reason why the reading went wrong.

Following is the code snippet from SequenceFile.java for the exception we are 
hitting :
{noformat}
2417 public synchronized Object next(Object key) throws IOException {
2418   if (key != null && key.getClass() != getKeyClass()) {
2419 throw new IOException("wrong key class: "+key.getClass().getName()
2420   +" is not "+keyClass);
2421   }
2422 
2423   if (!blockCompressed) {
2424 outBuf.reset();
2425 
2426 keyLength = next(outBuf);
2427 if (keyLength < 0)
2428   return null;
2429 
2430 valBuffer.reset(outBuf.getData(), outBuf.getLength());
2431 
2432 key = deserializeKey(key);
2433 valBuffer.mark(0);
2434 if (valBuffer.getPosition() != keyLength)
2435   throw new IOException(key + " read " + valBuffer.getPosition()
2436 + " bytes, should read " + keyLength);
{noformat}

> Reduce side joins failing with IOException from RowContainer.nextBlock
> --
>
> Key: HIVE-9324
> URL: https://issues.apache.org/jira/browse/HIVE-9324
> Project: Hive
>  Issue Type: Bug
>  Components: Query Processor
>Affects Versions: 0.13.1
>Reporter: Amareshwari Sriramadasu
>
> We are seeing some reduce side join mapreduce jobs failing with following 
> exception :
> {noformat}
> 2014-12-14 16:58:51,296 ERROR 
> org.apache.hadoop.hive.ql.exec.persistence.RowContainer: 
> org.apache.hadoop.hive.ql.io.RCFile$KeyBuffer@42610e8 read 1 bytes, should 
> read 27264
> java.io.IOException: org.apache.hadoop.hive.ql.io.RCFile$KeyBuffer@42610e8 
> read 1 bytes, should read 27264
>   at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:2435)
>   at 
> org.apache.hadoop.mapred.SequenceFileRecordReader.next(SequenceFileRecordReader.java:76)
>   at 
> org.apache.hadoop.hive.ql.exec.persistence.RowContainer.nextBlock(RowContainer.java:360)
>   at 
> org.apache.hadoop.hive.ql.exec.persistence.RowContainer.first(RowContainer.java:230)
>   at 
> org.apache.hadoop.hive.ql.exec.persistence.RowContainer.first(RowContainer.java:74)
>   at 
> org.apache.hadoop.hive.ql.exec.CommonJoinOperator.genUniqueJoinObject(CommonJoinOperator.java:644)
>   at 
> org.apache.hadoop.hive.ql.exec.CommonJoinOperator.checkAndGenObject(CommonJoinOperator.java:758)
>   at 
> org.apache.hadoop.hive.ql.exec.JoinOperator.endGroup(JoinOperator.java:256)
>   at 
> org.apache.hadoop.hive.ql.exec.mr.ExecReducer.reduce(ExecReducer.java:216)
>   at 
> org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:506)
>   at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:447)
>   at org.apache.hadoop.mapred.Child$4.run(Child.java:268)
>   at java.security.AccessController.doPrivileged(Native Method)
>   at javax.security.auth.Subject.doAs(Subject.java:416)
>   at 
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1408)
>   at org.apache.hadoop.mapred.Child.main(Child.java:262)
> 2014-12-14 16:58:51,334 FATAL Exe

[jira] [Commented] (HIVE-9324) Reduce side joins failing with IOException from RowContainer.nextBlock

[Amareshwari Sriramadasu (JIRA)]

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

Amareshwari Sriramadasu commented on HIVE-9324:
---

More task log :

{noformat}
2014-12-14 16:58:03,905 INFO org.apache.hadoop.hive.ql.exec.mr.ObjectCache: 
Ignoring retrieval request: __REDUCE_PLAN__
2014-12-14 16:58:03,945 INFO org.apache.hadoop.hive.ql.log.PerfLogger: 
2014-12-14 16:58:03,945 INFO org.apache.hadoop.hive.ql.exec.Utilities: 
Deserializing ReduceWork via kryo
2014-12-14 16:58:04,987 INFO org.apache.hadoop.hive.ql.log.PerfLogger: 

2014-12-14 16:58:04,988 INFO org.apache.hadoop.hive.ql.exec.mr.ObjectCache: 
Ignoring cache key: __REDUCE_PLAN__
2014-12-14 16:58:05,327 INFO ExecReducer: 
Id =0
  
Id =1
  
  <\Children>
  Id = 0 null<\Parent>
<\FS>
  <\Children>
  <\Parent>
<\JOIN>
2014-12-14 16:58:05,327 INFO org.apache.hadoop.hive.ql.exec.JoinOperator: 
Initializing Self 0 JOIN
2014-12-14 16:58:05,377 INFO org.apache.hadoop.hive.ql.exec.CommonJoinOperator: 
JOIN 
struct<_col23:string,_col65:double,_col99:double,_col237:double,_col240:double,_col250:string,_col367:int>
 totalsz = 7
2014-12-14 16:58:05,377 INFO org.apache.hadoop.hive.ql.exec.JoinOperator: 
Operator 0 JOIN initialized
2014-12-14 16:58:05,377 INFO org.apache.hadoop.hive.ql.exec.JoinOperator: 
Initializing children of 0 JOIN
2014-12-14 16:58:05,377 INFO org.apache.hadoop.hive.ql.exec.FileSinkOperator: 
Initializing child 1 FS
2014-12-14 16:58:05,377 INFO org.apache.hadoop.hive.ql.exec.FileSinkOperator: 
Initializing Self 1 FS
2014-12-14 16:58:05,394 INFO org.apache.hadoop.hive.ql.exec.FileSinkOperator: 
Operator 1 FS initialized
2014-12-14 16:58:05,394 INFO org.apache.hadoop.hive.ql.exec.FileSinkOperator: 
Initialization Done 1 FS
2014-12-14 16:58:05,395 INFO org.apache.hadoop.hive.ql.exec.JoinOperator: 
Initialization Done 0 JOIN
2014-12-14 16:58:05,401 INFO ExecReducer: ExecReducer: processing 1 rows: used 
memory = 242598168
2014-12-14 16:58:05,406 INFO ExecReducer: ExecReducer: processing 10 rows: used 
memory = 242759392
2014-12-14 16:58:05,437 INFO ExecReducer: ExecReducer: processing 100 rows: 
used memory = 242759392
2014-12-14 16:58:05,657 INFO ExecReducer: ExecReducer: processing 1000 rows: 
used memory = 243653240
2014-12-14 16:58:06,976 INFO ExecReducer: ExecReducer: processing 1 rows: 
used memory = 247197944
2014-12-14 16:58:07,646 INFO ExecReducer: ExecReducer: processing 10 rows: 
used memory = 277801256
2014-12-14 16:58:11,511 INFO ExecReducer: ExecReducer: processing 100 rows: 
used memory = 283150744
2014-12-14 16:58:14,993 INFO ExecReducer: ExecReducer: processing 200 rows: 
used memory = 293036992
2014-12-14 16:58:18,497 INFO ExecReducer: ExecReducer: processing 300 rows: 
used memory = 311449488
2014-12-14 16:58:20,815 INFO ExecReducer: ExecReducer: processing 400 rows: 
used memory = 285251752
2014-12-14 16:58:26,460 INFO ExecReducer: ExecReducer: processing 500 rows: 
used memory = 328223864
2014-12-14 16:58:29,412 INFO ExecReducer: ExecReducer: processing 600 rows: 
used memory = 263175576
2014-12-14 16:58:31,331 INFO ExecReducer: ExecReducer: processing 700 rows: 
used memory = 282021320
2014-12-14 16:58:35,099 INFO ExecReducer: ExecReducer: processing 800 rows: 
used memory = 299301184
2014-12-14 16:58:37,981 INFO ExecReducer: ExecReducer: processing 900 rows: 
used memory = 306925648
2014-12-14 16:58:40,506 INFO ExecReducer: ExecReducer: processing 1000 
rows: used memory = 307407920
2014-12-14 16:58:42,242 INFO ExecReducer: ExecReducer: processing 1100 
rows: used memory = 304664048
2014-12-14 16:58:46,142 INFO ExecReducer: ExecReducer: processing 1200 
rows: used memory = 298347024
2014-12-14 16:58:48,549 INFO org.apache.hadoop.hive.ql.exec.CommonJoinOperator: 
table 0 has 1000 rows for join key [003b9de7876541c2bcce9029ff0d3873]
2014-12-14 16:58:48,622 INFO org.apache.hadoop.hive.ql.exec.CommonJoinOperator: 
table 0 has 2000 rows for join key [003b9de7876541c2bcce9029ff0d3873]
2014-12-14 16:58:48,677 INFO org.apache.hadoop.hive.ql.exec.CommonJoinOperator: 
table 0 has 4000 rows for join key [003b9de7876541c2bcce9029ff0d3873]
2014-12-14 16:58:48,679 INFO org.apache.hadoop.hive.ql.exec.FileSinkOperator: 
Final Path: FS 
hdfs://data-grill300-null.arshad.ev1.inmobi.com:8020/tmp/hive-dataqa/hive_2014-12-14_16-49-14_996_1630664550753106415-32/_tmp.-mr-10002/00_0
2014-12-14 16:58:48,680 INFO org.apache.hadoop.hive.ql.exec.FileSinkOperator: 
Writing to temp file: FS 
hdfs://data-grill300-null.arshad.ev1.inmobi.com:8020/tmp/hive-dataqa/hive_2014-12-14_16-49-14_996_1630664550753106415-32/_task_tmp.-mr-10002/_tmp.00_0
2014-12-14 16:58:48,680 INFO org.apache.hadoop.hive.ql.exec.FileSinkOperator: 
New Final Path: FS 
hdfs://data-grill300-null.arshad.ev1.inmobi.com:8020/tmp/hive-dataqa/hive_2014-12-14_16-49-14_996_16