Test observation and personal understanding of Hystrix timeout mechanism and thread state

When we use Hystrix, most of the time we complete the request call directly based on Spring Cloud annotations. One of our projects is to manually create HystrixCommand to wrap RestTemplate to initiate requests. However, in the process of service running, it is found that when HystrixCommand returns fallback result overtime, the RestTemplate request process has not ended, resulting in more thread pool occupancy.

Here, through a simple test, we set different timeouts for RestTemplate and HystrixCommand to observe the details of the execution of HystrixCommand.

Test observation

Simulate external services:

Create a springboot service that provides an interface: Wait 5 seconds to return data

@RestController
public class DataController {

    @RequestMapping("queryData")
    public String queryData() {
        //Wait 5 seconds and return a random string
        long sleepTime = 5000;
        try {
            Thread.sleep(sleepTime);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return UUID.randomUUID().toString();
    }
}
Test code:
public class HystrixCommandTest {

    private static final SimpleDateFormat df = new SimpleDateFormat("HH:mm:ss");

    //http request timeout
    private static final int HTTP_TIMEOUT = 10000;
    //hystrix timeout
    private static final int HYSTRIX_TIMEOUT = 10000;

    private RestTemplate restTemplate;

    @Before
    public void init() {
        HttpComponentsClientHttpRequestFactory httpRequestFactory = new HttpComponentsClientHttpRequestFactory();
        httpRequestFactory.setReadTimeout(HTTP_TIMEOUT);
        restTemplate = new RestTemplate(httpRequestFactory);
    }

    @Test
    public void test() {
        //Create HystrixCommand.Setter
        HystrixCommandProperties.Setter propSetter = HystrixCommandProperties.Setter()
                .withExecutionTimeoutEnabled(true)  //Open the timeout mechanism
                .withExecutionTimeoutInMilliseconds(HYSTRIX_TIMEOUT)    //Setting timeout time
                .withExecutionIsolationStrategy(HystrixCommandProperties.ExecutionIsolationStrategy.THREAD) //Thread isolation
                .withExecutionIsolationThreadInterruptOnTimeout(true);  //Setting timeout interrupt threads here has no practical effect.
        HystrixCommand.Setter setter = HystrixCommand.Setter
                .withGroupKey(HystrixCommandGroupKey.Factory.asKey("queryData"))
                .andCommandPropertiesDefaults(propSetter);

        //Create HystrixCommand through Setter
        HystrixCommand<String> hystrixCommand = new HystrixCommand<String>(setter) {
            @Override
            protected String run() throws Exception {
                //Initiate http requests
                print("send request");
                String result = restTemplate.getForObject("http://127.0.0.1:9001/queryData", String.class);
                print("get response");
                return result;
            }

            @Override
            protected String getFallback() {
                print("fallback");
                return null;
            }
        };
        print("execute command");
        //Implementing HystrixCommand
        String result = hystrixCommand.execute();
        print("get result=" + result);
        //Blocking main thread to prevent program termination
        while (true) {
        }
    }

    private void print(String msg) {
        System.out.println(df.format(new Date()) + " [" + Thread.currentThread().getName() + "]: " + msg);
    }
}
Test scenario 1: Neither RestTemplate nor HystrixCommand timed out

Parameter settings:

  • RestTemplate timeout > interface response time (5s), Hystrix timeout > interface response time (5s)

  • HTTP_TIMEOUT and HYSTRIX_TIMEOUT are both set to 10s

Output results:

  • The main thread creates the HystrixCommand and executes it, and the Hystrix creation sub-thread initiates the http request and receives the response in 5 seconds. Finally, the main thread receives the correct response.

Test scenario 2: RestTemplate timeout, HystrixCommand no timeout

Parameter settings:

  • RestTemplate timeout < interface response time (5s), Hystrix timeout > interface response time (5s)

  • HTTP_TIMEOUT is set to 3s and HYSTRIX_TIMEOUT to 10s

Output results:

  • The whole process is as follows: the main thread creates HystrixCommand and executes, Hystrix creates sub-threads to initiate http requests, after 3 seconds, HTTP requests timeout and enter fallback method. Finally, the main thread receives the result null.

Test scenario 3: RestTemplate does not timeout, HystrixCommand timeout

Parameter settings:

  • RestTemplate timeout > interface response time (5s), Hystrix timeout < interface response time (5s)

  • HTTP_TIMEOUT is set to 10s and HYSTRIX_TIMEOUT to 3s

Output results:

  • The whole process is: the main thread creates HystrixCommand and executes, Hystrix creates sub-threads to initiate http requests, Hystrix timeout after 3 seconds, and the HystrixTimer thread calls fallback method. Finally, the main thread receives the result null.

  • Note, however, that when the main method receives the return result, the thread that initiates the http request still receives the request after 5s. That is to say, even if HystrixCommand expires, the actual sub-thread that initiated the request will not end, even if the withExecution Isolation ThreadInterruptOnTimeout (true) is set up.

Bottom mechanism

I refer to the source code parsing related articles of Hystrix, and read some source code of Hystrix to understand:

During the execution of HystrixCommand, there are two threads, one is the HystrixCommand task execution thread, and the other is the thread waiting to determine the timeout for HystrixCommand (HystrixTimer). When one of the threads completes its own logic, it tries to replace the status of HystrixCommand (CAS), as long as any thread labels HystrixCommand, it means the end of the timeout decision.

  • If the task execution thread completes first, status is set to complete. When the timeout listener thread reaches the timeout time, it finds that status has been marked as completion state and terminates directly. (corresponding to scenarios 1 and 2 above)

  • If the timeout listener thread reaches the timeout point first, it sets status to timeout, at which point HystrixCommand executes the process in fallback while the task execution thread is still running until its process terminates. (corresponding to scenario 3 above)

Flow chart

Combining with the underlying principles, the flow charts of the above three scenarios are simply drawn for easy understanding.

1. Normal return without timeout

2. Task request timeout

3.HystrixCommand timeout


Keywords: Java Spring SpringBoot

Added by karnul on Thu, 05 Sep 2019 10:32:02 +0300