今天应业务方要求,找一个指定URL在HDFS原始日志中的记录条数,为了方便, 就直接使用hadoop-examples-*.jar包中的 grep 作业。
    提交作业

  1. [root@localhost yinjie]>hadoop jar $HADOOP_HOME/hadoop-examples-*.jar grep -Dmapred.job.queue.name=cp_normal_job_queue /group/*****/2011-08-12/00 /group/*****/grep/2011-08-12/00 'www.****.cn'  
  2. 11/08/31 17:12:39 INFO hdfs.DFSClient: Created HDFS_DELEGATION_TOKEN token 140330 for yinjie  
  3. 11/08/31 17:12:39 INFO security.TokenCache: Got dt for hdfs://*****.com/home/hdfs/cluster-data/tmp/mapred/staging/yinjie/.staging/job_201108241351_24681;uri=****:8020;t.service=****:8020  
  4. 11/08/31 17:12:39 INFO lzo.GPLNativeCodeLoader: Loaded native gpl library  
  5. 11/08/31 17:12:39 INFO lzo.LzoCodec: Successfully loaded & initialized native-lzo library [hadoop-lzo rev 2ad6654f3e9cad97d13f716e51a0509253c0aabb]  
  6. 11/08/31 17:12:39 INFO mapred.FileInputFormat: Total input paths to process : 22  
  7. 11/08/31 17:12:40 INFO mapred.JobClient: Running job: job_201108241351_24681  
  8. 11/08/31 17:12:41 INFO mapred.JobClient:  map 0% reduce 0%  
  9. 11/08/31 17:12:50 INFO mapred.JobClient:  map 4% reduce 0%  
  10. 11/08/31 17:12:51 INFO mapred.JobClient:  map 52% reduce 0%  
  11. 11/08/31 17:12:52 INFO mapred.JobClient:  map 60% reduce 0%  
  12. 11/08/31 17:12:53 INFO mapred.JobClient:  map 69% reduce 0%  
  13. 11/08/31 17:12:54 INFO mapred.JobClient:  map 79% reduce 0%  
  14. 11/08/31 17:12:55 INFO mapred.JobClient:  map 84% reduce 0%  
  15. 11/08/31 17:12:56 INFO mapred.JobClient:  map 90% reduce 0%  
  16. 11/08/31 17:12:57 INFO mapred.JobClient:  map 93% reduce 0%  
  17. 11/08/31 17:12:58 INFO mapred.JobClient:  map 95% reduce 27%  
  18. 11/08/31 17:12:59 INFO mapred.JobClient:  map 97% reduce 27%  
  19. 11/08/31 17:13:01 INFO mapred.JobClient:  map 98% reduce 27%  
  20. 11/08/31 17:13:05 INFO mapred.JobClient:  map 99% reduce 27%  
  21. 11/08/31 17:13:07 INFO mapred.JobClient:  map 99% reduce 32%  
  22. 11/08/31 17:13:09 INFO mapred.JobClient:  map 100% reduce 32%  
  23. 11/08/31 17:13:14 INFO mapred.JobClient:  map 100% reduce 100%  
  24. 11/08/31 17:13:15 INFO mapred.JobClient: Job complete: job_201108241351_24681  
  25. 11/08/31 17:13:15 INFO mapred.JobClient: Counters: 24  
  26. 11/08/31 17:13:15 INFO mapred.JobClient:   Job Counters   
  27. 11/08/31 17:13:15 INFO mapred.JobClient:     Launched reduce tasks=1 
  28. 11/08/31 17:13:15 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=1542961 
  29. 11/08/31 17:13:15 INFO mapred.JobClient:     Total time spent by all reduces waiting after reserving slots (ms)=0  
  30. 11/08/31 17:13:15 INFO mapred.JobClient:     Total time spent by all maps waiting after reserving slots (ms)=0  
  31. 11/08/31 17:13:15 INFO mapred.JobClient:     Rack-local map tasks=44 
  32. 11/08/31 17:13:15 INFO mapred.JobClient:     Launched map tasks=242 
  33. 11/08/31 17:13:15 INFO mapred.JobClient:     Data-local map tasks=198 
  34. 11/08/31 17:13:15 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=23291 
  35. 11/08/31 17:13:15 INFO mapred.JobClient:   FileSystemCounters  
  36. 11/08/31 17:13:15 INFO mapred.JobClient:     FILE_BYTES_READ=3724 
  37. 11/08/31 17:13:15 INFO mapred.JobClient:     HDFS_BYTES_READ=32281139322 
  38. 11/08/31 17:13:15 INFO mapred.JobClient:     FILE_BYTES_WRITTEN=14502646 
  39. 11/08/31 17:13:15 INFO mapred.JobClient:     HDFS_BYTES_WRITTEN=118 
  40. 11/08/31 17:13:15 INFO mapred.JobClient:   Map-Reduce Framework  
  41. 11/08/31 17:13:15 INFO mapred.JobClient:     Reduce input groups=1 
  42. 11/08/31 17:13:15 INFO mapred.JobClient:     Combine output records=143 
  43. 11/08/31 17:13:15 INFO mapred.JobClient:     Map input records=37526374 
  44. 11/08/31 17:13:15 INFO mapred.JobClient:     Reduce shuffle bytes=5164 
  45. 11/08/31 17:13:15 INFO mapred.JobClient:     Reduce output records=1 
  46. 11/08/31 17:13:15 INFO mapred.JobClient:     Spilled Records=286 
  47. 11/08/31 17:13:15 INFO mapred.JobClient:     Map output bytes=786984 
  48. 11/08/31 17:13:15 INFO mapred.JobClient:     Map input bytes=32280203347 
  49. 11/08/31 17:13:15 INFO mapred.JobClient:     Combine input records=32791 
  50. 11/08/31 17:13:15 INFO mapred.JobClient:     Map output records=32791 
  51. 11/08/31 17:13:15 INFO mapred.JobClient:     SPLIT_RAW_BYTES=38731 
  52. 11/08/31 17:13:15 INFO mapred.JobClient:     Reduce input records=143 
  53. 11/08/31 17:13:15 WARN mapred.JobClient: Use GenericOptionsParser for parsing the arguments. Applications should implement Tool for the same.  
  54. 11/08/31 17:13:15 INFO hdfs.DFSClient: Created HDFS_DELEGATION_TOKEN token 140331 for yinjie  
  55. 11/08/31 17:13:15 INFO security.TokenCache: Got dt for hdfs://****.com/home/hdfs/cluster-data/tmp/mapred/staging/yinjie/.staging/job_201108241351_24682;uri=****:8020;t.service=****:8020  
  56. 11/08/31 17:13:15 INFO mapred.FileInputFormat: Total input paths to process : 1  
  57. 11/08/31 17:13:15 INFO mapred.JobClient: Cleaning up the staging area hdfs://****.com/home/hdfs/cluster-data/tmp/mapred/staging/yinjie/.staging/job_201108241351_24682  
  58. org.apache.hadoop.ipc.RemoteException: java.io.IOException: java.lang.NullPointerException  
  59.         at org.apache.hadoop.mapred.QueueManager.getQueueACL(QueueManager.java:382)  
  60.         at org.apache.hadoop.mapred.JobTracker.getQueueAdmins(JobTracker.java:4422)  
  61.         at sun.reflect.GeneratedMethodAccessor18.invoke(Unknown Source)  
  62.         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)  
  63.         at java.lang.reflect.Method.invoke(Method.java:597)  
  64.         at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:557)  
  65.         at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1434)  
  66.         at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1430)  
  67.         at java.security.AccessController.doPrivileged(Native Method)  
  68.         at javax.security.auth.Subject.doAs(Subject.java:396)  
  69.         at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1127)  
  70.         at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1428)  
  71.  
  72.         at org.apache.hadoop.ipc.Client.call(Client.java:1107)  
  73.         at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:226)  
  74.         at org.apache.hadoop.mapred.$Proxy6.getQueueAdmins(Unknown Source)  
  75.         at org.apache.hadoop.mapred.JobClient$2.run(JobClient.java:886)  
  76.         at org.apache.hadoop.mapred.JobClient$2.run(JobClient.java:833)  
  77.         at java.security.AccessController.doPrivileged(Native Method)  
  78.         at javax.security.auth.Subject.doAs(Subject.java:396)  
  79.         at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1127)  
  80.         at org.apache.hadoop.mapred.JobClient.submitJobInternal(JobClient.java:833)  
  81.         at org.apache.hadoop.mapred.JobClient.submitJob(JobClient.java:807)  
  82.         at org.apache.hadoop.mapred.JobClient.runJob(JobClient.java:1242)  
  83.         at org.apache.hadoop.examples.Grep.run(Grep.java:84)  
  84.         at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:65)  
  85.         at org.apache.hadoop.examples.Grep.main(Grep.java:93)  
  86.         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)  
  87.         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)  
  88.         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)  
  89.         at java.lang.reflect.Method.invoke(Method.java:597)  
  90.         at org.apache.hadoop.util.ProgramDriver$ProgramDescription.invoke(ProgramDriver.java:68)  
  91.         at org.apache.hadoop.util.ProgramDriver.driver(ProgramDriver.java:139)  
  92.         at org.apache.hadoop.examples.ExampleDriver.main(ExampleDriver.java:64)  
  93.         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)  
  94.         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)  
  95.         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)  
  96.         at java.lang.reflect.Method.invoke(Method.java:597)  
  97.         at org.apache.hadoop.util.RunJar.main(RunJar.java:186)  
  98. [root@localhost yinjie]> 

发现有错, 比较奇怪, 第一个job成功执行, 第二个却失败了, 从异常来看应该是访问控制权限问题。提交的作业中指定了
-Dmapred.job.queue.name=cp_normal_job_queue 参数, 怀疑是不是第一个作业执行时带上该参数, 但后面一个作业没有带上,导致失败
只好先查看下$HADOOP_HOME下的conf配置:

  1. [root@localhost yinjie]>cat $HADOOP_HOME/conf/mapred-site.xml  
  2. <?xml version="1.0"?> 
  3. <?xml-stylesheet type="text/xsl" href="configuration.xsl"?> 
  4. <configuration> 
  5. <property> 
  6.   <name>mapred.job.queue.name</name> 
  7.   <value>cp_admin_job_queue</value> 
  8.   <description> Queue to which a job is submitted. This must match one of the  
  9.     queues defined in mapred.queue.names for the system. Also, the ACL setup  
  10.     for the queue must allow the current user to submit a job to the queue.  
  11.     Before specifying a queue, ensure that the system is configured with  
  12.     the queue, and access is allowed for submitting jobs to the queue.  
  13.   </description> 
  14. </property> 
  15. ....  
  16. ....  
  17. ....  
  18. </configuration> 

发现mapred.job.queue.name配置值是cp_admin_job_queue而不是提交作业时指定的cp_normal_job_queue, 会不会是第二个作业使用了cp_admin_job_queue值而导致失败。
抱着试试的心态,把$HADOOP_HOME/conf配置文件拷贝一份到当前用户目录下

  1. [root@localhost yinjie]>cp -rf $HADOOP_HOME/conf ./  
  2. ....  
  3. [root@localhost yinjie/conf]>ls  
  4. allslaves               configuration.xsl  fair-scheduler.xml  hadoop-metrics.properties  hdfs-site.xml     mapred-queue-acls.xml  masters  ssl-client.xml.example  
  5. capacity-scheduler.xml  core-site.xml      hadoop-env.sh       hadoop-policy.xml          log4j.properties  mapred-site.xml        slaves   ssl-server.xml.example  
  6. [root@localhost yinjie/conf]> 
  7. [root@localhost yinjie/conf]>vi mapred-site.xml  

编辑mapred-site.xml, 把mapred.job.queue.name修改成cp_normal_job_queue 后保存
再一次提交作业,使用 --config 参数指定修改后的配置目录

  1. [root@localhost yinjie]>hadoop --config /home/yinjie/conf jar $HADOOP_HOME/hadoop-examples-*.jar grep -Dmapred.job.queue.name=cp_normal_job_queue /group/*****/2011-08-12/01 /group/*****/grep/2011-08-12/01 'www.****.cn'  
  2. 11/08/31 17:25:19 INFO hdfs.DFSClient: Created HDFS_DELEGATION_TOKEN token 140356 for yinjie  
  3. 11/08/31 17:25:19 INFO security.TokenCache: Got dt for hdfs://****.com/home/hdfs/cluster-data/tmp/mapred/staging/yinjie/.staging/job_201108241351_24719;uri=****:8020;t.service=****:8020  
  4. 11/08/31 17:25:19 INFO lzo.GPLNativeCodeLoader: Loaded native gpl library  
  5. 11/08/31 17:25:19 INFO lzo.LzoCodec: Successfully loaded & initialized native-lzo library [hadoop-lzo rev 2ad6654f3e9cad97d13f716e51a0509253c0aabb]  
  6. 11/08/31 17:25:19 INFO mapred.FileInputFormat: Total input paths to process : 22  
  7. 11/08/31 17:25:19 INFO mapred.JobClient: Running job: job_201108241351_24719  
  8. 11/08/31 17:25:20 INFO mapred.JobClient:  map 0% reduce 0%  
  9. 11/08/31 17:25:30 INFO mapred.JobClient:  map 4% reduce 0%  
  10. 11/08/31 17:25:31 INFO mapred.JobClient:  map 14% reduce 0%  
  11. 11/08/31 17:25:32 INFO mapred.JobClient:  map 51% reduce 0%  
  12. 11/08/31 17:25:33 INFO mapred.JobClient:  map 63% reduce 0%  
  13. 11/08/31 17:25:34 INFO mapred.JobClient:  map 68% reduce 0%  
  14. 11/08/31 17:25:35 INFO mapred.JobClient:  map 77% reduce 0%  
  15. 11/08/31 17:25:36 INFO mapred.JobClient:  map 87% reduce 0%  
  16. 11/08/31 17:25:37 INFO mapred.JobClient:  map 93% reduce 0%  
  17. 11/08/31 17:25:38 INFO mapred.JobClient:  map 96% reduce 0%  
  18. 11/08/31 17:25:39 INFO mapred.JobClient:  map 97% reduce 0%  
  19. 11/08/31 17:25:40 INFO mapred.JobClient:  map 98% reduce 0%  
  20. 11/08/31 17:25:42 INFO mapred.JobClient:  map 99% reduce 31%  
  21. 11/08/31 17:25:48 INFO mapred.JobClient:  map 100% reduce 31%  
  22. 11/08/31 17:25:51 INFO mapred.JobClient:  map 100% reduce 33%  
  23. 11/08/31 17:25:53 INFO mapred.JobClient:  map 100% reduce 100%  
  24. 11/08/31 17:25:53 INFO mapred.JobClient: Job complete: job_201108241351_24719  
  25. 11/08/31 17:25:53 INFO mapred.JobClient: Counters: 24  
  26. 11/08/31 17:25:53 INFO mapred.JobClient:   Job Counters   
  27. 11/08/31 17:25:53 INFO mapred.JobClient:     Launched reduce tasks=1 
  28. 11/08/31 17:25:53 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=1025313 
  29. 11/08/31 17:25:53 INFO mapred.JobClient:     Total time spent by all reduces waiting after reserving slots (ms)=0  
  30. 11/08/31 17:25:53 INFO mapred.JobClient:     Total time spent by all maps waiting after reserving slots (ms)=0  
  31. 11/08/31 17:25:53 INFO mapred.JobClient:     Rack-local map tasks=26 
  32. 11/08/31 17:25:53 INFO mapred.JobClient:     Launched map tasks=176 
  33. 11/08/31 17:25:53 INFO mapred.JobClient:     Data-local map tasks=150 
  34. 11/08/31 17:25:53 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=18297 
  35. 11/08/31 17:25:53 INFO mapred.JobClient:   FileSystemCounters  
  36. 11/08/31 17:25:53 INFO mapred.JobClient:     FILE_BYTES_READ=2580 
  37. 11/08/31 17:25:53 INFO mapred.JobClient:     HDFS_BYTES_READ=22352133231 
  38. 11/08/31 17:25:53 INFO mapred.JobClient:     FILE_BYTES_WRITTEN=10563326 
  39. 11/08/31 17:25:53 INFO mapred.JobClient:     HDFS_BYTES_WRITTEN=118 
  40. 11/08/31 17:25:53 INFO mapred.JobClient:   Map-Reduce Framework  
  41. 11/08/31 17:25:53 INFO mapred.JobClient:     Reduce input groups=1 
  42. 11/08/31 17:25:53 INFO mapred.JobClient:     Combine output records=99 
  43. 11/08/31 17:25:53 INFO mapred.JobClient:     Map input records=26525927 
  44. 11/08/31 17:25:53 INFO mapred.JobClient:     Reduce shuffle bytes=3624 
  45. 11/08/31 17:25:53 INFO mapred.JobClient:     Reduce output records=1 
  46. 11/08/31 17:25:53 INFO mapred.JobClient:     Spilled Records=198 
  47. 11/08/31 17:25:53 INFO mapred.JobClient:     Map output bytes=515064 
  48. 11/08/31 17:25:53 INFO mapred.JobClient:     Map input bytes=22351478236 
  49. 11/08/31 17:25:53 INFO mapred.JobClient:     Combine input records=21461 
  50. 11/08/31 17:25:53 INFO mapred.JobClient:     Map output records=21461 
  51. 11/08/31 17:25:53 INFO mapred.JobClient:     SPLIT_RAW_BYTES=28153 
  52. 11/08/31 17:25:53 INFO mapred.JobClient:     Reduce input records=99 
  53. 11/08/31 17:25:53 WARN mapred.JobClient: Use GenericOptionsParser for parsing the arguments. Applications should implement Tool for the same.  
  54. 11/08/31 17:25:53 INFO hdfs.DFSClient: Created HDFS_DELEGATION_TOKEN token 140359 for yinjie  
  55. 11/08/31 17:25:53 INFO security.TokenCache: Got dt for hdfs://****.com/home/hdfs/cluster-data/tmp/mapred/staging/yinjie/.staging/job_201108241351_24723;uri=****:8020;t.service=****:8020  
  56. 11/08/31 17:25:53 INFO mapred.FileInputFormat: Total input paths to process : 1  
  57. 11/08/31 17:25:53 INFO mapred.JobClient: Running job: job_201108241351_24723  
  58. 11/08/31 17:25:54 INFO mapred.JobClient:  map 0% reduce 0%  
  59. 11/08/31 17:26:01 INFO mapred.JobClient:  map 100% reduce 0%  
  60. 11/08/31 17:26:13 INFO mapred.JobClient:  map 100% reduce 100%  
  61. 11/08/31 17:26:13 INFO mapred.JobClient: Job complete: job_201108241351_24723  
  62. 11/08/31 17:26:13 INFO mapred.JobClient: Counters: 23  
  63. 11/08/31 17:26:13 INFO mapred.JobClient:   Job Counters   
  64. 11/08/31 17:26:13 INFO mapred.JobClient:     Launched reduce tasks=1 
  65. 11/08/31 17:26:13 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=3225 
  66. 11/08/31 17:26:13 INFO mapred.JobClient:     Total time spent by all reduces waiting after reserving slots (ms)=0  
  67. 11/08/31 17:26:13 INFO mapred.JobClient:     Total time spent by all maps waiting after reserving slots (ms)=0  
  68. 11/08/31 17:26:13 INFO mapred.JobClient:     Launched map tasks=1 
  69. 11/08/31 17:26:13 INFO mapred.JobClient:     Data-local map tasks=1 
  70. 11/08/31 17:26:13 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=8191 
  71. 11/08/31 17:26:13 INFO mapred.JobClient:   FileSystemCounters  
  72. 11/08/31 17:26:13 INFO mapred.JobClient:     FILE_BYTES_READ=32 
  73. 11/08/31 17:26:13 INFO mapred.JobClient:     HDFS_BYTES_READ=248 
  74. 11/08/31 17:26:13 INFO mapred.JobClient:     FILE_BYTES_WRITTEN=117216 
  75. 11/08/31 17:26:13 INFO mapred.JobClient:     HDFS_BYTES_WRITTEN=22 
  76. 11/08/31 17:26:13 INFO mapred.JobClient:   Map-Reduce Framework  
  77. 11/08/31 17:26:13 INFO mapred.JobClient:     Reduce input groups=1 
  78. 11/08/31 17:26:13 INFO mapred.JobClient:     Combine output records=0 
  79. 11/08/31 17:26:13 INFO mapred.JobClient:     Map input records=1 
  80. 11/08/31 17:26:13 INFO mapred.JobClient:     Reduce shuffle bytes=0 
  81. 11/08/31 17:26:13 INFO mapred.JobClient:     Reduce output records=1 
  82. 11/08/31 17:26:13 INFO mapred.JobClient:     Spilled Records=2 
  83. 11/08/31 17:26:13 INFO mapred.JobClient:     Map output bytes=24 
  84. 11/08/31 17:26:13 INFO mapred.JobClient:     Map input bytes=32 
  85. 11/08/31 17:26:13 INFO mapred.JobClient:     Combine input records=0 
  86. 11/08/31 17:26:13 INFO mapred.JobClient:     Map output records=1 
  87. 11/08/31 17:26:13 INFO mapred.JobClient:     SPLIT_RAW_BYTES=130 
  88. 11/08/31 17:26:13 INFO mapred.JobClient:     Reduce input records=1 

OK, 作业成功了!