概述
在使用公司内部后台系统测试环境时发现一个请求加载慢的问题,简简单单的列表,查询MongoDB数据库,测试环境不过几百上千条数据而已,请求耗时居然高达5~6秒:
作为对比,生产环境的请求响应截图如下:
经过持续跟进,该后台系统所有列表页面测试环境普遍比生产环境慢,不管是MongoDB还是MySQL数据库。
既然不是一个页面,也就是说查询的数据库类型不止一种,查询的DB和表不止一个,可排除因为测试环境和生产环境数据库表的索引不一致导致的。
是的,来到这家公司,发现之前根本就没有一个完善、规范、可审计、可追踪的数据库表变更上线审批工单系统;不管是开源的还是自研的,都没有。入职3个月来,收拾各种烂摊子,搭建并维护一个简陋版的开源SQL审计上线平台Archery。但是不能保证同一张DB数据表,测试和生产环境的表定义Schema相同。
另外,不管是测试还是生产环境,应用发布都是基于Git Tag。使用GitLab的compare功能,不难得知代码是同一套。于是把问题的症结抛给运维。但是没有得到很好的答复。
事实上,同后端架构技术交接一样,运维交接也是零,没有任何Wiki记录文档,没有任何交接文档,自己摸索去吧。基础设施,包括Kubernetes、网络、ELK、Nginx配置、网络转发,也是各种乱七八糟。
排查
测试环境请求慢
上面两个请求耗时异常慢的接口,都是在backend服务,都是从gateway-b网关服务转发到具体的业务承载服务。
gateway有如下两个Pod:
请求转发时,随机选择一个Pod节点,默认情况下ELK查看的是所有Pod里搜集到的应用日志。如果只想查看某个Pod的日志,要么在ELK日志查询平台指定IP:
要么使用Rancher的日志查看功能:
另一个Pod:
上面的日志截图不完全,一个比较完全的网关转发层日志记录截图如下:
gateway只是一个网关转发层,接口耗时还是得去看一下具体的接收请求的服务,如backend
服务,找到如下日志:
截图里的日期时间以及TraceId不是重点。可看到backend
服务使用ControllerLogAop记录requestBody和responseBody日志,某一次真实请求耗时仅12ms。算上请求跨微服务转发,也不可能长达几秒。所以问题应该在网关层应用上。
另外,关于日志记录多扯一句,由于所有应用都是经过gateway网关服务转发,完全可以在gateway服务里记录接口请求的requestBody和responseBody。除了在gateway里记录请求日志。在真正承载业务请求的若干个服务里也冗余Ctrl + C/V若干个ControllerLogAop类。也就是说,两层日志记录。
PS:这个测试环境请求慢的问题,优先级很低,重启可以解决,有空就去排查,前前后后1个多月搜集到若干个截图,还没定位到问题根源,也没有彻底解决。
可以看到日志打印类是PermissionFilter
,看下源码(有删减):
@Slf4j
@Component
public class PermissionFilter implements GlobalFilter, Ordered {private static final String BLACK_TOKEN = "BLACK_TOKEN:";@Resourceprivate RedisTemplate redisTemplate;@Resourceprivate JwtTokenUtil jwtTokenUtil;@Value("${jwt.header}")private String tokenHeader;@Value("${gwb.referer}")private String imsHost;@Overridepublic Mono<Void> filter(ServerWebExchange exchange, GatewayFilterChain chain) {final int NO_OPERATION_PERMISSION_CODE = 9641;final int AUTH_FAILED = 9642;ServerHttpRequest request = exchange.getRequest();ServerHttpResponse response = exchange.getResponse();String requestPath = request.getURI().getPath();log.info(requestPath);long s1 = System.currentTimeMillis();long s3 = 0;HttpHeaders headers = request.getHeaders();String username = headers.getFirst("username");if (!requestPath.contains("/auth/login/ldap")) {Assert.notNull(username, "header中的username不能为空");final String requestHeader = headers.getFirst(this.tokenHeader);Boolean invalid;String blackToken = null;if (StringUtils.isEmpty(requestHeader)) {log.error("token为空!");invalid = true;} else {try {long s2 = System.currentTimeMillis();log.info("header time consuming:{}ms", s2 - s1);String authToken = requestHeader.substring(7);blackToken = (String) redisTemplate.opsForValue().get(BLACK_TOKEN + authToken);invalid = jwtTokenUtil.isTokenExpired(authToken);String tokenName = jwtTokenUtil.getUsernameFromToken(authToken);s3 = System.currentTimeMillis();log.info("redis and token time consuming:{}ms", s3 - s2);if (!username.equals(tokenName)) {Response<Void> response = Response.error(AUTH_FAILED, "token非法!");log.info("token中用户与username不一致!");DataBuffer bodyDataBuffer = response.bufferFactory().wrap(JsonUtil.beanToJson(response).getBytes(StandardCharsets.UTF_8));return response.writeWith(Mono.just(bodyDataBuffer));}} catch (Exception e) {log.error("jwt校验发生异常!", e);invalid = true;}}if (invalid || !ObjectUtils.isEmpty(blackToken)) {Response<Void> response = Response.error(AUTH_FAILED, "token已失效!");log.info("token失效!");DataBuffer bodyDataBuffer = response.bufferFactory().wrap(JsonUtil.beanToJson(response).getBytes(StandardCharsets.UTF_8));return response.writeWith(Mono.just(bodyDataBuffer));}String postData = (String) redisTemplate.opsForValue().get(username);HashSet<String> roles;if (StringUtils.isBlank(postData)) {roles = Sets.newHashSet();} else {roles = (HashSet<String>) JSON.parseObject(postData).get("roles");}long s4 = System.currentTimeMillis();log.info("redis time consuming:{}ms", s4 - s3);// 初始值,默认为false,表示无权限AtomicBoolean isPermission = new AtomicBoolean(false);if (roles.contains(requestPath)) {log.info("path={}", requestPath);isPermission.set(true);} else {roles.forEach(role -> {if (requestPath.contains(role)) {log.info("role={}", role);log.info("path={}", requestPath);isPermission.set(true);}});}// 停止转发没有用户登录的请求if (!isPermission.get()) {Response<Void> response = Response.error(NO_OPERATION_PERMISSION_CODE, "权限不足,请检查配置!");log.info("用户没有操作权限");DataBuffer bodyDataBuffer = response.bufferFactory().wrap(JsonUtil.beanToJson(response).getBytes(StandardCharsets.UTF_8));return response.writeWith(Mono.just(bodyDataBuffer));}long s5 = System.currentTimeMillis();log.info("other time consuming:{}ms", s5 - s4);}return chain.filter(exchange);}@Overridepublic int getOrder() {return Integer.MIN_VALUE;}
}
测试环境XXL-Job任务调度异常
上面的问题并没有定位到根源。于此同时,微服务若干个定时任务采用XXL-Job调度平台,基于Spring Cloud Gateway来实现请求转发,参考Spring@Scheduled定时任务接入XXL-JOB的一种方案-基于SC Gateway。
测试环境定时调度任务收到如下执行异常告警邮件:
进入测试环境的XXL-Job管理平台,查看调度日志:
可知问题是偶发,具体的错误日志:
[com.aaaaa.gateway.config.SampleXxlJob#httpJobHandler]-[99]-[Thread-72] java.net.ConnectException: Connection refused (Connection refused)at java.base/java.net.PlainSocketImpl.socketConnect(Native Method)at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399)at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242)at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224)at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:403)at java.base/java.net.Socket.connect(Socket.java:591)
熟悉的连接被拒绝:java.net.ConnectException: Connection refused
。
进一步分析应用层日志,8点5分和5点5分两次的定时任务执行成功:
打印xxlJob调度执行返回数据=
这一行日志,也就是有回调动作的,才算是任务执行成功。
实际上,任务调度已经随机下发成功,即选择一个Kubernetes Pod成功,只是没有收到执行成功的回调。
穷途末路
上面两个问题都定位不到根源,穷途末路。
本地Debug模式启动gateway网关应用,借助于IDEA插件Profiler,也没分析出个啥。
本地Debug模式启动包括gateway网关应用在内的多个服务,通过gateway转发请求到别的服务,如backend
,速度也很快,Postman显示不到1s。
考虑到本地可以连接到测试环境Redis节点,编写单元测试:
@Test
public void testRedis() {long s1 = System.currentTimeMillis();String postData = (String) redisTemplate.opsForValue().get("my.domain.name");HashSet<String> roles = (HashSet<String>) JSON.parseObject(postData).get("roles");long s2 = System.currentTimeMillis();log.info("time consuming:{}ms", s2 - s1);
}
多次执行结果:
time consuming:130ms
time consuming:114ms
本地连接Redis速度挺快,不到150ms。为啥测试环境kubernetes集群连接Redis取数据耗时,短的要1s左右,长的要10s左右???
分析过SkyWalking Dashboard,没看出个啥。
Kubernetes Pod内存不一致
分析kubernetes Pod。借助于Prometheus + Grafana提供的分析面板Dashboard:
发现两处不太正常的地方:
- 两个Pod内存指标数据不一致,差距有点大。
具体来说,一个Pod Current内存是1.419GiB
另一个是2.013GiB。
- 都是保持着持续上涨的趋势
从1月24日应用发布以来到2月4日,两个Pod的Limit和Requested不变,是一条直线。其中Requested都是512MiB,Limit都是4GiB。
Current和Cache一直保持增长,Current总是大于Cache。截图没有体现出来,截止到2月4日,Current为1.580GiB,Cache为1.502GiB:
另一个Pod差不多也是这样的增长趋势:
但在1月29日凌晨左右,Cache超过Current保持一路高升趋势,到2月4日Cache高达3.193GiB,Current高达2.405GiB:
其余指标,如CPU和Network IO一直都很平稳。
参考
- kubernetes-pod-high-cache-memory-usage