在cdh上运行hibench的join报错,求大神指教

zenzondon 发布于 2016/01/12 16:21
阅读 878
收藏 0

我从github下载hibench编译后在CHD5.5集群上按照wiki配置好hibench,然后运行,跑dfsioe,wordcount,terasort的测试没有问题,但是在运行join时,按照手册先运行prepare.sh时报错,错误信息如下:

[root@host-102-1 prepare]# ./prepare.sh 
patching args=
Parsing conf: /script/HiBench-HiBench-5.0/conf/00-default-properties.conf
Parsing conf: /script/HiBench-HiBench-5.0/conf/01-default-streamingbench.conf
Parsing conf: /script/HiBench-HiBench-5.0/conf/10-data-scale-profile.conf
Parsing conf: /script/HiBench-HiBench-5.0/conf/20-samza-common.conf
Parsing conf: /script/HiBench-HiBench-5.0/conf/30-samza-workloads.conf
Parsing conf: /script/HiBench-HiBench-5.0/conf/99-user_defined_properties.conf
Parsing conf: /script/HiBench-HiBench-5.0/workloads/join/conf/00-join-default.conf
Parsing conf: /script/HiBench-HiBench-5.0/workloads/join/conf/10-join-userdefine.conf
probe sleep jar: /opt/cloudera/parcels/CDH-5.5.0-1.cdh5.5.0.p0.8/share/hadoop/mapreduce2/hadoop-mapreduce-client-jobclient-2.6.0-cdh5.5.0-tests.jar
start HadoopPrepareJoin bench
hdfs rm -r: /opt/cloudera/parcels/CDH-5.5.0-1.cdh5.5.0.p0.8/bin/hadoop --config /opt/cloudera/parcels/CDH-5.5.0-1.cdh5.5.0.p0.8/etc/hadoop fs -rm -r -skipTrash hdfs://nameservice1/HiBench/Join/Input
Deleted hdfs://nameservice1/HiBench/Join/Input
Pages:120000, USERVISITS:1000000
Submit MapReduce Job: /opt/cloudera/parcels/CDH-5.5.0-1.cdh5.5.0.p0.8/bin/hadoop --config /opt/cloudera/parcels/CDH-5.5.0-1.cdh5.5.0.p0.8/etc/hadoop jar /script/HiBench-HiBench-5.0/src/autogen/target/autogen-4.0-SNAPSHOT-jar-with-dependencies.jar HiBench.DataGen -t hive -b hdfs://nameservice1/HiBench/Join -n Input -m 12 -r 6 -p 120000 -v 1000000 -o sequence
2016-01-12 13:34:30,942 INFO  [main] Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1174)) - mapred.reduce.slowstart.completed.maps is deprecated. Instead, use mapreduce.job.reduce.slowstart.completedmaps
2016-01-12 13:34:31,006 INFO  [main] Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1174)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2016-01-12 13:34:31,176 WARN  [main] mapreduce.JobResourceUploader (JobResourceUploader.java:uploadFiles(64)) - Hadoop command-line option parsing not performed. Implement the Tool interface and execute your application with ToolRunner
 to remedy this.
2016-01-12 13:34:31,662 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:32,253 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:32,554 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:32,836 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:33,111 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:33,407 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:33,695 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:33,980 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:34,289 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:34,583 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:34,873 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:35,183 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 13:34:35,658 INFO  [pool-14-thread-1] Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1174)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2016-01-12 13:34:38,620 WARN  [main] mapreduce.JobResourceUploader (JobResourceUploader.java:uploadFiles(64)) - Hadoop command-line option parsing not performed. Implement the Tool interface and execute your application with ToolRunner
 to remedy this.
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452576878747/user_agents (No such file or directory)
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452576878747/user_agents (No such file or directory)
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452576878747/user_agents (No such file or directory)
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452576878747/user_agents (No such file or directory)
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452576878747/user_agents (No such file or directory)
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452576878747/user_agents (No such file or directory)
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452576878747/user_agents (No such file or directory)
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452576878747/user_agents (No such file or directory)
2016-01-12 13:34:40,926 WARN  [Thread-97] mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local2005830263_0002
java.lang.Exception: java.lang.NullPointerException
Caused by: java.lang.NullPointerException
Exception in thread "main" java.io.IOException: Job failed!
        at org.apache.hadoop.util.RunJar.main(RunJar.java:136)
ERROR: Hadoop job /script/HiBench-HiBench-5.0/src/autogen/target/autogen-4.0-SNAPSHOT-jar-with-dependencies.jar HiBench.DataGen failed to run successfully.
Hint: You can goto /script/HiBench-HiBench-5.0/report/join/prepare/conf/../bench.log to check for detailed log.
Opening log tail for you:


        at HiBench.HiveData.generate(HiveData.java:619)
        at HiBench.DataGen.run(DataGen.java:19)
        at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:70)
        at HiBench.DataGen.main(DataGen.java:45)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.apache.hadoop.util.RunJar.run(RunJar.java:221)
        at org.apache.hadoop.util.RunJar.main(RunJar.java:136)


/script/HiBench-HiBench-5.0/report/join/prepare/conf/../bench.log的内容如下:

2016-01-12 14:18:45,780 INFO  [main] HiBench.HiveData (HiveData.java:generate(615)) - Generating hive data files...
2016-01-12 14:18:45,782 INFO  [main] HiBench.HiveData (HiveData.java:init(632)) - Initializing hive date generator...
curIndex: 349, total: 350
2016-01-12 14:18:47,789 INFO  [main] HiBench.Dummy (Dummy.java:create(29)) - Creating dummy file hdfs://nameservice1/HiBench/Join/temp/dummy with 12 slots...
2016-01-12 14:18:47,940 INFO  [main] HiBench.HiveData (HiveData.java:createRankingsTableDirectly(296)) - Creating table rankings...
2016-01-12 14:18:47,957 INFO  [main] Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1174)) - mapred.reduce.slowstart.completed.maps is deprecated. Instead, use mapreduce.job.reduce.slowstart.completedmaps
2016-01-12 14:18:47,967 INFO  [main] HiBench.HiveData (HiveData.java:createRankingsTableDirectly(355)) - Running Job: Create rankings
2016-01-12 14:18:47,967 INFO  [main] HiBench.HiveData (HiveData.java:createRankingsTableDirectly(356)) - Pages file hdfs://nameservice1/HiBench/Join/temp/dummy as input
2016-01-12 14:18:47,967 INFO  [main] HiBench.HiveData (HiveData.java:createRankingsTableDirectly(357)) - Rankings file hdfs://nameservice1/HiBench/Join/Input/rankings as output
2016-01-12 14:18:47,981 INFO  [main] Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1174)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2016-01-12 14:18:48,025 INFO  [main] jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2016-01-12 14:18:48,043 INFO  [main] jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2016-01-12 14:18:48,197 WARN  [main] mapreduce.JobResourceUploader (JobResourceUploader.java:uploadFiles(64)) - Hadoop command-line option parsing not performed. Implement the Tool interface and execute your application with ToolRunner to remedy this.
2016-01-12 14:18:48,296 INFO  [main] mapred.FileInputFormat (FileInputFormat.java:listStatus(249)) - Total input paths to process : 1
2016-01-12 14:18:48,335 INFO  [main] mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(201)) - number of splits:12
2016-01-12 14:18:48,396 INFO  [main] mapreduce.JobSubmitter (JobSubmitter.java:printTokens(290)) - Submitting tokens for job: job_local1441950054_0001
2016-01-12 14:18:48,546 INFO  [main] mapred.LocalDistributedCacheManager (LocalDistributedCacheManager.java:symlink(201)) - Creating symlink: /tmp/hadoop-root/mapred/local/1452579528457/linkzipf <- /script/HiBench-HiBench-5.0/workloads/join/prepare/linkzipf
2016-01-12 14:18:48,549 INFO  [main] mapred.LocalDistributedCacheManager (LocalDistributedCacheManager.java:setup(165)) - Localized hdfs://nameservice1/HiBench/Join/temp/linkzipf as file:/tmp/hadoop-root/mapred/local/1452579528457/linkzipf
2016-01-12 14:18:48,583 INFO  [main] mapreduce.Job (Job.java:submit(1311)) - The url to track the job: http://localhost:8080/
2016-01-12 14:18:48,584 INFO  [Thread-34] mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2016-01-12 14:18:48,585 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1356)) - Running job: job_local1441950054_0001
2016-01-12 14:18:48,586 INFO  [Thread-34] mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2016-01-12 14:18:48,589 INFO  [Thread-34] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:48,607 INFO  [Thread-34] mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2016-01-12 14:18:48,610 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000000_0
2016-01-12 14:18:48,631 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:48,640 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:48,645 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:17+3
2016-01-12 14:18:48,661 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:48,683 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:48,684 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:48,684 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:48,684 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:48,684 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:48,687 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:48,689 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:48,694 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:48,809 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:48,809 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:48,809 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:48,809 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1729978; bufvoid = 104857600
2016-01-12 14:18:48,809 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25734888(102939552); length = 479509/6553600
2016-01-12 14:18:49,177 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:49,180 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000000_0 is done. And is in the process of committing
2016-01-12 14:18:49,188 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:17+3
2016-01-12 14:18:49,188 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000000_0' done.
2016-01-12 14:18:49,188 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000000_0
2016-01-12 14:18:49,188 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000001_0
2016-01-12 14:18:49,189 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:49,190 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:49,191 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:20+3
2016-01-12 14:18:49,193 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:49,219 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:49,220 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:49,220 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:49,220 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:49,220 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:49,222 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:49,222 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:49,224 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:49,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:49,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:49,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:49,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1735278; bufvoid = 104857600
2016-01-12 14:18:49,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25735540(102942160); length = 478857/6553600
2016-01-12 14:18:49,495 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:49,496 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000001_0 is done. And is in the process of committing
2016-01-12 14:18:49,498 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:20+3
2016-01-12 14:18:49,499 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000001_0' done.
2016-01-12 14:18:49,499 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000001_0
2016-01-12 14:18:49,499 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000002_0
2016-01-12 14:18:49,500 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:49,500 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:49,501 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:23+3
2016-01-12 14:18:49,504 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:49,519 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:49,519 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:49,519 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:49,519 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:49,519 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:49,520 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:49,520 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:49,521 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:49,578 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:49,578 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:49,578 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:49,578 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1745362; bufvoid = 104857600
2016-01-12 14:18:49,578 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25734988(102939952); length = 479409/6553600
2016-01-12 14:18:49,587 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1377)) - Job job_local1441950054_0001 running in uber mode : false
2016-01-12 14:18:49,588 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1384)) -  map 17% reduce 0%
2016-01-12 14:18:49,778 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:49,779 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000002_0 is done. And is in the process of committing
2016-01-12 14:18:49,781 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:23+3
2016-01-12 14:18:49,781 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000002_0' done.
2016-01-12 14:18:49,782 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000002_0
2016-01-12 14:18:49,782 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000003_0
2016-01-12 14:18:49,783 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:49,783 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:49,784 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:1+2
2016-01-12 14:18:49,787 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:49,807 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:49,807 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:49,807 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:49,807 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:49,808 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:49,808 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:49,808 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:49,810 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:49,866 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:49,866 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:49,866 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:49,866 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1738153; bufvoid = 104857600
2016-01-12 14:18:49,866 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25735260(102941040); length = 479137/6553600
2016-01-12 14:18:50,054 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:50,054 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000003_0 is done. And is in the process of committing
2016-01-12 14:18:50,057 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:1+2
2016-01-12 14:18:50,057 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000003_0' done.
2016-01-12 14:18:50,057 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000003_0
2016-01-12 14:18:50,057 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000004_0
2016-01-12 14:18:50,058 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:50,058 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:50,059 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:3+2
2016-01-12 14:18:50,062 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:50,077 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:50,077 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:50,077 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:50,077 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:50,077 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:50,078 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:50,078 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:50,079 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:50,135 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:50,135 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:50,135 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:50,135 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1735886; bufvoid = 104857600
2016-01-12 14:18:50,135 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25735452(102941808); length = 478945/6553600
2016-01-12 14:18:50,325 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:50,326 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000004_0 is done. And is in the process of committing
2016-01-12 14:18:50,328 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:3+2
2016-01-12 14:18:50,328 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000004_0' done.
2016-01-12 14:18:50,328 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000004_0
2016-01-12 14:18:50,328 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000005_0
2016-01-12 14:18:50,330 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:50,330 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:50,331 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:5+2
2016-01-12 14:18:50,333 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:50,353 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:50,353 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:50,354 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:50,354 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:50,354 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:50,354 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:50,354 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:50,356 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:50,412 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:50,412 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:50,412 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:50,412 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1739603; bufvoid = 104857600
2016-01-12 14:18:50,412 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25735228(102940912); length = 479169/6553600
2016-01-12 14:18:50,590 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1384)) -  map 42% reduce 0%
2016-01-12 14:18:50,596 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:50,597 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000005_0 is done. And is in the process of committing
2016-01-12 14:18:50,599 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:5+2
2016-01-12 14:18:50,599 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000005_0' done.
2016-01-12 14:18:50,599 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000005_0
2016-01-12 14:18:50,600 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000006_0
2016-01-12 14:18:50,601 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:50,601 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:50,603 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:7+2
2016-01-12 14:18:50,605 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:50,634 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:50,634 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:50,634 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:50,634 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:50,635 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:50,635 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:50,635 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:50,637 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:50,693 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:50,693 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:50,693 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:50,693 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1739386; bufvoid = 104857600
2016-01-12 14:18:50,693 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25734820(102939280); length = 479577/6553600
2016-01-12 14:18:50,880 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:50,881 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000006_0 is done. And is in the process of committing
2016-01-12 14:18:50,883 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:7+2
2016-01-12 14:18:50,883 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000006_0' done.
2016-01-12 14:18:50,883 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000006_0
2016-01-12 14:18:50,884 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000007_0
2016-01-12 14:18:50,885 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:50,885 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:50,886 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:9+2
2016-01-12 14:18:50,890 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:50,921 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:50,921 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:50,921 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:50,921 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:50,921 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:50,922 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:50,922 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:50,923 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:50,979 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:50,979 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:50,979 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:50,979 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1744663; bufvoid = 104857600
2016-01-12 14:18:50,979 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25734892(102939568); length = 479505/6553600
2016-01-12 14:18:51,161 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:51,161 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000007_0 is done. And is in the process of committing
2016-01-12 14:18:51,163 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:9+2
2016-01-12 14:18:51,164 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000007_0' done.
2016-01-12 14:18:51,164 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000007_0
2016-01-12 14:18:51,164 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000008_0
2016-01-12 14:18:51,165 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:51,166 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:51,167 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:11+2
2016-01-12 14:18:51,169 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:51,199 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:51,200 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:51,200 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:51,200 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:51,200 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:51,200 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:51,201 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:51,202 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:51,260 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:51,260 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:51,260 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:51,260 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1742349; bufvoid = 104857600
2016-01-12 14:18:51,260 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25734892(102939568); length = 479505/6553600
2016-01-12 14:18:51,458 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:51,459 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000008_0 is done. And is in the process of committing
2016-01-12 14:18:51,461 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:11+2
2016-01-12 14:18:51,461 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000008_0' done.
2016-01-12 14:18:51,461 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000008_0
2016-01-12 14:18:51,461 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000009_0
2016-01-12 14:18:51,462 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:51,463 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:51,463 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:13+2
2016-01-12 14:18:51,466 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:51,497 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:51,497 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:51,497 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:51,497 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:51,498 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:51,498 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:51,498 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:51,500 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:51,556 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:51,556 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:51,556 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:51,556 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1739076; bufvoid = 104857600
2016-01-12 14:18:51,556 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25734812(102939248); length = 479585/6553600
2016-01-12 14:18:51,591 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1384)) -  map 75% reduce 0%
2016-01-12 14:18:51,744 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:51,745 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000009_0 is done. And is in the process of committing
2016-01-12 14:18:51,747 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:13+2
2016-01-12 14:18:51,747 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000009_0' done.
2016-01-12 14:18:51,747 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000009_0
2016-01-12 14:18:51,748 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000010_0
2016-01-12 14:18:51,749 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:51,749 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:51,750 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:15+2
2016-01-12 14:18:51,753 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:51,784 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:51,784 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:51,784 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:51,784 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:51,784 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:51,785 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:51,785 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:51,786 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:51,842 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:51,842 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:51,843 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:51,843 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1740015; bufvoid = 104857600
2016-01-12 14:18:51,843 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25735312(102941248); length = 479085/6553600
2016-01-12 14:18:52,051 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:52,052 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000010_0 is done. And is in the process of committing
2016-01-12 14:18:52,054 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:15+2
2016-01-12 14:18:52,054 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000010_0' done.
2016-01-12 14:18:52,054 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000010_0
2016-01-12 14:18:52,054 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1441950054_0001_m_000011_0
2016-01-12 14:18:52,055 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:52,056 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:52,056 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:0+1
2016-01-12 14:18:52,058 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:52,089 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:52,089 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:52,089 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:52,089 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:52,089 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:52,090 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:52,090 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HtmlCore (HtmlCore.java:printDict(66)) - WARNING: dict empty!!!
2016-01-12 14:18:52,092 INFO  [LocalJobRunner Map Task Executor #0] HiBench.HiveData$DummyToRankingsMapper (HiveData.java:map(175)) - still running: 0 of 10000
2016-01-12 14:18:52,148 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:52,148 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:52,149 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:52,149 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1736335; bufvoid = 104857600
2016-01-12 14:18:52,149 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 25735176(102940704); length = 479221/6553600
2016-01-12 14:18:52,346 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:52,347 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_m_000011_0 is done. And is in the process of committing
2016-01-12 14:18:52,349 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/temp/dummy:0+1
2016-01-12 14:18:52,349 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_m_000011_0' done.
2016-01-12 14:18:52,349 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1441950054_0001_m_000011_0
2016-01-12 14:18:52,350 INFO  [Thread-34] mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2016-01-12 14:18:52,356 INFO  [Thread-34] mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2016-01-12 14:18:52,356 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1441950054_0001_r_000000_0
2016-01-12 14:18:52,362 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:52,362 INFO  [pool-14-thread-1] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:52,365 INFO  [pool-14-thread-1] mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6aebf91b
2016-01-12 14:18:52,377 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(197)) - MergerManager: memoryLimit=659868864, maxSingleShuffleLimit=164967216, mergeThreshold=435513472, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2016-01-12 14:18:52,379 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1441950054_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2016-01-12 14:18:52,405 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000009_0 decomp: 313634 len: 313638 to MEMORY
2016-01-12 14:18:52,408 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313634 bytes from map-output for attempt_local1441950054_0001_m_000009_0
2016-01-12 14:18:52,409 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313634, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->313634
2016-01-12 14:18:52,411 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000002_0 decomp: 314797 len: 314801 to MEMORY
2016-01-12 14:18:52,412 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314797 bytes from map-output for attempt_local1441950054_0001_m_000002_0
2016-01-12 14:18:52,412 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314797, inMemoryMapOutputs.size() -> 2, commitMemory -> 313634, usedMemory ->628431
2016-01-12 14:18:52,413 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000008_0 decomp: 314721 len: 314725 to MEMORY
2016-01-12 14:18:52,414 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314721 bytes from map-output for attempt_local1441950054_0001_m_000008_0
2016-01-12 14:18:52,414 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314721, inMemoryMapOutputs.size() -> 3, commitMemory -> 628431, usedMemory ->943152
2016-01-12 14:18:52,415 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000005_0 decomp: 309421 len: 309425 to MEMORY
2016-01-12 14:18:52,416 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 309421 bytes from map-output for attempt_local1441950054_0001_m_000005_0
2016-01-12 14:18:52,416 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 309421, inMemoryMapOutputs.size() -> 4, commitMemory -> 943152, usedMemory ->1252573
2016-01-12 14:18:52,417 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000011_0 decomp: 311307 len: 311311 to MEMORY
2016-01-12 14:18:52,417 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 311307 bytes from map-output for attempt_local1441950054_0001_m_000011_0
2016-01-12 14:18:52,418 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 311307, inMemoryMapOutputs.size() -> 5, commitMemory -> 1252573, usedMemory ->1563880
2016-01-12 14:18:52,418 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000004_0 decomp: 312372 len: 312376 to MEMORY
2016-01-12 14:18:52,419 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312372 bytes from map-output for attempt_local1441950054_0001_m_000004_0
2016-01-12 14:18:52,419 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312372, inMemoryMapOutputs.size() -> 6, commitMemory -> 1563880, usedMemory ->1876252
2016-01-12 14:18:52,420 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000001_0 decomp: 312664 len: 312668 to MEMORY
2016-01-12 14:18:52,421 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312664 bytes from map-output for attempt_local1441950054_0001_m_000001_0
2016-01-12 14:18:52,421 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312664, inMemoryMapOutputs.size() -> 7, commitMemory -> 1876252, usedMemory ->2188916
2016-01-12 14:18:52,422 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000010_0 decomp: 313219 len: 313223 to MEMORY
2016-01-12 14:18:52,422 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313219 bytes from map-output for attempt_local1441950054_0001_m_000010_0
2016-01-12 14:18:52,423 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313219, inMemoryMapOutputs.size() -> 8, commitMemory -> 2188916, usedMemory ->2502135
2016-01-12 14:18:52,423 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000007_0 decomp: 315147 len: 315151 to MEMORY
2016-01-12 14:18:52,424 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 315147 bytes from map-output for attempt_local1441950054_0001_m_000007_0
2016-01-12 14:18:52,424 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 315147, inMemoryMapOutputs.size() -> 9, commitMemory -> 2502135, usedMemory ->2817282
2016-01-12 14:18:52,425 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000000_0 decomp: 312489 len: 312493 to MEMORY
2016-01-12 14:18:52,426 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312489 bytes from map-output for attempt_local1441950054_0001_m_000000_0
2016-01-12 14:18:52,426 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312489, inMemoryMapOutputs.size() -> 10, commitMemory -> 2817282, usedMemory ->3129771
2016-01-12 14:18:52,427 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000006_0 decomp: 311892 len: 311896 to MEMORY
2016-01-12 14:18:52,427 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 311892 bytes from map-output for attempt_local1441950054_0001_m_000006_0
2016-01-12 14:18:52,427 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 311892, inMemoryMapOutputs.size() -> 11, commitMemory -> 3129771, usedMemory ->3441663
2016-01-12 14:18:52,428 INFO  [localfetcher#1] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#1 about to shuffle output of map attempt_local1441950054_0001_m_000003_0 decomp: 309229 len: 309233 to MEMORY
2016-01-12 14:18:52,429 INFO  [localfetcher#1] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 309229 bytes from map-output for attempt_local1441950054_0001_m_000003_0
2016-01-12 14:18:52,429 INFO  [localfetcher#1] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 309229, inMemoryMapOutputs.size() -> 12, commitMemory -> 3441663, usedMemory ->3750892
2016-01-12 14:18:52,430 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2016-01-12 14:18:52,430 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:52,431 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(687)) - finalMerge called with 12 in-memory map-outputs and 0 on-disk map-outputs
2016-01-12 14:18:52,436 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 12 sorted segments
2016-01-12 14:18:52,437 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 12 segments left of total size: 3750772 bytes
2016-01-12 14:18:52,576 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(754)) - Merged 12 segments, 3750892 bytes to disk to satisfy reduce memory limit
2016-01-12 14:18:52,577 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(784)) - Merging 1 files, 3750874 bytes from disk
2016-01-12 14:18:52,577 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(799)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-12 14:18:52,577 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 1 sorted segments
2016-01-12 14:18:52,578 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 1 segments left of total size: 3750860 bytes
2016-01-12 14:18:52,578 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:52,579 INFO  [pool-14-thread-1] Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1174)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2016-01-12 14:18:52,592 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1384)) -  map 100% reduce 0%
2016-01-12 14:18:52,596 INFO  [pool-14-thread-1] zlib.ZlibFactory (ZlibFactory.java:<clinit>(49)) - Successfully loaded & initialized native-zlib library
2016-01-12 14:18:52,596 INFO  [pool-14-thread-1] compress.CodecPool (CodecPool.java:getCompressor(153)) - Got brand-new compressor [.deflate]
2016-01-12 14:18:52,865 INFO  [pool-14-thread-1] HiBench.HiveData$GenerateRankingsReducer (HiveData.java:close(260)) - pid: 0, 0 erros, 0 missed
2016-01-12 14:18:52,896 INFO  [pool-14-thread-1] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_r_000000_0 is done. And is in the process of committing
2016-01-12 14:18:52,898 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:52,898 INFO  [pool-14-thread-1] mapred.Task (Task.java:commit(1164)) - Task attempt_local1441950054_0001_r_000000_0 is allowed to commit now
2016-01-12 14:18:52,904 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:commitTask(482)) - Saved output of task 'attempt_local1441950054_0001_r_000000_0' to hdfs://nameservice1/HiBench/Join/Input/rankings/_temporary/0/task_local1441950054_0001_r_000000
2016-01-12 14:18:52,905 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2016-01-12 14:18:52,905 INFO  [pool-14-thread-1] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_r_000000_0' done.
2016-01-12 14:18:52,905 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1441950054_0001_r_000000_0
2016-01-12 14:18:52,906 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1441950054_0001_r_000001_0
2016-01-12 14:18:52,907 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:52,908 INFO  [pool-14-thread-1] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:52,908 INFO  [pool-14-thread-1] mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@42a85f1d
2016-01-12 14:18:52,909 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(197)) - MergerManager: memoryLimit=652528832, maxSingleShuffleLimit=163132208, mergeThreshold=430669056, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2016-01-12 14:18:52,909 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1441950054_0001_r_000001_0 Thread started: EventFetcher for fetching Map Completion Events
2016-01-12 14:18:52,911 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000009_0 decomp: 312286 len: 312290 to MEMORY
2016-01-12 14:18:52,911 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312286 bytes from map-output for attempt_local1441950054_0001_m_000009_0
2016-01-12 14:18:52,912 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312286, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->312286
2016-01-12 14:18:52,913 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000002_0 decomp: 314309 len: 314313 to MEMORY
2016-01-12 14:18:52,913 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314309 bytes from map-output for attempt_local1441950054_0001_m_000002_0
2016-01-12 14:18:52,913 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314309, inMemoryMapOutputs.size() -> 2, commitMemory -> 312286, usedMemory ->626595
2016-01-12 14:18:52,914 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000008_0 decomp: 314019 len: 314023 to MEMORY
2016-01-12 14:18:52,915 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314019 bytes from map-output for attempt_local1441950054_0001_m_000008_0
2016-01-12 14:18:52,915 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314019, inMemoryMapOutputs.size() -> 3, commitMemory -> 626595, usedMemory ->940614
2016-01-12 14:18:52,916 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000005_0 decomp: 313319 len: 313323 to MEMORY
2016-01-12 14:18:52,916 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313319 bytes from map-output for attempt_local1441950054_0001_m_000005_0
2016-01-12 14:18:52,916 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313319, inMemoryMapOutputs.size() -> 4, commitMemory -> 940614, usedMemory ->1253933
2016-01-12 14:18:52,917 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000011_0 decomp: 310644 len: 310648 to MEMORY
2016-01-12 14:18:52,917 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 310644 bytes from map-output for attempt_local1441950054_0001_m_000011_0
2016-01-12 14:18:52,917 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 310644, inMemoryMapOutputs.size() -> 5, commitMemory -> 1253933, usedMemory ->1564577
2016-01-12 14:18:52,918 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000004_0 decomp: 310143 len: 310147 to MEMORY
2016-01-12 14:18:52,919 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 310143 bytes from map-output for attempt_local1441950054_0001_m_000004_0
2016-01-12 14:18:52,919 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 310143, inMemoryMapOutputs.size() -> 6, commitMemory -> 1564577, usedMemory ->1874720
2016-01-12 14:18:52,919 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000001_0 decomp: 313523 len: 313527 to MEMORY
2016-01-12 14:18:52,920 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313523 bytes from map-output for attempt_local1441950054_0001_m_000001_0
2016-01-12 14:18:52,920 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313523, inMemoryMapOutputs.size() -> 7, commitMemory -> 1874720, usedMemory ->2188243
2016-01-12 14:18:52,921 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000010_0 decomp: 314542 len: 314546 to MEMORY
2016-01-12 14:18:52,921 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314542 bytes from map-output for attempt_local1441950054_0001_m_000010_0
2016-01-12 14:18:52,921 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314542, inMemoryMapOutputs.size() -> 8, commitMemory -> 2188243, usedMemory ->2502785
2016-01-12 14:18:52,922 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000007_0 decomp: 314469 len: 314473 to MEMORY
2016-01-12 14:18:52,923 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314469 bytes from map-output for attempt_local1441950054_0001_m_000007_0
2016-01-12 14:18:52,923 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314469, inMemoryMapOutputs.size() -> 9, commitMemory -> 2502785, usedMemory ->2817254
2016-01-12 14:18:52,924 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000000_0 decomp: 310761 len: 310765 to MEMORY
2016-01-12 14:18:52,924 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 310761 bytes from map-output for attempt_local1441950054_0001_m_000000_0
2016-01-12 14:18:52,924 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 310761, inMemoryMapOutputs.size() -> 10, commitMemory -> 2817254, usedMemory ->3128015
2016-01-12 14:18:52,925 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000006_0 decomp: 311850 len: 311854 to MEMORY
2016-01-12 14:18:52,926 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 311850 bytes from map-output for attempt_local1441950054_0001_m_000006_0
2016-01-12 14:18:52,926 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 311850, inMemoryMapOutputs.size() -> 11, commitMemory -> 3128015, usedMemory ->3439865
2016-01-12 14:18:52,927 INFO  [localfetcher#2] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#2 about to shuffle output of map attempt_local1441950054_0001_m_000003_0 decomp: 313130 len: 313134 to MEMORY
2016-01-12 14:18:52,927 INFO  [localfetcher#2] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313130 bytes from map-output for attempt_local1441950054_0001_m_000003_0
2016-01-12 14:18:52,927 INFO  [localfetcher#2] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313130, inMemoryMapOutputs.size() -> 12, commitMemory -> 3439865, usedMemory ->3752995
2016-01-12 14:18:52,928 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2016-01-12 14:18:52,928 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:52,928 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(687)) - finalMerge called with 12 in-memory map-outputs and 0 on-disk map-outputs
2016-01-12 14:18:52,929 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 12 sorted segments
2016-01-12 14:18:52,930 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 12 segments left of total size: 3752875 bytes
2016-01-12 14:18:53,035 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(754)) - Merged 12 segments, 3752995 bytes to disk to satisfy reduce memory limit
2016-01-12 14:18:53,035 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(784)) - Merging 1 files, 3752977 bytes from disk
2016-01-12 14:18:53,036 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(799)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-12 14:18:53,036 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 1 sorted segments
2016-01-12 14:18:53,036 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 1 segments left of total size: 3752963 bytes
2016-01-12 14:18:53,036 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:53,270 INFO  [pool-14-thread-1] HiBench.HiveData$GenerateRankingsReducer (HiveData.java:close(260)) - pid: 1, 0 erros, 0 missed
2016-01-12 14:18:53,301 INFO  [pool-14-thread-1] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_r_000001_0 is done. And is in the process of committing
2016-01-12 14:18:53,303 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:53,303 INFO  [pool-14-thread-1] mapred.Task (Task.java:commit(1164)) - Task attempt_local1441950054_0001_r_000001_0 is allowed to commit now
2016-01-12 14:18:53,305 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:commitTask(482)) - Saved output of task 'attempt_local1441950054_0001_r_000001_0' to hdfs://nameservice1/HiBench/Join/Input/rankings/_temporary/0/task_local1441950054_0001_r_000001
2016-01-12 14:18:53,305 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2016-01-12 14:18:53,306 INFO  [pool-14-thread-1] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_r_000001_0' done.
2016-01-12 14:18:53,306 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1441950054_0001_r_000001_0
2016-01-12 14:18:53,306 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1441950054_0001_r_000002_0
2016-01-12 14:18:53,307 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:53,307 INFO  [pool-14-thread-1] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:53,307 INFO  [pool-14-thread-1] mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@33113f31
2016-01-12 14:18:53,308 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(197)) - MergerManager: memoryLimit=652528832, maxSingleShuffleLimit=163132208, mergeThreshold=430669056, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2016-01-12 14:18:53,308 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1441950054_0001_r_000002_0 Thread started: EventFetcher for fetching Map Completion Events
2016-01-12 14:18:53,310 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000009_0 decomp: 312772 len: 312776 to MEMORY
2016-01-12 14:18:53,310 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312772 bytes from map-output for attempt_local1441950054_0001_m_000009_0
2016-01-12 14:18:53,310 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312772, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->312772
2016-01-12 14:18:53,311 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000002_0 decomp: 312863 len: 312867 to MEMORY
2016-01-12 14:18:53,312 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312863 bytes from map-output for attempt_local1441950054_0001_m_000002_0
2016-01-12 14:18:53,312 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312863, inMemoryMapOutputs.size() -> 2, commitMemory -> 312772, usedMemory ->625635
2016-01-12 14:18:53,313 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000008_0 decomp: 314638 len: 314642 to MEMORY
2016-01-12 14:18:53,313 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314638 bytes from map-output for attempt_local1441950054_0001_m_000008_0
2016-01-12 14:18:53,313 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314638, inMemoryMapOutputs.size() -> 3, commitMemory -> 625635, usedMemory ->940273
2016-01-12 14:18:53,314 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000005_0 decomp: 314501 len: 314505 to MEMORY
2016-01-12 14:18:53,315 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314501 bytes from map-output for attempt_local1441950054_0001_m_000005_0
2016-01-12 14:18:53,315 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314501, inMemoryMapOutputs.size() -> 4, commitMemory -> 940273, usedMemory ->1254774
2016-01-12 14:18:53,316 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000011_0 decomp: 311237 len: 311241 to MEMORY
2016-01-12 14:18:53,316 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 311237 bytes from map-output for attempt_local1441950054_0001_m_000011_0
2016-01-12 14:18:53,317 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 311237, inMemoryMapOutputs.size() -> 5, commitMemory -> 1254774, usedMemory ->1566011
2016-01-12 14:18:53,318 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000004_0 decomp: 311876 len: 311880 to MEMORY
2016-01-12 14:18:53,318 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 311876 bytes from map-output for attempt_local1441950054_0001_m_000004_0
2016-01-12 14:18:53,318 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 311876, inMemoryMapOutputs.size() -> 6, commitMemory -> 1566011, usedMemory ->1877887
2016-01-12 14:18:53,319 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000001_0 decomp: 313816 len: 313820 to MEMORY
2016-01-12 14:18:53,319 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313816 bytes from map-output for attempt_local1441950054_0001_m_000001_0
2016-01-12 14:18:53,320 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313816, inMemoryMapOutputs.size() -> 7, commitMemory -> 1877887, usedMemory ->2191703
2016-01-12 14:18:53,321 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000010_0 decomp: 313533 len: 313537 to MEMORY
2016-01-12 14:18:53,321 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313533 bytes from map-output for attempt_local1441950054_0001_m_000010_0
2016-01-12 14:18:53,321 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313533, inMemoryMapOutputs.size() -> 8, commitMemory -> 2191703, usedMemory ->2505236
2016-01-12 14:18:53,322 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000007_0 decomp: 314294 len: 314298 to MEMORY
2016-01-12 14:18:53,322 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314294 bytes from map-output for attempt_local1441950054_0001_m_000007_0
2016-01-12 14:18:53,323 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314294, inMemoryMapOutputs.size() -> 9, commitMemory -> 2505236, usedMemory ->2819530
2016-01-12 14:18:53,323 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000000_0 decomp: 312120 len: 312124 to MEMORY
2016-01-12 14:18:53,324 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312120 bytes from map-output for attempt_local1441950054_0001_m_000000_0
2016-01-12 14:18:53,324 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312120, inMemoryMapOutputs.size() -> 10, commitMemory -> 2819530, usedMemory ->3131650
2016-01-12 14:18:53,325 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000006_0 decomp: 313352 len: 313356 to MEMORY
2016-01-12 14:18:53,326 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313352 bytes from map-output for attempt_local1441950054_0001_m_000006_0
2016-01-12 14:18:53,326 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313352, inMemoryMapOutputs.size() -> 11, commitMemory -> 3131650, usedMemory ->3445002
2016-01-12 14:18:53,327 INFO  [localfetcher#3] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#3 about to shuffle output of map attempt_local1441950054_0001_m_000003_0 decomp: 313274 len: 313278 to MEMORY
2016-01-12 14:18:53,327 INFO  [localfetcher#3] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313274 bytes from map-output for attempt_local1441950054_0001_m_000003_0
2016-01-12 14:18:53,327 INFO  [localfetcher#3] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313274, inMemoryMapOutputs.size() -> 12, commitMemory -> 3445002, usedMemory ->3758276
2016-01-12 14:18:53,327 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2016-01-12 14:18:53,328 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:53,328 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(687)) - finalMerge called with 12 in-memory map-outputs and 0 on-disk map-outputs
2016-01-12 14:18:53,329 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 12 sorted segments
2016-01-12 14:18:53,329 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 12 segments left of total size: 3758156 bytes
2016-01-12 14:18:53,436 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(754)) - Merged 12 segments, 3758276 bytes to disk to satisfy reduce memory limit
2016-01-12 14:18:53,436 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(784)) - Merging 1 files, 3758258 bytes from disk
2016-01-12 14:18:53,436 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(799)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-12 14:18:53,436 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 1 sorted segments
2016-01-12 14:18:53,437 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 1 segments left of total size: 3758244 bytes
2016-01-12 14:18:53,437 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:53,592 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1384)) -  map 100% reduce 33%
2016-01-12 14:18:53,641 INFO  [pool-14-thread-1] HiBench.HiveData$GenerateRankingsReducer (HiveData.java:close(260)) - pid: 2, 0 erros, 0 missed
2016-01-12 14:18:53,674 INFO  [pool-14-thread-1] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_r_000002_0 is done. And is in the process of committing
2016-01-12 14:18:53,675 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:53,675 INFO  [pool-14-thread-1] mapred.Task (Task.java:commit(1164)) - Task attempt_local1441950054_0001_r_000002_0 is allowed to commit now
2016-01-12 14:18:53,678 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:commitTask(482)) - Saved output of task 'attempt_local1441950054_0001_r_000002_0' to hdfs://nameservice1/HiBench/Join/Input/rankings/_temporary/0/task_local1441950054_0001_r_000002
2016-01-12 14:18:53,678 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2016-01-12 14:18:53,678 INFO  [pool-14-thread-1] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_r_000002_0' done.
2016-01-12 14:18:53,678 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1441950054_0001_r_000002_0
2016-01-12 14:18:53,678 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1441950054_0001_r_000003_0
2016-01-12 14:18:53,679 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:53,680 INFO  [pool-14-thread-1] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:53,680 INFO  [pool-14-thread-1] mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@3901c0c9
2016-01-12 14:18:53,680 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(197)) - MergerManager: memoryLimit=652528832, maxSingleShuffleLimit=163132208, mergeThreshold=430669056, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2016-01-12 14:18:53,681 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1441950054_0001_r_000003_0 Thread started: EventFetcher for fetching Map Completion Events
2016-01-12 14:18:53,682 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000009_0 decomp: 313992 len: 313996 to MEMORY
2016-01-12 14:18:53,682 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313992 bytes from map-output for attempt_local1441950054_0001_m_000009_0
2016-01-12 14:18:53,682 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313992, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->313992
2016-01-12 14:18:53,683 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000002_0 decomp: 316586 len: 316590 to MEMORY
2016-01-12 14:18:53,684 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 316586 bytes from map-output for attempt_local1441950054_0001_m_000002_0
2016-01-12 14:18:53,684 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 316586, inMemoryMapOutputs.size() -> 2, commitMemory -> 313992, usedMemory ->630578
2016-01-12 14:18:53,684 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000008_0 decomp: 313758 len: 313762 to MEMORY
2016-01-12 14:18:53,685 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313758 bytes from map-output for attempt_local1441950054_0001_m_000008_0
2016-01-12 14:18:53,685 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313758, inMemoryMapOutputs.size() -> 3, commitMemory -> 630578, usedMemory ->944336
2016-01-12 14:18:53,686 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000005_0 decomp: 313053 len: 313057 to MEMORY
2016-01-12 14:18:53,686 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313053 bytes from map-output for attempt_local1441950054_0001_m_000005_0
2016-01-12 14:18:53,686 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313053, inMemoryMapOutputs.size() -> 4, commitMemory -> 944336, usedMemory ->1257389
2016-01-12 14:18:53,687 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000011_0 decomp: 308976 len: 308980 to MEMORY
2016-01-12 14:18:53,687 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 308976 bytes from map-output for attempt_local1441950054_0001_m_000011_0
2016-01-12 14:18:53,687 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 308976, inMemoryMapOutputs.size() -> 5, commitMemory -> 1257389, usedMemory ->1566365
2016-01-12 14:18:53,688 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000004_0 decomp: 309770 len: 309774 to MEMORY
2016-01-12 14:18:53,688 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 309770 bytes from map-output for attempt_local1441950054_0001_m_000004_0
2016-01-12 14:18:53,688 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 309770, inMemoryMapOutputs.size() -> 6, commitMemory -> 1566365, usedMemory ->1876135
2016-01-12 14:18:53,689 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000001_0 decomp: 312347 len: 312351 to MEMORY
2016-01-12 14:18:53,689 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312347 bytes from map-output for attempt_local1441950054_0001_m_000001_0
2016-01-12 14:18:53,690 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312347, inMemoryMapOutputs.size() -> 7, commitMemory -> 1876135, usedMemory ->2188482
2016-01-12 14:18:53,690 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000010_0 decomp: 312914 len: 312918 to MEMORY
2016-01-12 14:18:53,691 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312914 bytes from map-output for attempt_local1441950054_0001_m_000010_0
2016-01-12 14:18:53,691 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312914, inMemoryMapOutputs.size() -> 8, commitMemory -> 2188482, usedMemory ->2501396
2016-01-12 14:18:53,692 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000007_0 decomp: 314267 len: 314271 to MEMORY
2016-01-12 14:18:53,693 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314267 bytes from map-output for attempt_local1441950054_0001_m_000007_0
2016-01-12 14:18:53,693 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314267, inMemoryMapOutputs.size() -> 9, commitMemory -> 2501396, usedMemory ->2815663
2016-01-12 14:18:53,694 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000000_0 decomp: 313833 len: 313837 to MEMORY
2016-01-12 14:18:53,694 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313833 bytes from map-output for attempt_local1441950054_0001_m_000000_0
2016-01-12 14:18:53,694 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313833, inMemoryMapOutputs.size() -> 10, commitMemory -> 2815663, usedMemory ->3129496
2016-01-12 14:18:53,695 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000006_0 decomp: 314731 len: 314735 to MEMORY
2016-01-12 14:18:53,696 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314731 bytes from map-output for attempt_local1441950054_0001_m_000006_0
2016-01-12 14:18:53,696 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314731, inMemoryMapOutputs.size() -> 11, commitMemory -> 3129496, usedMemory ->3444227
2016-01-12 14:18:53,696 INFO  [localfetcher#4] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#4 about to shuffle output of map attempt_local1441950054_0001_m_000003_0 decomp: 312113 len: 312117 to MEMORY
2016-01-12 14:18:53,697 INFO  [localfetcher#4] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312113 bytes from map-output for attempt_local1441950054_0001_m_000003_0
2016-01-12 14:18:53,697 INFO  [localfetcher#4] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312113, inMemoryMapOutputs.size() -> 12, commitMemory -> 3444227, usedMemory ->3756340
2016-01-12 14:18:53,697 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2016-01-12 14:18:53,697 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:53,698 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(687)) - finalMerge called with 12 in-memory map-outputs and 0 on-disk map-outputs
2016-01-12 14:18:53,698 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 12 sorted segments
2016-01-12 14:18:53,699 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 12 segments left of total size: 3756220 bytes
2016-01-12 14:18:53,806 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(754)) - Merged 12 segments, 3756340 bytes to disk to satisfy reduce memory limit
2016-01-12 14:18:53,806 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(784)) - Merging 1 files, 3756322 bytes from disk
2016-01-12 14:18:53,806 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(799)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-12 14:18:53,806 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 1 sorted segments
2016-01-12 14:18:53,806 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 1 segments left of total size: 3756308 bytes
2016-01-12 14:18:53,807 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:53,987 INFO  [pool-14-thread-1] HiBench.HiveData$GenerateRankingsReducer (HiveData.java:close(260)) - pid: 3, 0 erros, 0 missed
2016-01-12 14:18:54,018 INFO  [pool-14-thread-1] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_r_000003_0 is done. And is in the process of committing
2016-01-12 14:18:54,019 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:54,019 INFO  [pool-14-thread-1] mapred.Task (Task.java:commit(1164)) - Task attempt_local1441950054_0001_r_000003_0 is allowed to commit now
2016-01-12 14:18:54,021 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:commitTask(482)) - Saved output of task 'attempt_local1441950054_0001_r_000003_0' to hdfs://nameservice1/HiBench/Join/Input/rankings/_temporary/0/task_local1441950054_0001_r_000003
2016-01-12 14:18:54,022 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2016-01-12 14:18:54,022 INFO  [pool-14-thread-1] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_r_000003_0' done.
2016-01-12 14:18:54,022 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1441950054_0001_r_000003_0
2016-01-12 14:18:54,022 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1441950054_0001_r_000004_0
2016-01-12 14:18:54,023 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:54,023 INFO  [pool-14-thread-1] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:54,023 INFO  [pool-14-thread-1] mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@7d6442c2
2016-01-12 14:18:54,024 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(197)) - MergerManager: memoryLimit=656932864, maxSingleShuffleLimit=164233216, mergeThreshold=433575712, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2016-01-12 14:18:54,024 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1441950054_0001_r_000004_0 Thread started: EventFetcher for fetching Map Completion Events
2016-01-12 14:18:54,025 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000009_0 decomp: 313788 len: 313792 to MEMORY
2016-01-12 14:18:54,026 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313788 bytes from map-output for attempt_local1441950054_0001_m_000009_0
2016-01-12 14:18:54,026 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313788, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->313788
2016-01-12 14:18:54,027 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000002_0 decomp: 314740 len: 314744 to MEMORY
2016-01-12 14:18:54,027 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314740 bytes from map-output for attempt_local1441950054_0001_m_000002_0
2016-01-12 14:18:54,027 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314740, inMemoryMapOutputs.size() -> 2, commitMemory -> 313788, usedMemory ->628528
2016-01-12 14:18:54,028 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000008_0 decomp: 314814 len: 314818 to MEMORY
2016-01-12 14:18:54,028 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314814 bytes from map-output for attempt_local1441950054_0001_m_000008_0
2016-01-12 14:18:54,028 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314814, inMemoryMapOutputs.size() -> 3, commitMemory -> 628528, usedMemory ->943342
2016-01-12 14:18:54,029 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000005_0 decomp: 310960 len: 310964 to MEMORY
2016-01-12 14:18:54,029 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 310960 bytes from map-output for attempt_local1441950054_0001_m_000005_0
2016-01-12 14:18:54,029 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 310960, inMemoryMapOutputs.size() -> 4, commitMemory -> 943342, usedMemory ->1254302
2016-01-12 14:18:54,030 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000011_0 decomp: 313173 len: 313177 to MEMORY
2016-01-12 14:18:54,030 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313173 bytes from map-output for attempt_local1441950054_0001_m_000011_0
2016-01-12 14:18:54,030 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313173, inMemoryMapOutputs.size() -> 5, commitMemory -> 1254302, usedMemory ->1567475
2016-01-12 14:18:54,031 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000004_0 decomp: 313694 len: 313698 to MEMORY
2016-01-12 14:18:54,031 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313694 bytes from map-output for attempt_local1441950054_0001_m_000004_0
2016-01-12 14:18:54,032 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313694, inMemoryMapOutputs.size() -> 6, commitMemory -> 1567475, usedMemory ->1881169
2016-01-12 14:18:54,032 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000001_0 decomp: 312620 len: 312624 to MEMORY
2016-01-12 14:18:54,033 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312620 bytes from map-output for attempt_local1441950054_0001_m_000001_0
2016-01-12 14:18:54,033 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312620, inMemoryMapOutputs.size() -> 7, commitMemory -> 1881169, usedMemory ->2193789
2016-01-12 14:18:54,033 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000010_0 decomp: 313909 len: 313913 to MEMORY
2016-01-12 14:18:54,034 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313909 bytes from map-output for attempt_local1441950054_0001_m_000010_0
2016-01-12 14:18:54,034 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313909, inMemoryMapOutputs.size() -> 8, commitMemory -> 2193789, usedMemory ->2507698
2016-01-12 14:18:54,035 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000007_0 decomp: 315047 len: 315051 to MEMORY
2016-01-12 14:18:54,035 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 315047 bytes from map-output for attempt_local1441950054_0001_m_000007_0
2016-01-12 14:18:54,035 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 315047, inMemoryMapOutputs.size() -> 9, commitMemory -> 2507698, usedMemory ->2822745
2016-01-12 14:18:54,036 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000000_0 decomp: 311092 len: 311096 to MEMORY
2016-01-12 14:18:54,036 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 311092 bytes from map-output for attempt_local1441950054_0001_m_000000_0
2016-01-12 14:18:54,036 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 311092, inMemoryMapOutputs.size() -> 10, commitMemory -> 2822745, usedMemory ->3133837
2016-01-12 14:18:54,037 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000006_0 decomp: 314606 len: 314610 to MEMORY
2016-01-12 14:18:54,037 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314606 bytes from map-output for attempt_local1441950054_0001_m_000006_0
2016-01-12 14:18:54,037 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314606, inMemoryMapOutputs.size() -> 11, commitMemory -> 3133837, usedMemory ->3448443
2016-01-12 14:18:54,038 INFO  [localfetcher#5] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#5 about to shuffle output of map attempt_local1441950054_0001_m_000003_0 decomp: 310208 len: 310212 to MEMORY
2016-01-12 14:18:54,038 INFO  [localfetcher#5] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 310208 bytes from map-output for attempt_local1441950054_0001_m_000003_0
2016-01-12 14:18:54,038 INFO  [localfetcher#5] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 310208, inMemoryMapOutputs.size() -> 12, commitMemory -> 3448443, usedMemory ->3758651
2016-01-12 14:18:54,039 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2016-01-12 14:18:54,039 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:54,039 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(687)) - finalMerge called with 12 in-memory map-outputs and 0 on-disk map-outputs
2016-01-12 14:18:54,040 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 12 sorted segments
2016-01-12 14:18:54,040 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 12 segments left of total size: 3758531 bytes
2016-01-12 14:18:54,150 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(754)) - Merged 12 segments, 3758651 bytes to disk to satisfy reduce memory limit
2016-01-12 14:18:54,151 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(784)) - Merging 1 files, 3758633 bytes from disk
2016-01-12 14:18:54,151 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(799)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-12 14:18:54,151 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 1 sorted segments
2016-01-12 14:18:54,151 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 1 segments left of total size: 3758619 bytes
2016-01-12 14:18:54,151 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:54,319 INFO  [pool-14-thread-1] HiBench.HiveData$GenerateRankingsReducer (HiveData.java:close(260)) - pid: 4, 0 erros, 0 missed
2016-01-12 14:18:54,350 INFO  [pool-14-thread-1] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_r_000004_0 is done. And is in the process of committing
2016-01-12 14:18:54,351 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:54,351 INFO  [pool-14-thread-1] mapred.Task (Task.java:commit(1164)) - Task attempt_local1441950054_0001_r_000004_0 is allowed to commit now
2016-01-12 14:18:54,354 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:commitTask(482)) - Saved output of task 'attempt_local1441950054_0001_r_000004_0' to hdfs://nameservice1/HiBench/Join/Input/rankings/_temporary/0/task_local1441950054_0001_r_000004
2016-01-12 14:18:54,354 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2016-01-12 14:18:54,354 INFO  [pool-14-thread-1] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_r_000004_0' done.
2016-01-12 14:18:54,354 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1441950054_0001_r_000004_0
2016-01-12 14:18:54,354 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1441950054_0001_r_000005_0
2016-01-12 14:18:54,355 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:54,355 INFO  [pool-14-thread-1] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:54,356 INFO  [pool-14-thread-1] mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@33eaedc8
2016-01-12 14:18:54,356 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(197)) - MergerManager: memoryLimit=656932864, maxSingleShuffleLimit=164233216, mergeThreshold=433575712, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2016-01-12 14:18:54,357 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1441950054_0001_r_000005_0 Thread started: EventFetcher for fetching Map Completion Events
2016-01-12 14:18:54,358 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000009_0 decomp: 315236 len: 315240 to MEMORY
2016-01-12 14:18:54,358 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 315236 bytes from map-output for attempt_local1441950054_0001_m_000009_0
2016-01-12 14:18:54,358 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 315236, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->315236
2016-01-12 14:18:54,359 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000002_0 decomp: 314996 len: 315000 to MEMORY
2016-01-12 14:18:54,359 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314996 bytes from map-output for attempt_local1441950054_0001_m_000002_0
2016-01-12 14:18:54,359 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314996, inMemoryMapOutputs.size() -> 2, commitMemory -> 315236, usedMemory ->630232
2016-01-12 14:18:54,360 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000008_0 decomp: 313497 len: 313501 to MEMORY
2016-01-12 14:18:54,360 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313497 bytes from map-output for attempt_local1441950054_0001_m_000008_0
2016-01-12 14:18:54,361 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313497, inMemoryMapOutputs.size() -> 3, commitMemory -> 630232, usedMemory ->943729
2016-01-12 14:18:54,361 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000005_0 decomp: 312424 len: 312428 to MEMORY
2016-01-12 14:18:54,362 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312424 bytes from map-output for attempt_local1441950054_0001_m_000005_0
2016-01-12 14:18:54,362 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312424, inMemoryMapOutputs.size() -> 4, commitMemory -> 943729, usedMemory ->1256153
2016-01-12 14:18:54,362 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000011_0 decomp: 310776 len: 310780 to MEMORY
2016-01-12 14:18:54,363 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 310776 bytes from map-output for attempt_local1441950054_0001_m_000011_0
2016-01-12 14:18:54,363 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 310776, inMemoryMapOutputs.size() -> 5, commitMemory -> 1256153, usedMemory ->1566929
2016-01-12 14:18:54,363 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000004_0 decomp: 311631 len: 311635 to MEMORY
2016-01-12 14:18:54,364 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 311631 bytes from map-output for attempt_local1441950054_0001_m_000004_0
2016-01-12 14:18:54,364 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 311631, inMemoryMapOutputs.size() -> 6, commitMemory -> 1566929, usedMemory ->1878560
2016-01-12 14:18:54,364 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000001_0 decomp: 312774 len: 312778 to MEMORY
2016-01-12 14:18:54,365 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312774 bytes from map-output for attempt_local1441950054_0001_m_000001_0
2016-01-12 14:18:54,365 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312774, inMemoryMapOutputs.size() -> 7, commitMemory -> 1878560, usedMemory ->2191334
2016-01-12 14:18:54,365 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000010_0 decomp: 314423 len: 314427 to MEMORY
2016-01-12 14:18:54,366 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314423 bytes from map-output for attempt_local1441950054_0001_m_000010_0
2016-01-12 14:18:54,366 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314423, inMemoryMapOutputs.size() -> 8, commitMemory -> 2191334, usedMemory ->2505757
2016-01-12 14:18:54,367 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000007_0 decomp: 314284 len: 314288 to MEMORY
2016-01-12 14:18:54,367 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 314284 bytes from map-output for attempt_local1441950054_0001_m_000007_0
2016-01-12 14:18:54,367 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 314284, inMemoryMapOutputs.size() -> 9, commitMemory -> 2505757, usedMemory ->2820041
2016-01-12 14:18:54,368 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000000_0 decomp: 312288 len: 312292 to MEMORY
2016-01-12 14:18:54,368 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 312288 bytes from map-output for attempt_local1441950054_0001_m_000000_0
2016-01-12 14:18:54,368 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 312288, inMemoryMapOutputs.size() -> 10, commitMemory -> 2820041, usedMemory ->3132329
2016-01-12 14:18:54,369 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000006_0 decomp: 313086 len: 313090 to MEMORY
2016-01-12 14:18:54,369 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 313086 bytes from map-output for attempt_local1441950054_0001_m_000006_0
2016-01-12 14:18:54,370 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 313086, inMemoryMapOutputs.size() -> 11, commitMemory -> 3132329, usedMemory ->3445415
2016-01-12 14:18:54,370 INFO  [localfetcher#6] reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(141)) - localfetcher#6 about to shuffle output of map attempt_local1441950054_0001_m_000003_0 decomp: 310980 len: 310984 to MEMORY
2016-01-12 14:18:54,371 INFO  [localfetcher#6] reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 310980 bytes from map-output for attempt_local1441950054_0001_m_000003_0
2016-01-12 14:18:54,371 INFO  [localfetcher#6] reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(315)) - closeInMemoryFile -> map-output of size: 310980, inMemoryMapOutputs.size() -> 12, commitMemory -> 3445415, usedMemory ->3756395
2016-01-12 14:18:54,371 INFO  [EventFetcher for fetching Map Completion Events] reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2016-01-12 14:18:54,371 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:54,372 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(687)) - finalMerge called with 12 in-memory map-outputs and 0 on-disk map-outputs
2016-01-12 14:18:54,372 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 12 sorted segments
2016-01-12 14:18:54,373 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 12 segments left of total size: 3756275 bytes
2016-01-12 14:18:54,481 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(754)) - Merged 12 segments, 3756395 bytes to disk to satisfy reduce memory limit
2016-01-12 14:18:54,481 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(784)) - Merging 1 files, 3756377 bytes from disk
2016-01-12 14:18:54,481 INFO  [pool-14-thread-1] reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(799)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-12 14:18:54,481 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(606)) - Merging 1 sorted segments
2016-01-12 14:18:54,481 INFO  [pool-14-thread-1] mapred.Merger (Merger.java:merge(705)) - Down to the last merge-pass, with 1 segments left of total size: 3756363 bytes
2016-01-12 14:18:54,481 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:54,593 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1384)) -  map 100% reduce 83%
2016-01-12 14:18:54,649 INFO  [pool-14-thread-1] HiBench.HiveData$GenerateRankingsReducer (HiveData.java:close(260)) - pid: 5, 0 erros, 0 missed
2016-01-12 14:18:54,680 INFO  [pool-14-thread-1] mapred.Task (Task.java:done(1003)) - Task:attempt_local1441950054_0001_r_000005_0 is done. And is in the process of committing
2016-01-12 14:18:54,681 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 12 / 12 copied.
2016-01-12 14:18:54,681 INFO  [pool-14-thread-1] mapred.Task (Task.java:commit(1164)) - Task attempt_local1441950054_0001_r_000005_0 is allowed to commit now
2016-01-12 14:18:54,683 INFO  [pool-14-thread-1] output.FileOutputCommitter (FileOutputCommitter.java:commitTask(482)) - Saved output of task 'attempt_local1441950054_0001_r_000005_0' to hdfs://nameservice1/HiBench/Join/Input/rankings/_temporary/0/task_local1441950054_0001_r_000005
2016-01-12 14:18:54,684 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2016-01-12 14:18:54,684 INFO  [pool-14-thread-1] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local1441950054_0001_r_000005_0' done.
2016-01-12 14:18:54,684 INFO  [pool-14-thread-1] mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1441950054_0001_r_000005_0
2016-01-12 14:18:54,684 INFO  [Thread-34] mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2016-01-12 14:18:55,593 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1384)) -  map 100% reduce 100%
2016-01-12 14:18:55,594 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1395)) - Job job_local1441950054_0001 completed successfully
2016-01-12 14:18:55,623 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1402)) - Counters: 39
File System Counters
FILE: Number of bytes read=760423530
FILE: Number of bytes written=957050525
FILE: Number of read operations=0
FILE: Number of large read operations=0
FILE: Number of write operations=0
HDFS: Number of bytes read=87740
HDFS: Number of bytes written=20576511
HDFS: Number of read operations=777
HDFS: Number of large read operations=0
HDFS: Number of write operations=204
Map-Reduce Framework
Map input records=12
Map output records=1437885
Map output bytes=20866084
Map output materialized bytes=22533837
Input split bytes=1140
Combine input records=1437885
Combine output records=1328026
Reduce input groups=120000
Reduce shuffle bytes=22533837
Reduce input records=1328026
Reduce output records=120000
Spilled Records=2656052
Shuffled Maps =72
Failed Shuffles=0
Merged Map outputs=72
GC time elapsed (ms)=30
CPU time spent (ms)=0
Physical memory (bytes) snapshot=0
Virtual memory (bytes) snapshot=0
Total committed heap usage (bytes)=13659275264
HiBench.Counters
BYTES_DATA_GENERATED=8280632
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Input Format Counters
Bytes Read=200
File Output Format Counters
Bytes Written=5245714
2016-01-12 14:18:55,623 INFO  [main] HiBench.HiveData (HiveData.java:createRankingsTableDirectly(359)) - Finished Running Job: Create rankings
2016-01-12 14:18:55,623 INFO  [main] HiBench.HiveData (HiveData.java:createUserVisitsTableDirectly(535)) - Creating user visits...
2016-01-12 14:18:55,642 INFO  [main] HiBench.HiveData (HiveData.java:createUserVisitsTableDirectly(605)) - Running Job: Create uservisits
2016-01-12 14:18:55,642 INFO  [main] HiBench.HiveData (HiveData.java:createUserVisitsTableDirectly(606)) - Dummy file hdfs://nameservice1/HiBench/Join/temp/dummy as input
2016-01-12 14:18:55,642 INFO  [main] HiBench.HiveData (HiveData.java:createUserVisitsTableDirectly(607)) - Rankings file hdfs://nameservice1/HiBench/Join/Input/rankings as input
2016-01-12 14:18:55,642 INFO  [main] HiBench.HiveData (HiveData.java:createUserVisitsTableDirectly(608)) - Ouput file hdfs://nameservice1/HiBench/Join/Input/uservisits
2016-01-12 14:18:55,643 INFO  [main] jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2016-01-12 14:18:55,645 INFO  [main] jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2016-01-12 14:18:55,647 WARN  [main] mapreduce.JobResourceUploader (JobResourceUploader.java:uploadFiles(64)) - Hadoop command-line option parsing not performed. Implement the Tool interface and execute your application with ToolRunner to remedy this.
2016-01-12 14:18:55,734 INFO  [main] mapred.FileInputFormat (FileInputFormat.java:listStatus(249)) - Total input paths to process : 6
2016-01-12 14:18:55,739 INFO  [main] mapred.FileInputFormat (FileInputFormat.java:listStatus(249)) - Total input paths to process : 1
2016-01-12 14:18:55,742 INFO  [main] mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(201)) - number of splits:18
2016-01-12 14:18:55,748 INFO  [main] mapreduce.JobSubmitter (JobSubmitter.java:printTokens(290)) - Submitting tokens for job: job_local520291612_0002
2016-01-12 14:18:55,803 INFO  [main] mapred.LocalDistributedCacheManager (LocalDistributedCacheManager.java:symlink(201)) - Creating symlink: /tmp/hadoop-root/mapred/local/1452579535769/user_agents <- /script/HiBench-HiBench-5.0/workloads/join/prepare/user_agents
2016-01-12 14:18:55,805 INFO  [main] mapred.LocalDistributedCacheManager (LocalDistributedCacheManager.java:setup(165)) - Localized hdfs://nameservice1/HiBench/Join/temp/user_agents as file:/tmp/hadoop-root/mapred/local/1452579535769/user_agents
2016-01-12 14:18:55,805 INFO  [main] mapred.LocalDistributedCacheManager (LocalDistributedCacheManager.java:symlink(201)) - Creating symlink: /tmp/hadoop-root/mapred/local/1452579535770/country_codes <- /script/HiBench-HiBench-5.0/workloads/join/prepare/country_codes
2016-01-12 14:18:55,806 INFO  [main] mapred.LocalDistributedCacheManager (LocalDistributedCacheManager.java:setup(165)) - Localized hdfs://nameservice1/HiBench/Join/temp/country_codes as file:/tmp/hadoop-root/mapred/local/1452579535770/country_codes
2016-01-12 14:18:55,806 INFO  [main] mapred.LocalDistributedCacheManager (LocalDistributedCacheManager.java:symlink(201)) - Creating symlink: /tmp/hadoop-root/mapred/local/1452579535771/search_keys <- /script/HiBench-HiBench-5.0/workloads/join/prepare/search_keys
2016-01-12 14:18:55,808 INFO  [main] mapred.LocalDistributedCacheManager (LocalDistributedCacheManager.java:setup(165)) - Localized hdfs://nameservice1/HiBench/Join/temp/search_keys as file:/tmp/hadoop-root/mapred/local/1452579535771/search_keys
2016-01-12 14:18:55,838 INFO  [main] mapreduce.Job (Job.java:submit(1311)) - The url to track the job: http://localhost:8080/
2016-01-12 14:18:55,838 INFO  [Thread-97] mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2016-01-12 14:18:55,838 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1356)) - Running job: job_local520291612_0002
2016-01-12 14:18:55,838 INFO  [Thread-97] mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2016-01-12 14:18:55,839 INFO  [Thread-97] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:55,846 INFO  [Thread-97] mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2016-01-12 14:18:55,847 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000000_0
2016-01-12 14:18:55,847 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:55,848 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:55,848 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/Input/rankings/part-00004:0+876145
2016-01-12 14:18:55,856 INFO  [LocalJobRunner Map Task Executor #0] compress.CodecPool (CodecPool.java:getDecompressor(181)) - Got brand-new decompressor [.deflate]
2016-01-12 14:18:55,857 INFO  [LocalJobRunner Map Task Executor #0] compress.CodecPool (CodecPool.java:getDecompressor(181)) - Got brand-new decompressor [.deflate]
2016-01-12 14:18:55,857 INFO  [LocalJobRunner Map Task Executor #0] compress.CodecPool (CodecPool.java:getDecompressor(181)) - Got brand-new decompressor [.deflate]
2016-01-12 14:18:55,857 INFO  [LocalJobRunner Map Task Executor #0] compress.CodecPool (CodecPool.java:getDecompressor(181)) - Got brand-new decompressor [.deflate]
2016-01-12 14:18:55,859 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:55,874 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:55,874 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:55,874 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:55,874 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:55,874 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:55,874 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:55,946 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:55,946 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:55,946 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:55,946 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1284529; bufvoid = 104857600
2016-01-12 14:18:55,946 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 26134400(104537600); length = 79997/6553600
2016-01-12 14:18:55,971 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:55,972 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local520291612_0002_m_000000_0 is done. And is in the process of committing
2016-01-12 14:18:55,973 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/Input/rankings/part-00004:0+876145
2016-01-12 14:18:55,974 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local520291612_0002_m_000000_0' done.
2016-01-12 14:18:55,974 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local520291612_0002_m_000000_0
2016-01-12 14:18:55,974 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000001_0
2016-01-12 14:18:55,974 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:55,975 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:55,975 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/Input/rankings/part-00002:0+875076
2016-01-12 14:18:55,977 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:55,996 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:55,996 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:55,996 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:55,996 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:55,996 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:55,996 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:56,047 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:56,047 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:56,047 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:56,047 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1282787; bufvoid = 104857600
2016-01-12 14:18:56,047 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 26134400(104537600); length = 79997/6553600
2016-01-12 14:18:56,072 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:56,073 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local520291612_0002_m_000001_0 is done. And is in the process of committing
2016-01-12 14:18:56,074 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/Input/rankings/part-00002:0+875076
2016-01-12 14:18:56,074 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local520291612_0002_m_000001_0' done.
2016-01-12 14:18:56,074 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local520291612_0002_m_000001_0
2016-01-12 14:18:56,074 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000002_0
2016-01-12 14:18:56,075 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,075 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,076 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/Input/rankings/part-00003:0+874396
2016-01-12 14:18:56,078 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,097 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,097 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,097 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,097 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,097 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,098 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:56,136 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:56,136 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:56,136 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:56,136 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1281089; bufvoid = 104857600
2016-01-12 14:18:56,136 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 26134400(104537600); length = 79997/6553600
2016-01-12 14:18:56,162 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:56,163 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local520291612_0002_m_000002_0 is done. And is in the process of committing
2016-01-12 14:18:56,164 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/Input/rankings/part-00003:0+874396
2016-01-12 14:18:56,164 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local520291612_0002_m_000002_0' done.
2016-01-12 14:18:56,164 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local520291612_0002_m_000002_0
2016-01-12 14:18:56,164 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000003_0
2016-01-12 14:18:56,165 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,165 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,166 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/Input/rankings/part-00005:0+874326
2016-01-12 14:18:56,169 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,187 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,187 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,187 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,187 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,187 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,188 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:56,223 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:56,223 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:56,223 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:56,224 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1280399; bufvoid = 104857600
2016-01-12 14:18:56,224 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 26134400(104537600); length = 79997/6553600
2016-01-12 14:18:56,249 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:56,250 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local520291612_0002_m_000003_0 is done. And is in the process of committing
2016-01-12 14:18:56,251 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/Input/rankings/part-00005:0+874326
2016-01-12 14:18:56,251 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local520291612_0002_m_000003_0' done.
2016-01-12 14:18:56,251 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local520291612_0002_m_000003_0
2016-01-12 14:18:56,251 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000004_0
2016-01-12 14:18:56,252 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,252 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,253 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/Input/rankings/part-00000:0+873054
2016-01-12 14:18:56,255 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,273 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,273 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,274 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,274 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,274 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,274 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:56,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:56,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:56,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:56,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1279904; bufvoid = 104857600
2016-01-12 14:18:56,309 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 26134400(104537600); length = 79997/6553600
2016-01-12 14:18:56,334 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:56,335 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local520291612_0002_m_000004_0 is done. And is in the process of committing
2016-01-12 14:18:56,336 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/Input/rankings/part-00000:0+873054
2016-01-12 14:18:56,337 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local520291612_0002_m_000004_0' done.
2016-01-12 14:18:56,337 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local520291612_0002_m_000004_0
2016-01-12 14:18:56,337 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000005_0
2016-01-12 14:18:56,338 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,338 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,338 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/Input/rankings/part-00001:0+872717
2016-01-12 14:18:56,341 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,359 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,359 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,359 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,359 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,359 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,359 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2016-01-12 14:18:56,394 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2016-01-12 14:18:56,395 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1461)) - Starting flush of map output
2016-01-12 14:18:56,395 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1479)) - Spilling map output
2016-01-12 14:18:56,395 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1480)) - bufstart = 0; bufend = 1278254; bufvoid = 104857600
2016-01-12 14:18:56,395 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:flush(1482)) - kvstart = 26214396(104857584); kvend = 26134400(104537600); length = 79997/6553600
2016-01-12 14:18:56,420 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:sortAndSpill(1664)) - Finished spill 0
2016-01-12 14:18:56,421 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:done(1003)) - Task:attempt_local520291612_0002_m_000005_0 is done. And is in the process of committing
2016-01-12 14:18:56,422 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - hdfs://nameservice1/HiBench/Join/Input/rankings/part-00001:0+872717
2016-01-12 14:18:56,422 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:sendDone(1123)) - Task 'attempt_local520291612_0002_m_000005_0' done.
2016-01-12 14:18:56,423 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local520291612_0002_m_000005_0
2016-01-12 14:18:56,423 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000006_0
2016-01-12 14:18:56,423 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,424 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,424 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:17+3
2016-01-12 14:18:56,426 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,444 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,444 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,444 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,444 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,444 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,445 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452579535769/user_agents (No such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at java.io.FileReader.<init>(FileReader.java:58)
at HiBench.Visit.<init>(Visit.java:46)
at HiBench.HiveData$DummyToAccessNoMapper.configure(HiveData.java:389)
at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.hadoop.util.ReflectionUtils.setJobConf(ReflectionUtils.java:106)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:75)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:133)
at org.apache.hadoop.mapred.lib.DelegatingMapper.map(DelegatingMapper.java:53)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2016-01-12 14:18:56,450 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000007_0
2016-01-12 14:18:56,450 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,451 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,451 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:20+3
2016-01-12 14:18:56,453 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,468 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,468 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,468 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,469 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,469 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,469 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452579535769/user_agents (No such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at java.io.FileReader.<init>(FileReader.java:58)
at HiBench.Visit.<init>(Visit.java:46)
at HiBench.HiveData$DummyToAccessNoMapper.configure(HiveData.java:389)
at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.hadoop.util.ReflectionUtils.setJobConf(ReflectionUtils.java:106)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:75)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:133)
at org.apache.hadoop.mapred.lib.DelegatingMapper.map(DelegatingMapper.java:53)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2016-01-12 14:18:56,470 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000008_0
2016-01-12 14:18:56,471 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,472 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,472 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:23+3
2016-01-12 14:18:56,474 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,537 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,538 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,538 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,538 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,538 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,538 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452579535769/user_agents (No such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at java.io.FileReader.<init>(FileReader.java:58)
at HiBench.Visit.<init>(Visit.java:46)
at HiBench.HiveData$DummyToAccessNoMapper.configure(HiveData.java:389)
at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.hadoop.util.ReflectionUtils.setJobConf(ReflectionUtils.java:106)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:75)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:133)
at org.apache.hadoop.mapred.lib.DelegatingMapper.map(DelegatingMapper.java:53)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2016-01-12 14:18:56,540 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000009_0
2016-01-12 14:18:56,541 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,542 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,542 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:1+2
2016-01-12 14:18:56,545 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,560 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,560 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,560 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,560 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,560 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,561 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452579535769/user_agents (No such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at java.io.FileReader.<init>(FileReader.java:58)
at HiBench.Visit.<init>(Visit.java:46)
at HiBench.HiveData$DummyToAccessNoMapper.configure(HiveData.java:389)
at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.hadoop.util.ReflectionUtils.setJobConf(ReflectionUtils.java:106)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:75)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:133)
at org.apache.hadoop.mapred.lib.DelegatingMapper.map(DelegatingMapper.java:53)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2016-01-12 14:18:56,562 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000010_0
2016-01-12 14:18:56,563 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,563 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,564 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:3+2
2016-01-12 14:18:56,566 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,780 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,780 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,780 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,780 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,780 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,781 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452579535769/user_agents (No such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at java.io.FileReader.<init>(FileReader.java:58)
at HiBench.Visit.<init>(Visit.java:46)
at HiBench.HiveData$DummyToAccessNoMapper.configure(HiveData.java:389)
at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.hadoop.util.ReflectionUtils.setJobConf(ReflectionUtils.java:106)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:75)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:133)
at org.apache.hadoop.mapred.lib.DelegatingMapper.map(DelegatingMapper.java:53)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2016-01-12 14:18:56,782 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000011_0
2016-01-12 14:18:56,783 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,783 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,784 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:5+2
2016-01-12 14:18:56,786 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,801 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,801 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,801 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,801 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,801 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,802 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452579535769/user_agents (No such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at java.io.FileReader.<init>(FileReader.java:58)
at HiBench.Visit.<init>(Visit.java:46)
at HiBench.HiveData$DummyToAccessNoMapper.configure(HiveData.java:389)
at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.hadoop.util.ReflectionUtils.setJobConf(ReflectionUtils.java:106)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:75)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:133)
at org.apache.hadoop.mapred.lib.DelegatingMapper.map(DelegatingMapper.java:53)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2016-01-12 14:18:56,803 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000012_0
2016-01-12 14:18:56,804 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,804 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,805 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:7+2
2016-01-12 14:18:56,807 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,864 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1377)) - Job job_local520291612_0002 running in uber mode : false
2016-01-12 14:18:56,864 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1384)) -  map 100% reduce 0%
2016-01-12 14:18:56,879 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,879 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,879 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,879 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,879 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,880 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452579535769/user_agents (No such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at java.io.FileReader.<init>(FileReader.java:58)
at HiBench.Visit.<init>(Visit.java:46)
at HiBench.HiveData$DummyToAccessNoMapper.configure(HiveData.java:389)
at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.hadoop.util.ReflectionUtils.setJobConf(ReflectionUtils.java:106)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:75)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:133)
at org.apache.hadoop.mapred.lib.DelegatingMapper.map(DelegatingMapper.java:53)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2016-01-12 14:18:56,881 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000013_0
2016-01-12 14:18:56,882 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,882 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,883 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:9+2
2016-01-12 14:18:56,885 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:56,900 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:setEquator(1206)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-12 14:18:56,901 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(999)) - mapreduce.task.io.sort.mb: 100
2016-01-12 14:18:56,901 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1000)) - soft limit at 83886080
2016-01-12 14:18:56,901 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1001)) - bufstart = 0; bufvoid = 104857600
2016-01-12 14:18:56,901 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:init(1002)) - kvstart = 26214396; length = 6553600
2016-01-12 14:18:56,901 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:createSortingCollector(403)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
java.io.FileNotFoundException: file:/tmp/hadoop-root/mapred/local/1452579535769/user_agents (No such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at java.io.FileReader.<init>(FileReader.java:58)
at HiBench.Visit.<init>(Visit.java:46)
at HiBench.HiveData$DummyToAccessNoMapper.configure(HiveData.java:389)
at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.hadoop.util.ReflectionUtils.setJobConf(ReflectionUtils.java:106)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:75)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:133)
at org.apache.hadoop.mapred.lib.DelegatingMapper.map(DelegatingMapper.java:53)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2016-01-12 14:18:56,903 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000014_0
2016-01-12 14:18:56,904 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:56,904 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:56,904 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:11+2
2016-01-12 14:18:56,907 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:57,371 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000015_0
2016-01-12 14:18:57,374 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:57,374 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:57,375 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:13+2
2016-01-12 14:18:57,378 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:57,615 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000016_0
2016-01-12 14:18:57,616 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:57,617 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:57,617 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:15+2
2016-01-12 14:18:57,620 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:57,829 INFO  [LocalJobRunner Map Task Executor #0] mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520291612_0002_m_000017_0
2016-01-12 14:18:57,831 INFO  [LocalJobRunner Map Task Executor #0] output.FileOutputCommitter (FileOutputCommitter.java:<init>(100)) - File Output Committer Algorithm version is 1
2016-01-12 14:18:57,831 INFO  [LocalJobRunner Map Task Executor #0] mapred.Task (Task.java:initialize(588)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-12 14:18:57,832 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:updateJobWithSplit(485)) - Processing split: hdfs://nameservice1/HiBench/Join/temp/dummy:0+1
2016-01-12 14:18:57,833 INFO  [LocalJobRunner Map Task Executor #0] mapred.MapTask (MapTask.java:runOldMapper(439)) - numReduceTasks: 6
2016-01-12 14:18:58,052 INFO  [Thread-97] mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2016-01-12 14:18:58,055 WARN  [Thread-97] mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local520291612_0002
java.lang.Exception: java.lang.NullPointerException
at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462)
at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:522)
Caused by: java.lang.NullPointerException
at HiBench.HiveData$DummyToAccessNoMapper.map(HiveData.java:406)
at HiBench.HiveData$DummyToAccessNoMapper.map(HiveData.java:369)
at org.apache.hadoop.mapred.lib.DelegatingMapper.map(DelegatingMapper.java:56)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:453)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2016-01-12 14:18:59,053 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1397)) - Job job_local520291612_0002 failed with state FAILED due to: NA
2016-01-12 14:18:59,060 INFO  [main] mapreduce.Job (Job.java:monitorAndPrintJob(1402)) - Counters: 26
File System Counters
FILE: Number of bytes read=685425823
FILE: Number of bytes written=696586050
FILE: Number of read operations=0
FILE: Number of large read operations=0
FILE: Number of write operations=0
HDFS: Number of bytes read=19114497
HDFS: Number of bytes written=32215782
HDFS: Number of read operations=783
HDFS: Number of large read operations=0
HDFS: Number of write operations=180
Map-Reduce Framework
Map input records=120000
Map output records=120000
Map output bytes=7686962
Map output materialized bytes=7927178
Input split bytes=1506
Combine input records=120000
Combine output records=120000
Spilled Records=120000
Failed Shuffles=0
Merged Map outputs=0
GC time elapsed (ms)=14
CPU time spent (ms)=0
Physical memory (bytes) snapshot=0
Virtual memory (bytes) snapshot=0
Total committed heap usage (bytes)=5837946880
File Input Format Counters
Bytes Read=0
Exception in thread "main" java.io.IOException: Job failed!
at org.apache.hadoop.mapred.JobClient.runJob(JobClient.java:838)
at HiBench.HiveData.createUserVisitsTableDirectly(HiveData.java:609)
at HiBench.HiveData.generate(HiveData.java:619)
at HiBench.DataGen.run(DataGen.java:19)
at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:70)
at HiBench.DataGen.main(DataGen.java:45)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.hadoop.util.RunJar.run(RunJar.java:221)
at org.apache.hadoop.util.RunJar.main(RunJar.java:136)

根据日志信息,的确/tmp/hadoop-root/mapred/local/1452579535769/user_agents这个文件不存在,这个文件在hdfs上有,并通过LocalDistributedCacheManager共享拷贝到本地的/tmp/hadoop-root/mapred/local/1452579535769/user_agents目录,不知道为什么没有拷贝下来。问度娘说LocalDistributedCacheManager 必须在集群环境下运行,否则报错。我是按照hibench的wiki运行的,不知道怎么判断是不是这个原因导致的。

有人在CDH上成功跑过hibench吗? 遇到过这个问题没有啊




加载中
0
z
zenzondon

问题已经解决,少拷贝了mapred-site.xml到hibench下面,导致join测试是local模式运行

LocalDistributedCacheManager在local模式下,即使文件存在,也会报filenotfound。而我之所以观察到本地文件不存在,是因为测试用例会在运行结束后把本地文件删除掉。

返回顶部
顶部