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, stdoutlog4j.appender.stdout=org.apache.log4j.ConsoleAppenderlog4j.appender.stdout.layout=org.apache.log4j.PatternLayoutlog4j.appender.stdout.layout.ConversionPattern=%d %p [%c] - %m%nlog4j.appender.logfile=org.apache.log4j.FileAppenderlog4j.appender.logfile.File=target/spring.loglog4j.appender.logfile.layout=org.apache.log4j.PatternLayoutlog4j.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-id2014-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 : 32014-05-25 20:11:49,496 INFO [org.apache.hadoop.mapreduce.JobSubmitter] - number of splits:32014-05-25 20:11:50,155 INFO [org.apache.hadoop.mapreduce.JobSubmitter] - Submitting tokens for job: job_local196560459_00012014-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_00012014-05-25 20:11:50,983 INFO [org.apache.hadoop.mapred.LocalJobRunner] - OutputCommitter set in config null2014-05-25 20:11:51,011 INFO [org.apache.hadoop.mapred.LocalJobRunner] - OutputCommitter is org.apache.hadoop.mapreduce.lib.output.FileOutputCommitter2014-05-25 20:11:51,252 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Waiting for map tasks2014-05-25 20:11:51,256 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Starting task: attempt_local196560459_0001_m_000000_02014-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+162014-05-25 20:11:51,557 INFO [org.apache.hadoop.mapred.MapTask] - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer2014-05-25 20:11:52,000 INFO [org.apache.hadoop.mapreduce.Job] - Job job_local196560459_0001 running in uber mode : false2014-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: 1002014-05-25 20:11:52,984 INFO [org.apache.hadoop.mapred.MapTask] - soft limit at 838860802014-05-25 20:11:52,984 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufvoid = 1048576002014-05-25 20:11:52,984 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396; length = 65536002014-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 output2014-05-25 20:11:53,434 INFO [org.apache.hadoop.mapred.MapTask] - Spilling map output2014-05-25 20:11:53,434 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufend = 18; bufvoid = 1048576002014-05-25 20:11:53,434 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396(104857584); kvend = 26214388(104857552); length = 9/65536002014-05-25 20:11:53,474 INFO [org.apache.hadoop.mapred.MapTask] - Finished spill 02014-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 committing2014-05-25 20:11:53,535 INFO [org.apache.hadoop.mapred.LocalJobRunner] - map2014-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_02014-05-25 20:11:53,536 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Starting task: attempt_local196560459_0001_m_000001_02014-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+162014-05-25 20:11:53,553 INFO [org.apache.hadoop.mapred.MapTask] - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer2014-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: 1002014-05-25 20:11:55,083 INFO [org.apache.hadoop.mapred.MapTask] - soft limit at 838860802014-05-25 20:11:55,083 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufvoid = 1048576002014-05-25 20:11:55,083 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396; length = 65536002014-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 output2014-05-25 20:11:55,104 INFO [org.apache.hadoop.mapred.MapTask] - Spilling map output2014-05-25 20:11:55,105 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufend = 18; bufvoid = 1048576002014-05-25 20:11:55,105 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396(104857584); kvend = 26214388(104857552); length = 9/65536002014-05-25 20:11:55,113 INFO [org.apache.hadoop.mapred.MapTask] - Finished spill 02014-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 committing2014-05-25 20:11:55,135 INFO [org.apache.hadoop.mapred.LocalJobRunner] - map2014-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_02014-05-25 20:11:55,136 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Starting task: attempt_local196560459_0001_m_000002_02014-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+162014-05-25 20:11:55,152 INFO [org.apache.hadoop.mapred.MapTask] - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer2014-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: 1002014-05-25 20:11:57,197 INFO [org.apache.hadoop.mapred.MapTask] - soft limit at 838860802014-05-25 20:11:57,197 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufvoid = 1048576002014-05-25 20:11:57,197 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396; length = 65536002014-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 output2014-05-25 20:11:57,220 INFO [org.apache.hadoop.mapred.MapTask] - Spilling map output2014-05-25 20:11:57,220 INFO [org.apache.hadoop.mapred.MapTask] - bufstart = 0; bufend = 18; bufvoid = 1048576002014-05-25 20:11:57,220 INFO [org.apache.hadoop.mapred.MapTask] - kvstart = 26214396(104857584); kvend = 26214388(104857552); length = 9/65536002014-05-25 20:11:57,227 INFO [org.apache.hadoop.mapred.MapTask] - Finished spill 02014-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 committing2014-05-25 20:11:57,250 INFO [org.apache.hadoop.mapred.LocalJobRunner] - map2014-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_02014-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 tasks2014-05-25 20:11:57,266 INFO [org.apache.hadoop.mapred.LocalJobRunner] - Starting task: attempt_local196560459_0001_r_000000_02014-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@7f2623122014-05-25 20:11:57,475 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - MergerManager: memoryLimit=1302488704, maxSingleShuffleLimit=325622176, mergeThreshold=859642560, ioSortFactor=10, memToMemMergeOutputsThreshold=102014-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 Events2014-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 MEMORY2014-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_02014-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 ->262014-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 MEMORY2014-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_02014-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 ->522014-05-25 20:11:57,764 WARN [org.apache.hadoop.io.ReadaheadPool] - Failed readahead on ifileEBADF: Bad file descriptorat 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 MEMORY2014-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_02014-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 ->782014-05-25 20:11:57,784 INFO [org.apache.hadoop.mapreduce.task.reduce.EventFetcher] - EventFetcher is interrupted.. Returning2014-05-25 20:11:57,784 WARN [org.apache.hadoop.io.ReadaheadPool] - Failed readahead on ifileEBADF: Bad file descriptorat 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-outputs2014-05-25 20:11:57,829 INFO [org.apache.hadoop.mapred.Merger] - Merging 3 sorted segments2014-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 bytes2014-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 limit2014-05-25 20:11:57,841 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - Merging 1 files, 78 bytes from disk2014-05-25 20:11:57,844 INFO [org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl] - Merging 0 segments, 0 bytes from memory into reduce2014-05-25 20:11:57,844 INFO [org.apache.hadoop.mapred.Merger] - Merging 1 sorted segments2014-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 bytes2014-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.skiprecords2014-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 committing2014-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 now2014-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_0000002014-05-25 20:11:58,672 INFO [org.apache.hadoop.mapred.LocalJobRunner] - reduce > reduce2014-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_02014-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 successfully2014-05-25 20:11:59,099 INFO [org.apache.hadoop.mapreduce.Job] - Counters: 38File System CountersFILE: Number of bytes read=3536FILE: Number of bytes written=883072FILE: Number of read operations=0FILE: Number of large read operations=0FILE: Number of write operations=0HDFS: Number of bytes read=144HDFS: Number of bytes written=16HDFS: Number of read operations=37HDFS: Number of large read operations=0HDFS: Number of write operations=6Map-Reduce FrameworkMap input records=9Map output records=9Map output bytes=54Map output materialized bytes=90Input split bytes=321Combine input records=0Combine output records=0Reduce input groups=3Reduce shuffle bytes=90Reduce input records=9Reduce output records=3Spilled Records=18Shuffled Maps =3Failed Shuffles=0Merged Map outputs=3GC time elapsed (ms)=188CPU time spent (ms)=0Physical memory (bytes) snapshot=0Virtual memory (bytes) snapshot=0Total committed heap usage (bytes)=1585971200Shuffle ErrorsBAD_ID=0CONNECTION=0IO_ERROR=0WRONG_LENGTH=0WRONG_MAP=0WRONG_REDUCE=0File Input Format Counters Bytes Read=48File Output Format Counters Bytes Written=16