search

venf2k / google-cloud-sdk

Automatically exported from code.google.com/p/google-cloud-sdk
0 stars 0 forks source link

Dataflow "Refused to split GroupShuffleReader" error #738

Open GoogleCodeExporter opened 8 years ago

GoogleCodeExporter commented 8 years ago 
I've managed to run the DataStoreWordCount example pipeline locally but when I 
tried to run it remotely as BlockingDataflowPipelineRunner, it got stuck in a 
"Proposing dynamic split of work unit"/"Refused to split GroupShuffleReader" 
loop. Here's the worker log dum, it's quite long but you'll see this error 
right at the end.

https://console.cloud.google.com/logs?key1=2016-04-14_20_45_13-16473102604900529
178&service=dataflow.googleapis.com&logName=dataflow.googleapis.com%2Fworker&pro
ject=sirtrackwms&minLogLevel=0&expandAll=false&key2=&lastVisibleTimestampNanos=1
460691993810000000

20:46:29.775
Worker harness starting with: 
{"autoscalingAlgorithm":"NONE","maxNumWorkers":0,"numWorkers":3,"options":{"apiR
ootUrl":"https://dataflow.googleapis.com/","appName":"DatastoreWordCount","crede
ntialFactoryClass":"com.google.cloud.dataflow.sdk.util.GcpCredentialFactory","da
taflowEndpoint":"","dataset":"sirtrackwms","enableCloudDebugger":false,"jobName"
:"datastorewordcount-emanu-0415034411","kind":"kinglear","numShards":0,"numberOf
WorkerHarnessThreads":0,"output":"gs://sirtrackwms-dataflow-staging/dfoutput.txt
","pathValidatorClass":"com.google.cloud.dataflow.sdk.util.DataflowPathValidator
","project":"sirtrackwms","readOnly":true,"runner":"com.google.cloud.dataflow.sd
k.runners.BlockingDataflowPipelineRunner","stableUniqueNames":"WARNING","stagerC
lass":"com.google.cloud.dataflow.sdk.util.GcsStager","stagingLocation":"gs://sir
trackwms.appspot.com","streaming":false,"tempLocation":"gs://sirtrackwms.appspot
.com"}}
20:46:31.342
Logging initialized @4922ms
20:46:31.533
jetty-9.2.z-SNAPSHOT
{
metadata:
{…}
insertId:
"2016-04-14|20:46:34.129549-07|10.106.54.215|-1844844729"
log:
"dataflow.googleapis.com/worker"
structPayload:
{…}
}
20:46:31.632
Started ServerConnector@132d6fa{HTTP/1.1}{0.0.0.0:8081}
20:46:31.635
Started @5216ms
20:46:31.637
Status server started on http://172.17.0.2:8081/
20:46:32.290
Worker harness starting with: 
{"autoscalingAlgorithm":"NONE","maxNumWorkers":0,"numWorkers":3,"options":{"apiR
ootUrl":"https://dataflow.googleapis.com/","appName":"DatastoreWordCount","crede
ntialFactoryClass":"com.google.cloud.dataflow.sdk.util.GcpCredentialFactory","da
taflowEndpoint":"","dataset":"sirtrackwms","enableCloudDebugger":false,"jobName"
:"datastorewordcount-emanu-0415034411","kind":"kinglear","numShards":0,"numberOf
WorkerHarnessThreads":0,"output":"gs://sirtrackwms-dataflow-staging/dfoutput.txt
","pathValidatorClass":"com.google.cloud.dataflow.sdk.util.DataflowPathValidator
","project":"sirtrackwms","readOnly":true,"runner":"com.google.cloud.dataflow.sd
k.runners.BlockingDataflowPipelineRunner","stableUniqueNames":"WARNING","stagerC
lass":"com.google.cloud.dataflow.sdk.util.GcsStager","stagingLocation":"gs://sir
trackwms.appspot.com","streaming":false,"tempLocation":"gs://sirtrackwms.appspot
.com"}}
20:46:32.622
Worker harness starting with: 
{"autoscalingAlgorithm":"NONE","maxNumWorkers":0,"numWorkers":3,"options":{"apiR
ootUrl":"https://dataflow.googleapis.com/","appName":"DatastoreWordCount","crede
ntialFactoryClass":"com.google.cloud.dataflow.sdk.util.GcpCredentialFactory","da
taflowEndpoint":"","dataset":"sirtrackwms","enableCloudDebugger":false,"jobName"
:"datastorewordcount-emanu-0415034411","kind":"kinglear","numShards":0,"numberOf
WorkerHarnessThreads":0,"output":"gs://sirtrackwms-dataflow-staging/dfoutput.txt
","pathValidatorClass":"com.google.cloud.dataflow.sdk.util.DataflowPathValidator
","project":"sirtrackwms","readOnly":true,"runner":"com.google.cloud.dataflow.sd
k.runners.BlockingDataflowPipelineRunner","stableUniqueNames":"WARNING","stagerC
lass":"com.google.cloud.dataflow.sdk.util.GcsStager","stagingLocation":"gs://sir
trackwms.appspot.com","streaming":false,"tempLocation":"gs://sirtrackwms.appspot
.com"}}
20:46:33.435
Query for latest stats timestamp of dataset sirtrackwms took 147ms
20:46:33.499
Query for per-kind statistics took 48ms
20:46:33.542
Logging initialized @5914ms
20:46:33.686
jetty-9.2.z-SNAPSHOT
20:46:33.805
Started ServerConnector@6d900e97{HTTP/1.1}{0.0.0.0:8081}
20:46:33.805
Started @6178ms
20:46:33.810
Status server started on http://172.17.0.2:8081/
20:46:33.880
Query for latest stats timestamp of dataset sirtrackwms took 45ms
20:46:33.923
Query for per-kind statistics took 42ms
20:46:33.961
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: LESS_THAN value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "0679f9b5-063c-4ee5-9e4d-86319d97a97e" } } } } } } } , 
namespace=null}
20:46:34.024
Query for latest stats timestamp of dataset sirtrackwms took 44ms
20:46:34.062
Query for per-kind statistics took 37ms
20:46:34.071
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "0679f9b5-063c-4ee5-9e4d-86319d97a97e" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"15d94657-29b3-48a7-a31d-76986a583ff0" } } } } } } } , namespace=null}
20:46:34.118
Query for latest stats timestamp of dataset sirtrackwms took 43ms
20:46:34.160
Query for per-kind statistics took 38ms
20:46:34.164
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "15d94657-29b3-48a7-a31d-76986a583ff0" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"1f32f541-d176-45b2-94ee-4bf2c79d30f0" } } } } } } } , namespace=null}
20:46:34.212
Logging initialized @6859ms
20:46:34.214
Query for latest stats timestamp of dataset sirtrackwms took 48ms
20:46:34.252
Query for per-kind statistics took 37ms
20:46:34.256
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "1f32f541-d176-45b2-94ee-4bf2c79d30f0" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"518a8867-eb58-41d3-88a1-a16ffbc0b413" } } } } } } } , namespace=null}
20:46:34.303
Query for latest stats timestamp of dataset sirtrackwms took 44ms
20:46:34.342
Query for per-kind statistics took 38ms
20:46:34.344
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "518a8867-eb58-41d3-88a1-a16ffbc0b413" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"6b45ab53-274d-4faa-becb-d67b4438138e" } } } } } } } , namespace=null}
20:46:34.374
jetty-9.2.z-SNAPSHOT
20:46:34.394
Query for latest stats timestamp of dataset sirtrackwms took 44ms
20:46:34.433
Query for per-kind statistics took 39ms
20:46:34.450
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "6b45ab53-274d-4faa-becb-d67b4438138e" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"7d7cdae4-3012-409a-b4ba-d8f15d9d297c" } } } } } } } , namespace=null}
20:46:34.466
Started ServerConnector@7fbdeb7d{HTTP/1.1}{0.0.0.0:8081}
20:46:34.467
Started @7115ms
20:46:34.467
Status server started on http://172.17.0.2:8081/
20:46:34.493
Query for latest stats timestamp of dataset sirtrackwms took 39ms
20:46:34.528
Query for per-kind statistics took 34ms
20:46:34.533
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "7d7cdae4-3012-409a-b4ba-d8f15d9d297c" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"889f8719-14b1-4225-ae97-0bd67a6ab249" } } } } } } } , namespace=null}
20:46:34.579
Query for latest stats timestamp of dataset sirtrackwms took 42ms
20:46:34.617
Query for per-kind statistics took 38ms
20:46:34.618
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "889f8719-14b1-4225-ae97-0bd67a6ab249" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"98ec211b-8841-4141-af74-fb3a83fd6b8f" } } } } } } } , namespace=null}
20:46:34.677
Query for latest stats timestamp of dataset sirtrackwms took 51ms
20:46:34.718
Query for per-kind statistics took 40ms
20:46:34.720
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "98ec211b-8841-4141-af74-fb3a83fd6b8f" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"b69b9bf9-8584-4777-84fa-3873facab16d" } } } } } } } , namespace=null}
20:46:34.757
Query for latest stats timestamp of dataset sirtrackwms took 32ms
20:46:34.786
Query for per-kind statistics took 28ms
20:46:34.787
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "b69b9bf9-8584-4777-84fa-3873facab16d" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"ce9d28e2-52cc-48a5-a971-3dc47c0ba68a" } } } } } } } , namespace=null}
20:46:34.830
Query for latest stats timestamp of dataset sirtrackwms took 36ms
20:46:34.873
Query for per-kind statistics took 43ms
20:46:34.875
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "ce9d28e2-52cc-48a5-a971-3dc47c0ba68a" } } } } } filter 
{ property_filter { property { name: "__key__" } operator: LESS_THAN value { 
key_value { partition_id { dataset_id: "s~sirtrackwms" } path_element { kind: 
"kinglear" name: "root" } path_element { kind: "kinglear" name: 
"fb1c99c1-6e6f-417e-a9b3-c8af549a2b64" } } } } } } } , namespace=null}
20:46:34.915
Query for latest stats timestamp of dataset sirtrackwms took 38ms
20:46:34.964
Query for per-kind statistics took 49ms
20:46:34.966
Size estimation of the source failed: Source{host=https://www.googleapis.com, 
dataset=sirtrackwms, query=kind { name: "kinglear" } filter { composite_filter 
{ operator: AND filter { property_filter { property { name: "__key__" } 
operator: HAS_ANCESTOR value { key_value { path_element { kind: "kinglear" 
name: "root" } } } } } filter { property_filter { property { name: "__key__" } 
operator: GREATER_THAN_OR_EQUAL value { key_value { partition_id { dataset_id: 
"s~sirtrackwms" } path_element { kind: "kinglear" name: "root" } path_element { 
kind: "kinglear" name: "fb1c99c1-6e6f-417e-a9b3-c8af549a2b64" } } } } } } } , 
namespace=null}
20:46:35.276
Starting MapTask stage s07
20:46:35.344
Starting MapTask stage s07
20:46:36.461
Finished processing stage s07 with 0 errors in 1.184 seconds
20:46:36.755
Starting MapTask stage s07
20:46:37.106
Starting MapTask stage s07
20:46:37.706
Finished processing stage s07 with 0 errors in 2.348 seconds
20:46:37.743
Finished processing stage s07 with 0 errors in 0.636 seconds
20:46:38.849
Finished processing stage s07 with 0 errors in 2.092 seconds
20:46:40.376
Starting MapTask stage s07
20:46:40.598
Starting MapTask stage s07
20:46:40.686
Finished processing stage s07 with 0 errors in 0.309 seconds
20:46:40.778
Starting MapTask stage s07
20:46:40.803
Finished processing stage s07 with 0 errors in 0.204 seconds
20:46:41.019
Finished processing stage s07 with 0 errors in 0.237 seconds
20:46:41.792
Starting MapTask stage s07
20:46:42.296
Finished processing stage s07 with 0 errors in 0.504 seconds
20:46:42.422
Starting MapTask stage s07
20:46:42.643
Finished processing stage s07 with 0 errors in 0.221 seconds
20:46:42.894
Starting MapTask stage s07
20:46:43.178
Finished processing stage s07 with 0 errors in 0.284 seconds
20:46:43.190
Starting MapTask stage s07
20:46:43.774
Finished processing stage s07 with 0 errors in 0.584 seconds
20:46:43.861
Starting MapTask stage s07
20:46:44.462
Finished processing stage s07 with 0 errors in 0.598 seconds
20:46:45.155
Starting MapTask stage s02
20:46:46.199
Finished processing stage s02 with 0 errors in 1.042 seconds
20:46:47.475
Starting MapTask stage s04
20:46:47.787
Starting MapTask stage s04
20:46:48.171
Finished processing stage s04 with 0 errors in 0.695 seconds
20:46:48.993
Starting MapTask stage s04

{
metadata:
{…}
insertId:
"2016-04-14|20:49:07.158215-07|10.106.207.9|167801079"
log:
"dataflow.googleapis.com/worker"
structPayload:
{
message:
"Proposing dynamic split of work unit 
sirtrackwms;2016-04-14_20_45_13-16473102604900529178;8024817726443979134 at 
{"fractionConsumed":0.5,"position":{"shufflePosition":"AAAAAoAAAQ"}}"
work:
"8024817726443979134"
thread:
"51"
worker:
"datastorewordcount-emanu--04142045-7dc1-harness-p0a2"
logger:
"com.google.cloud.dataflow.sdk.runners.worker.DataflowWorkProgressUpdater"
stage:
"s04"
job:
"2016-04-14_20_45_13-16473102604900529178"
}
}

{
metadata:
{…}
insertId:
"2016-04-14|20:49:07.158268-07|10.106.207.9|167801079"
log:
"dataflow.googleapis.com/worker"
structPayload:
{
message:
"Refused to split GroupingShuffleReader <unstarted in shuffle range 
[ShufflePosition(base64:AAAAAg), ShufflePosition(base64:AAAAAw))> at AAAAAoAAAQ"
work:
"8024817726443979134"
thread:
"51"
worker:
"datastorewordcount-emanu--04142045-7dc1-harness-p0a2"
logger:
"com.google.cloud.dataflow.sdk.runners.worker.GroupingShuffleReader"
stage:
"s04"
job:
"2016-04-14_20_45_13-16473102604900529178"
}
}

Original issue reported on code.google.com by theb...@emanueleziglioli.it on 15 Apr 2016 at 4:12

GoogleCodeExporter commented 8 years ago 
I've passed this on to the Dataflow team; I'll let you know when they get back.

Original comment by z...@google.com on 15 Apr 2016 at 1:25

GoogleCodeExporter commented 8 years ago 
Here's what I have from the Dataflow team:

"Refusing to split" is not an error. It seems that the workers were stuck when 
reading from GBK, and the "refusing to split" errors are merely attempts by 
Dataflow to parallelize the load. I'm not sure what the workers were stuck in.

Q: Why can a worker get stuck reading from GBK? (note the "unstarted" in 
<unstarted in shuffle range [ShufflePosition(base64:AAAAAg), 
ShufflePosition(base64:AAAAAw))> at AAAAAoAAAQ")

A: For any number of reasons (connectivity, timeouts, slow disks, etc.).  
Besides the stack trace (which you can get from the http server on port 
8081/threadz (e.g., ssh on the VM, and do curl http://localhost:8081/threadz) 
what does the /var/log/dataflow/java-batch/boot-json.log file contain (on the 
affected worker)?

-----------------------------------------------
Do you mind grabbing that stack trace and those log files?

Original comment by z...@google.com on 15 Apr 2016 at 5:46

GoogleCodeExporter commented 8 years ago 
Thanks, is it possible/easy to ssh into a VM that's been created by Dataflow?

Original comment by emanu...@ziglioli.org on 16 Apr 2016 at 11:19

GoogleCodeExporter commented 8 years ago 
I'm no expert on Dataflow and haven't done this myself, but it seems possible:

> You can view the VM instances for a given pipeline by using the Google Cloud 
Platform Console. From there, you can use SSH to access each instance.

https://cloud.google.com/dataflow/faq#accessing-VMs

Looks like it'll be easiest from the Cloud Console.

Original comment by z...@google.com on 19 Apr 2016 at 3:34