Linux 命令中的 grep、awk、sed 命令因为功能强大，被人们称为Linux 命令三剑客。

本文中会用到 grep、awk、sort、head、cat 等命令。

场景 1: 找出耗时大于100的接口

实验数据：
为了更贴近于实际问题，从线上服务器随机捞了10条日志，用于原始数据案例，其中日志存在本地文件中，并命名为 demo.log（以下命令行中会用到该文件）。
以下日志是从服务器上随机抓取的10 条 response 日志，其中 proc_time = xxx 表示接口耗时。

  1. [INFO][2022-03-30T17:00:00.018+0800] _com_request_out||traceid=9a39b1aa62441c0f00005f59531706c9||spanid=0a0116660475b585||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=PassUncompletedOrderRemoteService||method_name=getLastUncompletedOrderNew||uri=getLastUncompletedOrderNew||protocol=dubbo||caller=hna-daijia-v.htw-middleware-kop||remoteIp=10.193.119.123||remotePort=7179||remote_application=hna-daijia-v.htw-middleware-kop||request=[{"appVersion":"6.2.4","channel":"780","clientSource":2,"pid":202350239,"userRole":1}]||response={"code":200,"msg":"无未完成订单"}||errno=200||proc_time=26
  2. [INFO][2022-03-30T17:00:00.117+0800] _com_request_out||traceid=0f4d012c62441c0e00003a7ecf75ffc1||spanid=0a018e465869f907||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=PassUncompletedOrderRemoteService||method_name=getLastUncompletedOrderNew||uri=getLastUncompletedOrderNew||protocol=dubbo||caller=hna-daijia-v.htw-middleware-kop||remoteIp=10.193.119.123||remotePort=7179||remote_application=hna-daijia-v.htw-middleware-kop||request=[{"appVersion":"6.2.4","channel":"827","clientSource":2,"pid":498283850,"userRole":1}]||response={"code":200,"msg":"无未完成订单"}||errno=200||proc_time=118
  3. [INFO][2022-03-30T17:00:00.126+0800] _com_request_out||traceid=49e1aee562441bfb00003ee26a41e040||spanid=0a0912ac234270bb||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=OrderRemotingService||method_name=queryNotStartAppointOrderListByDriverId||uri=queryNotStartAppointOrderListByDriverId||protocol=dubbo||caller=hna-v.daijia-cos_gz||remoteIp=10.193.119.123||remotePort=7100||remote_application=daijia-cos||request=[2832344501293022]||response={"code":200}||errno=200||proc_time=9
  4. [INFO][2022-03-30T17:00:00.128+0800] _com_request_out||traceid=38cb6d3962441c1000007d1d5ebe4192||spanid=0a050200ad9b75bf||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=PassUncompletedOrderRemoteService||method_name=getLastUncompletedOrderNew||uri=getLastUncompletedOrderNew||protocol=dubbo||caller=hna-daijia-v.htw-middleware-kop||remoteIp=10.193.119.123||remotePort=7179||remote_application=hna-daijia-v.htw-middleware-kop||request=[{"appVersion":"6.2.4","channel":"780","clientSource":2,"pid":510396449,"userRole":1}]||response={"code":200,"msg":"无未完成订单"}||errno=200||proc_time=99
  5. [INFO][2022-03-30T17:00:00.128+0800] _com_request_out||traceid=0c41076862441c10a3fa3c7c879fdbd9||spanid=0a0190c020e4585b||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=PassUncompletedOrderRemoteService||method_name=getLastUncompletedOrderNew||uri=getLastUncompletedOrderNew||protocol=dubbo||caller=hna-daijia-v.htw-middleware-kop||remoteIp=10.193.119.123||remotePort=7179||remote_application=hna-daijia-v.htw-middleware-kop||request=[{"appVersion":"6.3.19","channel":"1100000003","clientSource":2,"pid":1130539773,"userRole":1}]||response={"code":200,"msg":"无未完成订单"}||errno=200||proc_time=61
  6. [INFO][2022-03-30T17:00:00.129+0800] _com_request_out||traceid=36c1d24d62441c100000356ba5cc5236||spanid=0a05000c0be0508a||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=PassUncompletedOrderRemoteService||method_name=getLastUncompletedOrderNew||uri=getLastUncompletedOrderNew||protocol=dubbo||caller=hna-daijia-v.htw-middleware-kop||remoteIp=10.193.119.123||remotePort=7179||remote_application=hna-daijia-v.htw-middleware-kop||request=[{"appVersion":"6.2.4","channel":"780","clientSource":2,"pid":243684764,"userRole":1}]||response={"code":200,"msg":"无未完成订单"}||errno=200||proc_time=61
  7. [INFO][2022-03-30T17:00:00.129+0800] _com_request_out||traceid=cc565eb762441c0f96d81d87e6f4f874||spanid=0a090c8043fcf5c0||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=PassUncompletedOrderRemoteService||method_name=getLastUncompletedOrderNew||uri=getLastUncompletedOrderNew||protocol=dubbo||caller=hna-daijia-v.htw-middleware-kop||remoteIp=10.193.119.123||remotePort=7179||remote_application=hna-daijia-v.htw-middleware-kop||request=[{"appVersion":"6.3.19","channel":"1100000001","clientSource":2,"pid":328130693,"userRole":1}]||response={"code":200,"msg":"无未完成订单"}||errno=200||proc_time=110
  8. [INFO][2022-03-30T17:00:00.131+0800] _com_request_out||traceid=645aec2762441c1019a89b74ff196302||spanid=0a098e18342b248b||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=SafeRemoteService||method_name=getStopServiceInfo||uri=getStopServiceInfo||protocol=dubbo||caller=hna-v.daijia-cos_gz||remoteIp=10.193.119.123||remotePort=7100||remote_application=daijia-cos||request=[{"startLat":23.01683,"startLng":113.12041}]||response={"code":200,"data":{}}||errno=200||proc_time=5
  9. [INFO][2022-03-30T17:00:00.136+0800] _com_request_out||traceid=8772f8d362441c0f0000623227902e40||spanid=0a091a24ce771524||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=PassUncompletedOrderRemoteService||method_name=getLastUncompletedOrderNew||uri=getLastUncompletedOrderNew||protocol=dubbo||caller=hna-daijia-v.htw-middleware-kop||remoteIp=10.193.119.123||remotePort=7179||remote_application=hna-daijia-v.htw-middleware-kop||request=[{"appVersion":"6.2.2","channel":"1130980473","clientSource":2,"pid":425462608,"userRole":1}]||response={"code":200,"msg":"无未完成订单"}||errno=200||proc_time=10
  10. [INFO][2022-03-30T17:00:00.214+0800] _com_request_out||traceid=156593e262441c0f00007c2d231f9240||spanid=0a0190662adf8451||cspanid=||_msg=success||hintCode=0||hintContent=||application=daijia-order||service_name=DriverOrderRemoteService||method_name=driverQueryDrivingFee||uri=driverQueryDrivingFee||protocol=dubbo||caller=hna-daijia-v.htw-middleware-kop||remoteIp=10.193.119.123||remotePort=7100||remote_application=hna-daijia-v.htw-middleware-kop||request=[2832347395589871,163904738422642]||response={"code":200,"data":{"distance":9398,"drivingState":1,"fee":41.5,"freeWaitTime":600,"peekWaitTime":11400,"restTimes":3,"servicetime":1522,"waitTimeSecond":72,"waittime":2}}||errno=200||proc_time=230

第一步，提取关键信息：traceid、method_name、errno、proc_time，输出如下：

  1. scott@xxx: cat demo.log | awk -F '\\|\\|' '{print substr($1,8,28), $2, $10, $19, $20}'
  3. 2022-03-30T17:00:00.018+0800 traceid=9a39b1aa62441c0f00005f59531706c9 method_name=getLastUncompletedOrderNew errno=200 proc_time=26
  4. 2022-03-30T17:00:00.117+0800 traceid=0f4d012c62441c0e00003a7ecf75ffc1 method_name=getLastUncompletedOrderNew errno=200 proc_time=118
  5. 2022-03-30T17:00:00.126+0800 traceid=49e1aee562441bfb00003ee26a41e040 method_name=queryNotStartAppointOrderListByDriverId errno=200 proc_time=9
  6. 2022-03-30T17:00:00.128+0800 traceid=38cb6d3962441c1000007d1d5ebe4192 method_name=getLastUncompletedOrderNew errno=200 proc_time=99
  7. 2022-03-30T17:00:00.128+0800 traceid=0c41076862441c10a3fa3c7c879fdbd9 method_name=getLastUncompletedOrderNew errno=200 proc_time=61
  8. 2022-03-30T17:00:00.129+0800 traceid=36c1d24d62441c100000356ba5cc5236 method_name=getLastUncompletedOrderNew errno=200 proc_time=61
  9. 2022-03-30T17:00:00.129+0800 traceid=cc565eb762441c0f96d81d87e6f4f874 method_name=getLastUncompletedOrderNew errno=200 proc_time=110
  10. 2022-03-30T17:00:00.131+0800 traceid=645aec2762441c1019a89b74ff196302 method_name=getStopServiceInfo errno=200 proc_time=5
  11. 2022-03-30T17:00:00.136+0800 traceid=8772f8d362441c0f0000623227902e40 method_name=getLastUncompletedOrderNew errno=200 proc_time=10
  12. 2022-03-30T17:00:00.214+0800 traceid=156593e262441c0f00007c2d231f9240 method_name=driverQueryDrivingFee errno=200 proc_time=230

第二步，根据 proc_time 字段（在第五个位置，用 $5 表示）过滤耗时大于100的记录：

  1. scott@xxx: cat demo.log | awk -F '\\|\\|' '{print substr($1,8,28), $2, $10, $19, $20}' | awk -F '=' '$5>100 {print $0}'
  3. 2022-03-30T17:00:00.117+0800 traceid=0f4d012c62441c0e00003a7ecf75ffc1 method_name=getLastUncompletedOrderNew errno=200 proc_time=118
  4. 2022-03-30T17:00:00.129+0800 traceid=cc565eb762441c0f96d81d87e6f4f874 method_name=getLastUncompletedOrderNew errno=200 proc_time=110
  5. 2022-03-30T17:00:00.214+0800 traceid=156593e262441c0f00007c2d231f9240 method_name=driverQueryDrivingFee errno=200 proc_time=230

场景 2: 找出mybatis执行日志中耗时top100的执行记录

实验数据：从线上机器中捞取了一段时间内的mybatis执行日志，如下所示，其中Flag 前的那个数字就是mysql执行耗时。

  1. 2022-03-30 00:00:00.000,ValetOrderFeeSharding.getValetOrderFeeByOrderId,0,1,Flag=2b29b29162432cfe00002cb8ea0e3140
  2. 2022-03-30 00:00:00.000,ValetOrderSharding.getOrderByOidFromDbMaster,0,2,Flag=0a4ac31862432ca532ce2a1cfd55e402
  3. 2022-03-30 00:00:00.000,SsOrderTag.selectOrderTags,0,1,Flag=5b8cf44062432d0000006e253d2c7e67
  4. 2022-03-30 00:00:00.000,DidOrderIdRoute.queryOrderIdsByDriverIdAndAcpTime,0,1,Flag=0ac16ebd62432d001110d5cef2a48b86
  5. 2022-03-30 00:00:00.000,ValetOrderResultSharding.getOrderResultsByOrderIds,0,5,Flag=0ac16ebd62432d001110d5cef2a48b86
  6. 2022-03-30 00:00:00.000,ValetOrderExtraInfoSharding.getById,0,1,Flag=0a4ac31862432ce23b122a31fe490402
  7. 2022-03-30 00:00:00.000,ValetOrderTagSharding.selectByOrderIdFromMaster,0,1,Flag=0a4ac31862432b5242a62a45ffe43d02
  8. 2022-03-30 00:00:00.000,ValetOrderSharding.getOrdersByOrderIdsAndSendType,0,7,Flag=0ac16ebd62432d001110d5cef2a48b86
  9. 2022-03-30 00:00:00.000,ValetOrderRiskManagement.selectOrderIdListByOrderIdAndRiskCode,0,1,Flag=0ac16ebd62432d001110d5cef2a48b86
  10. 2022-03-30 00:00:00.000,ValetOrderFeeSharding.getValetOrderFeeByOrderId,0,1,Flag=0576a6d362432cfe000032ff35dc6240
  11. 2022-03-30 00:00:00.000,ValetOrderFeeSharding.getOrderFeesByIdsAndPayStatus,0,4,Flag=0ac16ebd62432d001110d5cef2a48b86
  12. 2022-03-30 00:00:00.000,ValetOrderSharding.getOrderByOidFromDbMaster,0,1,Flag=0a4ac31862432ca532ce2a1cfd55e402
  13. 2022-03-30 00:00:00.000,ValetOrderFeeSharding.getValetOrderFeeByOrderId,0,1,Flag=934d397d62432cfe00004228938d3e40

查询耗时大于1ms 的 top 100 的请求方法（会根据耗时倒序排列）：

scott@xxx: cat mybatis-demo.log | sort -nrk 4 -t, | awk -F ',' '$4>1 {print $0}' | head -n 100

2022-03-30 00:00:00.000,ValetOrderSharding.getOrdersByOrderIdsAndSendType,0,7,Flag=0ac16ebd62432d001110d5cef2a48b86
2022-03-30 00:00:00.000,ValetOrderResultSharding.getOrderResultsByOrderIds,0,5,Flag=0ac16ebd62432d001110d5cef2a48b86
2022-03-30 00:00:00.000,ValetOrderFeeSharding.getOrderFeesByIdsAndPayStatus,0,4,Flag=0ac16ebd62432d001110d5cef2a48b86
2022-03-30 00:00:00.000,ValetOrderSharding.getOrderByOidFromDbMaster,0,2,Flag=0a4ac31862432ca532ce2a1cfd55e402

场景3：统计dubbo provider 请求量top3的接口

实验数据：从线上机器中随机捞了一段时间内的dubbo provider 日志，如下所示（接口方法后面第二个数字就是接口耗时）：

2022-03-30 20:23:45.045,com.kuaidadi.order.data.api.dao.OrderFeeRemoteService:1.0.0_getOrderFeeByOrderIdFromEs(Long),0,504,daijia-order->daijia-order-data,10.193.181.94,Flag=4ec94b5662444bca00005e60ce9c9d11
2022-03-30 20:23:45.045,com.kuaidadi.order.data.api.config.OrderConfigRemoteService:1.0.0_getStrategyLinkLevelConfig(Integer),0,32,daijia-region-assign->daijia-order-data,10.193.170.224,Flag=e7d2f66c62444bd1000029d0b6172940
2022-03-30 20:23:45.045,com.kuaidadi.order.data.api.dao.OrderFeeRemoteService:1.0.0_getOrderFeeByOrderIdFromEs(Long),0,15,daijia-order->daijia-order-data,10.197.40.9,Flag=b37121af62444bcf000074eaf91e3e40
2022-03-30 20:23:45.045,com.kuaidadi.order.data.sunshine.api.SsOrderFeeItemRemoteService:1.0.0_getByOrderId(Long),0,133,sunshine-venus->daijia-order-data,10.155.105.250,Flag=b3ce746762444bd187d42a2659452209
2022-03-30 20:23:45.045,com.kuaidadi.order.data.api.config.OrderConfigRemoteService:1.0.0_getStrategyLinkLevelConfig(Integer),0,101,daijia-region-assign->daijia-order-data,10.193.170.224,Flag=f4b63a1862444bd100005d1d4475e140
2022-03-30 20:23:45.045,com.kuaidadi.order.data.sunshine.api.SsOrderResultRemoteService:1.0.0_getOrderResultById(Long),0,93,sunshine-venus->daijia-order-data,10.155.105.250,Flag=c9c6c1d062444bd000002b03ef332740
2022-03-30 20:23:45.045,com.kuaidadi.order.data.api.dao.OrderTagRemoteService:1.0.0_selectOrderTagsByOrderId(Long),0,83,springboot-pluto-engine->daijia-order-data,10.197.194.189,Flag=1b82a17362444bd1eb26430d10cf0303

统计dubbo provider 请求量top3的接口：

scott@xxx: cat dubbo-provider.log | cut -d ',' -f2 | sort | uniq -c | sort -nr | head -n 3
   2 com.kuaidadi.order.data.api.dao.OrderFeeRemoteService:1.0.0_getOrderFeeByOrderIdFromEs(Long)
   2 com.kuaidadi.order.data.api.config.OrderConfigRemoteService:1.0.0_getStrategyLinkLevelConfig(Integer)
   1 com.kuaidadi.order.data.sunshine.api.SsOrderResultRemoteService:1.0.0_getOrderResultById(Long)