协议调用时长监控

罪恶潜伏在各个角落。 --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处理。