目录SkyWalking 源码复盘 ⑪Trace Profiling 如何定位到具体慢方法一、Trace Profiling 到底是什么二、创建任务时的七个关键参数三、任务是 OAP 主动推给 Agent 吗四、OAP 如何判断哪些任务需要返回五、Agent 收到任务后如何安排执行六、任务开始后并不会立刻采样所有线程七、请求到达时如何匹配 Endpoint为什么还有一次 profilingRecheck八、Min Duration Threshold 是怎么实现的一个具体例子请求 A总耗时 300 ms请求 B总耗时 2500 ms九、谁真正执行线程栈采样十、线程栈到底怎么采集十一、一次采样生成什么数据十二、采样数据如何上传到 OAP十三、OAP 收到快照后保存什么十四、OAP 如何将上百次线程栈合并成一棵树十五、Dump Count 到底是什么十六、Duration 是怎么计算的Duration 示例非连续样本十七、Self Duration 是怎么计算的示例十八、三项指标应该如何联合阅读情况一Duration 高Self Duration 低情况二Duration 高Self Duration 也高情况三Dump Count 高但 Duration 不一定非常高情况四Thread.sleep 或网络读取节点很高十九、为什么你的 /order/query/1 必须在任务期间重新访问二十、为什么普通快速查询可能采不到数据二十一、跨线程请求如何继续 Profiling二十二、为什么要限制并发和采样数量二十三、结合你之前的实验完整还原二十四、面试回答模板二十五、本节必须记住SkyWalking 源码复盘 ⑪Trace Profiling 如何定位到具体慢方法你之前在 SkyWalking UI 中创建过性能剖析任务并分析GET:/order/query/1最后看到了Duration Self Duration Dump Count这一节解释整个源码链路UI 创建 Profiling 任务 → OAP 保存任务 → Agent 定时拉取任务 → 请求命中指定 Endpoint → 等待超过最小耗时阈值 → 周期性采样请求线程栈 → 快照上传 OAP → OAP 合并大量线程栈 → 计算 Duration、Self Duration、Dump Count一、Trace Profiling 到底是什么Trace Profiling 不是长期监控整个 JVM也不是对所有线程做全量 CPU Profiling。它的定位是针对某个出现高延迟的 Endpoint动态创建短期任务对命中该 Endpoint 的部分请求线程周期性采样。官方说明中Trace Profiling 与 Java Agent 绑定任务动态下发Agent 对指定 Endpoint 相关线程定期采集线程栈再由 OAP 分析具体慢在哪一行业务代码。和普通 Trace 的区别功能主要回答Trace哪个 Span、哪个远程调用慢Trace ProfilingSpan 内部具体哪个 Java 方法、哪一行附近慢例如普通 Trace 只能看到GET:/order/query/1 2100 ms └─ queryOrder 2050 ms但queryOrder内部还有很多代码public OrderInfo queryOrder(Integer id) { validate(id); loadCache(id); calculateSomething(); queryDatabase(id); formatResult(); }普通 Trace 未必会为这些方法都创建 Span。Trace Profiling 则通过多次采集线程栈判断线程长期停留在哪个方法上。二、创建任务时的七个关键参数在 UI 创建任务时主要填写Service Endpoint Start Time Duration Min Duration Threshold Dump Period Max Sampling Count官方文档对这些字段的定位如下参数作用Service对哪个服务的 Agent 下发任务Endpoint对哪个入口请求进行剖析Start Time任务什么时候开始Duration任务持续多少分钟Min Duration Threshold请求运行多久后才开始采样Dump Period每隔多少毫秒采样一次线程栈Max Sampling Count最多选择多少条请求进行 Profiling假设配置Service order-service Endpoint GET:/order/query/1 Start Time 立即 Duration 5 分钟 Min Duration Threshold 1000 ms Dump Period 10 ms Max Sampling Count 5其含义是在接下来 5 分钟内遇到GET:/order/query/1请求时如果该请求执行超过 1000 ms就开始每 10 ms 采样一次线程栈最多分析 5 条请求。三、任务是 OAP 主动推给 Agent 吗严格来说Java Agent 会定时向 OAP查询任务。Agent 中负责通信的是ProfileTaskChannelService它会周期性发送ProfileTaskCommandQuery其中携带service serviceInstance lastCommandTime源码builder.setService(Config.Agent.SERVICE_NAME) .setServiceInstance(Config.Agent.INSTANCE_NAME); builder.setLastCommandTime( profileTaskExecutionService.getLastCommandCreateTime() );然后调用getProfileTaskCommands(...)获取新的命令。完整方向是Agent 定时询问 OAP “order-service 这个实例有没有新任务” ↓ OAP 返回 Commands ↓ Agent 执行 ProfileTaskCommand而不是 OAP 随时主动建立一条连接把任务强行推过来。四、OAP 如何判断哪些任务需要返回OAP 收到 Agent 查询后根据Service ServiceInstance Last Command Time查找该服务的 Profiling 任务。核心逻辑ListProfileTask profileTaskList profileTaskCache.getProfileTaskList(serviceId);然后过滤if (profileTask.getCreateTime() lastCommandTime) { continue; }只有比 Agent 最后收到的任务更新才会重新下发。最后将任务封装成 Commands 返回。因此lastCommandTime的作用是避免 Agent 每次轮询都重复接收同一个任务五、Agent 收到任务后如何安排执行收到任务后进入ProfileTaskExecutionService.addProfileTask()首先检查Endpoint 是否为空 Duration 是否合法 最小耗时阈值是否合法 Dump Period 是否过小 Max Sampling Count 是否合法 任务时间是否与其他任务冲突检查成功后profileTaskList.add(task);并根据任务开始时间进行调度long delay task.getStartTime() - System.currentTimeMillis(); PROFILE_TASK_SCHEDULE.schedule( () - processProfileTask(task), delay, TimeUnit.MILLISECONDS );所以创建任务不代表立即采样。它可能处于等待开始 → 正在执行 → 已结束六、任务开始后并不会立刻采样所有线程任务开始时Agent 创建ProfileTaskExecutionContext然后启动一个独立 Profiling 线程currentTaskContext.startProfiling(PROFILE_EXECUTOR);任务持续时间结束后再自动停止schedule( () - stopCurrentProfileTask(...), task.getDuration(), TimeUnit.MINUTES );注意这个 Profiling 线程此时只是进入待命状态。真正要采样哪些线程要等新的业务请求到达。七、请求到达时如何匹配 Endpoint当 Tomcat 请求进入并创建新的TracingContext时构造函数会调用PROFILE_TASK_EXECUTION_SERVICE.addProfiling( this, segment.getTraceSegmentId(), firstOPName );其中firstOPName就是该 Trace 的第一个操作名例如GET:/order/query/1接下来ProfileTaskExecutionContext.attemptProfiling(...)执行精确匹配if (!Objects.equals( task.getFirstSpanOPName(), firstSpanOPName )) { return ProfileStatusContext.createWithNone(); }因此任务 Endpoint GET:/order/query/1 实际请求 GET:/order/query/1 → 匹配而实际请求 GET:/order/query/2 → 如果操作名未被模板化为相同 Endpoint可能不匹配本质上匹配的是 Agent 当前识别出的firstSpan operationName而不是 Controller 方法名。为什么还有一次profilingRecheck某些插件会在 Trace 创建后重新修改入口 Span 的操作名。例如最开始可能暂时是Tomcat/request后面 Spring MVC 再将其改成GET:/order/query/1因此TracingContext在嵌套 EntrySpan 修改名称时会重新检查profilingRecheck(parentSpan, operationName); parentSpan.setOperationName(operationName);这样可避免因 Endpoint 名称在插件链中发生变化而错过任务。八、Min Duration Threshold是怎么实现的这是 Trace Profiling 中最容易误解的参数。假设设置Min Duration Threshold 1000 msAgent 不可能在请求刚开始时就知道这个请求最终会不会超过 1000 ms因此它采用请求开始 → 状态设为 PENDING → 等待请求运行 → 已运行时间超过 1000 ms → 状态切换为 PROFILING → 开始采样源码if ( System.currentTimeMillis() - firstSegmentCreateTime task.getMinDurationThreshold() ) { profilingStartTime System.currentTimeMillis(); profilingStatus.updateStatus( ProfileStatus.PROFILING, tracingContext ); }所以它不是请求执行完成后发现总耗时 1000 ms → 再回头采样线程栈无法倒流。真实过程是请求执行超过阈值时仍未结束 → 从这一刻开始采样一个具体例子设置Min Duration Threshold 1000 ms请求 A总耗时 300 ms0 ms 请求开始 300 ms 请求结束没有超过阈值不采样请求 B总耗时 2500 ms0 ms 请求开始 1000 ms 超过阈值 1000~2500 周期采样 2500 ms 请求结束真正的采样时间段大约是后 1500 ms所以前 1000 ms 内的方法可能没有被 Profiling 捕获。九、谁真正执行线程栈采样Agent 启动一个ProfileThread它循环扫描所有正在被观察的ThreadProfiler状态处理switch (status) { case PENDING: startProfilingIfNeed(); break; case PROFILING: snapshot buildSnapshot(); addProfilingSnapshot(snapshot); break; }一轮扫描结束后根据任务的Thread Dump Period进行休眠。例如Dump Period 10 ms流程近似采样 → 等待约 10 ms → 再采样 → 等待约 10 ms → 再采样这是统计采样不是给每个方法加进入和退出计时器。十、线程栈到底怎么采集真正的核心代码是stackTrace profilingThread.getStackTrace();其中profilingThread就是实际处理当前请求的 Tomcat 线程例如http-nio-8083-exec-4采集到的原始线程栈可能是java.lang.Thread.sleep OrderController.slow OrderServiceImpl.queryOrder DispatcherServlet.doDispatch StandardHostValve.invoke ...Agent 随后将顺序反转构造成从外层调用到内层调用的结构StandardHostValve.invoke └─ DispatcherServlet.doDispatch └─ OrderController.slow └─ OrderServiceImpl.queryOrder └─ Thread.sleep源码明确反向遍历线程栈并将每一帧转换为className.methodName:lineNumber例如com.demo.OrderServiceImpl.queryOrder:87这就是 UI 中Code Signature的来源。十一、一次采样生成什么数据每次采样都会生成TracingThreadSnapshot主要包含taskId traceSegmentId sequence dumpTime stack协议层的ThreadSnapshot也定义了这些字段包括任务 ID、Segment ID、时间、序号和线程栈。例如taskId task-001 segmentId segment-A sequence 17 dumpTime 172... stack: StandardHostValve.invoke:... DispatcherServlet.doDispatch:... OrderServiceImpl.queryOrder:87 Thread.sleep:-2其中sequence 0、1、2、3……表示该请求线程的第几次采样。十二、采样数据如何上传到 OAPAgent 将快照放入BlockingQueueTracingThreadSnapshot队列容量由SNAPSHOT_TRANSPORT_BUFFER_SIZE控制。后台发送任务每 500 ms 执行一次snapshotQueue.drainTo(buffer); if (!buffer.isEmpty()) { sender.send(buffer); }所以采样线程并不是每采一次就同步等待 OAP 网络响应。链路是ProfileThread → 创建 Snapshot → 放入内存队列 → 后台批量取出 → gRPC 上传十三、OAP 收到快照后保存什么OAP 的ProfileTaskServiceHandler.collectSnapshot()收到每个ThreadSnapshot后转换为ProfileThreadSnapshotRecord写入taskId segmentId dumpTime sequence stackBinary timeBucket然后RecordStreamProcessor.getInstance().in(record);异步进入存储流程。注意OAP 此时只是保存原始采样快照。真正的树形合并分析通常发生在 UI 发起分析查询时。十四、OAP 如何将上百次线程栈合并成一棵树假设采样得到三份线程栈采样 1 A → B → C 采样 2 A → B → C 采样 3 A → B → DOAP 会合并成A └─ B ├─ C 出现 2 次 └─ D 出现 1 次ProfileAnalyzer会查询指定segmentId time range范围内的快照然后将它们反序列化为ProfileStack最后交给合并器构建树。合并器按照相同的Code Signature将节点聚合。源码逻辑如果父节点下已经存在相同 codeSignature → 将当前快照计入该节点 不存在 → 创建新的子节点十五、Dump Count到底是什么源码中element.setCount( this.detectedStacks.size() );所以Dump Count表示该栈帧在多少次线程栈采样中出现过。例如总共采样 100 次OrderServiceImpl.queryOrder 出现 90 次 Thread.sleep 出现 70 次 MySQL execute 出现 15 次那么queryOrder Dump Count 90 Thread.sleep Dump Count 70 execute Dump Count 15它不是方法被调用了 90 次而是采样时有 90 次看见线程正位于该方法调用路径中 因此Dump Count 越大说明线程越经常停留在该方法及其子调用中。十六、Duration是怎么计算的这里的 Duration 不是通过start System.nanoTime(); method(); end System.nanoTime();得到的精确方法耗时。OAP 会找出某节点出现的连续采样区间然后计算最后一次采样时间 - 第一次采样时间如果采样序号不连续则拆成多个时间段再相加。源码核心判断if ( previous.sequence 1 ! current.sequence ) { duration previous.dumpTime - windowStart.dumpTime; windowStart current; }最后再计算最后一个连续区间。Duration 示例采样周期10 ms某方法在以下序号出现sequence: 10、11、12、13、14采样时间100 ms 110 ms 120 ms 130 ms 140 ms源码计算140 - 100 40 ms虽然有 5 次采样但相邻采样之间只有 4 个时间间隔。因此它是基于连续线程栈样本推算出来的近似持续时间。不是 JVM 对该方法的精确纳秒级计时。非连续样本某方法出现在sequence 1、2、3 sequence 8、9、10则计算第一段time(3) - time(1) 第二段time(10) - time(8) Duration 第一段 第二段中间没出现该方法的采样区间不会计入。十七、Self Duration是怎么计算的源码中的实际字段名是Duration Child ExcludedUI 通常将其展示为Self Duration计算公式当前节点 Duration - 所有直接子节点 Duration 之和源码element.setDurationChildExcluded( element.getDuration() - children.stream() .mapToInt(child - child.duration) .sum() );可以理解为Duration 当前方法及其全部子调用占据的采样时间 Self Duration 尽量排除子方法后 当前方法自身代码占据的采样时间示例queryOrder ├─ validate └─ executeQuery分析结果queryOrder Duration 1800 ms validate Duration 100 ms executeQuery Duration 1500 ms那么近似queryOrder Self Duration 1800 - 100 - 1500 200 ms表示queryOrder 自身逻辑约 200 ms 其余大部分时间消耗在子方法十八、三项指标应该如何联合阅读指标真正含义Duration当前方法及子调用在连续采样中的累计近似时间Self Duration排除子调用后当前方法自身的近似时间Dump Count该方法出现在多少份线程栈快照中情况一Duration 高Self Duration 低queryOrder Duration 2000 ms Self Duration 50 ms Dump Count 180说明queryOrder 整体很慢 但不是自身代码慢 主要是某个子方法慢继续向下展开子节点。情况二Duration 高Self Duration 也高calculate Duration 1500 ms Self Duration 1300 ms Dump Count 140说明线程频繁停留在该方法自身复杂循环 大量计算 字符串处理 集合遍历 自旋它更可能是真正的业务代码热点。情况三Dump Count 高但 Duration 不一定非常高可能原因采样周期较长 样本不连续 该方法频繁出现但每次停留较短所以不能只看 Count。情况四Thread.sleep或网络读取节点很高例如java.lang.Thread.sleep Duration 1900 ms说明请求线程主要在休眠。例如SocketInputStream.read Duration 1800 ms说明线程主要等待网络或远端返回。这不等于 CPU 使用率高。Trace Profiling采集的是线程当时的调用栈它可能处于运行 休眠 数据库等待 网络等待 锁等待所以它更接近目标请求的线程时间分布分析。而不是纯 CPU 火焰图。十九、为什么你的/order/query/1必须在任务期间重新访问任务创建完成后Agent只对任务生效期间新进入的匹配请求建立ThreadProfiler。已在任务开始前完成的旧 Trace没有线程可供继续采样因此正确操作顺序是1. 创建 Profiling 任务 2. 等任务进入执行状态 3. 请求 GET /order/query/1 4. 让请求持续超过 Min Duration Threshold 5. 等请求完成 6. 查询任务详情 7. 选择可分析 Segment 和时间范围 8. 查看 Profiling 树官方流程也是先创建任务再生成匹配请求随后查询任务详情并进行分析。二十、为什么普通快速查询可能采不到数据例如Min Duration Threshold 1000 ms /order/query/1 实际耗时 80 ms请求在阈值之前就结束了。结果有普通 Trace 但没有 Profiling Snapshot所以可能出现Trace 页面能看到请求 Profile 页面没有可分析线程栈这不是 Agent 异常而是该请求没有达到任务触发条件。为了实验通常要保证实际请求耗时 Min Duration Threshold 至少若干次 Dump Period例如Threshold 1000 ms Dump Period 10 ms 请求耗时 2100 ms则大约还有1100 ms可用于采样。二十一、跨线程请求如何继续 Profiling前面讲过普通ThreadLocal无法自动跨线程传播。Profiling 状态也会放入ContextSnapshot父线程捕获上下文时会携带profileStatus子线程恢复上下文时如果 Profiling 状态需要继续执行PROFILE_TASK_EXECUTION_SERVICE.continueProfiling( this, segment.getTraceSegmentId() );这意味着异步任务可以形成新的TracingContext ThreadProfiler Segment继续采样。官方也明确说明Java Agent 支持对跨线程请求继续 Trace Profiling。二十二、为什么要限制并发和采样数量采样需要不断执行targetThread.getStackTrace()同时还要构造字符串 创建 Snapshot 缓存 网络上传 OAP 存储 后续合并分析如果对所有慢请求无限采样会增加明显开销。Agent 因此限制最大并行 Profiling 请求数 最大采样 Trace 数量 最大栈深度 最大任务时长 快照传输缓冲区ProfileTaskExecutionContext会检查currentEndpointProfilingCount Config.Profile.MAX_PARALLEL以及totalStartedProfilingCount task.getMaxSamplingCount()不满足条件的请求不再加入 Profiling。这解释了即使任务期间发出 100 个匹配请求最终也不一定对 100 个请求全部进行线程采样。二十三、结合你之前的实验完整还原你在 UI 创建Endpoint GET:/order/query/1随后发起请求。真实过程1. UI 创建 Profiling Task 2. OAP 保存任务 3. order-service Agent 周期查询任务 4. OAP 返回 ProfileTaskCommand 5. Agent 校验并安排任务开始 6. Tomcat 收到 GET /order/query/1 7. 创建 TracingContext 8. firstSpanOPName 与任务 Endpoint 匹配 9. 创建 ThreadProfiler 状态PENDING 10. 请求运行时间超过 Min Duration Threshold 11. 状态变为 PROFILING 12. ProfileThread 每隔 Dump Period requestThread.getStackTrace() 13. 生成 Snapshot taskId segmentId sequence dumpTime stack 14. Snapshot 放入 Agent 队列 15. 后台线程批量上传 OAP 16. OAP 持久化原始快照 17. 请求完成 18. Agent 停止该 TracingContext 的采样 19. UI 请求分析某个 Segment 的时间范围 20. OAP 查询所有相关 Snapshot 21. 相同 Code Signature 合并成树 22. 计算 Duration Self Duration Dump Count 23. UI 展示具体慢方法和代码行二十四、面试回答模板SkyWalking Trace Profiling 是如何定位具体慢方法的可以回答Trace Profiling 是一种针对指定 Endpoint 的动态、采样式线程分析。用户在 OAP 创建任务后Java Agent 会周期性拉取 Profiling 命令。任务生效期间新建TracingContext时会将首个 Span 的 Operation Name 与任务 Endpoint 进行匹配。匹配成功的请求先进入 Pending 状态当执行时间超过 Min Duration Threshold 后转为 Profiling 状态。Agent 的独立 Profiling 线程按照 Dump Period 周期调用目标业务线程的getStackTrace()生成包含 Task ID、Segment ID、采样序号、时间和代码栈的 Snapshot并异步上传 OAP。OAP 将同一 Segment 和时间范围内的大量线程栈按 Code Signature 合并成调用树根据节点在连续采样中的出现时间计算 Duration以父节点 Duration 减去子节点 Duration 得到 Self Duration并以出现的快照数量作为 Dump Count。因此它提供的是统计采样结果不是每个方法的精确埋点计时。二十五、本节必须记住Trace Profiling → 针对指定 Endpoint 的短期线程采样 Agent 定时拉取任务 → 不是普通业务服务接收 HTTP 推送 Endpoint 匹配 → 匹配 firstSpan operationName PENDING → 请求尚未超过最小耗时阈值 PROFILING → 开始周期性抓取线程栈 Thread.getStackTrace() → 真正的采样动作 Dump Period → 线程栈采样间隔 Max Sampling Count → 最多选取多少条 Trace Snapshot → taskId segmentId sequence time stack Dump Count → 栈帧被采样看见的次数不是方法调用次数 Duration → 连续采样区间推算的近似总时间 Self Duration → Duration 减去直接子节点 Duration 高 Duration、低 Self Duration → 慢点主要在子方法 高 Duration、高 Self Duration → 当前方法自身更可能是热点下一节将把 SkyWalking 全链路源码做最后收束-javaagent → 插件增强 → Entry / Local / Exit Span → 跨服务传播 → Segment 异步上报 → OAP 指标与拓扑 → 日志关联 → 告警 → Profiling 最后形成一张“从请求到监控结果”的完整源码地图。
