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?
