hive-jdbc獲取查詢日志慢的問題發現與解決

1、問題描述：

公司的數據平台的HiveJdbc查詢一直有一個問題，就是日志獲取太慢了，有時候差不多和結果一起出來的，這就非常影響用戶的體驗，半天都沒任何輸出。另一個是Beeline客戶端不一致，beeline客戶端每次都能很快的獲取日志。
這里首先我們普及一個經驗就是第一批日志獲取的快慢，非常影響用戶體驗。如果第一批日志來的快，用戶可以確認任務已經開始跑了，MR的JobId也會返回。日志的示例如下：

INFO  : Compiling command(queryId=app_20180412185224_ebd3d373-31bb-430b-9daf-44f01049a9d4): select count(*) from ods.team
INFO  : Semantic Analysis Completed
INFO  : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:_c0, type:bigint, comment:null)], properties:null)
INFO  : Completed compiling command(queryId=app_20180412185224_ebd3d373-31bb-430b-9daf-44f01049a9d4); Time taken: 0.057 seconds
INFO  : Concurrency mode is disabled, not creating a lock manager
INFO  : Executing command(queryId=app_20180412185224_ebd3d373-31bb-430b-9daf-44f01049a9d4): select count(*) from ods.team
INFO  : Query ID = app_20180412185224_ebd3d373-31bb-430b-9daf-44f01049a9d4
INFO  : Total jobs = 1
INFO  : Launching Job 1 out of 1
INFO  : Starting task [Stage-1:MAPRED] in serial mode
INFO  : Number of reduce tasks determined at compile time: 1
INFO  : In order to change the average load for a reducer (in bytes):
INFO  :   set hive.exec.reducers.bytes.per.reducer=<number>
INFO  : In order to limit the maximum number of reducers:
INFO  :   set hive.exec.reducers.max=<number>
INFO  : In order to set a constant number of reducers:
INFO  :   set mapreduce.job.reduces=<number>
INFO  : number of splits:3
INFO  : Submitting tokens for job: job_1523499276700_0219

hive-jdbc查詢后端的流程（hive-jdbc版本2.1.0）：

1、啟動一個線程T1，T1用於阻塞獲取結果，T1還用於啟動日志獲取線程T2
2、T2啟動獲取Hive的查詢日志
詳細的代碼請看下面這個DEMO， T1就是main線程獲取hive日志的結果，T2就是LogTask獲取hive的查詢日志

public class HiveJdbcQueryLog {
  public static void main(String[] args) throws Exception {
      Class.forName("org.apache.hive.jdbc.HiveDriver");
      Connection connection = DriverManager.getConnection("jdbc:hive2://hive-server0:10000", "app", "");
      HiveStatement stmt = (HiveStatement) connection.createStatement();

      String sql = "select count(*) from table";

      try {
          Thread logThread = new Thread(new LogTask(stmt));
          logThread.setDaemon(true);
          logThread.start();
          boolean hasResult = stmt.execute(sql);
          logThread.interrupt();
          if (hasResult) {
              ResultSet resultSet = stmt.getResultSet();
              ResultSetMetaData metaData = resultSet.getMetaData();
              int colCount = metaData.getColumnCount();
              List<String> res = Lists.newArrayList();
              while (resultSet.next()) {
                  List<String> row = Lists.newArrayList();
                  for (int i = 1; i <= colCount; i++) {
                      row.add(resultSet.getString(i));
                  }
                  res.addAll(row);
              }
              System.out.println(JSON.toJSONString(res));
          } else {
              stmt.getUpdateCount();
          }
      } catch (Exception ex) {
          ex.printStackTrace();
      }finally {
          stmt.close();
          connection.close();
      }
  }

  public static class LogTask implements Runnable {
      private HiveStatement stmt;
      public LogTask(HiveStatement stmt) {
          this.stmt = stmt;
      }
      @Override
      public void run() {
          try {
              while (stmt.hasMoreLogs()) {
                  try {
                      for (String line : stmt.getQueryLog(true, 1000)) {
                          System.out.println(line);
                      }
                      Thread.sleep(200);
                  } catch (SQLException e) {
                      e.printStackTrace();
                  }
              }
          } catch (Exception e) {
              e.printStackTrace();
          }
      }
  }
}

幾個比較奇怪的現象：

1、在數據平台執行查詢任務，有時候獲取hive日志也能很快，但是大部分的時候都很慢
2、當我把DEMO里面的獲取日志的線程，也就是上述的T2線程（LogTask），里面的Sleep去掉時，日志能比較快的返回。但是HiveServer2上的日志會被打爆，因為不Sleep會獲取幾十萬次，HiveServer2容易宕機。

2個懷疑的點：

1）有可能是HiveServer2堵塞，負載高或者日志文件很大，read IO需要很長時間
2）網絡問題，HiveJdbc和HiveServer2之間是使用Thrift通信的，有可能網絡原因，導致很慢。

2、排查過程

排查過程可以說是非常曲折，剛開始中間試過打日志，用Greys看耗時等等，但是一直沒什么結果，直到最近一次排查才有突破！！

1）首先比較比較快速的是在DP服務器上用Greys查看了HiveStatement.getQueryLog方法耗時，確認第一批日志獲取有快有慢的現象，有的時候是5S左右就有返回，有的時候需要15-20S左右才有返回。結果如下：

// 一次很慢的日志獲取的，結果出來了，日志才出來
`---+Tracing for : thread_name="Thread-78" thread_id=0x84;is_daemon=true;priority=5;
    `---+[17331,17331ms]org.apache.hive.jdbc.HiveStatement:getQueryLog()
        +---[0,0ms]org.apache.hive.jdbc.HiveStatement:checkConnection(@858)
        +---[0,0ms]java.util.ArrayList:<init>(@864)
        +---[0,0ms]org.apache.hive.jdbc.HiveStatement:getFetchOrientation(@868)
        +---[0,0ms]org.apache.hive.service.rpc.thrift.TFetchResultsReq:<init>(@868)
        +---[0,0ms]org.apache.hive.service.rpc.thrift.TFetchResultsReq:setFetchType(@870)
        +---[17330,17330ms]org.apache.hive.service.rpc.thrift.TCLIService$Iface:FetchResults(@871)
        +---[17330,0ms]org.apache.hive.service.rpc.thrift.TFetchResultsResp:getStatus(@872)
        +---[17330,0ms]org.apache.hive.jdbc.Utils:verifySuccessWithInfo(@872)
        +---[17330,0ms]org.apache.hive.service.rpc.thrift.TFetchResultsResp:getResults(@895)
        +---[17330,0ms]org.apache.hive.jdbc.HiveConnection:getProtocol(@895)
        +---[17330,0ms]org.apache.hive.service.cli.RowSetFactory:create(@895)
        +---[17330,0ms]org.apache.hive.service.cli.RowSet:iterator(@896)


// 一次正常的日志獲取，大概點擊執行之后5s有了數據（5s大概是一次RPC耗時）
`---+Tracing for : thread_name="Thread-71" thread_id=0x79;is_daemon=true;priority=5;
    `---+[4557,4557ms]org.apache.hive.jdbc.HiveStatement:getQueryLog()
        +---[0,0ms]org.apache.hive.jdbc.HiveStatement:checkConnection(@858)
        +---[0,0ms]java.util.ArrayList:<init>(@864)
        +---[0,0ms]org.apache.hive.jdbc.HiveStatement:getFetchOrientation(@868)
        +---[0,0ms]org.apache.hive.service.rpc.thrift.TFetchResultsReq:<init>(@868)
        +---[0,0ms]org.apache.hive.service.rpc.thrift.TFetchResultsReq:setFetchType(@870)
        +---[4554,4554ms]org.apache.hive.service.rpc.thrift.TCLIService$Iface:FetchResults(@871)
        +---[4554,0ms]org.apache.hive.service.rpc.thrift.TFetchResultsResp:getStatus(@872)
        +---[4554,0ms]org.apache.hive.jdbc.Utils:verifySuccessWithInfo(@872)
        +---[4554,0ms]org.apache.hive.service.rpc.thrift.TFetchResultsResp:getResults(@895)
        +---[4554,0ms]org.apache.hive.jdbc.HiveConnection:getProtocol(@895)
        +---[4554,0ms]org.apache.hive.service.cli.RowSetFactory:create(@895)
        +---[4555,0ms]org.apache.hive.service.cli.RowSet:iterator(@896)

在調用hive-jdbc的client端，用Greys查詢看的耗時都在TCLIService$Iface:FetchResults方法里面。看到這個信息的時候，肯定第一反應是RPC獲取結果耗時在HiveServer端，要么是在網絡上。這就是上面我基本懷疑的2個點。 很可惜，這2個懷疑的點最后都被證明是錯的！！！！

2）然后在HiveServer端和Client端，分別開起了tcpdump監聽網絡事件，然后在T2線程（Hive日志獲取的線程）上也打上了queryLog，開始獲取log的時間，第一次收到queryLog的時間等等。開始debug！！！
不得不說tcpdump日志需要比對時間非常麻煩，下面我就直接貼出來我整理的事件時間軸：

上圖可以看出來，時間上HiveServer端收到FetchResults事件已經是19s之后了，更奇怪的是dp端通過tcpdump可以看到發出fetchResult事件也在19S之后了。所以基本排除了HiveServer的耗時操作的可能性，還有網絡超時的可能性。
基本就可以確定了，就是Client端的hive-jdbc的問題，那么到底DP端這段時間干了什么事情，還沒rpc請求就要耗時19S么？？？？雷政富tm才12s啊！！

3、翻看hive-jdbc源碼

HiveStatement和HiveConnection

// HiveStatement
public List<String> getQueryLog(boolean incremental, int fetchSize)
		throws SQLException, ClosedOrCancelledStatementException {
	List<String> logs = new ArrayList<String>();
	TFetchResultsResp tFetchResultsResp = null;
	try {
		if (stmtHandle != null) {
			TFetchResultsReq tFetchResultsReq = new TFetchResultsReq(stmtHandle,
					getFetchOrientation(incremental), fetchSize);
			tFetchResultsReq.setFetchType((short)1);
			tFetchResultsResp = client.FetchResults(tFetchResultsReq);
			Utils.verifySuccessWithInfo(tFetchResultsResp.getStatus());
		} else {
      ...........
	} catch (SQLException e) {
		throw e;
	} catch (Exception e) {
		throw new SQLException("Error when getting query log: " + e, e);
	}
  ..........
	return logs;
}

client.FetchResults方法完整的是 TCLIService.Iface.FetchResults方法，是一個Thrift接口方法。不過debug過程發現client 實際是對TCLIService.Iface的一個JDK動態代理。這樣做是為了能對client對象做同步管理，代碼如下:

// HiveConnection
public static TCLIService.Iface newSynchronizedClient(
      TCLIService.Iface client) {
    return (TCLIService.Iface) Proxy.newProxyInstance(
        HiveConnection.class.getClassLoader(),
      new Class [] { TCLIService.Iface.class },
      new SynchronizedHandler(client));
}
private static class SynchronizedHandler implements InvocationHandler {
  private final TCLIService.Iface client;

  SynchronizedHandler(TCLIService.Iface client) {
    this.client = client;
  }

  @Override
  public Object invoke(Object proxy, Method method, Object [] args)
      throws Throwable {
    try {
      synchronized (client) {
        return method.invoke(client, args);
      }
    } catch (InvocationTargetException e) {
      .......
    } catch (Exception e) {
      throw new TException("Error in calling method " + method.getName(), e);
    }
  }
}

看到這里忽然明白，很有可能是這19S都在這里等鎖了！！！

因為在結果獲取的線程T1里面也需要使用client進行RPC調用，獲取狀態client.GetOperationStatus(statusReq)，所以這里就存在鎖競爭問題啊，而且hive結果獲取的線程T1調用waitForOperationToComplete方法時，獲取狀態client.GetOperationStatus並不Sleep （T2線程獲取日志是Sleep的），所以T1(Main)線程很可能會始終占用client的鎖，導致T2(LogTask)線程獲取不到鎖。只有當T1(Main)線程獲取到了結果才釋放鎖，T2(LogTask)線程才能獲取到鎖，然后獲取日志，就造成了結果出來了才能看到日志的現象

void waitForOperationToComplete() throws SQLException {
	TGetOperationStatusReq statusReq = new TGetOperationStatusReq(stmtHandle);
	TGetOperationStatusResp statusResp;
	while (!isOperationComplete) {
		try {
			statusResp = client.GetOperationStatus(statusReq);
			Utils.verifySuccessWithInfo(statusResp.getStatus());
			if (statusResp.isSetOperationState()) {
				switch (statusResp.getOperationState()) {
				case CLOSED_STATE:
				case FINISHED_STATE:
					isOperationComplete = true;
					isLogBeingGenerated = false;
					break;
					.......
			}
		} catch (SQLException e) {
			.......
		} catch (Exception e) {
			.......
		}
	}
}

4、總結

這肯定是一個bug，找了一下Hive的jira果然已經有人提出了用ReentrantLock的公平鎖來做同步，Jira地址。ReentrantLock的公平鎖保證了T1(Main)線程用完client之后，T2(LogTask)線程是等的時間最長的，T2(LogTask)線程能獲得鎖！從而保證T2(LogTask)線程獲取日志不會在有結果之后才獲取到！！
ReentrantLock的公平鎖是一個解決方案，但是如果有些場景下查詢在同一個鏈接上執行的SQL都是順序的，可不可以不要加鎖了呢？
答案是不可以！！！
因為thrift就是垃圾，client是線程不安全的，看這個Patch就知道了，任何想多線程操作client的，都要用同步鎖或者同步代碼塊