多线程任务下FileUtils.copyURLToFile引起的线程阻塞问题及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<500&&imgHeight<500){
FileUtils.deleteQuietly(f);
return null;
}
return imgWidth + "," + imgHeight;
} catch (Exception e) {
return null;
}
}
问题：
执行了很久很久，理论上如果任务都执行完成的话线程池会销毁，主线程会结束，可是结果是没有。第一想法是肯定哪里死锁了。于是打开Java VisualVM查看。
可以看到pool-4（也即我们自己的线程）大部分处于等待状态。
Jstack调出所有的stack信息：
"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 <0x0000000780faa230> (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 <0x0000000780faa230> (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等待状态。 都在等待<0x0000000780faa230> (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 <0x00000007810fa6c0> (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 <0x00000007810fa770> (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: - <0x00000007810e2060> (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, 感谢原作者分享。