一场 HttpClient 调用未关闭流引发的问题

2023-03-13
江西
本文字数：11365 字
阅读完需：约 37 分钟

最近生产环境出现了一个问题,就是 Job 服务日志好端端的不打印日志了,服务也没有挂, 现在将此次问题解决过程记录下来~

1 问题描述

生产环境有一台 Job 服务器，是专门用来跑所有定时任务的,然后有一天发现定时任务好像没有执行,所以上 Job 服务器查看日志,结果发现的情况是:最后打印的是昨天晚上九点半的,到我看的时候就一直没有日志,没有日志就没有执行 Job；当时为了快速解决问题就重启了服务器,Job 就正常执行了；后来第二天上去看的时候居然又停止了, 但是 Job 的 JVM 是还在的,并没有挂掉,就是没有日志，看起来就是被阻塞了一样;这个时候又把生成环境重启让他先正常执行,然后立马去测试环境看看能不能重现, 结果测试环境的日志也是一样

问题代码

//允许异步执行  Schedule@EnableAsync@Componentpublic class TestSchedule {    private static final Logger LOGGER = LoggerFactory.getLogger(LotterySchedule.class);
    // 使用线程池myAsync来执行这个Job    @Async("myAsync")    @Scheduled(cron = "0/1 * * * * ?")    public void testDoGet(){        LOGGER.info("\ntestDoGet:"+Thread.currentThread());  //业务代码:里面调用了 String json = HttpUtil.doGet(url);来调用第三方接口  HttpUtil.doGet("www.baidu.com")     }
 //这里没有用异步执行,单线程执行  @Scheduled(cron = "0/1 * * * * ?")    public void testPrint(){     LOGGER.info("\ntestPrint:"+Thread.currentThread()); }

}

复制代码

然后看看线程池的代码

@Configuration@EnableAsyncpublic class ExecutorConfig {
    /** Set the ThreadPoolExecutor's core pool size. */    private int corePoolSize = 10;    /** Set the ThreadPoolExecutor's maximum pool size. */    private int maxPoolSize = 25;    /** Set the capacity for the ThreadPoolExecutor's BlockingQueue. */    private int queueCapacity = 10;

    @Bean    public Executor myAsync() {        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();        executor.setCorePoolSize(corePoolSize);        executor.setMaxPoolSize(maxPoolSize);        executor.setQueueCapacity(queueCapacity);        executor.setThreadNamePrefix("MyJobExecutor-");
        // rejection-policy：当pool已经达到max size的时候，如何处理新任务        // CALLER_RUNS：不在新线程中执行任务，而是有调用者所在的线程来执行        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());        executor.initialize();        return executor;    }}

复制代码

1.查看 JVM 情况

Linux使用jstat命令查看jvm的GC情况

jps 查询 Jvm 进程号查询 Jvm jstat -gc 21738 5000 发现 Jvm 好像没有出现频繁 GC,GC 处理异常的情况，而且 Jvm 启动也配置了:+HeapDumpOnOutOfMemoryError;但是没有看到内存溢出的 Dump 文件;排除 Jvm 异常的情况

2.查看线程栈分析

jps 查询 Jvm 进程号 jstack -l 22741 查询线程栈信息

"MyJobExecutor-2" #25 prio=5 os_prio=31 tid=0x00007fc7f7374800 nid=0xa203 waiting on condition [0x0000700004def000]   java.lang.Thread.State: WAITING (parking)        at sun.misc.Unsafe.park(Native Method)        - parking to wait for  <0x0000000742196c58> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)        at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:380)        at org.apache.http.pool.AbstractConnPool.access$200(AbstractConnPool.java:69)        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:246)        - locked <0x00000007969b6910> (a org.apache.http.pool.AbstractConnPool$2)        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:193)        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:303)        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:279)        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:191)        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)        at com.xxx.util.HttpUtil.doGet(HttpUtil.java:97)        at com.xxx.util.HttpUtil.doGet(HttpUtil.java:70)  省略        at        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)        at org.springframework.transaction.interceptor.TransactionInterceptor$Lambda$392/226041624.proceedWithInvocation(Unknown Source)        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:294)        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)        at com.bfc.service.impl.LotteryHbkuai3MainServiceImpl$EnhancerBySpringCGLIB$4d3de61.publishPreByJob(<generated>)        at com.bfc.job.LotterySchedule.publishByJob(LotterySchedule.java:45)        at com.bfc.job.LotterySchedule$FastClassBySpringCGLIB$75ac0373.invoke(<generated>)        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)        at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115)        at org.springframework.aop.interceptor.AsyncExecutionInterceptor$Lambda$391/524684837.call(Unknown Source)        at java.util.concurrent.FutureTask.run(FutureTask.java:266)        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)        at java.lang.Thread.run(Thread.java:745)
   Locked ownable synchronizers:        - <0x0000000741db91a0> (a java.util.concurrent.ThreadPoolExecutor$Worker)
"MyJobExecutor-1" #24 prio=5 os_prio=31 tid=0x00007fc7f5ff7800 nid=0xa403 waiting on condition [0x0000700004cec000]   java.lang.Thread.State: WAITING (parking)        at sun.misc.Unsafe.park(Native Method)        - parking to wait for  <0x0000000742196c58> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)        at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:380)        at org.apache.http.pool.AbstractConnPool.access$200(AbstractConnPool.java:69)        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:246)        - locked <0x00000007968318d8> (a org.apache.http.pool.AbstractConnPool$2)        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:193)        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:303)        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:279)        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:191)        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)        at com.xxx.util.HttpUtil.doGet(HttpUtil.java:97)        at com.xxx.util.HttpUtil.doGet(HttpUtil.java:70)        at         省略        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)        at org.springframework.transaction.interceptor.TransactionInterceptor$Lambda$392/226041624.proceedWithInvocation(Unknown Source)        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:294)        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)        at com.bfc.service.impl.LotteryHbkuai3MainServiceImpl$EnhancerBySpringCGLIB$4d3de61.publishPreByJob(<generated>)        at com.bfc.job.LotterySchedule.publishByJob(LotterySchedule.java:45)        at com.bfc.job.LotterySchedule$FastClassBySpringCGLIB$75ac0373.invoke(<generated>)        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)        at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115)        at org.springframework.aop.interceptor.AsyncExecutionInterceptor$Lambda$391/524684837.call(Unknown Source)        at java.util.concurrent.FutureTask.run(FutureTask.java:266)        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)        at java.lang.Thread.run(Thread.java:745)
   Locked ownable synchronizers:        - <0x0000000741da4a28> (a java.util.concurrent.ThreadPoolExecutor$Worker)

复制代码

分析问题

通过栈信息可以发现,基本上所有的线程都被阻塞了,都在 wait;重点看 MyJobExecutor-" 开头的线程都在 wait 同一个 lock,并且代码发生的地方是 HttpUtil.doGet 方法;这么看来好像是 HttpUtil.doGet 发生了阻塞;然后分析问题代码,结果发现这个代码是这样的

  private static PoolingHttpClientConnectionManager connMgr;    private static RequestConfig requestConfig;    private static final int MAX_TIMEOUT = 7000;    private static CloseableHttpClient httpClient ;    static {        // 设置连接池        connMgr = new PoolingHttpClientConnectionManager();        // 设置连接池大小        connMgr.setMaxTotal(8);        connMgr.setDefaultMaxPerRoute(connMgr.getMaxTotal());        RequestConfig.Builder configBuilder = RequestConfig.custom();        // 设置连接超时        configBuilder.setConnectTimeout(MAX_TIMEOUT);        // 设置读取超时        configBuilder.setSocketTimeout(MAX_TIMEOUT);        // 设置从连接池获取连接实例的超时        configBuilder.setConnectionRequestTimeout(MAX_TIMEOUT);        // 在提交请求之前 测试连接是否可用        configBuilder.setStaleConnectionCheckEnabled(true);        requestConfig = configBuilder.build();        httpClient = HttpClients.custom().setConnectionManager(connMgr).build();    }/**     * 发送 GET 请求（HTTP），不带输入数据     * @param url     * @return     */    public static String doGet(String url) {        return doGet(url, new HashMap<String, Object>());    }
    /**     * 发送 GET 请求（HTTP），K-V形式     * @param url     * @param params     * @return     */    public static String doGet(String url, Map<String, Object> params) {        String apiUrl = url;        StringBuffer param = new StringBuffer();        int i = 0;        for (String key : params.keySet()) {            if (i == 0) {                param.append("?");            }else {                param.append("&");            }            param.append(key).append("=").append(params.get(key));            i++;        }        apiUrl += param;        String result = null;       // HttpClient httpclient = new DefaultHttpClient();        try {            HttpGet httpPost = new HttpGet(apiUrl);            HttpResponse response = httpClient.execute(httpPost);            HttpEntity entity = response.getEntity();            if (entity != null) {                InputStream instream = entity.getContent();                result = IOUtils.toString(instream, "UTF-8");            }        } catch (IOException e) {            e.printStackTrace();        }        return result;    }    }

复制代码

注意看这个 doGet(); 流没有关闭........因为流没有关闭,这个 HttpClient 连接池的连接一直没有回收回去,后面的线程又一直在调用这个 doGet 方法;但是又获取不到连接,所以就一直阻塞在哪里,直到连接超时HttpClient内部三个超时时间的区别然后 myAsync 这个线程池的线程也是有限的, Schedule 每秒都在执行,很快线程不够用了,然后就阻塞了 testDoGet 这个定时任务了；为了确认是流未关闭的问题我们可以看看服务器的 TCP 连接netstat -anp | grep 进程号

可以看到有很多的 80 连接端口处于 CLOSE_WAIT 状态的; CLOSE_WAIT状态的原因与解决方法

问题的原因找到了,那么解决的方法就很简单了,把 HttpClient 的连接的流关闭掉就行了

  HttpEntity entity = response.getEntity();            httpStr = EntityUtils.toString(entity, "UTF-8");

复制代码

EntityUtils.toString 方法里面有关闭流的;这样改了就没有问题了;好像问题是解决了但是怎么觉得哪里不对呢？？

定时任务 public void testDoGet()是用的线程池异步执行

定时任务public void testPrint()是单线程执行的;讲道理就算testDoGet阻塞了,也不应该把testPrint阻塞了吧?再看 jstack -l 信息

"pool-3-thread-1" #23 prio=5 os_prio=31 tid=0x00007ff371c86800 nid=0x5803 waiting on condition [0x0000700004776000]   java.lang.Thread.State: WAITING (parking)        at sun.misc.Unsafe.park(Native Method)        - parking to wait for  <0x00000007421cb160> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)        at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:380)        at org.apache.http.pool.AbstractConnPool.access$200(AbstractConnPool.java:69)        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:246)        - locked <0x0000000797dbc900> (a org.apache.http.pool.AbstractConnPool$2)        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:193)        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:303)        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:279)        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:191)        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)        at com.xxx.util.HttpUtil.doGet(HttpUtil.java:97)        at com.xxx.util.HttpUtil.doGet(HttpUtil.java:70)        at com.bfc.job.LotterySchedule$FastClassBySpringCGLIB$75ac0373.invoke(<generated>)        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)        at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115)        at org.springframework.aop.interceptor.AsyncExecutionInterceptor$Lambda$401/476029857.call(Unknown Source)        at java.util.concurrent.FutureTask.run(FutureTask.java:266)        at java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(ThreadPoolExecutor.java:2022)        at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823)        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369)        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134)        at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.submit(ThreadPoolTaskExecutor.java:341)        at org.springframework.aop.interceptor.AsyncExecutionAspectSupport.doSubmit(AsyncExecutionAspectSupport.java:284)        at org.springframework.aop.interceptor.AsyncExecutionInterceptor.invoke(AsyncExecutionInterceptor.java:129)        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)        at org.springframework.aop.framework.CglibAopProxysun.reflect.GeneratedMethodAccessor96.invoke(Unknown Source)        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)        at java.lang.reflect.Method.invoke(Method.java:498)        at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84)        at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)        at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:93)        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)        at java.util.concurrent.FutureTask.run(FutureTask.java:266)        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)        at java.lang.Thread.run(Thread.java:745)

复制代码

初步分析这个信息，说明 pool-3-thread-1(就是 Schedule 的主线程) 也去执行了我们的testDoGet;

myAsync 线程池不够用了,用了主线程来执行这个定时任务,然后又阻塞了,所以就阻塞了所有的其他定时任务

什么鬼?为什么会这样,然后翻过去看 myAsync 的线程池代码

  @Bean    public Executor myAsync() {        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();        executor.setCorePoolSize(corePoolSize);        executor.setMaxPoolSize(maxPoolSize);        executor.setQueueCapacity(queueCapacity);        executor.setThreadNamePrefix("MyJobExecutor-");
        // rejection-policy：当pool已经达到max size的时候，如何处理新任务        // CALLER_RUNS：不在新线程中执行任务，而是有调用者所在的线程来执行        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());        executor.initialize();        return executor;    }