Socket接口固定QPS性能测试实践

在学习了Socket协议的知识和完善固定QPS压测模型之后,打算对Socket.IO协议的接口进行一波压测实践,来验证自己写的功能是否存在BUG和更多能做的优化空间。

总结下来,修复了两三个BUG,性能测试进度条的计算方式进行了优化,不然在类似Socket这种异步处理的请求,可能会由于统计的doing()方法耗时太少,导致计算出错,会出现突然跳到循环展示程序,直接显示100%,当然这也是一个BUG

思路

首先由一个老师和一个学生连接Socket.IO,然后老师进入一个房间(提前构造测试数据),不停地发送某个获取数据的指令,这里采取固定QPS性能测试模型。为了更好描述性能,我引入了一个指标,消息响应延迟,用来表示Socket服务对于正常业务的处理能力。

监控线程

依然采用了内部静态类的形式,用的顺了就习惯了,比较简单,就是Groovy访问静态属性的时候有点问题,捯饬了好一阵子才解决编译报错的问题。其实直接运行Groovy脚本完全可以,大家用的时候可以不用理会编译报错。

/**
     * 监控延迟
     */
    static class ListenThread extends SourceCode implements Runnable {

        public boolean key = true;

        public ScoketIOFunClient listen;

        public List<Long> delays = []

        ListenThread(ScoketIOFunClient listen) {
            this.listen = listen
        }

        @Override
        void run() {
            listen.send(OkayScoketConstant.EVENT, getChat(roomId + 1, sbase.uname as long, tbase.uid, kid, ktype, DEFAULT_STRING, true))
            sleep(3.0)
            while (key) {
                def msg = StringUtil.getString(20)
                def start = Time.getTimeStamp()
                listen.send(OkayScoketConstant.EVENT, getChat(roomId + 1, sbase.uname as long, tbase.uid, kid, ktype, msg, true))
                for (int i = 0; i < 10; i++) {
                    def last = listen.msgs.getLast()
                    if (last.contains(msg)) break
                }
                def end = Time.getTimeStamp()
                def l = end - start
                delays << l
                logger.info("响应延迟时间:{}ms", l)
                sleep(3.0)
            }
        }

        public void stop() {
            key = false
            Save.saveLongList(delays, "delays")
        }
    }

多线程任务

这里采用了FixedQpsThread<ScoketIOFunClient>这个模式,目前全局使用一个Socket实例,并发完全满足,因为是异步的,所以毫无压力,若是测试多用户在线的场景,需要提前向房间内加入用户。

  • 这里我取消了Socket.IO响应消息的打印,为了防止日志太多,导致性能下降。
static class SendMsg extends FixedQpsThread<ScoketIOFunClient> {

        SendMsg(ScoketIOFunClient scoketIOFunClient) {
            super(scoketIOFunClient, getNum(), getQps(), null, true)
        }

        @Override
        protected void doing() throws Exception {
            t.send(OkayScoketConstant.EVENT, getCorrect(sbase.getUid(), 1, 24, 4))
        }

        @Override
        FixedQpsThread clone() {
           new SendMsg(this.t)
        }
    }

测试脚本

这个没啥好说的,可以翻看以前的文章。

class ST1 extends SocketBase {

    private static Logger logger = LoggerFactory.getLogger(ST1.class)

    static int roomId = 44465

    static int kid = 540

    static int ktype = 1

    static IBase tbase

    static IBase sbase

    static int qps = 200

    static int num = 4000

    public static void main(String[] args) {
        tbase = getTeaBase()
        sbase = getStuBase()
        ScoketIOFunClient teacher = getSocket(tbase)
        ScoketIOFunClient student = getSocket(sbase)

        initAll()
        registerAll()
        joinRoom(roomId)

        teacher.send(OkayScoketConstant.EVENT, getCorrect(sbase.getUid(), 1, 24, 4))

        def thread = new ListenThread(student)
        def thread1 = new Thread(thread)
        thread1.start()
        new FixedQpsConcurrent(new SendMsg(teacher), "测试不同压力下消息延迟").start()

        thread.stop()
        thread1.join()
        leaveRoom(roomId)

        ScoketIOFunClient.closeAll()
    }
}

控制台输出

INFO-> 当前用户:fv,IP:10.60.193.37,工作目录:/Users/fv/Documents/workspace/okay_test/,系统编码格式:UTF-8,系统Mac OS X版本:10.16
INFO-> 请求uri:https://teacherpad-***.cn/api/t_pad/user/login,耗时:985 ms, requestId:Fun20210220090333dMSx
INFO-> 教师:62951571858,学科:null,名称:背锅侠六二六,登录成功!
INFO-> 请求uri:https://stupad-dev***.cn/api/pad/user/login,耗时:187 ms, requestId:Fun20210220090334etdZ
INFO-> 用户:82951571513,登录成功!
INFO-> Socket 连接: http://aileaidGltZ97Fs&userType=1,客户端名称: 老师:62951571858
INFO-> Socket 连接: http://1MPkp-zlk&userType=2,客户端名称: 学生:82951571513
INFO-> 学生:82951571513 开始连接...
INFO-> 学生:82951571513 连接成功!
INFO-> 老师:62951571858 开始连接...
INFO-> 老师:62951571858 连接成功!
INFO-> 补偿线程开始!
INFO-> 响应延迟时间:7ms
INFO-> 测试不同压力下消息延迟进度:▍▍▍▍▍▍▍▍▍▍▍▍▍  20.35%
INFO-> 响应延迟时间:1ms
INFO-> 响应延迟时间:1ms
INFO-> 期望执行数:2000,实际执行数:1652,设置QPS:200
INFO-> 测试不同压力下消息延迟进度:▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍  41.4%
INFO-> 响应延迟时间:1ms
INFO-> 响应延迟时间:2ms
INFO-> 测试不同压力下消息延迟进度:▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍  63.9%
INFO-> 响应延迟时间:1ms
INFO-> 测试不同压力下消息延迟进度:▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍  86.78%
INFO-> 响应延迟时间:1ms
INFO-> 测试不同压力下消息延迟进度:▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍▍  100%
INFO-> 总计执行 4000次任务 ,共用时:23.715 s,执行总数:4133,错误数:0!
INFO-> 数据保存成功!文件名:/Users/fv/Documents/workspace/okay_test/long/data/测试不同压力下消息延迟200903_1
INFO-> 
~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~ JSON ~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~
>  {
>  ① . "rt":0,
>  ① . "total":4133,
>  ① . "qps":-6.829,
>  ① . "failRate":0.0,
>  ① . "threads":1,
>  ① . "startTime":"2021-02-20 09:03:41",
>  ① . "endTime":"2021-02-20 09:04:04",
>  ① . "errorRate":0.0,
>  ① . "executeTotal":4133,
>  ① . "mark":"测试不同压力下消息延迟200903",
>  ① . "table":"eJzj5VIgDjzb2v1i/dQnO3qfTuh52tf9tGv2kx3dz7Z1PGtc/3T3thf75xsZGFgaGBsSaRwvFy9+m4NSiwvy84pTFUIyc1OtFCp0i1OLMhNzFPJKc3UUKnVzU1MyE/MI2UGMS3Iz8xQgplkZKOQW6+QmVlgZAxnE+YIYVWSDR9M6gGjUllFbRm0ZUbY8mtYERPSxCWzFqE2jNo3aNGJtejStFYgop6jpImSzqEONumjURaMuGnXRqItwuwgADK4ysA=="
>  }
~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~ JSON ~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~~☢~
INFO-> 
                                       测试不同压力下消息延迟2009031                                       

                             Response Time: x-serial num, y-median                              
                                    min median:0 ms,max:3 ms                                    

******见下图*******


INFO-> 数据保存成功!文件名:/Users/fv/Documents/workspace/okay_test/long/delays
INFO-> 老师:62951571858 socket链接关闭!
INFO-> 学生:82951571513 socket链接关闭!
INFO-> 关闭所有Socket客户端!
INFO-> 测试不同压力下消息延迟进度:  0%
INFO-> 补偿线程结束!

Process finished with exit code 0

测试不同压力下消息延迟2009161

这里依然存在一些问题,如下:

  • QPS计算出错,这里是因为补偿线程导致的,因为太快了,补偿线程应该处理的这些问题,哈哈,这个我在HTTP接口测试时候没有这个问题的。
  • 由于测试时间偏短,其他辅助线程都是循环机制,所以导致日志可能会出错。比如INFO-> 测试不同压力下消息延迟进度: 0%这个是因为在测试任务结束后,我会把执行数重置为0,但是此时进度条任务还未结束,所以多打印了一次。这个已经确认了优化方式。
  • 补偿的请求的时机和补偿机制还有优化空间,总执行数4133比设定值4000高了不少,后面因为是固定量然后循环补偿,可能这个时候任务发生了变化,所以待优化。

参考文章:


FunTester腾讯云社区钦定年度作者,非著名测试开发er,欢迎关注。