zl程序教程

您现在的位置是:首页 >  工具

当前栏目

如何快速过滤出一次请求的所有日志?

日志 如何 快速 请求 所有 一次 过滤
2023-09-14 09:06:26 时间
 

本文在说什么???

先看下面的日志:

2019-03-29 11:41:00,766 INFO  [pool-9-thread-26] ? (:) - 执行请求......

2019-03-29 12:02:30,759 INFO  [pool-9-thread-26] ? (:) - 消息类型:epcc.401.001.01-网联格式......

我们知道,应用程序的线程池里的线程是会被重复利用的,就是说,一个线程处理完一个任务(比如一次http请求)后只是暂时处于空闲状态,然后会继续执行不断涌向线程池的任务。每个线程都有自己的Id(Thread#tid,只读属性)和名字(Thread#name),线程id是不可改变的,线程名通常是默认的XXXPool-M-Thread-N,例如Pool-1-Thread-0、DubboServerHandler-192.168.40.84:20880-thread-110

。我们在应用程序的log文件里也经常可以看到不同时间的两笔(或多笔)请求的线程名是一样的。

那么,问题来了,当现网系统请求比较大的时候,一次请求的所有日志并不是逐行在一起的,而是穿插在其他请求的日志行里。再加上线程名会重复。就像下面这样子的,我们要过滤出请求1的所有日志来排查问题,并不是一件容易的事情!本文要说的就是如何快速过滤出一次请求的所有日志。

2019-03-29 11:41:00,361 INFO [线程名1] 请求1的log,......
2019-03-29 11:41:00,362 INFO [线程名2] 请求2的log,......
2019-03-29 11:41:00,766 INFO [线程名2] 请求2的log,......
2019-03-29 11:41:00,812 INFO [线程名2] 请求2的log,......
2019-03-29 11:41:00,812 INFO [线程名1] 请求1的log,......
2019-03-29 11:41:00,833 INFO [线程名3] 请求3的log,......
2019-03-29 11:41:00,834 INFO [线程名4] 请求4的log,......
2019-03-29 11:41:00,891 INFO [线程名2] 请求2的log,......
2019-03-29 11:41:00,900 INFO [线程名1] 请求1的log,......
2019-03-29 11:41:01,000 INFO [线程名1] 请求5的log,......
2019-03-29 11:41:01,111 INFO [线程名1] 请求5的log,......
2019-03-29 11:41:01,111 INFO [线程名1] 请求5的log,......

曾经,,,

我曾在对接某银行银企直联通道时,看到了他们前置机系统log文件里所打印的日志,每个请求都有唯一的一个标志,查看日志感觉很清爽。于是我在那时的项目里也尝试并使用这种方式,在后续的系统运维排障中爽歪歪。https://www.cnblogs.com/buguge/p/7417737.html

樊哥也说,很多公司都是用这种方法,来定位业务日志的。比如华为的这哥们儿,也在用其他工具来实现类似这种的方式,来提高工作排障效率,https://wudashan.cn/2018/02/15/Log-Request-In-MutiThread/

 

现在,,,

payment_api转账这块,我把默认线程名改成有意义的字符串了,每次请求都有唯一的一个标志,方便排障。

 

 

但是payment_server和gateway_server的不好使。会重复。
现象:服务重启后,一旦某个线程被占用,更改了它的线程名之后,以后即使再被用到,线程名就改不了了。
通过分析thrift源码,目前进展是,线程池控制在TThreadedSelectorServer.startThreads()方法里。再往下分析比较吃力。