1.问题与现象
业务反馈 Phoniex 最近总是有 10 多秒的超时。我们测试的时候发现 Phoenix Client（ JDBC ） 第一次查询（基于 rowkey scan）的时候特别慢，即时是 expalin 这条 sql 也很慢，耗时达到 10s+，再查就很快，毫秒级。简称冷启动查询很慢。
问题必现，操作步骤如下：
- 进入 phoenix-client/bin/sqlline.py
- 执行 sql ：
select "record" from "secondline"."use_log_info" where "ROW" between '0155822583120211001000000000000' and '0155822583120211020zzzzzzzzzzzz' limit 2; - CTRL + C ，退出 shell
2. 结论
原因是 Phoenix 对于表 scan 类型的查询，第一次会查询表的 stats 信息（SYSTEM.STATS）并缓存到客户端（这个信息用来对 scan 执行计划进行优化），由于业务的表巨大，stats 信息特别多，导致这个操作耗时很久，引起冷启动查询慢的问题；
3. 问题定位过程
查看这张表 "secondline"."use_log_info" 有 2500+ region ，行数应该在百亿级别。最开始猜测：由于表太大，scan 查询本身是查询是很慢，后续再查走的缓存，所以很快，是正常的。
3.1 到底是谁的问题？HBase vs Phoenix
不确定是 hbase 本身的问题还是 phoenix 的问题，所以用排除法验证。我把这条 phoenix sql 用 Java HBase Client API 重写了，线上执行耗时 130 ms，所以基本可以排除 HBase 本身的性能问题，那问题就应该出在 Phoenix。其实也可以通过经验分析，业务的 rowkey 是基于：手机号倒序+时间+hash 拼接的。业务 scan 也基本都是针对单个手机号，没有负责的 filter，rowkey 是字典排序，前缀相同，scan 的数据范围应该不会跨多个 region，所以性能应该尚可。
3.2 Phoenix 表大小的问题
为了验证是不是表规模的问题，我用上述同样的步骤查询一张百万级的小表（2 个 region），确实没有出现冷启动问题，第一次查询很快。初步可以断定是表太大了会出现此类问题。
3.3 通过 Phoneix 源码分析问题
实在没辙，写了个 Java phoenix jdbc demo 程序放线上跑起来，日志级别调成 debug 。通过执行日志，可以清晰的看到第一次查询在 execute.ScanPlan 和 Iterator ready 之间卡了 10s 之久。
image.png
通过源码跟踪，卡住的这块代码是没有提交任务的，主要是在生成执行计划，怀疑是这一步里面有大量的循环计算或者是第一次请求元数据引起的耗时。
// 就卡在这一步，是在生成执行计划
ResultIterator iterator = newIterator(scanGrouper);
一路跟代码，大部分都是在初始化执行计划，设置优化参数等；跟到这里有两个地方在获取数据
public BaseResultIterators(QueryPlan plan, Integer perScanLimit, ParallelScanGrouper scanGrouper) throws SQLException {
super(plan.getContext(), plan.getTableRef(), plan.getGroupBy(), plan.getOrderBy(), plan.getStatement().getHint(), plan.getLimit());
this.plan = plan;
this.scanGrouper = scanGrouper;
StatementContext context = plan.getContext();
// Clone MutationState as the one on the connection will change if auto commit is on
// yet we need the original one with the original transaction from TableResultIterator.
this.mutationState = new MutationState(context.getConnection().getMutationState());
TableRef tableRef = plan.getTableRef();
PTable table = tableRef.getTable();
physicalTableName = table.getPhysicalName().getBytes();
// 1.如果使用 stats，则获取表的 stats 信息
tableStats = useStats() ? new MetaDataClient(context.getConnection()).getTableStats(table) : PTableStats.EMPTY_STATS;
// Used to tie all the scans together during logging
scanId = UUID.randomUUID().toString();
initializeScan(plan, perScanLimit);
// 2.这里会获取表的所有 region location 信息
this.scans = getParallelScans();
List<KeyRange> splitRanges = Lists.newArrayListWithExpectedSize(scans.size() * ESTIMATED_GUIDEPOSTS_PER_REGION);
for (List<Scan> scanList : scans) {
for (Scan aScan : scanList) {
splitRanges.add(KeyRange.getKeyRange(aScan.getStartRow(), aScan.getStopRow()));
}
}
this.splits = ImmutableList.copyOf(splitRanges);
// If split detected, this will be more than one, but that's unlikely
this.allFutures = Lists.newArrayListWithExpectedSize(1);
}
3.3.1 猜测卡在获取表 region location 这里
其中 this.scans = getParallelScans(); 里面会遍历 meta 表获取 region 元数据信息（表所有的 region location 以及对应的 start key 和 end key）。 具体的 API phoneix 用到了 HConnection.getRegionLocation，其实是一个过时的 API 了，代码也解释了用它是因为它有缓存，所以下次一次读就可以直接走缓存。代码如下：
@Override
public List<HRegionLocation> getAllTableRegions(byte[] tableName) throws SQLException {
/*
* Use HConnection.getRegionLocation as it uses the cache in HConnection, while getting
* all region locations from the HTable doesn't.
*/
int retryCount = 0, maxRetryCount = 1;
boolean reload =false;
while (true) {
try {
// We could surface the package projected HConnectionImplementation.getNumberOfCachedRegionLocations
// to get the sizing info we need, but this would require a new class in the same package and a cast
// to this implementation class, so it's probably not worth it.
List<HRegionLocation> locations = Lists.newArrayList();
byte[] currentKey = HConstants.EMPTY_START_ROW;
do {
HRegionLocation regionLocation = connection.getRegionLocation(
TableName.valueOf(tableName), currentKey, reload);
locations.add(regionLocation);
currentKey = regionLocation.getRegionInfo().getEndKey();
} while (!Bytes.equals(currentKey, HConstants.EMPTY_END_ROW));
return locations;
} catch (org.apache.hadoop.hbase.TableNotFoundException e) {
String fullName = Bytes.toString(tableName);
throw new TableNotFoundException(SchemaUtil.getSchemaNameFromFullName(fullName), SchemaUtil.getTableNameFromFullName(fullName));
} catch (IOException e) {
if (retryCount++ < maxRetryCount) { // One retry, in case split occurs while navigating
reload = true;
continue;
}
throw new SQLExceptionInfo.Builder(SQLExceptionCode.GET_TABLE_REGIONS_FAIL)
.setRootCause(e).build().buildException();
}
}
}
最开始怀疑问题是这里导致的。第一次需要获取 region 元数据信息，大表的 region 确实很多，达到 2000 +。第一次耗时久，后续可以直接走缓存就很快。。而小表元数据很少，不存在这个问题。跟目前的现象是一致的。
但是经验又告诉我好像不太对，hbase client 基本都会获取一次表 region 信息，不至于要 10 几秒，为了验证，我把这段代码直接拿线上跑了一次，耗时 1300ms 左右，也就是这张大表耗时 1.3s 拿到所有的 region 信息。所以这个猜测 pass。
3.3.2 猜测卡在获取 table stats
继续看代码，有一段是获取 table stats 信息：tableStats = useStats() ? new MetaDataClient(context.getConnection()).getTableStats(table) : PTableStats.EMPTY_STATS; 继续怀疑是它。
这里了解下 table stats 是什么？ 通过 Phoenix 来扫描最大的问题就是数据倾斜导致不方便并行化，因此首先要解决的问题是找到一种能均匀分片的方式。Phoenix 的 Statistics Collection 文档 提到了 Phoenix 内部通过收集数据的统计信息（table stats）来实现扫描并行化：
The UPDATE STATISTICS command updates the statistics collected on a table. This command collects a set of keys per region per column family that are equal byte distanced from each other. These collected keys are called guideposts and they act as hints/guides to improve the parallelization of queries on a given target region.
这些统计信息保存在 SYSTEM.STATS 表当中，可以通过表名查到对应的信息：
SELECT COLUMN_FAMILY, GUIDE_POST_KEY, GUIDE_POSTS_WIDTH, GUIDE_POSTS_ROW_COUNT
FROM SYSTEM.STATS
WHERE PHYSICAL_NAME = 'secondline:use_log_info''
LIMIT 5;
| COLUMN_FAMILY | GUIDE_POST_KEY | GUIDE_POSTS_WIDTH | GUIDE_POSTS_ROW_COUNT |
|---|---|---|---|
| info | rowkey bytes | 314572865 | 1063441 |
| info | rowkey bytes | 314573187 | 1071522 |
| info | rowkey bytes | 314573504 | 1051022 |
| info | rowkey bytes | 314572810 | 1036136 |
这个结果显示 Phoenix 保存了很多个 row key 的值，这些 key 之间大约间隔 300MB，100 万行，分布非常均匀。
看下什么情况需要获取 stats，以下两种情况，不需要获取 guide ：
- point lookup ，因为 HBase 本身就很擅长这种查询，所以不需要做额外的并行化处理。这里我理解 point lookup 就是 rowkey get 查询，因为 HBase 本身就是 key value 数据库，直接查就好了，不需要做优化。
- 正在采集 stats 数据的时候，有一种场景，我们需要扫描整个 region 信息，这时候不需要。
private boolean useStats() {
Scan scan = context.getScan();
boolean isPointLookup = context.getScanRanges().isPointLookup();
/*
* Don't use guide posts if:
* 1) We're doing a point lookup, as HBase is fast enough at those
* to not need them to be further parallelized. TODO: perf test to verify
* 2) We're collecting stats, as in this case we need to scan entire
* regions worth of data to track where to put the guide posts.
*/
if (isPointLookup || ScanUtil.isAnalyzeTable(scan)) {
return false;
}
return true;
}
为了验证是不是这里慢了，基于以上分析，我将上述步骤中的 scan sql 换成 get（point lookup），这样可以跳过获取 stats 这一步。还是查询那张大表，执行 sql：select * from "secondline"."use_log_info" where "ROW" = ‘xxx’; 终于看到曙光，果然没有冷启动问题，第一次耗时 1s 多 (主要在获取 region 元数据)，第二次毫秒级，那基本可以定位出就是慢在获取 stats 这一步了。
分析下为什么这一步很慢。查看具体的实现，在获取此表在 SYSTEM.STATS 的信息，并逐行分析写入缓存。。通过 sql 查看有 64430 行数据 （SELECT count(1) FROM SYSTEM.STATS WHERE PHYSICAL_NAME = 'secondline:use_log_info';）里面涉及到大量的复杂逻辑，留给以后再深入。（#todo）
public PTableStats getTableStats(PTable table) throws SQLException {
/*
* The shared view index case is tricky, because we don't have
* table meta data for it, only an HBase table. We do have stats,
* though, so we'll query them directly here and cache them so
* we don't keep querying for them.
*/
boolean isSharedIndex = table.getViewIndexId() != null;
if (isSharedIndex) {
// we are assuming the stats table is not transactional
return connection.getQueryServices().getTableStats(table.getPhysicalName().getBytes(), getCurrentScn());
}
boolean isView = table.getType() == PTableType.VIEW;
String physicalName = table.getPhysicalName().getString();
if (isView && table.getViewType() != ViewType.MAPPED) {
try {
return connection.getTable(new PTableKey(null, physicalName)).getTableStats();
} catch (TableNotFoundException e) {
// Possible when the table timestamp == current timestamp - 1.
// This would be most likely during the initial index build of a view index
// where we're doing an upsert select from the tenant specific table.
// TODO: would we want to always load the physical table in updateCache in
// this case too, as we might not update the view with all of it's indexes?
String physicalSchemaName = SchemaUtil.getSchemaNameFromFullName(physicalName);
String physicalTableName = SchemaUtil.getTableNameFromFullName(physicalName);
MetaDataMutationResult result = updateCache(null, physicalSchemaName, physicalTableName, false);
if (result.getTable() == null) {
throw new TableNotFoundException(physicalSchemaName, physicalTableName);
}
return result.getTable().getTableStats();
}
}
return table.getTableStats();
}
4. 解决办法
- 减小表的数据规模
- 改用 phoenix queryserver，只要 queryserver 不重启缓存不会失效。
5. 总结
定位性能问题需要完善的日志与监控(metrics)，不然每次遇到问题只能摸着石头过河了，想当然。
遇到问题尽量基于日志，基于源码分析。
网友评论