Spring Cloud 之极端续租间隔时间的影响|码代码的陈同学

# Spring Cloud 之极端续租间隔时间的影响

本文基于某环境一个真实Case，它配置了非常极端的续租间隔时间。虽然知道服务注册的基本知识，但未深入了解过，正好基于这个Case学习下。

## 问题现象

先简述下问题现象。

* 日志中大约以几秒一次的频率循环出现 *TimedSupervisorTask 67 task supervisor timed out*
* 摘除流量后，Eden区约800M，Minor GC频率约 **4分钟/次**，GC后对象基本全部回收，Old区基本未增长

错误日志如下图：

![](https://media.chenyongjun.vip/2018/08/28/40c1eca77a5d45de8040e4dbad36aa28.png)

## 续租机制

### heartbeat

在Spring Cloud中，各服务以heartbeat方式向Eureka Server续租以表明自己仍然存活。下面是两个续租相关配置。

* eureka.instance.lease-renewal-interval-in-seconds：续租(心跳)频率，服务定期向Server续租(即表明自己仍然存活，不要把自己剔除掉)
* eureka.instance.lease-expiration-duration-in-seconds：租约有效期，在该时间内若client未更新租约，将剔除client

续租频率默认30s，租约有效期默认90秒，即 **client有3次重试机会**。

###续租源码

`com.netflix.discovery.DiscoveryClient` 启动过程中，会以固定频率向Eureka Server续租。

贴纯代码很不友好，画了个简图，再结合代码解释下。

![](https://media.chenyongjun.vip/2018/08/28/4289bac5d05d40c9bac432908468c02e.png)

> TimedSupervisorTask 和 HeartbeatThread 都实现了Runnable接口

续租很简单，用了JUC的线程池，首先用 **scheduler** 管理 **TimedSupervisorTask**，然后 TimedSupervisorTask利用 **executor** 来submit心跳线程 **HeartbeatThread**，心跳线程以 **HTTP请求** 的方式向Eureka Server续租。

若HeartbeatThread执行超时，则进入 **超时处理逻辑**：即过一小会再执行心跳线程。

到底过多久再执行？延迟时间*2。延时时间初始值就是**续租间隔时间(renewalIntervalInSecs)**。 假设renewalIntervalInSecs设置为10秒，那第一次超时后将等待20秒再尝试续约，第二次超时后将等待40秒再尝试续约，以此类推。若续约成功，延迟时间将恢复为renewalIntervalInSecs。

了解以上逻辑后，再反向看源码。

HeartbeatThread是DiscoveryClient的内部类，向Eureka Server发送HTTP请求进行续约。

```java
private class HeartbeatThread implements Runnable {
    public void run() {
        if (renew()) {
            lastSuccessfulHeartbeatTimestamp = System.currentTimeMillis();
        }
    }
    
    // 伪代码,有删减
	boolean renew() {
	    try {
	        httpResponse = sendHeartBeat(应用名, 应用ID, 应用info); // HTTP请求
	        if (httpResponse.getStatusCode() == 404) {
	            return register();
	        }
	        return httpResponse.getStatusCode() == 200;
	    } catch (Throwable e) {
	        return false;
	    }
	}
}
```

schedule TimedSupervisorTask来监控HeartbeatThread，如果超时则执行超时处理逻辑；没超时则由HeartbeatThread正常处理即可。

```java
// Heartbeat timer
scheduler.schedule(
        new TimedSupervisorTask(
                "heartbeat",
                scheduler,
                heartbeatExecutor,
                renewalIntervalInSecs,
                TimeUnit.SECONDS,
                expBackOffBound,
                new HeartbeatThread()
        ),
        renewalIntervalInSecs, TimeUnit.SECONDS);
```

TimedSupervisorTask这个任务代码如下，主要看下超时处理和`finally`中的重新schedule(有较大删减，仅保留必要代码)。

```java
public class TimedSupervisorTask extends TimerTask {
    public TimedSupervisorTask(...) {
        this.scheduler = scheduler; 
        this.executor = executor;
        this.timeoutMillis = timeUnit.toMillis(timeout);
        this.task = task; //就是HeartbeatThread
        this.delay = new AtomicLong(timeoutMillis); // 延时时间
        this.maxDelay = timeoutMillis * expBackOffBound;
    }

public void run() {
        Future future = null;
        try {
            future = executor.submit(task);
            // 完成心跳或超时
            future.get(timeoutMillis, TimeUnit.MILLISECONDS);  
            delay.set(timeoutMillis); 
        } catch (TimeoutException e) {
            logger.error("task supervisor timed out", e);
            long currentDelay = delay.get();
            long newDelay = Math.min(maxDelay, currentDelay * 2);
            // 延时时间加倍
            delay.compareAndSet(currentDelay, newDelay);
        } finally {
            if (!scheduler.isShutdown()) {
                // 重新schedule心跳任务
                scheduler.schedule(this, delay.get(), TimeUnit.MILLISECONDS);
            }
        }
    }
```

heartbeatExecutor是JUC中的Executor，不特别介绍。

```java
ThreadPoolExecutor heartbeatExecutor = new ThreadPoolExecutor(
        1, clientConfig.getHeartbeatExecutorThreadPoolSize(), 0, TimeUnit.SECONDS,
        new SynchronousQueue<Runnable>(),
        new ThreadFactoryBuilder()
                .setNameFormat("DiscoveryClient-HeartbeatExecutor-%d")
                .setDaemon(true)
                .build()
```

scheduler这个线程池用来管理TimedSupervisorTask。

```java
ScheduledExecutorService scheduler = Executors.newScheduledThreadPool(2,
        new ThreadFactoryBuilder()
                .setNameFormat("DiscoveryClient-%d")
                .setDaemon(true)
                .build());
```

## 回归问题

### 续租配置

现在，我们回归问题现象。先看看问题应用的续租时间(renewalIntervalInSecs)配置：

```properties
eureka.instance.lease-renewal-interval-in-seconds=1
```

**是的，就是1秒，不要问我为什么，我也不知道！**

现在，至少可以确定：**应用在高频续租**

### 为何TimeoutException

TimedSupervisorTask设定的超时时间是？看看时间监控伙计的timeout属性：

```java
public TimedSupervisorTask(String name, ScheduledExecutorService scheduler, ThreadPoolExecutor executor,int timeout, TimeUnit timeUnit, int expBackOffBound, Runnable task) 
```

**timeout**配置是new TimedSupervisorTask()时传进来的，使用的是**renewalIntervalInSecs**。好了，是一秒！在内网，正常来说1秒也是够的，但因各种情况总是免不了会超时，且HTTP超时时间设置为1秒的也是少之又少。

```java
scheduler.schedule(
        new TimedSupervisorTask(
                "heartbeat",
                scheduler,
                heartbeatExecutor,
                renewalIntervalInSecs,
                TimeUnit.SECONDS,
                expBackOffBound,
                new HeartbeatThread()
        ),
        renewalIntervalInSecs, TimeUnit.SECONDS);
```

现在，出现 TimeoutException:  *task supervisor timed out* 就比较清楚了。

想本地重现超时异常的话，在续租renew()中加个断点，模拟下超时，就可以抛出该异常。

### 高频续租对GC的影响

在摘掉应用流量后，800M的Eden区在4分钟内被耗光。一下也找不到原因，在本地创建了Eureka Server和Client两个简单应用，观察Client的内存消耗情况。

为了便于观察，堆内存设置很小，如下：

```shell
-Xmx40m -Xms40m -XX:NewRatio=3  -verbosegc -XX:+PrintGCTimeStamps -Xloggc:/Users/cyj/gcdebug.log
```

接下来做2个对比实验：

**1秒1次心跳**

```shell
# 排除从Eureka Server获取所有实例的影响, 设置为10分钟
eureka.client.registry-fetch-interval-seconds=600
# 1秒一次心跳
eureka.instance.lease-renewal-interval-in-seconds=1
```

丢弃掉应用启动时的频繁GC，最后三次的 GC如下：

```java
2018-08-28T22:35:25.459-0800: 116.798: [GC (Allocation Failure) ...
2018-08-28T22:37:45.378-0800: 256.719: [GC (Allocation Failure) ...
2018-08-28T22:39:26.500-0800: 357.844: [GC (Allocation Failure) ...
```

平均GC时间约 **2分钟/次**。

**不进行心跳**

接下来，将续租间隔、租约时间都设置成10分钟，达到在观察期间不进行心跳的效果。

```properties
eureka.client.registry-fetch-interval-seconds=600
eureka.instance.lease-expiration-duration-in-seconds=600
eureka.instance.lease-renewal-interval-in-seconds=600
```

丢弃掉应用启动时的频繁GC，最后三次的 GC如下：

```java
2018-08-28T22:39:53.806-0800: 7.546: [Full GC (Ergonomics) ...
2018-08-28T22:49:53.416-0800: 607.167: [GC (Allocation Failure) ...
2018-08-28T22:57:37.248-0800: 1071.009: [GC (Allocation Failure) ...
```

碰巧来了次FullGC，但是不影响数据。平均GC时间接近**9分钟/次**的样子。

这两次对比实验虽然不是特别合适，但可以说明**不合理的心跳时间会加速内存的消耗**。

**调整问题应用的结果**

摘除问题应用的流量后，将续租间隔调整为默认值30秒后，该应用的Minor GC频率从 **4分钟/次** 降低到 **13分钟/次**。

扫码或搜索[码代码的陈同学]关注微信公众号, 结伴学习, 一起努力