协议调用时长监控
罪恶潜伏在各个角落。 --VN
游戏中的业务逻辑，通常是不建议在网络数据包接收线程池中处理的（如Netty Worker线程组），最好在自己的业务线程池中处理。但是，不管在哪里处理，我们的业务逻辑最好能快速完成。因为，游戏业务线程池的线程数量通常都是有限的，如果某个业务逻辑处理时间过长，那是可能阻塞其他玩家数据返回的，玩家体验起来会感觉游戏很“卡”。
比如业务线程池开启了8个线程，假如游戏的登录逻辑处理要1s钟，因为在登录逻辑里，可能要多次向第三方平台发送账号验证信息，这些就是额外的网络开销；还有的第一次登录逻辑里，可能会从数据库load很多功能模块数据，这些就是额外的磁盘读取开销，这些开销加起来就导致了登录逻辑处理时间过长，在高并发情况下，比如同时有9个玩家同时登录，每个业务线程分别处理一个玩家的登录，那第9个玩家首先就得先等1s，等前面8个玩家处理完后，然后自己的登录逻辑再处理1s，即需总计等待2s才能登录到游戏中。
有的游戏业务线程逻辑，还是按玩家id根据线程池大小求余绑定到指定业务线程处理的，在极端的情况下，如果上述9个玩家被分配到了同一个业务线程去处理，那么第2个玩家需要等2s钟才能登录进游戏，而第9个玩家需要等9s钟才能登录进游戏。这对玩家的游戏体验肯定是极其不好的。
因此，我们在游戏开发过程中，可以写一个工具，监测每条协议的调用时长，通过长时间的监测统计，最终选出最耗时的那几条协议处理，从而不断优化它们，使业务逻辑处理时间越来越短，提高游戏服的消息吞吐量及玩家的游戏体验。
在这个工具里，我们可以对上行协议（即发往服务端的协议）进行调用时长监控，从而优化业务处理时长；对下行协议（即服务端返回给客户端的协议）进行包长监控，从而及早把控客户端能否处理过来。
比如，对于protobuf协议可以这样设计，因为每条protobuf协议都是一个内部类：
private static final ConcurrentMap<Class<? extends Message>, Stats> STATS = new ConcurrentHashMap<>();//protobuf协议 -> 监控统计
public static void stats(Class<? extends Message> clazz, long time, int size) {
Stats stats = STATS.get(clazz);
if (stats == null) {//说明是新的protobuf协议
stats = new Stats(clazz);
Stats old = STATS.putIfAbsent(clazz, stats);
if (old != null)
stats = old;
}
stats.stats(time, size);//协议处理时长和包长记录
}
统计类Stats设计如下：
public static class Stats {
private Class<? extends Message> clazz;
private long count = 0;
private long total = 0;
private long min = Long.MAX_VALUE;
private long max = Long.MIN_VALUE;
private long minSize = 0;
private long maxSize = 0;
private long totalSize = 0;
public Stats(Class<? extends Message> clazz) {
this.clazz = clazz;
}
private synchronized void stats(long time, int size) {
count++;
total += time;
min = Math.min(min, time);
max = Math.max(max, time);
totalSize += size;
minSize = Math.min(minSize, size);
maxSize = Math.max(maxSize, size);
}
@Override
public synchronized String toString() {
StringBuilder sb = new StringBuilder();
sb.append("proto:").append(clazz.getSimpleName()).append(",")
.append("called:").append(count).append(",")
.append("avg:").append(count==0?0:total/count).append("ms,")
.append("min:").append(min==Long.MAX_VALUE?0:min).append("ms,")
.append("max:").append(max==Long.MIN_VALUE?0:max).append("ms,")
.append("avgSize:").append(count==0?0:totalSize/count).append("bytes,")
.append("minSize:").append(minSize==Long.MAX_VALUE?0:minSize).append("bytes,")
.append("maxSize:").append(maxSize==Long.MIN_VALUE?0:maxSize).append("bytes.");
return sb.toString();
}
}
在业务线程中监控协议处理如下：
long time = System.currentTimeMillis();
method.invoke(instance, session, msg);//游戏协议处理
time = System.currentTimeMillis() - time;
HandlerStatistic.stats(msg.getClass(), time, packet.getBytes().length);
返回协议监控如下：
conn.write(new Packet(Packet.HEAD_TCP, cmd, bytes));//返回客户端协议
HandlerStatistic.stats(message.getClass(), 0, bytes.length);
最后在关服时导出到文件中：
public static void dump(File file) {
FileWriter fileWriter = null;
try {
fileWriter = new FileWriter(file);
fileWriter.append("==================statistic of handler begin(")
.append(new Date().toString())
.append(")==================\n");
for (Map.Entry<Class<? extends Message>, Stats> entry : STATS.entrySet()) {
Stats stats = entry.getValue();
fileWriter.append(stats.toString()).append("\n");
}
fileWriter.append("==================statistic of handler end(")
.append(new Date().toString())
.append(")==================\n");
fileWriter.flush();
} catch (IOException e) {
log.error("write file failed", e);
} finally {
if (fileWriter != null) {
try {
fileWriter.close();
} catch (IOException e) {
log.error("close file writer failed", e);
}
}
}
}
在导出逻辑里，我们还可以对最大时长，最大返回包长做排序功能，提取前x名的请求协议或返回协议打印，从而优化它们。
最终打印信息如下(下面的把处理时间过长的筛选出来了)：
==================statistic of handler begin(Thu Apr 30 15:49:38 HKT 2020)==================
proto:LoginReq_101001,called:29,avg:154ms,min:60ms,max:947ms,avgSize:167bytes,minSize:0bytes,maxSize:188bytes.
proto:GroupChatReq_109001,called:12,avg:132ms,min:16ms,max:819ms,avgSize:53bytes,minSize:0bytes,maxSize:58bytes.
proto:PvpReq_106101,called:11,avg:37ms,min:15ms,max:64ms,avgSize:2bytes,minSize:0bytes,maxSize:2bytes.
proto:FightReq_1203004,called:6,avg:24ms,min:7ms,max:62ms,avgSize:15bytes,minSize:0bytes,maxSize:15bytes.
proto:ThresholdGetHangUpRewardReq_50003,called:2,avg:51ms,min:49ms,max:54ms,avgSize:2bytes,minSize:0bytes,maxSize:2bytes.
proto:OnekeyMailReq_104005,called:2,avg:37ms,min:25ms,max:50ms,avgSize:20bytes,minSize:0bytes,maxSize:20bytes.
proto:FactionHallReq_128004,called:1,avg:18ms,min:18ms,max:18ms,avgSize:2bytes,minSize:0bytes,maxSize:2bytes.
......
==================statistic of handler end(Thu Apr 30 15:49:38 HKT 2020)==================
这样，针对处理时间过长和包长返回过长的，我们可以查阅源码看是否有可优化的地方。
相应地，对于数据库的增删改查操作，我们也可做如此类似工具监测，以监控业务中是否时间过长的IO处理。
