在Java中如何准确定位耗时长的方法

Posted 2023-03-23 最后一根头发

场景说明

我是在使用Spark的时候出现某个task一直不结束或者尤其慢的问题，一开始猜测是数据倾斜问题，后来发现是某类数据会导致在调用正则匹配时出现耗时特别长的情况。

定位思路

使用Arthas的profiler功能来定位耗时过长的方法链。

具体操作

实际环境是因为是公司的环境不便贴出来，我就用本地模拟一下此场景。

1. 准备一个linux虚拟机环境。
2. 下载 arthas jar包。
   curl -O https://arthas.aliyun.com/arthas-boot.jar
3. 准备一个大文本。
4. 编写一个耗时死循环代码。代码只是为了测试粗略写的，请忽略编码规范。

public class DeadThread 

    public static void main(String[] args) 
        DeadThread dt = new DeadThread();
        while (true) 
            for (int i = 0; i < 100; i++) 
                dt.readFileInvoke();
            
        

    
    
    public void readFileInvoke() 
        ReadFiles readFiles = new ReadFiles();
        String readStr = readFiles.readFiles();
        //从大文本中提取一个内容，模拟之前发现的问题。
        String pattern = "《[\\\\u4e00-\\\\u9fa5]*》";
        Pattern p = Pattern.compile(pattern);
        Matcher m = p.matcher(readStr);
        Random random = new Random();
        ThreadController threadController = new ThreadController();
        threadController.sleep_thread(random);
        List<String> list = new ArrayList<String>();
        while (m.find()) 
            String data = m.group();
            list.add(data);
        
    

public class ThreadController 
    //空转一定时间，和Thread.sleep是相同的效果，只是Thread.sleep实际场景使用的少，而且从profiler中看到的不明显。
    public void sleep_thread(Random random) 

        int time = random.nextInt(10);
        long now = System.currentTimeMillis();
        System.out.println("sleep" + (time * 1000));
        while (System.currentTimeMillis() <= now + time * 1000) 

        
    

5. 打jar包到服务器上执行。
6. ps -ef | grep java 或者 jps 查看刚刚执行的进程pid
7. java -jar arthas-boot.jar --telnet-port 9998 --telnet-port 9998 是为了解决端口冲突问题，如果在同一台机器切入多个进程需要用不同的telnet端口来进行切入通信。也能避免其他服务的端口的占用冲突。
8. 选择要切入的进程，切进去。
9. profiler start --event itimer开始收集样本
   profiler 的参数很多，可以自行参考文档。
10. profiler stop --format html --file /usr/local/arthas_test/data/result_itimer.html
    收集一段时间后把结果导出到指定目录。此处我们导出来的是html格式，下载到本地电脑，用浏览器打开看就可以。
11. 结果展示，用红色箭头标出来的就是Main线程的调用链，宽度越宽说明耗时越长，由此可见，睡眠方法占用最大的耗时，可以在实际场景中认为此处就是你要找的耗时长的方法了。
    

总结

Arthas的功能很多，profiler的用法也很多，参数也挺多的，这里之只用到了最简单的用法来模拟耗时方法定位的思路。后续我专门在写一个针对profiler的参数解析及使用方法的文章。
补充一下:在Spark当中此方法也照样能行得通，Spark中就需要在每个节点都需要去下载arthas安装包，每个节点切入当前节点的进程内，进行排查和诊断。切入当前Executor机器的Worker进程即可，可以通过AppId准确定位进程PID。