You are viewing a plain text version of this content. The canonical link for it is here.

Posted to user@spark.apache.org by Darren Hoo <da...@gmail.com> on 2015/03/18 06:39:05 UTC

[spark-streaming] can shuffle write to disk be disabled?

I use spark-streaming reading  messages from a Kafka,  the producer creates
messages about 1500 per second

     def hash(x: String): Int = {

        MurmurHash3.stringHash(x)

     }


     val stream = KafkaUtils.createStream(ssc, zkQuorum, group, topicMap,
StorageLevel.MEMORY_ONLY_SER).map(_._2)


     val clickstream = stream.map(log => {

       //parse log

       ...

      (hash(log.url), HashSet(hash(log.userid)))

    }).window(Seconds(60), Seconds(3))


    val upv = clickstream.transform( rdd => rdd.reduceByKey(_ ++ _ ).map{
case(url, visits) => {

         val uv = visits.size

         (uv, url)

    }})


    upv.foreach(rdd => println(new Date() +
"\n---------------------------------------\n" + rdd.top(20).mkString("\n")
+ "\n"))


it is quite quick upon startup, but after running for a few minutes, it
goes slower and slower and the latency can be minutes.


I found a lot of shuffle writes at /tmp/spark-xxxx in several gigabytes.


with 1500 qps of message and window size of 60 seconds, I think it should
be done within memory without writing to disk at all


I've set executor-memory to 8G, So there is plenty of memory.


$SPARK_HOME/bin/spark-submit \

  --class "SimpleApp" \

  --master spark://localhost:7077 \

  --driver-memory 16G  \

  --executor-memory 8G  \

  target/scala-2.10/simple-assembly-1.0.jar


I also tries these settings, but it still spill to disk.


spark.master                     spark://localhost:7077

#spark.driver.memory              4g

#spark.shuffle.file.buffer.kb     4096

#spark.shuffle.memoryFraction     0.8

#spark.storage.unrollFraction     0.8

#spark.storage.unrollMemoryThreshold 1073741824

spark.io.compression.codec       lz4

spark.shuffle.spill              false

spark.serializer                 org.apache.spark.serializer.KryoSerializer


where am I wrong?

RE: [spark-streaming] can shuffle write to disk be disabled?

Posted by "Shao, Saisai" <sa...@intel.com>.

Please see the inline comments.

Thanks
Jerry

From: Darren Hoo [mailto:darren.hoo@gmail.com]
Sent: Wednesday, March 18, 2015 9:30 PM
To: Shao, Saisai
Cc: user@spark.apache.org; Akhil Das
Subject: Re: [spark-streaming] can shuffle write to disk be disabled?

On Wed, Mar 18, 2015 at 8:31 PM, Shao, Saisai <sa...@intel.com>> wrote:

>From the log you pasted I think this (-rw-r--r--  1 root root  80K Mar 18 16:54 shuffle_47_519_0.data) is not shuffle spilled data, but the final shuffle result.

why the shuffle result  is written to disk?

This is the internal mechanism for Spark.

As I said, did you think shuffle is the bottleneck which makes your job running slowly?

I am quite new to spark, So I am just doing wild guesses. which information should I provide further that
can help to find the real bottleneck?

You can monitor the system metrics, as well as JVM, also information from web UI is very useful.

Maybe you should identify the cause at first. Besides from the log it looks your memory is not enough the cache the data, maybe you should increase the memory size of the executor.

 running two executors, the memory ussage is quite low:

executor 0  8.6 MB / 4.1 GB
executor 1  23.9 MB / 4.1 GB
<driver>     0.0B / 529.9 MB

submitted with args : --executor-memory 8G  --num-executors 2 --driver-memory 1G

Re: [spark-streaming] can shuffle write to disk be disabled?

Posted by Darren Hoo <da...@gmail.com>.

On Wed, Mar 18, 2015 at 8:31 PM, Shao, Saisai <sa...@intel.com> wrote:

>  From the log you pasted I think this (-rw-r--r--  1 root root  80K Mar
> 18 16:54 shuffle_47_519_0.data) is not shuffle spilled data, but the
> final shuffle result.
>

why the shuffle result  is written to disk?


> As I said, did you think shuffle is the bottleneck which makes your job
> running slowly?
>

I am quite new to spark, So I am just doing wild guesses. which information
should I provide further that
can help to find the real bottleneck?

Maybe you should identify the cause at first. Besides from the log it looks
> your memory is not enough the cache the data, maybe you should increase the
> memory size of the executor.
>
>
>

 running two executors, the memory ussage is quite low:

executor 0  8.6 MB / 4.1 GB
executor 1  23.9 MB / 4.1 GB
<driver>     0.0B / 529.9 MB

submitted with args : --executor-memory 8G  --num-executors 2
--driver-memory 1G

RE: [spark-streaming] can shuffle write to disk be disabled?

Posted by "Shao, Saisai" <sa...@intel.com>.

>From the log you pasted I think this (-rw-r--r--  1 root root  80K Mar 18 16:54 shuffle_47_519_0.data) is not shuffle spilled data, but the final shuffle result. As I said, did you think shuffle is the bottleneck which makes your job running slowly? Maybe you should identify the cause at first. Besides from the log it looks your memory is not enough the cache the data, maybe you should increase the memory size of the executor.

Thanks

Jerry

From: Darren Hoo [mailto:darren.hoo@gmail.com]
Sent: Wednesday, March 18, 2015 6:41 PM
To: Akhil Das
Cc: user@spark.apache.org
Subject: Re: [spark-streaming] can shuffle write to disk be disabled?

I've already done that:

>From SparkUI Environment  Spark properties has:

spark.shuffle.spill

false

On Wed, Mar 18, 2015 at 6:34 PM, Akhil Das <ak...@sigmoidanalytics.com>> wrote:
I think you can disable it with spark.shuffle.spill=false

Thanks
Best Regards

On Wed, Mar 18, 2015 at 3:39 PM, Darren Hoo <da...@gmail.com>> wrote:
Thanks, Shao

On Wed, Mar 18, 2015 at 3:34 PM, Shao, Saisai <sa...@intel.com>> wrote:
Yeah, as I said your job processing time is much larger than the sliding window, and streaming job is executed one by one in sequence, so the next job will wait until the first job is finished, so the total latency will be accumulated.

I think you need to identify the bottleneck of your job at first. If the shuffle is so slow, you could enlarge the shuffle fraction of memory to reduce the spill, but finally the shuffle data will be written to disk, this cannot be disabled, unless you mount your spark.tmp.dir on ramdisk.

I have increased spark.shuffle.memoryFraction  to  0.8  which I can see from SparKUI's environment variables

But spill  always happens even from start when latency is less than slide window(I changed it to 10 seconds),
the shuflle data disk written is really a snow ball effect,  it slows down eventually.

I noticed that the files spilled to disk are all very small in size but huge in numbers:

total 344K

drwxr-xr-x  2 root root 4.0K Mar 18 16:55 .

drwxr-xr-x 66 root root 4.0K Mar 18 16:39 ..

-rw-r--r--  1 root root  80K Mar 18 16:54 shuffle_47_519_0.data

-rw-r--r--  1 root root  75K Mar 18 16:54 shuffle_48_419_0.data

-rw-r--r--  1 root root  36K Mar 18 16:54 shuffle_48_518_0.data

-rw-r--r--  1 root root  69K Mar 18 16:55 shuffle_49_319_0.data

-rw-r--r--  1 root root  330 Mar 18 16:55 shuffle_49_418_0.data

-rw-r--r--  1 root root  65K Mar 18 16:55 shuffle_49_517_0.data

MemStore says:

15/03/18 17:59:43 WARN MemoryStore: Failed to reserve initial memory threshold of 1024.0 KB for computing block rdd_1338_2 in memory.

15/03/18 17:59:43 WARN MemoryStore: Not enough space to cache rdd_1338_2 in memory! (computed 512.0 B so far)

15/03/18 17:59:43 INFO MemoryStore: Memory use = 529.0 MB (blocks) + 0.0 B (scratch space shared across 0 thread(s)) = 529.0 MB. Storage limit = 529.9 MB.
Not enough space even for 512 byte??

The executors still has plenty free memory:
0

       slave1:40778

0

      0.0 B / 529.9 MB

0.0 B

16

0

15047

15063

2.17 h

0.0 B

402.3 MB

768.0 B

1

slave2:50452

0

0.0 B / 529.9 MB

0.0 B

16

0

14447

14463

2.17 h

0.0 B

388.8 MB

1248.0 B

1

lvs02:47325

       116

27.6 MB / 529.9 MB

0.0 B

8

0

58169

58177

3.16 h

893.5 MB

624.0 B

1189.9 MB

<driver>

lvs02:47041

0

0.0 B / 529.9 MB

0.0 B

0

0

0

0

0 ms

0.0 B

0.0 B

0.0 B

Besides if CPU or network is the bottleneck, you might need to add more resources to your cluster.

 3 dedicated servers each with CPU 16 cores + 16GB memory and Gigabyte network.
 CPU load is quite low , about 1~3 from top,  and network usage  is far from saturated.

 I don't even  do any usefull complex calculations in this small Simple App yet.

Re: [spark-streaming] can shuffle write to disk be disabled?

Posted by Darren Hoo <da...@gmail.com>.

I've already done that:

>From SparkUI Environment  Spark properties has:

spark.shuffle.spillfalse

On Wed, Mar 18, 2015 at 6:34 PM, Akhil Das <ak...@sigmoidanalytics.com>
wrote:

> I think you can disable it with spark.shuffle.spill=false
>
> Thanks
> Best Regards
>
> On Wed, Mar 18, 2015 at 3:39 PM, Darren Hoo <da...@gmail.com> wrote:
>
>> Thanks, Shao
>>
>> On Wed, Mar 18, 2015 at 3:34 PM, Shao, Saisai <sa...@intel.com>
>> wrote:
>>
>>>  Yeah, as I said your job processing time is much larger than the
>>> sliding window, and streaming job is executed one by one in sequence, so
>>> the next job will wait until the first job is finished, so the total
>>> latency will be accumulated.
>>>
>>>
>>>
>>> I think you need to identify the bottleneck of your job at first. If the
>>> shuffle is so slow, you could enlarge the shuffle fraction of memory to
>>> reduce the spill, but finally the shuffle data will be written to disk,
>>> this cannot be disabled, unless you mount your spark.tmp.dir on ramdisk.
>>>
>>>
>>>
>> I have increased spark.shuffle.memoryFraction  to  0.8  which I can see
>> from SparKUI's environment variables
>>
>> But spill  always happens even from start when latency is less than slide
>> window(I changed it to 10 seconds),
>> the shuflle data disk written is really a snow ball effect,  it slows
>> down eventually.
>>
>> I noticed that the files spilled to disk are all very small in size but
>> huge in numbers:
>>
>> total 344K
>>
>> drwxr-xr-x  2 root root 4.0K Mar 18 16:55 .
>>
>> drwxr-xr-x 66 root root 4.0K Mar 18 16:39 ..
>>
>> -rw-r--r--  1 root root  80K Mar 18 16:54 shuffle_47_519_0.data
>>
>> -rw-r--r--  1 root root  75K Mar 18 16:54 shuffle_48_419_0.data
>>
>> -rw-r--r--  1 root root  36K Mar 18 16:54 shuffle_48_518_0.data
>>
>> -rw-r--r--  1 root root  69K Mar 18 16:55 shuffle_49_319_0.data
>>
>> -rw-r--r--  1 root root  330 Mar 18 16:55 shuffle_49_418_0.data
>>
>> -rw-r--r--  1 root root  65K Mar 18 16:55 shuffle_49_517_0.data
>>
>> MemStore says:
>>
>> 15/03/18 17:59:43 WARN MemoryStore: Failed to reserve initial memory threshold of 1024.0 KB for computing block rdd_1338_2 in memory.
>> 15/03/18 17:59:43 WARN MemoryStore: Not enough space to cache rdd_1338_2 in memory! (computed 512.0 B so far)
>> 15/03/18 17:59:43 INFO MemoryStore: Memory use = 529.0 MB (blocks) + 0.0 B (scratch space shared across 0 thread(s)) = 529.0 MB. Storage limit = 529.9 MB.
>>
>> Not enough space even for 512 byte??
>>
>>
>> The executors still has plenty free memory:
>> 0        slave1:40778 0       0.0 B / 529.9 MB  0.0 B 16 0 15047 15063 2.17
>> h  0.0 B  402.3 MB  768.0 B
>> 1 slave2:50452 0 0.0 B / 529.9 MB  0.0 B 16 0 14447 14463 2.17 h  0.0 B
>> 388.8 MB  1248.0 B
>>
>>     1 lvs02:47325        116 27.6 MB / 529.9 MB  0.0 B 8 0 58169 58177 3.16
>> h  893.5 MB  624.0 B  1189.9 MB
>>
>>     <driver> lvs02:47041 0 0.0 B / 529.9 MB  0.0 B 0 0 0 0 0 ms  0.0 B
>> 0.0 B  0.0 B
>>
>>
>> Besides if CPU or network is the bottleneck, you might need to add more
>>> resources to your cluster.
>>>
>>>
>>>
>>  3 dedicated servers each with CPU 16 cores + 16GB memory and Gigabyte
>> network.
>>  CPU load is quite low , about 1~3 from top,  and network usage  is far
>> from saturated.
>>
>>  I don't even  do any usefull complex calculations in this small Simple
>> App yet.
>>
>>
>>
>

Re: [spark-streaming] can shuffle write to disk be disabled?

Posted by Akhil Das <ak...@sigmoidanalytics.com>.

I think you can disable it with spark.shuffle.spill=false

Thanks
Best Regards

On Wed, Mar 18, 2015 at 3:39 PM, Darren Hoo <da...@gmail.com> wrote:

> Thanks, Shao
>
> On Wed, Mar 18, 2015 at 3:34 PM, Shao, Saisai <sa...@intel.com>
> wrote:
>
>>  Yeah, as I said your job processing time is much larger than the
>> sliding window, and streaming job is executed one by one in sequence, so
>> the next job will wait until the first job is finished, so the total
>> latency will be accumulated.
>>
>>
>>
>> I think you need to identify the bottleneck of your job at first. If the
>> shuffle is so slow, you could enlarge the shuffle fraction of memory to
>> reduce the spill, but finally the shuffle data will be written to disk,
>> this cannot be disabled, unless you mount your spark.tmp.dir on ramdisk.
>>
>>
>>
> I have increased spark.shuffle.memoryFraction  to  0.8  which I can see
> from SparKUI's environment variables
>
> But spill  always happens even from start when latency is less than slide
> window(I changed it to 10 seconds),
> the shuflle data disk written is really a snow ball effect,  it slows down
> eventually.
>
> I noticed that the files spilled to disk are all very small in size but
> huge in numbers:
>
> total 344K
>
> drwxr-xr-x  2 root root 4.0K Mar 18 16:55 .
>
> drwxr-xr-x 66 root root 4.0K Mar 18 16:39 ..
>
> -rw-r--r--  1 root root  80K Mar 18 16:54 shuffle_47_519_0.data
>
> -rw-r--r--  1 root root  75K Mar 18 16:54 shuffle_48_419_0.data
>
> -rw-r--r--  1 root root  36K Mar 18 16:54 shuffle_48_518_0.data
>
> -rw-r--r--  1 root root  69K Mar 18 16:55 shuffle_49_319_0.data
>
> -rw-r--r--  1 root root  330 Mar 18 16:55 shuffle_49_418_0.data
>
> -rw-r--r--  1 root root  65K Mar 18 16:55 shuffle_49_517_0.data
>
> MemStore says:
>
> 15/03/18 17:59:43 WARN MemoryStore: Failed to reserve initial memory threshold of 1024.0 KB for computing block rdd_1338_2 in memory.
> 15/03/18 17:59:43 WARN MemoryStore: Not enough space to cache rdd_1338_2 in memory! (computed 512.0 B so far)
> 15/03/18 17:59:43 INFO MemoryStore: Memory use = 529.0 MB (blocks) + 0.0 B (scratch space shared across 0 thread(s)) = 529.0 MB. Storage limit = 529.9 MB.
>
> Not enough space even for 512 byte??
>
>
> The executors still has plenty free memory:
> 0        slave1:40778 0       0.0 B / 529.9 MB  0.0 B 16 0 15047 15063 2.17
> h  0.0 B  402.3 MB  768.0 B
> 1 slave2:50452 0 0.0 B / 529.9 MB  0.0 B 16 0 14447 14463 2.17 h  0.0 B
> 388.8 MB  1248.0 B
>
>     1 lvs02:47325        116 27.6 MB / 529.9 MB  0.0 B 8 0 58169 58177 3.16
> h  893.5 MB  624.0 B  1189.9 MB
>
>     <driver> lvs02:47041 0 0.0 B / 529.9 MB  0.0 B 0 0 0 0 0 ms  0.0 B
> 0.0 B  0.0 B
>
>
> Besides if CPU or network is the bottleneck, you might need to add more
>> resources to your cluster.
>>
>>
>>
>  3 dedicated servers each with CPU 16 cores + 16GB memory and Gigabyte
> network.
>  CPU load is quite low , about 1~3 from top,  and network usage  is far
> from saturated.
>
>  I don't even  do any usefull complex calculations in this small Simple
> App yet.
>
>
>

Re: [spark-streaming] can shuffle write to disk be disabled?

Posted by Darren Hoo <da...@gmail.com>.

Thanks, Shao

On Wed, Mar 18, 2015 at 3:34 PM, Shao, Saisai <sa...@intel.com> wrote:

>  Yeah, as I said your job processing time is much larger than the sliding
> window, and streaming job is executed one by one in sequence, so the next
> job will wait until the first job is finished, so the total latency will be
> accumulated.
>
>
>
> I think you need to identify the bottleneck of your job at first. If the
> shuffle is so slow, you could enlarge the shuffle fraction of memory to
> reduce the spill, but finally the shuffle data will be written to disk,
> this cannot be disabled, unless you mount your spark.tmp.dir on ramdisk.
>
>
>
I have increased spark.shuffle.memoryFraction  to  0.8  which I can see
from SparKUI's environment variables

But spill  always happens even from start when latency is less than slide
window(I changed it to 10 seconds),
the shuflle data disk written is really a snow ball effect,  it slows down
eventually.

I noticed that the files spilled to disk are all very small in size but
huge in numbers:

total 344K

drwxr-xr-x  2 root root 4.0K Mar 18 16:55 .

drwxr-xr-x 66 root root 4.0K Mar 18 16:39 ..

-rw-r--r--  1 root root  80K Mar 18 16:54 shuffle_47_519_0.data

-rw-r--r--  1 root root  75K Mar 18 16:54 shuffle_48_419_0.data

-rw-r--r--  1 root root  36K Mar 18 16:54 shuffle_48_518_0.data

-rw-r--r--  1 root root  69K Mar 18 16:55 shuffle_49_319_0.data

-rw-r--r--  1 root root  330 Mar 18 16:55 shuffle_49_418_0.data

-rw-r--r--  1 root root  65K Mar 18 16:55 shuffle_49_517_0.data

MemStore says:

15/03/18 17:59:43 WARN MemoryStore: Failed to reserve initial memory
threshold of 1024.0 KB for computing block rdd_1338_2 in memory.
15/03/18 17:59:43 WARN MemoryStore: Not enough space to cache
rdd_1338_2 in memory! (computed 512.0 B so far)
15/03/18 17:59:43 INFO MemoryStore: Memory use = 529.0 MB (blocks) +
0.0 B (scratch space shared across 0 thread(s)) = 529.0 MB. Storage
limit = 529.9 MB.

Not enough space even for 512 byte??


The executors still has plenty free memory:
0        slave1:40778 0       0.0 B / 529.9 MB  0.0 B 16 0 15047 15063 2.17
h  0.0 B  402.3 MB  768.0 B
1 slave2:50452 0 0.0 B / 529.9 MB  0.0 B 16 0 14447 14463 2.17 h  0.0 B
388.8 MB  1248.0 B

    1 lvs02:47325        116 27.6 MB / 529.9 MB  0.0 B 8 0 58169 58177 3.16
h  893.5 MB  624.0 B  1189.9 MB

    <driver> lvs02:47041 0 0.0 B / 529.9 MB  0.0 B 0 0 0 0 0 ms  0.0 B  0.0
B  0.0 B


Besides if CPU or network is the bottleneck, you might need to add more
> resources to your cluster.
>
>
>
 3 dedicated servers each with CPU 16 cores + 16GB memory and Gigabyte
network.
 CPU load is quite low , about 1~3 from top,  and network usage  is far
from saturated.

 I don't even  do any usefull complex calculations in this small Simple App
yet.

RE: [spark-streaming] can shuffle write to disk be disabled?

Posted by "Shao, Saisai" <sa...@intel.com>.

Yeah, as I said your job processing time is much larger than the sliding window, and streaming job is executed one by one in sequence, so the next job will wait until the first job is finished, so the total latency will be accumulated.

I think you need to identify the bottleneck of your job at first. If the shuffle is so slow, you could enlarge the shuffle fraction of memory to reduce the spill, but finally the shuffle data will be written to disk, this cannot be disabled, unless you mount your spark.tmp.dir on ramdisk.

Besides if CPU or network is the bottleneck, you might need to add more resources to your cluster.

Thanks
Jerry

From: Darren Hoo [mailto:darren.hoo@gmail.com]
Sent: Wednesday, March 18, 2015 3:24 PM
To: Shao, Saisai
Cc: user@spark.apache.org
Subject: Re: [spark-streaming] can shuffle write to disk be disabled?

Hi, Saisai

Here is the duration of one of the jobs, 22 seconds in total, it is longer than the sliding window.

Stage Id  Description                   Submitted             Duration    Tasks: Succeeded/Total Input     Output     Shuffle Read  Shuffle Write
342         foreach at SimpleApp.scala:58   2015/03/18 15:06:58   16 s         288/288                                    10.6 MB
341       window at SimpleApp.scala:51    2015/03/18 15:06:52     6s           288/288               12.3 MB                              10.6 MB

And part of the driver log:


15/03/18 15:16:36 INFO DStreamGraph: Cleared checkpoint data for time 1426662996000 ms

15/03/18 15:16:36 INFO ReceivedBlockTracker: Deleting batches ArrayBuffer(1426662932000 ms)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 81.0 in stage 392.0 (TID 100515, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 75.0 in stage 392.0 (TID 100509) in 370 ms on lvs02 (75/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 82.0 in stage 392.0 (TID 100516, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 77.0 in stage 392.0 (TID 100511) in 261 ms on lvs02 (76/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 83.0 in stage 392.0 (TID 100517, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 78.0 in stage 392.0 (TID 100512) in 274 ms on lvs02 (77/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 84.0 in stage 392.0 (TID 100518, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 74.0 in stage 392.0 (TID 100508) in 569 ms on lvs02 (78/291)

15/03/18 15:16:36 INFO BlockManagerInfo: Added input-0-1426662996000 in memory on lvs02:38954 (size: 398.3 KB, free: 1073.7 MB)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 85.0 in stage 392.0 (TID 100519, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 76.0 in stage 392.0 (TID 100510) in 539 ms on lvs02 (79/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 86.0 in stage 392.0 (TID 100520, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 80.0 in stage 392.0 (TID 100514) in 296 ms on lvs02 (80/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 87.0 in stage 392.0 (TID 100521, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 81.0 in stage 392.0 (TID 100515) in 292 ms on lvs02 (81/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 88.0 in stage 392.0 (TID 100522, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 82.0 in stage 392.0 (TID 100516) in 331 ms on lvs02 (82/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 89.0 in stage 392.0 (TID 100523, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 83.0 in stage 392.0 (TID 100517) in 271 ms on lvs02 (83/291)

15/03/18 15:16:36 INFO BlockManagerInfo: Added input-0-1426662996200 in memory on lvs02:38954 (size: 31.0 KB, free: 1073.7 MB)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 90.0 in stage 392.0 (TID 100524, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 79.0 in stage 392.0 (TID 100513) in 549 ms on lvs02 (84/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 91.0 in stage 392.0 (TID 100525, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 84.0 in stage 392.0 (TID 100518) in 327 ms on lvs02 (85/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 92.0 in stage 392.0 (TID 100526, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 86.0 in stage 392.0 (TID 100520) in 293 ms on lvs02 (86/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 93.0 in stage 392.0 (TID 100527, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 87.0 in stage 392.0 (TID 100521) in 257 ms on lvs02 (87/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 94.0 in stage 392.0 (TID 100528, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 90.0 in stage 392.0 (TID 100524) in 244 ms on lvs02 (88/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 95.0 in stage 392.0 (TID 100529, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 85.0 in stage 392.0 (TID 100519) in 455 ms on lvs02 (89/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 96.0 in stage 392.0 (TID 100530, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 89.0 in stage 392.0 (TID 100523) in 358 ms on lvs02 (90/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 97.0 in stage 392.0 (TID 100531, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 88.0 in stage 392.0 (TID 100522) in 548 ms on lvs02 (91/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 98.0 in stage 392.0 (TID 100532, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 92.0 in stage 392.0 (TID 100526) in 363 ms on lvs02 (92/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 99.0 in stage 392.0 (TID 100533, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 93.0 in stage 392.0 (TID 100527) in 388 ms on lvs02 (93/291)

15/03/18 15:16:37 INFO MappedDStream: Slicing from 1426662938000 ms to 1426662997000 ms (aligned to 1426662938000 ms and 1426662997000 ms)

15/03/18 15:16:37 INFO JobScheduler: Added jobs for time 1426662997000 ms

15/03/18 15:16:37 INFO JobGenerator: Checkpointing graph for time 1426662997000 ms

15/03/18 15:16:37 INFO DStreamGraph: Updating checkpoint data for time 1426662997000 ms

15/03/18 15:16:37 INFO DStreamGraph: Updated checkpoint data for time 1426662997000 ms

15/03/18 15:16:37 INFO CheckpointWriter: Saving checkpoint for time 1426662997000 ms to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426662997000'

15/03/18 15:16:37 INFO CheckpointWriter: Deleting file:/home/hyg/simple/checkpoint/checkpoint-1426662987000

15/03/18 15:16:37 INFO CheckpointWriter: Checkpoint for time 1426662997000 ms saved to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426662997000', took 8741 bytes and 7 ms

15/03/18 15:16:37 INFO DStreamGraph: Clearing checkpoint data for time 1426662997000 ms

15/03/18 15:16:37 INFO DStreamGraph: Cleared checkpoint data for time 1426662997000 ms

15/03/18 15:16:37 INFO ReceivedBlockTracker: Deleting batches ArrayBuffer(1426662933000 ms)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662996800 in memory on lvs02:38954 (size: 891.8 KB, free: 1072.8 MB)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 100.0 in stage 392.0 (TID 100534, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 96.0 in stage 392.0 (TID 100530) in 289 ms on lvs02 (94/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 101.0 in stage 392.0 (TID 100535, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 91.0 in stage 392.0 (TID 100525) in 603 ms on lvs02 (95/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 102.0 in stage 392.0 (TID 100536, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 94.0 in stage 392.0 (TID 100528) in 445 ms on lvs02 (96/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 103.0 in stage 392.0 (TID 100537, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 95.0 in stage 392.0 (TID 100529) in 473 ms on lvs02 (97/291)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662997000 in memory on lvs02:38954 (size: 64.8 KB, free: 1072.8 MB)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 104.0 in stage 392.0 (TID 100538, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 98.0 in stage 392.0 (TID 100532) in 343 ms on lvs02 (98/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 105.0 in stage 392.0 (TID 100539, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 97.0 in stage 392.0 (TID 100531) in 378 ms on lvs02 (99/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 106.0 in stage 392.0 (TID 100540, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 101.0 in stage 392.0 (TID 100535) in 296 ms on lvs02 (100/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 107.0 in stage 392.0 (TID 100541, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 99.0 in stage 392.0 (TID 100533) in 420 ms on lvs02 (101/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 108.0 in stage 392.0 (TID 100542, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 100.0 in stage 392.0 (TID 100534) in 359 ms on lvs02 (102/291)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662997200 in memory on lvs02:38954 (size: 378.0 KB, free: 1072.4 MB)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662997400 in memory on lvs02:38954 (size: 68.5 KB, free: 1072.3 MB)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 109.0 in stage 392.0 (TID 100543, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 110.0 in stage 392.0 (TID 100544, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 104.0 in stage 392.0 (TID 100538) in 410 ms on lvs02 (103/291)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 102.0 in stage 392.0 (TID 100536) in 569 ms on lvs02 (104/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 111.0 in stage 392.0 (TID 100545, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 103.0 in stage 392.0 (TID 100537) in 511 ms on lvs02 (105/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 112.0 in stage 392.0 (TID 100546, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 108.0 in stage 392.0 (TID 100542) in 302 ms on lvs02 (106/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 113.0 in stage 392.0 (TID 100547, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 106.0 in stage 392.0 (TID 100540) in 412 ms on lvs02 (107/291)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662997600 in memory on lvs02:38954 (size: 288.6 KB, free: 1072.0 MB)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 114.0 in stage 392.0 (TID 100548, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 107.0 in stage 392.0 (TID 100541) in 445 ms on lvs02 (108/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 115.0 in stage 392.0 (TID 100549, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 105.0 in stage 392.0 (TID 100539) in 561 ms on lvs02 (109/291)

15/03/18 15:16:38 INFO TransformedDStream: Time 1426662998000 ms is invalid as zeroTime is 1426659436000 ms and slideDuration is 3000 ms and difference is 3562000 ms

15/03/18 15:16:38 INFO JobScheduler: No jobs added for time 1426662998000 ms

15/03/18 15:16:38 INFO JobGenerator: Checkpointing graph for time 1426662998000 ms

15/03/18 15:16:38 INFO DStreamGraph: Updating checkpoint data for time 1426662998000 ms

15/03/18 15:16:38 INFO DStreamGraph: Updated checkpoint data for time 1426662998000 ms

15/03/18 15:16:38 INFO CheckpointWriter: Saving checkpoint for time 1426662998000 ms to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426662998000'

15/03/18 15:16:38 INFO CheckpointWriter: Deleting file:/home/hyg/simple/checkpoint/checkpoint-1426662988000

15/03/18 15:16:38 INFO CheckpointWriter: Checkpoint for time 1426662998000 ms saved to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426662998000', took 8740 bytes and 7 ms

15/03/18 15:16:38 INFO DStreamGraph: Clearing checkpoint data for time 1426662998000 ms

15/03/18 15:16:38 INFO DStreamGraph: Cleared checkpoint data for time 1426662998000 ms

15/03/18 15:16:38 INFO ReceivedBlockTracker: Deleting batches ArrayBuffer(1426662934000 ms)

15/03/18 15:16:38 INFO BlockManagerInfo: Added input-0-1426662997800 in memory on lvs02:38954 (size: 324.3 KB, free: 1071.7 MB)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 116.0 in stage 392.0 (TID 100550, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 112.0 in stage 392.0 (TID 100546) in 403 ms on lvs02 (110/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 117.0 in stage 392.0 (TID 100551, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 110.0 in stage 392.0 (TID 100544) in 466 ms on lvs02 (111/291)

15/03/18 15:16:38 INFO BlockManagerInfo: Added input-0-1426662998000 in memory on lvs02:38954 (size: 164.9 KB, free: 1071.6 MB)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 118.0 in stage 392.0 (TID 100552, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 115.0 in stage 392.0 (TID 100549) in 399 ms on lvs02 (112/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 119.0 in stage 392.0 (TID 100553, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 113.0 in stage 392.0 (TID 100547) in 508 ms on lvs02 (113/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 120.0 in stage 392.0 (TID 100554, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 111.0 in stage 392.0 (TID 100545) in 617 ms on lvs02 (114/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 121.0 in stage 392.0 (TID 100555, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 109.0 in stage 392.0 (TID 100543) in 668 ms on lvs02 (115/291)

15/03/18 15:16:38 INFO BlockManagerInfo: Added input-0-1426662998200 in memory on lvs02:38954 (size: 83.7 KB, free: 1071.5 MB)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 122.0 in stage 392.0 (TID 100556, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 116.0 in stage 392.0 (TID 100550) in 335 ms on lvs02 (116/291)

15/03/18 15:16:38 INFO BlockManagerInfo: Added input-0-1426662998400 in memory on lvs02:38954 (size: 262.5 KB, free: 1071.2 MB)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 123.0 in stage 392.0 (TID 100557, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 114.0 in stage 392.0 (TID 100548) in 1036 ms on lvs02 (117/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 124.0 in stage 392.0 (TID 100558, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 118.0 in stage 392.0 (TID 100552) in 676 ms on lvs02 (118/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 125.0 in stage 392.0 (TID 100559, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 117.0 in stage 392.0 (TID 100551) in 787 ms on lvs02 (119/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 126.0 in stage 392.0 (TID 100560, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 120.0 in stage 392.0 (TID 100554) in 666 ms on lvs02 (120/291)

15/03/18 15:16:39 INFO TransformedDStream: Time 1426662999000 ms is invalid as zeroTime is 1426659436000 ms and slideDuration is 3000 ms and difference is 3563000 ms

15/03/18 15:16:39 INFO JobScheduler: No jobs added for time 1426662999000 ms

15/03/18 15:16:39 INFO JobGenerator: Checkpointing graph for time 1426662999000 ms

15/03/18 15:16:39 INFO DStreamGraph: Updating checkpoint data for time 1426662999000 ms

15/03/18 15:16:39 INFO DStreamGraph: Updated checkpoint data for time 1426662999000 ms

15/03/18 15:16:39 INFO CheckpointWriter: Saving checkpoint for time 1426662999000 ms to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426662999000'

15/03/18 15:16:39 INFO CheckpointWriter: Deleting file:/home/hyg/simple/checkpoint/checkpoint-1426662989000

15/03/18 15:16:39 INFO CheckpointWriter: Checkpoint for time 1426662999000 ms saved to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426662999000', took 8740 bytes and 8 ms

15/03/18 15:16:39 INFO DStreamGraph: Clearing checkpoint data for time 1426662999000 ms

15/03/18 15:16:39 INFO DStreamGraph: Cleared checkpoint data for time 1426662999000 ms

15/03/18 15:16:39 INFO ReceivedBlockTracker: Deleting batches ArrayBuffer(1426662935000 ms)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662998800 in memory on lvs02:38954 (size: 613.7 KB, free: 1070.6 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 127.0 in stage 392.0 (TID 100561, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 121.0 in stage 392.0 (TID 100555) in 714 ms on lvs02 (121/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 128.0 in stage 392.0 (TID 100562, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 119.0 in stage 392.0 (TID 100553) in 896 ms on lvs02 (122/291)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662999000 in memory on lvs02:38954 (size: 209.2 KB, free: 1070.4 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 129.0 in stage 392.0 (TID 100563, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 124.0 in stage 392.0 (TID 100558) in 279 ms on lvs02 (123/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 130.0 in stage 392.0 (TID 100564, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 126.0 in stage 392.0 (TID 100560) in 294 ms on lvs02 (124/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 131.0 in stage 392.0 (TID 100565, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 125.0 in stage 392.0 (TID 100559) in 347 ms on lvs02 (125/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 132.0 in stage 392.0 (TID 100566, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 123.0 in stage 392.0 (TID 100557) in 428 ms on lvs02 (126/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 133.0 in stage 392.0 (TID 100567, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 122.0 in stage 392.0 (TID 100556) in 871 ms on lvs02 (127/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 134.0 in stage 392.0 (TID 100568, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 127.0 in stage 392.0 (TID 100561) in 317 ms on lvs02 (128/291)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662999200 in memory on lvs02:38954 (size: 21.8 KB, free: 1070.4 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 135.0 in stage 392.0 (TID 100569, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 128.0 in stage 392.0 (TID 100562) in 246 ms on lvs02 (129/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 136.0 in stage 392.0 (TID 100570, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 132.0 in stage 392.0 (TID 100566) in 240 ms on lvs02 (130/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 137.0 in stage 392.0 (TID 100571, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 129.0 in stage 392.0 (TID 100563) in 364 ms on lvs02 (131/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 138.0 in stage 392.0 (TID 100572, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 134.0 in stage 392.0 (TID 100568) in 206 ms on lvs02 (132/291)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662999400 in memory on lvs02:38954 (size: 385.2 KB, free: 1070.0 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 139.0 in stage 392.0 (TID 100573, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 133.0 in stage 392.0 (TID 100567) in 337 ms on lvs02 (133/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 140.0 in stage 392.0 (TID 100574, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 130.0 in stage 392.0 (TID 100564) in 434 ms on lvs02 (134/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 141.0 in stage 392.0 (TID 100575, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 131.0 in stage 392.0 (TID 100565) in 440 ms on lvs02 (135/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 142.0 in stage 392.0 (TID 100576, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 135.0 in stage 392.0 (TID 100569) in 329 ms on lvs02 (136/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 143.0 in stage 392.0 (TID 100577, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 136.0 in stage 392.0 (TID 100570) in 224 ms on lvs02 (137/291)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662999600 in memory on lvs02:38954 (size: 104.8 KB, free: 1069.9 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 144.0 in stage 392.0 (TID 100578, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 138.0 in stage 392.0 (TID 100572) in 228 ms on lvs02 (138/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 145.0 in stage 392.0 (TID 100579, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 141.0 in stage 392.0 (TID 100575) in 240 ms on lvs02 (139/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 146.0 in stage 392.0 (TID 100580, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 140.0 in stage 392.0 (TID 100574) in 265 ms on lvs02 (140/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 147.0 in stage 392.0 (TID 100581, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 137.0 in stage 392.0 (TID 100571) in 396 ms on lvs02 (141/291)

15/03/18 15:16:40 INFO MappedDStream: Slicing from 1426662941000 ms to 1426663000000 ms (aligned to 1426662941000 ms and 1426663000000 ms)

15/03/18 15:16:40 INFO JobScheduler: Added jobs for time 1426663000000 ms

15/03/18 15:16:40 INFO JobGenerator: Checkpointing graph for time 1426663000000 ms

15/03/18 15:16:40 INFO DStreamGraph: Updating checkpoint data for time 1426663000000 ms

15/03/18 15:16:40 INFO DStreamGraph: Updated checkpoint data for time 1426663000000 ms

15/03/18 15:16:40 INFO CheckpointWriter: Saving checkpoint for time 1426663000000 ms to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426663000000'

15/03/18 15:16:40 INFO CheckpointWriter: Deleting file:/home/hyg/simple/checkpoint/checkpoint-1426662990000

15/03/18 15:16:40 INFO CheckpointWriter: Checkpoint for time 1426663000000 ms saved to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426663000000', took 8744 bytes and 7 ms

15/03/18 15:16:40 INFO DStreamGraph: Clearing checkpoint data for time 1426663000000 ms

15/03/18 15:16:40 INFO DStreamGraph: Cleared checkpoint data for time 1426663000000 ms

15/03/18 15:16:40 INFO ReceivedBlockTracker: Deleting batches ArrayBuffer(1426662936000 ms)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 148.0 in stage 392.0 (TID 100582, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 139.0 in stage 392.0 (TID 100573) in 370 ms on lvs02 (142/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 149.0 in stage 392.0 (TID 100583, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 142.0 in stage 392.0 (TID 100576) in 293 ms on lvs02 (143/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 150.0 in stage 392.0 (TID 100584, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 144.0 in stage 392.0 (TID 100578) in 258 ms on lvs02 (144/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 151.0 in stage 392.0 (TID 100585, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 143.0 in stage 392.0 (TID 100577) in 310 ms on lvs02 (145/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 152.0 in stage 392.0 (TID 100586, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 146.0 in stage 392.0 (TID 100580) in 180 ms on lvs02 (146/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 153.0 in stage 392.0 (TID 100587, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 145.0 in stage 392.0 (TID 100579) in 266 ms on lvs02 (147/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 154.0 in stage 392.0 (TID 100588, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 155.0 in stage 392.0 (TID 100589, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 147.0 in stage 392.0 (TID 100581) in 282 ms on lvs02 (148/291)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 148.0 in stage 392.0 (TID 100582) in 237 ms on lvs02 (149/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 156.0 in stage 392.0 (TID 100590, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 149.0 in stage 392.0 (TID 100583) in 242 ms on lvs02 (150/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 157.0 in stage 392.0 (TID 100591, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 152.0 in stage 392.0 (TID 100586) in 210 ms on lvs02 (151/291)

15/03/18 15:16:40 INFO BlockManagerInfo: Added input-0-1426663000200 in memory on lvs02:38954 (size: 569.3 KB, free: 1069.4 MB)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 158.0 in stage 392.0 (TID 100592, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 150.0 in stage 392.0 (TID 100584) in 348 ms on lvs02 (152/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 159.0 in stage 392.0 (TID 100593, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 155.0 in stage 392.0 (TID 100589) in 217 ms on lvs02 (153/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 160.0 in stage 392.0 (TID 100594, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 154.0 in stage 392.0 (TID 100588) in 264 ms on lvs02 (154/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 161.0 in stage 392.0 (TID 100595, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 153.0 in stage 392.0 (TID 100587) in 294 ms on lvs02 (155/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 162.0 in stage 392.0 (TID 100596, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 151.0 in stage 392.0 (TID 100585) in 444 ms on lvs02 (156/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 163.0 in stage 392.0 (TID 100597, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 156.0 in stage 392.0 (TID 100590) in 240 ms on lvs02 (157/291)

15/03/18 15:16:40 INFO BlockManagerInfo: Added input-0-1426663000400 in memory on lvs02:38954 (size: 343.0 KB, free: 1069.0 MB)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 164.0 in stage 392.0 (TID 100598, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 157.0 in stage 392.0 (TID 100591) in 275 ms on lvs02 (158/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 165.0 in stage 392.0 (TID 100599, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 159.0 in stage 392.0 (TID 100593) in 244 ms on lvs02 (159/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 166.0 in stage 392.0 (TID 100600, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 158.0 in stage 392.0 (TID 100592) in 298 ms on lvs02 (160/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 167.0 in stage 392.0 (TID 100601, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 163.0 in stage 392.0 (TID 100597) in 228 ms on lvs02 (161/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 168.0 in stage 392.0 (TID 100602, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 161.0 in stage 392.0 (TID 100595) in 253 ms on lvs02 (162/291)

15/03/18 15:16:40 INFO BlockManagerInfo: Added input-0-1426663000600 in memory on lvs02:38954 (size: 299.4 KB, free: 1068.7 MB)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 169.0 in stage 392.0 (TID 100603, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 160.0 in stage 392.0 (TID 100594) in 328 ms on lvs02 (163/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 170.0 in stage 392.0 (TID 100604, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 162.0 in stage 392.0 (TID 100596) in 345 ms on lvs02 (164/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 171.0 in stage 392.0 (TID 100605, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 164.0 in stage 392.0 (TID 100598) in 281 ms on lvs02 (165/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 172.0 in stage 392.0 (TID 100606, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 166.0 in stage 392.0 (TID 100600) in 270 ms on lvs02 (166/291)

15/03/18 15:16:41 INFO TransformedDStream: Time 1426663001000 ms is invalid as zeroTime is 1426659436000 ms and slideDuration is 3000 ms and difference is 3565000 ms

15/03/18 15:16:41 INFO JobScheduler: No jobs added for time 1426663001000 ms

15/03/18 15:16:41 INFO JobGenerator: Checkpointing graph for time 1426663001000 ms

15/03/18 15:16:41 INFO DStreamGraph: Updating checkpoint data for time 1426663001000 ms

15/03/18 15:16:41 INFO DStreamGraph: Updated checkpoint data for time 1426663001000 ms

15/03/18 15:16:41 INFO CheckpointWriter: Saving checkpoint for time 1426663001000 ms to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426663001000'

15/03/18 15:16:41 INFO TaskSetManager: Starting task 173.0 in stage 392.0 (TID 100607, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 167.0 in stage 392.0 (TID 100601) in 238 ms on lvs02 (167/291)

15/03/18 15:16:41 INFO CheckpointWriter: Deleting file:/home/hyg/simple/checkpoint/checkpoint-1426662991000

15/03/18 15:16:41 INFO CheckpointWriter: Checkpoint for time 1426663001000 ms saved to file 'file:/home/hyg/simple/checkpoint/checkpoint-1426663001000', took 8744 bytes and 7 ms

15/03/18 15:16:41 INFO DStreamGraph: Clearing checkpoint data for time 1426663001000 ms

15/03/18 15:16:41 INFO DStreamGraph: Cleared checkpoint data for time 1426663001000 ms

15/03/18 15:16:41 INFO ReceivedBlockTracker: Deleting batches ArrayBuffer(1426662937000 ms)

15/03/18 15:16:41 INFO BlockManagerInfo: Added input-0-1426663000800 in memory on lvs02:38954 (size: 180.4 KB, free: 1068.6 MB)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 174.0 in stage 392.0 (TID 100608, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 168.0 in stage 392.0 (TID 100602) in 263 ms on lvs02 (168/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 175.0 in stage 392.0 (TID 100609, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 165.0 in stage 392.0 (TID 100599) in 334 ms on lvs02 (169/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 176.0 in stage 392.0 (TID 100610, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 169.0 in stage 392.0 (TID 100603) in 254 ms on lvs02 (170/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 177.0 in stage 392.0 (TID 100611, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 171.0 in stage 392.0 (TID 100605) in 261 ms on lvs02 (171/291)

15/03/18 15:16:41 INFO BlockManagerInfo: Added input-0-1426663001000 in memory on lvs02:38954 (size: 6.8 KB, free: 1068.6 MB)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 178.0 in stage 392.0 (TID 100612, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 172.0 in stage 392.0 (TID 100606) in 255 ms on lvs02 (172/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 179.0 in stage 392.0 (TID 100613, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 170.0 in stage 392.0 (TID 100604) in 404 ms on lvs02 (173/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 180.0 in stage 392.0 (TID 100614, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 173.0 in stage 392.0 (TID 100607) in 285 ms on lvs02 (174/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 181.0 in stage 392.0 (TID 100615, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 176.0 in stage 392.0 (TID 100610) in 254 ms on lvs02 (175/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 182.0 in stage 392.0 (TID 100616, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 174.0 in stage 392.0 (TID 100608) in 325 ms on lvs02 (176/291)

15/03/18 15:16:41 INFO BlockManagerInfo: Added input-0-1426663001200 in memory on lvs02:38954 (size: 447.9 KB, free: 1068.1 MB)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 183.0 in stage 392.0 (TID 100617, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 175.0 in stage 392.0 (TID 100609) in 371 ms on lvs02 (177/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 184.0 in stage 392.0 (TID 100618, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 177.0 in stage 392.0 (TID 100611) in 291 ms on lvs02 (178/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 185.0 in stage 392.0 (TID 100619, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 178.0 in stage 392.0 (TID 100612) in 292 ms on lvs02 (179/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 186.0 in stage 392.0 (TID 100620, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 180.0 in stage 392.0 (TID 100614) in 259 ms on lvs02 (180/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 187.0 in stage 392.0 (TID 100621, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 179.0 in stage 392.0 (TID 100613) in 292 ms on lvs02 (181/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 188.0 in stage 392.0 (TID 100622, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 182.0 in stage 392.0 (TID 100616) in 213 ms on lvs02 (182/291)

15/03/18 15:16:41 INFO BlockManagerInfo: Added input-0-1426663001400 in memory on lvs02:38954 (size: 24.4 KB, free: 1068.1 MB)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 189.0 in stage 392.0 (TID 100623, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 181.0 in stage 392.0 (TID 100615) in 286 ms on lvs02 (183/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 190.0 in stage 392.0 (TID 100624, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 183.0 in stage 392.0 (TID 100617) in 261 ms on lvs02 (184/291)



Any hints?



Thanks!

On Wed, Mar 18, 2015 at 2:19 PM, Shao, Saisai <sa...@intel.com>> wrote:
Would you please check your driver log or streaming web UI to see each job's latency, including processing latency and total latency.

Seems from your code, sliding window is just 3 seconds, so you will process each 60 second's data in 3 seconds, if processing latency is larger than the sliding window, so maybe you computation power cannot reach to the qps you wanted.

I think you need to identify the bottleneck at first, and then trying to tune your code, balance the data, add more computation resources.

Thanks
Jerry

From: Darren Hoo [mailto:darren.hoo@gmail.com<ma...@gmail.com>]
Sent: Wednesday, March 18, 2015 1:39 PM
To: user@spark.apache.org<ma...@spark.apache.org>
Subject: [spark-streaming] can shuffle write to disk be disabled?

I use spark-streaming reading  messages from a Kafka,  the producer creates messages about 1500 per second


     def hash(x: String): Int = {

        MurmurHash3.stringHash(x)

     }



     val stream = KafkaUtils.createStream(ssc, zkQuorum, group, topicMap, StorageLevel.MEMORY_ONLY_SER).map(_._2)



     val clickstream = stream.map(log => {

       //parse log

       ...

      (hash(log.url), HashSet(hash(log.userid)))

    }).window(Seconds(60), Seconds(3))



    val upv = clickstream.transform( rdd => rdd.reduceByKey(_ ++ _ ).map{ case(url, visits) => {

         val uv = visits.size

         (uv, url)

    }})



    upv.foreach(rdd => println(new Date() + "\n---------------------------------------\n" + rdd.top(20).mkString("\n") + "\n"))



it is quite quick upon startup, but after running for a few minutes, it goes slower and slower and the latency can be minutes.



I found a lot of shuffle writes at /tmp/spark-xxxx in several gigabytes.



with 1500 qps of message and window size of 60 seconds, I think it should be done within memory without writing to disk at all



I've set executor-memory to 8G, So there is plenty of memory.



$SPARK_HOME/bin/spark-submit \

  --class "SimpleApp" \

  --master spark://localhost:7077 \

  --driver-memory 16G  \

  --executor-memory 8G  \

  target/scala-2.10/simple-assembly-1.0.jar



I also tries these settings, but it still spill to disk.



spark.master                     spark://localhost:7077

#spark.driver.memory              4g

#spark.shuffle.file.buffer.kb     4096

#spark.shuffle.memoryFraction     0.8

#spark.storage.unrollFraction     0.8

#spark.storage.unrollMemoryThreshold 1073741824

spark.io.compression.codec       lz4

spark.shuffle.spill              false

spark.serializer                 org.apache.spark.serializer.KryoSerializer



where am I wrong?

Re: [spark-streaming] can shuffle write to disk be disabled?

Posted by Darren Hoo <da...@gmail.com>.

Hi, Saisai

Here is the duration of one of the jobs, 22 seconds in total, it is longer
than the sliding window.

Stage Id Description                 Submitted         Duration  Tasks:
Succeeded/Total Input Output Shuffle Read Shuffle Write
342        foreach at SimpleApp.scala:58   2015/03/18 15:06:58 16 s
 288/288                                    10.6 MB
341       window at SimpleApp.scala:51    2015/03/18 15:06:52     6s
    288/288               12.3 MB                              10.6 MB


And part of the driver log:

15/03/18 15:16:36 INFO DStreamGraph: Cleared checkpoint data for time
1426662996000 ms

15/03/18 15:16:36 INFO ReceivedBlockTracker: Deleting batches
ArrayBuffer(1426662932000 ms)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 81.0 in stage 392.0
(TID 100515, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 75.0 in stage 392.0
(TID 100509) in 370 ms on lvs02 (75/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 82.0 in stage 392.0
(TID 100516, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 77.0 in stage 392.0
(TID 100511) in 261 ms on lvs02 (76/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 83.0 in stage 392.0
(TID 100517, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 78.0 in stage 392.0
(TID 100512) in 274 ms on lvs02 (77/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 84.0 in stage 392.0
(TID 100518, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 74.0 in stage 392.0
(TID 100508) in 569 ms on lvs02 (78/291)

15/03/18 15:16:36 INFO BlockManagerInfo: Added input-0-1426662996000 in
memory on lvs02:38954 (size: 398.3 KB, free: 1073.7 MB)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 85.0 in stage 392.0
(TID 100519, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 76.0 in stage 392.0
(TID 100510) in 539 ms on lvs02 (79/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 86.0 in stage 392.0
(TID 100520, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 80.0 in stage 392.0
(TID 100514) in 296 ms on lvs02 (80/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 87.0 in stage 392.0
(TID 100521, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 81.0 in stage 392.0
(TID 100515) in 292 ms on lvs02 (81/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 88.0 in stage 392.0
(TID 100522, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 82.0 in stage 392.0
(TID 100516) in 331 ms on lvs02 (82/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 89.0 in stage 392.0
(TID 100523, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 83.0 in stage 392.0
(TID 100517) in 271 ms on lvs02 (83/291)

15/03/18 15:16:36 INFO BlockManagerInfo: Added input-0-1426662996200 in
memory on lvs02:38954 (size: 31.0 KB, free: 1073.7 MB)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 90.0 in stage 392.0
(TID 100524, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 79.0 in stage 392.0
(TID 100513) in 549 ms on lvs02 (84/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 91.0 in stage 392.0
(TID 100525, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 84.0 in stage 392.0
(TID 100518) in 327 ms on lvs02 (85/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 92.0 in stage 392.0
(TID 100526, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 86.0 in stage 392.0
(TID 100520) in 293 ms on lvs02 (86/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 93.0 in stage 392.0
(TID 100527, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 87.0 in stage 392.0
(TID 100521) in 257 ms on lvs02 (87/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 94.0 in stage 392.0
(TID 100528, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 90.0 in stage 392.0
(TID 100524) in 244 ms on lvs02 (88/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 95.0 in stage 392.0
(TID 100529, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 85.0 in stage 392.0
(TID 100519) in 455 ms on lvs02 (89/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 96.0 in stage 392.0
(TID 100530, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 89.0 in stage 392.0
(TID 100523) in 358 ms on lvs02 (90/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 97.0 in stage 392.0
(TID 100531, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 88.0 in stage 392.0
(TID 100522) in 548 ms on lvs02 (91/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 98.0 in stage 392.0
(TID 100532, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 92.0 in stage 392.0
(TID 100526) in 363 ms on lvs02 (92/291)

15/03/18 15:16:36 INFO TaskSetManager: Starting task 99.0 in stage 392.0
(TID 100533, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:36 INFO TaskSetManager: Finished task 93.0 in stage 392.0
(TID 100527) in 388 ms on lvs02 (93/291)

15/03/18 15:16:37 INFO MappedDStream: Slicing from 1426662938000 ms to
1426662997000 ms (aligned to 1426662938000 ms and 1426662997000 ms)

15/03/18 15:16:37 INFO JobScheduler: Added jobs for time 1426662997000 ms

15/03/18 15:16:37 INFO JobGenerator: Checkpointing graph for time
1426662997000 ms

15/03/18 15:16:37 INFO DStreamGraph: Updating checkpoint data for time
1426662997000 ms

15/03/18 15:16:37 INFO DStreamGraph: Updated checkpoint data for time
1426662997000 ms

15/03/18 15:16:37 INFO CheckpointWriter: Saving checkpoint for time
1426662997000 ms to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426662997000'

15/03/18 15:16:37 INFO CheckpointWriter: Deleting
file:/home/hyg/simple/checkpoint/checkpoint-1426662987000

15/03/18 15:16:37 INFO CheckpointWriter: Checkpoint for time 1426662997000
ms saved to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426662997000', took 8741
bytes and 7 ms

15/03/18 15:16:37 INFO DStreamGraph: Clearing checkpoint data for time
1426662997000 ms

15/03/18 15:16:37 INFO DStreamGraph: Cleared checkpoint data for time
1426662997000 ms

15/03/18 15:16:37 INFO ReceivedBlockTracker: Deleting batches
ArrayBuffer(1426662933000 ms)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662996800 in
memory on lvs02:38954 (size: 891.8 KB, free: 1072.8 MB)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 100.0 in stage 392.0
(TID 100534, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 96.0 in stage 392.0
(TID 100530) in 289 ms on lvs02 (94/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 101.0 in stage 392.0
(TID 100535, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 91.0 in stage 392.0
(TID 100525) in 603 ms on lvs02 (95/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 102.0 in stage 392.0
(TID 100536, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 94.0 in stage 392.0
(TID 100528) in 445 ms on lvs02 (96/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 103.0 in stage 392.0
(TID 100537, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 95.0 in stage 392.0
(TID 100529) in 473 ms on lvs02 (97/291)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662997000 in
memory on lvs02:38954 (size: 64.8 KB, free: 1072.8 MB)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 104.0 in stage 392.0
(TID 100538, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 98.0 in stage 392.0
(TID 100532) in 343 ms on lvs02 (98/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 105.0 in stage 392.0
(TID 100539, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 97.0 in stage 392.0
(TID 100531) in 378 ms on lvs02 (99/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 106.0 in stage 392.0
(TID 100540, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 101.0 in stage 392.0
(TID 100535) in 296 ms on lvs02 (100/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 107.0 in stage 392.0
(TID 100541, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 99.0 in stage 392.0
(TID 100533) in 420 ms on lvs02 (101/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 108.0 in stage 392.0
(TID 100542, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 100.0 in stage 392.0
(TID 100534) in 359 ms on lvs02 (102/291)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662997200 in
memory on lvs02:38954 (size: 378.0 KB, free: 1072.4 MB)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662997400 in
memory on lvs02:38954 (size: 68.5 KB, free: 1072.3 MB)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 109.0 in stage 392.0
(TID 100543, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 110.0 in stage 392.0
(TID 100544, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 104.0 in stage 392.0
(TID 100538) in 410 ms on lvs02 (103/291)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 102.0 in stage 392.0
(TID 100536) in 569 ms on lvs02 (104/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 111.0 in stage 392.0
(TID 100545, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 103.0 in stage 392.0
(TID 100537) in 511 ms on lvs02 (105/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 112.0 in stage 392.0
(TID 100546, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 108.0 in stage 392.0
(TID 100542) in 302 ms on lvs02 (106/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 113.0 in stage 392.0
(TID 100547, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 106.0 in stage 392.0
(TID 100540) in 412 ms on lvs02 (107/291)

15/03/18 15:16:37 INFO BlockManagerInfo: Added input-0-1426662997600 in
memory on lvs02:38954 (size: 288.6 KB, free: 1072.0 MB)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 114.0 in stage 392.0
(TID 100548, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 107.0 in stage 392.0
(TID 100541) in 445 ms on lvs02 (108/291)

15/03/18 15:16:37 INFO TaskSetManager: Starting task 115.0 in stage 392.0
(TID 100549, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:37 INFO TaskSetManager: Finished task 105.0 in stage 392.0
(TID 100539) in 561 ms on lvs02 (109/291)

15/03/18 15:16:38 INFO TransformedDStream: Time 1426662998000 ms is invalid
as zeroTime is 1426659436000 ms and slideDuration is 3000 ms and difference
is 3562000 ms

15/03/18 15:16:38 INFO JobScheduler: No jobs added for time 1426662998000 ms

15/03/18 15:16:38 INFO JobGenerator: Checkpointing graph for time
1426662998000 ms

15/03/18 15:16:38 INFO DStreamGraph: Updating checkpoint data for time
1426662998000 ms

15/03/18 15:16:38 INFO DStreamGraph: Updated checkpoint data for time
1426662998000 ms

15/03/18 15:16:38 INFO CheckpointWriter: Saving checkpoint for time
1426662998000 ms to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426662998000'

15/03/18 15:16:38 INFO CheckpointWriter: Deleting
file:/home/hyg/simple/checkpoint/checkpoint-1426662988000

15/03/18 15:16:38 INFO CheckpointWriter: Checkpoint for time 1426662998000
ms saved to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426662998000', took 8740
bytes and 7 ms

15/03/18 15:16:38 INFO DStreamGraph: Clearing checkpoint data for time
1426662998000 ms

15/03/18 15:16:38 INFO DStreamGraph: Cleared checkpoint data for time
1426662998000 ms

15/03/18 15:16:38 INFO ReceivedBlockTracker: Deleting batches
ArrayBuffer(1426662934000 ms)

15/03/18 15:16:38 INFO BlockManagerInfo: Added input-0-1426662997800 in
memory on lvs02:38954 (size: 324.3 KB, free: 1071.7 MB)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 116.0 in stage 392.0
(TID 100550, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 112.0 in stage 392.0
(TID 100546) in 403 ms on lvs02 (110/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 117.0 in stage 392.0
(TID 100551, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 110.0 in stage 392.0
(TID 100544) in 466 ms on lvs02 (111/291)

15/03/18 15:16:38 INFO BlockManagerInfo: Added input-0-1426662998000 in
memory on lvs02:38954 (size: 164.9 KB, free: 1071.6 MB)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 118.0 in stage 392.0
(TID 100552, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 115.0 in stage 392.0
(TID 100549) in 399 ms on lvs02 (112/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 119.0 in stage 392.0
(TID 100553, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 113.0 in stage 392.0
(TID 100547) in 508 ms on lvs02 (113/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 120.0 in stage 392.0
(TID 100554, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 111.0 in stage 392.0
(TID 100545) in 617 ms on lvs02 (114/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 121.0 in stage 392.0
(TID 100555, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 109.0 in stage 392.0
(TID 100543) in 668 ms on lvs02 (115/291)

15/03/18 15:16:38 INFO BlockManagerInfo: Added input-0-1426662998200 in
memory on lvs02:38954 (size: 83.7 KB, free: 1071.5 MB)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 122.0 in stage 392.0
(TID 100556, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 116.0 in stage 392.0
(TID 100550) in 335 ms on lvs02 (116/291)

15/03/18 15:16:38 INFO BlockManagerInfo: Added input-0-1426662998400 in
memory on lvs02:38954 (size: 262.5 KB, free: 1071.2 MB)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 123.0 in stage 392.0
(TID 100557, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 114.0 in stage 392.0
(TID 100548) in 1036 ms on lvs02 (117/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 124.0 in stage 392.0
(TID 100558, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 118.0 in stage 392.0
(TID 100552) in 676 ms on lvs02 (118/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 125.0 in stage 392.0
(TID 100559, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 117.0 in stage 392.0
(TID 100551) in 787 ms on lvs02 (119/291)

15/03/18 15:16:38 INFO TaskSetManager: Starting task 126.0 in stage 392.0
(TID 100560, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:38 INFO TaskSetManager: Finished task 120.0 in stage 392.0
(TID 100554) in 666 ms on lvs02 (120/291)

15/03/18 15:16:39 INFO TransformedDStream: Time 1426662999000 ms is invalid
as zeroTime is 1426659436000 ms and slideDuration is 3000 ms and difference
is 3563000 ms

15/03/18 15:16:39 INFO JobScheduler: No jobs added for time 1426662999000 ms

15/03/18 15:16:39 INFO JobGenerator: Checkpointing graph for time
1426662999000 ms

15/03/18 15:16:39 INFO DStreamGraph: Updating checkpoint data for time
1426662999000 ms

15/03/18 15:16:39 INFO DStreamGraph: Updated checkpoint data for time
1426662999000 ms

15/03/18 15:16:39 INFO CheckpointWriter: Saving checkpoint for time
1426662999000 ms to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426662999000'

15/03/18 15:16:39 INFO CheckpointWriter: Deleting
file:/home/hyg/simple/checkpoint/checkpoint-1426662989000

15/03/18 15:16:39 INFO CheckpointWriter: Checkpoint for time 1426662999000
ms saved to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426662999000', took 8740
bytes and 8 ms

15/03/18 15:16:39 INFO DStreamGraph: Clearing checkpoint data for time
1426662999000 ms

15/03/18 15:16:39 INFO DStreamGraph: Cleared checkpoint data for time
1426662999000 ms

15/03/18 15:16:39 INFO ReceivedBlockTracker: Deleting batches
ArrayBuffer(1426662935000 ms)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662998800 in
memory on lvs02:38954 (size: 613.7 KB, free: 1070.6 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 127.0 in stage 392.0
(TID 100561, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 121.0 in stage 392.0
(TID 100555) in 714 ms on lvs02 (121/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 128.0 in stage 392.0
(TID 100562, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 119.0 in stage 392.0
(TID 100553) in 896 ms on lvs02 (122/291)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662999000 in
memory on lvs02:38954 (size: 209.2 KB, free: 1070.4 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 129.0 in stage 392.0
(TID 100563, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 124.0 in stage 392.0
(TID 100558) in 279 ms on lvs02 (123/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 130.0 in stage 392.0
(TID 100564, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 126.0 in stage 392.0
(TID 100560) in 294 ms on lvs02 (124/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 131.0 in stage 392.0
(TID 100565, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 125.0 in stage 392.0
(TID 100559) in 347 ms on lvs02 (125/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 132.0 in stage 392.0
(TID 100566, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 123.0 in stage 392.0
(TID 100557) in 428 ms on lvs02 (126/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 133.0 in stage 392.0
(TID 100567, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 122.0 in stage 392.0
(TID 100556) in 871 ms on lvs02 (127/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 134.0 in stage 392.0
(TID 100568, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 127.0 in stage 392.0
(TID 100561) in 317 ms on lvs02 (128/291)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662999200 in
memory on lvs02:38954 (size: 21.8 KB, free: 1070.4 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 135.0 in stage 392.0
(TID 100569, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 128.0 in stage 392.0
(TID 100562) in 246 ms on lvs02 (129/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 136.0 in stage 392.0
(TID 100570, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 132.0 in stage 392.0
(TID 100566) in 240 ms on lvs02 (130/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 137.0 in stage 392.0
(TID 100571, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 129.0 in stage 392.0
(TID 100563) in 364 ms on lvs02 (131/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 138.0 in stage 392.0
(TID 100572, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 134.0 in stage 392.0
(TID 100568) in 206 ms on lvs02 (132/291)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662999400 in
memory on lvs02:38954 (size: 385.2 KB, free: 1070.0 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 139.0 in stage 392.0
(TID 100573, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 133.0 in stage 392.0
(TID 100567) in 337 ms on lvs02 (133/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 140.0 in stage 392.0
(TID 100574, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 130.0 in stage 392.0
(TID 100564) in 434 ms on lvs02 (134/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 141.0 in stage 392.0
(TID 100575, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 131.0 in stage 392.0
(TID 100565) in 440 ms on lvs02 (135/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 142.0 in stage 392.0
(TID 100576, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 135.0 in stage 392.0
(TID 100569) in 329 ms on lvs02 (136/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 143.0 in stage 392.0
(TID 100577, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 136.0 in stage 392.0
(TID 100570) in 224 ms on lvs02 (137/291)

15/03/18 15:16:39 INFO BlockManagerInfo: Added input-0-1426662999600 in
memory on lvs02:38954 (size: 104.8 KB, free: 1069.9 MB)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 144.0 in stage 392.0
(TID 100578, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 138.0 in stage 392.0
(TID 100572) in 228 ms on lvs02 (138/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 145.0 in stage 392.0
(TID 100579, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 141.0 in stage 392.0
(TID 100575) in 240 ms on lvs02 (139/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 146.0 in stage 392.0
(TID 100580, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 140.0 in stage 392.0
(TID 100574) in 265 ms on lvs02 (140/291)

15/03/18 15:16:39 INFO TaskSetManager: Starting task 147.0 in stage 392.0
(TID 100581, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:39 INFO TaskSetManager: Finished task 137.0 in stage 392.0
(TID 100571) in 396 ms on lvs02 (141/291)

15/03/18 15:16:40 INFO MappedDStream: Slicing from 1426662941000 ms to
1426663000000 ms (aligned to 1426662941000 ms and 1426663000000 ms)

15/03/18 15:16:40 INFO JobScheduler: Added jobs for time 1426663000000 ms

15/03/18 15:16:40 INFO JobGenerator: Checkpointing graph for time
1426663000000 ms

15/03/18 15:16:40 INFO DStreamGraph: Updating checkpoint data for time
1426663000000 ms

15/03/18 15:16:40 INFO DStreamGraph: Updated checkpoint data for time
1426663000000 ms

15/03/18 15:16:40 INFO CheckpointWriter: Saving checkpoint for time
1426663000000 ms to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426663000000'

15/03/18 15:16:40 INFO CheckpointWriter: Deleting
file:/home/hyg/simple/checkpoint/checkpoint-1426662990000

15/03/18 15:16:40 INFO CheckpointWriter: Checkpoint for time 1426663000000
ms saved to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426663000000', took 8744
bytes and 7 ms

15/03/18 15:16:40 INFO DStreamGraph: Clearing checkpoint data for time
1426663000000 ms

15/03/18 15:16:40 INFO DStreamGraph: Cleared checkpoint data for time
1426663000000 ms

15/03/18 15:16:40 INFO ReceivedBlockTracker: Deleting batches
ArrayBuffer(1426662936000 ms)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 148.0 in stage 392.0
(TID 100582, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 139.0 in stage 392.0
(TID 100573) in 370 ms on lvs02 (142/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 149.0 in stage 392.0
(TID 100583, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 142.0 in stage 392.0
(TID 100576) in 293 ms on lvs02 (143/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 150.0 in stage 392.0
(TID 100584, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 144.0 in stage 392.0
(TID 100578) in 258 ms on lvs02 (144/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 151.0 in stage 392.0
(TID 100585, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 143.0 in stage 392.0
(TID 100577) in 310 ms on lvs02 (145/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 152.0 in stage 392.0
(TID 100586, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 146.0 in stage 392.0
(TID 100580) in 180 ms on lvs02 (146/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 153.0 in stage 392.0
(TID 100587, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 145.0 in stage 392.0
(TID 100579) in 266 ms on lvs02 (147/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 154.0 in stage 392.0
(TID 100588, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 155.0 in stage 392.0
(TID 100589, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 147.0 in stage 392.0
(TID 100581) in 282 ms on lvs02 (148/291)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 148.0 in stage 392.0
(TID 100582) in 237 ms on lvs02 (149/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 156.0 in stage 392.0
(TID 100590, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 149.0 in stage 392.0
(TID 100583) in 242 ms on lvs02 (150/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 157.0 in stage 392.0
(TID 100591, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 152.0 in stage 392.0
(TID 100586) in 210 ms on lvs02 (151/291)

15/03/18 15:16:40 INFO BlockManagerInfo: Added input-0-1426663000200 in
memory on lvs02:38954 (size: 569.3 KB, free: 1069.4 MB)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 158.0 in stage 392.0
(TID 100592, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 150.0 in stage 392.0
(TID 100584) in 348 ms on lvs02 (152/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 159.0 in stage 392.0
(TID 100593, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 155.0 in stage 392.0
(TID 100589) in 217 ms on lvs02 (153/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 160.0 in stage 392.0
(TID 100594, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 154.0 in stage 392.0
(TID 100588) in 264 ms on lvs02 (154/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 161.0 in stage 392.0
(TID 100595, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 153.0 in stage 392.0
(TID 100587) in 294 ms on lvs02 (155/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 162.0 in stage 392.0
(TID 100596, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 151.0 in stage 392.0
(TID 100585) in 444 ms on lvs02 (156/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 163.0 in stage 392.0
(TID 100597, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 156.0 in stage 392.0
(TID 100590) in 240 ms on lvs02 (157/291)

15/03/18 15:16:40 INFO BlockManagerInfo: Added input-0-1426663000400 in
memory on lvs02:38954 (size: 343.0 KB, free: 1069.0 MB)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 164.0 in stage 392.0
(TID 100598, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 157.0 in stage 392.0
(TID 100591) in 275 ms on lvs02 (158/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 165.0 in stage 392.0
(TID 100599, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 159.0 in stage 392.0
(TID 100593) in 244 ms on lvs02 (159/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 166.0 in stage 392.0
(TID 100600, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 158.0 in stage 392.0
(TID 100592) in 298 ms on lvs02 (160/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 167.0 in stage 392.0
(TID 100601, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 163.0 in stage 392.0
(TID 100597) in 228 ms on lvs02 (161/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 168.0 in stage 392.0
(TID 100602, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 161.0 in stage 392.0
(TID 100595) in 253 ms on lvs02 (162/291)

15/03/18 15:16:40 INFO BlockManagerInfo: Added input-0-1426663000600 in
memory on lvs02:38954 (size: 299.4 KB, free: 1068.7 MB)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 169.0 in stage 392.0
(TID 100603, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 160.0 in stage 392.0
(TID 100594) in 328 ms on lvs02 (163/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 170.0 in stage 392.0
(TID 100604, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 162.0 in stage 392.0
(TID 100596) in 345 ms on lvs02 (164/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 171.0 in stage 392.0
(TID 100605, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 164.0 in stage 392.0
(TID 100598) in 281 ms on lvs02 (165/291)

15/03/18 15:16:40 INFO TaskSetManager: Starting task 172.0 in stage 392.0
(TID 100606, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:40 INFO TaskSetManager: Finished task 166.0 in stage 392.0
(TID 100600) in 270 ms on lvs02 (166/291)

15/03/18 15:16:41 INFO TransformedDStream: Time 1426663001000 ms is invalid
as zeroTime is 1426659436000 ms and slideDuration is 3000 ms and difference
is 3565000 ms

15/03/18 15:16:41 INFO JobScheduler: No jobs added for time 1426663001000 ms

15/03/18 15:16:41 INFO JobGenerator: Checkpointing graph for time
1426663001000 ms

15/03/18 15:16:41 INFO DStreamGraph: Updating checkpoint data for time
1426663001000 ms

15/03/18 15:16:41 INFO DStreamGraph: Updated checkpoint data for time
1426663001000 ms

15/03/18 15:16:41 INFO CheckpointWriter: Saving checkpoint for time
1426663001000 ms to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426663001000'

15/03/18 15:16:41 INFO TaskSetManager: Starting task 173.0 in stage 392.0
(TID 100607, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 167.0 in stage 392.0
(TID 100601) in 238 ms on lvs02 (167/291)

15/03/18 15:16:41 INFO CheckpointWriter: Deleting
file:/home/hyg/simple/checkpoint/checkpoint-1426662991000

15/03/18 15:16:41 INFO CheckpointWriter: Checkpoint for time 1426663001000
ms saved to file
'file:/home/hyg/simple/checkpoint/checkpoint-1426663001000', took 8744
bytes and 7 ms

15/03/18 15:16:41 INFO DStreamGraph: Clearing checkpoint data for time
1426663001000 ms

15/03/18 15:16:41 INFO DStreamGraph: Cleared checkpoint data for time
1426663001000 ms

15/03/18 15:16:41 INFO ReceivedBlockTracker: Deleting batches
ArrayBuffer(1426662937000 ms)

15/03/18 15:16:41 INFO BlockManagerInfo: Added input-0-1426663000800 in
memory on lvs02:38954 (size: 180.4 KB, free: 1068.6 MB)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 174.0 in stage 392.0
(TID 100608, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 168.0 in stage 392.0
(TID 100602) in 263 ms on lvs02 (168/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 175.0 in stage 392.0
(TID 100609, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 165.0 in stage 392.0
(TID 100599) in 334 ms on lvs02 (169/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 176.0 in stage 392.0
(TID 100610, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 169.0 in stage 392.0
(TID 100603) in 254 ms on lvs02 (170/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 177.0 in stage 392.0
(TID 100611, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 171.0 in stage 392.0
(TID 100605) in 261 ms on lvs02 (171/291)

15/03/18 15:16:41 INFO BlockManagerInfo: Added input-0-1426663001000 in
memory on lvs02:38954 (size: 6.8 KB, free: 1068.6 MB)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 178.0 in stage 392.0
(TID 100612, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 172.0 in stage 392.0
(TID 100606) in 255 ms on lvs02 (172/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 179.0 in stage 392.0
(TID 100613, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 170.0 in stage 392.0
(TID 100604) in 404 ms on lvs02 (173/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 180.0 in stage 392.0
(TID 100614, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 173.0 in stage 392.0
(TID 100607) in 285 ms on lvs02 (174/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 181.0 in stage 392.0
(TID 100615, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 176.0 in stage 392.0
(TID 100610) in 254 ms on lvs02 (175/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 182.0 in stage 392.0
(TID 100616, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 174.0 in stage 392.0
(TID 100608) in 325 ms on lvs02 (176/291)

15/03/18 15:16:41 INFO BlockManagerInfo: Added input-0-1426663001200 in
memory on lvs02:38954 (size: 447.9 KB, free: 1068.1 MB)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 183.0 in stage 392.0
(TID 100617, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 175.0 in stage 392.0
(TID 100609) in 371 ms on lvs02 (177/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 184.0 in stage 392.0
(TID 100618, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 177.0 in stage 392.0
(TID 100611) in 291 ms on lvs02 (178/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 185.0 in stage 392.0
(TID 100619, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 178.0 in stage 392.0
(TID 100612) in 292 ms on lvs02 (179/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 186.0 in stage 392.0
(TID 100620, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 180.0 in stage 392.0
(TID 100614) in 259 ms on lvs02 (180/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 187.0 in stage 392.0
(TID 100621, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 179.0 in stage 392.0
(TID 100613) in 292 ms on lvs02 (181/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 188.0 in stage 392.0
(TID 100622, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 182.0 in stage 392.0
(TID 100616) in 213 ms on lvs02 (182/291)

15/03/18 15:16:41 INFO BlockManagerInfo: Added input-0-1426663001400 in
memory on lvs02:38954 (size: 24.4 KB, free: 1068.1 MB)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 189.0 in stage 392.0
(TID 100623, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 181.0 in stage 392.0
(TID 100615) in 286 ms on lvs02 (183/291)

15/03/18 15:16:41 INFO TaskSetManager: Starting task 190.0 in stage 392.0
(TID 100624, lvs02, PROCESS_LOCAL, 1122 bytes)

15/03/18 15:16:41 INFO TaskSetManager: Finished task 183.0 in stage 392.0
(TID 100617) in 261 ms on lvs02 (184/291)


Any hints?


Thanks!

On Wed, Mar 18, 2015 at 2:19 PM, Shao, Saisai <sa...@intel.com> wrote:

>  Would you please check your driver log or streaming web UI to see each
> job's latency, including processing latency and total latency.
>
>
>
> Seems from your code, sliding window is just 3 seconds, so you will
> process each 60 second's data in 3 seconds, if processing latency is larger
> than the sliding window, so maybe you computation power cannot reach to the
> qps you wanted.
>
>
>
> I think you need to identify the bottleneck at first, and then trying to
> tune your code, balance the data, add more computation resources.
>
>
>
> Thanks
>
> Jerry
>
>
>
> *From:* Darren Hoo [mailto:darren.hoo@gmail.com]
> *Sent:* Wednesday, March 18, 2015 1:39 PM
> *To:* user@spark.apache.org
> *Subject:* [spark-streaming] can shuffle write to disk be disabled?
>
>
>
> I use spark-streaming reading  messages from a Kafka,  the producer
> creates messages about 1500 per second
>
>
>
>      def hash(x: String): Int = {
>
>         MurmurHash3.stringHash(x)
>
>      }
>
>
>
>      val stream = KafkaUtils.createStream(ssc, zkQuorum, group, topicMap,
> StorageLevel.MEMORY_ONLY_SER).map(_._2)
>
>
>
>      val clickstream = stream.map(log => {
>
>        //parse log
>
>        ...
>
>       (hash(log.url), HashSet(hash(log.userid)))
>
>     }).window(Seconds(60), Seconds(3))
>
>
>
>     val upv = clickstream.transform( rdd => rdd.reduceByKey(_ ++ _ ).map{
> case(url, visits) => {
>
>          val uv = visits.size
>
>          (uv, url)
>
>     }})
>
>
>
>     upv.foreach(rdd => println(new Date() +
> "\n---------------------------------------\n" + rdd.top(20).mkString("\n")
> + "\n"))
>
>
>
> it is quite quick upon startup, but after running for a few minutes, it
> goes slower and slower and the latency can be minutes.
>
>
>
> I found a lot of shuffle writes at /tmp/spark-xxxx in several gigabytes.
>
>
>
> with 1500 qps of message and window size of 60 seconds, I think it should
> be done within memory without writing to disk at all
>
>
>
> I've set executor-memory to 8G, So there is plenty of memory.
>
>
>
> $SPARK_HOME/bin/spark-submit \
>
>   --class "SimpleApp" \
>
>   --master spark://localhost:7077 \
>
>   --driver-memory 16G  \
>
>   --executor-memory 8G  \
>
>   target/scala-2.10/simple-assembly-1.0.jar
>
>
>
> I also tries these settings, but it still spill to disk.
>
>
>
> spark.master                     spark://localhost:7077
>
> #spark.driver.memory              4g
>
> #spark.shuffle.file.buffer.kb     4096
>
> #spark.shuffle.memoryFraction     0.8
>
> #spark.storage.unrollFraction     0.8
>
> #spark.storage.unrollMemoryThreshold 1073741824
>
> spark.io.compression.codec       lz4
>
> spark.shuffle.spill              false
>
> spark.serializer                 org.apache.spark.serializer.KryoSerializer
>
>
>
> where am I wrong?
>

RE: [spark-streaming] can shuffle write to disk be disabled?

Posted by "Shao, Saisai" <sa...@intel.com>.

Would you please check your driver log or streaming web UI to see each job's latency, including processing latency and total latency.

Seems from your code, sliding window is just 3 seconds, so you will process each 60 second's data in 3 seconds, if processing latency is larger than the sliding window, so maybe you computation power cannot reach to the qps you wanted.

I think you need to identify the bottleneck at first, and then trying to tune your code, balance the data, add more computation resources.

Thanks
Jerry

From: Darren Hoo [mailto:darren.hoo@gmail.com]
Sent: Wednesday, March 18, 2015 1:39 PM
To: user@spark.apache.org
Subject: [spark-streaming] can shuffle write to disk be disabled?

I use spark-streaming reading  messages from a Kafka,  the producer creates messages about 1500 per second


     def hash(x: String): Int = {

        MurmurHash3.stringHash(x)

     }



     val stream = KafkaUtils.createStream(ssc, zkQuorum, group, topicMap, StorageLevel.MEMORY_ONLY_SER).map(_._2)



     val clickstream = stream.map(log => {

       //parse log

       ...

      (hash(log.url), HashSet(hash(log.userid)))

    }).window(Seconds(60), Seconds(3))



    val upv = clickstream.transform( rdd => rdd.reduceByKey(_ ++ _ ).map{ case(url, visits) => {

         val uv = visits.size

         (uv, url)

    }})



    upv.foreach(rdd => println(new Date() + "\n---------------------------------------\n" + rdd.top(20).mkString("\n") + "\n"))



it is quite quick upon startup, but after running for a few minutes, it goes slower and slower and the latency can be minutes.



I found a lot of shuffle writes at /tmp/spark-xxxx in several gigabytes.



with 1500 qps of message and window size of 60 seconds, I think it should be done within memory without writing to disk at all



I've set executor-memory to 8G, So there is plenty of memory.



$SPARK_HOME/bin/spark-submit \

  --class "SimpleApp" \

  --master spark://localhost:7077 \

  --driver-memory 16G  \

  --executor-memory 8G  \

  target/scala-2.10/simple-assembly-1.0.jar



I also tries these settings, but it still spill to disk.



spark.master                     spark://localhost:7077

#spark.driver.memory              4g

#spark.shuffle.file.buffer.kb     4096

#spark.shuffle.memoryFraction     0.8

#spark.storage.unrollFraction     0.8

#spark.storage.unrollMemoryThreshold 1073741824

spark.io.compression.codec       lz4

spark.shuffle.spill              false

spark.serializer                 org.apache.spark.serializer.KryoSerializer



where am I wrong?