hadoop-common-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Satoshi Yamada <bigtvioletb...@yahoo.co.jp>
Subject NNBench in Hadoop 0.21.0
Date Mon, 15 Nov 2010 14:17:46 GMT
Hi,

I just ran NNBench in my cluster with hadoop-0.21.0 and got exceptions. I had no successful file operations.

I've run NNBench in the same cluster with hadoop-0.20.2 without any exceptions or # maps that missed the barrier.

So, I would like to ask if you have some tips to run NNBench in hadoop-0.21.0 or if it is a bug.


Thanks, in advance.
satoshi 

Here are outputs and logs.


 ***********************************************************
 
[hadoop@guest0 hadoop-0.21.0]$ ./bin/hadoop jar hadoop-mapred-test-0.21.0.jar nnbench -operation create_write
NameNode Benchmark 0.4
10/11/15 12:57:47 INFO hdfs.NNBench: Test Inputs: 
10/11/15 12:57:47 INFO hdfs.NNBench:            Test Operation: create_write
10/11/15 12:57:47 INFO hdfs.NNBench:                Start time: 2010-11-15 12:59:47,598
10/11/15 12:57:47 INFO hdfs.NNBench:            Number of maps: 1
10/11/15 12:57:47 INFO hdfs.NNBench:         Number of reduces: 1
10/11/15 12:57:47 INFO hdfs.NNBench:                Block Size: 1
10/11/15 12:57:47 INFO hdfs.NNBench:            Bytes to write: 0
10/11/15 12:57:47 INFO hdfs.NNBench:        Bytes per checksum: 1
10/11/15 12:57:47 INFO hdfs.NNBench:           Number of files: 1
10/11/15 12:57:47 INFO hdfs.NNBench:        Replication factor: 1
10/11/15 12:57:47 INFO hdfs.NNBench:                  Base dir: /benchmarks/NNBench
10/11/15 12:57:47 INFO hdfs.NNBench:      Read file after open: false
10/11/15 12:57:47 INFO security.Groups: Group mapping impl=org.apache.hadoop.security.ShellBasedUnixGroupsMapping; cacheTimeout=300000
10/11/15 12:57:47 WARN conf.Configuration: mapred.task.id is deprecated. Instead, use mapreduce.task.attempt.id
10/11/15 12:57:48 INFO hdfs.NNBench: Deleting data directory
10/11/15 12:57:48 INFO hdfs.NNBench: Creating 1 control files
10/11/15 12:57:52 WARN mapreduce.JobSubmitter: Use GenericOptionsParser for parsing the arguments. Applications should implement Tool for the same.
10/11/15 12:57:52 INFO mapred.FileInputFormat: Total input paths to process : 1
10/11/15 12:57:52 WARN conf.Configuration: mapred.map.tasks is deprecated. Instead, use mapreduce.job.maps
10/11/15 12:57:52 INFO mapreduce.JobSubmitter: number of splits:1
10/11/15 12:57:53 INFO mapreduce.JobSubmitter: adding the following namenodes' delegation tokens:null
10/11/15 12:57:53 INFO mapreduce.Job: Running job: job_201011151256_0001
10/11/15 12:57:54 INFO mapreduce.Job:  map 0% reduce 0%
10/11/15 12:58:09 INFO mapreduce.Job:  map 66% reduce 0%
10/11/15 12:59:52 INFO mapreduce.Job:  map 100% reduce 0%
10/11/15 12:59:58 INFO mapreduce.Job:  map 100% reduce 100%
10/11/15 13:00:00 INFO mapreduce.Job: Job complete: job_201011151256_0001
10/11/15 13:00:00 INFO mapreduce.Job: Counters: 33
        FileInputFormatCounters
                BYTES_READ=38
        FileSystemCounters
                FILE_BYTES_READ=187
                FILE_BYTES_WRITTEN=406
                HDFS_BYTES_READ=244
                HDFS_BYTES_WRITTEN=167
        Shuffle Errors
                BAD_ID=0
                CONNECTION=0
                IO_ERROR=0
                WRONG_LENGTH=0
                WRONG_MAP=0
                WRONG_REDUCE=0
        Job Counters 
                Data-local map tasks=1
                Total time spent by all maps waiting after reserving slots (ms)=0
                Total time spent by all reduces waiting after reserving slots (ms)=0
                SLOTS_MILLIS_MAPS=111798
                SLOTS_MILLIS_REDUCES=3516
                Launched map tasks=1
                Launched reduce tasks=1
        Map-Reduce Framework
                Combine input records=0
                Combine output records=0
                Failed Shuffles=0
                GC time elapsed (ms)=79
                Map input records=1
                Map output bytes=167
                Map output records=7
                Merged Map outputs=1
                Reduce input groups=7
                Reduce input records=7
                Reduce output records=7
                Reduce shuffle bytes=187
                Shuffled Maps =1
                Spilled Records=14
                SPLIT_RAW_BYTES=120
10/11/15 13:00:00 INFO hdfs.NNBench: -------------- NNBench -------------- : 
10/11/15 13:00:00 INFO hdfs.NNBench:                                Version: NameNode Benchmark 0.4
10/11/15 13:00:00 INFO hdfs.NNBench:                            Date & time: 2010-11-15 13:00:00,570
10/11/15 13:00:00 INFO hdfs.NNBench: 
10/11/15 13:00:00 INFO hdfs.NNBench:                         Test Operation: create_write
10/11/15 13:00:00 INFO hdfs.NNBench:                             Start time: 2010-11-15 12:59:47,598
10/11/15 13:00:00 INFO hdfs.NNBench:                            Maps to run: 1
10/11/15 13:00:00 INFO hdfs.NNBench:                         Reduces to run: 1
10/11/15 13:00:00 INFO hdfs.NNBench:                     Block Size (bytes): 1
10/11/15 13:00:00 INFO hdfs.NNBench:                         Bytes to write: 0
10/11/15 13:00:00 INFO hdfs.NNBench:                     Bytes per checksum: 1
10/11/15 13:00:00 INFO hdfs.NNBench:                        Number of files: 1
10/11/15 13:00:00 INFO hdfs.NNBench:                     Replication factor: 1
10/11/15 13:00:00 INFO hdfs.NNBench:             Successful file operations: 0
10/11/15 13:00:00 INFO hdfs.NNBench: 
10/11/15 13:00:00 INFO hdfs.NNBench:         # maps that missed the barrier: 0
10/11/15 13:00:00 INFO hdfs.NNBench:                           # exceptions: 1000
10/11/15 13:00:00 INFO hdfs.NNBench: 
10/11/15 13:00:00 INFO hdfs.NNBench:                TPS: Create/Write/Close: 0
10/11/15 13:00:00 INFO hdfs.NNBench: Avg exec time (ms): Create/Write/Close: Infinity
10/11/15 13:00:00 INFO hdfs.NNBench:             Avg Lat (ms): Create/Write: NaN
10/11/15 13:00:00 INFO hdfs.NNBench:                    Avg Lat (ms): Close: NaN
10/11/15 13:00:00 INFO hdfs.NNBench: 
10/11/15 13:00:00 INFO hdfs.NNBench:                  RAW DATA: AL Total #1: 0
10/11/15 13:00:00 INFO hdfs.NNBench:                  RAW DATA: AL Total #2: 0
10/11/15 13:00:00 INFO hdfs.NNBench:               RAW DATA: TPS Total (ms): 146
10/11/15 13:00:00 INFO hdfs.NNBench:        RAW DATA: Longest Map Time (ms): 146.0
10/11/15 13:00:00 INFO hdfs.NNBench:                    RAW DATA: Late maps: 0
10/11/15 13:00:00 INFO hdfs.NNBench:              RAW DATA: # of exceptions: 1000
10/11/15 13:00:00 INFO hdfs.NNBench: 

 
 ***********************************************************
 

logs from tasktracker. I found some error messages in it.


 ***********************************************************
 
2010-11-15 13:05:00,897 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201011151256_0002_m_000002_0 task's state:UNASSIGNED
2010-11-15 13:05:00,898 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201011151256_0002_m_000002_0 which needs 1 slots
2010-11-15 13:05:00,898 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 64 and trying to launch attempt_201011151256_0002_m_000002_0 which needs 1 slots
2010-11-15 13:05:00,898 INFO org.apache.hadoop.mapreduce.server.tasktracker.Localizer: User-directories for the user hadoop are already initialized on this TT. Not doing anything.
2010-11-15 13:05:01,167 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201011151256_0002_m_398522298
2010-11-15 13:05:01,167 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201011151256_0002_m_398522298 spawned.
2010-11-15 13:05:02,004 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201011151256_0002_m_398522298 given task: attempt_201011151256_0002_m_000002_0
2010-11-15 13:05:02,522 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_m_000002_0 0.0% setup > map
2010-11-15 13:05:02,523 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201011151256_0002_m_000002_0 is done.
2010-11-15 13:05:02,523 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201011151256_0002_m_000002_0  was -1
2010-11-15 13:05:02,526 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 64
2010-11-15 13:05:02,812 WARN org.apache.hadoop.mapreduce.util.ProcessTree: Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException: kill -2477: No such process

2010-11-15 13:05:02,812 INFO org.apache.hadoop.mapreduce.util.ProcessTree: Sending signal to all members of process group -2477: SIGTERM. Exit code 1
2010-11-15 13:05:03,916 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201011151256_0002_m_000000_0 task's state:UNASSIGNED
2010-11-15 13:05:03,917 INFO org.apache.hadoop.mapred.TaskTracker: Received KillTaskAction for task: attempt_201011151256_0002_m_000002_0
2010-11-15 13:05:03,917 INFO org.apache.hadoop.mapred.TaskTracker: About to purge task: attempt_201011151256_0002_m_000002_0
2010-11-15 13:05:03,918 INFO org.apache.hadoop.mapred.TaskRunner: attempt_201011151256_0002_m_000002_0 done; removing files.
2010-11-15 13:05:03,919 INFO org.apache.hadoop.mapred.IndexCache: Map ID attempt_201011151256_0002_m_000002_0 not found in cache
2010-11-15 13:05:03,920 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201011151256_0002_m_000000_0 which needs 1 slots
2010-11-15 13:05:03,920 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 64 and trying to launch attempt_201011151256_0002_m_000000_0 which needs 1 slots
2010-11-15 13:05:03,920 INFO org.apache.hadoop.mapreduce.server.tasktracker.Localizer: User-directories for the user hadoop are already initialized on this TT. Not doing anything.
2010-11-15 13:05:04,061 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201011151256_0002_m_-1524314987
2010-11-15 13:05:04,062 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201011151256_0002_m_-1524314987 spawned.
2010-11-15 13:05:04,926 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201011151256_0002_m_-1524314987 given task: attempt_201011151256_0002_m_000000_0
2010-11-15 13:05:07,885 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201011151256_0002_m_398522298 exited with exit code 0. Number of tasks it ran: 1
2010-11-15 13:05:11,386 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_m_000000_0 0.667% hdfs://guest0:64310/benchmarks/NNBench/control/NNBench_Controlfile_0:0+124 > map
2010-11-15 13:06:58,538 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_m_000000_0 0.667% hdfs://guest0:64310/benchmarks/NNBench/control/NNBench_Controlfile_0:0+124 > map
2010-11-15 13:06:58,560 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_m_000000_0 0.667% hdfs://guest0:64310/benchmarks/NNBench/control/NNBench_Controlfile_0:0+124 > sort
2010-11-15 13:06:58,560 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201011151256_0002_m_000000_0 is done.
2010-11-15 13:06:58,560 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201011151256_0002_m_000000_0  was 187
2010-11-15 13:06:58,561 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 64
2010-11-15 13:06:58,790 WARN org.apache.hadoop.mapreduce.util.ProcessTree: Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException: kill -2518: No such process

2010-11-15 13:06:58,790 INFO org.apache.hadoop.mapreduce.util.ProcessTree: Sending signal to all members of process group -2518: SIGTERM. Exit code 1
2010-11-15 13:07:01,239 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201011151256_0002_r_000000_0 task's state:UNASSIGNED
2010-11-15 13:07:01,239 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201011151256_0002_r_000000_0 which needs 1 slots
2010-11-15 13:07:01,239 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 8 and trying to launch attempt_201011151256_0002_r_000000_0 which needs 1 slots
2010-11-15 13:07:01,239 INFO org.apache.hadoop.mapreduce.server.tasktracker.Localizer: User-directories for the user hadoop are already initialized on this TT. Not doing anything.
2010-11-15 13:07:01,314 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201011151256_0002_r_148464420
2010-11-15 13:07:01,315 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201011151256_0002_r_148464420 spawned.
2010-11-15 13:07:02,187 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201011151256_0002_r_148464420 given task: attempt_201011151256_0002_r_000000_0
2010-11-15 13:07:03,298 INFO org.apache.hadoop.mapred.TaskTracker: Sent out 187 bytes to reduce 0 from map: attempt_201011151256_0002_m_000000_0 given 187/183
2010-11-15 13:07:03,298 INFO org.apache.hadoop.mapred.TaskTracker: Shuffled 1maps (mapIds=attempt_201011151256_0002_m_000000_0) to reduce 0 in 3s
2010-11-15 13:07:03,299 INFO org.apache.hadoop.mapred.TaskTracker.clienttrace: src: 192.168.122.21:50060, dest: 192.168.122.21:47877, maps: 1, op: MAPRED_SHUFFLE, reduceID: 0, duration: 3
2010-11-15 13:07:03,308 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_r_000000_0 0.0% 1 / 1 copied.
2010-11-15 13:07:03,342 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_r_000000_0 0.0% 1 / 1 copied.
2010-11-15 13:07:03,471 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201011151256_0002_r_000000_0 is in commit-pending, task state:COMMIT_PENDING
2010-11-15 13:07:03,471 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_r_000000_0 0.0% 1 / 1 copied.
2010-11-15 13:07:03,865 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201011151256_0002_m_-1524314987 exited with exit code 0. Number of tasks it ran: 1
2010-11-15 13:07:04,300 INFO org.apache.hadoop.mapred.TaskTracker: Received commit task action for attempt_201011151256_0002_r_000000_0
2010-11-15 13:07:04,503 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_r_000000_0 1.0% finished min:mapStartTimeTPmS ::host = guest2 > reduce
2010-11-15 13:07:04,510 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201011151256_0002_r_000000_0 is done.
2010-11-15 13:07:04,510 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201011151256_0002_r_000000_0  was -1
2010-11-15 13:07:04,512 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 8
2010-11-15 13:07:04,778 WARN org.apache.hadoop.mapreduce.util.ProcessTree: Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException: kill -2570: No such process

2010-11-15 13:07:04,778 INFO org.apache.hadoop.mapreduce.util.ProcessTree: Sending signal to all members of process group -2570: SIGTERM. Exit code 1
2010-11-15 13:07:07,484 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201011151256_0002_m_000001_0 task's state:UNASSIGNED
2010-11-15 13:07:07,484 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201011151256_0002_m_000001_0 which needs 1 slots
2010-11-15 13:07:07,484 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 64 and trying to launch attempt_201011151256_0002_m_000001_0 which needs 1 slots
2010-11-15 13:07:07,484 INFO org.apache.hadoop.mapreduce.server.tasktracker.Localizer: User-directories for the user hadoop are already initialized on this TT. Not doing anything.
2010-11-15 13:07:07,512 INFO org.apache.hadoop.mapred.TaskTracker: Received KillTaskAction for task: attempt_201011151256_0002_r_000000_0
2010-11-15 13:07:07,513 INFO org.apache.hadoop.mapred.TaskTracker: About to purge task: attempt_201011151256_0002_r_000000_0
2010-11-15 13:07:07,513 INFO org.apache.hadoop.mapred.TaskRunner: attempt_201011151256_0002_r_000000_0 done; removing files.
2010-11-15 13:07:07,584 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201011151256_0002_m_982149053
2010-11-15 13:07:07,585 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201011151256_0002_m_982149053 spawned.
2010-11-15 13:07:08,538 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201011151256_0002_m_982149053 given task: attempt_201011151256_0002_m_000001_0
2010-11-15 13:07:08,962 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_m_000001_0 0.0% 
2010-11-15 13:07:09,050 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201011151256_0002_m_000001_0 0.0% cleanup > map
2010-11-15 13:07:09,054 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201011151256_0002_m_000001_0 is done.
2010-11-15 13:07:09,054 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201011151256_0002_m_000001_0  was -1
2010-11-15 13:07:09,078 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 64
2010-11-15 13:07:09,183 WARN org.apache.hadoop.mapreduce.util.ProcessTree: Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException: kill -2629: No such process

2010-11-15 13:07:09,183 INFO org.apache.hadoop.mapreduce.util.ProcessTree: Sending signal to all members of process group -2629: SIGTERM. Exit code 1
2010-11-15 13:07:09,800 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201011151256_0002_r_148464420 exited with exit code 0. Number of tasks it ran: 1
2010-11-15 13:07:10,573 INFO org.apache.hadoop.mapred.TaskTracker: Received 'KillJobAction' for job: job_201011151256_0002
2010-11-15 13:07:10,574 INFO org.apache.hadoop.mapred.TaskRunner: attempt_201011151256_0002_m_000000_0 done; removing files.
2010-11-15 13:07:10,576 INFO org.apache.hadoop.mapred.TaskRunner: attempt_201011151256_0002_m_000001_0 done; removing files.
2010-11-15 13:07:10,577 INFO org.apache.hadoop.mapred.IndexCache: Map ID attempt_201011151256_0002_m_000001_0 not found in cache
2010-11-15 13:07:10,577 INFO org.apache.hadoop.mapred.UserLogCleaner: Adding job_201011151256_0002 for user-log deletion with retainTimeStamp:1289912830577
2010-11-15 13:07:14,206 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201011151256_0002_m_982149053 exited with exit code 0. Number of tasks it ran: 1


 
  ***********************************************************

namenode logs below.
 
  ***********************************************************

2010-11-15 13:04:58,811 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_7952178289902603971_1029 to 192.168.122.21:50010 
2010-11-15 13:04:58,811 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 59 Total time for transactions(ms): 2Number of transactions batched in Syncs: 1 Number of syncs: 45 SyncTimes(ms): 466 
2010-11-15 13:04:58,812 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=deletesrc=/benchmarks/NNBench/control  dst=null        perm=null
2010-11-15 13:04:58,813 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-5192109264753098555_1037 to 192.168.122.21:50010 
2010-11-15 13:04:58,814 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=deletesrc=/benchmarks/NNBench/output   dst=null        perm=null
2010-11-15 13:04:58,833 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=createsrc=/benchmarks/NNBench/control/NNBench_Controlfile_0    dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:58,851 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /benchmarks/NNBench/control/NNBench_Controlfile_0. blk_667327631922096856_1040{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
2010-11-15 13:04:58,896 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 192.168.122.21:50010 is added to blk_667327631922096856_1040{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
 size 0
2010-11-15 13:04:58,897 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /benchmarks/NNBench/control/NNBench_Controlfile_0 is closed by DFSClient_2064418803
2010-11-15 13:04:58,994 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=mkdirssrc=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002      dst=null        perm=hadoop:supergroup:rwxr-xr-x
2010-11-15 13:04:58,997 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=setPermission  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002     dst=null        perm=hadoop:supergroup:rwx------
2010-11-15 13:04:59,026 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=createsrc=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.jar      dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,068 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.jar. blk_-5982330171978228296_1041{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
 replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
2010-11-15 13:04:59,102 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 192.168.122.21:50010 is added to blk_-5982330171978228296_1041{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
 size 0
2010-11-15 13:04:59,104 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.jar is closed by DFSClient_2064418803
2010-11-15 13:04:59,106 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Increasing replication for file /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.jar. New replication is 10
2010-11-15 13:04:59,107 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=setReplication src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.jar     dst=null        perm=null
2010-11-15 13:04:59,109 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=setPermission  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.jar     dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,132 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=listStatus     src=/benchmarks/NNBench/control dst=null        perm=null
2010-11-15 13:04:59,143 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=open  src=/benchmarks/NNBench/control/NNBench_Controlfile_0    dst=null        perm=null
2010-11-15 13:04:59,151 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=createsrc=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.split    dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,153 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=setPermission  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.split   dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,156 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Increasing replication for file /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.split. New replication is 10
2010-11-15 13:04:59,156 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=setReplication src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.split   dst=null        perm=null
2010-11-15 13:04:59,158 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.split. blk_-8949513092476944942_1042{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
 replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
2010-11-15 13:04:59,162 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 192.168.122.21:50010 is added to blk_-8949513092476944942_1042{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
 size 0
2010-11-15 13:04:59,164 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.split is closed by DFSClient_2064418803
2010-11-15 13:04:59,173 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=createsrc=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.splitmetainfo    dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,549 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=setPermission  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.splitmetainfo   dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,554 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.splitmetainfo. blk_4045193522256115073_1043{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
 replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
2010-11-15 13:04:59,561 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 192.168.122.21:50010 is added to blk_4045193522256115073_1043{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
 size 0
2010-11-15 13:04:59,564 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.splitmetainfo is closed by DFSClient_2064418803
2010-11-15 13:04:59,574 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=createsrc=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.xml      dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,578 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=setPermission  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.xml     dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,700 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.xml. blk_-4637967787808166403_1044{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
 replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
2010-11-15 13:04:59,705 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 192.168.122.21:50010 is added to blk_-4637967787808166403_1044{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
 size 0
2010-11-15 13:04:59,707 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.xml is closed by DFSClient_2064418803
2010-11-15 13:04:59,714 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=open  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.xml      dst=null        perm=null
2010-11-15 13:04:59,756 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=mkdirssrc=/home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002     dst=null        perm=hadoop:supergroup:rwxr-xr-x
2010-11-15 13:04:59,757 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=setPermission  src=/home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002    dst=null        perm=hadoop:supergroup:rwx------
2010-11-15 13:04:59,763 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=createsrc=/home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002/job-info    dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,765 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002/job-info. blk_-5341196869405167887_1045{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
 replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
2010-11-15 13:04:59,773 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 192.168.122.21:50010 is added to blk_-5341196869405167887_1045{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
 size 0
2010-11-15 13:04:59,773 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002/job-info is closed by DFSClient_-827684356
2010-11-15 13:04:59,823 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=createsrc=/home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002/jobToken    dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:04:59,825 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002/jobToken. blk_6492009810912882763_1046{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
 replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
2010-11-15 13:04:59,829 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 192.168.122.21:50010 is added to blk_6492009810912882763_1046{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
 size 0
2010-11-15 13:04:59,831 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002/jobToken is closed by DFSClient_-827684356
2010-11-15 13:04:59,834 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=open  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.splitmetainfo    dst=null        perm=null
2010-11-15 13:05:00,194 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask 192.168.122.21:50010 to delete  blk_7952178289902603971_1029 blk_-5192109264753098555_1037
2010-11-15 13:05:00,905 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=open  src=/home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002/jobToken    dst=null        perm=null
2010-11-15 13:05:00,939 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=open  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.xml      dst=null        perm=null
2010-11-15 13:05:01,019 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=open  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.jar      dst=null        perm=null
2010-11-15 13:05:02,507 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=mkdirssrc=/benchmarks/NNBench/output/_temporary        dst=null        perm=hadoop:supergroup:rwxr-xr-x
2010-11-15 13:05:05,368 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=open  src=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002/job.split    dst=null        perm=null
2010-11-15 13:05:05,405 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=open  src=/benchmarks/NNBench/control/NNBench_Controlfile_0    dst=null        perm=null
2010-11-15 13:07:03,358 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 95 Total time for transactions(ms): 3Number of transactions batched in Syncs: 1 Number of syncs: 72 SyncTimes(ms): 871 
2010-11-15 13:07:03,359 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=mkdirssrc=/benchmarks/NNBench/output/_temporary/_attempt_201011151256_0002_r_000000_0  dst=null        perm=hadoop:supergroup:rwxr-xr-x
2010-11-15 13:07:03,363 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=createsrc=/benchmarks/NNBench/output/_temporary/_attempt_201011151256_0002_r_000000_0/part-00000       dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:07:03,376 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /benchmarks/NNBench/output/_temporary/_attempt_201011151256_0002_r_000000_0/part-00000. blk_-4563027756382672617_1047{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
 replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
2010-11-15 13:07:03,461 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 192.168.122.21:50010 is added to blk_-4563027756382672617_1047{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
 size 0
2010-11-15 13:07:03,463 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /benchmarks/NNBench/output/_temporary/_attempt_201011151256_0002_r_000000_0/part-00000 is closed by DFSClient_attempt_201011151256_0002_r_000000_0
2010-11-15 13:07:04,484 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=listStatus     src=/benchmarks/NNBench/output/_temporary/_attempt_201011151256_0002_r_000000_0 dst=null        perm=null
2010-11-15 13:07:04,489 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=mkdirssrc=/benchmarks/NNBench/output   dst=null        perm=hadoop:supergroup:rwxr-xr-x
2010-11-15 13:07:04,494 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=renamesrc=/benchmarks/NNBench/output/_temporary/_attempt_201011151256_0002_r_000000_0/part-00000       dst=/benchmarks/NNBench/output/part-00000
 perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:07:04,497 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=deletesrc=/benchmarks/NNBench/output/_temporary/_attempt_201011151256_0002_r_000000_0  dst=null        perm=null
2010-11-15 13:07:08,968 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=deletesrc=/benchmarks/NNBench/output/_temporary        dst=null        perm=null
2010-11-15 13:07:08,975 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=createsrc=/benchmarks/NNBench/output/_SUCCESS  dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:07:08,982 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /benchmarks/NNBench/output/_SUCCESS is closed by DFSClient_attempt_201011151256_0002_m_000001_0
2010-11-15 13:07:09,034 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-5982330171978228296_1041 to 192.168.122.21:50010 
2010-11-15 13:07:09,034 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-8949513092476944942_1042 to 192.168.122.21:50010 
2010-11-15 13:07:09,034 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_4045193522256115073_1043 to 192.168.122.21:50010 
2010-11-15 13:07:09,034 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-4637967787808166403_1044 to 192.168.122.21:50010 
2010-11-15 13:07:09,035 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.21      cmd=deletesrc=/tmp/hadoop-hadoop/mapred/staging/hadoop/.staging/job_201011151256_0002      dst=null        perm=null
2010-11-15 13:07:09,374 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask 192.168.122.21:50010 to delete  blk_4045193522256115073_1043 blk_-8949513092476944942_1042 blk_-5982330171978228296_1041 blk_-4637967787808166403_1044
2010-11-15 13:07:10,512 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=createsrc=/jobtracker/jobsInfo/job_201011151256_0002.info      dst=null        perm=hadoop:supergroup:rw-r--r--
2010-11-15 13:07:10,517 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /jobtracker/jobsInfo/job_201011151256_0002.info. blk_-63779571351333019_1049{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
2010-11-15 13:07:10,533 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 192.168.122.21:50010 is added to blk_-63779571351333019_1049{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[192.168.122.21:50010|RBW]]}
 size 0
2010-11-15 13:07:10,535 INFO org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.completeFile: file /jobtracker/jobsInfo/job_201011151256_0002.info is closed by DFSClient_-827684356
2010-11-15 13:07:10,600 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-5341196869405167887_1045 to 192.168.122.21:50010 
2010-11-15 13:07:10,600 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_6492009810912882763_1046 to 192.168.122.21:50010 
2010-11-15 13:07:10,601 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=deletesrc=/home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002     dst=null        perm=null
2010-11-15 13:07:11,418 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=open  src=/jobtracker/jobsInfo/job_201011151256_0002.info      dst=null        perm=null
2010-11-15 13:07:11,433 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.212     cmd=open  src=/jobtracker/jobsInfo/job_201011151256_0002.info      dst=null        perm=null
2010-11-15 13:07:11,475 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem.audit: ugi=hadoop      ip=/192.168.122.242     cmd=open  src=/benchmarks/NNBench/output/part-00000        dst=null        perm=null
2010-11-15 13:07:12,406 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* ask 192.168.122.21:50010 to delete  blk_-5341196869405167887_1045 blk_6492009810912882763_1046


**********************************************

jobtracker logs below

***********************************************

2010-11-15 13:04:59,776 INFO org.apache.hadoop.mapred.JobTracker: Initializing job_201011151256_0002
2010-11-15 13:04:59,776 INFO org.apache.hadoop.mapred.JobInProgress: Initializing job_201011151256_0002
2010-11-15 13:04:59,783 INFO org.apache.hadoop.mapreduce.jobhistory.JobHistory: SetupWriter, creating file file:/home/hadoop/hadoop-dist2/hadoop-0.21.0/logs/history/job_201011151256_0002_hadoop
2010-11-15 13:04:59,793 INFO org.apache.hadoop.mapred.JobTracker: Job job_201011151256_0002 added successfully for user 'hadoop' to queue 'default'
2010-11-15 13:04:59,803 INFO org.apache.hadoop.mapreduce.jobhistory.JobHistory: LogDirConfPath is file:/home/hadoop/hadoop-dist2/hadoop-0.21.0/logs/history/job_201011151256_0002_conf.xml
2010-11-15 13:04:59,832 INFO org.apache.hadoop.mapred.JobInProgress: jobToken generated and stored with users keys in /home/hadoop/hadoop-dist2/filesystem/mapred/system/job_201011151256_0002/jobToken
2010-11-15 13:04:59,837 INFO org.apache.hadoop.mapred.JobInProgress: Input size for job job_201011151256_0002 = 124. Number of splits = 1
2010-11-15 13:04:59,837 INFO org.apache.hadoop.mapred.JobInProgress: tip:task_201011151256_0002_m_000000 has split on node:/default-rack/guest2
2010-11-15 13:04:59,837 INFO org.apache.hadoop.mapred.JobInProgress: Job job_201011151256_0002 initialized successfully with 1 map tasks and 1 reduce tasks.
2010-11-15 13:05:00,894 INFO org.apache.hadoop.mapred.JobTracker: Adding task (JOB_SETUP) 'attempt_201011151256_0002_m_000002_0' to tip task_201011151256_0002_m_000002, for tracker 'tracker_guest2:localhost.localdomain/127.0.0.1:41953'
2010-11-15 13:05:03,908 INFO org.apache.hadoop.mapred.JobInProgress: Task 'attempt_201011151256_0002_m_000002_0' has completed task_201011151256_0002_m_000002 successfully.
2010-11-15 13:05:03,912 INFO org.apache.hadoop.mapred.JobTracker: Adding task (MAP) 'attempt_201011151256_0002_m_000000_0' to tip task_201011151256_0002_m_000000, for tracker 'tracker_guest2:localhost.localdomain/127.0.0.1:41953'
2010-11-15 13:05:03,913 INFO org.apache.hadoop.mapred.JobInProgress: Choosing data-local task task_201011151256_0002_m_000000
2010-11-15 13:07:01,232 INFO org.apache.hadoop.mapred.JobInProgress: Task 'attempt_201011151256_0002_m_000000_0' has completed task_201011151256_0002_m_000000 successfully.
2010-11-15 13:07:01,236 INFO org.apache.hadoop.mapred.JobTracker: Adding task (REDUCE) 'attempt_201011151256_0002_r_000000_0' to tip task_201011151256_0002_r_000000, for tracker 'tracker_guest2:localhost.localdomain/127.0.0.1:41953'
2010-11-15 13:07:07,476 INFO org.apache.hadoop.mapred.JobInProgress: Task 'attempt_201011151256_0002_r_000000_0' has completed task_201011151256_0002_r_000000 successfully.
2010-11-15 13:07:07,481 INFO org.apache.hadoop.mapred.JobTracker: Adding task (JOB_CLEANUP) 'attempt_201011151256_0002_m_000001_0' to tip task_201011151256_0002_m_000001, for tracker 'tracker_guest2:localhost.localdomain/127.0.0.1:41953'
2010-11-15 13:07:10,496 INFO org.apache.hadoop.mapred.JobInProgress: Task 'attempt_201011151256_0002_m_000001_0' has completed task_201011151256_0002_m_000001 successfully.
2010-11-15 13:07:10,499 INFO org.apache.hadoop.mapred.JobInProgress: Job job_201011151256_0002 has completed successfully.
2010-11-15 13:07:10,500 INFO org.apache.hadoop.mapred.JobInProgress$JobSummary:
 jobId=job_201011151256_0002,submitTime=1289826299709,launchTime=1289826299837,finishTime=1289826430499,numMaps=1,numSlotsPerMap=1,numReduces=1,numSlotsPerReduce=1,user=hadoop,queue=default,status=SUCCEEDED,mapSlotSeconds=117,reduceSlotsSeconds=3,clusterMapCapacity=64,clusterReduceCapacity=8
2010-11-15 13:07:10,571 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201011151256_0002_m_000000_0'
2010-11-15 13:07:10,572 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201011151256_0002_m_000001_0'
2010-11-15 13:07:10,572 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201011151256_0002_m_000002_0'
2010-11-15 13:07:10,572 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201011151256_0002_r_000000_0'
2010-11-15 13:07:10,573 INFO org.apache.hadoop.mapreduce.jobhistory.JobHistory: Moving file:/home/hadoop/hadoop-dist2/hadoop-0.21.0/logs/history/job_201011151256_0002_hadoop to file:/home/hadoop/hadoop-dist2/hadoop-0.21.0/logs/history/done/job_201011151256_0002_hadoop
2010-11-15 13:07:10,616 INFO org.apache.hadoop.mapreduce.jobhistory.JobHistory: Moving file:/home/hadoop/hadoop-dist2/hadoop-0.21.0/logs/history/job_201011151256_0002_conf.xml to file:/home/hadoop/hadoop-dist2/hadoop-0.21.0/logs/history/done/job_201011151256_0002_conf.xml
2010-11-15 13:07:10,646 INFO org.apache.hadoop.mapred.JobInProgress: Deleting localized job conf at /home/hadoop/hadoop-dist2/hadoop-0.21.0/bin/../logs/job_201011151256_0002_conf.xml
2010-11-15 13:07:10,647 INFO org.apache.hadoop.mapred.JobTracker: Retired job with id: 'job_201011151256_0002' of user 'hadoop'


******************************************

datanode logs

*********************************************

2010-11-15 13:04:58,890 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_667327631922096856_1040 src: /192.168.122.242:39421 dest: /192.168.122.21:50010
2010-11-15 13:04:58,895 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.242:39421, dest: /192.168.122.21:50010, bytes: 124, op: HDFS_WRITE, cliID: DFSClient_2064418803, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_667327631922096856_1040, duration: 2570000
2010-11-15 13:04:58,895 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block blk_667327631922096856_1040 terminating
2010-11-15 13:04:59,070 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_-5982330171978228296_1041 src: /192.168.122.242:39423 dest: /192.168.122.21:50010
2010-11-15 13:04:59,101 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.242:39423, dest: /192.168.122.21:50010, bytes: 1492025, op: HDFS_WRITE, cliID: DFSClient_2064418803, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-5982330171978228296_1041, duration: 28422000
2010-11-15 13:04:59,101 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block blk_-5982330171978228296_1041 terminating
2010-11-15 13:04:59,159 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_-8949513092476944942_1042 src: /192.168.122.242:39424 dest: /192.168.122.21:50010
2010-11-15 13:04:59,162 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.242:39424, dest: /192.168.122.21:50010, bytes: 127, op: HDFS_WRITE, cliID: DFSClient_2064418803, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-8949513092476944942_1042, duration: 1103000
2010-11-15 13:04:59,162 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block blk_-8949513092476944942_1042 terminating
2010-11-15 13:04:59,556 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_4045193522256115073_1043 src: /192.168.122.242:39425 dest: /192.168.122.21:50010
2010-11-15 13:04:59,561 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.242:39425, dest: /192.168.122.21:50010, bytes: 20, op: HDFS_WRITE, cliID: DFSClient_2064418803, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_4045193522256115073_1043, duration: 2213000
2010-11-15 13:04:59,562 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block blk_4045193522256115073_1043 terminating
2010-11-15 13:04:59,700 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_-4637967787808166403_1044 src: /192.168.122.242:39426 dest: /192.168.122.21:50010
2010-11-15 13:04:59,704 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.242:39426, dest: /192.168.122.21:50010, bytes: 33698, op: HDFS_WRITE, cliID: DFSClient_2064418803, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-4637967787808166403_1044, duration: 1968000
2010-11-15 13:04:59,705 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block blk_-4637967787808166403_1044 terminating
2010-11-15 13:04:59,725 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.212:48816, bytes: 33962, op: HDFS_READ, cliID: DFSClient_-2033075547, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-4637967787808166403_1044, duration: 647000
2010-11-15 13:04:59,766 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_-5341196869405167887_1045 src: /192.168.122.212:48817 dest: /192.168.122.21:50010
2010-11-15 13:04:59,769 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.212:48817, dest: /192.168.122.21:50010, bytes: 118, op: HDFS_WRITE, cliID: DFSClient_-827684356, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-5341196869405167887_1045, duration: 1228000
2010-11-15 13:04:59,769 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block blk_-5341196869405167887_1045 terminating
2010-11-15 13:04:59,826 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_6492009810912882763_1046 src: /192.168.122.212:48818 dest: /192.168.122.21:50010
2010-11-15 13:04:59,829 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.212:48818, dest: /192.168.122.21:50010, bytes: 101, op: HDFS_WRITE, cliID: DFSClient_-827684356, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_6492009810912882763_1046, duration: 1146000
2010-11-15 13:04:59,829 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block blk_6492009810912882763_1046 terminating
2010-11-15 13:04:59,836 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.212:48819, bytes: 24, op: HDFS_READ, cliID: DFSClient_-2033075547, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_4045193522256115073_1043, duration: 288000
2010-11-15 13:05:00,925 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.21:45356, bytes: 105, op: HDFS_READ, cliID: DFSClient_275878657, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_6492009810912882763_1046, duration: 231000
2010-11-15 13:05:00,954 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.21:45358, bytes: 33962, op: HDFS_READ, cliID: DFSClient_-1502261171, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-4637967787808166403_1044, duration: 265000
2010-11-15 13:05:01,074 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.21:45359, bytes: 1503685, op: HDFS_READ, cliID: DFSClient_-1502261171, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-5982330171978228296_1041, duration: 37232000
2010-11-15 13:05:02,679 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Scheduling block blk_-5192109264753098555_1037 file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-5192109264753098555 for deletion
2010-11-15 13:05:02,690 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Scheduling block blk_7952178289902603971_1029 file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_7952178289902603971 for deletion
2010-11-15 13:05:02,690 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Deleted block blk_-5192109264753098555_1037 at file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-5192109264753098555
2010-11-15 13:05:02,690 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Deleted block blk_7952178289902603971_1029 at file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_7952178289902603971
2010-11-15 13:05:05,379 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.21:45364, bytes: 131, op: HDFS_READ, cliID: DFSClient_attempt_201011151256_0002_m_000000_0, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460,
 blockid: blk_-8949513092476944942_1042, duration: 235000
2010-11-15 13:05:05,410 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.21:45365, bytes: 128, op: HDFS_READ, cliID: DFSClient_attempt_201011151256_0002_m_000000_0, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460,
 blockid: blk_667327631922096856_1040, duration: 232000
2010-11-15 13:07:03,456 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_-4563027756382672617_1047 src: /192.168.122.21:45370 dest: /192.168.122.21:50010
2010-11-15 13:07:03,460 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:45370, dest: /192.168.122.21:50010, bytes: 167, op: HDFS_WRITE, cliID: DFSClient_attempt_201011151256_0002_r_000000_0, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460,
 blockid: blk_-4563027756382672617_1047, duration: 2622000
2010-11-15 13:07:03,460 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block blk_-4563027756382672617_1047 terminating
2010-11-15 13:07:10,519 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_-63779571351333019_1049 src: /192.168.122.212:48840 dest: /192.168.122.21:50010
2010-11-15 13:07:10,532 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.212:48840, dest: /192.168.122.21:50010, bytes: 2113, op: HDFS_WRITE, cliID: DFSClient_-827684356, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-63779571351333019_1049, duration: 10257000
2010-11-15 13:07:10,533 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder 0 for block blk_-63779571351333019_1049 terminating
2010-11-15 13:07:11,422 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.212:48841, bytes: 2133, op: HDFS_READ, cliID: DFSClient_-827684356, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-63779571351333019_1049, duration: 684000
2010-11-15 13:07:11,436 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.212:48842, bytes: 2133, op: HDFS_READ, cliID: DFSClient_-827684356, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-63779571351333019_1049, duration: 553000
2010-11-15 13:07:11,483 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.122.21:50010, dest: /192.168.122.242:42366, bytes: 171, op: HDFS_READ, cliID: DFSClient_2064418803, offset: 0, srvID: DS-2050198494-192.168.122.21-50010-1289741482460, blockid:
 blk_-4563027756382672617_1047, duration: 526000
2010-11-15 13:07:11,872 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Scheduling block blk_-8949513092476944942_1042 file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-8949513092476944942 for deletion
2010-11-15 13:07:11,873 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Scheduling block blk_-5982330171978228296_1041 file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-5982330171978228296 for deletion
2010-11-15 13:07:11,873 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Scheduling block blk_-4637967787808166403_1044 file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-4637967787808166403 for deletion
2010-11-15 13:07:11,873 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Scheduling block blk_4045193522256115073_1043 file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_4045193522256115073 for deletion
2010-11-15 13:07:11,874 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Deleted block blk_-8949513092476944942_1042 at file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-8949513092476944942
2010-11-15 13:07:11,875 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Deleted block blk_-5982330171978228296_1041 at file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-5982330171978228296
2010-11-15 13:07:11,875 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Deleted block blk_-4637967787808166403_1044 at file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-4637967787808166403
2010-11-15 13:07:11,875 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Deleted block blk_4045193522256115073_1043 at file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_4045193522256115073
2010-11-15 13:07:14,876 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Scheduling block blk_-5341196869405167887_1045 file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-5341196869405167887 for deletion
2010-11-15 13:07:14,877 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Scheduling block blk_6492009810912882763_1046 file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_6492009810912882763 for deletion
2010-11-15 13:07:14,877 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Deleted block blk_-5341196869405167887_1045 at file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_-5341196869405167887
2010-11-15 13:07:14,877 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Deleted block blk_6492009810912882763_1046 at file /home/hadoop/hadoop-dist2/filesystem/data/current/finalized/blk_6492009810912882763
2010-11-15 13:07:17,759 INFO org.apache.hadoop.hdfs.server.datanode.DataBlockScanner: Verification succeeded for blk_6610282913947390908_1017

 

 
---------------------------------
Get the new Internet Explorer 8 optimized for Yahoo! JAPAN

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message