Eclipse中运行MapReduce程序时控制台无法打印进度信息的问题

一般会在控制台上打印以下信息：

log4j:WARN No appenders could be found for logger (org.apache.hadoop.util.Shell).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

然后不会出现MapReduce进度信息。

这种情况一般是由于log4j这个日志信息打印模块的配置信息没有给出造成的，可以在项目的src目录下，新建一个文件，命名为“log4j.properties”，填入以下信息：

log4j.rootLogger=INFO, stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d %p [%c] - %m%n
log4j.appender.logfile=org.apache.log4j.FileAppender
log4j.appender.logfile.File=target/spring.log
log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
log4j.appender.logfile.layout.ConversionPattern=%d %p [%c] - %m%n

就可以将Hadoop运行过程中产生的所有的以[INFO]开头的日志信息打印出来。

添加后，效果如下：

2014-05-25 20:11:47,738 INFO [org.apache.hadoop.conf.Configuration.deprecation] - session.id is deprecated. Instead, use dfs.metrics.session-id
2014-05-25 20:11:47,741 INFO [org.apache.hadoop.metrics.jvm.JvmMetrics] - Initializing JVM Metrics with processName=JobTracker, sessionId=
2014-05-25 20:11:49,079 WARN [org.apache.hadoop.mapreduce.JobSubmitter] - No job jar file set.  User classes may not be found. See Job or Job#setJar(String).
2014-05-25 20:11:49,346 INFO [org.apache.hadoop.mapreduce.lib.input.FileInputFormat] - Total input paths to process : 3
2014-05-25 20:11:49,496 INFO [org.apache.hadoop.mapreduce.JobSubmitter] - number of splits:3
2014-05-25 20:11:50,155 INFO [org.apache.hadoop.mapreduce.JobSubmitter] - Submitting tokens for job: job_local196560459_0001
2014-05-25 20:11:50,386 WARN [org.apache.hadoop.conf.Configuration] - file:/tmp/hadoop-lichao/mapred/staging/lichao196560459/.staging/job_local196560459_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2014-05-25 20:11:50,424 WARN [org.apache.hadoop.conf.Configuration] - file:/tmp/hadoop-lichao/mapred/staging/lichao196560459/.staging/job_local196560459_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2014-05-25 20:11:50,925 WARN [org.apache.hadoop.conf.Configuration] - file:/tmp/hadoop-lichao/mapred/local/localRunner/lichao/job_local196560459_0001/job_local196560459_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2014-05-25 20:11:50,951 WARN [org.apache.hadoop.conf.Configuration] - file:/tmp/hadoop-lichao/mapred/local/localRunner/lichao/job_local196560459_0001/job_local196560459_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2014-05-25 20:11:50,973 INFO [org.apache.hadoop.mapreduce.Job] - The url to track the job: http://localhost:8080/ 2014-05-25 20:11:50,976 INFO [org.apache.hadoop.mapreduce.Job] - Running job: job_local196560459_0001
2014-05-25 20:11:50,983 INFO [org.apache.hadoop.mapred.LocalJobRunner] - OutputCommitter set in config null
2014-05-25 20:11:51,011 INFO [org.apache.hadoop.mapred.LocalJobRunner] - OutputCommitter is org.apache.hadoop.mapreduce.lib.output.FileOutputCommitter
2014-05-25 20:11:51,252 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Waiting for map tasks
2014-05-25 20:11:51,256 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Starting task: attempt_local196560459_0001_m_000000_0
2014-05-25 20:11:51,464 INFO [org.apache.hadoop.mapred.Task] -  Using ResourceCalculatorProcessTree : [ ]
2014-05-25 20:11:51,481 INFO [org.apache.hadoop.mapred.MapTask] - Processing split: hdfs://localhost:9000/data/score_in/chinese:0+16
2014-05-25 20:11:51,557 INFO [org.apache.hadoop.mapred.MapTask] - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-05-25 20:11:52,000 INFO [org.apache.hadoop.mapreduce.Job] - Job job_local196560459_0001 running in uber mode : false
2014-05-25 20:11:52,006 INFO [org.apache.hadoop.mapreduce.Job] -  map 0% reduce 0%
2014-05-25 20:11:52,983 INFO [org.apache.hadoop.mapred.MapTask] - (EQUATOR) 0 kvi 26214396(104857584)
2014-05-25 20:11:52,984 INFO [org.apache.hadoop.mapred.MapTask] - mapreduce.task.io.sort.mb: 100
2014-05-25 20:11:52,984 INFO [org.apache.hadoop.mapred.MapTask] - soft limit at 83886080
2014-05-25 20:11:52,984 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufvoid = 104857600
2014-05-25 20:11:52,984 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396; length = 6553600
2014-05-25 20:11:53,421 INFO [org.apache.hadoop.mapred.LocalJobRunner] -
2014-05-25 20:11:53,433 INFO [org.apache.hadoop.mapred.MapTask] - Starting flush of map output
2014-05-25 20:11:53,434 INFO [org.apache.hadoop.mapred.MapTask] - Spilling map output
2014-05-25 20:11:53,434 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufend = 18; bufvoid = 104857600
2014-05-25 20:11:53,434 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396(104857584); kvend = 26214388(104857552); length = 9/6553600
2014-05-25 20:11:53,474 INFO [org.apache.hadoop.mapred.MapTask] - Finished spill 0
2014-05-25 20:11:53,487 INFO [org.apache.hadoop.mapred.Task] - Task:attempt_local196560459_0001_m_000000_0 is done. And is in the process of committing
2014-05-25 20:11:53,535 INFO [org.apache.hadoop.mapred.LocalJobRunner] - map
2014-05-25 20:11:53,535 INFO [org.apache.hadoop.mapred.Task] - Task 'attempt_local196560459_0001_m_000000_0' done.
2014-05-25 20:11:53,536 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Finishing task: attempt_local196560459_0001_m_000000_0
2014-05-25 20:11:53,536 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Starting task: attempt_local196560459_0001_m_000001_0
2014-05-25 20:11:53,545 INFO [org.apache.hadoop.mapred.Task] -  Using ResourceCalculatorProcessTree : [ ]
2014-05-25 20:11:53,550 INFO [org.apache.hadoop.mapred.MapTask] - Processing split: hdfs://localhost:9000/data/score_in/english:0+16
2014-05-25 20:11:53,553 INFO [org.apache.hadoop.mapred.MapTask] - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-05-25 20:11:54,024 INFO [org.apache.hadoop.mapreduce.Job] -  map 100% reduce 0%
2014-05-25 20:11:55,083 INFO [org.apache.hadoop.mapred.MapTask] - (EQUATOR) 0 kvi 26214396(104857584)
2014-05-25 20:11:55,083 INFO [org.apache.hadoop.mapred.MapTask] - mapreduce.task.io.sort.mb: 100
2014-05-25 20:11:55,083 INFO [org.apache.hadoop.mapred.MapTask] - soft limit at 83886080
2014-05-25 20:11:55,083 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufvoid = 104857600
2014-05-25 20:11:55,083 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396; length = 6553600
2014-05-25 20:11:55,104 INFO [org.apache.hadoop.mapred.LocalJobRunner] -
2014-05-25 20:11:55,104 INFO [org.apache.hadoop.mapred.MapTask] - Starting flush of map output
2014-05-25 20:11:55,104 INFO [org.apache.hadoop.mapred.MapTask] - Spilling map output
2014-05-25 20:11:55,105 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufend = 18; bufvoid = 104857600
2014-05-25 20:11:55,105 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396(104857584); kvend = 26214388(104857552); length = 9/6553600
2014-05-25 20:11:55,113 INFO [org.apache.hadoop.mapred.MapTask] - Finished spill 0
2014-05-25 20:11:55,121 INFO [org.apache.hadoop.mapred.Task] - Task:attempt_local196560459_0001_m_000001_0 is done. And is in the process of committing
2014-05-25 20:11:55,135 INFO [org.apache.hadoop.mapred.LocalJobRunner] - map
2014-05-25 20:11:55,135 INFO [org.apache.hadoop.mapred.Task] - Task 'attempt_local196560459_0001_m_000001_0' done.
2014-05-25 20:11:55,136 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Finishing task: attempt_local196560459_0001_m_000001_0
2014-05-25 20:11:55,136 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Starting task: attempt_local196560459_0001_m_000002_0
2014-05-25 20:11:55,146 INFO [org.apache.hadoop.mapred.Task] -  Using ResourceCalculatorProcessTree : [ ]
2014-05-25 20:11:55,150 INFO [org.apache.hadoop.mapred.MapTask] - Processing split: hdfs://localhost:9000/data/score_in/math:0+16
2014-05-25 20:11:55,152 INFO [org.apache.hadoop.mapred.MapTask] - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-05-25 20:11:57,197 INFO [org.apache.hadoop.mapred.MapTask] - (EQUATOR) 0 kvi 26214396(104857584)
2014-05-25 20:11:57,197 INFO [org.apache.hadoop.mapred.MapTask] - mapreduce.task.io.sort.mb: 100
2014-05-25 20:11:57,197 INFO [org.apache.hadoop.mapred.MapTask] - soft limit at 83886080
2014-05-25 20:11:57,197 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufvoid = 104857600
2014-05-25 20:11:57,197 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396; length = 6553600
2014-05-25 20:11:57,219 INFO [org.apache.hadoop.mapred.LocalJobRunner] -
2014-05-25 20:11:57,220 INFO [org.apache.hadoop.mapred.MapTask] - Starting flush of map output
2014-05-25 20:11:57,220 INFO [org.apache.hadoop.mapred.MapTask] - Spilling map output
2014-05-25 20:11:57,220 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufend = 18; bufvoid = 104857600
2014-05-25 20:11:57,220 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396(104857584); kvend = 26214388(104857552); length = 9/6553600
2014-05-25 20:11:57,227 INFO [org.apache.hadoop.mapred.MapTask] - Finished spill 0
2014-05-25 20:11:57,236 INFO [org.apache.hadoop.mapred.Task] - Task:attempt_local196560459_0001_m_000002_0 is done. And is in the process of committing
2014-05-25 20:11:57,250 INFO [org.apache.hadoop.mapred.LocalJobRunner] - map
2014-05-25 20:11:57,250 INFO [org.apache.hadoop.mapred.Task] - Task 'attempt_local196560459_0001_m_000002_0' done.
2014-05-25 20:11:57,250 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Finishing task: attempt_local196560459_0001_m_000002_0
2014-05-25 20:11:57,251 INFO [org.apache.hadoop.mapred.LocalJobRunner] - map task executor complete.
2014-05-25 20:11:57,266 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Waiting for reduce tasks
2014-05-25 20:11:57,266 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Starting task: attempt_local196560459_0001_r_000000_0
2014-05-25 20:11:57,329 INFO [org.apache.hadoop.mapred.Task] -  Using ResourceCalculatorProcessTree : [ ]
2014-05-25 20:11:57,354 INFO [org.apache.hadoop.mapred.ReduceTask] - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@7f262312
2014-05-25 20:11:57,475 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - MergerManager: memoryLimit=1302488704, maxSingleShuffleLimit=325622176, mergeThreshold=859642560, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-05-25 20:11:57,501 INFO [org.apache.hadoop.mapreduce.task.reduce.EventFetcher] - attempt_local196560459_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-05-25 20:11:57,714 INFO [org.apache.hadoop.mapreduce.task.reduce.LocalFetcher] - localfetcher#1 about to shuffle output of map attempt_local196560459_0001_m_000001_0 decomp: 26 len: 30 to MEMORY
2014-05-25 20:11:57,732 INFO [org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput] - Read 26 bytes from map-output for attempt_local196560459_0001_m_000001_0
2014-05-25 20:11:57,744 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - closeInMemoryFile -> map-output of size: 26, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->26
2014-05-25 20:11:57,757 INFO [org.apache.hadoop.mapreduce.task.reduce.LocalFetcher] - localfetcher#1 about to shuffle output of map attempt_local196560459_0001_m_000000_0 decomp: 26 len: 30 to MEMORY
2014-05-25 20:11:57,760 INFO [org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput] - Read 26 bytes from map-output for attempt_local196560459_0001_m_000000_0
2014-05-25 20:11:57,760 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - closeInMemoryFile -> map-output of size: 26, inMemoryMapOutputs.size() -> 2, commitMemory -> 26, usedMemory ->52
2014-05-25 20:11:57,764 WARN [org.apache.hadoop.io.ReadaheadPool] - Failed readahead on ifile
EBADF: Bad file descriptor
at org.apache.hadoop.io.nativeio.NativeIO$POSIX.posix_fadvise(Native Method)
at org.apache.hadoop.io.nativeio.NativeIO$POSIX.posixFadviseIfPossible(NativeIO.java:263)
at org.apache.hadoop.io.nativeio.NativeIO$POSIX$CacheManipulator.posixFadviseIfPossible(NativeIO.java:142)
at org.apache.hadoop.io.ReadaheadPool$ReadaheadRequestImpl.run(ReadaheadPool.java:206)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2014-05-25 20:11:57,769 INFO [org.apache.hadoop.mapreduce.task.reduce.LocalFetcher] - localfetcher#1 about to shuffle output of map attempt_local196560459_0001_m_000002_0 decomp: 26 len: 30 to MEMORY
2014-05-25 20:11:57,778 INFO [org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput] - Read 26 bytes from map-output for attempt_local196560459_0001_m_000002_0
2014-05-25 20:11:57,778 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - closeInMemoryFile -> map-output of size: 26, inMemoryMapOutputs.size() -> 3, commitMemory -> 52, usedMemory ->78
2014-05-25 20:11:57,784 INFO [org.apache.hadoop.mapreduce.task.reduce.EventFetcher] - EventFetcher is interrupted.. Returning
2014-05-25 20:11:57,784 WARN [org.apache.hadoop.io.ReadaheadPool] - Failed readahead on ifile
EBADF: Bad file descriptor
at org.apache.hadoop.io.nativeio.NativeIO$POSIX.posix_fadvise(Native Method)
at org.apache.hadoop.io.nativeio.NativeIO$POSIX.posixFadviseIfPossible(NativeIO.java:263)
at org.apache.hadoop.io.nativeio.NativeIO$POSIX$CacheManipulator.posixFadviseIfPossible(NativeIO.java:142)
at org.apache.hadoop.io.ReadaheadPool$ReadaheadRequestImpl.run(ReadaheadPool.java:206)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2014-05-25 20:11:57,793 INFO [org.apache.hadoop.mapred.LocalJobRunner] - 3 / 3 copied.
2014-05-25 20:11:57,793 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - finalMerge called with 3 in-memory map-outputs and 0 on-disk map-outputs
2014-05-25 20:11:57,829 INFO [org.apache.hadoop.mapred.Merger] - Merging 3 sorted segments
2014-05-25 20:11:57,830 INFO [org.apache.hadoop.mapred.Merger] - Down to the last merge-pass, with 3 segments left of total size: 66 bytes
2014-05-25 20:11:57,840 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - Merged 3 segments, 78 bytes to disk to satisfy reduce memory limit
2014-05-25 20:11:57,841 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - Merging 1 files, 78 bytes from disk
2014-05-25 20:11:57,844 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - Merging 0 segments, 0 bytes from memory into reduce
2014-05-25 20:11:57,844 INFO [org.apache.hadoop.mapred.Merger] - Merging 1 sorted segments
2014-05-25 20:11:57,847 INFO [org.apache.hadoop.mapred.Merger] - Down to the last merge-pass, with 1 segments left of total size: 70 bytes
2014-05-25 20:11:57,850 INFO [org.apache.hadoop.mapred.LocalJobRunner] - 3 / 3 copied.
2014-05-25 20:11:57,970 INFO [org.apache.hadoop.conf.Configuration.deprecation] - mapred.skip.on is deprecated. Instead, use mapreduce.job.skiprecords
2014-05-25 20:11:58,616 INFO [org.apache.hadoop.mapred.Task] - Task:attempt_local196560459_0001_r_000000_0 is done. And is in the process of committing
2014-05-25 20:11:58,628 INFO [org.apache.hadoop.mapred.LocalJobRunner] - 3 / 3 copied.
2014-05-25 20:11:58,629 INFO [org.apache.hadoop.mapred.Task] - Task attempt_local196560459_0001_r_000000_0 is allowed to commit now
2014-05-25 20:11:58,667 INFO [org.apache.hadoop.mapreduce.lib.output.FileOutputCommitter] - Saved output of task 'attempt_local196560459_0001_r_000000_0' to hdfs://localhost:9000/data/score_out3/_temporary/0/task_local196560459_0001_r_000000
2014-05-25 20:11:58,672 INFO [org.apache.hadoop.mapred.LocalJobRunner] - reduce > reduce
2014-05-25 20:11:58,673 INFO [org.apache.hadoop.mapred.Task] - Task 'attempt_local196560459_0001_r_000000_0' done.
2014-05-25 20:11:58,673 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Finishing task: attempt_local196560459_0001_r_000000_0
2014-05-25 20:11:58,673 INFO [org.apache.hadoop.mapred.LocalJobRunner] - reduce task executor complete.
2014-05-25 20:11:59,034 INFO [org.apache.hadoop.mapreduce.Job] -  map 100% reduce 100%
2014-05-25 20:11:59,035 INFO [org.apache.hadoop.mapreduce.Job] - Job job_local196560459_0001 completed successfully
2014-05-25 20:11:59,099 INFO [org.apache.hadoop.mapreduce.Job] - Counters: 38
File System Counters
FILE: Number of bytes read=3536
FILE: Number of bytes written=883072
FILE: Number of read operations=0
FILE: Number of large read operations=0
FILE: Number of write operations=0
HDFS: Number of bytes read=144
HDFS: Number of bytes written=16
HDFS: Number of read operations=37
HDFS: Number of large read operations=0
HDFS: Number of write operations=6
Map-Reduce Framework
Map input records=9
Map output records=9
Map output bytes=54
Map output materialized bytes=90
Input split bytes=321
Combine input records=0
Combine output records=0
Reduce input groups=3
Reduce shuffle bytes=90
Reduce input records=9
Reduce output records=3
Spilled Records=18
Shuffled Maps =3
Failed Shuffles=0
Merged Map outputs=3
GC time elapsed (ms)=188
CPU time spent (ms)=0
Physical memory (bytes) snapshot=0
Virtual memory (bytes) snapshot=0
Total committed heap usage (bytes)=1585971200
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Input Format Counters
Bytes Read=48
File Output Format Counters
Bytes Written=16