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的，都要用同步锁或者同步代码块