ARTICLE DETAIL

资讯详情

深耕网站建设与运营推广的一线实战洞察。

TraceId全链路日志追踪实战:从生成到Elasticsearch检索

TraceId全链路日志追踪实战:从生成到Elasticsearch检索 有一次排查线上接口超时问题我对着日志平台来回筛了快40分钟。用户反馈13点42分点提交按钮没反应我手头只有用户ID、客户端IP和接口名。先从Nginx access log里抠出那个时间点的请求再拿客户端IP去四个微服务里逐条grep每到一个服务都要对比前后时间戳去猜调用顺序最后终于在B服务的一段异常堆栈里看到了root cause。整个过程最耗时的不是看代码而是把散落在十几个文件、几百条日志里的片段拼成一条完整的请求故事。后来我们在全链路日志里统一加了TraceId再遇到同类问题从拿到ID到定位完成基本不超过三分钟。这篇文章就把我从零搭建TraceId机制的过程、踩过的坑、以及最终怎么和Elasticsearch打通讲清楚。内容包括Java项目里如何生成和注入TraceId、怎么在线程池和跨服务调用中透传、日志侧如何输出、以及如何通过TraceId在ES里查回一次请求对应的SQL执行链。适合正在做日志治理、接口排查效率优化或者准备落地全链路日志的同学参考。1. 先想清楚TraceId到底在解决什么日志的“检索主键”思维1.1 一次故障排查现场没有TraceId时我们是这样“考古”的很多团队其实不是没有日志而是日志太多、太散。微服务架构下一次用户请求往往会经过网关、鉴权服务、业务服务、基础服务甚至还会触发MQ异步任务和定时任务。每个服务各自写各自的日志文件服务之间没有任何关联ID排查问题就变成了“考古”。我记得最典型的一次线上有个订单状态没更新用户那边已经付款了但订单服务显示未支付。我手里的线索只有用户ID和大概时间。排查路径是这样的先去Nginx access log里找到那个时间点的请求拿到完整URL和入参。凭经验判断这个请求先进了哪个服务到对应服务的日志文件里grep用户ID。在订单服务里发现它调了支付回调接口于是再去支付服务的日志里grep同一个时间段的请求。几个服务之间反复横跳用时间戳去对齐调用顺序猜哪一步出了问题。这种方式的痛点非常明显只要有一个服务的日志没看全或者客户端IP被Nginx转发后变了链条就断了。更难受的是如果请求量很大同一个用户ID在同一秒可能有好几条请求靠时间戳过滤出来的日志根本分不清哪条是哪条。所以在做日志治理的时候第一步不是搞什么复杂链路追踪系统而是先给每个请求发一个唯一ID让这个ID贯穿整条调用链。这就是TraceId存在的意义——它是日志的“检索主键”像数据库主键一样让你能从海量日志中精确定位到某一条请求的全部痕迹。1.2 TraceId的完整链路逻辑生成、透传、收敛、检索TraceId本身不复杂就是一个字符串但它要起作用的链路比想象中长。一条带TraceId的请求生命周期大概是这样的入口生成外部请求到达网关或第一个服务时如果没有携带TraceId就生成一个新的如果带了就沿用。透传服务A调用服务B时把TraceId放到HTTP Header或RPC隐式参数里带过去服务B收到后取出并写入自己的日志上下文。收敛所有日志业务日志、SQL日志、异常堆栈在输出时都带上当前上下文的TraceId。检索日志采集到Elasticsearch后用TraceId做关键字一次查回这个请求从入口到出口、从业务逻辑到SQL执行的全部日志。这个机制很像快递单号。你寄快递时拿到一个单号这个单号跟着包裹走遍全网每个中转站扫码都会记录一笔。出了问题快递公司拿着单号一查所有流转记录全出来不用靠打电话问“你那个包裹长什么样”。但和快递单号不同TraceId不是天然存在的需要你自己在每个环节做埋点。实际的难点不在生成ID本身而在“透传”和“日志打点”这两个环节。线程池会弄丢它HTTP调用默认不会带它日志框架如果没有额外配置也不会输出它。后面的章节就按这条链路逐步拆开讲。2. 入口侧实现从请求到达的第一毫秒就把TraceId种下去2.1 生成规则的选择UUID、雪花还是自定义随机串先把最简单的部分说清楚——TraceId怎么生成。我见过很多团队直接用UUID.randomUUID().toString()生成出来是36个字符含横杠依然能用但有点浪费存储。日志里每行都带这个字段在ES里索引和存储成本都会翻倍。而且纯UUID是随机串不带时间信息你一眼看不出这条请求是什么时候进来的。也有的团队用雪花算法Snowflake生成。雪花ID是64位整数转成字符串之后大概19位比UUID短很多而且自带时间戳和机器信息适合已经有分布式ID生成器的团队。缺点是需要引入额外的组件或依赖比如美团Leaf、百度UidGenerator这些。我的建议是如果没有现成的分布式ID基础设施优先用自定义随机串长度控制在30位左右包含时间信息随机字符。这样可以兼顾可读性、存储成本和唯一性。TraceId不要求全局绝对唯一只要在日志保留周期内不冲突就行。一个比较实用的生成方式public static String generateTraceId() { // 时间戳取到毫秒转成36进制长度约8位 String timePart Long.toString(System.currentTimeMillis(), 36); // 后面拼24位随机字符字符集去掉容易混淆的0O1IlL String randomPart RandomStringUtils.randomAlphanumeric(24); return timePart randomPart; }这里把时间戳换成36进制是为了压缩长度同时让TraceId从字符串上就能看出生成时间排查时直接心里有数。随机部分用SecureRandom更好但一般场景RandomStringUtils够用了。如果团队有雪花ID生成器直接用雪花ID也可以长度更短就是可读性差一些。2.2 入口Filter的标准写法解析Header、自动生成、写入MDC生成规则定了之后下一个问题就是在哪一步把TraceId种到日志上下文里。我推荐在Servlet Filter里做而不是Interceptor或者AOP。原因很简单Filter是Servlet规范里最靠前的入口连Spring MVC还没介入时它就能拿到请求而且Filter天然覆盖静态资源、拦截器没覆盖到的路径。一个标准的TraceIdFilter长这样Component public class TraceIdFilter implements Filter { private static final String TRACE_ID_HEADER traceId; private static final String TRACE_ID_MDC_KEY traceId; Override public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException { HttpServletRequest httpRequest (HttpServletRequest) request; String traceId httpRequest.getHeader(TRACE_ID_HEADER); // 上游没传就自己生成一个 if (StringUtils.isBlank(traceId)) { traceId generateTraceId(); } MDC.put(TRACE_ID_MDC_KEY, traceId); try { chain.doFilter(request, response); } finally { // 一定记得清理否则线程池复用时会出现串号 MDC.remove(TRACE_ID_MDC_KEY); } } }这个Filter做了三件事从请求头里取traceId取不到就生成把traceId放进MDC请求结束从MDC移除。注意finally里的MDC.remove()这一步比MDC.put()还要重要后面讲线程池的时候会细说为什么。在Spring Boot里注册这个Filter有两种方式一种是加Component注解靠Spring Boot自动扫描生效另一种是通过FilterRegistrationBean显式注册可以精确控制过滤顺序和URL匹配。建议用FilterRegistrationBean把顺序调到最前面确保真正“第一毫秒”就生效。毕竟如果TraceIdFilter没排到最前前面的Filter里打日志还是没有TraceId。2.3 MDC的本质为什么它能自动跟着日志走很多同学第一次接触MDC会有点懵我只是MDC.put(traceId, xxx)为什么logback打印日志时就能自动带上这个值MDC的全称是Mapped Diagnostic Context直译是“映射诊断上下文”。它本质上就是一个ThreadLocalMapString, String每个线程自己维护一份键值对。logback在打印日志时会去PatternLayout里找%X{traceId}这样的占位符然后从当前线程的MDC Map里取值拼到日志文本里。这就解释了为什么同一条线程里所有日志都能自动带上TraceId——因为同一个线程的ThreadLocal始终能取到同一个值。但这也就引出了一个关键问题ThreadLocal是线程私有的。一旦发生线程切换比如用了线程池、Async、CompletableFuture子线程的MDC里是拿不到父线程那个值的。这是整个TraceId机制里最大的坑下一章单独展开。3. 跨线程传递异步场景里TraceId丢失和串号的双重陷阱3.1 线程池复用导致的“看不到”和“看错人”异步场景下TraceId有两个问题丢失和串号。丢失好理解你在Controller里MDC.put(traceId, xxx)然后往线程池里submit一个任务子线程执行时MDC.get(traceId)是null。因为ThreadLocal不跨线程继承子线程有自己独立的ThreadLocal Map父线程put的值对它不可见于是子线程里打的日志全部没有TraceId。串号比丢失更隐蔽也更危险。线程池里的线程是复用的——执行完任务A之后这个线程会被归还给线程池下一次执行任务B时还是同一个线程。如果任务A执行时往MDC里put了traceId但结束前没清理线程B执行时从MDC里取到的是任务A的traceId日志全部记到别人名下了。我之前就踩过这个坑。有个模块用了Async去发通知邮件发邮件的日志偶尔会混在完全不相干的请求TraceId下面。排查了好久才发现是线程池复用的锅异步任务执行完没有清MDC下一个任务上来直接拿脏数据。3.2 TaskDecorator包装Runnable的标准解法Spring的ThreadPoolTaskExecutor提供了setTaskDecorator方法可以在每次执行任务前对Runnable做一层包装。这是解决线程池MDC透传最优雅的方式代码侵入小只要在创建线程池时统一配置一次。Bean(commonTaskExecutor) public ThreadPoolTaskExecutor taskExecutor() { ThreadPoolTaskExecutor executor new ThreadPoolTaskExecutor(); executor.setCorePoolSize(8); executor.setMaxPoolSize(16); executor.setQueueCapacity(100); executor.setThreadNamePrefix(common-task-); executor.setTaskDecorator(runnable - { // 父线程提交任务的那个线程的MDC上下文 MapString, String contextMap MDC.getCopyOfContextMap(); return () - { MapString, String previous MDC.getCopyOfContextMap(); try { // 把父线程的MDC上下文塞到子线程 if (contextMap ! null) { MDC.setContextMap(contextMap); } runnable.run(); } finally { // 执行完恢复子线程之前的MDC没有就清空 if (previous ! null) { MDC.setContextMap(previous); } else { MDC.clear(); } } }; }); return executor; }核心逻辑就三步先getCopyOfContextMap()把父线程当前的MDC内容拷贝一份在子线程执行前setContextMap(contextMap)把拷贝内容填进去执行完后要么恢复之前的MDC要么直接MDC.clear()防止污染这个线程的下一个任务。这个方案同样适用于Async场景。你需要实现AsyncConfigurer接口返回自定义的ThreadPoolTaskExecutorAsync注解就会自动使用这个线程池。当然Async本身就是基于代理的它拿到Runnable时会走TaskDecorator这一层包装所以能生效。3.3 需要无侵入透传时TransmittableThreadLocalTaskDecorator方案虽然好但有一个前提代码里的线程池都是你自己创建的。如果项目里存在原生Executors.newFixedThreadPool()、第三方SDK的内部线程池或者用了ForkJoinPool、并行流这种不好干预的地方TaskDecorator就覆盖不到了。这时候可以考虑阿里的TransmittableThreadLocalTTL。它的原理是继承InheritableThreadLocal并扩展在线程池复用场景下能自动捕获提交任务时父线程的值并传给子线程。用法非常简// 把MDC换成TTL包装一下 TransmittableThreadLocalMapString, String holder new TransmittableThreadLocal(); // 提交任务时用TtlRunnable包装或在创建线程池时统一包装 executor.execute(TtlRunnable.get(() - { // 这里能拿到父线程的MDC }));更省事的是用TtlExecutors.getTtlExecutorService(executor)直接包装整个线程池这样提交任务时连TtlRunnable.get()都不用显式调。不过我也要说句实话TTL确实方便但引入一个新依赖、尤其是可能需要Java Agent配合才能完全发挥效果时团队接入成本其实不低。如果你的异步场景主要集中在Spring线程池、Async、MQ消费端这几个可控位置TaskDecorator方案已经能解决90%的问题。TTL更适合那些线程模型很复杂、动不了源码、只能靠外部包装解决的场景。4. 跨服务传递让TraceId顺着HTTP和RPC调用链游走4.1 Header命名规范和网关统一入口线程内部搞定了接下来是跨服务调用。分布式系统里一次请求往往要经过多个服务如果每个服务各用各的TraceId前面做的工作就白费了。所以必须定一个规矩TraceId在服务间传递时放在哪里叫什么名字。我们的做法是统一用HTTP Header里的traceId字段。所有服务约定俗成收到外部请求时看Header里有没有traceId有就沿用没有就生成。内部服务之间调用时一律从MDC里取出当前traceId放到Header里带过去。名字也可以叫X-Trace-Id或者X-Request-Id这个不关键关键是全团队统一。微服务架构下外部请求往往先进网关。网关这里做一次统一入口处理检查请求Header里的traceId为空就生成一个放进去然后转发给下游服务。Spring Cloud Gateway里可以写一个GlobalFilterComponent public class TraceIdGatewayFilter implements GlobalFilter, Ordered { Override public MonoVoid filter(ServerWebExchange exchange, GatewayFilterChain chain) { String traceId exchange.getRequest().getHeaders().getFirst(traceId); if (StringUtils.isBlank(traceId)) { traceId generateTraceId(); } ServerWebExchange mutatedExchange exchange.mutate() .request(r - r.header(traceId, traceId)) .build(); return chain.filter(mutatedExchange); } Override public int getOrder() { return -1000; } }Gateway这里有个坑要提醒一下WebFlux是响应式编程模型基于Netty不走Servlet规范所以MDC在这套模型里默认不可用直接MDC.put是无效的。所以我上面这段代码只是往Header里塞了traceId没有碰MDC。下游的WebFlux服务如果要打日志建议用Reactor的contextWrite或者把traceId塞进请求上下文里这个主题比较深先不展开。你只需要记住一个关键点网关层最核心的任务是保证Header里有traceId保证下游能拿到。4.2 Feign、RestTemplate、OkHttp三大客户端的拦截器配置网关配好了内部服务之间的调用也要带上Header。最省心的做法是配置一个全局拦截器而不是在每次调用时手动加Header。Feign场景Spring Cloud OpenFeign最常用通过RequestInterceptor实现Bean public RequestInterceptor traceIdRequestInterceptor() { return template - { String traceId MDC.get(traceId); if (StringUtils.isNotBlank(traceId)) { template.header(traceId, traceId); } }; }这个Bean配上之后所有Feign请求都会自动带上MDC里的traceId。唯一要注意的是如果Feign配置了RequestInterceptor多个注意它们的顺序不过我们的场景里顺序无所谓只要能把Header塞上就行。RestTemplate场景用ClientHttpRequestInterceptorBean public RestTemplate restTemplate() { RestTemplate restTemplate new RestTemplate(); restTemplate.getInterceptors().add((request, body, execution) - { String traceId MDC.get(traceId); if (StringUtils.isNotBlank(traceId)) { request.getHeaders().add(traceId, traceId); } return execution.execute(request, body); }); return restTemplate; }OkHttp场景用okhttp3.InterceptorBean public OkHttpClient okHttpClient() { return new OkHttpClient.Builder() .addInterceptor(chain - { Request original chain.request(); String traceId MDC.get(traceId); if (StringUtils.isNotBlank(traceId)) { Request requestWithTrace original.newBuilder() .header(traceId, traceId) .build(); return chain.proceed(requestWithTrace); } return chain.proceed(original); }) .build(); }这三个拦截器的套路完全一样从MDC里取traceId取到就往Header里塞。之所以要用拦截器而不是每次手动加Header是因为拦截器能保证团队所有成员写的调用代码默认带上TraceId不需要每个人都记得手动处理。这属于“约定优于配置”的思路能让机制持续运转而不是靠某个人写代码时想起来才加。下游服务收到带traceId的Header后会走我前面写的TraceIdFilter从Header里读到traceId直接put进MDC于是整条调用链的日志就串起来了。4.3 Dubbo这类RPC框架的隐式参数传递服务之间不全是HTTP调用很多团队内部用Dubbo这类RPC框架。Dubbo天然支持隐式参数传递attachments不会污染业务入参很适合用来传TraceId。消费者侧在调用前把traceId塞进RpcContextRpcContext.getContext().setAttachment(traceId, MDC.get(traceId));提供者侧在收到请求时从RpcContext取出traceId并放入MDCString traceId RpcContext.getContext().getAttachment(traceId); if (StringUtils.isNotBlank(traceId)) { MDC.put(traceId, traceId); }当然你可以在Dubbo的Filter扩展点里做统一处理这样不需要每个接口都手动setAttachment。实现一个org.apache.dubbo.rpc.Filter在invoke方法里处理presetAttachment和MDC的写入与清理然后通过Activate(group {CommonConstants.PROVIDER, CommonConstants.CONSUMER})激活即可。这个方案和HTTP拦截器的思路一样核心都是“通过统一入口透传而不是靠业务代码手动配合”。5. 日志侧收口业务日志和SQL日志如何都带上TraceId5.1 logback下MDC输出配置与JSON结构化日志到了这一步TraceId已经能在一次请求的所有线程和服务里传递了接下来要做的就是在日志输出时把它“印”出来。如果你用的是logback最简单的方式是在pattern里加%X{traceId}appender nameCONSOLE classch.qos.logback.core.ConsoleAppender encoder pattern%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} [%X{traceId}] - %msg%n/pattern charsetUTF-8/charset /encoder /appender这里的%X{traceId}就是从当前线程MDC里取“traceId”这个key对应的值。如果MDC里没有就输出空字符串。所以即使某个地方漏配了TraceIdFilter日志也能照常输出不会因为缺这个字段就报错崩溃。但如果你的日志要采集进Elasticsearch我更推荐直接用LogstashEncoder输出JSON格式的日志。好处是MDC里的所有字段会被自动解析成JSON的独立字段到了ES里就是独立的traceId字段检索效率远超在整段message里做模糊匹配。appender nameJSON_FILE classch.qos.logback.core.rolling.RollingFileAppender filelogs/app.json.log/file encoder classnet.logstash.logback.encoder.LogstashEncoder includeMdctrue/includeMdc customFields{appname:order-service}/customFields /encoder /appender这样打出来的日志是类似这样的JSON{ timestamp: 2025-01-15T13:42:37.123Z, level: INFO, logger: com.example.OrderServiceImpl, message: 订单创建成功 orderId12345, traceId: 6aa2526590ad07346b76e2b8d8d80384, appname: order-service }traceId作为独立字段出现之后在ES里用term查询就能精确匹配不用再担心正则匹配把性能拖垮。5.2 SQL日志打点p6spy和MyBatis的两种配置方式业务日志带上TraceId之后还差一类关键日志SQL执行日志。这也是标题里“能在Elasticsearch查询到对应SQL日志”的核心诉求。如果SQL日志没有带TraceId你就没法知道某条慢SQL到底是哪次请求触发的排查性能问题还得靠猜。方案一p6spy 统一拦截JDBCp6spy是一个JDBC驱动代理会在你的真实数据库驱动外层包装一层把执行的SQL、参数、耗时都打印出来。配置方式如下引入依赖dependency groupIdp6spy/groupId artifactIdp6spy/artifactId version3.9.1/version /dependency修改JDBC连接串把真实驱动包在p6spy外面jdbc-urljdbc:p6spy:mysql://localhost:3306/order_db driver-class-namecom.p6spy.engine.spy.P6SpyDriver在classpath下放一个spy.properties# 让SQL日志走logback而不是输出到控制台 appendercom.p6spy.engine.spy.appender.Slf4JLogger logMessageFormatcom.p6spy.engine.spy.appender.CustomLineFormat customLogMessageFormat%(currentTime) | took %(executionTime) ms | %(sql)p6spy有一个很明显的优势它对业务代码完全透明只要改了连接串和驱动所有JDBC操作都会被统一记录下来包括MyBatis、JPA、原生JDBC。而且p6spy打印SQL日志时是直接在应用进程里打logback的那套logger所以MDC里的traceId会自然带上。方案二MyBatis本身的日志输出MyBatis本身也支持打印SQL通过configuration.setLogImpl(StdOutImpl.class)或配置log-impl就能实现。但MyBatis打印SQL的时候默认不是DEBUG级别你需要在配置文件里把mapper所在的包级别调成DEBUGlogging: level: com.example.mapper: debug这样MyBatis会打印Preparing、Parameters、Total这几个阶段。缺点是SQL日志和业务日志可能不在同一行如果MDC没设置好检索时不太方便关联。我的建议是如果你依赖的ORM不只是MyBatis或者你有多个数据源直接用p6spy如果项目很轻、只是MyBatis用MyBatis本身的日志也够用。两种方案的关键点是不管用哪种一定要让SQL日志的logger是走logback/Log4j2体系的这样MDC里的traceId才会同步出现在SQL日志上。否则SQL日志从JDBC层面直接打到stdout那采集到ES里还是没有traceId关联。5.3 日志采集到Elasticsearch时避免TraceId变成“消息里的字符串”日志文件生成后采集环节也很关键。很多团队用Filebeat或Logstash采集日志如果日志是文本格式TraceId会嵌在整行message里比如2025-01-15 13:42:37.123 [http-nio-8080-exec-8] INFO c.e.OrderServiceImpl [6aa2526590ad07346b76e2b8d8d80384] - 订单创建成功这种情况下ES里traceId不是一个独立字段你只能用message: *6aa2526590ad07346b76e2b8d8d80384*去做wildcard查询。Wildcard查询性能差尤其在高基数日志量下慢得让人崩溃。所以在Filebeat采集时最好把traceId单独拆成一个字段。以Filebeat为例用processors里的grok解析filebeat.inputs: - type: filestream paths: - /data/logs/order-service/*.log processors: - dissect: tokenizer: %{timestamp} [%{thread}] %{level} %{logger} [%{traceId}] - %{message} target_prefix: 如果你的日志直接用LogstashEncoder输出JSON格式就不用这么麻烦。Filebeat的json keys配置或Logstash的json filter能自动把JSON展开成独立字段traceId天然成为独立字段。这里要特别提一句在ES的索引mapping里最好给traceId建keyword类型的字段。因为traceId的用法是精确匹配term查询不需要分词。如果默认被映射成text查询时还要处理分词问题甚至可能被拆得面目全非。{ mappings: { properties: { traceId: { type: keyword } } } }这一步做到了才真正具备“在ES里用TraceId查回对应SQL日志”的能力。6. Elasticsearch里的垂直切片用TraceId捞回一次请求的完整执行链6.1 先看Kibana查询一条TraceId对齐所有服务与SQL一切配置就绪后排查问题的体验会发生质的改变。比如你在日志平台收到一条报错或者某个请求比较慢从日志里看到traceId是6aa2526590ad07346b76e2b8d8d80384在Kibana的Discover页面直接搜traceId: 6aa2526590ad07346b76e2b8d8d80384或者用Elasticsearch的DSL{ query: { bool: { must: [ { term: { traceId: 6aa2526590ad07346b76e2b8d8d80384 } } ] } }, sort: [ { timestamp: asc } ] }搜索结果会把这个ID对应的所有日志按时间排好序呈现出来。你看到的可能包括网关的转发日志订单服务的Controller入参日志订单服务的Service业务日志订单服务调用支付服务的Feign日志支付服务的业务日志p6spy打印的SQL执行日志包含真实参数和耗时异常堆栈日志如果请求失败这就是“垂直切片”。同一条请求的生命周期全部日志再也不用跨服务去grep再也不用靠时间戳和IP猜顺序。一个ID整条链。这就是标题里“提高日志排查效率”的真实落地场景。以前40分钟才能拼出来的故事现在一条查询语句搞定。尤其是SQL日志当你能看到“这条请求在这个时间点执行了什么SQL、耗时多少毫秒”时排查慢请求基本就是看证据而不是猜方向了。6.2 更高效的三步排查法错误定位、时间轴还原、SQL分析拿到traceId之后怎么利用它快速定位问题我自己的习惯是三步走。第一步先看错误。在搜索框里输入traceId: 6aa2526590ad07346b76e2b8d8d80384 AND level: ERROR如果这条请求里有异常直接先看错误堆栈弄清楚是什么类型的错——是空指针、是超时、还是SQL异常。错误定位是性价比最高的一步很多时候看到错误信息问题原因就已经清楚了。第二步看时间轴。如果没有任何ERROR日志那大概率不是“报错型”问题而是“性能型”问题。这时候去掉level过滤按timestamp升序排列看整条链路的日志节奏。重点关注请求到达网关的时间进入订单服务的时间调用支付服务的耗时返回响应的时间如果发现某个服务之间的时间差特别大那瓶颈基本就锁定了。第三步重点看SQL。如果请求慢是因为数据库操作慢SQL日志会是关键证据。p6spy打印的每条SQL都带执行耗时直接看这条请求里多条SQL的执行时间分布。比如有SQL花了2秒拿那条SQL去数据库EXPLAIN一遍看是否有索引失效、全表扫描之类的问题。这三步法不需要什么高端工具就在Kibana的搜索框里反复组合条件而已。但配合TraceId这个“主键”所有操作都是在一条请求的有限日志里进行而不是面对几十个服务日志文件做全量grep。6.3 落地为团队可复用的搜索模板学会自己查没用还得让团队都用起来。如果每个人都靠手工输入搜索条件效率还是会打折扣。Kibana支持保存搜索和创建可视化的功能建议把上面三步法的Query DSL直接保存成模板按TraceId查全链路traceId: $id$按时间排序按TraceId查错误traceId: $id$ AND level: ERROR按TraceId查SQLtraceId: $id$ AND logger: p6spy或SQL logger的名字把这三个保存成Discover里的Saved Search团队成员排查时只需要输入一个变量——traceId再点开对应的保存搜索就能跳过繁琐的组合条件输入直接看到结果。更进一步如果你的日志平台支持自定义看板还可以把“每日慢SQL对应的traceId Top20”这种聚合指标做成看板从更大维度反推系统瓶颈。不过这些都是锦上添花先把“按TraceId查全链路”这个基本动作在团队里普及开排查效率就已经提升一大截了。结尾把TraceId用成本能后的几个小习惯我现在排查线上问题第一步一定是先把请求的TraceId拿在手上。不管是用户报障时日志里贴的、还是Kibana里看到的先用它把该请求的日志垂直切出来再看错误、拖时间轴、分析SQL。这个操作路径已经变成肌肉记忆了。最后再分享两个小细节可能帮你少走弯路。第一个在业务日志里把TraceId和关键入参放在一起。比如下单时打一条订单创建请求 userIdxxx orderNoxxx这样在ES里搜索时不仅能按TraceId切片还能拿业务字段反向查TraceId。很多时候用户只记得“我当时的订单号是多少”不记得具体时间有这个映射日志就能反查。第二个TraceId只是起点不是终点。如果团队后续要做真正的调用链监控每个Span的耗时、依赖关系、拓扑图可以在TraceId基础上再引入SpanId和父SpanId形成完整的调用树。但说句实在话大部分中小团队先别急着上一套重量级链路追踪系统把TraceId在日志侧老老实实打透已经能解决80%的日志排查痛点了。先把地基打好再谈盖高楼。
返回列表