Spark job hang up when using alluxio
253 views
Skip to first unread message
Kaiming Wan
Oct 27, 2016, 6:24:25 AM10/27/16
to Alluxio Users, fanb...@gmail.com
Basic Info:
- role of hosts
alluxio1: alluxio master ,alluxio worker,namenodealluxio2: alluxio worker,datanodealluxio3: alluxio worker,datanode
- version info
alluxio:1.3.0JDK:1.8
hadoop :2.7.3(hdfs as UFS)
spark: 2.0.0
I write a job to count how many lines in a 10GB file as follows:
import org.apache.spark.{SparkContext, SparkConf}
/**
*
*
* @author Wan Kaiming on 2016/10/26
* @version 1.0
*/
object LineCopyAndOut{
def main(args:Array[String])
{
val conf = new SparkConf()
conf.setAppName("CopyAndOut").setMaster("spark://10.8.12.16:7077")
val spark = new SparkContext(conf)
//val textFile = spark.textFile("hdfs://10.8.12.18:9000/alluxio/data/linecount/10G.txt")
val textFile = spark.textFile("alluxio://10.8.12.18:39998/linecount/10G.txt")
val counts = textFile.count()
println("总共的行数为："+counts)
}
} I can finish the job without using alluxio. However, when I using alluxio, the job was stuck during the process.
The 10GB file are stored in alluxio with 'round robin policy'
The configuration of
1. spark-env.sh(alluxio2 as a example)
export JAVA_HOME=/home/appadmin/jdk1.8.0_77
export SPARK_HOME=/home/appadmin/spark-2.0.0-bin-without-hadoop
export HADOOP_HOME=/home/appadmin/hadoop-2.7.2
export SPARK_DIST_CLASSPATH=$(/home/appadmin/hadoop-2.7.2/bin/hadoop classpath)
export YARN_CONF_DIR=$HADOOP_HOME/etc/hadoop
export SPARK_LIBARY_PATH=.:$JAVA_HOME/lib:$JAVA_HOME/jre/lib:$HADOOP_HOME/lib/native
export HADOOP_CONF_DIR=$HADOOP_HOME/etc/hadoop
SPARK_MASTER_HOST=10.8.12.16
SPARK_MASTER_WEBUI_PORT=28686
SPARK_LOCAL_DIRS=/home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local
SPARK_WORKER_DIR=/home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/work
SPARK_LOG_DIR=/home/appadmin/spark-2.0.0-bin-without-hadoop/logs
SPARK_WORKER_MEMORY=120g
SPARK_LOCAL_HOSTNAME=sq-hbase2.800best.com2. spark-defaul.conf(alluxio2 as a example)
spark.driver.memory 5g
spark.eventLog.dir hdfs://10.8.12.16:9000/spark-event-log
spark.executor.instances = 12
spark.executor.cores = 9
spark.executor.memory = 30g
spark.driver.extraClassPath=/home/appadmin/spark-2.0.0-bin-without-hadoop/jars/alluxio-core-client-1.3.0-jar-with-dependencies.jar
spark.executor.extraClassPath=/home/appadmin/spark-2.0.0-bin-without-hadoop/jars/alluxio-core-client-1.3.0-jar-with-dependencies.jar
spark.driver.extraJavaOptions -Dalluxio.user.file.write.location.policy.class=alluxio.client.file.policy.RoundRobinPolicy
spark.executor.extraJavaOptions -Dalluxio.user.file.write.location.policy.class=alluxio.client.file.policy.RoundRobinPolicyKaiming Wan
Oct 27, 2016, 6:59:14 AM10/27/16
to Alluxio Users, fanb...@gmail.com
I checked the log of spark executor:
16/10/27 18:56:16 INFO executor.CoarseGrainedExecutorBackend: Started daemon with process name: 30...@sq-hbase2.800best.com 16/10/27 18:56:16 INFO util.SignalUtils: Registered signal handler for TERM 16/10/27 18:56:16 INFO util.SignalUtils: Registered signal handler for HUP 16/10/27 18:56:16 INFO util.SignalUtils: Registered signal handler for INT 16/10/27 18:56:16 WARN util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable 16/10/27 18:56:16 INFO spark.SecurityManager: Changing view acls to: appadmin,root 16/10/27 18:56:16 INFO spark.SecurityManager: Changing modify acls to: appadmin,root 16/10/27 18:56:16 INFO spark.SecurityManager: Changing view acls groups to: 16/10/27 18:56:16 INFO spark.SecurityManager: Changing modify acls groups to: 16/10/27 18:56:16 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(appadmin, root); groups with view permissions: Set(); users with modify permissions: Set(appadmin, root); groups with modify permissions: Set() 16/10/27 18:56:16 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:37822 after 36 ms (0 ms spent in bootstraps) 16/10/27 18:56:16 INFO spark.SecurityManager: Changing view acls to: appadmin,root 16/10/27 18:56:16 INFO spark.SecurityManager: Changing modify acls to: appadmin,root 16/10/27 18:56:16 INFO spark.SecurityManager: Changing view acls groups to: 16/10/27 18:56:16 INFO spark.SecurityManager: Changing modify acls groups to: 16/10/27 18:56:16 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(appadmin, root); groups with view permissions: Set(); users with modify permissions: Set(appadmin, root); groups with modify permissions: Set() 16/10/27 18:56:16 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:37822 after 1 ms (0 ms spent in bootstraps) 16/10/27 18:56:16 INFO storage.DiskBlockManager: Created local directory at /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-456ee17e-ad18-4d09-83cc-b428f58aa769/executor-24d3811b-a4d5-45fa-9258-58637ff2a481/blockmgr-2603f7ad-a81b-46c8-8b79-2ff6867703c3 16/10/27 18:56:16 INFO memory.MemoryStore: MemoryStore started with capacity 15.8 GB 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Connecting to driver: spark://CoarseGrain...@sq-hbase1.800best.com:37822 16/10/27 18:56:17 INFO worker.WorkerWatcher: Connecting to worker spark://Wor...@sq-hbase2.800best.com:56346 16/10/27 18:56:17 INFO client.TransportClientFactory: Successfully created connection to sq-hbase2.800best.com/10.8.12.17:56346 after 2 ms (0 ms spent in bootstraps) 16/10/27 18:56:17 INFO worker.WorkerWatcher: Successfully connected to spark://Wor...@sq-hbase2.800best.com:56346 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Successfully registered with driver 16/10/27 18:56:17 INFO executor.Executor: Starting executor ID 2 on host sq-hbase2.800best.com 16/10/27 18:56:17 INFO util.Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 46561. 16/10/27 18:56:17 INFO netty.NettyBlockTransferService: Server created on sq-hbase2.800best.com:46561 16/10/27 18:56:17 INFO storage.BlockManagerMaster: Registering BlockManager BlockManagerId(2, sq-hbase2.800best.com, 46561) 16/10/27 18:56:17 INFO storage.BlockManagerMaster: Registered BlockManager BlockManagerId(2, sq-hbase2.800best.com, 46561) 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 0 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 1 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 2 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 3 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 4 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 5 16/10/27 18:56:17 INFO executor.Executor: Running task 1.0 in stage 0.0 (TID 1) 16/10/27 18:56:17 INFO executor.Executor: Running task 0.0 in stage 0.0 (TID 0) 16/10/27 18:56:17 INFO executor.Executor: Running task 2.0 in stage 0.0 (TID 2) 16/10/27 18:56:17 INFO executor.Executor: Running task 3.0 in stage 0.0 (TID 3) 16/10/27 18:56:17 INFO executor.Executor: Running task 4.0 in stage 0.0 (TID 4) 16/10/27 18:56:17 INFO executor.Executor: Running task 5.0 in stage 0.0 (TID 5) 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 6 16/10/27 18:56:17 INFO executor.Executor: Running task 6.0 in stage 0.0 (TID 6) 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 7 16/10/27 18:56:17 INFO executor.Executor: Running task 7.0 in stage 0.0 (TID 7) 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 8 16/10/27 18:56:17 INFO executor.Executor: Running task 9.0 in stage 0.0 (TID 8) 16/10/27 18:56:17 INFO executor.Executor: Fetching spark://sq-hbase1.800best.com:37822/jars/aux-sp-count.jar with timestamp 1477565775553 16/10/27 18:56:17 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:37822 after 1 ms (0 ms spent in bootstraps) 16/10/27 18:56:17 INFO util.Utils: Fetching spark://sq-hbase1.800best.com:37822/jars/aux-sp-count.jar to /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-456ee17e-ad18-4d09-83cc-b428f58aa769/executor-24d3811b-a4d5-45fa-9258-58637ff2a481/spark-4f8710e9-1479-4587-99fd-5a9a7d3cfef8/fetchFileTemp3000402121285987072.tmp 16/10/27 18:56:17 INFO util.Utils: Copying /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-456ee17e-ad18-4d09-83cc-b428f58aa769/executor-24d3811b-a4d5-45fa-9258-58637ff2a481/spark-4f8710e9-1479-4587-99fd-5a9a7d3cfef8/7615150421477565775553_cache to /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/work/app-20161027185615-0002/2/./aux-sp-count.jar 16/10/27 18:56:17 INFO executor.Executor: Adding file:/home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/work/app-20161027185615-0002/2/./aux-sp-count.jar to class loader 16/10/27 18:56:17 INFO broadcast.TorrentBroadcast: Started reading broadcast variable 1 16/10/27 18:56:17 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:33187 after 1 ms (0 ms spent in bootstraps) 16/10/27 18:56:17 INFO memory.MemoryStore: Block broadcast_1_piece0 stored as bytes in memory (estimated size 1823.0 B, free 15.8 GB) 16/10/27 18:56:17 INFO broadcast.TorrentBroadcast: Reading broadcast variable 1 took 78 ms 16/10/27 18:56:17 INFO memory.MemoryStore: Block broadcast_1 stored as values in memory (estimated size 2.9 KB, free 15.8 GB) 16/10/27 18:56:17 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.18:39998/linecount/10G.txt:805306368+134217728 16/10/27 18:56:17 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.18:39998/linecount/10G.txt:939524096+134217728 16/10/27 18:56:17 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.18:39998/linecount/10G.txt:268435456+134217728 16/10/27 18:56:17 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.18:39998/linecount/10G.txt:402653184+134217728 16/10/27 18:56:17 INFO broadcast.TorrentBroadcast: Started reading broadcast variable 0 16/10/27 18:56:17 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.18:39998/linecount/10G.txt:1207959552+134217728 16/10/27 18:56:17 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.18:39998/linecount/10G.txt:671088640+134217728 16/10/27 18:56:17 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.18:39998/linecount/10G.txt:536870912+134217728 16/10/27 18:56:17 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.18:39998/linecount/10G.txt:0+134217728 16/10/27 18:56:17 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.18:39998/linecount/10G.txt:134217728+134217728 16/10/27 18:56:17 INFO memory.MemoryStore: Block broadcast_0_piece0 stored as bytes in memory (estimated size 16.6 KB, free 15.8 GB) 16/10/27 18:56:17 INFO broadcast.TorrentBroadcast: Reading broadcast variable 0 took 8 ms 16/10/27 18:56:17 INFO memory.MemoryStore: Block broadcast_0 stored as values in memory (estimated size 202.4 KB, free 15.8 GB) 16/10/27 18:56:18 INFO Configuration.deprecation: mapred.tip.id is deprecated. Instead, use mapreduce.task.id 16/10/27 18:56:18 INFO Configuration.deprecation: mapred.task.is.map is deprecated. Instead, use mapreduce.task.ismap 16/10/27 18:56:18 INFO Configuration.deprecation: mapred.task.id is deprecated. Instead, use mapreduce.task.attempt.id 16/10/27 18:56:18 INFO Configuration.deprecation: mapred.job.id is deprecated. Instead, use mapreduce.job.id 16/10/27 18:56:18 INFO Configuration.deprecation: mapred.task.partition is deprecated. Instead, use mapreduce.task.partition 16/10/27 18:56:18 INFO logger.type: initialize(alluxio://10.8.12.18:39998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.18:39998/linecount/10G.txt 16/10/27 18:56:18 INFO logger.type: initialize(alluxio://10.8.12.18:39998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.18:39998/linecount/10G.txt 16/10/27 18:56:18 INFO logger.type: initialize(alluxio://10.8.12.18:39998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.18:39998/linecount/10G.txt 16/10/27 18:56:18 INFO logger.type: initialize(alluxio://10.8.12.18:39998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.18:39998/linecount/10G.txt 16/10/27 18:56:18 INFO logger.type: initialize(alluxio://10.8.12.18:39998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.18:39998/linecount/10G.txt 16/10/27 18:56:18 INFO logger.type: initialize(alluxio://10.8.12.18:39998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.18:39998/linecount/10G.txt 16/10/27 18:56:18 INFO logger.type: initialize(alluxio://10.8.12.18:39998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.18:39998/linecount/10G.txt 16/10/27 18:56:18 INFO logger.type: initialize(alluxio://10.8.12.18:39998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.18:39998/linecount/10G.txt 16/10/27 18:56:18 INFO logger.type: initialize(alluxio://10.8.12.18:39998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.18:39998/linecount/10G.txt 16/10/27 18:56:18 INFO logger.type: alluxio://10.8.12.18:39998 alluxio://10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: alluxio://10.8.12.18:39998 alluxio://10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: alluxio://10.8.12.18:39998 alluxio://10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: alluxio://10.8.12.18:39998 alluxio://10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: alluxio://10.8.12.18:39998 alluxio://10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: alluxio://10.8.12.18:39998 alluxio://10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: alluxio://10.8.12.18:39998 alluxio://10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: alluxio://10.8.12.18:39998 alluxio://10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: alluxio://10.8.12.18:39998 alluxio://10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Loading Alluxio properties from Hadoop configuration: {} 16/10/27 18:56:18 INFO logger.type: Configuration file /etc/alluxio/alluxio-site.properties loaded. 16/10/27 18:56:18 INFO logger.type: Starting sinks with config: {}. 16/10/27 18:56:18 INFO logger.type: Sinks have already been started. 16/10/27 18:56:18 INFO logger.type: open(alluxio://10.8.12.18:39998/linecount/10G.txt, 65536) 16/10/27 18:56:18 INFO logger.type: open(alluxio://10.8.12.18:39998/linecount/10G.txt, 65536) 16/10/27 18:56:18 INFO logger.type: open(alluxio://10.8.12.18:39998/linecount/10G.txt, 65536) 16/10/27 18:56:18 INFO logger.type: open(alluxio://10.8.12.18:39998/linecount/10G.txt, 65536) 16/10/27 18:56:18 INFO logger.type: open(alluxio://10.8.12.18:39998/linecount/10G.txt, 65536) 16/10/27 18:56:18 INFO logger.type: open(alluxio://10.8.12.18:39998/linecount/10G.txt, 65536) 16/10/27 18:56:18 INFO logger.type: open(alluxio://10.8.12.18:39998/linecount/10G.txt, 65536) 16/10/27 18:56:18 INFO logger.type: open(alluxio://10.8.12.18:39998/linecount/10G.txt, 65536) 16/10/27 18:56:18 INFO logger.type: open(alluxio://10.8.12.18:39998/linecount/10G.txt, 65536) 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.18:39998 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@5ede039d 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@105490bf 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@bff1539 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@3cd2470b 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@1a8d1ea6 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@38884c6e 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@681af022 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@2d1bbe0b 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@62c4539c 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@330f7e04 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@3d455081 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@6781417a 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@53f769d1 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@3f5c27ef 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@3f7156a7 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@3610c03c 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@33dc69d4 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@338316b9 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@4993cb20 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@6a3044c2 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@5f8d60a8 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@2cd5236a 16/10/27 18:56:18 WARN logger.type: Failed to open local stream for block 16777216. /home/kami/ramdisk/alluxioworker/16777216 (Permission denied) 16/10/27 18:56:18 WARN logger.type: Failed to open local stream for block 16777216. /home/kami/ramdisk/alluxioworker/16777216 (Permission denied) 16/10/27 18:56:18 WARN logger.type: Failed to open local stream for block 16777216. /home/kami/ramdisk/alluxioworker/16777216 (Permission denied) 16/10/27 18:56:18 WARN logger.type: Failed to open local stream for block 16777216. /home/kami/ramdisk/alluxioworker/16777216 (Permission denied) 16/10/27 18:56:18 WARN logger.type: Failed to open local stream for block 16777216. /home/kami/ramdisk/alluxioworker/16777216 (Permission denied) 16/10/27 18:56:18 WARN logger.type: Failed to open local stream for block 16777216. /home/kami/ramdisk/alluxioworker/16777216 (Permission denied) 16/10/27 18:56:18 WARN logger.type: Failed to open local stream for block 16777216. /home/kami/ramdisk/alluxioworker/16777216 (Permission denied) 16/10/27 18:56:18 WARN logger.type: Failed to open local stream for block 16777216. /home/kami/ramdisk/alluxioworker/16777216 (Permission denied) 16/10/27 18:56:18 WARN logger.type: Failed to open local stream for block 16777216. /home/kami/ramdisk/alluxioworker/16777216 (Permission denied) 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@2791eeb0 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@1b6b5b99 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@5f4dd6aa 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@242a59f 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@41292294 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@b247131 16/10/27 18:56:18 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@8d7df90 16/10/27 18:56:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@7638175a. 16/10/27 18:56:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@7638175a. 16/10/27 18:56:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@7638175a. 16/10/27 18:56:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@7638175a. 16/10/27 18:56:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@7638175a. 16/10/27 18:56:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@7638175a. 16/10/27 18:56:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@7638175a. 16/10/27 18:56:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@7638175a. 16/10/27 18:56:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@7638175a. 16/10/27 18:56:19 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@617449b2 16/10/27 18:56:19 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@16b95478 16/10/27 18:56:19 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@8fcd709 16/10/27 18:56:19 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@3aaf98ac 16/10/27 18:56:19 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@ec7d112 16/10/27 18:56:28 WARN logger.type: The block with ID 16777216 could not be cached into Alluxio storage. 16/10/27 18:56:30 WARN logger.type: The block with ID 16777216 could not be cached into Alluxio storage. 16/10/27 18:56:31 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@404bf644. 16/10/27 18:56:31 WARN logger.type: The block with ID 16777216 could not be cached into Alluxio storage. 16/10/27 18:56:31 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@565cd28a 16/10/27 18:56:31 WARN logger.type: The block with ID 16777216 could not be cached into Alluxio storage. 16/10/27 18:56:37 INFO logger.type: Clearing unhealthy resource [id: 0x6a730603, /10.8.12.17:27590 :> /10.8.12.16:49998]. 16/10/27 18:56:37 INFO logger.type: Channel closed 16/10/27 18:56:37 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@404bf644. 16/10/27 18:56:37 WARN logger.type: The block with ID 16777216 could not be cached into Alluxio storage. 16/10/27 18:56:37 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@240361a5 16/10/27 18:56:38 INFO logger.type: Clearing unhealthy resource [id: 0xf3a5b988, /10.8.12.17:27605 :> /10.8.12.16:49998]. 16/10/27 18:56:38 INFO logger.type: Channel closed 16/10/27 18:56:38 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@404bf644. 16/10/27 18:56:38 WARN logger.type: The block with ID 16777216 could not be cached into Alluxio storage. 16/10/27 18:56:38 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@6f83be8f 16/10/27 18:56:38 WARN logger.type: The block with ID 16777216 could not be cached into Alluxio storage. 16/10/27 18:56:38 INFO logger.type: Clearing unhealthy resource [id: 0x2eecca8a, /10.8.12.17:27609 :> /10.8.12.16:49998]. 16/10/27 18:56:38 INFO logger.type: Channel closed 16/10/27 18:56:38 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@404bf644. 16/10/27 18:56:39 WARN logger.type: The block with ID 16777216 could not be cached into Alluxio storage. 16/10/27 18:56:39 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@5270ac9e 16/10/27 18:56:39 INFO logger.type: Clearing unhealthy resource [id: 0x65ea04ae, /10.8.12.17:27612 :> /10.8.12.16:49998]. 16/10/27 18:56:39 INFO logger.type: Channel closed 16/10/27 18:56:39 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@404bf644. 16/10/27 18:56:39 WARN logger.type: The block with ID 16777216 could not be cached into Alluxio storage. 16/10/27 18:56:39 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@3f7a31af 16/10/27 18:57:19 INFO logger.type: Block 16777216 exists. 16/10/27 18:57:19 INFO logger.type: Block 16777216 exists. 16/10/27 18:57:19 INFO logger.type: Block 16777216 exists. 16/10/27 18:57:19 INFO logger.type: Block 16777216 exists. 16/10/27 18:57:19 INFO logger.type: Block 16777216 exists. 16/10/27 18:57:19 WARN logger.type: Failed to open local stream for block 16777220. /home/kami/ramdisk/alluxioworker/16777220 (Permission denied) 16/10/27 18:57:19 WARN logger.type: Failed to open local stream for block 16777219. /home/kami/ramdisk/alluxioworker/16777219 (Permission denied) 16/10/27 18:57:19 WARN logger.type: Failed to open local stream for block 16777221. /home/kami/ramdisk/alluxioworker/16777221 (Permission denied) 16/10/27 18:57:19 WARN logger.type: Failed to open local stream for block 16777225. /home/kami/ramdisk/alluxioworker/16777225 (Permission denied) 16/10/27 18:57:19 WARN logger.type: Failed to open local stream for block 16777217. /home/kami/ramdisk/alluxioworker/16777217 (Permission denied) 16/10/27 18:57:19 INFO logger.type: The block with ID 16777219 is already stored in the target worker, canceling the cache request. 16/10/27 18:57:19 INFO logger.type: The block with ID 16777220 is already stored in the target worker, canceling the cache request. 16/10/27 18:57:19 INFO logger.type: The block with ID 16777225 is already stored in the target worker, canceling the cache request. 16/10/27 18:57:19 INFO logger.type: Clearing unhealthy resource [id: 0x374de251, /10.8.12.17:62949]. 16/10/27 18:57:19 INFO logger.type: The block with ID 16777221 is already stored in the target worker, canceling the cache request. 16/10/27 18:57:19 INFO logger.type: Channel closed 16/10/27 18:57:19 INFO logger.type: Clearing unhealthy resource [id: 0x1c45ea6d, /10.8.12.17:62948]. 16/10/27 18:57:19 INFO logger.type: Channel closed 16/10/27 18:57:28 WARN logger.type: The block with ID 16777217 could not be cached into Alluxio storage.
Pei Sun
Oct 27, 2016, 4:57:25 PM10/27/16
to Kaiming Wan, Alluxio Users, Bin Fan
Hi Kaiming,
From the executor log, I see things like "16/10/27 18:57:19 WARN logger.type: Failed to open local stream for block 16777220. /home/kami/ramdisk/alluxioworker/16777220 (Permission denied)"
Do you have permission to access the file?
Can you also send the Alluxio master/worker logs?
Pei
On Thu, Oct 27, 2016 at 3:59 AM, Kaiming Wan <wan...@gmail.com> wrote:
I checked the log of spark executor:
16/10/27 18:56:16 INFO executor.CoarseGrainedExecutorBackend: Started daemon with process name: 30...@sq-hbase2.800best.com 16/10/27 18:56:16 INFO util.SignalUtils: Registered signal handler for TERM 16/10/27 18:56:16 INFO util.SignalUtils: Registered signal handler for HUP 16/10/27 18:56:16 INFO util.SignalUtils: Registered signal handler for INT 16/10/27 18:56:16 WARN util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable 16/10/27 18:56:16 INFO spark.SecurityManager: Changing view acls to: appadmin,root 16/10/27 18:56:16 INFO spark.SecurityManager: Changing modify acls to: appadmin,root 16/10/27 18:56:16 INFO spark.SecurityManager: Changing view acls groups to: 16/10/27 18:56:16 INFO spark.SecurityManager: Changing modify acls groups to: 16/10/27 18:56:16 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(appadmin, root); groups with view permissions: Set(); users with modify permissions: Set(appadmin, root); groups with modify permissions: Set() 16/10/27 18:56:16 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:37822 after 36 ms (0 ms spent in bootstraps) 16/10/27 18:56:16 INFO spark.SecurityManager: Changing view acls to: appadmin,root 16/10/27 18:56:16 INFO spark.SecurityManager: Changing modify acls to: appadmin,root 16/10/27 18:56:16 INFO spark.SecurityManager: Changing view acls groups to: 16/10/27 18:56:16 INFO spark.SecurityManager: Changing modify acls groups to: 16/10/27 18:56:16 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(appadmin, root); groups with view permissions: Set(); users with modify permissions: Set(appadmin, root); groups with modify permissions: Set() 16/10/27 18:56:16 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:37822 after 1 ms (0 ms spent in bootstraps) 16/10/27 18:56:16 INFO storage.DiskBlockManager: Created local directory at /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-456ee17e-ad18-4d09-83cc-b428f58aa769/executor-24d3811b-a4d5-45fa-9258-58637ff2a481/blockmgr-2603f7ad-a81b-46c8-8b79-
2ff6867703c3 16/10/27 18:56:16 INFO memory.MemoryStore: MemoryStore started with capacity 15.8 GB 16/10/27 18:56:17 INFO executor.CoarseGrainedExecutorBackend: Connecting to driver: spark://CoarseGrainedScheduler@sq-hbase1.800best.com:37822 16/10/27 18:56:17 INFO worker.WorkerWatcher: Connecting to worker spark://Worker@sq-hbase2.800best.com:56346
16/10/27 18:56:17 INFO client.TransportClientFactory: Successfully created connection to sq-hbase2.800best.com/10.8.12.17:56346
after 2 ms (0 ms spent in bootstraps) 16/10/27 18:56:17 INFO worker.WorkerWatcher: Successfully connected to spark://Worker@sq-hbase2.800best.com:56346
--
You received this message because you are subscribed to the Google Groups "Alluxio Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to alluxio-users+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Pei Sun
Kaiming Wan
Oct 28, 2016, 2:25:55 AM10/28/16
to Alluxio Users, wan...@gmail.com, fanb...@gmail.com
Hi, Pei Sun
1. executor log:
I found there are many GC and timeout issue. What will cause this problem.
16/10/28 12:46:03 INFO executor.CoarseGrainedExecutorBackend: Started daemon with process name: 86...@sq-hbase1.800best.com 16/10/28 12:46:03 INFO util.SignalUtils: Registered signal handler for TERM 16/10/28 12:46:03 INFO util.SignalUtils: Registered signal handler for HUP 16/10/28 12:46:03 INFO util.SignalUtils: Registered signal handler for INT 16/10/28 12:46:03 WARN util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable 16/10/28 12:46:04 INFO spark.SecurityManager: Changing view acls to: appadmin 16/10/28 12:46:04 INFO spark.SecurityManager: Changing modify acls to: appadmin 16/10/28 12:46:04 INFO spark.SecurityManager: Changing view acls groups to: 16/10/28 12:46:04 INFO spark.SecurityManager: Changing modify acls groups to: 16/10/28 12:46:04 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(appadmin); groups with view permissions: Set(); users with modify permissions: Set(appadmin); groups with modify permissions: Set() 16/10/28 12:46:04 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:5289 after 39 ms (0 ms spent in bootstraps) 16/10/28 12:46:04 INFO spark.SecurityManager: Changing view acls to: appadmin 16/10/28 12:46:04 INFO spark.SecurityManager: Changing modify acls to: appadmin 16/10/28 12:46:04 INFO spark.SecurityManager: Changing view acls groups to: 16/10/28 12:46:04 INFO spark.SecurityManager: Changing modify acls groups to: 16/10/28 12:46:04 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(appadmin); groups with view permissions: Set(); users with modify permissions: Set(appadmin); groups with modify permissions: Set() 16/10/28 12:46:04 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:5289 after 1 ms (0 ms spent in bootstraps) 16/10/28 12:46:04 INFO storage.DiskBlockManager: Created local directory at /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-934e5ce3-343c-4951-a468-44bd1a18d7ad/executor-d1cec12d-0323-40e8-b06d-84ea28570148/blockmgr-5f01a470-58e3-4309-8c76-5f4d6ffe7766 16/10/28 12:46:04 INFO memory.MemoryStore: MemoryStore started with capacity 15.8 GB 16/10/28 12:46:04 INFO executor.CoarseGrainedExecutorBackend: Connecting to driver: spark://CoarseGrain...@sq-hbase1.800best.com:5289 16/10/28 12:46:04 INFO worker.WorkerWatcher: Connecting to worker spark://Wor...@sq-hbase1.800best.com:61406 16/10/28 12:46:04 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:61406 after 1 ms (0 ms spent in bootstraps) 16/10/28 12:46:04 INFO worker.WorkerWatcher: Successfully connected to spark://Wor...@sq-hbase1.800best.com:61406 16/10/28 12:46:04 INFO executor.CoarseGrainedExecutorBackend: Successfully registered with driver 16/10/28 12:46:04 INFO executor.Executor: Starting executor ID 1 on host sq-hbase1.800best.com 16/10/28 12:46:04 INFO util.Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 25758. 16/10/28 12:46:04 INFO netty.NettyBlockTransferService: Server created on sq-hbase1.800best.com:25758 16/10/28 12:46:04 INFO storage.BlockManagerMaster: Registering BlockManager BlockManagerId(1, sq-hbase1.800best.com, 25758) 16/10/28 12:46:04 INFO storage.BlockManagerMaster: Registered BlockManager BlockManagerId(1, sq-hbase1.800best.com, 25758) 16/10/28 12:46:09 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 1 16/10/28 12:46:09 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 4 16/10/28 12:46:09 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 7 16/10/28 12:46:09 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 10 16/10/28 12:46:09 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 13 16/10/28 12:46:09 INFO executor.Executor: Running task 13.0 in stage 0.0 (TID 13) 16/10/28 12:46:09 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 16 16/10/28 12:46:09 INFO executor.Executor: Running task 4.0 in stage 0.0 (TID 7) 16/10/28 12:46:09 INFO executor.Executor: Running task 2.0 in stage 0.0 (TID 4) 16/10/28 12:46:09 INFO executor.Executor: Running task 0.0 in stage 0.0 (TID 1) 16/10/28 12:46:09 INFO executor.Executor: Running task 8.0 in stage 0.0 (TID 10) 16/10/28 12:46:09 INFO executor.Executor: Running task 15.0 in stage 0.0 (TID 16) 16/10/28 12:46:09 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 19 16/10/28 12:46:09 INFO executor.Executor: Running task 18.0 in stage 0.0 (TID 19) 16/10/28 12:46:09 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 22 16/10/28 12:46:09 INFO executor.Executor: Running task 21.0 in stage 0.0 (TID 22) 16/10/28 12:46:09 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 25 16/10/28 12:46:09 INFO executor.Executor: Running task 25.0 in stage 0.0 (TID 25) 16/10/28 12:46:09 INFO executor.Executor: Fetching spark://sq-hbase1.800best.com:5289/files/core-site.xml with timestamp 1477629962863 16/10/28 12:46:09 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:5289 after 1 ms (0 ms spent in bootstraps) 16/10/28 12:46:09 INFO util.Utils: Fetching spark://sq-hbase1.800best.com:5289/files/core-site.xml to /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-934e5ce3-343c-4951-a468-44bd1a18d7ad/executor-d1cec12d-0323-40e8-b06d-84ea28570148/spark-f85fd571-f22c-43ed-93bd-cd3f794d47db/fetchFileTemp5635052499459849008.tmp 16/10/28 12:46:09 INFO util.Utils: Copying /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-934e5ce3-343c-4951-a468-44bd1a18d7ad/executor-d1cec12d-0323-40e8-b06d-84ea28570148/spark-f85fd571-f22c-43ed-93bd-cd3f794d47db/-1435087321477629962863_cache to /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/work/app-20161028124603-0000/1/./core-site.xml 16/10/28 12:46:09 INFO executor.Executor: Fetching spark://sq-hbase1.800best.com:5289/files/hdfs-site.xml with timestamp 1477629962855 16/10/28 12:46:09 INFO util.Utils: Fetching spark://sq-hbase1.800best.com:5289/files/hdfs-site.xml to /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-934e5ce3-343c-4951-a468-44bd1a18d7ad/executor-d1cec12d-0323-40e8-b06d-84ea28570148/spark-f85fd571-f22c-43ed-93bd-cd3f794d47db/fetchFileTemp6182228989894884620.tmp 16/10/28 12:46:09 INFO util.Utils: Copying /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-934e5ce3-343c-4951-a468-44bd1a18d7ad/executor-d1cec12d-0323-40e8-b06d-84ea28570148/spark-f85fd571-f22c-43ed-93bd-cd3f794d47db/-13980756221477629962855_cache to /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/work/app-20161028124603-0000/1/./hdfs-site.xml 16/10/28 12:46:09 INFO executor.Executor: Fetching spark://sq-hbase1.800best.com:5289/jars/aux-16-sp-count.jar with timestamp 1477629962796 16/10/28 12:46:09 INFO util.Utils: Fetching spark://sq-hbase1.800best.com:5289/jars/aux-16-sp-count.jar to /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-934e5ce3-343c-4951-a468-44bd1a18d7ad/executor-d1cec12d-0323-40e8-b06d-84ea28570148/spark-f85fd571-f22c-43ed-93bd-cd3f794d47db/fetchFileTemp1923161047440159462.tmp 16/10/28 12:46:09 INFO util.Utils: Copying /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-934e5ce3-343c-4951-a468-44bd1a18d7ad/executor-d1cec12d-0323-40e8-b06d-84ea28570148/spark-f85fd571-f22c-43ed-93bd-cd3f794d47db/12208101341477629962796_cache to /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/work/app-20161028124603-0000/1/./aux-16-sp-count.jar 16/10/28 12:46:09 INFO executor.Executor: Adding file:/home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/work/app-20161028124603-0000/1/./aux-16-sp-count.jar to class loader 16/10/28 12:46:09 INFO broadcast.TorrentBroadcast: Started reading broadcast variable 1 16/10/28 12:46:09 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:21454 after 1 ms (0 ms spent in bootstraps) 16/10/28 12:46:09 INFO memory.MemoryStore: Block broadcast_1_piece0 stored as bytes in memory (estimated size 1823.0 B, free 15.8 GB) 16/10/28 12:46:09 INFO broadcast.TorrentBroadcast: Reading broadcast variable 1 took 74 ms 16/10/28 12:46:09 INFO memory.MemoryStore: Block broadcast_1 stored as values in memory (estimated size 2.9 KB, free 15.8 GB) 16/10/28 12:46:09 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:2013265920+134217728 16/10/28 12:46:09 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:268435456+134217728 16/10/28 12:46:09 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:2818572288+134217728 16/10/28 12:46:09 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:536870912+134217728 16/10/28 12:46:09 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:3355443200+134217728 16/10/28 12:46:09 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:1744830464+134217728 16/10/28 12:46:09 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:1073741824+134217728 16/10/28 12:46:09 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:2415919104+134217728 16/10/28 12:46:09 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:0+134217728 16/10/28 12:46:09 INFO broadcast.TorrentBroadcast: Started reading broadcast variable 0 16/10/28 12:46:09 INFO memory.MemoryStore: Block broadcast_0_piece0 stored as bytes in memory (estimated size 23.6 KB, free 15.8 GB) 16/10/28 12:46:09 INFO broadcast.TorrentBroadcast: Reading broadcast variable 0 took 8 ms 16/10/28 12:46:09 INFO memory.MemoryStore: Block broadcast_0 stored as values in memory (estimated size 331.3 KB, free 15.8 GB) 16/10/28 12:46:15 INFO Configuration.deprecation: mapred.tip.id is deprecated. Instead, use mapreduce.task.id 16/10/28 12:46:15 INFO Configuration.deprecation: mapred.task.id is deprecated. Instead, use mapreduce.task.attempt.id 16/10/28 12:46:15 INFO Configuration.deprecation: mapred.task.partition is deprecated. Instead, use mapreduce.task.partition 16/10/28 12:46:15 INFO Configuration.deprecation: mapred.task.is.map is deprecated. Instead, use mapreduce.task.ismap 16/10/28 12:46:15 INFO Configuration.deprecation: mapred.job.id is deprecated. Instead, use mapreduce.job.id 16/10/28 12:46:15 INFO logger.type: initialize(alluxio://10.8.12.16:19998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.16:19998/linecount/10G.txt 16/10/28 12:46:15 INFO logger.type: initialize(alluxio://10.8.12.16:19998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.16:19998/linecount/10G.txt 16/10/28 12:46:15 INFO logger.type: initialize(alluxio://10.8.12.16:19998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.16:19998/linecount/10G.txt 16/10/28 12:46:15 INFO logger.type: initialize(alluxio://10.8.12.16:19998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.16:19998/linecount/10G.txt 16/10/28 12:46:15 INFO logger.type: initialize(alluxio://10.8.12.16:19998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.16:19998/linecount/10G.txt 16/10/28 12:46:15 INFO logger.type: initialize(alluxio://10.8.12.16:19998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.16:19998/linecount/10G.txt 16/10/28 12:46:15 INFO logger.type: initialize(alluxio://10.8.12.16:19998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.16:19998/linecount/10G.txt 16/10/28 12:46:15 INFO logger.type: initialize(alluxio://10.8.12.16:19998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.16:19998/linecount/10G.txt 16/10/28 12:46:15 INFO logger.type: initialize(alluxio://10.8.12.16:19998/linecount/10G.txt, Configuration: ). Connecting to Alluxio: alluxio://10.8.12.16:19998/linecount/10G.txt 16/10/28 12:46:15 INFO logger.type: alluxio://10.8.12.16:19998 alluxio://10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: alluxio://10.8.12.16:19998 alluxio://10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: alluxio://10.8.12.16:19998 alluxio://10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: alluxio://10.8.12.16:19998 alluxio://10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: alluxio://10.8.12.16:19998 alluxio://10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: alluxio://10.8.12.16:19998 alluxio://10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: alluxio://10.8.12.16:19998 alluxio://10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: alluxio://10.8.12.16:19998 alluxio://10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: alluxio://10.8.12.16:19998 alluxio://10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Loading Alluxio properties from Hadoop configuration: {} 16/10/28 12:46:15 INFO logger.type: Configuration file /etc/alluxio/alluxio-site.properties loaded. 16/10/28 12:46:15 INFO logger.type: Starting sinks with config: {}. 16/10/28 12:46:15 INFO logger.type: Sinks have already been started. 16/10/28 12:46:15 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:46:15 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:46:15 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:46:15 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:46:15 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:46:15 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:46:15 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:46:15 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:46:15 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with FileSystemMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@1b88b7e5 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@77962bc0 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@1d04f7c0 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@69cce27 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@90e2a00 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@6d9d8316 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@38a38e99 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@2af203ee 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@4b9c719b 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@4e20b18 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@c78c3d6 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@63177339 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@199c3d98 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@539229e 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@7e4cd478 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@f7d3ede 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@3efa95db 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@794ed1fb 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@515191e1 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@45f96bdf 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@63ac4fd5 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@29fa652c 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@7bdf2e70 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@4fe61c0e 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@39ed110d 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@62089e0d 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@2cb32c1c 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@7854c62a 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@4b5cf41c 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.FileSystemWorkerClientService$Client@69adbb52 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Alluxio client (version 1.3.0) is trying to connect with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Client registered with BlockMasterClient master @ /10.8.12.16:19998 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@3ff56a2e 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@49d85d9e 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@59d45f15 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@5fc587dc 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@5706ac6f 16/10/28 12:46:15 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@6ca4fe4 16/10/28 12:46:15 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2894f015. 16/10/28 12:46:15 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2894f015. 16/10/28 12:46:15 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2894f015. 16/10/28 12:46:15 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2894f015. 16/10/28 12:46:15 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2894f015. 16/10/28 12:46:15 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2894f015. 16/10/28 12:46:15 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2894f015. 16/10/28 12:46:15 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2894f015. 16/10/28 12:46:16 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@554eef17. 16/10/28 12:46:16 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2d07099b. 16/10/28 12:46:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@554eef17. 16/10/28 12:46:18 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@554eef17. 16/10/28 12:47:36 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2d07099b. 16/10/28 12:47:36 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@648febc2 16/10/28 12:47:36 INFO executor.Executor: Finished task 4.0 in stage 0.0 (TID 7). 948 bytes result sent to driver 16/10/28 12:47:36 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 27 16/10/28 12:47:36 INFO executor.Executor: Running task 27.0 in stage 0.0 (TID 27) 16/10/28 12:47:36 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:3623878656+134217728 16/10/28 12:47:36 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:47:48 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@4aadc996 16/10/28 12:47:48 INFO executor.Executor: Finished task 13.0 in stage 0.0 (TID 13). 948 bytes result sent to driver 16/10/28 12:47:48 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 29 16/10/28 12:47:48 INFO executor.Executor: Running task 28.0 in stage 0.0 (TID 29) 16/10/28 12:47:48 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:3758096384+134217728 16/10/28 12:47:48 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:48:07 INFO executor.Executor: Finished task 21.0 in stage 0.0 (TID 22). 1725 bytes result sent to driver 16/10/28 12:48:07 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 34 16/10/28 12:48:07 INFO executor.Executor: Running task 34.0 in stage 0.0 (TID 34) 16/10/28 12:48:07 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:4563402752+134217728 16/10/28 12:48:07 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:48:19 INFO executor.Executor: Finished task 0.0 in stage 0.0 (TID 1). 948 bytes result sent to driver 16/10/28 12:48:19 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 38 16/10/28 12:48:19 INFO executor.Executor: Running task 38.0 in stage 0.0 (TID 38) 16/10/28 12:48:19 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:5100273664+134217728 16/10/28 12:48:19 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:48:23 INFO executor.Executor: Finished task 25.0 in stage 0.0 (TID 25). 948 bytes result sent to driver 16/10/28 12:48:23 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 43 16/10/28 12:48:23 INFO executor.Executor: Running task 43.0 in stage 0.0 (TID 43) 16/10/28 12:48:23 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:5771362304+134217728 16/10/28 12:48:23 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:48:31 INFO executor.Executor: Finished task 18.0 in stage 0.0 (TID 19). 948 bytes result sent to driver 16/10/28 12:48:31 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 47 16/10/28 12:48:31 INFO executor.Executor: Running task 45.0 in stage 0.0 (TID 47) 16/10/28 12:48:31 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:6039797760+134217728 16/10/28 12:48:31 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:48:38 INFO executor.Executor: Finished task 15.0 in stage 0.0 (TID 16). 1725 bytes result sent to driver 16/10/28 12:48:38 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 48 16/10/28 12:48:38 INFO executor.Executor: Running task 48.0 in stage 0.0 (TID 48) 16/10/28 12:48:38 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:6442450944+134217728 16/10/28 12:48:38 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:48:59 INFO executor.Executor: Finished task 2.0 in stage 0.0 (TID 4). 948 bytes result sent to driver 16/10/28 12:48:59 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 50 16/10/28 12:48:59 INFO executor.Executor: Running task 49.0 in stage 0.0 (TID 50) 16/10/28 12:48:59 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:6576668672+134217728 16/10/28 12:48:59 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:49:10 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2d07099b. 16/10/28 12:49:12 INFO executor.Executor: Finished task 8.0 in stage 0.0 (TID 10). 948 bytes result sent to driver 16/10/28 12:49:12 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 52 16/10/28 12:49:12 INFO executor.Executor: Running task 52.0 in stage 0.0 (TID 52) 16/10/28 12:49:12 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:6979321856+134217728 16/10/28 12:49:12 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:49:16 INFO executor.Executor: Finished task 27.0 in stage 0.0 (TID 27). 1027 bytes result sent to driver 16/10/28 12:49:16 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 53 16/10/28 12:49:16 INFO executor.Executor: Running task 53.0 in stage 0.0 (TID 53) 16/10/28 12:49:16 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:7113539584+134217728 16/10/28 12:49:16 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:49:48 INFO executor.Executor: Finished task 28.0 in stage 0.0 (TID 29). 940 bytes result sent to driver 16/10/28 12:49:48 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 58 16/10/28 12:49:48 INFO executor.Executor: Running task 56.0 in stage 0.0 (TID 58) 16/10/28 12:49:48 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:7516192768+134217728 16/10/28 12:49:48 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:49:58 INFO executor.Executor: Finished task 45.0 in stage 0.0 (TID 47). 1114 bytes result sent to driver 16/10/28 12:49:58 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 60 16/10/28 12:49:58 INFO executor.Executor: Running task 58.0 in stage 0.0 (TID 60) 16/10/28 12:49:58 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:7784628224+134217728 16/10/28 12:49:58 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:50:27 INFO executor.Executor: Finished task 49.0 in stage 0.0 (TID 50). 1027 bytes result sent to driver 16/10/28 12:50:27 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 65 16/10/28 12:50:27 INFO executor.Executor: Running task 60.0 in stage 0.0 (TID 65) 16/10/28 12:50:27 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:8053063680+134217728 16/10/28 12:50:27 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:50:44 INFO logger.type: The block with ID 26960986165 is already stored in the target worker, canceling the cache request. 16/10/28 12:50:44 INFO executor.Executor: Finished task 52.0 in stage 0.0 (TID 52). 1027 bytes result sent to driver 16/10/28 12:50:44 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 70 16/10/28 12:50:44 INFO executor.Executor: Running task 64.0 in stage 0.0 (TID 70) 16/10/28 12:50:44 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:8589934592+134217728 16/10/28 12:50:44 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:51:05 INFO executor.Executor: Finished task 56.0 in stage 0.0 (TID 58). 1027 bytes result sent to driver 16/10/28 12:51:05 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 74 16/10/28 12:51:05 INFO executor.Executor: Running task 73.0 in stage 0.0 (TID 74) 16/10/28 12:51:05 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:9797894144+134217728 16/10/28 12:51:05 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:51:55 INFO executor.Executor: Finished task 34.0 in stage 0.0 (TID 34). 1027 bytes result sent to driver 16/10/28 12:51:55 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 79 16/10/28 12:51:55 INFO executor.Executor: Running task 79.0 in stage 0.0 (TID 79) 16/10/28 12:51:55 INFO rdd.HadoopRDD: Input split: alluxio://10.8.12.16:19998/linecount/10G.txt:10603200512+134217728 16/10/28 12:51:55 INFO logger.type: open(alluxio://10.8.12.16:19998/linecount/10G.txt, 65536) 16/10/28 12:51:58 INFO executor.Executor: Finished task 38.0 in stage 0.0 (TID 38). 1027 bytes result sent to driver 16/10/28 12:51:59 INFO executor.Executor: Finished task 43.0 in stage 0.0 (TID 43). 1027 bytes result sent to driver 16/10/28 12:52:01 WARN logger.type: The block with ID 26960986177 could not be cached into Alluxio storage. 16/10/28 12:52:02 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@1e3374bd 16/10/28 12:52:02 INFO logger.type: Clearing unhealthy resource [id: 0xf150733c, /10.8.12.16:13385]. 16/10/28 12:52:02 INFO logger.type: Channel closed 16/10/28 12:52:04 WARN logger.type: The block with ID 26960986161 could not be cached into Alluxio storage. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@c78c3d6 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@199c3d98 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@539229e is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@2af203ee is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@63177339 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@1b88b7e5 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@77962bc0 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@4e20b18 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@38a38e99 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@1d04f7c0 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@69cce27 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@4b5cf41c is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@4fe61c0e is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@62089e0d is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@2cb32c1c is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@7bdf2e70 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@7854c62a is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@69adbb52 is garbage collected. 16/10/28 12:52:15 INFO logger.type: Resource [id: 0xfc2f2f19, /10.8.12.16:11372 => /10.8.12.16:29999] is garbage collected. 16/10/28 12:52:15 INFO logger.type: Channel closed 16/10/28 12:52:15 INFO logger.type: Resource [id: 0x8f1d7585, /10.8.12.16:11366 => /10.8.12.16:29999] is garbage collected. 16/10/28 12:52:15 INFO logger.type: Channel closed 16/10/28 12:52:15 INFO logger.type: Resource [id: 0x474705dc, /10.8.12.16:11368 => /10.8.12.16:29999] is garbage collected. 16/10/28 12:52:15 INFO logger.type: Channel closed 16/10/28 12:52:15 INFO logger.type: Resource [id: 0x85347f1f, /10.8.12.16:11369 => /10.8.12.16:29999] is garbage collected. 16/10/28 12:52:15 INFO logger.type: Channel closed 16/10/28 12:52:15 INFO logger.type: Resource [id: 0x8a7ce103, /10.8.12.16:11365 => /10.8.12.16:29999] is garbage collected. 16/10/28 12:52:15 INFO logger.type: Channel closed 16/10/28 12:52:15 INFO logger.type: Resource [id: 0xf999c792, /10.8.12.16:11371 => /10.8.12.16:29999] is garbage collected. 16/10/28 12:52:15 INFO logger.type: Channel closed 16/10/28 12:52:17 INFO executor.Executor: Finished task 53.0 in stage 0.0 (TID 53). 1027 bytes result sent to driver 16/10/28 12:52:18 INFO logger.type: Clearing unhealthy resource [id: 0x41650c53, /10.8.12.16:13294]. 16/10/28 12:52:18 INFO logger.type: Channel closed 16/10/28 12:52:19 INFO logger.type: Created netty channel to with netty boostrap alluxio.client.block.BlockStoreContext$2@2894f015. 16/10/28 12:52:21 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@67173fa3 16/10/28 12:52:21 INFO executor.Executor: Finished task 73.0 in stage 0.0 (TID 74). 1027 bytes result sent to driver 16/10/28 12:52:24 WARN logger.type: The block with ID 26960986171 could not be cached into Alluxio storage. 16/10/28 12:52:26 INFO executor.Executor: Finished task 60.0 in stage 0.0 (TID 65). 1027 bytes result sent to driver 16/10/28 12:52:27 INFO executor.Executor: Finished task 79.0 in stage 0.0 (TID 79). 1027 bytes result sent to driver 16/10/28 12:54:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@3efa95db is garbage collected. 16/10/28 12:54:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@29fa652c is garbage collected. 16/10/28 12:54:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@7e4cd478 is garbage collected. 16/10/28 12:54:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@515191e1 is garbage collected. 16/10/28 12:54:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@45f96bdf is garbage collected. 16/10/28 12:54:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@794ed1fb is garbage collected. 16/10/28 12:54:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@59d45f15 is garbage collected. 16/10/28 12:54:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@5706ac6f is garbage collected. 16/10/28 12:54:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@49d85d9e is garbage collected. 16/10/28 12:56:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@90e2a00 is garbage collected. 16/10/28 12:56:15 INFO logger.type: Resource alluxio.thrift.FileSystemWorkerClientService$Client@63ac4fd5 is garbage collected. 16/10/28 12:57:36 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@67173fa3 is garbage collected. 16/10/28 12:58:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@5fc587dc is garbage collected. 16/10/28 12:58:15 INFO logger.type: Resource [id: 0x39f22360, /10.8.12.16:11714 => /10.8.12.16:29999] is garbage collected. 16/10/28 12:58:15 INFO logger.type: Channel closed 16/10/28 12:58:15 INFO logger.type: Resource [id: 0x67487f7f, /10.8.12.16:11367 => /10.8.12.16:29999] is garbage collected. 16/10/28 12:58:15 INFO logger.type: Channel closed 16/10/28 12:58:16 INFO logger.type: Resource [id: 0x67a0fcb5, /10.8.12.16:34680] is garbage collected. 16/10/28 12:58:16 INFO logger.type: Channel closed 16/10/28 12:58:16 INFO logger.type: Resource [id: 0x4693e062, /10.8.12.16:34683 => /10.8.12.18:29999] is garbage collected. 16/10/28 12:58:16 INFO logger.type: Channel closed 16/10/28 13:19:46 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@79e41d3b 16/10/28 13:26:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@6ca4fe4 is garbage collected. 16/10/28 13:42:01 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@24ac2b91 16/10/28 13:42:01 ERROR logger.type: java.net.SocketTimeoutException: Read timed out alluxio.org.apache.thrift.transport.TTransportException: java.net.SocketTimeoutException: Read timed out at alluxio.org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:129) at alluxio.org.apache.thrift.transport.TTransport.readAll(TTransport.java:86) at alluxio.org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:376) at alluxio.org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:453) at alluxio.org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:435) at alluxio.org.apache.thrift.transport.TSaslClientTransport.read(TSaslClientTransport.java:37) at alluxio.org.apache.thrift.transport.TTransport.readAll(TTransport.java:86) at alluxio.org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:429) at alluxio.org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:318) at alluxio.org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:219) at alluxio.org.apache.thrift.protocol.TProtocolDecorator.readMessageBegin(TProtocolDecorator.java:135) at alluxio.org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:77) at alluxio.thrift.BlockWorkerClientService$Client.recv_cancelBlock(BlockWorkerClientService.java:250) at alluxio.thrift.BlockWorkerClientService$Client.cancelBlock(BlockWorkerClientService.java:236) at alluxio.client.block.RetryHandlingBlockWorkerClient$5.call(RetryHandlingBlockWorkerClient.java:172) at alluxio.client.block.RetryHandlingBlockWorkerClient$5.call(RetryHandlingBlockWorkerClient.java:168) at alluxio.AbstractThriftClient.retryRPC(AbstractThriftClient.java:140) at alluxio.client.block.RetryHandlingBlockWorkerClient.cancelBlock(RetryHandlingBlockWorkerClient.java:168) at alluxio.client.block.RemoteBlockOutStream.cancel(RemoteBlockOutStream.java:67) at alluxio.client.file.FileInStream.closeOrCancelCacheStream(FileInStream.java:347) at alluxio.client.file.FileInStream.handleCacheStreamIOException(FileInStream.java:408) at alluxio.client.file.FileInStream.read(FileInStream.java:212) at alluxio.client.file.FileInStream.readCurrentBlockToPos(FileInStream.java:628) at alluxio.client.file.FileInStream.readCurrentBlockToEnd(FileInStream.java:639) at alluxio.client.file.FileInStream.close(FileInStream.java:147) at alluxio.hadoop.HdfsFileInputStream.close(HdfsFileInputStream.java:109) at java.io.FilterInputStream.close(FilterInputStream.java:181) at org.apache.hadoop.util.LineReader.close(LineReader.java:150) at org.apache.hadoop.mapred.LineRecordReader.close(LineRecordReader.java:284) at org.apache.spark.rdd.HadoopRDD$$anon$1.close(HadoopRDD.scala:277) at org.apache.spark.util.NextIterator.closeIfNeeded(NextIterator.scala:66) at org.apache.spark.util.NextIterator.hasNext(NextIterator.scala:75) at org.apache.spark.InterruptibleIterator.hasNext(InterruptibleIterator.scala:39) at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:408) at org.apache.spark.util.Utils$.getIteratorSize(Utils.scala:1682) at org.apache.spark.rdd.RDD$$anonfun$count$1.apply(RDD.scala:1115) at org.apache.spark.rdd.RDD$$anonfun$count$1.apply(RDD.scala:1115) at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897) at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897) at org.apache.spark.scheduler.ResultTask.runTask(ResultTask.scala:70) at org.apache.spark.scheduler.Task.run(Task.scala:85) at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:274) 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) Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:170) at java.net.SocketInputStream.read(SocketInputStream.java:141) at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) at java.io.BufferedInputStream.read1(BufferedInputStream.java:286) at java.io.BufferedInputStream.read(BufferedInputStream.java:345) at alluxio.org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127) ... 44 more 16/10/28 13:42:01 INFO logger.type: Clearing unhealthy resource alluxio.thrift.BlockWorkerClientService$Client@648febc2. 16/10/28 13:42:01 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@6c31663e 16/10/28 13:42:04 ERROR logger.type: java.net.SocketTimeoutException: Read timed out alluxio.org.apache.thrift.transport.TTransportException: java.net.SocketTimeoutException: Read timed out at alluxio.org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:129) at alluxio.org.apache.thrift.transport.TTransport.readAll(TTransport.java:86) at alluxio.org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:376) at alluxio.org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:453) at alluxio.org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:435) at alluxio.org.apache.thrift.transport.TSaslClientTransport.read(TSaslClientTransport.java:37) at alluxio.org.apache.thrift.transport.TTransport.readAll(TTransport.java:86) at alluxio.org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:429) at alluxio.org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:318) at alluxio.org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:219) at alluxio.org.apache.thrift.protocol.TProtocolDecorator.readMessageBegin(TProtocolDecorator.java:135) at alluxio.org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:77) at alluxio.thrift.BlockWorkerClientService$Client.recv_cancelBlock(BlockWorkerClientService.java:250) at alluxio.thrift.BlockWorkerClientService$Client.cancelBlock(BlockWorkerClientService.java:236) at alluxio.client.block.RetryHandlingBlockWorkerClient$5.call(RetryHandlingBlockWorkerClient.java:172) at alluxio.client.block.RetryHandlingBlockWorkerClient$5.call(RetryHandlingBlockWorkerClient.java:168) at alluxio.AbstractThriftClient.retryRPC(AbstractThriftClient.java:140) at alluxio.client.block.RetryHandlingBlockWorkerClient.cancelBlock(RetryHandlingBlockWorkerClient.java:168) at alluxio.client.block.RemoteBlockOutStream.cancel(RemoteBlockOutStream.java:67) at alluxio.client.file.FileInStream.closeOrCancelCacheStream(FileInStream.java:347) at alluxio.client.file.FileInStream.handleCacheStreamIOException(FileInStream.java:408) at alluxio.client.file.FileInStream.read(FileInStream.java:212) at alluxio.client.file.FileInStream.readCurrentBlockToPos(FileInStream.java:628) at alluxio.client.file.FileInStream.readCurrentBlockToEnd(FileInStream.java:639) at alluxio.client.file.FileInStream.close(FileInStream.java:147) at alluxio.hadoop.HdfsFileInputStream.close(HdfsFileInputStream.java:109) at java.io.FilterInputStream.close(FilterInputStream.java:181) at org.apache.hadoop.util.LineReader.close(LineReader.java:150) at org.apache.hadoop.mapred.LineRecordReader.close(LineRecordReader.java:284) at org.apache.spark.rdd.HadoopRDD$$anon$1.close(HadoopRDD.scala:277) at org.apache.spark.util.NextIterator.closeIfNeeded(NextIterator.scala:66) at org.apache.spark.util.NextIterator.hasNext(NextIterator.scala:75) at org.apache.spark.InterruptibleIterator.hasNext(InterruptibleIterator.scala:39) at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:408) at org.apache.spark.util.Utils$.getIteratorSize(Utils.scala:1682) at org.apache.spark.rdd.RDD$$anonfun$count$1.apply(RDD.scala:1115) at org.apache.spark.rdd.RDD$$anonfun$count$1.apply(RDD.scala:1115) at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897) at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897) at org.apache.spark.scheduler.ResultTask.runTask(ResultTask.scala:70) at org.apache.spark.scheduler.Task.run(Task.scala:85) at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:274) 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) Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:170) at java.net.SocketInputStream.read(SocketInputStream.java:141) at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) at java.io.BufferedInputStream.read1(BufferedInputStream.java:286) at java.io.BufferedInputStream.read(BufferedInputStream.java:345) at alluxio.org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127) ... 44 more 16/10/28 13:42:04 INFO logger.type: Clearing unhealthy resource alluxio.thrift.BlockWorkerClientService$Client@1e3374bd. 16/10/28 13:42:04 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@276a2f04 16/10/28 13:42:24 ERROR logger.type: java.net.SocketTimeoutException: Read timed out alluxio.org.apache.thrift.transport.TTransportException: java.net.SocketTimeoutException: Read timed out at alluxio.org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:129) at alluxio.org.apache.thrift.transport.TTransport.readAll(TTransport.java:86) at alluxio.org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:376) at alluxio.org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:453) at alluxio.org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:435) at alluxio.org.apache.thrift.transport.TSaslClientTransport.read(TSaslClientTransport.java:37) at alluxio.org.apache.thrift.transport.TTransport.readAll(TTransport.java:86) at alluxio.org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:429) at alluxio.org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:318) at alluxio.org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:219) at alluxio.org.apache.thrift.protocol.TProtocolDecorator.readMessageBegin(TProtocolDecorator.java:135) at alluxio.org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:77) at alluxio.thrift.BlockWorkerClientService$Client.recv_cancelBlock(BlockWorkerClientService.java:250) at alluxio.thrift.BlockWorkerClientService$Client.cancelBlock(BlockWorkerClientService.java:236) at alluxio.client.block.RetryHandlingBlockWorkerClient$5.call(RetryHandlingBlockWorkerClient.java:172) at alluxio.client.block.RetryHandlingBlockWorkerClient$5.call(RetryHandlingBlockWorkerClient.java:168) at alluxio.AbstractThriftClient.retryRPC(AbstractThriftClient.java:140) at alluxio.client.block.RetryHandlingBlockWorkerClient.cancelBlock(RetryHandlingBlockWorkerClient.java:168) at alluxio.client.block.RemoteBlockOutStream.cancel(RemoteBlockOutStream.java:67) at alluxio.client.file.FileInStream.closeOrCancelCacheStream(FileInStream.java:347) at alluxio.client.file.FileInStream.handleCacheStreamIOException(FileInStream.java:408) at alluxio.client.file.FileInStream.read(FileInStream.java:212) at alluxio.client.file.FileInStream.readCurrentBlockToPos(FileInStream.java:628) at alluxio.client.file.FileInStream.readCurrentBlockToEnd(FileInStream.java:639) at alluxio.client.file.FileInStream.close(FileInStream.java:147) at alluxio.hadoop.HdfsFileInputStream.close(HdfsFileInputStream.java:109) at java.io.FilterInputStream.close(FilterInputStream.java:181) at org.apache.hadoop.util.LineReader.close(LineReader.java:150) at org.apache.hadoop.mapred.LineRecordReader.close(LineRecordReader.java:284) at org.apache.spark.rdd.HadoopRDD$$anon$1.close(HadoopRDD.scala:277) at org.apache.spark.util.NextIterator.closeIfNeeded(NextIterator.scala:66) at org.apache.spark.util.NextIterator.hasNext(NextIterator.scala:75) at org.apache.spark.InterruptibleIterator.hasNext(InterruptibleIterator.scala:39) at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:408) at org.apache.spark.util.Utils$.getIteratorSize(Utils.scala:1682) at org.apache.spark.rdd.RDD$$anonfun$count$1.apply(RDD.scala:1115) at org.apache.spark.rdd.RDD$$anonfun$count$1.apply(RDD.scala:1115) at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897) at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897) at org.apache.spark.scheduler.ResultTask.runTask(ResultTask.scala:70) at org.apache.spark.scheduler.Task.run(Task.scala:85) at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:274) 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) Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:170) at java.net.SocketInputStream.read(SocketInputStream.java:141) at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) at java.io.BufferedInputStream.read1(BufferedInputStream.java:286) at java.io.BufferedInputStream.read(BufferedInputStream.java:345) at alluxio.org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127) ... 44 more 16/10/28 13:42:24 INFO logger.type: Clearing unhealthy resource alluxio.thrift.BlockWorkerClientService$Client@4aadc996. 16/10/28 13:42:24 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@77aacb36 16/10/28 13:48:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@79e41d3b is garbage collected. 16/10/28 13:55:06 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@445b30a2 16/10/28 14:02:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@24ac2b91 is garbage collected. 16/10/28 14:02:48 INFO logger.type: Created a new thrift client alluxio.thrift.BlockWorkerClientService$Client@ddce97d 16/10/28 14:08:15 INFO logger.type: Resource alluxio.thrift.BlockWorkerClientService$Client@445b30a2 is garbage collected.
master.log:
No more log info when executing the spark job.
worker.log(alluxio1 for example):
use command "cat worker.log | grep -C 10 Exception" to get the log info.
2016-10-28 12:46:11,400 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986112 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986112 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:46:12,023 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986112 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986112 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:46:12,232 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986112 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986112 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:46:12,275 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986112 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986112 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:47:47,567 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986119 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986119 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:47:51,088 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986123 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986123 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:50:39,717 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986150 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986150 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:50:46,175 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986163 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986163 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:51:29,696 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986170 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986170 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:51:53,682 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986181 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986181 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:51:56,141 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986172 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986172 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
[appadmin@sq-hbase1 logs]$ cat worker.log | grep -C 10 Exception >> worker.exeception.log
[appadmin@sq-hbase1 logs]$ ls
master.log master.out user_appadmin.log worker.exeception.log worker.log.1
master.log.1 task.log user_root.log worker.log worker.out
[appadmin@sq-hbase1 logs]$ vi worker.exeception.log
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
--
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:831)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:322)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
at java.lang.Thread.run(Thread.java:745)
2016-10-28 12:51:56,141 ERROR logger.type (BlockDataServerHandler.java:handleBlockWriteRequest) - Error writing remote block : Temp blockId 26960986172 is not available, because it already exists
alluxio.exception.BlockAlreadyExistsException: Temp blockId 26960986172 is not available, because it already exists
at alluxio.worker.block.TieredBlockStore.checkTempBlockIdAvailable(TieredBlockStore.java:390)
at alluxio.worker.block.TieredBlockStore.createBlockMetaInternal(TieredBlockStore.java:521)
at alluxio.worker.block.TieredBlockStore.createBlockMeta(TieredBlockStore.java:185)
at alluxio.worker.block.DefaultBlockWorker.createBlockRemote(DefaultBlockWorker.java:299)
at alluxio.worker.netty.BlockDataServerHandler.handleBlockWriteRequest(BlockDataServerHandler.java:147)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:73)
at alluxio.worker.netty.DataServerHandler.channelRead0(DataServerHandler.java:42)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
在 2016年10月28日星期五 UTC+8上午4:57:25，Pei Sun写道：
To unsubscribe from this group and stop receiving emails from it, send an email to alluxio-user...@googlegroups.com.
--Pei Sun
Kaiming Wan
Oct 30, 2016, 10:11:03 PM10/30/16
to Alluxio Users, fanb...@gmail.com
I have solved this problem by not using following configuration in spark and fotmat alluxio. I will check whether the round robin policy cause the problem later.
在 2016年10月27日星期四 UTC+8下午6:24:25，Kaiming Wan写道：
spark.driver.extraJavaOptions -Dalluxio.user.file.write.location.policy.class=alluxio.client.file.policy.RoundRobinPolicy
spark.executor.extraJavaOptions -Dalluxio.user.file.write.location.policy.class=alluxio.client.file.policy.RoundRobinPolicy
在 2016年10月27日星期四 UTC+8下午6:24:25，Kaiming Wan写道：
Pei Sun
Oct 31, 2016, 2:09:44 AM10/31/16
to Kaiming Wan, Alluxio Users, Bin Fan
Glad to hear that you have solved the problem. If you do need round robin policy, we can work together to figure out the root cause later.
--
You received this message because you are subscribed to the Google Groups "Alluxio Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to alluxio-users+unsubscribe@googlegroups.com.
Pei Sun
Eric Wang
Nov 21, 2016, 3:52:58 AM11/21/16
to Alluxio Users, wan...@gmail.com, fanb...@gmail.com
Hi KaiMing
I have the same Permission problem as yours.
java.io.IOException: Failed to cache: /home/alluxio/ramdisk/alluxioworker/.tmp_blocks/678/5bbebd62959576a6-c000000 (Permission denied)
at alluxio.client.file.FileOutStream.handleCacheWriteException(FileOutStream.java:358)
Could you please tell me how to fix it ?
Thank You
在 2016年10月28日星期五 UTC+8下午2:25:55，Kaiming Wan写道：
Hi, Pei SunI solved the permission problem and redo the spark line count job, but the job still hang up during process. Here comes some log information:1. executor log:I found there are many GC and timeout issue. What will cause this problem.
16/10/28 12:46:03 INFO executor.CoarseGrainedExecutorBackend: Started daemon with process name: 86...@sq-hbase1.800best.com 16/10/28 12:46:03 INFO util.SignalUtils: Registered signal handler for TERM 16/10/28 12:46:03 INFO util.SignalUtils: Registered signal handler for HUP 16/10/28 12:46:03 INFO util.SignalUtils: Registered signal handler for INT 16/10/28 12:46:03 WARN util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable 16/10/28 12:46:04 INFO spark.SecurityManager: Changing view acls to: appadmin 16/10/28 12:46:04 INFO spark.SecurityManager: Changing modify acls to: appadmin 16/10/28 12:46:04 INFO spark.SecurityManager: Changing view acls groups to: 16/10/28 12:46:04 INFO spark.SecurityManager: Changing modify acls groups to: 16/10/28 12:46:04 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(appadmin); groups with view permissions: Set(); users with modify permissions: Set(appadmin); groups with modify permissions: Set() 16/10/28 12:46:04 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:5289 after 39 ms (0 ms spent in bootstraps) 16/10/28 12:46:04 INFO spark.SecurityManager: Changing view acls to: appadmin 16/10/28 12:46:04 INFO spark.SecurityManager: Changing modify acls to: appadmin 16/10/28 12:46:04 INFO spark.SecurityManager: Changing view acls groups to: 16/10/28 12:46:04 INFO spark.SecurityManager: Changing modify acls groups to: 16/10/28 12:46:04 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(appadmin); groups with view permissions: Set(); users with modify permissions: Set(appadmin); groups with modify permissions: Set() 16/10/28 12:46:04 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:5289 after 1 ms (0 ms spent in bootstraps) 16/10/28 12:46:04 INFO storage.DiskBlockManager: Created local directory at /home/appadmin/spark-2.0.0-bin-without-hadoop/sparkdata/local/spark-934e5ce3-343c-4951-a468-44bd1a18d7ad/executor-d1cec12d-0323-40e8-b06d-84ea28570148/blockmgr-5f01a470-58e3-4309-8c76-
5f4d6ffe7766 16/10/28 12:46:04 INFO memory.MemoryStore: MemoryStore started with capacity 15.8 GB 16/10/28 12:46:04 INFO executor.CoarseGrainedExecutorBackend: Connecting to driver: spark://CoarseGrainedScheduler@sq-hbase1.800best.com:5289 16/10/28 12:46:04 INFO worker.WorkerWatcher: Connecting to worker spark://Worker@sq-hbase1.800best.com:61406
16/10/28 12:46:04 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:61406
after 1 ms (0 ms spent in bootstraps) 16/10/28 12:46:04 INFO worker.WorkerWatcher: Successfully connected to spark://Worker@sq-hbase1.800best.com:61406
...
Bin Fan
Nov 21, 2016, 4:49:42 PM11/21/16
to Eric Wang, Alluxio Users, Kaiming Wan
Hi Eric,
could you try to restart your deployment from scratch?
e.g., running
$ ./bin/alluxio format
before
$ ./bin/alluxio-start.sh
and see if the format solves the permission issue?
16/10/28 12:46:04 INFO worker.WorkerWatcher: Connecting to worker spark://Wor...@sq-hbase1.800best.com:61406
16/10/28 12:46:04 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:61406
after 1 ms (0 ms spent in bootstraps) 16/10/28 12:46:04 INFO worker.WorkerWatcher: Successfully connected to spark://Wor...@sq-hbase1.800best.com:61406
...
Eric Wang
Nov 22, 2016, 1:23:31 AM11/22/16
to Alluxio Users, 5247...@qq.com, wan...@gmail.com
Hi , Bin Fan:
Thanks for your reply!
在 2016年11月22日星期二 UTC+8上午5:49:42，Bin Fan写道：
I had solved the Permission problem which was cause by the path of alluxio worker ramdisk
However there is another question confusing me :I used user hadoop submited a spark job on yarn with the yarn-cluster mode:
data.saveAsTextFile("alluxio://ip:19998/user/hadoop/data")
The file create sccessfully , but the file created in alluxio was owned by user yarn not hadoop?
So I test save to hdfs the file created in hdfs is owned by hadoop.
Why it is different in alluxio?
在 2016年11月22日星期二 UTC+8上午5:49:42，Bin Fan写道：
16/10/28 12:46:04 INFO worker.WorkerWatcher: Connecting to worker spark://Worker@sq-hbase1.800best.com:61406
16/10/28 12:46:04 INFO client.TransportClientFactory: Successfully created connection to sq-hbase1.800best.com/10.8.12.16:61406
after 1 ms (0 ms spent in bootstraps) 16/10/28 12:46:04 INFO worker.WorkerWatcher: Successfully connected to spark://Worker@sq-hbase1.800best.com:61406
...
Bin Fan
Jan 5, 2017, 1:53:47 AM1/5/17
to Alluxio Users, 5247...@qq.com
Hi Eric,
I believe this issue has been fixed in branch-1.4.
If you want to test, feel free to try what is posted in
If you still have problem, could you send the question in a new and separate thread?
In this way, it is easier for us to track the problem and also for other users to search.
Thanks.
...
Reply all
Reply to author
Forward
0 new messages