一、起因
业务方反馈说图服务升级后gremlin查询性能较之前旧版本慢了五倍
,特此记录下定位记录和思路。
二、思路和步骤
- 由于新旧版数据库此时并行在一起,尚未切量,故无法通过监控来查看相关信息,使用的是一套集群。我们从server端比较好入手
- 由于hugegraph采用存算分离,我们首先需要确定慢是由于图
server端/client端/hbase
,层层推进。首先找到图server调用gremlin的API,这里使用阿里的开源项目artha来剖析 (⚠️注意:我们以下的查询每次均为不同的查询语句,因为图本身具有缓存,查询过的点边都会加入缓存而不走我们跟踪的路径,事先找几个案例进行查询)
2.1准备工作:
下载并启动arthas
curl -O https://arthas.aliyun.com/arthas-boot.jar && java -jar arthas-boot.jar
2.2 链路追踪
1.我们执行 trace com.baidu.hugegraph.api.gremlin.GremlinAPI get
,然后使用postman执行查询语句,查看gremlin的调用链路及其耗时,其中trace com.baidu.hugegraph.api.gremlin.GremlinAPI
为调用的类,get
为调用方法:
`---ts=2021-05-10 16:10:28;thread_name=grizzly-http-server-28;id=63;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@232204a1
`---[45097.334926ms] com.baidu.hugegraph.api.gremlin.GremlinAPI:get() [throws Exception]
+---[0.016083ms] javax.ws.rs.core.HttpHeaders:getHeaderString() #114
+---[0.009815ms] javax.ws.rs.core.UriInfo:getRequestUri() #115
+---[0.034164ms] javax.ws.rs.core.UriInfo:getQueryParameters() #116
+---[0.009963ms] com.baidu.hugegraph.api.gremlin.GremlinAPI:client() #117
//重点关注此处
+---[45034.476917ms] com.baidu.hugegraph.api.gremlin.GremlinClient:doGetRequest() #95
+---[0.045994ms] com.codahale.metrics.Histogram:update() #118
+---[0.024552ms] javax.ws.rs.core.Response:getLength() #119
+---[0.019595ms] com.codahale.metrics.Histogram:update() #95
+---[62.2564ms] com.baidu.hugegraph.api.gremlin.GremlinAPI:transformResponseIfNeeded() #120 [throws Exception]
`---throw:com.baidu.hugegraph.exception.HugeGremlinException #152 [null]
- 定位到耗时最久的函数后,我们依次对此函数进行跟踪并在前端执行查询语句
trace com.baidu.hugegraph.api.gremlin.GremlinClient doGetRequest
:
`---ts=2021-05-10 16:15:09;thread_name=grizzly-http-server-27;id=62;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@232204a1
`---[2395.877787ms] com.baidu.hugegraph.api.gremlin.GremlinClient:doGetRequest()
+---[0.025715ms] javax.ws.rs.core.MultivaluedMap:entrySet() #65
+---[0.012735ms] com.baidu.hugegraph.util.E:checkArgument() #66
+---[0.136357ms] javax.ws.rs.client.WebTarget:queryParam() #70
+---[0.113385ms] javax.ws.rs.client.WebTarget:request() #72
+---[0.032459ms] javax.ws.rs.client.Invocation$Builder:header() #73
+---[0.027921ms] javax.ws.rs.client.Invocation$Builder:accept() #74
+---[0.015461ms] javax.ws.rs.client.Invocation$Builder:acceptEncoding() #75
`---[2395.244523ms] javax.ws.rs.client.Invocation$Builder:get() #76
看到进入了客户端查询,我们切入客户端
- 执行
trace com.baidu.hugegraph.backend.store.hbase.HbaseTable query -n 10 '#cost>100'
其中#cost>
表示过滤出查询耗时大于多少毫秒的查询,-n
表示获取多少次查询结束调用
`---ts=2021-05-10 17:52:20;thread_name=gremlin-server-exec-13;id=28d1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@232204a1
`---[104.269486ms] com.baidu.hugegraph.backend.store.hbase.HbaseTable:query()
+---[0.002985ms] com.baidu.hugegraph.backend.query.Query:limit() #156
+---[104.241873ms] com.baidu.hugegraph.backend.store.hbase.HbaseTable:query() #162
| `---[104.232068ms] com.baidu.hugegraph.backend.store.hbase.HbaseTable:query()
| +---[0.002668ms] com.baidu.hugegraph.backend.query.Query:empty() #167
| +---[0.002552ms] com.baidu.hugegraph.backend.query.Query:conditions() #184
| +---[0.002382ms] com.baidu.hugegraph.backend.query.Query:ids() #186
| +---[0.002212ms] com.baidu.hugegraph.backend.query.Query:ids() #187
//关注此耗时最久
| `---[104.200252ms] com.baidu.hugegraph.backend.store.hbase.HbaseTable:queryById() #188
`---[0.007368ms] com.baidu.hugegraph.backend.store.hbase.HbaseTable:newEntryIterator() #95
- 如上可看到
queryById
这个函数耗时最久,似乎进入了hbase,此时基本可确认是hbase层面的问题,我们继续验证,trace com.baidu.hugegraph.backend.store.hbase.HbaseTable queryById -n 10 '#cost>100'
`---ts=2021-05-10 17:55:23;thread_name=gremlin-server-exec-20;id=28e0;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@232204a1
`---[117.206504ms] com.baidu.hugegraph.backend.store.hbase.HbaseTable:queryById()
+---[0.002969ms] com.baidu.hugegraph.backend.store.hbase.HbaseTable:table() #210
+---[0.002292ms] com.baidu.hugegraph.backend.id.Id:asBytes() #95
`---[117.1856ms] com.baidu.hugegraph.backend.store.hbase.HbaseSessions$HbaseSession:get() #95
- 继续跟踪
trace com.baidu.hugegraph.backend.store.hbase.HbaseSessions$HbaseSession get -n 10 '#cost>100'
`---[294.896811ms] com.baidu.hugegraph.backend.store.hbase.HbaseSessions$Session:get()
`---[294.891196ms] com.baidu.hugegraph.backend.store.hbase.HbaseSessions$Session:get() #427
`---[294.885125ms] com.baidu.hugegraph.backend.store.hbase.HbaseSessions$Session:get()
+---[0.001963ms] org.apache.hadoop.hbase.client.Get:<init>() #658
+---[0.032304ms] com.baidu.hugegraph.backend.store.hbase.HbaseSessions:access$100() #663
//进入get hbase数据了
+---[294.828674ms] org.apache.hadoop.hbase.client.Table:get() #664
+---[0.003014ms] com.baidu.hugegraph.backend.store.hbase.HbaseSessions$RowIterator:<init>() #95
`---[0.001837ms] org.apache.hadoop.hbase.client.Table:close() #95
由上可见,瓶颈不在图server/client(耗时很小),问题出在hbase的查询慢
2.3 hbase为何查询慢?
我们的新旧版本图数据库布在同一hbase集群,若慢也应该都慢,除非有什么特殊?哦,是之前的异构策略~
我们hdfs的三副本采用的是 1ssd,2hdd
的策略,保证读io打到ssd保证性能,赶紧去hdfs下查询异构:
hdfs storagepolicies -getStoragePolicy -path /home/hbase/data/netlabpro/g_ie
果然 此时没有任何策略,看来是异构失效了,可是它怎么会失效呢?哦,我傻了,升级后虽然设置了一次异构,然后后来由于业务方清理导入进程失误以及其他问题,又重新进行了删表重建,而并没有设置异构策略,且由于之前索引数据过大,我们的异构是表级别的,而不是db级别的,因此在我重建region信息的时候,之前的异构就消失了,于是将其设置为db级别(子默认路径继承异构策略),避免异构消失。
~/software/hadoop/bin/hdfs storagepolicies -setStoragePolicy -path /home/hbase/data/netlabpro/ -policy ONE_SSD
ok 对表做一次compaction在查询,耗时正常。
三、hotfix
线上热修改又是另一救命神器,可以在不重启的前提下进行线上热修复。三连 如:
1. 反编译看线上代码 可用vi 修改
jad --source-only *BackendStore > /tmp/BackendStore.java`
2. 修改后重新编译为class
mc -d /tmp/output /tmp/BackendStore.java
3.加载新的字节码
retransform /tmp/com/example/demo/arthas/user/BackendStore.class
三连后可线上运行修改后的代码,但是不可重启,不可使用一下watch之类的命令,否则会失效具体看文档