AnsweredAssumed Answered

Wrong results / Corruption due to jobtracker failure

Question asked by dimamah on Nov 24, 2013
Latest reply on Nov 25, 2013 by dimamah
The cluster (1.2.9.14720.GA) was running an `insert overwrite` command while in the middle, the jobtracker failed  
(most reasonable guess is - due to extreme overload of the system. no logs unfortunately but there was a simple message of "shutting down jobtracker"). 
The jobtracker status was "standby" (In the WebUI) - which frankly i don't understand what it means but it doesn't raise any alerts and its too bad. 
After manually restarting the jobtracker, it restarted the previous running task. 
When the job ended, it loaded half of the amount of rows it should have loaded! nevertheless, it claimed that ~3/4 of the rows were loaded.

For the numbers : 
Manually running the `insert overwrite` command to a different similar table loads ~155K rows. 
In the HiveServer log for the break down it says : `115618 Rows loaded to sometable`. 
Counting the rows in the table :

    [hadoop@joya-02 sometable]$ hive -e "select count(*) from somedb.sometable"
    OK
    77148

Manually counting the rows :

    cd /mnt/mfs/my.cluster.com/user/hive/warehouse/somedb.db/sometable
    [hadoop@joya-02 sometable]$ ll
    total 23877
    -rwxrwxrwx 1 hadoop hadoop 12224792 Nov 12 21:46 000001_20001
    -rwxrwxrwx 1 hadoop hadoop 12224199 Nov 12 21:47 000003_20000
    [hadoop@joya-02 sometable]$ wc -l *
       38574 000001_20001
       38574 000003_20000
       77148 total

You can notice the weird suffix to the file names : _**2**000x as opposed to the regular _**0**...   
**What does this mean and when does this happen?**

In the HiveServer log its clear that the other 2 files that should be in this table (resulting in the full ~155k expected rows)  were assumed duplicate :

    Duplicate taskid file removed: maprfs:/tmp/hive-hadoop/.../000002_20000 with length 12218331.
    Existing file: maprfs:/tmp/hive-hadoop/.../000003_20000 with length 12224199
    Duplicate taskid file removed: maprfs:/tmp/hive-hadoop/.../000002_20001 with length 12218327.
    Existing file: maprfs:/tmp/hive-hadoop/.../000001_20001 with length 12224792
    Duplicate taskid file removed: maprfs:/tmp/hive-hadoop/.../000000_20000 with length 12198714.
    Existing file: maprfs:/tmp/hive-hadoop/.../000003_20000 with length 12224199

I think its rather clear that only 000002\_20000 and 000002\_20001 were duplicates of each other.

This raises the following questions :

 1. Why did hive claim to load 115618 rows while loading only 77148?
 2. Why did hive mark a non duplicate file as duplicate?
 3. What does all of this have to do with the crash?
 4. **Most important** - How can i be sure the results I'm getting are **persistent**?

CLDB/Jobtracker are on "joya-02". zookeepers are on "joya-0[1-3]" 
The HiveServer log :

    Starting Job = job_201309111853_50009, Tracking URL = http://joya-02:50030/jobdetails.jsp?jobid=job_201309111853_50009
    13/11/12 19:30:23 INFO exec.MapRedTask: Starting Job = job_201309111853_50009, Tracking URL = http://joya-02:50030/jobdetails.jsp?jobid=job_201309111853_50009
    Kill Command = /opt/mapr/hadoop/hadoop-0.20.2/bin/../bin/hadoop job  -Dmapred.job.tracker=maprfs:/// -kill job_201309111853_50009
    13/11/12 19:30:23 INFO exec.MapRedTask: Kill Command = /opt/mapr/hadoop/hadoop-0.20.2/bin/../bin/hadoop job  -Dmapred.job.tracker=maprfs:/// -kill job_201309111853_50009
    2013-11-12 19:30:24,729 Stage-1 map = 0%,  reduce = 0%
    13/11/12 19:30:24 INFO exec.MapRedTask: 2013-11-12 19:30:24,729 Stage-1 map = 0%,  reduce = 0%
    2013-11-12 19:31:02,957 Stage-1 map = 1%,  reduce = 0%
    13/11/12 19:31:02 INFO exec.MapRedTask: 2013-11-12 19:31:02,957 Stage-1 map = 1%,  reduce = 0%
    2013-11-12 19:31:30,004 Stage-1 map = 2%,  reduce = 0%
    13/11/12 19:31:30 INFO exec.MapRedTask: 2013-11-12 19:31:30,004 Stage-1 map = 2%,  reduce = 0%
    ...
    ...
    13/11/12 19:34:06 INFO exec.MapRedTask: 2013-11-12 19:34:06,491 Stage-1 map = 34%,  reduce = 0%
    13/11/12 19:34:11 INFO zookeeper.ClientCnxn: Client session timed out, have not heard from server in 20000ms for sessionid 0x2424d09b26f001d, closing socket connection and attempting reconnect
    13/11/12 19:34:12 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-02/106.103.1.82:5181
    13/11/12 19:34:12 INFO zookeeper.ClientCnxn: Socket connection established to joya-02/106.103.1.82:5181, initiating session
    2013-11-12 19:34:13,521 Stage-1 map = 35%,  reduce = 0%
    13/11/12 19:34:13 INFO exec.MapRedTask: 2013-11-12 19:34:13,521 Stage-1 map = 35%,  reduce = 0%
    13/11/12 19:34:16 INFO zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x2424d09b26f001d, likely server has closed socket, closing socket connection and attempting reconnect
    13/11/12 19:34:16 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-01/106.103.1.81:5181
    13/11/12 19:34:16 WARN zookeeper.ClientCnxn: Session 0x2424d09b26f001d for server null, unexpected error, closing socket connection and attempting reconnect
    java.net.ConnectException: Connection refused
            at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
            at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
            at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1125)
    13/11/12 19:34:17 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-03/106.103.1.83:5181
    13/11/12 19:34:17 INFO zookeeper.ClientCnxn: Socket connection established to joya-03/106.103.1.83:5181, initiating session
    2013-11-12 19:34:22,542 Stage-1 map = 36%,  reduce = 0%
    13/11/12 19:34:22 INFO exec.MapRedTask: 2013-11-12 19:34:22,542 Stage-1 map = 36%,  reduce = 0%
    2013-11-12 19:34:25,547 Stage-1 map = 37%,  reduce = 0%
    13/11/12 19:34:25 INFO exec.MapRedTask: 2013-11-12 19:34:25,547 Stage-1 map = 37%,  reduce = 0%
    2013-11-12 19:34:26,550 Stage-1 map = 38%,  reduce = 0%
    13/11/12 19:34:26 INFO exec.MapRedTask: 2013-11-12 19:34:26,550 Stage-1 map = 38%,  reduce = 0%
    13/11/12 19:34:27 INFO zookeeper.ClientCnxn: Client session timed out, have not heard from server in 10000ms for sessionid 0x2424d09b26f001d, closing socket connection and attempting reconnect
    13/11/12 19:34:27 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-02/106.103.1.82:5181
    13/11/12 19:34:27 INFO zookeeper.ClientCnxn: Socket connection established to joya-02/106.103.1.82:5181, initiating session
    13/11/12 19:34:27 INFO zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x2424d09b26f001d, likely server has closed socket, closing socket connection and attempting reconnect
    13/11/12 19:34:28 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-01/106.103.1.81:5181
    13/11/12 19:34:28 WARN zookeeper.ClientCnxn: Session 0x2424d09b26f001d for server null, unexpected error, closing socket connection and attempting reconnect
    java.net.ConnectException: Connection refused
            at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
            at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
            at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1125)
    2013-11-12 19:34:28,554 Stage-1 map = 39%,  reduce = 0%
    13/11/12 19:34:28 INFO exec.MapRedTask: 2013-11-12 19:34:28,554 Stage-1 map = 39%,  reduce = 0%
    13/11/12 19:34:29 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-03/106.103.1.83:5181
    2013-11-12 19:34:29,556 Stage-1 map = 40%,  reduce = 0%
    13/11/12 19:34:29 INFO exec.MapRedTask: 2013-11-12 19:34:29,556 Stage-1 map = 40%,  reduce = 0%
    ...
    ...
    13/11/12 19:34:38 INFO exec.MapRedTask: 2013-11-12 19:34:38,602 Stage-1 map = 50%,  reduce = 0%
    13/11/12 19:34:39 INFO zookeeper.ClientCnxn: Client session timed out, have not heard from server in 10648ms for sessionid 0x2424d09b26f001d, closing socket connection and attempting reconnect
    2013-11-12 19:34:39,608 Stage-1 map = 51%,  reduce = 0%
    13/11/12 19:34:39 INFO exec.MapRedTask: 2013-11-12 19:34:39,608 Stage-1 map = 51%,  reduce = 0%
    13/11/12 19:34:41 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-02/106.103.1.82:5181
    13/11/12 19:34:41 INFO zookeeper.ClientCnxn: Socket connection established to joya-02/106.103.1.82:5181, initiating session
    13/11/12 19:34:41 INFO zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x2424d09b26f001d, likely server has closed socket, closing socket connection and attempting reconnect
    13/11/12 19:34:41 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-01/106.103.1.81:5181
    13/11/12 19:34:41 WARN zookeeper.ClientCnxn: Session 0x2424d09b26f001d for server null, unexpected error, closing socket connection and attempting reconnect
    java.net.ConnectException: Connection refused
            at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
            at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
            at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1125)
    2013-11-12 19:34:41,614 Stage-1 map = 52%,  reduce = 0%
    13/11/12 19:34:41 INFO exec.MapRedTask: 2013-11-12 19:34:41,614 Stage-1 map = 52%,  reduce = 0%
    13/11/12 19:34:42 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-03/106.103.1.83:5181
    2013-11-12 19:34:42,617 Stage-1 map = 53%,  reduce = 0%
    13/11/12 19:34:42 INFO exec.MapRedTask: 2013-11-12 19:34:42,617 Stage-1 map = 53%,  reduce = 0%
    ...
    ...
    13/11/12 19:34:50 INFO exec.MapRedTask: 2013-11-12 19:34:50,952 Stage-1 map = 66%,  reduce = 0%
    13/11/12 19:34:51 INFO zookeeper.ClientCnxn: Socket connection established to joya-03/106.103.1.83:5181, initiating session
    2013-11-12 19:34:51,978 Stage-1 map = 67%,  reduce = 0%
    13/11/12 19:34:51 INFO exec.MapRedTask: 2013-11-12 19:34:51,978 Stage-1 map = 67%,  reduce = 0%
    ...
    ...
    13/11/12 19:35:01 INFO exec.MapRedTask: 2013-11-12 19:35:01,146 Stage-1 map = 80%,  reduce = 0%
    13/11/12 19:35:01 INFO zookeeper.ClientCnxn: Client session timed out, have not heard from server in 10000ms for sessionid 0x2424d09b26f001d, closing socket connection and attempting reconnect
    13/11/12 19:35:02 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-02/106.103.1.82:5181
    13/11/12 19:35:02 INFO zookeeper.ClientCnxn: Socket connection established to joya-02/106.103.1.82:5181, initiating session
    13/11/12 19:35:02 INFO zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x2424d09b26f001d, likely server has closed socket, closing socket connection and attempting reconnect
    13/11/12 19:35:03 INFO ipc.RPC: FailoverProxy: Server on joya-02/106.103.1.82:9001 is lost due to java.net.SocketException: Call to joya-02/106.103.1.82:9001 failed on socket exception in call getJobStatus
    13/11/12 19:35:03 INFO ipc.RPC: Searching for the Active Server ...
    13/11/12 19:35:03 INFO ipc.RPC: Attempt# 1 . Trying to connect Server at joya-02/106.103.1.82:9001
    13/11/12 19:35:03 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-01/106.103.1.81:5181
    13/11/12 19:35:03 WARN zookeeper.ClientCnxn: Session 0x2424d09b26f001d for server null, unexpected error, closing socket connection and attempting reconnect
    java.net.ConnectException: Connection refused
            at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
            at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
            at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1125)
    13/11/12 19:35:04 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 0 time(s).
    13/11/12 19:35:04 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-03/106.103.1.83:5181
    13/11/12 19:35:04 INFO zookeeper.ClientCnxn: Socket connection established to joya-03/106.103.1.83:5181, initiating session
    13/11/12 19:35:05 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 1 time(s).
    13/11/12 19:35:06 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 2 time(s).
    13/11/12 19:35:07 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 3 time(s).
    13/11/12 19:35:08 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 4 time(s).
    13/11/12 19:35:09 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 5 time(s).
    13/11/12 19:35:10 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 6 time(s).
    13/11/12 19:35:10 INFO zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x2424d09b26f001d, likely server has closed socket, closing socket connection and attempting reconnect
    13/11/12 19:35:11 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 7 time(s).
    13/11/12 19:35:11 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-02/106.103.1.82:5181
    13/11/12 19:35:11 INFO zookeeper.ClientCnxn: Socket connection established to joya-02/106.103.1.82:5181, initiating session
    13/11/12 19:35:11 INFO zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x2424d09b26f001d, likely server has closed socket, closing socket connection and attempting reconnect
    13/11/12 19:35:12 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 8 time(s).
    13/11/12 19:35:12 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-01/106.103.1.81:5181
    13/11/12 19:35:12 WARN zookeeper.ClientCnxn: Session 0x2424d09b26f001d for server null, unexpected error, closing socket connection and attempting reconnect
    java.net.ConnectException: Connection refused
            at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
            at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
            at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1125)
    13/11/12 19:35:12 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-03/106.103.1.83:5181
    13/11/12 19:35:12 INFO zookeeper.ClientCnxn: Socket connection established to joya-03/106.103.1.83:5181, initiating session
    13/11/12 19:35:13 INFO ipc.Client: Retrying connect to server: joya-02/106.103.1.82:9001. Already tried 9 time(s).
    13/11/12 19:35:13 WARN ipc.RPC: Error connecting server at joya-02/106.103.1.82:9001 java.net.SocketException: Call to joya-02/106.103.1.82:9001 failed on socket exception
    13/11/12 19:35:13 INFO ipc.RPC: Tried all servers sleeping
    13/11/12 19:35:13 INFO zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x2424d09b26f001d, likely server has closed socket, closing socket connection and attempting reconnect
    13/11/12 19:35:14 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-02/106.103.1.82:5181
    13/11/12 19:35:14 INFO zookeeper.ClientCnxn: Socket connection established to joya-02/106.103.1.82:5181, initiating session
    13/11/12 19:35:14 INFO zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x2424d09b26f001d, likely server has closed socket, closing socket connection and attempting reconnect
    13/11/12 19:35:14 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-01/106.103.1.81:5181
    13/11/12 19:35:14 WARN zookeeper.ClientCnxn: Session 0x2424d09b26f001d for server null, unexpected error, closing socket connection and attempting reconnect
    java.net.ConnectException: Connection refused
            at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
            at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
            at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1125)
    13/11/12 19:35:15 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-03/106.103.1.83:5181
    13/11/12 19:35:15 INFO zookeeper.ClientCnxn: Socket connection established to joya-03/106.103.1.83:5181, initiating session
    13/11/12 19:35:20 INFO zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x2424d09b26f001d, likely server has closed socket, closing socket connection and attempting reconnect
    13/11/12 19:35:20 INFO fs.JobTrackerWatcher: findJobTrackerAddr: ConnectionLost, Reconnecting... Current ZooKeeper Server: joya-01:5181,joya-02:5181,joya-03:5181
    13/11/12 19:35:21 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-02/106.103.1.82:5181
    13/11/12 19:35:21 INFO zookeeper.ClientCnxn: Socket connection established to joya-02/106.103.1.82:5181, initiating session
    13/11/12 19:35:21 INFO zookeeper.ZooKeeper: Session: 0x2424d09b26f001d closed
    13/11/12 19:35:21 INFO zookeeper.ClientCnxn: EventThread shut down
    13/11/12 19:35:21 ERROR fs.MapRClient: Retrying...Fetching new Zookeeper locations from CLDB.  Attempt #1
    2013-11-12 19:35:23,1674 ERROR Cidcache fs/client/fileclient/cc/cidcache.cc:1318 Thread: 47175909750528 ClusterInfoRequest RPC error Connection reset by peer(104) for CLDB 106.103.1.82:7222
    ...
    ...
    2013-11-12 19:35:51,1695 ERROR Cidcache fs/client/fileclient/cc/cidcache.cc:1318 Thread: 47175909750528 ClusterInfoRequest RPC error Connection reset by peer(104) for CLDB 106.103.1.82:7222
    13/11/12 19:36:29 INFO zookeeper.ZooKeeper: Initiating client connection, connectString=joya-01:5181,joya-02:5181,joya-03:5181 sessionTimeout=30000 watcher=com.mapr.fs.JobTrackerWatcher@4511a3a4
    13/11/12 19:36:29 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-03/106.103.1.83:5181
    13/11/12 19:36:29 INFO zookeeper.ClientCnxn: Socket connection established to joya-03/106.103.1.83:5181, initiating session
    13/11/12 19:36:29 INFO zookeeper.ClientCnxn: Session establishment complete on server joya-03/106.103.1.83:5181, sessionid = 0x2424d61fce60012, negotiated timeout = 30000
    13/11/12 19:36:29 INFO fs.JobTrackerWatcher: findJobTrackerAddr: NoNodeFound, Retrying... Current ZooKeeper Server: joya-01:5181,joya-02:5181,joya-03:5181
    13/11/12 19:36:29 INFO fs.JobTrackerWatcher: Retrying to connect ZooKeeper Attempt# 0 Current ZooKeeper Server: joya-01:5181,joya-02:5181,joya-03:5181
    13/11/12 19:36:31 INFO fs.JobTrackerWatcher: findJobTrackerAddr: NoNodeFound, Retrying... Current ZooKeeper Server: joya-01:5181,joya-02:5181,joya-03:5181
    13/11/12 19:36:31 INFO fs.JobTrackerWatcher: Retrying to connect ZooKeeper Attempt# 1 Current ZooKeeper Server: joya-01:5181,joya-02:5181,joya-03:5181
    13/11/12 19:36:35 INFO fs.JobTrackerWatcher: findJobTrackerAddr: NoNodeFound, Retrying... Current ZooKeeper Server: joya-01:5181,joya-02:5181,joya-03:5181
    ...
    ...
    13/11/12 21:40:31 INFO fs.JobTrackerWatcher: Retrying to connect ZooKeeper Attempt# 255 Current ZooKeeper Server: joya-01:5181,joya-02:5181,joya-03:5181
    13/11/12 21:41:01 INFO fs.JobTrackerWatcher: Current running JobTracker is: joya-02/106.103.1.82:9001
    13/11/12 21:41:01 INFO ipc.RPC: Attempt# 2 . Trying to connect Server at joya-02/106.103.1.82:9001
    13/11/12 21:41:10 INFO ipc.RPC: New Active server found on joya-02/106.103.1.82:9001
    2013-11-12 21:41:10,242 Stage-1 map = 0%,  reduce = 0%
    13/11/12 21:41:10 INFO exec.MapRedTask: 2013-11-12 21:41:10,242 Stage-1 map = 0%,  reduce = 0%
    ...
    ...
    2013-11-12 21:46:50,669 Stage-1 map = 100%,  reduce = 93%
    13/11/12 21:46:50 INFO exec.MapRedTask: 2013-11-12 21:46:50,669 Stage-1 map = 100%,  reduce = 93%
    13/11/12 21:47:01 INFO zookeeper.ClientCnxn: Client session timed out, have not heard from server in 20000ms for sessionid 0x2424d61fce60012, closing socket connection and attempting reconnect
    13/11/12 21:47:02 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-01/106.103.1.81:5181
    13/11/12 21:47:02 WARN zookeeper.ClientCnxn: Session 0x2424d61fce60012 for server null, unexpected error, closing socket connection and attempting reconnect
    java.net.ConnectException: Connection refused
            at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
            at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
            at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1125)
    13/11/12 21:47:02 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-02/106.103.1.82:5181
    13/11/12 21:47:02 INFO zookeeper.ClientCnxn: Socket connection established to joya-02/106.103.1.82:5181, initiating session
    2013-11-12 21:47:07,019 Stage-1 map = 100%,  reduce = 94%
    13/11/12 21:47:07 INFO exec.MapRedTask: 2013-11-12 21:47:07,019 Stage-1 map = 100%,  reduce = 94%
    2013-11-12 21:47:10,025 Stage-1 map = 100%,  reduce = 95%
    13/11/12 21:47:10 INFO exec.MapRedTask: 2013-11-12 21:47:10,025 Stage-1 map = 100%,  reduce = 95%
    13/11/12 21:47:12 INFO zookeeper.ClientCnxn: Client session timed out, have not heard from server in 10003ms for sessionid 0x2424d61fce60012, closing socket connection and attempting reconnect
    13/11/12 21:47:13 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-03/106.103.1.83:5181
    13/11/12 21:47:13 INFO zookeeper.ClientCnxn: Socket connection established to joya-03/106.103.1.83:5181, initiating session
    13/11/12 21:47:23 INFO zookeeper.ClientCnxn: Client session timed out, have not heard from server in 10000ms for sessionid 0x2424d61fce60012, closing socket connection and attempting reconnect
    13/11/12 21:47:23 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-01/106.103.1.81:5181
    13/11/12 21:47:23 WARN zookeeper.ClientCnxn: Session 0x2424d61fce60012 for server null, unexpected error, closing socket connection and attempting reconnect
    java.net.ConnectException: Connection refused
            at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
            at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
            at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1125)
    13/11/12 21:47:24 INFO zookeeper.ClientCnxn: Opening socket connection to server joya-02/106.103.1.82:5181
    13/11/12 21:47:24 INFO zookeeper.ClientCnxn: Socket connection established to joya-02/106.103.1.82:5181, initiating session
    13/11/12 21:47:25 INFO zookeeper.ClientCnxn: EventThread shut down
    13/11/12 21:47:25 INFO zookeeper.ClientCnxn: Unable to reconnect to ZooKeeper service, session 0x2424d61fce60012 has expired, closing socket connection
    2013-11-12 21:47:33,087 Stage-1 map = 100%,  reduce = 96%
    13/11/12 21:47:33 INFO exec.MapRedTask: 2013-11-12 21:47:33,087 Stage-1 map = 100%,  reduce = 96%
    ...
    ...
    2013-11-12 22:00:07,996 Stage-1 map = 100%,  reduce = 100%
    13/11/12 22:00:07 INFO exec.MapRedTask: 2013-11-12 22:00:07,996 Stage-1 map = 100%,  reduce = 100%
    13/11/12 22:00:09 INFO exec.MapRedTask: Ended Job = job_201309111853_50009
    
    13/11/12 22:00:09 INFO exec.FileSinkOperator: Moving tmp dir: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/_tmp.-ext-10000 to: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/_tmp.-ext-10000.intermediate
    13/11/12 22:00:09 WARN exec.Utilities: Duplicate taskid file removed: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/_tmp.-ext-10000.intermediate/000002_20000 with length 12218331. Existing file: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/_tmp.-ext-10000.intermediate/000003_20000 with length 12224199
    13/11/12 22:00:09 WARN exec.Utilities: Duplicate taskid file removed: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/_tmp.-ext-10000.intermediate/000002_20001 with length 12218327. Existing file: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/_tmp.-ext-10000.intermediate/000001_20001 with length 12224792
    13/11/12 22:00:09 WARN exec.Utilities: Duplicate taskid file removed: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/_tmp.-ext-10000.intermediate/000000_20000 with length 12198714. Existing file: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/_tmp.-ext-10000.intermediate/000003_20000 with length 12224199
    13/11/12 22:00:09 INFO exec.FileSinkOperator: Moving tmp dir: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/_tmp.-ext-10000.intermediate to: maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/-ext-10000
    Loading data to table somedb.sometable
    13/11/12 22:00:09 INFO exec.MoveTask: Loading data to table somedb.sometable from maprfs:/tmp/hive-hadoop/hive_2013-11-12_19-30-16_703_5641386431431812795/-ext-10000
    13/11/12 22:00:09 INFO metastore.HiveMetaStore: 4: get_table : db=somedb tbl=sometable
    13/11/12 22:00:09 INFO HiveMetaStore.audit: ugi=hadoop  ip=unknown-ip-addr      cmd=get_table : db=somedb tbl=sometable
    13/11/12 22:00:09 INFO hive.log: DDL: struct sometable {..XXX..}
    13/11/12 22:00:09 INFO metastore.HiveMetaStore: 4: get_table : db=somedb tbl=sometable
    13/11/12 22:00:09 INFO HiveMetaStore.audit: ugi=hadoop  ip=unknown-ip-addr      cmd=get_table : db=somedb tbl=sometable
    13/11/12 22:00:09 INFO hive.log: DDL: struct sometable {..XXX..}
    Deleted maprfs:/user/hive/warehouse/somedb.db/sometable
    13/11/12 22:00:09 INFO metastore.HiveMetaStore: 4: alter_table: db=somedb tbl=sometable newtbl=sometable
    13/11/12 22:00:09 INFO HiveMetaStore.audit: ugi=hadoop  ip=unknown-ip-addr      cmd=alter_table: db=somedb tbl=sometable newtbl=sometable
    115618 Rows loaded to sometable
    13/11/12 22:00:09 INFO exec.HiveHistory: 115618 Rows loaded to sometable
    OK
    13/11/12 22:00:09 INFO ql.Driver: OK

Outcomes