详解
随着微服务盛行,很多公司都把系统按照业务边界拆成了很多微服务,在排错查日志的时候。因为业务链路贯穿着很多微服务节点,导致定位某个请求的日志以及上下游业务的日志会变得有些困难。
搭建分布式链路追踪系统一天下来产生几十G上百G的数据其实非常正常。如果想保存时间长点的话,也需要增加服务器磁盘的成本。那么就可以考虑这个Tlog轻量级日志追踪,接入简单,基本十分钟就可以实现微服务之间链路追踪。
他不存储日志,它只是自动的对你的日志进行打标签,自动生成TraceId贯穿你微服务的一整条链路。并且提供上下游节点信息。
特性:
- 持dubbo,dubbox,spring cloud三大RPC框架。
- 对业务代码无侵入式设计,使用简单,10分钟即可接入。
- 支持常见的log4j,log4j2,logback三大日志框架,并提供自动检测,完成适配。
- 支持Spring Cloud Gateway和Soul网关。
- 适配HttpClient和Okhttp的http调用标签传递。
- 支持三种任务框架,JDK的TimerTask,Quartz,XXL-JOB。
- 支持日志标签的自定义模板的配置,提供多个系统级埋点标签的选择。
- 支持异步线程的追踪,包括线程池,多级异步线程等场景。
- 几乎无性能损耗,快速稳定,经过压测,损耗在0.01%。
开始接入:
- pom引入依赖
<dependency>
<groupId>com.yomahub</groupId>
<artifactId>tlog-all-spring-boot-starter</artifactId>
<version>1.3.6</version>
</dependency>
这里选择了springboot的依赖包,还支持spring native
- 日志配置文件修改:
按照接入文档修改的encoder的class为com.yomahub.tlog.core.enhance.logback.AspectLogbackEncoder
- 需要打印上层服务名称、ip,需要增加配置
#TLog轻量级日志追踪
tlog:
pattern: '[$preApp][$preIp][$spanId][$traceId]'
$preApp:上游微服务节点名称
$preHost: 上游微服务的Host Name
$preIp:上游微服务的IP地址
$spanId:链路spanId,具体规则可以参照八.SpanId生成规则
$traceId:全局唯一跟踪ID
这里最好建一个公共的yaml,所有模块都引入,否则每个模块都要改
- 日志输出格式修改:
<encoder class="com.yomahub.tlog.core.enhance.logback.AspectLogbackEncoder">
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %X{tl} [%thread] %-5level %logger{50} - %msg%n</pattern>
</encoder>
TLog中log4j和logback的占位符为%X{tl},而在log4j2中的占位符为%TX{tl},不要写错
对于springboot应用来说,你只需在springboot的配置文件中作如下配置:
#TLog轻量级日志追踪
tlog:
# 不配默认为false
enable-invoke-time-print: true
TLog默认采用snowflake算法生成traceId,当然你也可以去更换traceId的生成算法。
定义自己的traceId生成类去继承TLogIdGenerator接口:
tlog:
id-generator: cn.zealon.readingcloud.common.generator.IdGenerator
- 对OpenFeign支持:
需要在spring xml里如下配置
<bean class="com.yomahub.tlog.feign.filter.TLogFeignFilter"/>
<bean class="com.yomahub.tlog.core.aop.AspectLogAop"/>
- 自定义模板显示和开启rpc时间打印
需要在spring xml如下配置
<bean class="com.yomahub.tlog.spring.TLogPropertyInit">
<property name="pattern" value="[$preApp][$preHost][$preIp][$spanId][$traceId]"/>
<property name="enableInvokeTimePrint" value="true"/>
</bean>
- 查看效果
gateway服务 日志 日志id:bc9a91d8-0156-43a0-9361-5ed037016f32
2022-03-13 17:45:13.858 [NONE][NONE][0][bc9a91d8-0156-43a0-9361-5ed037016f32] [reactor-http-nio-3] INFO com.netflix.config.ChainedDynamicProperty - Flipping property: light-reading-cloud-account.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
2022-03-13 17:45:13.881 [NONE][NONE][0][bc9a91d8-0156-43a0-9361-5ed037016f32] [reactor-http-nio-3] INFO com.netflix.loadbalancer.BaseLoadBalancer - Client: light-reading-cloud-account instantiated a LoadBalancer: DynamicServerListLoadBalancer:{NFLoadBalancer:name=light-reading-cloud-account,current list of Servers=[],Load balancer stats=Zone stats: {},Server stats: []}ServerList:null
2022-03-13 17:45:13.889 [NONE][NONE][0][bc9a91d8-0156-43a0-9361-5ed037016f32] [reactor-http-nio-3] INFO c.n.loadbalancer.DynamicServerListLoadBalancer - Using serverListUpdater PollingServerListUpdater
2022-03-13 17:45:13.910 [NONE][NONE][0][bc9a91d8-0156-43a0-9361-5ed037016f32] [reactor-http-nio-3] INFO com.netflix.config.ChainedDynamicProperty - Flipping property: light-reading-cloud-account.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
2022-03-13 17:45:13.913 [NONE][NONE][0][bc9a91d8-0156-43a0-9361-5ed037016f32] [reactor-http-nio-3] INFO c.n.loadbalancer.DynamicServerListLoadBalancer - DynamicServerListLoadBalancer for client light-reading-cloud-account initialized: DynamicServerListLoadBalancer:{NFLoadBalancer:name=light-reading-cloud-account,current list of Servers=[192.168.0.102:8003],Load balancer stats=Zone stats: {unknown=[Zone:unknown; Instance count:1; Active connections count: 0; Circuit breaker tripped count: 0; Active connections per server: 0.0;]
},Server stats: [[Server:192.168.0.102:8003; Zone:UNKNOWN; Total Requests:0; Successive connection failure:0; Total blackout seconds:0; Last connection made:Thu Jan 01 08:00:00 CST 1970; First connection made: Thu Jan 01 08:00:00 CST 1970; Active Connections:0; total failure count in last (1000) msecs:0; average resp time:0.0; 90 percentile resp time:0.0; 95 percentile resp time:0.0; min resp time:0.0; max resp time:0.0; stddev resp time:0.0]
]}ServerList:org.springframework.cloud.alibaba.nacos.ribbon.NacosServerList@40ba8c05
2022-03-13 17:45:14.909 [NONE][NONE][0][bc9a91d8-0156-43a0-9361-5ed037016f32] [PollingServerListUpdater-0] INFO com.netflix.config.ChainedDynamicProperty - Flipping property: light-reading-cloud-account.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
account服务 日志id:bc9a91d8-0156-43a0-9361-5ed037016f32
2022-03-13 17:45:14.417 [light-reading-cloud-gateway][192.168.0.102][0.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8003-exec-1] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/account/like-see/get-books],参数为:{"limit":["10"],"page":["1"]}
2022-03-13 17:45:15.772 [light-reading-cloud-gateway][192.168.0.102][0.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [HystrixTimer-1] ERROR c.z.r.book.feign.fallback.BookClientFallBack - 获取图书[60034980]失败:null
2022-03-13 17:45:15.814 [light-reading-cloud-gateway][192.168.0.102][0.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [hystrix-light-reading-cloud-book-1] INFO com.netflix.config.ChainedDynamicProperty - Flipping property: light-reading-cloud-book.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
2022-03-13 17:45:15.836 [light-reading-cloud-gateway][192.168.0.102][0.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [hystrix-light-reading-cloud-book-1] INFO com.netflix.loadbalancer.BaseLoadBalancer - Client: light-reading-cloud-book instantiated a LoadBalancer: DynamicServerListLoadBalancer:{NFLoadBalancer:name=light-reading-cloud-book,current list of Servers=[],Load balancer stats=Zone stats: {},Server stats: []}ServerList:null
2022-03-13 17:45:15.846 [light-reading-cloud-gateway][192.168.0.102][0.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [hystrix-light-reading-cloud-book-1] INFO c.n.loadbalancer.DynamicServerListLoadBalancer - Using serverListUpdater PollingServerListUpdater
2022-03-13 17:45:15.860 [light-reading-cloud-gateway][192.168.0.102][0.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [hystrix-light-reading-cloud-book-1] INFO com.netflix.config.ChainedDynamicProperty - Flipping property: light-reading-cloud-book.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
2022-03-13 17:45:15.863 [light-reading-cloud-gateway][192.168.0.102][0.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [hystrix-light-reading-cloud-book-1] INFO c.n.loadbalancer.DynamicServerListLoadBalancer - DynamicServerListLoadBalancer for client light-reading-cloud-book initialized: DynamicServerListLoadBalancer:{NFLoadBalancer:name=light-reading-cloud-book,current list of Servers=[192.168.0.102:8001],Load balancer stats=Zone stats: {unknown=[Zone:unknown; Instance count:1; Active connections count: 0; Circuit breaker tripped count: 0; Active connections per server: 0.0;]
},Server stats: [[Server:192.168.0.102:8001; Zone:UNKNOWN; Total Requests:0; Successive connection failure:0; Total blackout seconds:0; Last connection made:Thu Jan 01 08:00:00 CST 1970; First connection made: Thu Jan 01 08:00:00 CST 1970; Active Connections:0; total failure count in last (1000) msecs:0; average resp time:0.0; 90 percentile resp time:0.0; 95 percentile resp time:0.0; min resp time:0.0; max resp time:0.0; stddev resp time:0.0]
]}ServerList:org.springframework.cloud.alibaba.nacos.ribbon.NacosServerList@18164192
2022-03-13 17:45:16.686 [light-reading-cloud-gateway][192.168.0.102][0.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8003-exec-1] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/account/like-see/get-books]的调用,耗时为:2265毫秒
2022-03-13 17:45:16.859 [light-reading-cloud-gateway][192.168.0.102][0.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [PollingServerListUpdater-0] INFO com.netflix.config.ChainedDynamicProperty - Flipping property: light-reading-cloud-book.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
服务Feign调用Book服务 日志id:bc9a91d8-0156-43a0-9361-5ed037016f32
2022-03-13 17:45:16.345 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-1] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["355025"]}
2022-03-13 17:45:16.345 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-2] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["60034980"]}
2022-03-13 17:45:16.473 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-1] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:124毫秒
2022-03-13 17:45:16.473 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-2] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:124毫秒
2022-03-13 17:45:16.544 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-3] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["60924085"]}
2022-03-13 17:45:16.550 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-3] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:5毫秒
2022-03-13 17:45:16.557 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-4] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["60036284"]}
2022-03-13 17:45:16.564 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-4] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:5毫秒
2022-03-13 17:45:16.570 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-5] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["60348379"]}
2022-03-13 17:45:16.576 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-5] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:5毫秒
2022-03-13 17:45:16.585 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-6] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["3001823523"]}
2022-03-13 17:45:16.590 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-6] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:4毫秒
2022-03-13 17:45:16.600 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-7] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["3001823403"]}
2022-03-13 17:45:16.605 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-7] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:4毫秒
2022-03-13 17:45:16.616 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-8] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["3001823527"]}
2022-03-13 17:45:16.621 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-8] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:4毫秒
2022-03-13 17:45:16.627 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-9] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["322538"]}
2022-03-13 17:45:16.632 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-9] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:4毫秒
2022-03-13 17:45:16.638 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-10] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]开始请求URL[/book/getBookById],参数为:{"bookId":["60348651"]}
2022-03-13 17:45:16.645 [light-reading-cloud-account][192.168.0.102][0.1.1][bc9a91d8-0156-43a0-9361-5ed037016f32] [http-nio-8001-exec-10] INFO c.y.t.web.interceptor.TLogWebInvokeTimeInterceptor - [TLOG]结束URL[/book/getBookById]的调用,耗时为:6毫秒
这里我们看到日志id可以统一了,并且有调用方的服务名字、每个接口的进出响应时间、参数。