多线程任务下FileUtils.copyURLToFile引起的线程阻塞问题及Java
- WBOY原创
- 2016-06-07 16:39:326412浏览
导读：Java多线程开发给程序带来好处的同时，由于多线程程序导致的问题也越来越多，而且对问题的查找和分析解决对于菜鸟程序原来是是件头疼的事。下面我就项目中使用多线程开发程序过程中遇到的问题做详细的分析和解决思路的分享。本人也属菜鸟，忘大神指点
导读：Java多线程开发给程序带来好处的同时，由于多线程程序导致的问题也越来越多，而且对问题的查找和分析解决对于菜鸟程序原来是是件头疼的事。下面我就项目中使用多线程开发程序过程中遇到的问题做详细的分析和解决思路的分享。本人也属菜鸟，忘大神指点。
项目描述：
工作中要编写一份程序用于爬取某某网站上的大量图片。从HBase里面遍历出所有的爬取任务，开启固定大小的线程池Executors.newFixedThreadPool(100)，提交线程，线程每个线程做的事情是使用FileUtils.copyURLToFile去从Url下载图片，保存到本地。详细代码如下：
主线程:
public static void getAllRecord (String tableName,String prefix,String dir) {
HTable table = null;
try{
table = new HTable(conf, tableName);
Scan s = new Scan();
s.setFilter(new PrefixFilter(prefix.getBytes()));
ResultScanner ss = table.getScanner(s);
ExecutorService executor = Executors.newFixedThreadPool(100);
for(Result r:ss){
try {
TimeUnit.SECONDS.sleep(2);
} catch (InterruptedException e) {
// TODO Auto-generated catch block
e.printStackTrace();
}
Thread task = new Thread(new DownLoadPicTask(r,dir,tableName));
executor.submit(task);
}
executor.shutdown();
} catch (IOException e){
}finally{
...关闭资源
}
}
任务线程：
public static String downloadFromUrl(String url,String dir,String cityName,String id) {
try {
URL httpurl = new URL(url);
String fileName = getFileNameFromUrl(url);
System.out.println(fileName);
File f = new File(dir + File.separator+ cityName+ File.separator+id+File.separator+ fileName);
FileUtils.copyURLToFile(httpurl, f);
FileInputStream fis = new FileInputStream(f);
BufferedImage bufferedImg = ImageIO.read(fis);
int imgWidth = bufferedImg.getWidth();
int imgHeight = bufferedImg.getHeight();
bufferedImg = null;
fis.close();
if(imgWidth
<h3>问题：</h3>
<p>执行了很久很久，理论上如果任务都执行完成的话线程池会销毁，主线程会结束，可是结果是没有。第一想法是肯定哪里死锁了。于是打开Java VisualVM查看。</p>
<p><img alt="多线程问题" class="aligncenter size-full wp-image-1083" style="max-width:90%" src="http://www.geedoo.info/wp-content/uploads/2014/10/%E5%A4%9A%E7%BA%BF%E7%A8%8B%E9%97%AE%E9%A2%98.jpg" style="max-width:90%"></p>
<p>可以看到pool-4（也即我们自己的线程）大部分处于<span style="color: #ff6600;">等待状态</span>。</p>
<p><span style="color: #000000;">Jstack调出所有的stack信息：</span></p>
<pre class="brush:php;toolbar:false">
"pool-4-thread-21" prio=6 tid=0x000000000d662800 nid=0x2364 waiting on condition [0x000000001175f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
"pool-4-thread-20" prio=6 tid=0x000000000d662000 nid=0x32f8 waiting on condition [0x00000000114ef000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
上述大概有100个线程的stack信息，这里只列出两条。
关于虚拟机的stack信息分析可以参考文章：《三个实例演示 Java Thread Dump 日志分析》
初步分析：
大部分线程(主：“大部分”，这里没说全部的原因后面跟着我的分析思路会说明)处于WAITING等待状态。 都在等待 (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)这么一个资源。
既然线程们都在等待某个资源，那么这个资源是什么呢？
带着疑问我们搜索了整个stack信息，发现只有pool-4-thread-**线程在同样的位置有这个0x0000000780faa230东西。然后这个东西是什么呢？
AbstractQueuedSynchronizer提供了一个基于FIFO队列，可以用于构建锁或者其他相关同步装置的基础框架。
Condition是一个条件功能的class，必须放在Lock代码块内，如同wait,notify方法放在synchronized块一样。
Condition的(await,signal)与object的(wait,notify)相比，提供了更为通用和灵活的解决方案，可以让多种条件的线程之间相互通信。
更多详细关于AbstractQueuedSynchronizer的可以参看：
《AbstractQueuedSynchronizer的介绍和原理分析》
《AbstractQueuedSynchronizer》
说了这么多，参考了大量的上述文献，还是一头雾水是不是？
线程处于闲等状态，不能获取某个资源/条件（java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject），那么肯定是被某个线程占用了。
FileUtils.copyURLToFile的问题
基于这么个思路，我在次查看了所有线程状态，终于发现在100个线程中被我遗漏的3个正在运行的线程：
其中之一如下：
"pool-4-thread-15" prio=6 tid=0x000000000d65e000 nid=0x28e4 runnable [0x00000000109fe000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:152) at java.net.SocketInputStream.read(SocketInputStream.java:122) at java.io.BufferedInputStream.fill(BufferedInputStream.java:235) at java.io.BufferedInputStream.read1(BufferedInputStream.java:275) at java.io.BufferedInputStream.read(BufferedInputStream.java:334) - locked (a java.io.BufferedInputStream) at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:687) at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:633) at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323) - locked (a sun.net.www.protocol.http.HttpURLConnection) at java.net.URL.openStream(URL.java:1037) at org.apache.commons.io.FileUtils.copyURLToFile(FileUtils.java:1460) at com.esf.crawler.bootsStrap.DownLoadPicTask.downloadFromUrl(DownLoadPicTask.java:139) at com.esf.crawler.bootsStrap.DownLoadPicTask.run(DownLoadPicTask.java:101) at java.lang.Thread.run(Thread.java:745) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) Locked ownable synchronizers: - (a java.util.concurrent.ThreadPoolExecutor$Worker)
没错！！！这就是罪魁祸首，这3个线程正处于运行状态（RUNNABLE）。
根据stack信息我们可以发现现在正在执行下载操作里的FileUtils.copyURLToFile方法，而该方法在读取socket流而没有结束（at java.net.SocketInputStream.read(SocketInputStream.java:152)）
问题应该就是这里了！
那为什么读取不会结束呢？网络读取如果不能完成应该超时退出啊。带着这个问题我打开了下载网络图片的方法（见上面）。
FileUtils.copyURLToFile(httpurl, f);
翻看FileUtils.copyURLToFile的api：
public static void copyURLToFile(URL source,File destination)throws IOException public static void copyURLToFile(URL source,File destination,int connectionTimeout,int readTimeout)throws IOException
可以看到我使用的是第一个方法。
它有一个警告：
Warning: this method does not set a connection or read timeout and thus might block forever. Use copyURLToFile(URL, File, int, int) with reasonable timeouts to prevent this.
也即是如果没有设置连接超时和读超时时间的话，可能会由于某些异常而永久阻塞。
那好吧，改成有超时设置的函数。
重新执行！结果还是不是我预想的>_
HBase超时
重新启动后一段时间后100个线程还是全部休眠，参看debug日志，发现下面异常：
Exception in thread "main" java.lang.RuntimeException: org.apache.hadoop.hbase.client.ScannerTimeoutException: 200243ms passed since the last invocation, timeout is currently set to 60000 at org.apache.hadoop.hbase.client.AbstractClientScanner$1.hasNext(AbstractClientScanner.java:94) at com.esf.crawler.bootsStrap.AjkPicDownload.getAllRecord(AjkPicDownload.java:32) at com.esf.crawler.bootsStrap.AjkPicDownload.main(AjkPicDownload.java:75) Caused by: org.apache.hadoop.hbase.client.ScannerTimeoutException: 200243ms passed since the last invocation, timeout is currently set to 60000 at org.apache.hadoop.hbase.client.ClientScanner.next(ClientScanner.java:370) at org.apache.hadoop.hbase.client.AbstractClientScanner$1.hasNext(AbstractClientScanner.java:91) ... 2 more Caused by: org.apache.hadoop.hbase.UnknownScannerException: org.apache.hadoop.hbase.UnknownScannerException: Name: 1679, already closed? at org.apache.hadoop.hbase.regionserver.HRegionServer.scan(HRegionServer.java:3053) at org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:29497) at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2012) at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:98) at org.apache.hadoop.hbase.ipc.SimpleRpcScheduler.consumerLoop(SimpleRpcScheduler.java:168) at org.apache.hadoop.hbase.ipc.SimpleRpcScheduler.access$000(SimpleRpcScheduler.java:39) at org.apache.hadoop.hbase.ipc.SimpleRpcScheduler$1.run(SimpleRpcScheduler.java:111) at java.lang.Thread.run(Thread.java:745) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:526) at org.apache.hadoop.ipc.RemoteException.instantiateException(RemoteException.java:106) at org.apache.hadoop.ipc.RemoteException.unwrapRemoteException(RemoteException.java:95) at org.apache.hadoop.hbase.protobuf.ProtobufUtil.getRemoteException(ProtobufUtil.java:285) at org.apache.hadoop.hbase.client.ScannerCallable.call(ScannerCallable.java:204) at org.apache.hadoop.hbase.client.ScannerCallable.call(ScannerCallable.java:59) at org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithRetries(RpcRetryingCaller.java:114) at org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithRetries(RpcRetryingCaller.java:90) at org.apache.hadoop.hbase.client.ClientScanner.next(ClientScanner.java:354) ... 3 more Caused by: org.apache.hadoop.hbase.ipc.RemoteWithExtrasException(org.apache.hadoop.hbase.UnknownScannerException): org.apache.hadoop.hbase.UnknownScannerException: Name: 1679, already closed? at org.apache.hadoop.hbase.regionserver.HRegionServer.scan(HRegionServer.java:3053) at org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:29497) at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2012) at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:98) at org.apache.hadoop.hbase.ipc.SimpleRpcScheduler.consumerLoop(SimpleRpcScheduler.java:168) at org.apache.hadoop.hbase.ipc.SimpleRpcScheduler.access$000(SimpleRpcScheduler.java:39) at org.apache.hadoop.hbase.ipc.SimpleRpcScheduler$1.run(SimpleRpcScheduler.java:111) at java.lang.Thread.run(Thread.java:745) at org.apache.hadoop.hbase.ipc.RpcClient.call(RpcClient.java:1453) at org.apache.hadoop.hbase.ipc.RpcClient.callBlockingMethod(RpcClient.java:1657) at org.apache.hadoop.hbase.ipc.RpcClient$BlockingRpcChannelImplementation.callBlockingMethod(RpcClient.java:1715) at org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$BlockingStub.scan(ClientProtos.java:29900) at org.apache.hadoop.hbase.client.ScannerCallable.call(ScannerCallable.java:174) ... 7 more
上述异常是HBase使用的Scan超时，超过了默认的6000的默认值。然后抛出异常，程序终结。也就是不在从HBase的Scaner里遍历出记录，产生任务Task。导致100线程无任务而空等。
原来我在上面程序中加入了线程休眠的代码，导致Scaner的超时。原本使用sleep代码只是为了让任务不要过早启动太多，结果导致的这个异常。
至此大致的问题已经找到了。
总结： 从出现问题到定位，再到分析解决。过程中不免会经过一起看是错误的猜想，我们还是要不同不但的分析推理验证尽可能的想法。一步一查找线索。多线程问题的出现无非就是由于同步，并发等情况下造成的死锁，资源竞争等等。
通过JDK里面提供的工具进行检测和导出相应的堆栈信息。能够分析dump日志里面线程各种状态产生的原因，及找到解决该问题的相应方案。
dump里线程状态大致如下：
- 死锁，Deadlock（重点关注）?
- 执行中，Runnable? ?
- 等待资源，Waiting on condition（重点关注）?
- 等待获取监视器，Waiting on monitor entry（重点关注）
- 暂停，Suspended
- 对象等待中，Object.wait() 或 TIMED_WAITING
- 阻塞，Blocked（重点关注）??
- 停止，Parked
分析出原因后进而定位到相应的代码。改之！！！
参考：
《三个实例演示 Java Thread Dump 日志分析》
《AbstractQueuedSynchronizer的介绍和原理分析》
《AbstractQueuedSynchronizer》
《Java线程池使用说明》
原文地址：多线程任务下FileUtils.copyURLToFile引起的线程阻塞问题及Java虚拟机stac, 感谢原作者分享。