概述

在使用公司内部后台系统测试环境时发现一个请求加载慢的问题，简简单单的列表，查询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