Arthas之trace命令：方法执行为何耗时那么久？
一、引言
在 Java 开发的中，我们常常会遇到各种各样的性能问题。想象一下，你的应用在生产环境中突然出现响应变慢的情况，而你面对的是成百上千行的代码和复杂的调用关系，此时你该如何快速定位问题呢？代码中哪一行或者哪个子方法耗时太久导致的响应变慢呢？Arthas 这款强大的 Java 诊断工具就能派上用场，而其中的 trace 命令更是一把利刃，能够帮助我们深入剖析方法的执行过程，精准定位性能瓶颈。接下来，就让我们一起走进 Arthas 中 trace 命令的精彩世界，探索它的强大功能与使用技巧 。
二、trace 命令简介
2.1 trace 命令作用
在 Arthas 中，trace命令能够深入到 Java 方法的内部，详细地记录方法调用的时间、参数、返回值等关键信息 ，帮助开发者洞察代码运行时的每一个细节。
当我们的应用程序出现性能问题时，trace命令是我们进行性能分析的得力助手。它可以帮助我们识别方法调用的耗时情况，精准地找出性能瓶颈所在。例如，在一个电商系统中，用户下单操作响应缓慢，通过trace命令追踪下单方法的内部调用路径和各子方法的耗时，我们可能会发现是库存检查或者订单数据持久化的方法花费了过多的时间，从而为优化提供了明确的方向。
在调试阶段，trace命令能追踪方法的执行路径，让我们清晰地了解方法内部的逻辑流动。这对于理解复杂的业务逻辑、排查潜在的逻辑错误非常有帮助。假设我们在开发一个工作流引擎，其中的任务分配逻辑较为复杂，通过trace命令，我们可以直观地看到任务是如何根据不同条件分配到不同处理节点的，从而验证逻辑的正确性。
当程序出现异常时，trace命令还能快速捕获异常信息，并展示异常发生时的上下文，帮助我们更高效地定位问题根源。例如，在一个文件处理系统中，出现文件读取失败的异常，trace命令可以显示在文件读取方法调用前后的相关操作和参数，让我们迅速判断是文件路径错误、权限问题还是其他原因导致的异常 。
三、trace 命令的基本语法与参数详解
3.1 基本语法结构
trace命令的基本语法结构如下：
trace [class-pattern] [method-pattern] [condition-express]class-pattern：类名表达式匹配，用于指定需要追踪的类，可以使用通配符*来匹配任意字符。例如，*ServiceImpl表示匹配所有以ServiceImpl结尾的类。如果我们要追踪com.example.demo.service.UserServiceImpl类，就可以直接填写com.example.demo.service.UserServiceImpl 。
method-pattern：方法名表达式匹配，用于指定需要追踪的方法，同样支持通配符*。比如，get*表示匹配所有以get开头的方法；*ById表示匹配所有以ById结尾的方法。若要追踪UserServiceImpl类中的getUserById方法，此处就填写getUserById 。
condition-express：条件表达式，是一个可选参数，用于对追踪的方法调用进行过滤 。它基于 OGNL（Object - Graph Navigation Language）表达式，非常灵活。比如，我们只想追踪方法参数中第一个参数大于 10 的调用，就可以使用params[0] > 10这样的条件表达式 。不过需要注意的是，条件表达式的语法相对复杂，使用时需要对 OGNL 表达式有一定的了解 。
3.2 参数逐一剖析
除了上述基本语法中的参数，trace命令还有一些其他常用参数，它们能进一步增强trace命令的功能，让我们更精准地进行方法追踪和性能分析。
-E：开启正则表达式匹配。默认情况下，trace命令使用通配符匹配类名和方法名。当我们需要更复杂的匹配规则时，就可以使用-E参数开启正则表达式匹配。例如，如果我们想要追踪com.example.demo.service包下所有以Service结尾的类中的所有方法，可以使用命令：
trace -E com.example.demo.service.*Service.*这里的.*就是正则表达式，表示任意字符出现任意次数。这样，只要类名和方法名符合这个正则表达式规则，都会被追踪。
-n：命令执行次数限制。在方法调用非常频繁的情况下，我们可能不希望一直追踪下去，以免产生大量的输出信息，影响分析效率。这时就可以使用-n参数来限制命令执行的次数。比如，我们只想追踪某个方法的前 5 次调用，可以使用命令：
trace com.example.demo.service.UserServiceImpl getUserById -n 5当追踪到第 5 次调用后，trace命令就会自动停止，不再继续输出追踪信息。
#cost：方法执行耗时。这个参数用于根据方法执行的耗时来进行过滤。我们可以设置一个阈值，只有当方法执行耗时超过这个阈值时，才会输出追踪结果。例如，我们想找出执行耗时超过 100 毫秒的方法调用，可以使用命令：
trace com.example.demo.controller.UserController getUserInfo '#cost > 100'这样，只有当getUserInfo方法的执行耗时超过 100 毫秒时，才会输出该方法的追踪信息，方便我们快速定位耗时较长的方法调用。
-m：指定类名匹配的最大数量。当使用通配符或正则表达式匹配类名时，可能会匹配到大量的类，这可能会导致追踪过程变得缓慢，甚至消耗过多的系统资源。-m参数可以限制匹配类的最大数量，避免这种情况的发生。例如，我们想追踪com.example.demo.service包下的方法，但又不想匹配太多类，可以使用命令：
trace -m 10 com.example.demo.service.*Service.*这表示最多只匹配 10 个符合条件的类，当匹配到 10 个类后，就不再继续匹配其他类，从而提高追踪效率。
-v：查看详细信息。默认情况下，trace命令输出的是方法调用路径和各节点的耗时等基本信息。当我们加上-v参数后，会显示更多详细信息，比如方法的入参、返回值等。这对于调试和分析方法的具体执行逻辑非常有帮助。例如：
trace -v com.example.demo.service.ProductServiceImpl getProductById执行这个命令后，除了常规的追踪信息，还会显示getProductById方法的输入参数以及返回值，让我们对方法的执行有更全面的了解 。
四、使用场景与实际案例
4.1 性能分析：定位接口响应慢问题
在我们的后台管理系统中，发现保存角色的数据权限接口的响应速度越来越慢，严重影响了用户体验。但是不确定方法内部哪些逻辑比较耗时以及走了哪些代码分支逻辑。为了找出问题所在，我们使用trace命令来追踪这个方法的执行过程：
[arthas@13643]$ trace com.maisuitx.udf.iam.admin.service.rbac.impl.RoleAdminServiceImpl saveAccesses '#cost > 1000'
Press Q or Ctrl+C to abort.
Affect(class count: 2 , method count: 2) cost in 203 ms, listenerId: 5
`---ts=2025-10-16 14:04:21.000;thread_name=http-nio-39005-exec-1;id=31;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@3113a37
`---[17070.483083ms] com.maisuitx.udf.iam.admin.service.rbac.impl.RoleAdminServiceImpl$$EnhancerBySpringCGLIB$$8d05c0a9:saveAccesses()
`---[100.00% 17070.384196ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()
`---[99.94% 17060.640262ms ] com.maisuitx.udf.iam.admin.service.rbac.impl.RoleAdminServiceImpl:saveAccesses()
+---[0.09% 14.961213ms ] com.maisuitx.udf.iam.domain.service.rbac.RoleService:saveAccesses() #143
+---[0.00% 0.018588ms ] com.maisuitx.udf.iam.domain.command.rbac.role.RoleAccessesSaveCmd:getRoleId() #145
+---[99.91% 17045.491583ms ] com.maisuitx.udf.iam.admin.service.rbac.AuthUserAdminService:refreshDataAccessByRoleId() #145
`---[0.00% 0.006989ms ] com.maisuitx.udf.common.result.Result:success() #147这条命令表示我们要追踪RoleAdminServiceImpl类中的saveAccesses方法，并且只输出执行耗时超过 1000 毫秒的追踪结果。
从追踪结果中可以清晰地看到，saveAccesses方法的总执行时间为 17060.64 毫秒，其中refreshDataAccessByRoleId方法耗时 17045.49 毫秒，占了总耗时的99.91%。我们进一步追踪refreshDataAccessByRoleId方法的代码。
[arthas@13643]$ trace com.maisuitx.udf.iam.admin.service.rbac.AuthUserAdminService refreshDataAccessByRoleId '#cost > 1000'
Press Q or Ctrl+C to abort.
Affect(class count: 2 , method count: 1) cost in 202 ms, listenerId: 6
`---ts=2025-10-16 14:11:48.005;thread_name=http-nio-39005-exec-2;id=32;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@3113a37
`---[31179.518861ms] com.maisuitx.udf.iam.admin.service.rbac.impl.AuthUserAdminServiceImpl:refreshDataAccessByRoleId()
+---[0.00% 1.17085ms ] com.maisuitx.udf.iam.admin.service.rbac.impl.AuthUserAdminServiceImpl:getRole() #48
+---[0.00% 0.007393ms ] com.maisuitx.udf.iam.domain.model.rbac.Role:getAppId() #49
+---[0.02% 7.68629ms ] com.maisuitx.udf.iam.admin.service.rbac.impl.AuthUserAdminServiceImpl:getClientList() #49
+---[0.00% 0.009113ms ] com.maisuitx.udf.iam.domain.model.app.Client:getClientKey() #51
+---[0.19% 57.898947ms ] org.springframework.security.oauth2.provider.token.TokenStore:findTokensByClientId() #51
+---[2.42% min=0.133663ms,max=6.073971ms,total=753.428561ms,count=2782] org.springframework.security.oauth2.provider.token.TokenStore:readAuthentication() #53
+---[0.02% min=0.001091ms,max=0.0356ms,total=5.100081ms,count=2505] org.springframework.security.oauth2.provider.OAuth2Authentication:getUserAuthentication() #55
+---[0.02% min=0.00107ms,max=0.025433ms,total=4.720582ms,count=2505] org.springframework.security.core.Authentication:getPrincipal() #55
+---[74.02% min=4.243902ms,max=174.482267ms,total=23077.798261ms,count=2505] com.maisuitx.udf.iam.domain.service.ou.AuthUserService:fillDataAccess() #56
`---[23.19% min=1.824882ms,max=11.571983ms,total=7229.970755ms,count=2505] com.maisuitx.udf.iam.admin.service.rbac.impl.AuthUserAdminServiceImpl:restoreAccessToken() #57从上述追踪结果结合代码可以看到，其中有一个循环执行了2782次。可以很明显的看到该处代码有bug。我们需要结合我们的代码针对性去解决该问题。
4.2 调试：追踪复杂业务逻辑执行路径
以我们系统中添加律师函生成任务为例，在EmailGenTaskServiceImpl类中有一个add方法，这个方法负责提交律师函生成任务，整个流程包括数据校验、检查余额、扣减余额、保存任务记录、更新律师函状态等多个步骤，并且内部分支逻辑比较多。由于业务逻辑复杂，在线上使用过程中偶尔会出现任务提交失败的情况，但错误信息不明确，难以定位问题。
为了明确add方法的内部执行逻辑，定位代码执行的分支逻辑，我们使用trace命令进行追踪：
[arthas@7756]$ trace com.maisuitx.email.domain.service.impl.EmailGenTaskServiceImpl add
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 472 ms, listenerId: 1
`---ts=2025-10-16 14:32:39.031;thread_name=http-nio-39015-exec-3;id=32;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@6134ac4a
`---[122.526889ms] com.maisuitx.email.domain.service.impl.EmailGenTaskServiceImpl:add()
+---[30.45% 37.313445ms ] com.maisuitx.email.domain.service.impl.EmailGenTaskServiceImpl:group() #79
+---[18.23% 22.337194ms ] com.maisuitx.udf.sys.domain.service.CodeService:generateCode() #84
+---[0.02% 0.018943ms ] com.maisuitx.email.domain.model.EmailGenTask:<init>() #90
+---[0.01% 0.007313ms ] com.maisuitx.email.domain.model.EmailBatch:getEmailTemplate() #107
+---[0.01% 0.007075ms ] com.maisuitx.email.domain.model.EmailTemplate:getEmailType() #107
+---[0.01% 0.006208ms ] com.maisuitx.email.domain.model.EmailBatch:getEmailTemplate() #108
+---[0.00% 0.00592ms ] com.maisuitx.email.domain.model.EmailTemplate:getLawFirm() #108
+---[23.82% 29.187881ms ] com.maisuitx.email.domain.service.EmailDeductService:emailNoDeduct() #108
+---[4.31% 5.283771ms ] com.maisuitx.email.domain.repository.EmailGenTaskRepository:batchAdd() #111
+---[0.01% 0.008456ms ] com.maisuitx.email.domain.query.EmailQuery:getOrganId() #112
+---[5.37% 6.58505ms ] com.maisuitx.email.domain.service.EmailDeductService:emailGenDemandFree() #112
+---[0.01% min=0.003722ms,max=0.008701ms,total=0.012423ms,count=2] com.maisuitx.email.domain.query.EmailQuery:getUsername() #120
+---[0.00% 0.005439ms ] com.maisuitx.email.domain.query.EmailQuery:getUserId() #120
+---[0.00% 0.004677ms ] com.maisuitx.email.domain.query.EmailQuery:getOrganId() #120
+---[12.08% 14.804333ms ] com.maisuitx.email.domain.service.EmailDeductService:genDeduct() #120
`---[4.54% 5.568476ms ] com.maisuitx.email.domain.service.impl.EmailGenTaskServiceImpl:updateEmailStatus() #123从追踪结果中，我们可以清楚地看到add方法依次调用了哪些子方法，我们可以清晰的看到代码的执行逻辑，以及每个子方法的执行耗时。如果任务处理失败，我们可以根据这个追踪信息，快速定位到是哪个子方法出现了问题。
六、总结
通过以上对 Arthas 中 trace 命令的深入探讨，我们了解到它在 Java 开发中是一个功能强大且不可或缺的工具。从命令的基本语法，到丰富多样的参数，再到实际应用中的各种场景，trace 命令都展现出了其卓越的性能分析、调试和问题定位能力。
在性能分析时，它能精准定位接口响应慢的根源，帮助我们优化代码，提升系统性能；在调试复杂业务逻辑时，清晰的执行路径追踪让我们对程序的运行一目了然。
希望各位开发者在今后的 Java 开发工作中，能够熟练运用 trace 命令。当遇到性能瓶颈、逻辑错误或异常问题时，不要忘记 Arthas 的 trace 命令这一得力助手，它将帮助你更高效地开发和维护 Java 应用程序 ，让你的开发之旅更加顺畅。
