spark-8seconds-jb

2017-10-26 14:35:57 TRACE MessageDecoder:47 - Received message OneWayMessage: OneWayMessage{body=NettyManagedBuffer{buf=CompositeByteBuf(ridx: 5, widx: 8470, cap: 8470, components=9)}}
2017-10-26 14:35:57 INFO  CoarseGrainedExecutorBackend:54 - Got assigned task 62
2017-10-26 14:35:57 INFO  Executor:54 - Running task 0.0 in stage 72.0 (TID 62)
2017-10-26 14:35:57 DEBUG Executor:58 - Task 62's epoch is 40
2017-10-26 14:35:57 DEBUG BlockManager:58 - Getting local block broadcast_65
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire read lock for broadcast_65
2017-10-26 14:35:57 DEBUG BlockManager:58 - Block broadcast_65 was not found
2017-10-26 14:35:57 INFO  TorrentBroadcast:54 - Started reading broadcast variable 65
2017-10-26 14:35:57 DEBUG TorrentBroadcast:58 - Reading piece broadcast_65_piece0 of broadcast_65
2017-10-26 14:35:57 DEBUG BlockManager:58 - Getting local block broadcast_65_piece0 as bytes
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire read lock for broadcast_65_piece0
2017-10-26 14:35:57 DEBUG BlockManager:58 - Getting remote block broadcast_65_piece0
2017-10-26 14:35:57 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:35:57 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5289918079860252008, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 265, cap: 16384)}}
2017-10-26 14:35:57 TRACE TransportClient:239 - Sending request 5289918079860252008 to /172.31.15.200:36445 took 4 ms
2017-10-26 14:35:57 DEBUG BlockManager:58 - Getting remote block broadcast_65_piece0 from BlockManagerId(driver, 172.31.15.200, 36302, None)
2017-10-26 14:35:57 TRACE NettyBlockTransferService:62 - Fetch blocks from 172.31.15.200:36302 (executor id driver)
2017-10-26 14:35:57 TRACE TransportClientFactory:154 - Returning cached connection to /172.31.15.200:36302: TransportClient{remoteAdress=/172.31.15.200:36302, clientId=null, isActive=true}
2017-10-26 14:35:57 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36302
2017-10-26 14:35:57 TRACE TransportClient:239 - Sending request 4964253698184974921 to /172.31.15.200:36302 took 0 ms
2017-10-26 14:35:57 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=4964253698184974921, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 34, cap: 4096)}}
2017-10-26 14:35:57 TRACE OneForOneBlockFetcher:98 - Successfully opened blocks StreamHandle{streamId=24338427064, numChunks=1}, preparing to fetch chunks.
2017-10-26 14:35:57 DEBUG TransportClient:140 - Sending fetch chunk request 0 to /172.31.15.200:36302
2017-10-26 14:35:57 TRACE TransportClient:153 - Sending request StreamChunkId{streamId=24338427064, chunkIndex=0} to /172.31.15.200:36302 took 0 ms
2017-10-26 14:35:57 TRACE MessageDecoder:47 - Received message ChunkFetchSuccess: ChunkFetchSuccess{streamChunkId=StreamChunkId{streamId=24338427064, chunkIndex=0}, buffer=NettyManagedBuffer{buf=DuplicatedAbstractByteBuf(ridx: 13, widx: 4667, cap: 4667, unwrapped: CompositeByteBuf(ridx: 13, widx: 4667, cap: 4667, components=2))}}
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to put broadcast_65_piece0
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire read lock for broadcast_65_piece0
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire write lock for broadcast_65_piece0
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 acquired write lock for broadcast_65_piece0
2017-10-26 14:35:57 INFO  MemoryStore:54 - Block broadcast_65_piece0 stored as bytes in memory (estimated size 4.5 KB, free 366.3 MB)
2017-10-26 14:35:57 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:35:57 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=8647232787127567826, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 16384)}}
2017-10-26 14:35:57 TRACE TransportClient:239 - Sending request 8647232787127567826 to /172.31.15.200:36445 took 3 ms
2017-10-26 14:35:57 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_65_piece0
2017-10-26 14:35:57 DEBUG BlockManager:58 - Told master about block broadcast_65_piece0
2017-10-26 14:35:57 DEBUG BlockManager:58 - Put block broadcast_65_piece0 locally took  3 ms
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 releasing lock for broadcast_65_piece0
2017-10-26 14:35:57 DEBUG BlockManager:58 - Putting block broadcast_65_piece0 without replication took  3 ms
2017-10-26 14:35:57 INFO  TorrentBroadcast:54 - Reading broadcast variable 65 took 14 ms
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to put broadcast_65
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire read lock for broadcast_65
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire write lock for broadcast_65
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 acquired write lock for broadcast_65
2017-10-26 14:35:57 INFO  MemoryStore:54 - Block broadcast_65 stored as values in memory (estimated size 8.3 KB, free 366.3 MB)
2017-10-26 14:35:57 DEBUG BlockManager:58 - Put block broadcast_65 locally took  1 ms
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 releasing lock for broadcast_65
2017-10-26 14:35:57 DEBUG BlockManager:58 - Putting block broadcast_65 without replication took  1 ms
2017-10-26 14:35:57 INFO  NewHadoopRDD:54 - Input split: HBase table split(table name: flow, scan: {"loadColumnFamiliesOnDemand":null,"startRow":"CbiH7mWDgDdy1aaWskXizg==","stopRow":"CbiH7mWDgDdy1aaWskXizg=>","batch":-1,"cacheBlocks":true,"totalColumns":8,"maxResultSize":-1,"families":{"d":["ba","bb","c","h"]},"caching":20000,"maxVersions":1,"timeRange":[0,9223372036854775807]}, start row: CbiH7mWDgDdy1aaWskXizg==, end row: CbiH7mWDgDdy1aaWskXizg=>, region location: ip-172-31-15-200.ec2.internal, encoded region name: 4e4d11e77742818f3c7ee4782f787b16)
2017-10-26 14:35:57 DEBUG BlockManager:58 - Getting local block broadcast_64
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire read lock for broadcast_64
2017-10-26 14:35:57 DEBUG BlockManager:58 - Block broadcast_64 was not found
2017-10-26 14:35:57 INFO  TorrentBroadcast:54 - Started reading broadcast variable 64
2017-10-26 14:35:57 DEBUG TorrentBroadcast:58 - Reading piece broadcast_64_piece0 of broadcast_64
2017-10-26 14:35:57 DEBUG BlockManager:58 - Getting local block broadcast_64_piece0 as bytes
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire read lock for broadcast_64_piece0
2017-10-26 14:35:57 DEBUG BlockManager:58 - Getting remote block broadcast_64_piece0
2017-10-26 14:35:57 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:35:57 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5661731853663979389, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 265, cap: 8192)}}
2017-10-26 14:35:57 TRACE TransportClient:239 - Sending request 5661731853663979389 to /172.31.15.200:36445 took 3 ms
2017-10-26 14:35:57 DEBUG BlockManager:58 - Getting remote block broadcast_64_piece0 from BlockManagerId(driver, 172.31.15.200, 36302, None)
2017-10-26 14:35:57 TRACE NettyBlockTransferService:62 - Fetch blocks from 172.31.15.200:36302 (executor id driver)
2017-10-26 14:35:57 TRACE TransportClientFactory:154 - Returning cached connection to /172.31.15.200:36302: TransportClient{remoteAdress=/172.31.15.200:36302, clientId=null, isActive=true}
2017-10-26 14:35:57 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36302
2017-10-26 14:35:57 TRACE TransportClient:239 - Sending request 8376746877995017872 to /172.31.15.200:36302 took 1 ms
2017-10-26 14:35:57 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=8376746877995017872, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 34, cap: 65536)}}
2017-10-26 14:35:57 TRACE OneForOneBlockFetcher:98 - Successfully opened blocks StreamHandle{streamId=24338427065, numChunks=1}, preparing to fetch chunks.
2017-10-26 14:35:57 DEBUG TransportClient:140 - Sending fetch chunk request 0 to /172.31.15.200:36302
2017-10-26 14:35:57 TRACE TransportClient:153 - Sending request StreamChunkId{streamId=24338427065, chunkIndex=0} to /172.31.15.200:36302 took 1 ms
2017-10-26 14:35:57 TRACE MessageDecoder:47 - Received message ChunkFetchSuccess: ChunkFetchSuccess{streamChunkId=StreamChunkId{streamId=24338427065, chunkIndex=0}, buffer=NettyManagedBuffer{buf=DuplicatedAbstractByteBuf(ridx: 21, widx: 32458, cap: 65536, unwrapped: PooledUnsafeDirectByteBuf(ridx: 21, widx: 32458, cap: 65536))}}
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to put broadcast_64_piece0
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire read lock for broadcast_64_piece0
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire write lock for broadcast_64_piece0
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 acquired write lock for broadcast_64_piece0
2017-10-26 14:35:57 INFO  MemoryStore:54 - Block broadcast_64_piece0 stored as bytes in memory (estimated size 31.7 KB, free 366.3 MB)
2017-10-26 14:35:57 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:35:57 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=8425448177283586976, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 8192)}}
2017-10-26 14:35:57 TRACE TransportClient:239 - Sending request 8425448177283586976 to /172.31.15.200:36445 took 4 ms
2017-10-26 14:35:57 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_64_piece0
2017-10-26 14:35:57 DEBUG BlockManager:58 - Told master about block broadcast_64_piece0
2017-10-26 14:35:57 DEBUG BlockManager:58 - Put block broadcast_64_piece0 locally took  10 ms
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 releasing lock for broadcast_64_piece0
2017-10-26 14:35:57 DEBUG BlockManager:58 - Putting block broadcast_64_piece0 without replication took  10 ms
2017-10-26 14:35:57 INFO  TorrentBroadcast:54 - Reading broadcast variable 64 took 18 ms
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to put broadcast_64
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire read lock for broadcast_64
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 trying to acquire write lock for broadcast_64
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 acquired write lock for broadcast_64
2017-10-26 14:35:57 INFO  MemoryStore:54 - Block broadcast_64 stored as values in memory (estimated size 467.2 KB, free 365.8 MB)
2017-10-26 14:35:57 DEBUG BlockManager:58 - Put block broadcast_64 locally took  6 ms
2017-10-26 14:35:57 TRACE BlockInfoManager:62 - Task 62 releasing lock for broadcast_64
2017-10-26 14:35:57 DEBUG BlockManager:58 - Putting block broadcast_64 without replication took  6 ms
2017-10-26 14:35:57 TRACE RetryingCallerInterceptorFactory:79 - Using NoOpRetryableCallerInterceptor for intercepting the RpcRetryingCaller
2017-10-26 14:35:57 TRACE ZKConfig:105 - Skipped reading ZK properties file 'zoo.cfg' since 'hbase.config.read.zookeeper.config' was not set to true
2017-10-26 14:35:57 TRACE ZKUtil:131 - hconnection-0x380de4d9 opening connection to ZooKeeper ensemble=ip-172-31-15-200.ec2.internal:2181
2017-10-26 14:35:57 INFO  RecoverableZooKeeper:120 - Process identifier=hconnection-0x380de4d9 connecting to ZooKeeper ensemble=ip-172-31-15-200.ec2.internal:2181
2017-10-26 14:35:57 INFO  ZooKeeper:438 - Initiating client connection, connectString=ip-172-31-15-200.ec2.internal:2181 sessionTimeout=90000 watcher=org.apache.hadoop.hbase.zookeeper.PendingWatcher@42c2a47c
2017-10-26 14:35:57 INFO  ClientCnxn:975 - Opening socket connection to server ip-172-31-15-200.ec2.internal/172.31.15.200:2181. Will not attempt to authenticate using SASL (unknown error)
2017-10-26 14:35:57 INFO  ClientCnxn:852 - Socket connection established to ip-172-31-15-200.ec2.internal/172.31.15.200:2181, initiating session
2017-10-26 14:35:57 DEBUG ClientCnxn:892 - Session establishment request sent on ip-172-31-15-200.ec2.internal/172.31.15.200:2181
2017-10-26 14:35:57 TRACE ClientCnxnSocket:124 - readConnectResult 37 0x[0,0,0,0,0,0,ffffff9c,40,1,5f,58,fffffff8,17,1a,0,25,0,0,0,10,fffffff7,7b,ffffff80,ffffffb8,ffffffd0,ffffff91,ffffffe3,7b,ffffffa4,31,49,ffffffb2,78,44,ffffffdb,ffffffb5,0,]
2017-10-26 14:35:57 INFO  ClientCnxn:1235 - Session establishment complete on server ip-172-31-15-200.ec2.internal/172.31.15.200:2181, sessionid = 0x15f58f8171a0025, negotiated timeout = 40000
2017-10-26 14:35:57 DEBUG ZooKeeperWatcher:600 - hconnection-0x380de4d90x0, quorum=ip-172-31-15-200.ec2.internal:2181, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2017-10-26 14:35:57 DEBUG ZooKeeperWatcher:663 - hconnection-0x380de4d9-0x15f58f8171a0025 connected
2017-10-26 14:35:57 DEBUG ClientCnxn:818 - Reading reply sessionid:0x15f58f8171a0025, packet:: clientPath:null serverPath:null finished:false header:: 1,3  replyHeader:: 1,744159,0  request:: '/hbase/hbaseid,F  response:: s{17,744053,1508568476660,1509026254236,2,0,0,0,67,0,17} 
2017-10-26 14:35:57 DEBUG ClientCnxn:818 - Reading reply sessionid:0x15f58f8171a0025, packet:: clientPath:null serverPath:null finished:false header:: 2,4  replyHeader:: 2,744159,0  request:: '/hbase/hbaseid,F  response:: #ffffffff000146d61737465723a31363030306ffffffebffffff9476ffffffe73dffffff832550425546a2430633034643938652d356631382d346236622d383739392d373836393438633664366332,s{17,744053,1508568476660,1509026254236,2,0,0,0,67,0,17} 
2017-10-26 14:35:57 TRACE ZKUtil:1968 - hconnection-0x380de4d9-0x15f58f8171a0025, quorum=ip-172-31-15-200.ec2.internal:2181, baseZNode=/hbase Retrieved 42 byte(s) of data from znode /hbase/hbaseid; data=PBUF\x0A$0c04d98e-5f18-4b6b-8...
2017-10-26 14:35:57 DEBUG AbstractRpcClient:116 - Codec=org.apache.hadoop.hbase.codec.KeyValueCodec@7ab2613f, compressor=null, tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000, writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0, fallbackAllowed=false, bind address=null
2017-10-26 14:35:57 INFO  TableInputFormatBase:178 - Input split length: 119 M bytes.
2017-10-26 14:35:57 TRACE ClientScanner:122 - Scan table=flow, startRow=CbiH7mWDgDdy1aaWskXizg==
2017-10-26 14:35:57 TRACE ClientScanner:122 - Scan table=hbase:meta, startRow=flow,CbiH7mWDgDdy1aaWskXizg==,99999999999999
2017-10-26 14:35:57 TRACE ClientSmallReversedScanner:179 - Advancing internal small scanner to startKey at 'flow,CbiH7mWDgDdy1aaWskXizg==,99999999999999'
2017-10-26 14:35:57 TRACE ZooKeeperRegistry:59 - Looking up meta region location in ZK, connection=org.apache.hadoop.hbase.client.ZooKeeperRegistry@235089ff
2017-10-26 14:35:57 DEBUG ClientCnxn:818 - Reading reply sessionid:0x15f58f8171a0025, packet:: clientPath:null serverPath:null finished:false header:: 3,4  replyHeader:: 3,744159,0  request:: '/hbase/meta-region-server,F  response:: #ffffffff0001a726567696f6e7365727665723a3136303230ffffff8d1effffff8878ffffffaaffffffbb35ffffff9550425546a29a1d69702d3137322d33312d31352d3230302e6563322e696e7465726e616c10ffffff947d18ffffff86ffffff88ffffffe2ffffffc7fffffff52b100183,s{744069,744069,1509026271671,1509026271671,0,0,0,0,82,0,744069} 
2017-10-26 14:35:57 TRACE ZKUtil:1968 - hconnection-0x380de4d9-0x15f58f8171a0025, quorum=ip-172-31-15-200.ec2.internal:2181, baseZNode=/hbase Retrieved 51 byte(s) of data from znode /hbase/meta-region-server; data=PBUF\x0A)\x0A\x1Dip-172-31-15...
2017-10-26 14:35:57 DEBUG ClientCnxn:818 - Reading reply sessionid:0x15f58f8171a0025, packet:: clientPath:null serverPath:null finished:false header:: 4,8  replyHeader:: 4,744159,0  request:: '/hbase,F  response:: v{'replication,'meta-region-server,'rs,'splitWAL,'backup-masters,'table-lock,'flush-table-proc,'region-in-transition,'online-snapshot,'switch,'master,'running,'recovering-regions,'draining,'namespace,'hbaseid,'table} 
2017-10-26 14:35:57 TRACE ZooKeeperRegistry:73 - Looked up meta region location, connection=org.apache.hadoop.hbase.client.ZooKeeperRegistry@235089ff; servers = ip-172-31-15-200.ec2.internal,16020,1509026202630 
2017-10-26 14:35:57 TRACE MetaCache:175 - Merged cached locations: [region=hbase:meta,,1.1588230740, hostname=ip-172-31-15-200.ec2.internal,16020,1509026202630, seqNum=0]
2017-10-26 14:35:57 TRACE ZooKeeperRegistry:59 - Looking up meta region location in ZK, connection=org.apache.hadoop.hbase.client.ZooKeeperRegistry@235089ff
2017-10-26 14:35:57 DEBUG ClientCnxn:818 - Reading reply sessionid:0x15f58f8171a0025, packet:: clientPath:null serverPath:null finished:false header:: 5,4  replyHeader:: 5,744159,0  request:: '/hbase/meta-region-server,F  response:: #ffffffff0001a726567696f6e7365727665723a3136303230ffffff8d1effffff8878ffffffaaffffffbb35ffffff9550425546a29a1d69702d3137322d33312d31352d3230302e6563322e696e7465726e616c10ffffff947d18ffffff86ffffff88ffffffe2ffffffc7fffffff52b100183,s{744069,744069,1509026271671,1509026271671,0,0,0,0,82,0,744069} 
2017-10-26 14:35:57 TRACE ZKUtil:1968 - hconnection-0x380de4d9-0x15f58f8171a0025, quorum=ip-172-31-15-200.ec2.internal:2181, baseZNode=/hbase Retrieved 51 byte(s) of data from znode /hbase/meta-region-server; data=PBUF\x0A)\x0A\x1Dip-172-31-15...
2017-10-26 14:35:57 DEBUG ClientCnxn:818 - Reading reply sessionid:0x15f58f8171a0025, packet:: clientPath:null serverPath:null finished:false header:: 6,8  replyHeader:: 6,744159,0  request:: '/hbase,F  response:: v{'replication,'meta-region-server,'rs,'splitWAL,'backup-masters,'table-lock,'flush-table-proc,'region-in-transition,'online-snapshot,'switch,'master,'running,'recovering-regions,'draining,'namespace,'hbaseid,'table} 
2017-10-26 14:35:57 TRACE ZooKeeperRegistry:73 - Looked up meta region location, connection=org.apache.hadoop.hbase.client.ZooKeeperRegistry@235089ff; servers = ip-172-31-15-200.ec2.internal,16020,1509026202630 
2017-10-26 14:35:57 TRACE MetaCache:175 - Merged cached locations: [region=hbase:meta,,1.1588230740, hostname=ip-172-31-15-200.ec2.internal,16020,1509026202630, seqNum=0]
2017-10-26 14:35:57 DEBUG RpcClientImpl:351 - Use SIMPLE authentication for service ClientService, sasl=false
2017-10-26 14:35:57 DEBUG RpcClientImpl:716 - Connecting to ip-172-31-15-200.ec2.internal/172.31.15.200:16020
2017-10-26 14:35:57 TRACE RpcClientImpl:561 - IPC Client (427545599) connection to ip-172-31-15-200.ec2.internal/172.31.15.200:16020 from spark: starting, connections 1
2017-10-26 14:35:57 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 9ms
2017-10-26 14:35:57 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=-1 associated with replica=0
2017-10-26 14:35:57 TRACE MetaCache:175 - Merged cached locations: [region=flow,,1508569108231.4e4d11e77742818f3c7ee4782f787b16., hostname=ip-172-31-15-200.ec2.internal,16020,1509026202630, seqNum=2771]
2017-10-26 14:35:57 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 3ms
2017-10-26 14:35:57 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:35:57 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 135ms
2017-10-26 14:35:57 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:35:57 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 0
2017-10-26 14:35:58 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 146ms
2017-10-26 14:35:58 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:35:58 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:35:58 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 170ms
2017-10-26 14:35:58 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:35:58 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:35:58 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:35:58 TRACE TransportClient:239 - Sending request 7204377861344362286 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:35:58 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=7204377861344362286, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 102, cap: 4096)}}
2017-10-26 14:35:58 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 188ms
2017-10-26 14:35:58 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:35:58 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:35:59 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 138ms
2017-10-26 14:35:59 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:35:59 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:35:59 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 150ms
2017-10-26 14:35:59 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:35:59 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:35:59 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 125ms
2017-10-26 14:35:59 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:35:59 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:35:59 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 159ms
2017-10-26 14:35:59 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:35:59 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:00 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 134ms
2017-10-26 14:36:00 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:00 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:00 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 146ms
2017-10-26 14:36:00 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:00 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:00 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 120ms
2017-10-26 14:36:00 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:00 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:00 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 130ms
2017-10-26 14:36:00 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:00 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:00 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 110ms
2017-10-26 14:36:00 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:00 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:01 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 141ms
2017-10-26 14:36:01 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:01 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:01 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 136ms
2017-10-26 14:36:01 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:01 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:01 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 89ms
2017-10-26 14:36:01 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:01 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:01 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 128ms
2017-10-26 14:36:01 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:01 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:01 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 96ms
2017-10-26 14:36:01 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:01 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 49ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 38ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 41ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 37ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 41ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 38ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 60ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 41ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 35ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 39ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:02 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:02 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:02 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 41ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 39ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 42ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 39ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 42ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 49ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 37ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 37ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:03 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:03 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:03 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 37ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 38ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 37ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 43ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 38ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 35ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 39ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 37ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:04 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 44ms
2017-10-26 14:36:04 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:04 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 39ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2966,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 37ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2965,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 41ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 36ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 42ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2967,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 40ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 38ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 2968,partial != null: true,number of partials so far: 1
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 4ms
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:234 - Setting current scanner as id=155 associated with replica=0
2017-10-26 14:36:05 TRACE ClientScanner:651 - number results from RPC: 233,partial != null: false,number of partials so far: 1
2017-10-26 14:36:05 TRACE ScannerCallableWithReplicas:143 - Closing scanner id=155
2017-10-26 14:36:05 TRACE AbstractRpcClient:236 - Call: Scan, callTime: 0ms
2017-10-26 14:36:05 TRACE ClientScanner:268 - Finished {ENCODED => 4e4d11e77742818f3c7ee4782f787b16, NAME => 'flow,,1508569108231.4e4d11e77742818f3c7ee4782f787b16.', STARTKEY => '', ENDKEY => ''}
2017-10-26 14:36:05 INFO  ConnectionManager$HConnectionImplementation:1720 - Closing zookeeper sessionid=0x15f58f8171a0025
2017-10-26 14:36:05 DEBUG ZooKeeper:673 - Closing session: 0x15f58f8171a0025
2017-10-26 14:36:05 DEBUG ClientCnxn:1306 - Closing client for session: 0x15f58f8171a0025
2017-10-26 14:36:05 DEBUG ClientCnxn:818 - Reading reply sessionid:0x15f58f8171a0025, packet:: clientPath:null serverPath:null finished:false header:: 7,-11  replyHeader:: 7,744160,0  request:: null response:: null
2017-10-26 14:36:05 DEBUG ClientCnxn:1290 - Disconnecting client for session: 0x15f58f8171a0025
2017-10-26 14:36:05 INFO  ZooKeeper:684 - Session: 0x15f58f8171a0025 closed
2017-10-26 14:36:05 INFO  ClientCnxn:512 - EventThread shut down
2017-10-26 14:36:05 DEBUG RpcClientImpl:1160 - Stopping rpc client
2017-10-26 14:36:05 TRACE RpcClientImpl:570 - IPC Client (427545599) connection to ip-172-31-15-200.ec2.internal/172.31.15.200:16020 from spark: interrupted while waiting for call responses
2017-10-26 14:36:05 TRACE RpcClientImpl:1063 - IPC Client (427545599) connection to ip-172-31-15-200.ec2.internal/172.31.15.200:16020 from spark: marking at should close, reason: Origin: InterruptedException
2017-10-26 14:36:05 TRACE RpcClientImpl:860 - IPC Client (427545599) connection to ip-172-31-15-200.ec2.internal/172.31.15.200:16020 from spark: closing ipc connection to ip-172-31-15-200.ec2.internal/172.31.15.200:16020
2017-10-26 14:36:05 TRACE RpcClientImpl:866 - IPC Client (427545599) connection to ip-172-31-15-200.ec2.internal/172.31.15.200:16020 from spark: ipc connection to ip-172-31-15-200.ec2.internal/172.31.15.200:16020 closed
2017-10-26 14:36:05 TRACE RpcClientImpl:583 - IPC Client (427545599) connection to ip-172-31-15-200.ec2.internal/172.31.15.200:16020 from spark: stopped, connections 0
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 62 release 0.0 B from org.apache.spark.util.collection.ExternalSorter@5e4ac
2017-10-26 14:36:05 INFO  Executor:54 - Finished task 0.0 in stage 72.0 (TID 62). 2584 bytes result sent to driver
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message OneWayMessage: OneWayMessage{body=NettyManagedBuffer{buf=CompositeByteBuf(ridx: 5, widx: 7998, cap: 7998, components=2)}}
2017-10-26 14:36:05 INFO  CoarseGrainedExecutorBackend:54 - Got assigned task 63
2017-10-26 14:36:05 INFO  Executor:54 - Running task 0.0 in stage 73.0 (TID 63)
2017-10-26 14:36:05 DEBUG Executor:58 - Task 63's epoch is 41
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Updating epoch to 41 and clearing cache
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_66
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 trying to acquire read lock for broadcast_66
2017-10-26 14:36:05 DEBUG BlockManager:58 - Block broadcast_66 was not found
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Started reading broadcast variable 66
2017-10-26 14:36:05 DEBUG TorrentBroadcast:58 - Reading piece broadcast_66_piece0 of broadcast_66
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_66_piece0 as bytes
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 trying to acquire read lock for broadcast_66_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_66_piece0
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 5563219765355263953 to /172.31.15.200:36445 took 3 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5563219765355263953, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 265, cap: 65536)}}
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_66_piece0 from BlockManagerId(driver, 172.31.15.200, 36302, None)
2017-10-26 14:36:05 TRACE NettyBlockTransferService:62 - Fetch blocks from 172.31.15.200:36302 (executor id driver)
2017-10-26 14:36:05 TRACE TransportClientFactory:154 - Returning cached connection to /172.31.15.200:36302: TransportClient{remoteAdress=/172.31.15.200:36302, clientId=null, isActive=true}
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 6427551152186675066 to /172.31.15.200:36302 took 1 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=6427551152186675066, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 34, cap: 65536)}}
2017-10-26 14:36:05 TRACE OneForOneBlockFetcher:98 - Successfully opened blocks StreamHandle{streamId=24338427066, numChunks=1}, preparing to fetch chunks.
2017-10-26 14:36:05 DEBUG TransportClient:140 - Sending fetch chunk request 0 to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:153 - Sending request StreamChunkId{streamId=24338427066, chunkIndex=0} to /172.31.15.200:36302 took 1 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message ChunkFetchSuccess: ChunkFetchSuccess{streamChunkId=StreamChunkId{streamId=24338427066, chunkIndex=0}, buffer=NettyManagedBuffer{buf=DuplicatedAbstractByteBuf(ridx: 21, widx: 3533, cap: 32768, unwrapped: PooledUnsafeDirectByteBuf(ridx: 21, widx: 3533, cap: 32768))}}
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 trying to put broadcast_66_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 trying to acquire read lock for broadcast_66_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 trying to acquire write lock for broadcast_66_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 acquired write lock for broadcast_66_piece0
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_66_piece0 stored as bytes in memory (estimated size 3.4 KB, free 365.8 MB)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 6900619097775915791 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=6900619097775915791, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 65536)}}
2017-10-26 14:36:05 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_66_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Told master about block broadcast_66_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_66_piece0 locally took  1 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 releasing lock for broadcast_66_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_66_piece0 without replication took  2 ms
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Reading broadcast variable 66 took 10 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 trying to put broadcast_66
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 trying to acquire read lock for broadcast_66
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 trying to acquire write lock for broadcast_66
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 acquired write lock for broadcast_66
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_66 stored as values in memory (estimated size 6.7 KB, free 365.8 MB)
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_66 locally took  1 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 63 releasing lock for broadcast_66
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_66 without replication took  2 ms
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching outputs for shuffle 43, partitions 0-1
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Don't have map outputs for shuffle 43, fetching them
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Doing the fetch; tracker endpoint = NettyRpcEndpointRef(spark://[email protected]:36445)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 4637519653978466708 to /172.31.15.200:36445 took 2 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=4637519653978466708, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 208, cap: 32768)}}
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Got the output locations
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching map output statuses for shuffle 43 took 3 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - maxBytesInFlight: 50331648, targetRequestSize: 10066329
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Getting 1 non-empty blocks out of 1 blocks
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Started 0 remote fetches in 0 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - Got local blocks in  0 ms
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 63 release 0.0 B from org.apache.spark.util.collection.ExternalAppendOnlyMap@44d21cde
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 63 release 0.0 B from org.apache.spark.util.collection.ExternalSorter@1a469996
2017-10-26 14:36:05 INFO  Executor:54 - Finished task 0.0 in stage 73.0 (TID 63). 2876 bytes result sent to driver
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message OneWayMessage: OneWayMessage{body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 13, widx: 8006, cap: 32768)}}
2017-10-26 14:36:05 INFO  CoarseGrainedExecutorBackend:54 - Got assigned task 64
2017-10-26 14:36:05 INFO  Executor:54 - Running task 0.0 in stage 74.0 (TID 64)
2017-10-26 14:36:05 DEBUG Executor:58 - Task 64's epoch is 42
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Updating epoch to 42 and clearing cache
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_67
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 trying to acquire read lock for broadcast_67
2017-10-26 14:36:05 DEBUG BlockManager:58 - Block broadcast_67 was not found
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Started reading broadcast variable 67
2017-10-26 14:36:05 DEBUG TorrentBroadcast:58 - Reading piece broadcast_67_piece0 of broadcast_67
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_67_piece0 as bytes
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 trying to acquire read lock for broadcast_67_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_67_piece0
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 9160490183397739566 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=9160490183397739566, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 265, cap: 16384)}}
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_67_piece0 from BlockManagerId(driver, 172.31.15.200, 36302, None)
2017-10-26 14:36:05 TRACE NettyBlockTransferService:62 - Fetch blocks from 172.31.15.200:36302 (executor id driver)
2017-10-26 14:36:05 TRACE TransportClientFactory:154 - Returning cached connection to /172.31.15.200:36302: TransportClient{remoteAdress=/172.31.15.200:36302, clientId=null, isActive=true}
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 8636729947585057718 to /172.31.15.200:36302 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=8636729947585057718, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 34, cap: 32768)}}
2017-10-26 14:36:05 TRACE OneForOneBlockFetcher:98 - Successfully opened blocks StreamHandle{streamId=24338427067, numChunks=1}, preparing to fetch chunks.
2017-10-26 14:36:05 DEBUG TransportClient:140 - Sending fetch chunk request 0 to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:153 - Sending request StreamChunkId{streamId=24338427067, chunkIndex=0} to /172.31.15.200:36302 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message ChunkFetchSuccess: ChunkFetchSuccess{streamChunkId=StreamChunkId{streamId=24338427067, chunkIndex=0}, buffer=NettyManagedBuffer{buf=DuplicatedAbstractByteBuf(ridx: 21, widx: 4597, cap: 16384, unwrapped: PooledUnsafeDirectByteBuf(ridx: 21, widx: 4597, cap: 16384))}}
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 trying to put broadcast_67_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 trying to acquire read lock for broadcast_67_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 trying to acquire write lock for broadcast_67_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 acquired write lock for broadcast_67_piece0
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_67_piece0 stored as bytes in memory (estimated size 4.5 KB, free 365.8 MB)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 8780313406806570019 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=8780313406806570019, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 16384)}}
2017-10-26 14:36:05 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_67_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Told master about block broadcast_67_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_67_piece0 locally took  1 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 releasing lock for broadcast_67_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_67_piece0 without replication took  2 ms
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Reading broadcast variable 67 took 6 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 trying to put broadcast_67
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 trying to acquire read lock for broadcast_67
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 trying to acquire write lock for broadcast_67
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 acquired write lock for broadcast_67
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_67 stored as values in memory (estimated size 9.6 KB, free 365.8 MB)
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_67 locally took  1 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 64 releasing lock for broadcast_67
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_67 without replication took  1 ms
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching outputs for shuffle 42, partitions 0-1
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Don't have map outputs for shuffle 42, fetching them
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Doing the fetch; tracker endpoint = NettyRpcEndpointRef(spark://[email protected]:36445)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 6728692769359523756 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=6728692769359523756, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 208, cap: 8192)}}
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Got the output locations
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching map output statuses for shuffle 42 took 1 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - maxBytesInFlight: 50331648, targetRequestSize: 10066329
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Getting 1 non-empty blocks out of 1 blocks
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Started 0 remote fetches in 0 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - Got local blocks in  0 ms
2017-10-26 14:36:05 TRACE ClientCnxnSocketNIO:243 - Doing client selector close
2017-10-26 14:36:05 TRACE ClientCnxnSocketNIO:247 - Closed client selector
2017-10-26 14:36:05 TRACE ClientCnxn:71 - SendThread exitedloop.
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 64 release 0.0 B from org.apache.spark.util.collection.ExternalAppendOnlyMap@5b9ee686
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 64 release 0.0 B from org.apache.spark.util.collection.ExternalSorter@216d9138
2017-10-26 14:36:05 INFO  Executor:54 - Finished task 0.0 in stage 74.0 (TID 64). 2877 bytes result sent to driver
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message OneWayMessage: OneWayMessage{body=NettyManagedBuffer{buf=SlicedAbstractByteBuf(ridx: 5, widx: 7998, cap: 7998/7998, unwrapped: PooledUnsafeDirectByteBuf(ridx: 8006, widx: 8192, cap: 8192))}}
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message OneWayMessage: OneWayMessage{body=NettyManagedBuffer{buf=CompositeByteBuf(ridx: 5, widx: 7998, cap: 7998, components=2)}}
2017-10-26 14:36:05 INFO  CoarseGrainedExecutorBackend:54 - Got assigned task 65
2017-10-26 14:36:05 INFO  CoarseGrainedExecutorBackend:54 - Got assigned task 66
2017-10-26 14:36:05 INFO  Executor:54 - Running task 0.0 in stage 75.0 (TID 65)
2017-10-26 14:36:05 DEBUG Executor:58 - Task 65's epoch is 43
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Updating epoch to 43 and clearing cache
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_68
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 trying to acquire read lock for broadcast_68
2017-10-26 14:36:05 DEBUG BlockManager:58 - Block broadcast_68 was not found
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Started reading broadcast variable 68
2017-10-26 14:36:05 DEBUG TorrentBroadcast:58 - Reading piece broadcast_68_piece0 of broadcast_68
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_68_piece0 as bytes
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 trying to acquire read lock for broadcast_68_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_68_piece0
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=6248744083671556522, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 265, cap: 65536)}}
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 6248744083671556522 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_68_piece0 from BlockManagerId(driver, 172.31.15.200, 36302, None)
2017-10-26 14:36:05 TRACE NettyBlockTransferService:62 - Fetch blocks from 172.31.15.200:36302 (executor id driver)
2017-10-26 14:36:05 TRACE TransportClientFactory:154 - Returning cached connection to /172.31.15.200:36302: TransportClient{remoteAdress=/172.31.15.200:36302, clientId=null, isActive=true}
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36302
2017-10-26 14:36:05 INFO  Executor:54 - Running task 1.0 in stage 75.0 (TID 66)
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 4985388871000983015 to /172.31.15.200:36302 took 1 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=4985388871000983015, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 34, cap: 16384)}}
2017-10-26 14:36:05 TRACE OneForOneBlockFetcher:98 - Successfully opened blocks StreamHandle{streamId=24338427068, numChunks=1}, preparing to fetch chunks.
2017-10-26 14:36:05 DEBUG TransportClient:140 - Sending fetch chunk request 0 to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:153 - Sending request StreamChunkId{streamId=24338427068, chunkIndex=0} to /172.31.15.200:36302 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message ChunkFetchSuccess: ChunkFetchSuccess{streamChunkId=StreamChunkId{streamId=24338427068, chunkIndex=0}, buffer=NettyManagedBuffer{buf=DuplicatedAbstractByteBuf(ridx: 21, widx: 4975, cap: 16384, unwrapped: PooledUnsafeDirectByteBuf(ridx: 21, widx: 4975, cap: 16384))}}
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 trying to put broadcast_68_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 trying to acquire read lock for broadcast_68_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 trying to acquire write lock for broadcast_68_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 acquired write lock for broadcast_68_piece0
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_68_piece0 stored as bytes in memory (estimated size 4.8 KB, free 365.8 MB)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 DEBUG Executor:58 - Task 66's epoch is 43
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=9056090485398056249, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 65536)}}
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 9056090485398056249 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_68_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Told master about block broadcast_68_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_68_piece0 locally took  3 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 releasing lock for broadcast_68_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_68_piece0 without replication took  3 ms
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Reading broadcast variable 68 took 8 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 trying to put broadcast_68
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 trying to acquire read lock for broadcast_68
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 trying to acquire write lock for broadcast_68
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 acquired write lock for broadcast_68
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_68 stored as values in memory (estimated size 10.5 KB, free 365.8 MB)
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_68 locally took  0 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 65 releasing lock for broadcast_68
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_68 without replication took  0 ms
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_68
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 66 trying to acquire read lock for broadcast_68
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 66 acquired read lock for broadcast_68
2017-10-26 14:36:05 DEBUG BlockManager:58 - Level for block broadcast_68 is StorageLevel(disk, memory, deserialized, 1 replicas)
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching outputs for shuffle 41, partitions 1-2
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Don't have map outputs for shuffle 41, fetching them
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Doing the fetch; tracker endpoint = NettyRpcEndpointRef(spark://[email protected]:36445)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=4614447181406529793, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 210, cap: 32768)}}
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 4614447181406529793 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Got the output locations
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching map output statuses for shuffle 41 took 3 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - maxBytesInFlight: 50331648, targetRequestSize: 10066329
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Getting 1 non-empty blocks out of 1 blocks
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Started 0 remote fetches in 1 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - Got local blocks in  1 ms
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 66 release 0.0 B from org.apache.spark.util.collection.ExternalAppendOnlyMap@7f6fb9c0
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching outputs for shuffle 41, partitions 0-1
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - maxBytesInFlight: 50331648, targetRequestSize: 10066329
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Getting 1 non-empty blocks out of 1 blocks
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Started 0 remote fetches in 0 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - Got local blocks in  0 ms
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 65 release 0.0 B from org.apache.spark.util.collection.ExternalAppendOnlyMap@518366f5
2017-10-26 14:36:05 INFO  Executor:54 - Finished task 0.0 in stage 75.0 (TID 65). 2877 bytes result sent to driver
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 66 releasing lock for broadcast_68
2017-10-26 14:36:05 INFO  Executor:54 - Finished task 1.0 in stage 75.0 (TID 66). 2062 bytes result sent to driver
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message OneWayMessage: OneWayMessage{body=NettyManagedBuffer{buf=SlicedAbstractByteBuf(ridx: 5, widx: 8009, cap: 8009/8009, unwrapped: PooledUnsafeDirectByteBuf(ridx: 8017, widx: 16034, cap: 32768))}}
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message OneWayMessage: OneWayMessage{body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 8030, widx: 16034, cap: 32768)}}
2017-10-26 14:36:05 INFO  CoarseGrainedExecutorBackend:54 - Got assigned task 67
2017-10-26 14:36:05 INFO  CoarseGrainedExecutorBackend:54 - Got assigned task 68
2017-10-26 14:36:05 INFO  Executor:54 - Running task 0.0 in stage 76.0 (TID 67)
2017-10-26 14:36:05 DEBUG Executor:58 - Task 67's epoch is 44
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Updating epoch to 44 and clearing cache
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_69
2017-10-26 14:36:05 INFO  Executor:54 - Running task 1.0 in stage 76.0 (TID 68)
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 trying to acquire read lock for broadcast_69
2017-10-26 14:36:05 DEBUG BlockManager:58 - Block broadcast_69 was not found
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Started reading broadcast variable 69
2017-10-26 14:36:05 DEBUG TorrentBroadcast:58 - Reading piece broadcast_69_piece0 of broadcast_69
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_69_piece0 as bytes
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 trying to acquire read lock for broadcast_69_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_69_piece0
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=7160522511528243087, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 265, cap: 32768)}}
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 7160522511528243087 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 DEBUG Executor:58 - Task 68's epoch is 44
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_69_piece0 from BlockManagerId(driver, 172.31.15.200, 36302, None)
2017-10-26 14:36:05 TRACE NettyBlockTransferService:62 - Fetch blocks from 172.31.15.200:36302 (executor id driver)
2017-10-26 14:36:05 TRACE TransportClientFactory:154 - Returning cached connection to /172.31.15.200:36302: TransportClient{remoteAdress=/172.31.15.200:36302, clientId=null, isActive=true}
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 4685955560201419597 to /172.31.15.200:36302 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=4685955560201419597, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 34, cap: 16384)}}
2017-10-26 14:36:05 TRACE OneForOneBlockFetcher:98 - Successfully opened blocks StreamHandle{streamId=24338427069, numChunks=1}, preparing to fetch chunks.
2017-10-26 14:36:05 DEBUG TransportClient:140 - Sending fetch chunk request 0 to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:153 - Sending request StreamChunkId{streamId=24338427069, chunkIndex=0} to /172.31.15.200:36302 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message ChunkFetchSuccess: ChunkFetchSuccess{streamChunkId=StreamChunkId{streamId=24338427069, chunkIndex=0}, buffer=NettyManagedBuffer{buf=DuplicatedAbstractByteBuf(ridx: 21, widx: 3252, cap: 8192, unwrapped: PooledUnsafeDirectByteBuf(ridx: 21, widx: 3252, cap: 8192))}}
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 trying to put broadcast_69_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 trying to acquire read lock for broadcast_69_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 trying to acquire write lock for broadcast_69_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 acquired write lock for broadcast_69_piece0
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_69_piece0 stored as bytes in memory (estimated size 3.2 KB, free 365.8 MB)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 9203128082701892040 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=9203128082701892040, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 16384)}}
2017-10-26 14:36:05 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_69_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Told master about block broadcast_69_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_69_piece0 locally took  2 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 releasing lock for broadcast_69_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_69_piece0 without replication took  2 ms
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Reading broadcast variable 69 took 8 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 trying to put broadcast_69
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 trying to acquire read lock for broadcast_69
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 trying to acquire write lock for broadcast_69
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 acquired write lock for broadcast_69
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_69 stored as values in memory (estimated size 5.7 KB, free 365.8 MB)
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_69 locally took  1 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 67 releasing lock for broadcast_69
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_69 without replication took  1 ms
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_69
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 68 trying to acquire read lock for broadcast_69
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 68 acquired read lock for broadcast_69
2017-10-26 14:36:05 DEBUG BlockManager:58 - Level for block broadcast_69 is StorageLevel(disk, memory, deserialized, 1 replicas)
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching outputs for shuffle 40, partitions 1-2
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Don't have map outputs for shuffle 40, fetching them
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Doing the fetch; tracker endpoint = NettyRpcEndpointRef(spark://[email protected]:36445)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 7763609454548873567 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=7763609454548873567, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 217, cap: 16384)}}
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Got the output locations
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching map output statuses for shuffle 40 took 1 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - maxBytesInFlight: 50331648, targetRequestSize: 10066329
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Getting 2 non-empty blocks out of 2 blocks
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Started 0 remote fetches in 1 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - Got local blocks in  1 ms
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 68 release 0.0 B from org.apache.spark.util.collection.ExternalSorter@4eba0a73
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 68 releasing lock for broadcast_69
2017-10-26 14:36:05 INFO  Executor:54 - Finished task 1.0 in stage 76.0 (TID 68). 3277 bytes result sent to driver
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching outputs for shuffle 40, partitions 0-1
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - maxBytesInFlight: 50331648, targetRequestSize: 10066329
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Getting 2 non-empty blocks out of 2 blocks
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Started 0 remote fetches in 0 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - Got local blocks in  0 ms
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 67 release 0.0 B from org.apache.spark.util.collection.ExternalSorter@3e583d41
2017-10-26 14:36:05 INFO  Executor:54 - Finished task 0.0 in stage 76.0 (TID 67). 8619 bytes result sent to driver
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message OneWayMessage: OneWayMessage{body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 13, widx: 8001, cap: 8192)}}
2017-10-26 14:36:05 INFO  CoarseGrainedExecutorBackend:54 - Got assigned task 69
2017-10-26 14:36:05 INFO  Executor:54 - Running task 0.0 in stage 79.0 (TID 69)
2017-10-26 14:36:05 DEBUG Executor:58 - Task 69's epoch is 44
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_70
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 trying to acquire read lock for broadcast_70
2017-10-26 14:36:05 DEBUG BlockManager:58 - Block broadcast_70 was not found
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Started reading broadcast variable 70
2017-10-26 14:36:05 DEBUG TorrentBroadcast:58 - Reading piece broadcast_70_piece0 of broadcast_70
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_70_piece0 as bytes
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 trying to acquire read lock for broadcast_70_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_70_piece0
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 5873275877572088820 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5873275877572088820, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 265, cap: 8192)}}
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_70_piece0 from BlockManagerId(driver, 172.31.15.200, 36302, None)
2017-10-26 14:36:05 TRACE NettyBlockTransferService:62 - Fetch blocks from 172.31.15.200:36302 (executor id driver)
2017-10-26 14:36:05 TRACE TransportClientFactory:154 - Returning cached connection to /172.31.15.200:36302: TransportClient{remoteAdress=/172.31.15.200:36302, clientId=null, isActive=true}
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 8566131326448742404 to /172.31.15.200:36302 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=8566131326448742404, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 34, cap: 8192)}}
2017-10-26 14:36:05 TRACE OneForOneBlockFetcher:98 - Successfully opened blocks StreamHandle{streamId=24338427070, numChunks=1}, preparing to fetch chunks.
2017-10-26 14:36:05 DEBUG TransportClient:140 - Sending fetch chunk request 0 to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:153 - Sending request StreamChunkId{streamId=24338427070, chunkIndex=0} to /172.31.15.200:36302 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message ChunkFetchSuccess: ChunkFetchSuccess{streamChunkId=StreamChunkId{streamId=24338427070, chunkIndex=0}, buffer=NettyManagedBuffer{buf=DuplicatedAbstractByteBuf(ridx: 21, widx: 6858, cap: 8192, unwrapped: PooledUnsafeDirectByteBuf(ridx: 21, widx: 6858, cap: 8192))}}
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 trying to put broadcast_70_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 trying to acquire read lock for broadcast_70_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 trying to acquire write lock for broadcast_70_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 acquired write lock for broadcast_70_piece0
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_70_piece0 stored as bytes in memory (estimated size 6.7 KB, free 365.7 MB)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 5445416917871203358 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5445416917871203358, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 8192)}}
2017-10-26 14:36:05 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_70_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Told master about block broadcast_70_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_70_piece0 locally took  2 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 releasing lock for broadcast_70_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_70_piece0 without replication took  2 ms
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Reading broadcast variable 70 took 7 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 trying to put broadcast_70
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 trying to acquire read lock for broadcast_70
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 trying to acquire write lock for broadcast_70
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 acquired write lock for broadcast_70
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_70 stored as values in memory (estimated size 16.1 KB, free 365.7 MB)
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_70 locally took  0 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 69 releasing lock for broadcast_70
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_70 without replication took  0 ms
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching outputs for shuffle 42, partitions 0-1
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Don't have map outputs for shuffle 42, fetching them
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Doing the fetch; tracker endpoint = NettyRpcEndpointRef(spark://[email protected]:36445)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 9021381798469407306 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=9021381798469407306, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 208, cap: 4096)}}
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Got the output locations
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching map output statuses for shuffle 42 took 1 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - maxBytesInFlight: 50331648, targetRequestSize: 10066329
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Getting 1 non-empty blocks out of 1 blocks
2017-10-26 14:36:05 INFO  ShuffleBlockFetcherIterator:54 - Started 0 remote fetches in 0 ms
2017-10-26 14:36:05 DEBUG ShuffleBlockFetcherIterator:58 - Got local blocks in  0 ms
2017-10-26 14:36:05 DEBUG TaskMemoryManager:194 - Task 69 release 0.0 B from org.apache.spark.util.collection.ExternalAppendOnlyMap@42c7ee31
2017-10-26 14:36:05 INFO  Executor:54 - Finished task 0.0 in stage 79.0 (TID 69). 2876 bytes result sent to driver
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message OneWayMessage: OneWayMessage{body=NettyManagedBuffer{buf=CompositeByteBuf(ridx: 5, widx: 8004, cap: 8004, components=2)}}
2017-10-26 14:36:05 INFO  CoarseGrainedExecutorBackend:54 - Got assigned task 70
2017-10-26 14:36:05 INFO  Executor:54 - Running task 0.0 in stage 80.0 (TID 70)
2017-10-26 14:36:05 DEBUG Executor:58 - Task 70's epoch is 45
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Updating epoch to 45 and clearing cache
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_71
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 trying to acquire read lock for broadcast_71
2017-10-26 14:36:05 DEBUG BlockManager:58 - Block broadcast_71 was not found
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Started reading broadcast variable 71
2017-10-26 14:36:05 DEBUG TorrentBroadcast:58 - Reading piece broadcast_71_piece0 of broadcast_71
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting local block broadcast_71_piece0 as bytes
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 trying to acquire read lock for broadcast_71_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_71_piece0
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 7584380005691466660 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=7666133481595506609, body=NettyManagedBuffer{buf=SlicedAbstractByteBuf(ridx: 13, widx: 1112, cap: 1112/1112, unwrapped: PooledUnsafeDirectByteBuf(ridx: 1120, widx: 2268, cap: 65536))}}
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=7848939825630983764, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 1141, widx: 2268, cap: 65536)}}
2017-10-26 14:36:05 DEBUG BlockManagerSlaveEndpoint:58 - removing shuffle 40
2017-10-26 14:36:05 DEBUG BlockManagerSlaveEndpoint:58 - removing broadcast 68
2017-10-26 14:36:05 DEBUG BlockManager:58 - Removing broadcast 68
2017-10-26 14:36:05 DEBUG BlockManager:58 - Removing block broadcast_68_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_68_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_68_piece0
2017-10-26 14:36:05 DEBUG MemoryStore:58 - Block broadcast_68_piece0 of size 4954 dropped from memory (free 383501421)
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_68_piece0
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=7584380005691466660, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 265, cap: 65536)}}
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 4729492606699978307 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 DEBUG BlockManager:58 - Getting remote block broadcast_71_piece0 from BlockManagerId(driver, 172.31.15.200, 36302, None)
2017-10-26 14:36:05 TRACE NettyBlockTransferService:62 - Fetch blocks from 172.31.15.200:36302 (executor id driver)
2017-10-26 14:36:05 TRACE TransportClientFactory:154 - Returning cached connection to /172.31.15.200:36302: TransportClient{remoteAdress=/172.31.15.200:36302, clientId=null, isActive=true}
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 5400102376109401552 to /172.31.15.200:36302 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5400102376109401552, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 34, cap: 8192)}}
2017-10-26 14:36:05 TRACE OneForOneBlockFetcher:98 - Successfully opened blocks StreamHandle{streamId=24338427071, numChunks=1}, preparing to fetch chunks.
2017-10-26 14:36:05 DEBUG TransportClient:140 - Sending fetch chunk request 0 to /172.31.15.200:36302
2017-10-26 14:36:05 TRACE TransportClient:153 - Sending request StreamChunkId{streamId=24338427071, chunkIndex=0} to /172.31.15.200:36302 took 0 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=4729492606699978307, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 32768)}}
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message ChunkFetchSuccess: ChunkFetchSuccess{streamChunkId=StreamChunkId{streamId=24338427071, chunkIndex=0}, buffer=NettyManagedBuffer{buf=DuplicatedAbstractByteBuf(ridx: 21, widx: 2254, cap: 4096, unwrapped: PooledUnsafeDirectByteBuf(ridx: 21, widx: 2254, cap: 4096))}}
2017-10-26 14:36:05 DEBUG BlockManagerSlaveEndpoint:58 - Done removing shuffle 40, response is true
2017-10-26 14:36:05 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: true to 172.31.15.200:36445
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 trying to put broadcast_71_piece0
2017-10-26 14:36:05 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_68_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Told master about block broadcast_68_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Removing block broadcast_68
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 trying to acquire read lock for broadcast_71_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 trying to acquire write lock for broadcast_71_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 acquired write lock for broadcast_71_piece0
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_68
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_68
2017-10-26 14:36:05 DEBUG MemoryStore:58 - Block broadcast_68 of size 10752 dropped from memory (free 383509940)
2017-10-26 14:36:05 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=7666133481595506609, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=47 cap=64]}} to client /172.31.15.200:36445
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_68
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_71_piece0 stored as bytes in memory (estimated size 2.2 KB, free 365.7 MB)
2017-10-26 14:36:05 DEBUG BlockManagerSlaveEndpoint:58 - Done removing broadcast 68, response is 0
2017-10-26 14:36:05 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: 0 to 172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=7848939825630983764, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=81 cap=128]}} to client /172.31.15.200:36445
2017-10-26 14:36:05 TRACE TransportClient:239 - Sending request 6421707628855602639 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=6421707628855602639, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 32768)}}
2017-10-26 14:36:05 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_71_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Told master about block broadcast_71_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_71_piece0 locally took  8 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 releasing lock for broadcast_71_piece0
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_71_piece0 without replication took  8 ms
2017-10-26 14:36:05 INFO  TorrentBroadcast:54 - Reading broadcast variable 71 took 35 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 trying to put broadcast_71
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 trying to acquire read lock for broadcast_71
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 trying to acquire write lock for broadcast_71
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 acquired write lock for broadcast_71
2017-10-26 14:36:05 INFO  MemoryStore:54 - Block broadcast_71 stored as values in memory (estimated size 3.8 KB, free 365.7 MB)
2017-10-26 14:36:05 DEBUG BlockManager:58 - Put block broadcast_71 locally took  0 ms
2017-10-26 14:36:05 TRACE BlockInfoManager:62 - Task 70 releasing lock for broadcast_71
2017-10-26 14:36:05 DEBUG BlockManager:58 - Putting block broadcast_71 without replication took  0 ms
2017-10-26 14:36:05 DEBUG MapOutputTrackerWorker:58 - Fetching outputs for shuffle 44, partitions 0-1
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Don't have map outputs for shuffle 44, fetching them
2017-10-26 14:36:05 INFO  MapOutputTrackerWorker:54 - Doing the fetch; tracker endpoint = NettyRpcEndpointRef(spark://[email protected]:36445)
2017-10-26 14:36:05 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:05 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=7653853790402738553, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 208, cap: 16384)}}
2017-10-26 14:36:06 TRACE TransportClient:239 - Sending request 7653853790402738553 to /172.31.15.200:36445 took 2 ms
2017-10-26 14:36:06 INFO  MapOutputTrackerWorker:54 - Got the output locations
2017-10-26 14:36:06 DEBUG MapOutputTrackerWorker:58 - Fetching map output statuses for shuffle 44 took 2 ms
2017-10-26 14:36:06 DEBUG ShuffleBlockFetcherIterator:58 - maxBytesInFlight: 50331648, targetRequestSize: 10066329
2017-10-26 14:36:06 INFO  ShuffleBlockFetcherIterator:54 - Getting 1 non-empty blocks out of 1 blocks
2017-10-26 14:36:06 INFO  ShuffleBlockFetcherIterator:54 - Started 0 remote fetches in 0 ms
2017-10-26 14:36:06 DEBUG ShuffleBlockFetcherIterator:58 - Got local blocks in  0 ms
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=8403123557275171907, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1148, cap: 16384)}}
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - removing broadcast 67
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing broadcast 67
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_67_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_67_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_67_piece0
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_67_piece0 of size 4576 dropped from memory (free 383510620)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_67_piece0
2017-10-26 14:36:06 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=6645988095227457805, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 8192)}}
2017-10-26 14:36:06 TRACE TransportClient:239 - Sending request 6645988095227457805 to /172.31.15.200:36445 took 1 ms
2017-10-26 14:36:06 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_67_piece0
2017-10-26 14:36:06 DEBUG BlockManager:58 - Told master about block broadcast_67_piece0
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_67
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_67
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_67
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_67 of size 9856 dropped from memory (free 383520476)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_67
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Done removing broadcast 67, response is 0
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: 0 to 172.31.15.200:36445
2017-10-26 14:36:06 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=8403123557275171907, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=81 cap=128]}} to client /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=5906576166179832118, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1148, cap: 8192)}}
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - removing broadcast 66
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing broadcast 66
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_66_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_66_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_66_piece0
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_66_piece0 of size 3512 dropped from memory (free 383523988)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_66_piece0
2017-10-26 14:36:06 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5238240306191776392, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 4096)}}
2017-10-26 14:36:06 TRACE TransportClient:239 - Sending request 5238240306191776392 to /172.31.15.200:36445 took 2 ms
2017-10-26 14:36:06 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_66_piece0
2017-10-26 14:36:06 DEBUG BlockManager:58 - Told master about block broadcast_66_piece0
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_66
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_66
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_66
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_66 of size 6904 dropped from memory (free 383530892)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_66
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Done removing broadcast 66, response is 0
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: 0 to 172.31.15.200:36445
2017-10-26 14:36:06 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=5906576166179832118, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=81 cap=128]}} to client /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=6035227935010400033, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1148, cap: 4096)}}
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - removing broadcast 65
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing broadcast 65
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_65
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_65
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_65
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_65 of size 8480 dropped from memory (free 383539372)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_65
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_65_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_65_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_65_piece0
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_65_piece0 of size 4654 dropped from memory (free 383544026)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_65_piece0
2017-10-26 14:36:06 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=8787132321718076683, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 4096)}}
2017-10-26 14:36:06 TRACE TransportClient:239 - Sending request 8787132321718076683 to /172.31.15.200:36445 took 4 ms
2017-10-26 14:36:06 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_65_piece0
2017-10-26 14:36:06 DEBUG BlockManager:58 - Told master about block broadcast_65_piece0
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Done removing broadcast 65, response is 0
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: 0 to 172.31.15.200:36445
2017-10-26 14:36:06 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=6035227935010400033, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=81 cap=128]}} to client /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=5055161624983598181, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1148, cap: 2048)}}
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - removing broadcast 70
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing broadcast 70
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_70
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_70
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_70
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_70 of size 16456 dropped from memory (free 383560482)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_70
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_70_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_70_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_70_piece0
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_70_piece0 of size 6837 dropped from memory (free 383567319)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_70_piece0
2017-10-26 14:36:06 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5605942441959484256, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 2048)}}
2017-10-26 14:36:06 TRACE TransportClient:239 - Sending request 5605942441959484256 to /172.31.15.200:36445 took 5 ms
2017-10-26 14:36:06 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_70_piece0
2017-10-26 14:36:06 DEBUG BlockManager:58 - Told master about block broadcast_70_piece0
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Done removing broadcast 70, response is 0
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: 0 to 172.31.15.200:36445
2017-10-26 14:36:06 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=5055161624983598181, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=81 cap=128]}} to client /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=8345653804687834788, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1148, cap: 2048)}}
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - removing broadcast 69
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing broadcast 69
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_69
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_69
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_69
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_69 of size 5816 dropped from memory (free 383573135)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_69
2017-10-26 14:36:06 DEBUG BlockManager:58 - Removing block broadcast_69_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_69_piece0
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_69_piece0
2017-10-26 14:36:06 DEBUG MemoryStore:58 - Block broadcast_69_piece0 of size 3231 dropped from memory (free 383576366)
2017-10-26 14:36:06 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_69_piece0
2017-10-26 14:36:06 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=6651317536227272337, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 2048)}}
2017-10-26 14:36:06 TRACE TransportClient:239 - Sending request 6651317536227272337 to /172.31.15.200:36445 took 3 ms
2017-10-26 14:36:06 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_69_piece0
2017-10-26 14:36:06 DEBUG BlockManager:58 - Told master about block broadcast_69_piece0
2017-10-26 14:36:06 DEBUG TaskMemoryManager:194 - Task 70 release 0.0 B from org.apache.spark.util.collection.ExternalSorter@3c520e3c
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Done removing broadcast 69, response is 0
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: 0 to 172.31.15.200:36445
2017-10-26 14:36:06 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=8345653804687834788, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=81 cap=128]}} to client /172.31.15.200:36445
2017-10-26 14:36:06 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=7450190977428617159, body=NettyManagedBuffer{buf=CompositeByteBuf(ridx: 13, widx: 1112, cap: 1112, components=2)}}
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - removing shuffle 41
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Done removing shuffle 41, response is true
2017-10-26 14:36:06 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: true to 172.31.15.200:36445
2017-10-26 14:36:06 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=7450190977428617159, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=47 cap=64]}} to client /172.31.15.200:36445
2017-10-26 14:36:06 INFO  Executor:54 - Finished task 0.0 in stage 80.0 (TID 70). 11360 bytes result sent to driver
2017-10-26 14:36:08 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:08 TRACE TransportClient:239 - Sending request 7944996239306066861 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:08 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=7944996239306066861, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 102, cap: 16384)}}
2017-10-26 14:36:09 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=8874309013453210216, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1120, cap: 16384)}}
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - removing shuffle 44
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Done removing shuffle 44, response is true
2017-10-26 14:36:09 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=5235505883180342936, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1148, cap: 8192)}}
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: true to 172.31.15.200:36445
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - removing broadcast 64
2017-10-26 14:36:09 DEBUG BlockManager:58 - Removing broadcast 64
2017-10-26 14:36:09 DEBUG BlockManager:58 - Removing block broadcast_64_piece0
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_64_piece0
2017-10-26 14:36:09 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=8874309013453210216, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=47 cap=64]}} to client /172.31.15.200:36445
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_64_piece0
2017-10-26 14:36:09 DEBUG MemoryStore:58 - Block broadcast_64_piece0 of size 32437 dropped from memory (free 383608803)
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_64_piece0
2017-10-26 14:36:09 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:09 TRACE TransportClient:239 - Sending request 8835744167733280191 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:09 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=8835744167733280191, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 8192)}}
2017-10-26 14:36:09 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_64_piece0
2017-10-26 14:36:09 DEBUG BlockManager:58 - Told master about block broadcast_64_piece0
2017-10-26 14:36:09 DEBUG BlockManager:58 - Removing block broadcast_64
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_64
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_64
2017-10-26 14:36:09 DEBUG MemoryStore:58 - Block broadcast_64 of size 478456 dropped from memory (free 384087259)
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_64
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Done removing broadcast 64, response is 0
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: 0 to 172.31.15.200:36445
2017-10-26 14:36:09 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=5235505883180342936, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=81 cap=128]}} to client /172.31.15.200:36445
2017-10-26 14:36:09 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=4842956074532627101, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1120, cap: 4096)}}
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - removing shuffle 42
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Done removing shuffle 42, response is true
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: true to 172.31.15.200:36445
2017-10-26 14:36:09 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=4842956074532627101, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=47 cap=64]}} to client /172.31.15.200:36445
2017-10-26 14:36:09 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=6008732211255900380, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1148, cap: 4096)}}
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - removing broadcast 71
2017-10-26 14:36:09 DEBUG BlockManager:58 - Removing broadcast 71
2017-10-26 14:36:09 DEBUG BlockManager:58 - Removing block broadcast_71
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_71
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_71
2017-10-26 14:36:09 DEBUG MemoryStore:58 - Block broadcast_71 of size 3896 dropped from memory (free 384091155)
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_71
2017-10-26 14:36:09 DEBUG BlockManager:58 - Removing block broadcast_71_piece0
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 trying to acquire write lock for broadcast_71_piece0
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 acquired write lock for broadcast_71_piece0
2017-10-26 14:36:09 DEBUG MemoryStore:58 - Block broadcast_71_piece0 of size 2233 dropped from memory (free 384093388)
2017-10-26 14:36:09 TRACE BlockInfoManager:62 - Task -1024 trying to remove block broadcast_71_piece0
2017-10-26 14:36:09 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:09 TRACE TransportClient:239 - Sending request 5889240717504396093 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:09 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5889240717504396093, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 68, cap: 4096)}}
2017-10-26 14:36:09 DEBUG BlockManagerMaster:58 - Updated info of block broadcast_71_piece0
2017-10-26 14:36:09 DEBUG BlockManager:58 - Told master about block broadcast_71_piece0
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Done removing broadcast 71, response is 0
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: 0 to 172.31.15.200:36445
2017-10-26 14:36:09 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=6008732211255900380, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=81 cap=128]}} to client /172.31.15.200:36445
2017-10-26 14:36:09 TRACE MessageDecoder:47 - Received message RpcRequest: RpcRequest{requestId=7831488172680667717, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 1120, cap: 4096)}}
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - removing shuffle 43
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Done removing shuffle 43, response is true
2017-10-26 14:36:09 DEBUG BlockManagerSlaveEndpoint:58 - Sent response: true to 172.31.15.200:36445
2017-10-26 14:36:09 TRACE TransportRequestHandler:199 - Sent result RpcResponse{requestId=7831488172680667717, body=NioManagedBuffer{buf=java.nio.HeapByteBuffer[pos=0 lim=47 cap=64]}} to client /172.31.15.200:36445
2017-10-26 14:36:18 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:18 TRACE TransportClient:239 - Sending request 4723205548263325490 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:18 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=4723205548263325490, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 102, cap: 4096)}}
2017-10-26 14:36:28 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:28 TRACE TransportClient:239 - Sending request 4860935457710495741 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:28 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=4860935457710495741, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 102, cap: 2048)}}
2017-10-26 14:36:38 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:38 TRACE TransportClient:239 - Sending request 9080721171014231694 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:38 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=9080721171014231694, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 102, cap: 2048)}}
2017-10-26 14:36:48 TRACE TransportClient:226 - Sending RPC to /172.31.15.200:36445
2017-10-26 14:36:48 TRACE TransportClient:239 - Sending request 5340672125322937760 to /172.31.15.200:36445 took 0 ms
2017-10-26 14:36:48 TRACE MessageDecoder:47 - Received message RpcResponse: RpcResponse{requestId=5340672125322937760, body=NettyManagedBuffer{buf=PooledUnsafeDirectByteBuf(ridx: 21, widx: 102, cap: 1024)}}