incubator-giraph-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jianfeng Qian (Commented) (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (GIRAPH-169) How to close all child when a job finished?
Date Thu, 29 Mar 2012 11:56:25 GMT

    [ https://issues.apache.org/jira/browse/GIRAPH-169?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13241163#comment-13241163 ] 

Jianfeng Qian commented on GIRAPH-169:
--------------------------------------

I use a persudo hadoop platform and there is the command and logs
 bin/hadoop jar lib/giraph-0.2-all.jar org.apache.giraph.benchmark.PageRankBenchmark -e 1 -s 10
 -v -V 1000 -w 2
12/03/29 19:43:24 INFO benchmark.PageRankBenchmark: Using class org.apache.giraph.benchmark.HashMapVertexPageRankBenchmark
12/03/29 19:43:24 WARN bsp.BspOutputFormat: checkOutputSpecs: ImmutableOutputCommiter will not check anything
12/03/29 19:43:24 INFO mapred.JobClient: Running job: job_201203291941_0001
12/03/29 19:43:25 INFO mapred.JobClient:  map 0% reduce 0%
12/03/29 19:43:43 INFO mapred.JobClient:  map 33% reduce 0%
12/03/29 19:43:46 INFO mapred.JobClient:  map 66% reduce 0%
12/03/29 19:43:49 INFO mapred.JobClient:  map 100% reduce 0%
12/03/29 19:43:54 INFO mapred.JobClient: Job complete: job_201203291941_0001
12/03/29 19:43:54 INFO mapred.JobClient: Counters: 42
12/03/29 19:43:54 INFO mapred.JobClient:   Job Counters 
12/03/29 19:43:54 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=38014
12/03/29 19:43:54 INFO mapred.JobClient:     Total time spent by all reduces waiting after reserving slots (ms)=0
12/03/29 19:43:54 INFO mapred.JobClient:     Total time spent by all maps waiting after reserving slots (ms)=0
12/03/29 19:43:54 INFO mapred.JobClient:     Launched map tasks=3
12/03/29 19:43:54 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=0
12/03/29 19:43:54 INFO mapred.JobClient:   Giraph Timers
12/03/29 19:43:54 INFO mapred.JobClient:     Total (milliseconds)=7515
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 3 (milliseconds)=328
12/03/29 19:43:54 INFO mapred.JobClient:     Vertex input superstep (milliseconds)=293
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 4 (milliseconds)=296
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 10 (milliseconds)=240
12/03/29 19:43:54 INFO mapred.JobClient:     Setup (milliseconds)=3245
12/03/29 19:43:54 INFO mapred.JobClient:     Shutdown (milliseconds)=432
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 7 (milliseconds)=301
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 0 (milliseconds)=473
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 8 (milliseconds)=300
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 9 (milliseconds)=330
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 6 (milliseconds)=330
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 5 (milliseconds)=282
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 2 (milliseconds)=307
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep 1 (milliseconds)=354
12/03/29 19:43:54 INFO mapred.JobClient:   Giraph Stats
12/03/29 19:43:54 INFO mapred.JobClient:     Aggregate edges=1000
12/03/29 19:43:54 INFO mapred.JobClient:     Superstep=11
12/03/29 19:43:54 INFO mapred.JobClient:     Last checkpointed superstep=0
12/03/29 19:43:54 INFO mapred.JobClient:     Current workers=2
12/03/29 19:43:54 INFO mapred.JobClient:     Current master task partition=0
12/03/29 19:43:54 INFO mapred.JobClient:     Sent messages=0
12/03/29 19:43:54 INFO mapred.JobClient:     Aggregate finished vertices=1000
12/03/29 19:43:54 INFO mapred.JobClient:     Aggregate vertices=1000
12/03/29 19:43:54 INFO mapred.JobClient:   File Output Format Counters 
12/03/29 19:43:54 INFO mapred.JobClient:     Bytes Written=0
12/03/29 19:43:54 INFO mapred.JobClient:   FileSystemCounters
12/03/29 19:43:54 INFO mapred.JobClient:     FILE_BYTES_READ=236
12/03/29 19:43:54 INFO mapred.JobClient:     HDFS_BYTES_READ=132
12/03/29 19:43:54 INFO mapred.JobClient:     FILE_BYTES_WRITTEN=65745
12/03/29 19:43:54 INFO mapred.JobClient:     HDFS_BYTES_WRITTEN=50186
12/03/29 19:43:54 INFO mapred.JobClient:   File Input Format Counters 
12/03/29 19:43:54 INFO mapred.JobClient:     Bytes Read=0
12/03/29 19:43:54 INFO mapred.JobClient:   Map-Reduce Framework
12/03/29 19:43:54 INFO mapred.JobClient:     Map input records=3
12/03/29 19:43:54 INFO mapred.JobClient:     Physical memory (bytes) snapshot=342470656
12/03/29 19:43:54 INFO mapred.JobClient:     Spilled Records=0
12/03/29 19:43:54 INFO mapred.JobClient:     CPU time spent (ms)=6180
12/03/29 19:43:54 INFO mapred.JobClient:     Total committed heap usage (bytes)=751239168
12/03/29 19:43:54 INFO mapred.JobClient:     Virtual memory (bytes) snapshot=7229767680
12/03/29 19:43:54 INFO mapred.JobClient:     Map output records=0
12/03/29 19:43:54 INFO mapred.JobClient:     SPLIT_RAW_BYTES=132
--------------------------------------------
Master log:
2012-03-29 19:43:34,362 WARN org.apache.hadoop.util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2012-03-29 19:43:34,626 WARN org.apache.giraph.bsp.BspOutputFormat: getOutputCommitter: Returning ImmutableOutputCommiter (does nothing).
2012-03-29 19:43:34,636 INFO org.apache.hadoop.util.ProcessTree: setsid exited with exit code 0
2012-03-29 19:43:34,643 INFO org.apache.hadoop.mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@4bf54c5f
2012-03-29 19:43:34,728 INFO org.apache.giraph.graph.GraphMapper: Distributed cache is empty. Assuming fatjar.
2012-03-29 19:43:34,728 INFO org.apache.giraph.graph.GraphMapper: setup: classpath @ /usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/jars/job.jar
2012-03-29 19:43:34,744 INFO org.apache.giraph.zk.ZooKeeperManager: createCandidateStamp: Made the directory _bsp/_defaultZkManagerDir/job_201203291941_0001
2012-03-29 19:43:34,746 INFO org.apache.giraph.zk.ZooKeeperManager: createCandidateStamp: Creating my filestamp _bsp/_defaultZkManagerDir/job_201203291941_0001/_task/tmm-e4 0
2012-03-29 19:43:34,856 INFO org.apache.giraph.zk.ZooKeeperManager: getZooKeeperServerList: Got [tmm-e4] 1 hosts from 1 candidates when 1 required (polling period is 3000) on attempt 0
2012-03-29 19:43:34,856 INFO org.apache.giraph.zk.ZooKeeperManager: createZooKeeperServerList: Creating the final ZooKeeper file '_bsp/_defaultZkManagerDir/job_201203291941_0001/zkServerList_tmm-e4 0 '
2012-03-29 19:43:34,878 INFO org.apache.giraph.zk.ZooKeeperManager: getZooKeeperServerList: For task 0, got file 'zkServerList_tmm-e4 0 ' (polling period is 3000)
2012-03-29 19:43:34,879 INFO org.apache.giraph.zk.ZooKeeperManager: getZooKeeperServerList: Found [tmm-e4, 0] 2 hosts in filename 'zkServerList_tmm-e4 0 '
2012-03-29 19:43:34,880 INFO org.apache.giraph.zk.ZooKeeperManager: onlineZooKeeperServers: Trying to delete old directory /usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/work/_bspZooKeeper
2012-03-29 19:43:34,884 INFO org.apache.giraph.zk.ZooKeeperManager: generateZooKeeperConfigFile: Creating file /usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/work/_bspZooKeeper/zoo.cfg in /usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/work/_bspZooKeeper with base port 22181
2012-03-29 19:43:34,884 INFO org.apache.giraph.zk.ZooKeeperManager: generateZooKeeperConfigFile: Make directory of _bspZooKeeper = true
2012-03-29 19:43:34,884 INFO org.apache.giraph.zk.ZooKeeperManager: generateZooKeeperConfigFile: Delete of zoo.cfg = false
2012-03-29 19:43:34,891 INFO org.apache.giraph.zk.ZooKeeperManager: onlineZooKeeperServers: Attempting to start ZooKeeper server with command [/usr/local/java/jdk1.6.0_22/jre/bin/java, -Xmx512m, -XX:ParallelGCThreads=4, -XX:+UseConcMarkSweepGC, -XX:CMSInitiatingOccupancyFraction=70, -XX:MaxGCPauseMillis=100, -cp, /usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/jars/job.jar, org.apache.zookeeper.server.quorum.QuorumPeerMain, /usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/work/_bspZooKeeper/zoo.cfg] in directory /usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/work/_bspZooKeeper
2012-03-29 19:43:34,896 INFO org.apache.giraph.zk.ZooKeeperManager: onlineZooKeeperServers: Connect attempt 0 of 10 max trying to connect to tmm-e4:22181 with poll msecs = 3000
2012-03-29 19:43:34,901 WARN org.apache.giraph.zk.ZooKeeperManager: onlineZooKeeperServers: Got ConnectException
java.net.ConnectException: Connection refused
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
	at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
	at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
	at java.net.Socket.connect(Socket.java:529)
	at org.apache.giraph.zk.ZooKeeperManager.onlineZooKeeperServers(ZooKeeperManager.java:661)
	at org.apache.giraph.graph.GraphMapper.setup(GraphMapper.java:425)
	at org.apache.giraph.graph.GraphMapper.run(GraphMapper.java:647)
	at org.apache.hadoop.mapred.MapTask.runNewMapper(MapTask.java:764)
	at org.apache.hadoop.mapred.MapTask.run(MapTask.java:370)
	at org.apache.hadoop.mapred.Child$4.run(Child.java:255)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAs(Subject.java:396)
	at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1059)
	at org.apache.hadoop.mapred.Child.main(Child.java:249)
2012-03-29 19:43:37,901 INFO org.apache.giraph.zk.ZooKeeperManager: onlineZooKeeperServers: Connect attempt 1 of 10 max trying to connect to tmm-e4:22181 with poll msecs = 3000
2012-03-29 19:43:37,902 INFO org.apache.giraph.zk.ZooKeeperManager: onlineZooKeeperServers: Connected to tmm-e4/2.1.1.124:22181!
2012-03-29 19:43:37,902 INFO org.apache.giraph.zk.ZooKeeperManager: onlineZooKeeperServers: Creating my filestamp _bsp/_defaultZkManagerDir/job_201203291941_0001/_zkServer/tmm-e4 0
2012-03-29 19:43:37,918 INFO org.apache.giraph.graph.GraphMapper: &&&setup:serverPortList is tmm-e4:22181
2012-03-29 19:43:37,918 INFO org.apache.giraph.graph.GraphMapper: setup: Starting up BspServiceMaster (master thread)...
2012-03-29 19:43:37,931 INFO org.apache.giraph.graph.BspService: BspService: Connecting to ZooKeeper with job job_201203291941_0001, 0 on tmm-e4:22181
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:zookeeper.version=3.3.3-1073969, built on 02/23/2011 22:27 GMT
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:host.name=tmm-e4
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.version=1.6.0_22
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.vendor=Sun Microsystems Inc.
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.home=/usr/local/java/jdk1.6.0_22/jre
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.class.path=/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/jars/classes:/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/jars:/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/attempt_201203291941_0001_m_000000_0/work:/usr/local/h-test/hadoop-0.20.205.0/libexec/../conf:/usr/local/java/jdk1.6.0_22/lib/tools.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/hadoop-core-0.20.205.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/asm-3.2.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/aspectjrt-1.6.5.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/aspectjtools-1.6.5.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-beanutils-1.7.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-beanutils-core-1.8.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-cli-1.2.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-codec-1.4.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-collections-3.2.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-configuration-1.6.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-daemon-1.0.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-digester-1.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-el-1.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-httpclient-3.0.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-lang-2.4.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-logging-1.1.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-logging-api-1.0.4.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-math-2.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-net-1.4.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/core-3.1.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/hadoop-capacity-scheduler-0.20.205.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/hadoop-fairscheduler-0.20.205.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/hadoop-thriftfs-0.20.205.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/hsqldb-1.8.0.10.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jackson-core-asl-1.0.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jackson-mapper-asl-1.0.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jasper-compiler-5.5.12.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jasper-runtime-5.5.12.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jdeb-0.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jersey-core-1.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jersey-json-1.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jersey-server-1.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jets3t-0.6.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jetty-6.1.26.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jetty-util-6.1.26.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jsch-0.1.42.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/junit-4.5.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/kfs-0.2.2.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/log4j-1.2.15.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/mockito-all-1.8.5.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/oro-2.0.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/servlet-api-2.5-20081211.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/slf4j-api-1.4.3.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/slf4j-log4j12-1.4.3.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/xmlenc-0.52.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jsp-2.1/jsp-2.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jsp-2.1/jsp-api-2.1.jar
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.library.path=/usr/local/h-test/hadoop-0.20.205.0/libexec/../lib:/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/attempt_201203291941_0001_m_000000_0/work
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.io.tmpdir=/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/attempt_201203291941_0001_m_000000_0/work/tmp
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.compiler=<NA>
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:os.name=Linux
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:os.arch=amd64
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:os.version=2.6.32.12-0.7-default
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:user.name=root
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:user.home=/root
2012-03-29 19:43:37,939 INFO org.apache.zookeeper.ZooKeeper: Client environment:user.dir=/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/attempt_201203291941_0001_m_000000_0/work
2012-03-29 19:43:37,940 INFO org.apache.zookeeper.ZooKeeper: Initiating client connection, connectString=tmm-e4:22181 sessionTimeout=60000 watcher=org.apache.giraph.graph.BspServiceMaster@5bf02b85
2012-03-29 19:43:37,952 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server tmm-e4/2.1.1.124:22181
2012-03-29 19:43:37,953 INFO org.apache.zookeeper.ClientCnxn: Socket connection established to tmm-e4/2.1.1.124:22181, initiating session
2012-03-29 19:43:38,030 INFO org.apache.zookeeper.ClientCnxn: Session establishment complete on server tmm-e4/2.1.1.124:22181, sessionid = 0x1365e4496ab0000, negotiated timeout = 300000
2012-03-29 19:43:38,032 INFO org.apache.giraph.graph.BspService: process: Asynchronous connection complete.
2012-03-29 19:43:38,034 INFO org.apache.giraph.graph.GraphMapper: map: No need to do anything when not a worker
2012-03-29 19:43:38,034 INFO org.apache.giraph.graph.GraphMapper: cleanup: Starting for MASTER_ZOOKEEPER_ONLY
2012-03-29 19:43:38,117 INFO org.apache.giraph.graph.BspServiceMaster: becomeMaster: First child is '/_hadoopBsp/job_201203291941_0001/_masterElectionDir/tmm-e4_00000000000' and my bid is '/_hadoopBsp/job_201203291941_0001/_masterElectionDir/tmm-e4_00000000000'
2012-03-29 19:43:38,129 INFO org.apache.giraph.graph.BspServiceMaster: becomeMaster: I am now the master!
2012-03-29 19:43:38,172 INFO org.apache.giraph.graph.BspService: process: applicationAttemptChanged signaled
2012-03-29 19:43:38,219 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir, type=NodeChildrenChanged, state=SyncConnected)
2012-03-29 19:43:41,238 INFO org.apache.giraph.graph.BspServiceMaster: generateInputSplits: Got 2 input splits for 2 workers
2012-03-29 19:43:41,295 INFO org.apache.giraph.graph.partition.HashMasterPartitioner: createInitialPartitionOwners: Creating 4, default would have been 4 partitions.
2012-03-29 19:43:41,376 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep -1 on path /_hadoopBsp/job_201203291941_0001/_inputSplitDoneDir
2012-03-29 19:43:41,508 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep -1 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/-1/_workerFinishedDir
2012-03-29 19:43:41,534 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=0) on superstep = -1
2012-03-29 19:43:41,574 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep -1 took 0.293 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 0
2012-03-29 19:43:41,704 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:41,706 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:41,707 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:41,724 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 0 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/0/_workerFinishedDir
2012-03-29 19:43:41,889 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 0
2012-03-29 19:43:42,047 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 0 took 0.473 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 1
2012-03-29 19:43:42,080 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:42,080 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:42,080 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:42,138 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 1 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/1/_workerFinishedDir
2012-03-29 19:43:42,191 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 1
2012-03-29 19:43:42,197 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/0
2012-03-29 19:43:42,401 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 1 took 0.354 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 2
2012-03-29 19:43:42,417 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:42,417 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:42,417 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:42,438 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 2 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/2/_workerFinishedDir
2012-03-29 19:43:42,491 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 2
2012-03-29 19:43:42,503 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/1
2012-03-29 19:43:42,708 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 2 took 0.307 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 3
2012-03-29 19:43:42,723 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:42,723 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:42,724 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:42,756 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 3 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/3/_workerFinishedDir
2012-03-29 19:43:42,840 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 3
2012-03-29 19:43:42,846 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/2
2012-03-29 19:43:43,036 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 3 took 0.328 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 4
2012-03-29 19:43:43,053 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:43,054 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:43,054 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:43,075 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 4 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/4/_workerFinishedDir
2012-03-29 19:43:43,134 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 4
2012-03-29 19:43:43,140 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/3
2012-03-29 19:43:43,332 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 4 took 0.296 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 5
2012-03-29 19:43:43,348 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:43,348 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:43,348 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:43,369 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 5 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/5/_workerFinishedDir
2012-03-29 19:43:43,416 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 5
2012-03-29 19:43:43,422 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/4
2012-03-29 19:43:43,614 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 5 took 0.282 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 6
2012-03-29 19:43:43,630 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:43,630 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:43,630 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:43,651 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 6 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/6/_workerFinishedDir
2012-03-29 19:43:43,728 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 6
2012-03-29 19:43:43,740 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/5
2012-03-29 19:43:43,944 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 6 took 0.33 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 7
2012-03-29 19:43:43,966 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:43,966 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:43,966 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:43,993 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 7 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/7/_workerFinishedDir
2012-03-29 19:43:44,052 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 7
2012-03-29 19:43:44,058 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/6
2012-03-29 19:43:44,245 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 7 took 0.301 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 8
2012-03-29 19:43:44,261 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:44,261 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:44,261 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:44,282 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 8 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/8/_workerFinishedDir
2012-03-29 19:43:44,335 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 8
2012-03-29 19:43:44,382 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/7
2012-03-29 19:43:44,545 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 8 took 0.3 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 9
2012-03-29 19:43:44,561 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:44,561 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:44,561 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:44,600 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 9 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/9/_workerFinishedDir
2012-03-29 19:43:44,655 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=0,edges=1000,msgCount=2000) on superstep = 9
2012-03-29 19:43:44,665 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/8
2012-03-29 19:43:44,875 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 9 took 0.33 seconds ended with state THIS_SUPERSTEP_DONE and is now on superstep 10
2012-03-29 19:43:44,891 INFO org.apache.giraph.graph.partition.PartitionBalancer: balancePartitionsAcrossWorkers: Using algorithm static
2012-03-29 19:43:44,891 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Vertices - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:44,891 INFO org.apache.giraph.graph.partition.PartitionUtils: analyzePartitionStats: Edges - Mean: 500, Min: Worker(hostname=tmm-e4, MRpartition=1, port=30001) - 500, Max: Worker(hostname=tmm-e4, MRpartition=2, port=30002) - 500
2012-03-29 19:43:44,912 INFO org.apache.giraph.graph.BspServiceMaster: barrierOnWorkerList: 0 out of 2 workers finished on superstep 10 on path /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/10/_workerFinishedDir
2012-03-29 19:43:44,940 INFO org.apache.giraph.graph.BspServiceMaster: aggregateWorkerStats: Aggregation found (vtx=1000,finVtx=1000,edges=1000,msgCount=0) on superstep = 10
2012-03-29 19:43:44,947 INFO org.apache.giraph.graph.BspServiceMaster: coordinateSuperstep: Cleaning up old Superstep /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/9
2012-03-29 19:43:45,115 INFO org.apache.giraph.graph.MasterThread: masterThread: Coordination of superstep 10 took 0.24 seconds ended with state ALL_SUPERSTEPS_DONE and is now on superstep 11
2012-03-29 19:43:45,116 INFO org.apache.giraph.graph.BspServiceMaster: setJobState: {"_stateKey":"FINISHED","_applicationAttemptKey":-1,"_superstepKey":-1} on superstep 11
2012-03-29 19:43:45,127 INFO org.apache.giraph.graph.BspServiceMaster: cleanup: Notifying master its okay to cleanup with /_hadoopBsp/job_201203291941_0001/_cleanedUpDir/0_master
2012-03-29 19:43:45,133 INFO org.apache.giraph.graph.BspServiceMaster: cleanUpZooKeeper: Node /_hadoopBsp/job_201203291941_0001/_cleanedUpDir already exists, no need to create.
2012-03-29 19:43:45,134 INFO org.apache.giraph.graph.BspServiceMaster: cleanUpZooKeeper: Got 3 of 3 desired children from /_hadoopBsp/job_201203291941_0001/_cleanedUpDir
2012-03-29 19:43:45,134 INFO org.apache.giraph.graph.BspServiceMaster: cleanupZooKeeper: Removing the following path and all children - /_hadoopBsp/job_201203291941_0001
2012-03-29 19:43:45,427 INFO org.apache.giraph.graph.BspService: process: masterElectionChildrenChanged signaled
2012-03-29 19:43:45,487 INFO org.apache.giraph.graph.BspService: process: cleanedUpChildrenChanged signaled
2012-03-29 19:43:45,539 INFO org.apache.giraph.graph.BspServiceMaster: cleanup: Removed HDFS checkpoint directory (_bsp/_checkpoints//job_201203291941_0001) with return = true since this job succeeded 
2012-03-29 19:43:45,547 INFO org.apache.zookeeper.ZooKeeper: Session: 0x1365e4496ab0000 closed
2012-03-29 19:43:45,547 INFO org.apache.zookeeper.ClientCnxn: EventThread shut down
2012-03-29 19:43:45,547 INFO org.apache.giraph.graph.MasterThread: setup: Took 3.245 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: vertex input superstep: Took 0.293 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 0: Took 0.473 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 1: Took 0.354 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 2: Took 0.307 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 3: Took 0.328 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 4: Took 0.296 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 5: Took 0.282 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 6: Took 0.33 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 7: Took 0.301 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 8: Took 0.3 seconds.
2012-03-29 19:43:45,548 INFO org.apache.giraph.graph.MasterThread: superstep 9: Took 0.33 seconds.
2012-03-29 19:43:45,549 INFO org.apache.giraph.graph.MasterThread: superstep 10: Took 0.24 seconds.
2012-03-29 19:43:45,549 INFO org.apache.giraph.graph.MasterThread: shutdown: Took 0.434 seconds.
2012-03-29 19:43:45,549 INFO org.apache.giraph.graph.MasterThread: total: Took 1.3330214223040001E9 seconds.
2012-03-29 19:43:45,549 INFO org.apache.giraph.zk.ZooKeeperManager: createZooKeeperClosedStamp: Creating my filestamp _bsp/_defaultZkManagerDir/job_201203291941_0001/_task/0.COMPUTATION_DONE
2012-03-29 19:43:45,566 INFO org.apache.giraph.zk.ZooKeeperManager: waitUntilAllTasksDone: Got 3 and 3 desired (polling period is 3000) on attempt 0
2012-03-29 19:43:45,925 INFO org.apache.giraph.zk.ZooKeeperManager: offlineZooKeeperServers: waitFor returned 143 and deleted directory /usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/work/_bspZooKeeper
2012-03-29 19:43:45,926 INFO org.apache.hadoop.mapred.Task: Task:attempt_201203291941_0001_m_000000_0 is done. And is in the process of commiting
2012-03-29 19:43:46,745 INFO org.apache.hadoop.mapred.Task: Task 'attempt_201203291941_0001_m_000000_0' done.
2012-03-29 19:43:46,748 INFO org.apache.hadoop.mapred.TaskLogsTruncater: Initializing logs' truncater with mapRetainSize=-1 and reduceRetainSize=-1
-------------------------------------------------
work1 logs:
2012-03-29 19:43:37,379 WARN org.apache.hadoop.util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2012-03-29 19:43:37,644 WARN org.apache.giraph.bsp.BspOutputFormat: getOutputCommitter: Returning ImmutableOutputCommiter (does nothing).
2012-03-29 19:43:37,654 INFO org.apache.hadoop.util.ProcessTree: setsid exited with exit code 0
2012-03-29 19:43:37,661 INFO org.apache.hadoop.mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@4bf54c5f
2012-03-29 19:43:37,747 INFO org.apache.giraph.graph.GraphMapper: Distributed cache is empty. Assuming fatjar.
2012-03-29 19:43:37,747 INFO org.apache.giraph.graph.GraphMapper: setup: classpath @ /usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/jars/job.jar
2012-03-29 19:43:37,755 INFO org.apache.giraph.zk.ZooKeeperManager: createCandidateStamp: Made the directory _bsp/_defaultZkManagerDir/job_201203291941_0001
2012-03-29 19:43:37,758 INFO org.apache.giraph.zk.ZooKeeperManager: createCandidateStamp: Creating my filestamp _bsp/_defaultZkManagerDir/job_201203291941_0001/_task/tmm-e4 1
2012-03-29 19:43:37,783 INFO org.apache.giraph.zk.ZooKeeperManager: getZooKeeperServerList: For task 1, got file 'zkServerList_tmm-e4 0 ' (polling period is 3000)
2012-03-29 19:43:37,783 INFO org.apache.giraph.zk.ZooKeeperManager: getZooKeeperServerList: Found [tmm-e4, 0] 2 hosts in filename 'zkServerList_tmm-e4 0 '
2012-03-29 19:43:37,785 INFO org.apache.giraph.zk.ZooKeeperManager: onlineZooKeeperSErvers: Empty directory _bsp/_defaultZkManagerDir/job_201203291941_0001/_zkServer, waiting 3000 msecs.
2012-03-29 19:43:40,787 INFO org.apache.giraph.zk.ZooKeeperManager: onlineZooKeeperServers: Got [tmm-e4] 1 hosts from 1 ready servers when 1 required (polling period is 3000) on attempt 1
2012-03-29 19:43:40,787 INFO org.apache.giraph.graph.GraphMapper: &&&setup:serverPortList is tmm-e4:22181
2012-03-29 19:43:40,787 INFO org.apache.giraph.graph.GraphMapper: setup: Starting up BspServiceWorker...
2012-03-29 19:43:40,798 INFO org.apache.giraph.graph.BspService: BspService: Connecting to ZooKeeper with job job_201203291941_0001, 1 on tmm-e4:22181
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:zookeeper.version=3.3.3-1073969, built on 02/23/2011 22:27 GMT
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:host.name=tmm-e4
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.version=1.6.0_22
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.vendor=Sun Microsystems Inc.
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.home=/usr/local/java/jdk1.6.0_22/jre
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.class.path=/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/jars/classes:/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/jars:/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/attempt_201203291941_0001_m_000001_0/work:/usr/local/h-test/hadoop-0.20.205.0/libexec/../conf:/usr/local/java/jdk1.6.0_22/lib/tools.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/hadoop-core-0.20.205.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/asm-3.2.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/aspectjrt-1.6.5.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/aspectjtools-1.6.5.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-beanutils-1.7.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-beanutils-core-1.8.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-cli-1.2.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-codec-1.4.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-collections-3.2.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-configuration-1.6.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-daemon-1.0.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-digester-1.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-el-1.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-httpclient-3.0.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-lang-2.4.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-logging-1.1.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-logging-api-1.0.4.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-math-2.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/commons-net-1.4.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/core-3.1.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/hadoop-capacity-scheduler-0.20.205.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/hadoop-fairscheduler-0.20.205.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/hadoop-thriftfs-0.20.205.0.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/hsqldb-1.8.0.10.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jackson-core-asl-1.0.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jackson-mapper-asl-1.0.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jasper-compiler-5.5.12.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jasper-runtime-5.5.12.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jdeb-0.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jersey-core-1.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jersey-json-1.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jersey-server-1.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jets3t-0.6.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jetty-6.1.26.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jetty-util-6.1.26.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jsch-0.1.42.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/junit-4.5.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/kfs-0.2.2.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/log4j-1.2.15.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/mockito-all-1.8.5.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/oro-2.0.8.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/servlet-api-2.5-20081211.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/slf4j-api-1.4.3.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/slf4j-log4j12-1.4.3.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/xmlenc-0.52.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jsp-2.1/jsp-2.1.jar:/usr/local/h-test/hadoop-0.20.205.0/libexec/../share/hadoop/lib/jsp-2.1/jsp-api-2.1.jar
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.library.path=/usr/local/h-test/hadoop-0.20.205.0/libexec/../lib:/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/attempt_201203291941_0001_m_000001_0/work
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.io.tmpdir=/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/attempt_201203291941_0001_m_000001_0/work/tmp
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:java.compiler=<NA>
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:os.name=Linux
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:os.arch=amd64
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:os.version=2.6.32.12-0.7-default
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:user.name=root
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:user.home=/root
2012-03-29 19:43:40,804 INFO org.apache.zookeeper.ZooKeeper: Client environment:user.dir=/usr/local/h-test/hadoop-data/h-0.20.205/mapred/local/taskTracker/root/jobcache/job_201203291941_0001/attempt_201203291941_0001_m_000001_0/work
2012-03-29 19:43:40,805 INFO org.apache.zookeeper.ZooKeeper: Initiating client connection, connectString=tmm-e4:22181 sessionTimeout=60000 watcher=org.apache.giraph.graph.BspServiceWorker@342798e7
2012-03-29 19:43:40,816 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server tmm-e4/2.1.1.124:22181
2012-03-29 19:43:40,817 INFO org.apache.zookeeper.ClientCnxn: Socket connection established to tmm-e4/2.1.1.124:22181, initiating session
2012-03-29 19:43:40,825 INFO org.apache.zookeeper.ClientCnxn: Session establishment complete on server tmm-e4/2.1.1.124:22181, sessionid = 0x1365e4496ab0001, negotiated timeout = 300000
2012-03-29 19:43:40,826 INFO org.apache.giraph.graph.BspService: process: Asynchronous connection complete.
2012-03-29 19:43:41,152 INFO org.apache.giraph.comm.RPCCommunications: getRPCServer: Added jobToken Ident: 15 6a 6f 62 5f 32 30 31 32 30 33 32 39 31 39 34 31 5f 30 30 30 31, Pass: 19 ef a9 0b ce df 80 83 7e 73 e3 07 32 63 e5 5b 07 44 89 e5, Kind: mapreduce.job, Service: job_201203291941_0001
2012-03-29 19:43:41,157 INFO org.apache.hadoop.ipc.Server: Starting SocketReader
2012-03-29 19:43:41,163 INFO org.apache.hadoop.ipc.Server: IPC Server Responder: starting
2012-03-29 19:43:41,163 INFO org.apache.hadoop.ipc.Server: IPC Server listener on 30001: starting
2012-03-29 19:43:41,165 INFO org.apache.hadoop.ipc.Server: IPC Server handler 0 on 30001: starting
2012-03-29 19:43:41,165 INFO org.apache.hadoop.ipc.Server: IPC Server handler 1 on 30001: starting
2012-03-29 19:43:41,165 INFO org.apache.hadoop.ipc.Server: IPC Server handler 2 on 30001: starting
2012-03-29 19:43:41,165 INFO org.apache.giraph.comm.BasicRPCCommunications: BasicRPCCommunications: Started RPC communication server: tmm-e4/2.1.1.124:30001 with 3 handlers and 1 flush threads on bind attempt 0
2012-03-29 19:43:41,166 INFO org.apache.giraph.graph.GraphMapper: setup: Registering health of this worker...
2012-03-29 19:43:41,188 INFO org.apache.giraph.graph.BspService: getJobState: Job state already exists (/_hadoopBsp/job_201203291941_0001/_masterJobState)
2012-03-29 19:43:41,201 INFO org.apache.giraph.graph.BspService: getApplicationAttempt: Node /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir already exists!
2012-03-29 19:43:41,207 INFO org.apache.giraph.graph.BspService: getApplicationAttempt: Node /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir already exists!
2012-03-29 19:43:41,225 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=-1 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/-1/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:41,365 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:41,379 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep -1 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/-1/_partitionAssignments
2012-03-29 19:43:41,411 INFO org.apache.giraph.graph.BspServiceWorker: reserveInputSplit: Couldn't reserve (already reserved) inputSplit at /_hadoopBsp/job_201203291941_0001/_inputSplitDir/1/_inputSplitReserved
2012-03-29 19:43:41,417 INFO org.apache.giraph.graph.BspServiceWorker: reserveInputSplit: Reserved input split path /_hadoopBsp/job_201203291941_0001/_inputSplitDir/0, overall roughly 0.0% input splits finished
2012-03-29 19:43:41,418 INFO org.apache.giraph.graph.BspServiceWorker: getInputSplitForVertices: Reserved /_hadoopBsp/job_201203291941_0001/_inputSplitDir/0 from ZooKeeper and got input split ''org.apache.giraph.bsp.BspInputSplit, index=0, num=2'
2012-03-29 19:43:41,444 INFO org.apache.giraph.graph.BspServiceWorker: loadVerticesFromInputSplit: Finished loading /_hadoopBsp/job_201203291941_0001/_inputSplitDir/0 (v=500, e=500)
2012-03-29 19:43:41,461 INFO org.apache.giraph.graph.BspServiceWorker: reserveInputSplit: reservedPath = null, 2 of 2 InputSplits are finished.
2012-03-29 19:43:41,477 INFO org.apache.giraph.graph.BspServiceWorker: setup: Finally loaded a total of (v=500, e=500)
2012-03-29 19:43:41,501 INFO org.apache.giraph.graph.BspService: process: inputSplitsAllDoneChanged (all vertices sent from input splits)
2012-03-29 19:43:41,502 INFO org.apache.giraph.graph.BspServiceWorker: moveVerticesToWorker: Adding 250 vertices for partition id 1
2012-03-29 19:43:41,502 INFO org.apache.giraph.graph.BspServiceWorker: moveVerticesToWorker: Adding 250 vertices for partition id 3
2012-03-29 19:43:41,503 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep -1 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 216.3302M
2012-03-29 19:43:41,505 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep -1 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 216.32999M
2012-03-29 19:43:41,505 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep -1 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 216.32999M
2012-03-29 19:43:41,543 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:41,545 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep -1 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=0)
2012-03-29 19:43:41,545 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 0 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 216.32999M
2012-03-29 19:43:41,621 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir, type=NodeChildrenChanged, state=SyncConnected)
2012-03-29 19:43:41,645 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=0 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/0/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:41,717 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:41,725 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 0 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/0/_partitionAssignments
2012-03-29 19:43:41,735 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:41,736 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:41,831 INFO org.apache.giraph.graph.BspServiceWorker: storeCheckpoint: Finished metadata (_bsp/_checkpoints/job_201203291941_0001/0.tmm-e4_1.metadata) and vertices (_bsp/_checkpoints/job_201203291941_0001/0.tmm-e4_1.vertices).
2012-03-29 19:43:41,866 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 0 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 211.79204M
2012-03-29 19:43:41,877 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 0 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 211.47375M
2012-03-29 19:43:41,877 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 0 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 211.47375M
2012-03-29 19:43:41,897 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:41,899 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 0 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:41,899 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 1 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 211.47375M
2012-03-29 19:43:42,071 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=1 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/1/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:42,131 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:42,138 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 1 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/1/_partitionAssignments
2012-03-29 19:43:42,138 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/0/_mergedAggregatorDir on superstep 1
2012-03-29 19:43:42,143 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:42,149 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:42,164 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 1 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 211.47375M
2012-03-29 19:43:42,173 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 1 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 211.16217M
2012-03-29 19:43:42,173 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 1 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 211.16217M
2012-03-29 19:43:42,197 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:42,198 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 1 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:42,198 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 2 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 211.16217M
2012-03-29 19:43:42,221 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/0/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:42,305 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=2 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/2/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:42,317 INFO org.apache.giraph.graph.BspServiceWorker: processEvent : partitionExchangeChildrenChanged (at least one worker is done sending partitions)
2012-03-29 19:43:42,371 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/0/_superstepFinished, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:42,431 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:42,439 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 2 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/2/_partitionAssignments
2012-03-29 19:43:42,440 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/1/_mergedAggregatorDir on superstep 2
2012-03-29 19:43:42,449 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:42,450 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:42,464 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 2 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 207.57089M
2012-03-29 19:43:42,473 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 2 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 207.57089M
2012-03-29 19:43:42,473 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 2 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 207.57089M
2012-03-29 19:43:42,503 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:42,511 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 2 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:42,511 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 3 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 207.57089M
2012-03-29 19:43:42,515 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/1/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:42,648 INFO org.apache.giraph.graph.BspServiceWorker: processEvent : partitionExchangeChildrenChanged (at least one worker is done sending partitions)
2012-03-29 19:43:42,654 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=3 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/3/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:42,678 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/1/_superstepFinished, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:42,738 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:42,745 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 3 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/3/_partitionAssignments
2012-03-29 19:43:42,746 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/2/_mergedAggregatorDir on superstep 3
2012-03-29 19:43:42,756 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:42,757 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:42,769 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 3 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 207.57089M
2012-03-29 19:43:42,777 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 3 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 207.25923M
2012-03-29 19:43:42,777 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 3 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 207.25923M
2012-03-29 19:43:42,846 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:42,852 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 3 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:42,852 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 4 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 207.25923M
2012-03-29 19:43:42,858 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/2/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:42,948 INFO org.apache.giraph.graph.BspServiceWorker: processEvent : partitionExchangeChildrenChanged (at least one worker is done sending partitions)
2012-03-29 19:43:42,954 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=4 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/4/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:42,978 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/2/_superstepFinished, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:43,068 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:43,074 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 4 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/4/_partitionAssignments
2012-03-29 19:43:43,075 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/3/_mergedAggregatorDir on superstep 4
2012-03-29 19:43:43,080 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:43,086 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:43,100 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 4 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 207.25923M
2012-03-29 19:43:43,109 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 4 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 206.94612M
2012-03-29 19:43:43,109 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 4 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 206.94612M
2012-03-29 19:43:43,140 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:43,146 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 4 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:43,146 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 5 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 206.94612M
2012-03-29 19:43:43,152 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/3/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:43,236 INFO org.apache.giraph.graph.BspServiceWorker: processEvent : partitionExchangeChildrenChanged (at least one worker is done sending partitions)
2012-03-29 19:43:43,276 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=5 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/5/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:43,302 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/3/_superstepFinished, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:43,362 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:43,368 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 5 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/5/_partitionAssignments
2012-03-29 19:43:43,369 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/4/_mergedAggregatorDir on superstep 5
2012-03-29 19:43:43,374 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:43,381 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:43,392 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 5 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 205.84897M
2012-03-29 19:43:43,400 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 5 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 205.84897M
2012-03-29 19:43:43,400 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 5 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 205.84897M
2012-03-29 19:43:43,422 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:43,428 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 5 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:43,428 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 6 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 205.84897M
2012-03-29 19:43:43,434 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/4/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:43,548 INFO org.apache.giraph.graph.BspServiceWorker: processEvent : partitionExchangeChildrenChanged (at least one worker is done sending partitions)
2012-03-29 19:43:43,560 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=6 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/6/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:43,584 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/4/_superstepFinished, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:43,644 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:43,650 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 6 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/6/_partitionAssignments
2012-03-29 19:43:43,651 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/5/_mergedAggregatorDir on superstep 6
2012-03-29 19:43:43,679 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:43,684 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:43,699 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 6 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 199.68237M
2012-03-29 19:43:43,709 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 6 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 199.68237M
2012-03-29 19:43:43,709 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 6 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 199.68237M
2012-03-29 19:43:43,740 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:43,746 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 6 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:43,746 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 7 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 199.68237M
2012-03-29 19:43:43,752 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/5/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:43,842 INFO org.apache.giraph.graph.BspServiceWorker: processEvent : partitionExchangeChildrenChanged (at least one worker is done sending partitions)
2012-03-29 19:43:43,848 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=7 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/7/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:43,872 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/5/_superstepFinished, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:43,980 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:43,994 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 7 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/7/_partitionAssignments
2012-03-29 19:43:43,994 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/6/_mergedAggregatorDir on superstep 7
2012-03-29 19:43:44,010 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:44,011 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:44,024 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 7 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 198.58546M
2012-03-29 19:43:44,037 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 7 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 198.58546M
2012-03-29 19:43:44,037 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 7 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 198.58546M
2012-03-29 19:43:44,058 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:44,064 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 7 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:44,064 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 8 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 198.58546M
2012-03-29 19:43:44,070 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/6/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:44,185 INFO org.apache.giraph.graph.BspServiceWorker: processEvent : partitionExchangeChildrenChanged (at least one worker is done sending partitions)
2012-03-29 19:43:44,191 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=8 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/8/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:44,215 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/6/_superstepFinished, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:44,275 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:44,281 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 8 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/8/_partitionAssignments
2012-03-29 19:43:44,282 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/7/_mergedAggregatorDir on superstep 8
2012-03-29 19:43:44,287 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:44,293 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:44,305 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 8 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 198.58546M
2012-03-29 19:43:44,317 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 8 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 197.96222M
2012-03-29 19:43:44,318 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 8 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 197.96222M
2012-03-29 19:43:44,382 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:44,389 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 8 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:44,389 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 9 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 197.96222M
2012-03-29 19:43:44,395 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/7/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:44,479 INFO org.apache.giraph.graph.BspServiceWorker: processEvent : partitionExchangeChildrenChanged (at least one worker is done sending partitions)
2012-03-29 19:43:44,491 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=9 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/9/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:44,515 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/7/_superstepFinished, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:44,592 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:44,599 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 9 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/9/_partitionAssignments
2012-03-29 19:43:44,600 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/8/_mergedAggregatorDir on superstep 9
2012-03-29 19:43:44,605 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:44,612 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:44,625 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 9 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 197.96222M
2012-03-29 19:43:44,635 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 9 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 197.96222M
2012-03-29 19:43:44,635 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 9 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 197.96222M
2012-03-29 19:43:44,665 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:44,677 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 9 with global stats (vtx=1000,finVtx=0,edges=1000,msgCount=2000)
2012-03-29 19:43:44,678 INFO org.apache.giraph.comm.BasicRPCCommunications: prepareSuperstep: Superstep 10 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 196.86533M
2012-03-29 19:43:44,695 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/8/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:44,785 INFO org.apache.giraph.graph.BspServiceWorker: processEvent : partitionExchangeChildrenChanged (at least one worker is done sending partitions)
2012-03-29 19:43:44,791 INFO org.apache.giraph.graph.BspServiceWorker: registerHealth: Created my health node for attempt=0, superstep=10 with /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/10/_workerHealthyDir/tmm-e4_1 and workerInfo= Worker(hostname=tmm-e4, MRpartition=1, port=30001)
2012-03-29 19:43:44,845 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/8/_superstepFinished, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:44,905 INFO org.apache.giraph.graph.BspService: process: partitionAssignmentsReadyChanged (partitions are assigned)
2012-03-29 19:43:44,912 INFO org.apache.giraph.graph.BspServiceWorker: startSuperstep: Ready for computation on superstep 10 since worker selection and vertex range assignments are done in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/10/_partitionAssignments
2012-03-29 19:43:44,912 INFO org.apache.giraph.graph.BspServiceWorker: getAggregatorValues: no aggregators in /_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/9/_mergedAggregatorDir on superstep 10
2012-03-29 19:43:44,917 INFO org.apache.giraph.graph.BspServiceWorker: sendWorkerPartitions: Done sending all my partitions.
2012-03-29 19:43:44,923 INFO org.apache.giraph.graph.BspServiceWorker: exchangeVertexPartitions: Done with exchange.
2012-03-29 19:43:44,926 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: starting for superstep 10 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 196.22968M
2012-03-29 19:43:44,926 INFO org.apache.giraph.comm.BasicRPCCommunications: flush: ended for superstep 10 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 196.22968M
2012-03-29 19:43:44,926 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Superstep 10 totalMem = 238.8125M, maxMem = 1777.8125M, freeMem = 196.22968M
2012-03-29 19:43:44,947 INFO org.apache.giraph.graph.BspService: process: superstepFinished signaled
2012-03-29 19:43:44,953 INFO org.apache.giraph.graph.BspServiceWorker: finishSuperstep: Completed superstep 10 with global stats (vtx=1000,finVtx=1000,edges=1000,msgCount=0)
2012-03-29 19:43:44,953 INFO org.apache.giraph.graph.GraphMapper: map: BSP application done (global vertices marked done)
2012-03-29 19:43:44,953 INFO org.apache.giraph.graph.GraphMapper: cleanup: Starting for WORKER_ONLY
2012-03-29 19:43:44,953 WARN org.apache.giraph.graph.BspServiceWorker: saveVertices: giraph.vertexOutputFormatClass not specified -- there will be no saved output
2012-03-29 19:43:44,965 WARN org.apache.giraph.graph.BspService: process: Unknown and unprocessed event (path=/_hadoopBsp/job_201203291941_0001/_applicationAttemptsDir/0/_superstepDir/9/_partitionAssignments, type=NodeDeleted, state=SyncConnected)
2012-03-29 19:43:45,031 INFO org.apache.giraph.graph.BspServiceWorker: cleanup: Notifying master its okay to cleanup with /_hadoopBsp/job_201203291941_0001/_cleanedUpDir/1_worker
2012-03-29 19:43:45,044 INFO org.apache.zookeeper.ZooKeeper: Session: 0x1365e4496ab0001 closed
2012-03-29 19:43:45,044 INFO org.apache.giraph.comm.BasicRPCCommunications: close: shutting down RPC server
2012-03-29 19:43:45,044 INFO org.apache.hadoop.ipc.Server: Stopping server on 30001
2012-03-29 19:43:45,044 INFO org.apache.zookeeper.ClientCnxn: EventThread shut down
2012-03-29 19:43:45,045 INFO org.apache.hadoop.ipc.Server: Stopping IPC Server listener on 30001
2012-03-29 19:43:45,045 INFO org.apache.hadoop.ipc.Server: IPC Server handler 1 on 30001: exiting
2012-03-29 19:43:45,045 INFO org.apache.hadoop.ipc.Server: Stopping IPC Server Responder
2012-03-29 19:43:45,045 INFO org.apache.hadoop.ipc.metrics.RpcInstrumentation: shut down
2012-03-29 19:43:45,045 INFO org.apache.hadoop.ipc.Server: IPC Server handler 2 on 30001: exiting
2012-03-29 19:43:45,045 INFO org.apache.hadoop.ipc.Server: IPC Server handler 0 on 30001: exiting
2012-03-29 19:43:45,046 INFO org.apache.giraph.zk.ZooKeeperManager: createZooKeeperClosedStamp: Creating my filestamp _bsp/_defaultZkManagerDir/job_201203291941_0001/_task/1.COMPUTATION_DONE
2012-03-29 19:43:45,065 INFO org.apache.hadoop.mapred.Task: Task:attempt_201203291941_0001_m_000001_0 is done. And is in the process of commiting
2012-03-29 19:43:46,727 INFO org.apache.hadoop.mapred.Task: Task 'attempt_201203291941_0001_m_000001_0' done.
2012-03-29 19:43:46,729 INFO org.apache.hadoop.mapred.TaskLogsTruncater: Initializing logs' truncater with mapRetainSize=-1 and reduceRetainSize=-1
---------------------------------------------------------
2012-03-29 19:43:49,419 WARN org.apache.hadoop.util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2012-03-29 19:43:49,687 WARN org.apache.giraph.bsp.BspOutputFormat: getOutputCommitter: Returning ImmutableOutputCommiter (does nothing).
2012-03-29 19:43:49,697 INFO org.apache.hadoop.util.ProcessTree: setsid exited with exit code 0
2012-03-29 19:43:49,705 INFO org.apache.hadoop.mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@4bf54c5f
2012-03-29 19:43:49,759 INFO org.apache.hadoop.mapred.Task: Cleaning up job
2012-03-29 19:43:49,759 INFO org.apache.hadoop.mapred.Task: Committing job
2012-03-29 19:43:49,770 INFO org.apache.hadoop.mapred.Task: Task:attempt_201203291941_0001_m_000003_0 is done. And is in the process of commiting
2012-03-29 19:43:52,689 INFO org.apache.hadoop.mapred.Task: Task 'attempt_201203291941_0001_m_000003_0' done.
2012-03-29 19:43:52,714 INFO org.apache.hadoop.mapred.TaskLogsTruncater: Initializing logs' truncater with mapRetainSize=-1 and reduceRetainSize=-1
------------------------
tmm-e4:/usr/local/h-test/hadoop-0.20.205.0/logs/userlogs/job_201203291941_0001 # date
Thu Mar 29 19:48:37 CST 2012
tmm-e4:/usr/local/h-test/hadoop-0.20.205.0/logs/userlogs/job_201203291941_0001 # jps
7708 TaskTracker
7112 NameNode
8602 Jps
8163 Child
7544 JobTracker
7259 DataNode
8216 Child
7420 SecondaryNameNode

                
> How to close all child when a job finished?
> -------------------------------------------
>
>                 Key: GIRAPH-169
>                 URL: https://issues.apache.org/jira/browse/GIRAPH-169
>             Project: Giraph
>          Issue Type: Improvement
>          Components: mapreduce
>    Affects Versions: 0.2.0
>         Environment: sles 11 x64,jdk 1.6,hadoop 0.20.205.0,1 Master and 8 slaves,
>            Reporter: Jianfeng Qian
>            Priority: Minor
>
> I ran pagerank at hadoop 0.20.205.0. When the job finished,the child in slaves didn't quit immediately and sometimes they never quit and I have to kill them. 

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

       

Mime
View raw message