概述
在使用公司内部后台系统测试环境时发现一个请求加载慢的问题，简简单单的列表，查询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:";
@Resource
private RedisTemplate redisTemplate;
@Resource
private JwtTokenUtil jwtTokenUtil;
@Value("${jwt.header}")
private String tokenHeader;
@Value("${gwb.referer}")
private String imsHost;
@Override
public 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);
}
@Override
public 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一直都很平稳。