You are viewing a plain text version of this content. The canonical link for it is here.
Posted to mapreduce-user@hadoop.apache.org by wd <wd...@wdicc.com> on 2011/08/12 10:14:23 UTC
some map run really slow
hi,
Here is the log for map run in one map/reduce.
map1, run 1mins, 2sec, and processed 48572 rows
2011-08-12 01:34:28,313 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: Initializing Self 10 MAP
2011-08-12 01:34:28,313 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: Initializing Self 0
TS
2011-08-12 01:34:28,313 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: Operator 0 TS
initialized
2011-08-12 01:34:28,313 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: Initializing
children of 0 TS
2011-08-12 01:34:28,313 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing child 1
FIL
2011-08-12 01:34:28,313 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing Self 1 FIL
2011-08-12 01:34:28,318 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 1 FIL
initialized
2011-08-12 01:34:28,318 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing children
of 1 FIL
2011-08-12 01:34:28,318 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing child 2
FIL
2011-08-12 01:34:28,318 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing Self 2 FIL
2011-08-12 01:34:28,318 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 2 FIL
initialized
2011-08-12 01:34:28,318 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing children
of 2 FIL
2011-08-12 01:34:28,318 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing child 3
SEL
2011-08-12 01:34:28,318 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing Self 3 SEL
2011-08-12 01:34:28,407 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Operator 3 SEL
initialized
2011-08-12 01:34:28,407 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing children
of 3 SEL
2011-08-12 01:34:28,407 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Initializing child
4 RS
2011-08-12 01:34:28,407 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Initializing Self 4
RS
2011-08-12 01:34:28,408 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Using tag = -1
2011-08-12 01:34:28,420 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Operator 4 RS
initialized
2011-08-12 01:34:28,420 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Initialization Done
4 RS
2011-08-12 01:34:28,420 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Initialization Done 3
SEL
2011-08-12 01:34:28,420 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initialization Done 2
FIL
2011-08-12 01:34:28,420 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initialization Done 1
FIL
2011-08-12 01:34:28,420 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: Initialization Done
0 TS
2011-08-12 01:34:28,420 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: Initialization Done 10 MAP
2011-08-12 01:34:28,423 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: Processing path
hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/beacon_logs/dt=20110811/tmp_b.20110811
2011-08-12 01:34:28,423 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: Processing alias
m:test_logs for file
hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811
2011-08-12 01:34:28,424 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 1 rows
2011-08-12 01:34:28,424 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 1 rows
2011-08-12 01:34:28,427 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 1 rows
2011-08-12 01:34:28,427 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 1 rows
2011-08-12 01:34:28,430 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 1 rows
2011-08-12 01:34:28,432 INFO ExecMapper: ExecMapper: processing 1
rows: used memory = 217548568
2011-08-12 01:34:28,440 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 10 rows
2011-08-12 01:34:28,440 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 10 rows
2011-08-12 01:34:28,441 INFO ExecMapper: ExecMapper: processing 10
rows: used memory = 217760328
2011-08-12 01:34:28,443 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 10 rows
2011-08-12 01:34:28,443 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 10 rows
2011-08-12 01:34:28,444 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 10 rows
2011-08-12 01:34:28,486 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 100 rows
2011-08-12 01:34:28,487 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 100
rows
2011-08-12 01:34:28,487 INFO ExecMapper: ExecMapper: processing 100
rows: used memory = 218813320
2011-08-12 01:34:28,499 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 100 rows
2011-08-12 01:34:28,499 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 100 rows
2011-08-12 01:34:28,499 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 100 rows
2011-08-12 01:34:30,451 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 1000 rows
2011-08-12 01:34:30,451 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 1000
rows
2011-08-12 01:34:30,451 INFO ExecMapper: ExecMapper: processing 1000
rows: used memory = 216809296
2011-08-12 01:34:31,050 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 1000 rows
2011-08-12 01:34:31,050 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 1000 rows
2011-08-12 01:34:31,050 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 1000 rows
2011-08-12 01:34:52,125 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 10000 rows
2011-08-12 01:34:52,125 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 10000
rows
2011-08-12 01:34:52,125 INFO ExecMapper: ExecMapper: processing 10000
rows: used memory = 216713344
2011-08-12 01:34:55,876 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 10000 rows
2011-08-12 01:34:55,876 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 10000 rows
2011-08-12 01:34:55,876 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 10000 rows
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 finished. closing...
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarded 48572 rows
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: DESERIALIZE_ERRORS:0
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 finished.
closing...
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarded 48572
rows
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 finished. closing...
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarded 37222 rows
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: PASSED:37222
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: FILTERED:11350
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 finished. closing...
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarded 37222 rows
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: PASSED:37222
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: FILTERED:0
2011-08-12 01:35:28,859 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 finished. closing...
2011-08-12 01:35:28,860 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarded 37222 rows
2011-08-12 01:35:28,860 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4 finished.
closing...
2011-08-12 01:35:28,860 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4 forwarded 0 rows
2011-08-12 01:35:28,860 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 Close done
2011-08-12 01:35:28,860 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 Close done
2011-08-12 01:35:28,860 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 Close done
2011-08-12 01:35:28,860 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 Close done
2011-08-12 01:35:28,860 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 Close done
2011-08-12 01:35:28,860 INFO ExecMapper: ExecMapper: processed 48572
rows: used memory = 245403616
2011-08-12 01:35:28,864 INFO org.apache.hadoop.mapred.MapTask:
Starting flush of map output
2011-08-12 01:35:29,094 INFO org.apache.hadoop.mapred.MapTask: Finished spill 0
2011-08-12 01:35:29,097 INFO org.apache.hadoop.mapred.TaskRunner:
Task:attempt_201108111828_0008_m_000126_0 is done. And is in the
process of commiting
2011-08-12 01:35:29,100 INFO org.apache.hadoop.mapred.TaskRunner: Task
'attempt_201108111828_0008_m_000126_0' done.
map2, run 7sec, processed 81078 rows
2011-08-12 01:34:32,160 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: Initializing Self 10 MAP
2011-08-12 01:34:32,160 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: Initializing Self 0
TS
2011-08-12 01:34:32,160 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: Operator 0 TS
initialized
2011-08-12 01:34:32,160 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: Initializing
children of 0 TS
2011-08-12 01:34:32,160 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing child 1
FIL
2011-08-12 01:34:32,160 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing Self 1 FIL
2011-08-12 01:34:32,166 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 1 FIL
initialized
2011-08-12 01:34:32,166 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing children
of 1 FIL
2011-08-12 01:34:32,166 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing child 2
FIL
2011-08-12 01:34:32,166 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing Self 2 FIL
2011-08-12 01:34:32,166 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 2 FIL
initialized
2011-08-12 01:34:32,166 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing children
of 2 FIL
2011-08-12 01:34:32,166 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing child 3
SEL
2011-08-12 01:34:32,166 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing Self 3 SEL
2011-08-12 01:34:32,286 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Operator 3 SEL
initialized
2011-08-12 01:34:32,286 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing children
of 3 SEL
2011-08-12 01:34:32,286 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Initializing child
4 RS
2011-08-12 01:34:32,286 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Initializing Self 4
RS
2011-08-12 01:34:32,286 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Using tag = -1
2011-08-12 01:34:32,302 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Operator 4 RS
initialized
2011-08-12 01:34:32,302 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Initialization Done
4 RS
2011-08-12 01:34:32,302 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: Initialization Done 3
SEL
2011-08-12 01:34:32,302 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initialization Done 2
FIL
2011-08-12 01:34:32,302 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: Initialization Done 1
FIL
2011-08-12 01:34:32,302 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: Initialization Done
0 TS
2011-08-12 01:34:32,302 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: Initialization Done 10 MAP
2011-08-12 01:34:32,305 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: Processing path
hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811/tmp_b.20110811
2011-08-12 01:34:32,306 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: Processing alias
m:test_logs for file
hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/test_logs/dt=20110811
2011-08-12 01:34:32,307 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 1 rows
2011-08-12 01:34:32,307 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 1 rows
2011-08-12 01:34:32,311 INFO ExecMapper: ExecMapper: processing 1
rows: used memory = 280854088
2011-08-12 01:34:32,313 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 10 rows
2011-08-12 01:34:32,313 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 10 rows
2011-08-12 01:34:32,314 INFO ExecMapper: ExecMapper: processing 10
rows: used memory = 280854088
2011-08-12 01:34:32,335 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 100 rows
2011-08-12 01:34:32,335 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 100
rows
2011-08-12 01:34:32,335 INFO ExecMapper: ExecMapper: processing 100
rows: used memory = 280854088
2011-08-12 01:34:32,416 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 1000 rows
2011-08-12 01:34:32,416 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 1000
rows
2011-08-12 01:34:32,416 INFO ExecMapper: ExecMapper: processing 1000
rows: used memory = 280854088
2011-08-12 01:34:32,911 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 10000 rows
2011-08-12 01:34:32,911 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarding 10000
rows
2011-08-12 01:34:32,911 INFO ExecMapper: ExecMapper: processing 10000
rows: used memory = 280854088
2011-08-12 01:34:33,522 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 1 rows
2011-08-12 01:34:33,523 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 1 rows
2011-08-12 01:34:33,527 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 1 rows
2011-08-12 01:34:33,538 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 10 rows
2011-08-12 01:34:33,538 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 10 rows
2011-08-12 01:34:33,538 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 10 rows
2011-08-12 01:34:33,580 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 100 rows
2011-08-12 01:34:33,580 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 100 rows
2011-08-12 01:34:33,581 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 100 rows
2011-08-12 01:34:33,839 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 1000 rows
2011-08-12 01:34:33,839 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 1000 rows
2011-08-12 01:34:33,839 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 1000 rows
2011-08-12 01:34:34,755 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding 10000 rows
2011-08-12 01:34:34,755 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding 10000 rows
2011-08-12 01:34:34,755 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding 10000 rows
2011-08-12 01:34:37,268 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 finished. closing...
2011-08-12 01:34:37,268 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarded 81078 rows
2011-08-12 01:34:37,268 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: DESERIALIZE_ERRORS:0
2011-08-12 01:34:37,268 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 finished.
closing...
2011-08-12 01:34:37,268 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 forwarded 81078
rows
2011-08-12 01:34:37,268 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 finished. closing...
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarded 16791 rows
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: FILTERED:64287
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: PASSED:16791
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 finished. closing...
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarded 16791 rows
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: FILTERED:0
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: PASSED:16791
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 finished. closing...
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarded 16791 rows
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4 finished.
closing...
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4 forwarded 0 rows
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.SelectOperator: 3 Close done
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 2 Close done
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.FilterOperator: 1 Close done
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 Close done
2011-08-12 01:34:37,269 INFO
org.apache.hadoop.hive.ql.exec.MapOperator: 10 Close done
2011-08-12 01:34:37,269 INFO ExecMapper: ExecMapper: processed 81078
rows: used memory = 244564320
2011-08-12 01:34:37,274 INFO org.apache.hadoop.mapred.MapTask:
Starting flush of map output
2011-08-12 01:34:37,465 INFO org.apache.hadoop.mapred.MapTask: Finished spill 0
2011-08-12 01:34:37,470 INFO org.apache.hadoop.mapred.TaskRunner:
Task:attempt_201108111828_0008_m_000128_0 is done. And is in the
process of commiting
2011-08-12 01:34:37,475 INFO org.apache.hadoop.mapred.TaskRunner: Task
'attempt_201108111828_0008_m_000128_0' done.
why this happen? how to avoid the slow map?
Re: some map run really slow
Posted by wd <wd...@wdicc.com>.
Thanks, the io.sort.mb is 200M here, I'll do more test on it.
On Fri, Aug 12, 2011 at 8:47 PM, Florin P <fl...@yahoo.com> wrote:
> Hello!
> We've encountered some slow map process when sending large amounts of data from the mapper process to the reducer process. The output of the map process will be first written into a buffer whose size is given by the
> io.sort.mb property defined in core-site.xml. Its default value is 100. Here is its explanation:
> io.sort.mb-->"The total amount of buffer memory to use while sorting files, in megabytes. By default, gives each merge stream 1MB, which should minimize seeks".
> The problem is that when this buffer is full, then a process named "spill" will write the its content to your harddisk. Then, a copy phase will take output from the harddisk+buffer to the the reducer machine (via HTTP) where again it is written to a buffer and when that buffer is full then it will be flushed to harddriver.
> Bottom line, the more map output data you have the more IO operations you'll encounter. So that it was in mour case.
> I hope that this help.
> Regards,
> Florin
>
>
> --- On Fri, 8/12/11, wd <wd...@wdicc.com> wrote:
>
>> From: wd <wd...@wdicc.com>
>> Subject: Re: some map run really slow
>> To: mapreduce-user@hadoop.apache.org
>> Date: Friday, August 12, 2011, 6:26 AM
>> yes, there is a reduce. In fact, I'm
>> using hive to run map reduce
>> jobs, and the reducer is a perl script.
>>
>> The data send to reducer is about 1/3 or 1/4 of map input
>> data.
>>
>> On Fri, Aug 12, 2011 at 5:26 PM, Florin P <fl...@yahoo.com>
>> wrote:
>> > Hello!
>> > Di you have a reducer class involved? If yes, what
>> is the amount of data that you are sending from the mapper
>> to the reducer?
>> > Regards,
>> > Florin
>> >
>> > --- On Fri, 8/12/11, wd <wd...@wdicc.com>
>> wrote:
>> >
>> >> From: wd <wd...@wdicc.com>
>> >> Subject: some map run really slow
>> >> To: mapreduce-user@hadoop.apache.org
>> >> Date: Friday, August 12, 2011, 4:14 AM
>> >> hi,
>> >> Here is the log for map run in one map/reduce.
>> >>
>> >> map1, run 1mins, 2sec, and processed 48572 rows
>> >>
>> >> 2011-08-12 01:34:28,313 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> Initializing
>> >> Self 10 MAP
>> >> 2011-08-12 01:34:28,313 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> >> Initializing Self 0
>> >> TS
>> >> 2011-08-12 01:34:28,313 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> Operator
>> >> 0 TS
>> >> initialized
>> >> 2011-08-12 01:34:28,313 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> >> Initializing
>> >> children of 0 TS
>> >> 2011-08-12 01:34:28,313 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> child 1
>> >> FIL
>> >> 2011-08-12 01:34:28,313 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> Self 1 FIL
>> >> 2011-08-12 01:34:28,318 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Operator 1
>> >> FIL
>> >> initialized
>> >> 2011-08-12 01:34:28,318 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> children
>> >> of 1 FIL
>> >> 2011-08-12 01:34:28,318 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> child 2
>> >> FIL
>> >> 2011-08-12 01:34:28,318 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> Self 2 FIL
>> >> 2011-08-12 01:34:28,318 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Operator 2
>> >> FIL
>> >> initialized
>> >> 2011-08-12 01:34:28,318 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> children
>> >> of 2 FIL
>> >> 2011-08-12 01:34:28,318 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Initializing
>> >> child 3
>> >> SEL
>> >> 2011-08-12 01:34:28,318 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Initializing
>> >> Self 3 SEL
>> >> 2011-08-12 01:34:28,407 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Operator 3
>> >> SEL
>> >> initialized
>> >> 2011-08-12 01:34:28,407 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Initializing
>> >> children
>> >> of 3 SEL
>> >> 2011-08-12 01:34:28,407 INFO
>> >>
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> >> Initializing child
>> >> 4 RS
>> >> 2011-08-12 01:34:28,407 INFO
>> >>
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> >> Initializing Self 4
>> >> RS
>> >> 2011-08-12 01:34:28,408 INFO
>> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Using
>> >> tag = -1
>> >> 2011-08-12 01:34:28,420 INFO
>> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Operator
>> >> 4 RS
>> >> initialized
>> >> 2011-08-12 01:34:28,420 INFO
>> >>
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> >> Initialization Done
>> >> 4 RS
>> >> 2011-08-12 01:34:28,420 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> >> Initialization Done 3
>> >> SEL
>> >> 2011-08-12 01:34:28,420 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> Initialization Done 2
>> >> FIL
>> >> 2011-08-12 01:34:28,420 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> Initialization Done 1
>> >> FIL
>> >> 2011-08-12 01:34:28,420 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> >> Initialization Done
>> >> 0 TS
>> >> 2011-08-12 01:34:28,420 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> Initialization
>> >> Done 10 MAP
>> >> 2011-08-12 01:34:28,423 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> Processing
>> >> path
>> >>
>> hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/beacon_logs/dt=20110811/tmp_b.20110811
>> >> 2011-08-12 01:34:28,423 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> Processing
>> >> alias
>> >> m:test_logs for file
>> >>
>> hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811
>> >> 2011-08-12 01:34:28,424 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding 1
>> >> rows
>> >> 2011-08-12 01:34:28,424 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 1 rows
>> >> 2011-08-12 01:34:28,427 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 1 rows
>> >> 2011-08-12 01:34:28,427 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 1 rows
>> >> 2011-08-12 01:34:28,430 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 1 rows
>> >> 2011-08-12 01:34:28,432 INFO ExecMapper:
>> ExecMapper:
>> >> processing 1
>> >> rows: used memory = 217548568
>> >> 2011-08-12 01:34:28,440 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding
>> >> 10 rows
>> >> 2011-08-12 01:34:28,440 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 10 rows
>> >> 2011-08-12 01:34:28,441 INFO ExecMapper:
>> ExecMapper:
>> >> processing 10
>> >> rows: used memory = 217760328
>> >> 2011-08-12 01:34:28,443 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 10 rows
>> >> 2011-08-12 01:34:28,443 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 10 rows
>> >> 2011-08-12 01:34:28,444 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 10 rows
>> >> 2011-08-12 01:34:28,486 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding
>> >> 100 rows
>> >> 2011-08-12 01:34:28,487 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 100
>> >> rows
>> >> 2011-08-12 01:34:28,487 INFO ExecMapper:
>> ExecMapper:
>> >> processing 100
>> >> rows: used memory = 218813320
>> >> 2011-08-12 01:34:28,499 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 100 rows
>> >> 2011-08-12 01:34:28,499 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 100 rows
>> >> 2011-08-12 01:34:28,499 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 100 rows
>> >> 2011-08-12 01:34:30,451 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding
>> >> 1000 rows
>> >> 2011-08-12 01:34:30,451 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 1000
>> >> rows
>> >> 2011-08-12 01:34:30,451 INFO ExecMapper:
>> ExecMapper:
>> >> processing 1000
>> >> rows: used memory = 216809296
>> >> 2011-08-12 01:34:31,050 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 1000 rows
>> >> 2011-08-12 01:34:31,050 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 1000 rows
>> >> 2011-08-12 01:34:31,050 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 1000 rows
>> >> 2011-08-12 01:34:52,125 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding
>> >> 10000 rows
>> >> 2011-08-12 01:34:52,125 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 10000
>> >> rows
>> >> 2011-08-12 01:34:52,125 INFO ExecMapper:
>> ExecMapper:
>> >> processing 10000
>> >> rows: used memory = 216713344
>> >> 2011-08-12 01:34:55,876 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 10000 rows
>> >> 2011-08-12 01:34:55,876 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 10000 rows
>> >> 2011-08-12 01:34:55,876 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 10000 rows
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> finished.
>> >> closing...
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarded
>> >> 48572 rows
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> >> DESERIALIZE_ERRORS:0
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> finished.
>> >> closing...
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarded 48572
>> >> rows
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> finished.
>> >> closing...
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarded
>> >> 37222 rows
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> PASSED:37222
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> FILTERED:11350
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> finished.
>> >> closing...
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarded
>> >> 37222 rows
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> PASSED:37222
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> FILTERED:0
>> >> 2011-08-12 01:35:28,859 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> finished.
>> >> closing...
>> >> 2011-08-12 01:35:28,860 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarded
>> >> 37222 rows
>> >> 2011-08-12 01:35:28,860 INFO
>> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> 4
>> >> finished.
>> >> closing...
>> >> 2011-08-12 01:35:28,860 INFO
>> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> 4
>> >> forwarded 0 rows
>> >> 2011-08-12 01:35:28,860 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> Close
>> >> done
>> >> 2011-08-12 01:35:28,860 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> Close
>> >> done
>> >> 2011-08-12 01:35:28,860 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> Close
>> >> done
>> >> 2011-08-12 01:35:28,860 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0 Close
>> >> done
>> >> 2011-08-12 01:35:28,860 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> Close done
>> >> 2011-08-12 01:35:28,860 INFO ExecMapper:
>> ExecMapper:
>> >> processed 48572
>> >> rows: used memory = 245403616
>> >> 2011-08-12 01:35:28,864 INFO
>> >> org.apache.hadoop.mapred.MapTask:
>> >> Starting flush of map output
>> >> 2011-08-12 01:35:29,094 INFO
>> >> org.apache.hadoop.mapred.MapTask: Finished spill
>> 0
>> >> 2011-08-12 01:35:29,097 INFO
>> >> org.apache.hadoop.mapred.TaskRunner:
>> >> Task:attempt_201108111828_0008_m_000126_0 is done.
>> And is
>> >> in the
>> >> process of commiting
>> >> 2011-08-12 01:35:29,100 INFO
>> >> org.apache.hadoop.mapred.TaskRunner: Task
>> >> 'attempt_201108111828_0008_m_000126_0' done.
>> >>
>> >>
>> >> map2, run 7sec, processed 81078 rows
>> >>
>> >> 2011-08-12 01:34:32,160 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> Initializing
>> >> Self 10 MAP
>> >> 2011-08-12 01:34:32,160 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> >> Initializing Self 0
>> >> TS
>> >> 2011-08-12 01:34:32,160 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> Operator
>> >> 0 TS
>> >> initialized
>> >> 2011-08-12 01:34:32,160 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> >> Initializing
>> >> children of 0 TS
>> >> 2011-08-12 01:34:32,160 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> child 1
>> >> FIL
>> >> 2011-08-12 01:34:32,160 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> Self 1 FIL
>> >> 2011-08-12 01:34:32,166 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Operator 1
>> >> FIL
>> >> initialized
>> >> 2011-08-12 01:34:32,166 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> children
>> >> of 1 FIL
>> >> 2011-08-12 01:34:32,166 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> child 2
>> >> FIL
>> >> 2011-08-12 01:34:32,166 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> Self 2 FIL
>> >> 2011-08-12 01:34:32,166 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Operator 2
>> >> FIL
>> >> initialized
>> >> 2011-08-12 01:34:32,166 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initializing
>> >> children
>> >> of 2 FIL
>> >> 2011-08-12 01:34:32,166 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Initializing
>> >> child 3
>> >> SEL
>> >> 2011-08-12 01:34:32,166 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Initializing
>> >> Self 3 SEL
>> >> 2011-08-12 01:34:32,286 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Operator 3
>> >> SEL
>> >> initialized
>> >> 2011-08-12 01:34:32,286 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Initializing
>> >> children
>> >> of 3 SEL
>> >> 2011-08-12 01:34:32,286 INFO
>> >>
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> >> Initializing child
>> >> 4 RS
>> >> 2011-08-12 01:34:32,286 INFO
>> >>
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> >> Initializing Self 4
>> >> RS
>> >> 2011-08-12 01:34:32,286 INFO
>> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Using
>> >> tag = -1
>> >> 2011-08-12 01:34:32,302 INFO
>> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Operator
>> >> 4 RS
>> >> initialized
>> >> 2011-08-12 01:34:32,302 INFO
>> >>
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> >> Initialization Done
>> >> 4 RS
>> >> 2011-08-12 01:34:32,302 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> >> Initialization Done 3
>> >> SEL
>> >> 2011-08-12 01:34:32,302 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> Initialization Done 2
>> >> FIL
>> >> 2011-08-12 01:34:32,302 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> Initialization Done 1
>> >> FIL
>> >> 2011-08-12 01:34:32,302 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> >> Initialization Done
>> >> 0 TS
>> >> 2011-08-12 01:34:32,302 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> Initialization
>> >> Done 10 MAP
>> >> 2011-08-12 01:34:32,305 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> Processing
>> >> path
>> >>
>> hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811/tmp_b.20110811
>> >> 2011-08-12 01:34:32,306 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> Processing
>> >> alias
>> >> m:test_logs for file
>> >>
>> hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/test_logs/dt=20110811
>> >> 2011-08-12 01:34:32,307 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding 1
>> >> rows
>> >> 2011-08-12 01:34:32,307 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 1 rows
>> >> 2011-08-12 01:34:32,311 INFO ExecMapper:
>> ExecMapper:
>> >> processing 1
>> >> rows: used memory = 280854088
>> >> 2011-08-12 01:34:32,313 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding
>> >> 10 rows
>> >> 2011-08-12 01:34:32,313 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 10 rows
>> >> 2011-08-12 01:34:32,314 INFO ExecMapper:
>> ExecMapper:
>> >> processing 10
>> >> rows: used memory = 280854088
>> >> 2011-08-12 01:34:32,335 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding
>> >> 100 rows
>> >> 2011-08-12 01:34:32,335 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 100
>> >> rows
>> >> 2011-08-12 01:34:32,335 INFO ExecMapper:
>> ExecMapper:
>> >> processing 100
>> >> rows: used memory = 280854088
>> >> 2011-08-12 01:34:32,416 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding
>> >> 1000 rows
>> >> 2011-08-12 01:34:32,416 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 1000
>> >> rows
>> >> 2011-08-12 01:34:32,416 INFO ExecMapper:
>> ExecMapper:
>> >> processing 1000
>> >> rows: used memory = 280854088
>> >> 2011-08-12 01:34:32,911 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarding
>> >> 10000 rows
>> >> 2011-08-12 01:34:32,911 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarding 10000
>> >> rows
>> >> 2011-08-12 01:34:32,911 INFO ExecMapper:
>> ExecMapper:
>> >> processing 10000
>> >> rows: used memory = 280854088
>> >> 2011-08-12 01:34:33,522 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 1 rows
>> >> 2011-08-12 01:34:33,523 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 1 rows
>> >> 2011-08-12 01:34:33,527 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 1 rows
>> >> 2011-08-12 01:34:33,538 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 10 rows
>> >> 2011-08-12 01:34:33,538 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 10 rows
>> >> 2011-08-12 01:34:33,538 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 10 rows
>> >> 2011-08-12 01:34:33,580 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 100 rows
>> >> 2011-08-12 01:34:33,580 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 100 rows
>> >> 2011-08-12 01:34:33,581 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 100 rows
>> >> 2011-08-12 01:34:33,839 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 1000 rows
>> >> 2011-08-12 01:34:33,839 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 1000 rows
>> >> 2011-08-12 01:34:33,839 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 1000 rows
>> >> 2011-08-12 01:34:34,755 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarding
>> >> 10000 rows
>> >> 2011-08-12 01:34:34,755 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarding
>> >> 10000 rows
>> >> 2011-08-12 01:34:34,755 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarding
>> >> 10000 rows
>> >> 2011-08-12 01:34:37,268 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> finished.
>> >> closing...
>> >> 2011-08-12 01:34:37,268 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> forwarded
>> >> 81078 rows
>> >> 2011-08-12 01:34:37,268 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator:
>> >> DESERIALIZE_ERRORS:0
>> >> 2011-08-12 01:34:37,268 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> finished.
>> >> closing...
>> >> 2011-08-12 01:34:37,268 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0
>> >> forwarded 81078
>> >> rows
>> >> 2011-08-12 01:34:37,268 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> finished.
>> >> closing...
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> forwarded
>> >> 16791 rows
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> FILTERED:64287
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> PASSED:16791
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> finished.
>> >> closing...
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> forwarded
>> >> 16791 rows
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> FILTERED:0
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> >> PASSED:16791
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> finished.
>> >> closing...
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> forwarded
>> >> 16791 rows
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> 4
>> >> finished.
>> >> closing...
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> 4
>> >> forwarded 0 rows
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
>> Close
>> >> done
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
>> Close
>> >> done
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
>> Close
>> >> done
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> 0 Close
>> >> done
>> >> 2011-08-12 01:34:37,269 INFO
>> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
>> Close done
>> >> 2011-08-12 01:34:37,269 INFO ExecMapper:
>> ExecMapper:
>> >> processed 81078
>> >> rows: used memory = 244564320
>> >> 2011-08-12 01:34:37,274 INFO
>> >> org.apache.hadoop.mapred.MapTask:
>> >> Starting flush of map output
>> >> 2011-08-12 01:34:37,465 INFO
>> >> org.apache.hadoop.mapred.MapTask: Finished spill
>> 0
>> >> 2011-08-12 01:34:37,470 INFO
>> >> org.apache.hadoop.mapred.TaskRunner:
>> >> Task:attempt_201108111828_0008_m_000128_0 is done.
>> And is
>> >> in the
>> >> process of commiting
>> >> 2011-08-12 01:34:37,475 INFO
>> >> org.apache.hadoop.mapred.TaskRunner: Task
>> >> 'attempt_201108111828_0008_m_000128_0' done.
>> >>
>> >> why this happen? how to avoid the slow map?
>> >>
>> >
>>
>
Re: Possible to override the context.write() method in
ReduceContext?
Posted by Ross Nordeen <rj...@mtu.edu>.
Dino,
Ya that was another method we are using now. thanks
-Ross
--
Ross Nordeen
Computer Networking And Systems Administration
Michigan Technological University
http://www.linkedin.com/in/rjnordee
----- Original Message -----
From: "Dino Kečo" <di...@gmail.com>
To: mapreduce-user@hadoop.apache.org, "Ross" <rj...@mtu.edu>
Sent: Saturday, August 13, 2011 1:29:14 AM GMT -08:00 US/Canada Pacific
Subject: Re: Possible to override the context.write() method in ReduceContext?
Hi Ross,
The first thing that I should do is to create one main reducer and create writeToContext method in it. This method should handle your logic with if(...){...} and context.write(). All other reducers would extend this main reducer and call writeToContext instead context.write.
Thanks,
dino
On Fri, Aug 12, 2011 at 11:06 PM, Ross Nordeen < rjnordee@mtu.edu > wrote:
Using 0.20.2...
Is it possible to override the context.write() method in ReduceContext? I have an entire set of Reducers that I would like to all use a specific function just before every context.write() but I don't want them to worry about that logic, just to have it handled transparently.
For instance:
Iterator<Text> vit = values.iterator();
if (trans2 != null) {
key = (Text) trans2.transform(key);
}
while (vit.hasNext()) {
Text item = vit.next();
if (trans1 != null) {
item = (Text) trans1.transform(item);
}
context.write(key, item);
}
The logic before/after the write is often different, and there may be writes that happen in different cases. I want to move the if->transform functionality out to the write() function so I can just call context.write(a,b) instead of if (trans1 !=....
My end-goal is something like this:
protected void reduce(Text key, Iterable<Text> values, Context context)
throws IOException, InterruptedException {
Iterator<Text> vit = values.iterator();
while (vit.hasNext())
context.write(key, vit.next());
}
With the write() method override:
public void write(Text key, Text val) {
if (trans1 != null)
val = trans1.transform(val);
if (trans2 != null)
key = trans2.transform(key);
super.write(key,val);
}
or something similar.
Thanks in advance,
-Ross
--
Ross Nordeen
Computer Networking And Systems Administration
Michigan Technological University
http://www.linkedin.com/in/rjnordee
Re: Possible to override the context.write() method in ReduceContext?
Posted by Dino Kečo <di...@gmail.com>.
Hi Ross,
The first thing that I should do is to create one main reducer and create
writeToContext method in it. This method should handle your logic with
if(...){...} and context.write(). All other reducers would extend this main
reducer and call writeToContext instead context.write.
Thanks,
dino
On Fri, Aug 12, 2011 at 11:06 PM, Ross Nordeen <rj...@mtu.edu> wrote:
> Using 0.20.2...
>
> Is it possible to override the context.write() method in ReduceContext? I
> have an entire set of Reducers that I would like to all use a specific
> function just before every context.write() but I don't want them to worry
> about that logic, just to have it handled transparently.
>
> For instance:
>
> Iterator<Text> vit = values.iterator();
>
> if (trans2 != null) {
> key = (Text) trans2.transform(key);
> }
>
> while (vit.hasNext()) {
> Text item = vit.next();
> if (trans1 != null) {
> item = (Text) trans1.transform(item);
> }
> context.write(key, item);
> }
>
> The logic before/after the write is often different, and there may be
> writes that happen in different cases. I want to move the if->transform
> functionality out to the write() function so I can just call
> context.write(a,b) instead of if (trans1 !=....
>
> My end-goal is something like this:
>
> protected void reduce(Text key, Iterable<Text> values, Context context)
> throws IOException, InterruptedException {
> Iterator<Text> vit = values.iterator();
>
> while (vit.hasNext())
> context.write(key, vit.next());
> }
>
> With the write() method override:
>
> public void write(Text key, Text val) {
> if (trans1 != null)
> val = trans1.transform(val);
> if (trans2 != null)
> key = trans2.transform(key);
> super.write(key,val);
> }
>
> or something similar.
>
> Thanks in advance,
>
> -Ross
>
> --
> Ross Nordeen
> Computer Networking And Systems Administration
> Michigan Technological University
> http://www.linkedin.com/in/rjnordee
>
>
Possible to override the context.write() method in ReduceContext?
Posted by Ross Nordeen <rj...@mtu.edu>.
Using 0.20.2...
Is it possible to override the context.write() method in ReduceContext? I have an entire set of Reducers that I would like to all use a specific function just before every context.write() but I don't want them to worry about that logic, just to have it handled transparently.
For instance:
Iterator<Text> vit = values.iterator();
if (trans2 != null) {
key = (Text) trans2.transform(key);
}
while (vit.hasNext()) {
Text item = vit.next();
if (trans1 != null) {
item = (Text) trans1.transform(item);
}
context.write(key, item);
}
The logic before/after the write is often different, and there may be writes that happen in different cases. I want to move the if->transform functionality out to the write() function so I can just call context.write(a,b) instead of if (trans1 !=....
My end-goal is something like this:
protected void reduce(Text key, Iterable<Text> values, Context context)
throws IOException, InterruptedException {
Iterator<Text> vit = values.iterator();
while (vit.hasNext())
context.write(key, vit.next());
}
With the write() method override:
public void write(Text key, Text val) {
if (trans1 != null)
val = trans1.transform(val);
if (trans2 != null)
key = trans2.transform(key);
super.write(key,val);
}
or something similar.
Thanks in advance,
-Ross
--
Ross Nordeen
Computer Networking And Systems Administration
Michigan Technological University
http://www.linkedin.com/in/rjnordee
Re: some map run really slow
Posted by Florin P <fl...@yahoo.com>.
Hello!
We've encountered some slow map process when sending large amounts of data from the mapper process to the reducer process. The output of the map process will be first written into a buffer whose size is given by the
io.sort.mb property defined in core-site.xml. Its default value is 100. Here is its explanation:
io.sort.mb-->"The total amount of buffer memory to use while sorting files, in megabytes. By default, gives each merge stream 1MB, which should minimize seeks".
The problem is that when this buffer is full, then a process named "spill" will write the its content to your harddisk. Then, a copy phase will take output from the harddisk+buffer to the the reducer machine (via HTTP) where again it is written to a buffer and when that buffer is full then it will be flushed to harddriver.
Bottom line, the more map output data you have the more IO operations you'll encounter. So that it was in mour case.
I hope that this help.
Regards,
Florin
--- On Fri, 8/12/11, wd <wd...@wdicc.com> wrote:
> From: wd <wd...@wdicc.com>
> Subject: Re: some map run really slow
> To: mapreduce-user@hadoop.apache.org
> Date: Friday, August 12, 2011, 6:26 AM
> yes, there is a reduce. In fact, I'm
> using hive to run map reduce
> jobs, and the reducer is a perl script.
>
> The data send to reducer is about 1/3 or 1/4 of map input
> data.
>
> On Fri, Aug 12, 2011 at 5:26 PM, Florin P <fl...@yahoo.com>
> wrote:
> > Hello!
> > Di you have a reducer class involved? If yes, what
> is the amount of data that you are sending from the mapper
> to the reducer?
> > Regards,
> > Florin
> >
> > --- On Fri, 8/12/11, wd <wd...@wdicc.com>
> wrote:
> >
> >> From: wd <wd...@wdicc.com>
> >> Subject: some map run really slow
> >> To: mapreduce-user@hadoop.apache.org
> >> Date: Friday, August 12, 2011, 4:14 AM
> >> hi,
> >> Here is the log for map run in one map/reduce.
> >>
> >> map1, run 1mins, 2sec, and processed 48572 rows
> >>
> >> 2011-08-12 01:34:28,313 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> Initializing
> >> Self 10 MAP
> >> 2011-08-12 01:34:28,313 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> >> Initializing Self 0
> >> TS
> >> 2011-08-12 01:34:28,313 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> Operator
> >> 0 TS
> >> initialized
> >> 2011-08-12 01:34:28,313 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> >> Initializing
> >> children of 0 TS
> >> 2011-08-12 01:34:28,313 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> child 1
> >> FIL
> >> 2011-08-12 01:34:28,313 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> Self 1 FIL
> >> 2011-08-12 01:34:28,318 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Operator 1
> >> FIL
> >> initialized
> >> 2011-08-12 01:34:28,318 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> children
> >> of 1 FIL
> >> 2011-08-12 01:34:28,318 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> child 2
> >> FIL
> >> 2011-08-12 01:34:28,318 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> Self 2 FIL
> >> 2011-08-12 01:34:28,318 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Operator 2
> >> FIL
> >> initialized
> >> 2011-08-12 01:34:28,318 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> children
> >> of 2 FIL
> >> 2011-08-12 01:34:28,318 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Initializing
> >> child 3
> >> SEL
> >> 2011-08-12 01:34:28,318 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Initializing
> >> Self 3 SEL
> >> 2011-08-12 01:34:28,407 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Operator 3
> >> SEL
> >> initialized
> >> 2011-08-12 01:34:28,407 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Initializing
> >> children
> >> of 3 SEL
> >> 2011-08-12 01:34:28,407 INFO
> >>
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> >> Initializing child
> >> 4 RS
> >> 2011-08-12 01:34:28,407 INFO
> >>
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> >> Initializing Self 4
> >> RS
> >> 2011-08-12 01:34:28,408 INFO
> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Using
> >> tag = -1
> >> 2011-08-12 01:34:28,420 INFO
> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Operator
> >> 4 RS
> >> initialized
> >> 2011-08-12 01:34:28,420 INFO
> >>
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> >> Initialization Done
> >> 4 RS
> >> 2011-08-12 01:34:28,420 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> >> Initialization Done 3
> >> SEL
> >> 2011-08-12 01:34:28,420 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> Initialization Done 2
> >> FIL
> >> 2011-08-12 01:34:28,420 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> Initialization Done 1
> >> FIL
> >> 2011-08-12 01:34:28,420 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> >> Initialization Done
> >> 0 TS
> >> 2011-08-12 01:34:28,420 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> Initialization
> >> Done 10 MAP
> >> 2011-08-12 01:34:28,423 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> Processing
> >> path
> >>
> hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/beacon_logs/dt=20110811/tmp_b.20110811
> >> 2011-08-12 01:34:28,423 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> Processing
> >> alias
> >> m:test_logs for file
> >>
> hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811
> >> 2011-08-12 01:34:28,424 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding 1
> >> rows
> >> 2011-08-12 01:34:28,424 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 1 rows
> >> 2011-08-12 01:34:28,427 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 1 rows
> >> 2011-08-12 01:34:28,427 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 1 rows
> >> 2011-08-12 01:34:28,430 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 1 rows
> >> 2011-08-12 01:34:28,432 INFO ExecMapper:
> ExecMapper:
> >> processing 1
> >> rows: used memory = 217548568
> >> 2011-08-12 01:34:28,440 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding
> >> 10 rows
> >> 2011-08-12 01:34:28,440 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 10 rows
> >> 2011-08-12 01:34:28,441 INFO ExecMapper:
> ExecMapper:
> >> processing 10
> >> rows: used memory = 217760328
> >> 2011-08-12 01:34:28,443 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 10 rows
> >> 2011-08-12 01:34:28,443 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 10 rows
> >> 2011-08-12 01:34:28,444 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 10 rows
> >> 2011-08-12 01:34:28,486 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding
> >> 100 rows
> >> 2011-08-12 01:34:28,487 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 100
> >> rows
> >> 2011-08-12 01:34:28,487 INFO ExecMapper:
> ExecMapper:
> >> processing 100
> >> rows: used memory = 218813320
> >> 2011-08-12 01:34:28,499 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 100 rows
> >> 2011-08-12 01:34:28,499 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 100 rows
> >> 2011-08-12 01:34:28,499 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 100 rows
> >> 2011-08-12 01:34:30,451 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding
> >> 1000 rows
> >> 2011-08-12 01:34:30,451 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 1000
> >> rows
> >> 2011-08-12 01:34:30,451 INFO ExecMapper:
> ExecMapper:
> >> processing 1000
> >> rows: used memory = 216809296
> >> 2011-08-12 01:34:31,050 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 1000 rows
> >> 2011-08-12 01:34:31,050 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 1000 rows
> >> 2011-08-12 01:34:31,050 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 1000 rows
> >> 2011-08-12 01:34:52,125 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding
> >> 10000 rows
> >> 2011-08-12 01:34:52,125 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 10000
> >> rows
> >> 2011-08-12 01:34:52,125 INFO ExecMapper:
> ExecMapper:
> >> processing 10000
> >> rows: used memory = 216713344
> >> 2011-08-12 01:34:55,876 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 10000 rows
> >> 2011-08-12 01:34:55,876 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 10000 rows
> >> 2011-08-12 01:34:55,876 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 10000 rows
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> finished.
> >> closing...
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarded
> >> 48572 rows
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> >> DESERIALIZE_ERRORS:0
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> finished.
> >> closing...
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarded 48572
> >> rows
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> finished.
> >> closing...
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarded
> >> 37222 rows
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> PASSED:37222
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> FILTERED:11350
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> finished.
> >> closing...
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarded
> >> 37222 rows
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> PASSED:37222
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> FILTERED:0
> >> 2011-08-12 01:35:28,859 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> finished.
> >> closing...
> >> 2011-08-12 01:35:28,860 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarded
> >> 37222 rows
> >> 2011-08-12 01:35:28,860 INFO
> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> 4
> >> finished.
> >> closing...
> >> 2011-08-12 01:35:28,860 INFO
> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> 4
> >> forwarded 0 rows
> >> 2011-08-12 01:35:28,860 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> Close
> >> done
> >> 2011-08-12 01:35:28,860 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> Close
> >> done
> >> 2011-08-12 01:35:28,860 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> Close
> >> done
> >> 2011-08-12 01:35:28,860 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0 Close
> >> done
> >> 2011-08-12 01:35:28,860 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> Close done
> >> 2011-08-12 01:35:28,860 INFO ExecMapper:
> ExecMapper:
> >> processed 48572
> >> rows: used memory = 245403616
> >> 2011-08-12 01:35:28,864 INFO
> >> org.apache.hadoop.mapred.MapTask:
> >> Starting flush of map output
> >> 2011-08-12 01:35:29,094 INFO
> >> org.apache.hadoop.mapred.MapTask: Finished spill
> 0
> >> 2011-08-12 01:35:29,097 INFO
> >> org.apache.hadoop.mapred.TaskRunner:
> >> Task:attempt_201108111828_0008_m_000126_0 is done.
> And is
> >> in the
> >> process of commiting
> >> 2011-08-12 01:35:29,100 INFO
> >> org.apache.hadoop.mapred.TaskRunner: Task
> >> 'attempt_201108111828_0008_m_000126_0' done.
> >>
> >>
> >> map2, run 7sec, processed 81078 rows
> >>
> >> 2011-08-12 01:34:32,160 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> Initializing
> >> Self 10 MAP
> >> 2011-08-12 01:34:32,160 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> >> Initializing Self 0
> >> TS
> >> 2011-08-12 01:34:32,160 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> Operator
> >> 0 TS
> >> initialized
> >> 2011-08-12 01:34:32,160 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> >> Initializing
> >> children of 0 TS
> >> 2011-08-12 01:34:32,160 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> child 1
> >> FIL
> >> 2011-08-12 01:34:32,160 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> Self 1 FIL
> >> 2011-08-12 01:34:32,166 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Operator 1
> >> FIL
> >> initialized
> >> 2011-08-12 01:34:32,166 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> children
> >> of 1 FIL
> >> 2011-08-12 01:34:32,166 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> child 2
> >> FIL
> >> 2011-08-12 01:34:32,166 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> Self 2 FIL
> >> 2011-08-12 01:34:32,166 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Operator 2
> >> FIL
> >> initialized
> >> 2011-08-12 01:34:32,166 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initializing
> >> children
> >> of 2 FIL
> >> 2011-08-12 01:34:32,166 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Initializing
> >> child 3
> >> SEL
> >> 2011-08-12 01:34:32,166 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Initializing
> >> Self 3 SEL
> >> 2011-08-12 01:34:32,286 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Operator 3
> >> SEL
> >> initialized
> >> 2011-08-12 01:34:32,286 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Initializing
> >> children
> >> of 3 SEL
> >> 2011-08-12 01:34:32,286 INFO
> >>
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> >> Initializing child
> >> 4 RS
> >> 2011-08-12 01:34:32,286 INFO
> >>
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> >> Initializing Self 4
> >> RS
> >> 2011-08-12 01:34:32,286 INFO
> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Using
> >> tag = -1
> >> 2011-08-12 01:34:32,302 INFO
> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Operator
> >> 4 RS
> >> initialized
> >> 2011-08-12 01:34:32,302 INFO
> >>
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> >> Initialization Done
> >> 4 RS
> >> 2011-08-12 01:34:32,302 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator:
> >> Initialization Done 3
> >> SEL
> >> 2011-08-12 01:34:32,302 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> Initialization Done 2
> >> FIL
> >> 2011-08-12 01:34:32,302 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> Initialization Done 1
> >> FIL
> >> 2011-08-12 01:34:32,302 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> >> Initialization Done
> >> 0 TS
> >> 2011-08-12 01:34:32,302 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> Initialization
> >> Done 10 MAP
> >> 2011-08-12 01:34:32,305 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> Processing
> >> path
> >>
> hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811/tmp_b.20110811
> >> 2011-08-12 01:34:32,306 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> Processing
> >> alias
> >> m:test_logs for file
> >>
> hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/test_logs/dt=20110811
> >> 2011-08-12 01:34:32,307 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding 1
> >> rows
> >> 2011-08-12 01:34:32,307 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 1 rows
> >> 2011-08-12 01:34:32,311 INFO ExecMapper:
> ExecMapper:
> >> processing 1
> >> rows: used memory = 280854088
> >> 2011-08-12 01:34:32,313 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding
> >> 10 rows
> >> 2011-08-12 01:34:32,313 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 10 rows
> >> 2011-08-12 01:34:32,314 INFO ExecMapper:
> ExecMapper:
> >> processing 10
> >> rows: used memory = 280854088
> >> 2011-08-12 01:34:32,335 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding
> >> 100 rows
> >> 2011-08-12 01:34:32,335 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 100
> >> rows
> >> 2011-08-12 01:34:32,335 INFO ExecMapper:
> ExecMapper:
> >> processing 100
> >> rows: used memory = 280854088
> >> 2011-08-12 01:34:32,416 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding
> >> 1000 rows
> >> 2011-08-12 01:34:32,416 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 1000
> >> rows
> >> 2011-08-12 01:34:32,416 INFO ExecMapper:
> ExecMapper:
> >> processing 1000
> >> rows: used memory = 280854088
> >> 2011-08-12 01:34:32,911 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarding
> >> 10000 rows
> >> 2011-08-12 01:34:32,911 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarding 10000
> >> rows
> >> 2011-08-12 01:34:32,911 INFO ExecMapper:
> ExecMapper:
> >> processing 10000
> >> rows: used memory = 280854088
> >> 2011-08-12 01:34:33,522 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 1 rows
> >> 2011-08-12 01:34:33,523 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 1 rows
> >> 2011-08-12 01:34:33,527 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 1 rows
> >> 2011-08-12 01:34:33,538 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 10 rows
> >> 2011-08-12 01:34:33,538 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 10 rows
> >> 2011-08-12 01:34:33,538 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 10 rows
> >> 2011-08-12 01:34:33,580 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 100 rows
> >> 2011-08-12 01:34:33,580 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 100 rows
> >> 2011-08-12 01:34:33,581 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 100 rows
> >> 2011-08-12 01:34:33,839 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 1000 rows
> >> 2011-08-12 01:34:33,839 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 1000 rows
> >> 2011-08-12 01:34:33,839 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 1000 rows
> >> 2011-08-12 01:34:34,755 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarding
> >> 10000 rows
> >> 2011-08-12 01:34:34,755 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarding
> >> 10000 rows
> >> 2011-08-12 01:34:34,755 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarding
> >> 10000 rows
> >> 2011-08-12 01:34:37,268 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> finished.
> >> closing...
> >> 2011-08-12 01:34:37,268 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> forwarded
> >> 81078 rows
> >> 2011-08-12 01:34:37,268 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator:
> >> DESERIALIZE_ERRORS:0
> >> 2011-08-12 01:34:37,268 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> finished.
> >> closing...
> >> 2011-08-12 01:34:37,268 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0
> >> forwarded 81078
> >> rows
> >> 2011-08-12 01:34:37,268 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> finished.
> >> closing...
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> forwarded
> >> 16791 rows
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> FILTERED:64287
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> PASSED:16791
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> finished.
> >> closing...
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> forwarded
> >> 16791 rows
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> FILTERED:0
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator:
> >> PASSED:16791
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> finished.
> >> closing...
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> forwarded
> >> 16791 rows
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> 4
> >> finished.
> >> closing...
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> 4
> >> forwarded 0 rows
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.SelectOperator: 3
> Close
> >> done
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 2
> Close
> >> done
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.FilterOperator: 1
> Close
> >> done
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> 0 Close
> >> done
> >> 2011-08-12 01:34:37,269 INFO
> >> org.apache.hadoop.hive.ql.exec.MapOperator: 10
> Close done
> >> 2011-08-12 01:34:37,269 INFO ExecMapper:
> ExecMapper:
> >> processed 81078
> >> rows: used memory = 244564320
> >> 2011-08-12 01:34:37,274 INFO
> >> org.apache.hadoop.mapred.MapTask:
> >> Starting flush of map output
> >> 2011-08-12 01:34:37,465 INFO
> >> org.apache.hadoop.mapred.MapTask: Finished spill
> 0
> >> 2011-08-12 01:34:37,470 INFO
> >> org.apache.hadoop.mapred.TaskRunner:
> >> Task:attempt_201108111828_0008_m_000128_0 is done.
> And is
> >> in the
> >> process of commiting
> >> 2011-08-12 01:34:37,475 INFO
> >> org.apache.hadoop.mapred.TaskRunner: Task
> >> 'attempt_201108111828_0008_m_000128_0' done.
> >>
> >> why this happen? how to avoid the slow map?
> >>
> >
>
Re: some map run really slow
Posted by wd <wd...@wdicc.com>.
yes, there is a reduce. In fact, I'm using hive to run map reduce
jobs, and the reducer is a perl script.
The data send to reducer is about 1/3 or 1/4 of map input data.
On Fri, Aug 12, 2011 at 5:26 PM, Florin P <fl...@yahoo.com> wrote:
> Hello!
> Di you have a reducer class involved? If yes, what is the amount of data that you are sending from the mapper to the reducer?
> Regards,
> Florin
>
> --- On Fri, 8/12/11, wd <wd...@wdicc.com> wrote:
>
>> From: wd <wd...@wdicc.com>
>> Subject: some map run really slow
>> To: mapreduce-user@hadoop.apache.org
>> Date: Friday, August 12, 2011, 4:14 AM
>> hi,
>> Here is the log for map run in one map/reduce.
>>
>> map1, run 1mins, 2sec, and processed 48572 rows
>>
>> 2011-08-12 01:34:28,313 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: Initializing
>> Self 10 MAP
>> 2011-08-12 01:34:28,313 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> Initializing Self 0
>> TS
>> 2011-08-12 01:34:28,313 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: Operator
>> 0 TS
>> initialized
>> 2011-08-12 01:34:28,313 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> Initializing
>> children of 0 TS
>> 2011-08-12 01:34:28,313 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> child 1
>> FIL
>> 2011-08-12 01:34:28,313 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> Self 1 FIL
>> 2011-08-12 01:34:28,318 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 1
>> FIL
>> initialized
>> 2011-08-12 01:34:28,318 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> children
>> of 1 FIL
>> 2011-08-12 01:34:28,318 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> child 2
>> FIL
>> 2011-08-12 01:34:28,318 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> Self 2 FIL
>> 2011-08-12 01:34:28,318 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 2
>> FIL
>> initialized
>> 2011-08-12 01:34:28,318 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> children
>> of 2 FIL
>> 2011-08-12 01:34:28,318 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
>> child 3
>> SEL
>> 2011-08-12 01:34:28,318 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
>> Self 3 SEL
>> 2011-08-12 01:34:28,407 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: Operator 3
>> SEL
>> initialized
>> 2011-08-12 01:34:28,407 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
>> children
>> of 3 SEL
>> 2011-08-12 01:34:28,407 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Initializing child
>> 4 RS
>> 2011-08-12 01:34:28,407 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Initializing Self 4
>> RS
>> 2011-08-12 01:34:28,408 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Using
>> tag = -1
>> 2011-08-12 01:34:28,420 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Operator
>> 4 RS
>> initialized
>> 2011-08-12 01:34:28,420 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Initialization Done
>> 4 RS
>> 2011-08-12 01:34:28,420 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Initialization Done 3
>> SEL
>> 2011-08-12 01:34:28,420 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initialization Done 2
>> FIL
>> 2011-08-12 01:34:28,420 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initialization Done 1
>> FIL
>> 2011-08-12 01:34:28,420 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> Initialization Done
>> 0 TS
>> 2011-08-12 01:34:28,420 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: Initialization
>> Done 10 MAP
>> 2011-08-12 01:34:28,423 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: Processing
>> path
>> hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/beacon_logs/dt=20110811/tmp_b.20110811
>> 2011-08-12 01:34:28,423 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: Processing
>> alias
>> m:test_logs for file
>> hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811
>> 2011-08-12 01:34:28,424 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 1
>> rows
>> 2011-08-12 01:34:28,424 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 1 rows
>> 2011-08-12 01:34:28,427 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 1 rows
>> 2011-08-12 01:34:28,427 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 1 rows
>> 2011-08-12 01:34:28,430 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 1 rows
>> 2011-08-12 01:34:28,432 INFO ExecMapper: ExecMapper:
>> processing 1
>> rows: used memory = 217548568
>> 2011-08-12 01:34:28,440 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
>> 10 rows
>> 2011-08-12 01:34:28,440 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 10 rows
>> 2011-08-12 01:34:28,441 INFO ExecMapper: ExecMapper:
>> processing 10
>> rows: used memory = 217760328
>> 2011-08-12 01:34:28,443 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 10 rows
>> 2011-08-12 01:34:28,443 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 10 rows
>> 2011-08-12 01:34:28,444 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 10 rows
>> 2011-08-12 01:34:28,486 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
>> 100 rows
>> 2011-08-12 01:34:28,487 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 100
>> rows
>> 2011-08-12 01:34:28,487 INFO ExecMapper: ExecMapper:
>> processing 100
>> rows: used memory = 218813320
>> 2011-08-12 01:34:28,499 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 100 rows
>> 2011-08-12 01:34:28,499 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 100 rows
>> 2011-08-12 01:34:28,499 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 100 rows
>> 2011-08-12 01:34:30,451 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
>> 1000 rows
>> 2011-08-12 01:34:30,451 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 1000
>> rows
>> 2011-08-12 01:34:30,451 INFO ExecMapper: ExecMapper:
>> processing 1000
>> rows: used memory = 216809296
>> 2011-08-12 01:34:31,050 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 1000 rows
>> 2011-08-12 01:34:31,050 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 1000 rows
>> 2011-08-12 01:34:31,050 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 1000 rows
>> 2011-08-12 01:34:52,125 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
>> 10000 rows
>> 2011-08-12 01:34:52,125 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 10000
>> rows
>> 2011-08-12 01:34:52,125 INFO ExecMapper: ExecMapper:
>> processing 10000
>> rows: used memory = 216713344
>> 2011-08-12 01:34:55,876 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 10000 rows
>> 2011-08-12 01:34:55,876 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 10000 rows
>> 2011-08-12 01:34:55,876 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 10000 rows
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 finished.
>> closing...
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarded
>> 48572 rows
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator:
>> DESERIALIZE_ERRORS:0
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> finished.
>> closing...
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarded 48572
>> rows
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 finished.
>> closing...
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarded
>> 37222 rows
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> PASSED:37222
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> FILTERED:11350
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 finished.
>> closing...
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarded
>> 37222 rows
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> PASSED:37222
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: FILTERED:0
>> 2011-08-12 01:35:28,859 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 finished.
>> closing...
>> 2011-08-12 01:35:28,860 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarded
>> 37222 rows
>> 2011-08-12 01:35:28,860 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4
>> finished.
>> closing...
>> 2011-08-12 01:35:28,860 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4
>> forwarded 0 rows
>> 2011-08-12 01:35:28,860 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 Close
>> done
>> 2011-08-12 01:35:28,860 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 Close
>> done
>> 2011-08-12 01:35:28,860 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 Close
>> done
>> 2011-08-12 01:35:28,860 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 Close
>> done
>> 2011-08-12 01:35:28,860 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 Close done
>> 2011-08-12 01:35:28,860 INFO ExecMapper: ExecMapper:
>> processed 48572
>> rows: used memory = 245403616
>> 2011-08-12 01:35:28,864 INFO
>> org.apache.hadoop.mapred.MapTask:
>> Starting flush of map output
>> 2011-08-12 01:35:29,094 INFO
>> org.apache.hadoop.mapred.MapTask: Finished spill 0
>> 2011-08-12 01:35:29,097 INFO
>> org.apache.hadoop.mapred.TaskRunner:
>> Task:attempt_201108111828_0008_m_000126_0 is done. And is
>> in the
>> process of commiting
>> 2011-08-12 01:35:29,100 INFO
>> org.apache.hadoop.mapred.TaskRunner: Task
>> 'attempt_201108111828_0008_m_000126_0' done.
>>
>>
>> map2, run 7sec, processed 81078 rows
>>
>> 2011-08-12 01:34:32,160 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: Initializing
>> Self 10 MAP
>> 2011-08-12 01:34:32,160 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> Initializing Self 0
>> TS
>> 2011-08-12 01:34:32,160 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: Operator
>> 0 TS
>> initialized
>> 2011-08-12 01:34:32,160 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> Initializing
>> children of 0 TS
>> 2011-08-12 01:34:32,160 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> child 1
>> FIL
>> 2011-08-12 01:34:32,160 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> Self 1 FIL
>> 2011-08-12 01:34:32,166 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 1
>> FIL
>> initialized
>> 2011-08-12 01:34:32,166 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> children
>> of 1 FIL
>> 2011-08-12 01:34:32,166 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> child 2
>> FIL
>> 2011-08-12 01:34:32,166 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> Self 2 FIL
>> 2011-08-12 01:34:32,166 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 2
>> FIL
>> initialized
>> 2011-08-12 01:34:32,166 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
>> children
>> of 2 FIL
>> 2011-08-12 01:34:32,166 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
>> child 3
>> SEL
>> 2011-08-12 01:34:32,166 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
>> Self 3 SEL
>> 2011-08-12 01:34:32,286 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: Operator 3
>> SEL
>> initialized
>> 2011-08-12 01:34:32,286 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
>> children
>> of 3 SEL
>> 2011-08-12 01:34:32,286 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Initializing child
>> 4 RS
>> 2011-08-12 01:34:32,286 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Initializing Self 4
>> RS
>> 2011-08-12 01:34:32,286 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Using
>> tag = -1
>> 2011-08-12 01:34:32,302 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Operator
>> 4 RS
>> initialized
>> 2011-08-12 01:34:32,302 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
>> Initialization Done
>> 4 RS
>> 2011-08-12 01:34:32,302 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator:
>> Initialization Done 3
>> SEL
>> 2011-08-12 01:34:32,302 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initialization Done 2
>> FIL
>> 2011-08-12 01:34:32,302 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> Initialization Done 1
>> FIL
>> 2011-08-12 01:34:32,302 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator:
>> Initialization Done
>> 0 TS
>> 2011-08-12 01:34:32,302 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: Initialization
>> Done 10 MAP
>> 2011-08-12 01:34:32,305 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: Processing
>> path
>> hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811/tmp_b.20110811
>> 2011-08-12 01:34:32,306 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: Processing
>> alias
>> m:test_logs for file
>> hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/test_logs/dt=20110811
>> 2011-08-12 01:34:32,307 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 1
>> rows
>> 2011-08-12 01:34:32,307 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 1 rows
>> 2011-08-12 01:34:32,311 INFO ExecMapper: ExecMapper:
>> processing 1
>> rows: used memory = 280854088
>> 2011-08-12 01:34:32,313 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
>> 10 rows
>> 2011-08-12 01:34:32,313 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 10 rows
>> 2011-08-12 01:34:32,314 INFO ExecMapper: ExecMapper:
>> processing 10
>> rows: used memory = 280854088
>> 2011-08-12 01:34:32,335 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
>> 100 rows
>> 2011-08-12 01:34:32,335 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 100
>> rows
>> 2011-08-12 01:34:32,335 INFO ExecMapper: ExecMapper:
>> processing 100
>> rows: used memory = 280854088
>> 2011-08-12 01:34:32,416 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
>> 1000 rows
>> 2011-08-12 01:34:32,416 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 1000
>> rows
>> 2011-08-12 01:34:32,416 INFO ExecMapper: ExecMapper:
>> processing 1000
>> rows: used memory = 280854088
>> 2011-08-12 01:34:32,911 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
>> 10000 rows
>> 2011-08-12 01:34:32,911 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarding 10000
>> rows
>> 2011-08-12 01:34:32,911 INFO ExecMapper: ExecMapper:
>> processing 10000
>> rows: used memory = 280854088
>> 2011-08-12 01:34:33,522 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 1 rows
>> 2011-08-12 01:34:33,523 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 1 rows
>> 2011-08-12 01:34:33,527 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 1 rows
>> 2011-08-12 01:34:33,538 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 10 rows
>> 2011-08-12 01:34:33,538 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 10 rows
>> 2011-08-12 01:34:33,538 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 10 rows
>> 2011-08-12 01:34:33,580 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 100 rows
>> 2011-08-12 01:34:33,580 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 100 rows
>> 2011-08-12 01:34:33,581 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 100 rows
>> 2011-08-12 01:34:33,839 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 1000 rows
>> 2011-08-12 01:34:33,839 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 1000 rows
>> 2011-08-12 01:34:33,839 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 1000 rows
>> 2011-08-12 01:34:34,755 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
>> 10000 rows
>> 2011-08-12 01:34:34,755 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
>> 10000 rows
>> 2011-08-12 01:34:34,755 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
>> 10000 rows
>> 2011-08-12 01:34:37,268 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 finished.
>> closing...
>> 2011-08-12 01:34:37,268 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarded
>> 81078 rows
>> 2011-08-12 01:34:37,268 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator:
>> DESERIALIZE_ERRORS:0
>> 2011-08-12 01:34:37,268 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> finished.
>> closing...
>> 2011-08-12 01:34:37,268 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
>> forwarded 81078
>> rows
>> 2011-08-12 01:34:37,268 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 finished.
>> closing...
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarded
>> 16791 rows
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> FILTERED:64287
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> PASSED:16791
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 finished.
>> closing...
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarded
>> 16791 rows
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: FILTERED:0
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator:
>> PASSED:16791
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 finished.
>> closing...
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarded
>> 16791 rows
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4
>> finished.
>> closing...
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4
>> forwarded 0 rows
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 Close
>> done
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 Close
>> done
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 Close
>> done
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 Close
>> done
>> 2011-08-12 01:34:37,269 INFO
>> org.apache.hadoop.hive.ql.exec.MapOperator: 10 Close done
>> 2011-08-12 01:34:37,269 INFO ExecMapper: ExecMapper:
>> processed 81078
>> rows: used memory = 244564320
>> 2011-08-12 01:34:37,274 INFO
>> org.apache.hadoop.mapred.MapTask:
>> Starting flush of map output
>> 2011-08-12 01:34:37,465 INFO
>> org.apache.hadoop.mapred.MapTask: Finished spill 0
>> 2011-08-12 01:34:37,470 INFO
>> org.apache.hadoop.mapred.TaskRunner:
>> Task:attempt_201108111828_0008_m_000128_0 is done. And is
>> in the
>> process of commiting
>> 2011-08-12 01:34:37,475 INFO
>> org.apache.hadoop.mapred.TaskRunner: Task
>> 'attempt_201108111828_0008_m_000128_0' done.
>>
>> why this happen? how to avoid the slow map?
>>
>
Re: some map run really slow
Posted by Florin P <fl...@yahoo.com>.
Hello!
Di you have a reducer class involved? If yes, what is the amount of data that you are sending from the mapper to the reducer?
Regards,
Florin
--- On Fri, 8/12/11, wd <wd...@wdicc.com> wrote:
> From: wd <wd...@wdicc.com>
> Subject: some map run really slow
> To: mapreduce-user@hadoop.apache.org
> Date: Friday, August 12, 2011, 4:14 AM
> hi,
> Here is the log for map run in one map/reduce.
>
> map1, run 1mins, 2sec, and processed 48572 rows
>
> 2011-08-12 01:34:28,313 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: Initializing
> Self 10 MAP
> 2011-08-12 01:34:28,313 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> Initializing Self 0
> TS
> 2011-08-12 01:34:28,313 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: Operator
> 0 TS
> initialized
> 2011-08-12 01:34:28,313 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> Initializing
> children of 0 TS
> 2011-08-12 01:34:28,313 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> child 1
> FIL
> 2011-08-12 01:34:28,313 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> Self 1 FIL
> 2011-08-12 01:34:28,318 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 1
> FIL
> initialized
> 2011-08-12 01:34:28,318 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> children
> of 1 FIL
> 2011-08-12 01:34:28,318 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> child 2
> FIL
> 2011-08-12 01:34:28,318 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> Self 2 FIL
> 2011-08-12 01:34:28,318 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 2
> FIL
> initialized
> 2011-08-12 01:34:28,318 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> children
> of 2 FIL
> 2011-08-12 01:34:28,318 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
> child 3
> SEL
> 2011-08-12 01:34:28,318 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
> Self 3 SEL
> 2011-08-12 01:34:28,407 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: Operator 3
> SEL
> initialized
> 2011-08-12 01:34:28,407 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
> children
> of 3 SEL
> 2011-08-12 01:34:28,407 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Initializing child
> 4 RS
> 2011-08-12 01:34:28,407 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Initializing Self 4
> RS
> 2011-08-12 01:34:28,408 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Using
> tag = -1
> 2011-08-12 01:34:28,420 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Operator
> 4 RS
> initialized
> 2011-08-12 01:34:28,420 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Initialization Done
> 4 RS
> 2011-08-12 01:34:28,420 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Initialization Done 3
> SEL
> 2011-08-12 01:34:28,420 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initialization Done 2
> FIL
> 2011-08-12 01:34:28,420 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initialization Done 1
> FIL
> 2011-08-12 01:34:28,420 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> Initialization Done
> 0 TS
> 2011-08-12 01:34:28,420 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: Initialization
> Done 10 MAP
> 2011-08-12 01:34:28,423 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: Processing
> path
> hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/beacon_logs/dt=20110811/tmp_b.20110811
> 2011-08-12 01:34:28,423 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: Processing
> alias
> m:test_logs for file
> hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811
> 2011-08-12 01:34:28,424 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 1
> rows
> 2011-08-12 01:34:28,424 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 1 rows
> 2011-08-12 01:34:28,427 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 1 rows
> 2011-08-12 01:34:28,427 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 1 rows
> 2011-08-12 01:34:28,430 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 1 rows
> 2011-08-12 01:34:28,432 INFO ExecMapper: ExecMapper:
> processing 1
> rows: used memory = 217548568
> 2011-08-12 01:34:28,440 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
> 10 rows
> 2011-08-12 01:34:28,440 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 10 rows
> 2011-08-12 01:34:28,441 INFO ExecMapper: ExecMapper:
> processing 10
> rows: used memory = 217760328
> 2011-08-12 01:34:28,443 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 10 rows
> 2011-08-12 01:34:28,443 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 10 rows
> 2011-08-12 01:34:28,444 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 10 rows
> 2011-08-12 01:34:28,486 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
> 100 rows
> 2011-08-12 01:34:28,487 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 100
> rows
> 2011-08-12 01:34:28,487 INFO ExecMapper: ExecMapper:
> processing 100
> rows: used memory = 218813320
> 2011-08-12 01:34:28,499 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 100 rows
> 2011-08-12 01:34:28,499 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 100 rows
> 2011-08-12 01:34:28,499 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 100 rows
> 2011-08-12 01:34:30,451 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
> 1000 rows
> 2011-08-12 01:34:30,451 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 1000
> rows
> 2011-08-12 01:34:30,451 INFO ExecMapper: ExecMapper:
> processing 1000
> rows: used memory = 216809296
> 2011-08-12 01:34:31,050 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 1000 rows
> 2011-08-12 01:34:31,050 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 1000 rows
> 2011-08-12 01:34:31,050 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 1000 rows
> 2011-08-12 01:34:52,125 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
> 10000 rows
> 2011-08-12 01:34:52,125 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 10000
> rows
> 2011-08-12 01:34:52,125 INFO ExecMapper: ExecMapper:
> processing 10000
> rows: used memory = 216713344
> 2011-08-12 01:34:55,876 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 10000 rows
> 2011-08-12 01:34:55,876 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 10000 rows
> 2011-08-12 01:34:55,876 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 10000 rows
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 finished.
> closing...
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarded
> 48572 rows
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator:
> DESERIALIZE_ERRORS:0
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> finished.
> closing...
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarded 48572
> rows
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 finished.
> closing...
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarded
> 37222 rows
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> PASSED:37222
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> FILTERED:11350
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 finished.
> closing...
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarded
> 37222 rows
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> PASSED:37222
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: FILTERED:0
> 2011-08-12 01:35:28,859 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 finished.
> closing...
> 2011-08-12 01:35:28,860 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarded
> 37222 rows
> 2011-08-12 01:35:28,860 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4
> finished.
> closing...
> 2011-08-12 01:35:28,860 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4
> forwarded 0 rows
> 2011-08-12 01:35:28,860 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 Close
> done
> 2011-08-12 01:35:28,860 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 Close
> done
> 2011-08-12 01:35:28,860 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 Close
> done
> 2011-08-12 01:35:28,860 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 Close
> done
> 2011-08-12 01:35:28,860 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 Close done
> 2011-08-12 01:35:28,860 INFO ExecMapper: ExecMapper:
> processed 48572
> rows: used memory = 245403616
> 2011-08-12 01:35:28,864 INFO
> org.apache.hadoop.mapred.MapTask:
> Starting flush of map output
> 2011-08-12 01:35:29,094 INFO
> org.apache.hadoop.mapred.MapTask: Finished spill 0
> 2011-08-12 01:35:29,097 INFO
> org.apache.hadoop.mapred.TaskRunner:
> Task:attempt_201108111828_0008_m_000126_0 is done. And is
> in the
> process of commiting
> 2011-08-12 01:35:29,100 INFO
> org.apache.hadoop.mapred.TaskRunner: Task
> 'attempt_201108111828_0008_m_000126_0' done.
>
>
> map2, run 7sec, processed 81078 rows
>
> 2011-08-12 01:34:32,160 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: Initializing
> Self 10 MAP
> 2011-08-12 01:34:32,160 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> Initializing Self 0
> TS
> 2011-08-12 01:34:32,160 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: Operator
> 0 TS
> initialized
> 2011-08-12 01:34:32,160 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> Initializing
> children of 0 TS
> 2011-08-12 01:34:32,160 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> child 1
> FIL
> 2011-08-12 01:34:32,160 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> Self 1 FIL
> 2011-08-12 01:34:32,166 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 1
> FIL
> initialized
> 2011-08-12 01:34:32,166 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> children
> of 1 FIL
> 2011-08-12 01:34:32,166 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> child 2
> FIL
> 2011-08-12 01:34:32,166 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> Self 2 FIL
> 2011-08-12 01:34:32,166 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Operator 2
> FIL
> initialized
> 2011-08-12 01:34:32,166 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: Initializing
> children
> of 2 FIL
> 2011-08-12 01:34:32,166 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
> child 3
> SEL
> 2011-08-12 01:34:32,166 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
> Self 3 SEL
> 2011-08-12 01:34:32,286 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: Operator 3
> SEL
> initialized
> 2011-08-12 01:34:32,286 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: Initializing
> children
> of 3 SEL
> 2011-08-12 01:34:32,286 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Initializing child
> 4 RS
> 2011-08-12 01:34:32,286 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Initializing Self 4
> RS
> 2011-08-12 01:34:32,286 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Using
> tag = -1
> 2011-08-12 01:34:32,302 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: Operator
> 4 RS
> initialized
> 2011-08-12 01:34:32,302 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator:
> Initialization Done
> 4 RS
> 2011-08-12 01:34:32,302 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator:
> Initialization Done 3
> SEL
> 2011-08-12 01:34:32,302 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initialization Done 2
> FIL
> 2011-08-12 01:34:32,302 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> Initialization Done 1
> FIL
> 2011-08-12 01:34:32,302 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator:
> Initialization Done
> 0 TS
> 2011-08-12 01:34:32,302 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: Initialization
> Done 10 MAP
> 2011-08-12 01:34:32,305 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: Processing
> path
> hdfs://test1:9000/user/hive/warehouse/test_logs/dt=20110811/tmp_b.20110811
> 2011-08-12 01:34:32,306 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: Processing
> alias
> m:test_logs for file
> hdfs://l-etl1.s.cn5:9000/user/hive/warehouse/test_logs/dt=20110811
> 2011-08-12 01:34:32,307 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding 1
> rows
> 2011-08-12 01:34:32,307 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 1 rows
> 2011-08-12 01:34:32,311 INFO ExecMapper: ExecMapper:
> processing 1
> rows: used memory = 280854088
> 2011-08-12 01:34:32,313 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
> 10 rows
> 2011-08-12 01:34:32,313 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 10 rows
> 2011-08-12 01:34:32,314 INFO ExecMapper: ExecMapper:
> processing 10
> rows: used memory = 280854088
> 2011-08-12 01:34:32,335 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
> 100 rows
> 2011-08-12 01:34:32,335 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 100
> rows
> 2011-08-12 01:34:32,335 INFO ExecMapper: ExecMapper:
> processing 100
> rows: used memory = 280854088
> 2011-08-12 01:34:32,416 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
> 1000 rows
> 2011-08-12 01:34:32,416 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 1000
> rows
> 2011-08-12 01:34:32,416 INFO ExecMapper: ExecMapper:
> processing 1000
> rows: used memory = 280854088
> 2011-08-12 01:34:32,911 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarding
> 10000 rows
> 2011-08-12 01:34:32,911 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarding 10000
> rows
> 2011-08-12 01:34:32,911 INFO ExecMapper: ExecMapper:
> processing 10000
> rows: used memory = 280854088
> 2011-08-12 01:34:33,522 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 1 rows
> 2011-08-12 01:34:33,523 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 1 rows
> 2011-08-12 01:34:33,527 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 1 rows
> 2011-08-12 01:34:33,538 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 10 rows
> 2011-08-12 01:34:33,538 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 10 rows
> 2011-08-12 01:34:33,538 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 10 rows
> 2011-08-12 01:34:33,580 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 100 rows
> 2011-08-12 01:34:33,580 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 100 rows
> 2011-08-12 01:34:33,581 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 100 rows
> 2011-08-12 01:34:33,839 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 1000 rows
> 2011-08-12 01:34:33,839 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 1000 rows
> 2011-08-12 01:34:33,839 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 1000 rows
> 2011-08-12 01:34:34,755 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarding
> 10000 rows
> 2011-08-12 01:34:34,755 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarding
> 10000 rows
> 2011-08-12 01:34:34,755 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarding
> 10000 rows
> 2011-08-12 01:34:37,268 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 finished.
> closing...
> 2011-08-12 01:34:37,268 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 forwarded
> 81078 rows
> 2011-08-12 01:34:37,268 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator:
> DESERIALIZE_ERRORS:0
> 2011-08-12 01:34:37,268 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> finished.
> closing...
> 2011-08-12 01:34:37,268 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0
> forwarded 81078
> rows
> 2011-08-12 01:34:37,268 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 finished.
> closing...
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 forwarded
> 16791 rows
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> FILTERED:64287
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> PASSED:16791
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 finished.
> closing...
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 forwarded
> 16791 rows
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: FILTERED:0
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator:
> PASSED:16791
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 finished.
> closing...
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 forwarded
> 16791 rows
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4
> finished.
> closing...
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.ReduceSinkOperator: 4
> forwarded 0 rows
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.SelectOperator: 3 Close
> done
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 2 Close
> done
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.FilterOperator: 1 Close
> done
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.TableScanOperator: 0 Close
> done
> 2011-08-12 01:34:37,269 INFO
> org.apache.hadoop.hive.ql.exec.MapOperator: 10 Close done
> 2011-08-12 01:34:37,269 INFO ExecMapper: ExecMapper:
> processed 81078
> rows: used memory = 244564320
> 2011-08-12 01:34:37,274 INFO
> org.apache.hadoop.mapred.MapTask:
> Starting flush of map output
> 2011-08-12 01:34:37,465 INFO
> org.apache.hadoop.mapred.MapTask: Finished spill 0
> 2011-08-12 01:34:37,470 INFO
> org.apache.hadoop.mapred.TaskRunner:
> Task:attempt_201108111828_0008_m_000128_0 is done. And is
> in the
> process of commiting
> 2011-08-12 01:34:37,475 INFO
> org.apache.hadoop.mapred.TaskRunner: Task
> 'attempt_201108111828_0008_m_000128_0' done.
>
> why this happen? how to avoid the slow map?
>