Shulou(Shulou.com)06/03 Report--

This article mainly introduces "how to elegantly print interface call time". In daily operation, I believe many people have doubts about how to elegantly print interface call time. The editor consulted all kinds of data and sorted out simple and easy-to-use operation methods. I hope it will be helpful to answer the question of "how to elegantly print interface call time"! Next, please follow the editor to study!

Introduction

Elegant API design is not just a code-level writing specification. It is almost impossible for API to be put into use after development, and it is more about polishing the details. For example, each execution time of the interface, the input parameters will be repeatedly deliberated in the API test.

Thinking

How to design a solution so that developers can see at a glance whether the processing time and input parameters of the interface are correct?

Train of thought

The first thing that comes to mind is the AOP aspect of Spring. Now when we write the API interface, we usually write the interface in the controller control layer, which is divided into controller classes under different business packages according to different services. The general architecture is as follows: according to the writing specification of the control layer, you only need to use the aspect to find the controller class under each business package, monitor the input parameters and execution time of each method under the class, print it in the log log, and then you can visualize the real-time status of each interface in the console.

Org.springframework.boot spring-boot-starter-web org.springframework.boot spring-boot-starter-aopAOP core of the practice guide package

The core of aop is pointcut and notification type. Combined with the solution we need to implement, what we focus on is each class method of the control layer package under each business. The main types of notifications are:

Pre-notification [Before advice]: executed before the join point, the advance notification will not affect the execution of the join point unless an exception is thrown here.

Normal return notification [After returning advice]: it is executed after the normal execution of the connection point is completed. If the connection point throws an exception, it will not be executed.

Exception return notification [After throwing advice]: executes after the join point throws an exception.

Return notification [After (finally) advice]: the contents of the return notification will be executed after the connection point execution is completed, regardless of whether the normal execution is completed or an exception is thrown.

Surround notification [Around advice]: surround notifications around join points, such as before and after a method call. This is the most powerful notification type and can customize some actions before and after the method call. The surround notification is also responsible for deciding whether to continue processing join point (calling the proceed method of ProceedingJoinPoint) or interrupt execution.

Here, because we need to record input parameters and interface processing time, we choose Before pre-notification and Around surround notification.

Define tangent point

In the first step of the aspect, we need to find the right pointcut to create a new RuntimeMethod class, define it with @ Aspect @ Component modifier, which is the aspect entry class managed by spring, and the @ Log4j2 annotation to facilitate subsequent log printing.

@ Aspect@Component@Log4j2public class RuntimeMethod {/ / define the aopPoint private method, decorate and identify the tangent point of the section with @ Pointcut / / execution (* com.staging.business.*.controller.*.* (..)) For example, / / execution () is the body of the section / / the first "*" symbol, indicating the type of return value any / / com.staging.business represents the package name of the service cut by AOP, that is, the ".." after the business class / / package name that needs to be crosscut, indicates the "*" after the current package and subpackage / /, indicates the class name, * that is, all classes / /. * (..) Indicates any method name, parameters in parentheses, and two dots that match any parameter type @ Pointcut ("execution (* com.staging.business.*.controller.*.* (..)") Private void aopPoint () {}}

The second step of the section is to define the pre-and surround notifications and declare that the pointcut of the notification is aopPoint ()

/ * function description: pre-notification * / @ Before ("aopPoint ()") public void before (JoinPoint joinPoint) throws Throwable {/ / enter here before calling the aspect management API} / * function description: surround notification * / @ Around ("aopPoint ()") public Object around (ProceedingJoinPoint joinPoint) throws Throwable { / / will enter here after being notified by before The client can not get the return parameter Object result = joinPoint.proceed () until the result object is returned. Return result;}

The first two steps implement two required notifications and briefly explain his role. Next, we need to use the ServletRequestAttributes object in the spring package to get the HttpServletRequest object and get some of the print parameters we want.

Public void before (JoinPoint joinPoint) throws Throwable {/ / enters here before calling the aspect management interface ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes (); HttpServletRequest request = requestAttributes.getRequest (); Enumeration e = request.getHeaderNames (); JSONObject headers = new JSONObject (); if (null! = e) {while (e.hasMoreElements ()) {String headerName = e.nextElement () Enumeration headerValues = request.getHeaders (headerName); while (headerValues.hasMoreElements ()) {headers.put (headerName, headerValues.nextElement ()) } / / parameters represent request method, request address, parameter, header parameter, call time log.info ("- in- {}-{} {}", request.getMethod (), request.getRequestURI (), joinPoint.getArgs (), headers.toJSONString ()}})

The interface call time can also be easily printed in the surround notification.

Public Object around (ProceedingJoinPoint joinPoint) throws Throwable {long begin=System.currentTimeMillis (); / / will enter here after the before notification, and the client can not get the return parameter Object result = joinPoint.proceed (); long end= System.currentTimeMillis (); log.info ("- out-time: {} ms", end-begin} return result;} until the result object is returned.

When running and calling the API interface, we will all output the following log

-in- GET / user/info-id=123 header: {"content-length": "0",.}-out--time:91ms.

There is no problem with the test at all, of course, this is not the final version, try to put it in the test environment, call more people, it will be very confusing, similar to the following painting style

-in- GET / user/info-id=123 header: {"content-length": "0",.}-in- GET / teacher/info-id=123 header: {"content-length": "0",.}-out--time:91ms-in- GET / user/info-id=321 header: {"content-length": "0",.}-out--time:191ms.

You can see that the problem occurs in concurrent operations. When multiple interfaces are called at the same time, the log will be messed up, which is not the result I want. We must find a way to solve the problem. Looking through the materials, I came up with the idea of using ThreadLocal thread local variables and Tuple tuple objects to solve this problem. Next, modify the code. Define a private variable ThreadLocal. Exe in the RuntimeMethod class.

Private ThreadLocal threadLocal = new ThreadLocal ()

Re-transformation notice section

@ Before ("aopPoint ()") public void before (JoinPoint joinPoint) throws Throwable {/ / print request body ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes (); if (null! = requestAttributes) {/ / use ThreadLocal and Tuple objects to store parameters in loadingThreadLocal. In this way, you can easily take out the necessary parameters of the interface loadingThreadLocal (requestAttributes, joinPoint.getArgs ()); log.info ("- in- {} {}-{}", threadLocal.get (). GetT1 (), threadLocal.get (). GetT2 (), threadLocal.get (). GetT6 () Log.info ("Method arguments: {}-{}", threadLocal.get () .getT3 (), threadLocal.get () .getT6 ()) Log.info ("Request header: {}-{}", threadLocal.get (). GetT4 (), threadLocal.get (). GetT6 ());} @ Around ("aopPoint ()") public Object around (ProceedingJoinPoint joinPoint) throws Throwable {/ / call target method Object result = joinPoint.proceed () String requestUrl = threadLocal.get (). GetT2 (); / notice that in out, take out the name of the called interface, so that you can use the interface name to facilitate filtering, so you don't have to be afraid of log confusion. Return parameters should not be added in the production environment as far as possible, because it is the log of troubleshooting problems during the test phase, so the more detailed the better. Log.info ("- out- {} return: {}-time: {} ms-{}", requestUrl, JSONObject.toJSONString (result), System.currentTimeMillis ()-threadLocal.get (). GetT5 (), threadLocal.get (). GetT6 ()); / / API output parameter processing return delReturnData (result);} private void loadingThreadLocal (ServletRequestAttributes requestAttributes, Object [] args) {HttpServletRequest request = requestAttributes.getRequest () Enumeration e = request.getHeaderNames (); JSONObject headers = new JSONObject (); if (null! = e) {while (e.hasMoreElements ()) {String headerName = e.nextElement (); Enumeration headerValues = request.getHeaders (headerName); while (headerValues.hasMoreElements ()) {headers.put (headerName, headerValues.nextElement ()) } / / An id of the call chain is appended here, which can be returned to the client and let the client bring the id in the next request. The method counts a business closed loop. String businessId = IdUtil.getSnowflake (1,1). NextIdStr (); / / request method, request address, parameters, header parameters, call time, call chain id threadLocal.set (Tuples.of (request.getMethod (), request.getRequestURI (), args, headers.toJSONString (), System.currentTimeMillis (), businessId);}

Then take a look at the API call log after using this scheme.

2021-01-11 20 activityArea/getUserPrize 16 in- GET [http-nio-8080-exec-7] INFO cn.mc.apd [86]-- in- GET / activityArea/getUserPrize-13486047359214592002021-01-11 2020 14565 [http-nio-8080-exec-7] INFO cn.mc.appod [90]-Method arguments: [1]-13486047359214592002021-01-11 2016 http-nio-8080-exec-7 39.566 [http-nio-8080-exec-7] INFO cn.mc.app.tood [93] -Request header: {"content-length": "0" "idfa": "00000", x-nondec-sign ":" d93207ba "," host ":" 80 "}-13486047359214592002021-01-11 20 d93207ba 1615 INFO cn.mc.app.tools.interceptor.RuntimeMethod [http-nio-8080-exec-7] INFO cn.mc.app.tools.interceptor.RuntimeMethod-- out- / activityArea/getUserPrize return: {" code ": 0," data ": {" userActivePrizeRec ":" 0 "," message ":" success "}-time:28ms The study on "how to elegantly print the calling time of the interface" is over. I hope to be able to solve your doubts. The collocation of theory and practice can better help you learn, go and try it! If you want to continue to learn more related knowledge, please continue to follow the website, the editor will continue to work hard to bring you more practical articles!

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.