# Spring Cloud 之极端续租间隔时间的影响 本文基于某环境一个真实Case，它配置了非常极端的续租间隔时间。虽然知道服务注册的基本知识，但未深入了解过，正好基于这个Case学习下。 ## 问题现象 先简述下问题现象。 * 日志中大约以几秒一次的频率循环出现 *TimedSupervisorTask 67 task supervisor timed out* * 摘除流量后，Eden区约800M，Minor GC频率约 **4分钟/次**，GC后对象基本全部回收，Old区基本未增长 错误日志如下图：  ## 续租机制 ### 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续租。 贴纯代码很不友好，画了个简图，再结合代码解释下。  > 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分钟/次**。