See <https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/7/display/redirect>
Changes: ------------------------------------------ [...truncated 86.40 KB...] INFO:root:Starting a JAR-based expansion service from JAR <https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/java/io/expansion-service/build/libs/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT.jar> INFO:apache_beam.utils.subprocess_server:Starting service with ['java' '-jar' '<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/java/io/expansion-service/build/libs/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT.jar'> '44607' '--filesToStage=<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/java/io/expansion-service/build/libs/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT.jar']> INFO:apache_beam.utils.subprocess_server:Starting expansion service at localhost:44607 INFO:apache_beam.utils.subprocess_server:Dec 23, 2022 3:43:43 PM org.apache.beam.sdk.expansion.service.ExpansionService loadRegisteredTransforms INFO:apache_beam.utils.subprocess_server:INFO: Registering external transforms: [beam:transform:org.apache.beam:kafka_read_with_metadata:v1, beam:transform:org.apache.beam:kafka_read_without_metadata:v1, beam:transform:org.apache.beam:kafka_write:v1, beam:external:java:generate_sequence:v1] INFO:apache_beam.utils.subprocess_server: INFO:apache_beam.utils.subprocess_server:Registered transforms: INFO:apache_beam.utils.subprocess_server: beam:transform:org.apache.beam:kafka_read_with_metadata:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@e50a6f6 INFO:apache_beam.utils.subprocess_server: beam:transform:org.apache.beam:kafka_read_without_metadata:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@14ec4505 INFO:apache_beam.utils.subprocess_server: beam:transform:org.apache.beam:kafka_write:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@53ca01a2 INFO:apache_beam.utils.subprocess_server: beam:external:java:generate_sequence:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@358c99f5 INFO:apache_beam.utils.subprocess_server: INFO:apache_beam.utils.subprocess_server:Registered SchemaTransformProviders: INFO:apache_beam.utils.subprocess_server: beam:schematransform:org.apache.beam:kafka_read:v1 INFO:apache_beam.utils.subprocess_server:Dec 23, 2022 3:43:45 PM org.apache.beam.sdk.expansion.service.ExpansionService expand INFO:apache_beam.utils.subprocess_server:INFO: Expanding 'WriteToKafka' with URN 'beam:transform:org.apache.beam:kafka_write:v1' INFO:apache_beam.utils.subprocess_server:Dec 23, 2022 3:43:45 PM org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader payloadToConfig INFO:apache_beam.utils.subprocess_server:WARNING: Configuration class 'org.apache.beam.sdk.io.kafka.KafkaIO$Write$External$Configuration' has no schema registered. Attempting to construct with setter approach. INFO:apache_beam.utils.subprocess_server:Dec 23, 2022 3:43:46 PM org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader payloadToConfig INFO:apache_beam.utils.subprocess_server:WARNING: Configuration class 'org.apache.beam.sdk.io.kafka.KafkaIO$Write$External$Configuration' has no schema registered. Attempting to construct with setter approach. INFO:apache_beam.runners.dataflow.dataflow_runner:Automatically enabling Dataflow Runner V2 since the pipeline used cross-language transforms. INFO:apache_beam.runners.portability.stager:Copying Beam SDK "<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/python/build/apache-beam.tar.gz";> to staging location. INFO:apache_beam.runners.dataflow.dataflow_runner:Pipeline has additional dependencies to be installed in SDK **** container, consider using the SDK container image pre-building workflow to avoid repetitive installations. Learn more on https://cloud.google.com/dataflow/docs/guides/using-custom-containers#prebuild INFO:root:Default Python SDK image for environment is apache/beam_python3.7_sdk:2.45.0.dev INFO:root:Using provided Python SDK container image: gcr.io/cloud-dataflow/v1beta3/python37-fnapi:beam-master-20221205 INFO:root:Python SDK container image set to "gcr.io/cloud-dataflow/v1beta3/python37-fnapi:beam-master-20221205" for Docker environment INFO:apache_beam.runners.portability.fn_api_runner.translations:==================== <function pack_combiners at 0x7f623c39be60> ==================== INFO:apache_beam.runners.portability.fn_api_runner.translations:==================== <function sort_stages at 0x7f623c3a0680> ==================== INFO:apache_beam.runners.dataflow.internal.apiclient:Defaulting to the temp_location as staging_location: gs://temp-storage-for-perf-tests/ INFO:apache_beam.internal.gcp.auth:Setting socket default timeout to 60 seconds. INFO:apache_beam.internal.gcp.auth:socket default timeout is 60.0 seconds. INFO:apache_beam.runners.dataflow.internal.apiclient:Starting GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223154348-754018-zrdx1wjx.1671810228.754397/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT-M9S8eOAlbHU32ueZanc7urT7Ut8avVN9__JqfoDn1k8.jar... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223154348-754018-zrdx1wjx.1671810228.754397/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT-M9S8eOAlbHU32ueZanc7urT7Ut8avVN9__JqfoDn1k8.jar in 2 seconds. INFO:apache_beam.runners.dataflow.internal.apiclient:Starting GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223154348-754018-zrdx1wjx.1671810228.754397/dataflow_python_sdk.tar... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223154348-754018-zrdx1wjx.1671810228.754397/dataflow_python_sdk.tar in 0 seconds. INFO:apache_beam.runners.dataflow.internal.apiclient:Starting GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223154348-754018-zrdx1wjx.1671810228.754397/pipeline.pb... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223154348-754018-zrdx1wjx.1671810228.754397/pipeline.pb in 0 seconds. INFO:apache_beam.runners.dataflow.internal.apiclient:Create job: <Job clientRequestId: '20221223154348755649-3785' createTime: '2022-12-23T15:43:52.461372Z' currentStateTime: '1970-01-01T00:00:00Z' id: '2022-12-23_07_43_51-15147644868263657809' location: 'us-central1' name: 'beamapp-jenkins-1223154348-754018-zrdx1wjx' projectId: 'apache-beam-testing' stageStates: [] startTime: '2022-12-23T15:43:52.461372Z' steps: [] tempFiles: [] type: TypeValueValuesEnum(JOB_TYPE_BATCH, 1)> INFO:apache_beam.runners.dataflow.internal.apiclient:Created job with id: [2022-12-23_07_43_51-15147644868263657809] INFO:apache_beam.runners.dataflow.internal.apiclient:Submitted job: 2022-12-23_07_43_51-15147644868263657809 INFO:apache_beam.runners.dataflow.internal.apiclient:To access the Dataflow monitoring console, please navigate to https://console.cloud.google.com/dataflow/jobs/us-central1/2022-12-23_07_43_51-15147644868263657809?project=apache-beam-testing INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-23_07_43_51-15147644868263657809 is in state JOB_STATE_PENDING INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:54.971Z: JOB_MESSAGE_BASIC: Worker configuration: e2-standard-2 in us-central1-f. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.310Z: JOB_MESSAGE_DETAILED: Expanding SplittableParDo operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.348Z: JOB_MESSAGE_DETAILED: Expanding CollectionToSingleton operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.419Z: JOB_MESSAGE_DETAILED: Expanding CoGroupByKey operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.449Z: JOB_MESSAGE_DEBUG: Combiner lifting skipped for step Avoid Fusion/ReshufflePerKey/GroupByKey: GroupByKey not followed by a combiner. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.476Z: JOB_MESSAGE_DETAILED: Expanding GroupByKey operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.503Z: JOB_MESSAGE_DEBUG: Annotating graph with Autotuner information. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.538Z: JOB_MESSAGE_DETAILED: Fusing adjacent ParDo, Read, Write, and Flatten operations INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.566Z: JOB_MESSAGE_DETAILED: Fusing consumer Generate records/Map(<lambda at iobase.py:908>) into Generate records/Impulse INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.591Z: JOB_MESSAGE_DETAILED: Fusing consumer ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/PairWithRestriction into Generate records/Map(<lambda at iobase.py:908>) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.638Z: JOB_MESSAGE_DETAILED: Fusing consumer ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/SplitWithSizing into ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/PairWithRestriction INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.666Z: JOB_MESSAGE_DETAILED: Fusing consumer Count records into ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/ProcessElementAndRestrictionWithSizing INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.693Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/AddRandomKeys into Count records INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.725Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/Map(reify_timestamps) into Avoid Fusion/AddRandomKeys INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.755Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/GroupByKey/Reify into Avoid Fusion/ReshufflePerKey/Map(reify_timestamps) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.787Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/GroupByKey/Write into Avoid Fusion/ReshufflePerKey/GroupByKey/Reify INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.814Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/GroupByKey/GroupByWindow into Avoid Fusion/ReshufflePerKey/GroupByKey/Read INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.850Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/FlatMap(restore_timestamps) into Avoid Fusion/ReshufflePerKey/GroupByKey/GroupByWindow INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.881Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/RemoveRandomKeys into Avoid Fusion/ReshufflePerKey/FlatMap(restore_timestamps) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.916Z: JOB_MESSAGE_DETAILED: Fusing consumer Measure time into Avoid Fusion/RemoveRandomKeys INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.949Z: JOB_MESSAGE_DETAILED: Fusing consumer WriteToKafka/Kafka ProducerRecord/Map/ParMultiDo(Anonymous) into Measure time INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:56.984Z: JOB_MESSAGE_DETAILED: Fusing consumer WriteToKafka/KafkaIO.WriteRecords/ParDo(KafkaWriter)/ParMultiDo(KafkaWriter) into WriteToKafka/Kafka ProducerRecord/Map/ParMultiDo(Anonymous) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:57.014Z: JOB_MESSAGE_DEBUG: Workflow config is missing a default resource spec. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:57.040Z: JOB_MESSAGE_DEBUG: Adding StepResource setup and teardown to workflow graph. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:57.075Z: JOB_MESSAGE_DEBUG: Adding workflow start and stop steps. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:57.113Z: JOB_MESSAGE_DEBUG: Assigning stage ids. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:57.287Z: JOB_MESSAGE_DEBUG: Executing wait step start20 INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:57.357Z: JOB_MESSAGE_BASIC: Executing operation Generate records/Impulse+Generate records/Map(<lambda at iobase.py:908>)+ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/PairWithRestriction+ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/SplitWithSizing INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:57.405Z: JOB_MESSAGE_DEBUG: Starting **** pool setup. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:43:57.442Z: JOB_MESSAGE_BASIC: Starting 5 ****s in us-central1-f... INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-23_07_43_51-15147644868263657809 is in state JOB_STATE_RUNNING INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:44:34.359Z: JOB_MESSAGE_BASIC: Your project already contains 100 Dataflow-created metric descriptors, so new user metrics of the form custom.googleapis.com/* will not be created. However, all user metrics are also available in the metric dataflow.googleapis.com/job/user_counter. If you rely on the custom metrics, you can delete old / unused metric descriptors. See https://developers.google.com/apis-explorer/#p/monitoring/v3/monitoring.projects.metricDescriptors.list and https://developers.google.com/apis-explorer/#p/monitoring/v3/monitoring.projects.metricDescriptors.delete INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:44:40.065Z: JOB_MESSAGE_DETAILED: Autoscaling: Raised the number of ****s to 5 based on the rate of progress in the currently running stage(s). INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:46:32.983Z: JOB_MESSAGE_DETAILED: Workers have started successfully. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:52:45.685Z: JOB_MESSAGE_DETAILED: All ****s have finished the startup processes and began to receive work requests. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:52:47.459Z: JOB_MESSAGE_BASIC: Finished operation Generate records/Impulse+Generate records/Map(<lambda at iobase.py:908>)+ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/PairWithRestriction+ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/SplitWithSizing INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:52:47.537Z: JOB_MESSAGE_DEBUG: Value "ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6-split-with-sizing-out3" materialized. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:52:47.606Z: JOB_MESSAGE_BASIC: Executing operation Avoid Fusion/ReshufflePerKey/GroupByKey/Create INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:52:49.097Z: JOB_MESSAGE_BASIC: Finished operation Avoid Fusion/ReshufflePerKey/GroupByKey/Create INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:52:49.167Z: JOB_MESSAGE_DEBUG: Value "Avoid Fusion/ReshufflePerKey/GroupByKey/Session" materialized. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T15:52:49.233Z: JOB_MESSAGE_BASIC: Executing operation ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/ProcessElementAndRestrictionWithSizing+Count records+Avoid Fusion/AddRandomKeys+Avoid Fusion/ReshufflePerKey/Map(reify_timestamps)+Avoid Fusion/ReshufflePerKey/GroupByKey/Reify+Avoid Fusion/ReshufflePerKey/GroupByKey/Write INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:05:32.420Z: JOB_MESSAGE_BASIC: Finished operation ref_AppliedPTransform_Generate-records-SDFBoundedSourceReader-ParDo-SDFBoundedSourceDoFn-_6/ProcessElementAndRestrictionWithSizing+Count records+Avoid Fusion/AddRandomKeys+Avoid Fusion/ReshufflePerKey/Map(reify_timestamps)+Avoid Fusion/ReshufflePerKey/GroupByKey/Reify+Avoid Fusion/ReshufflePerKey/GroupByKey/Write INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:05:32.545Z: JOB_MESSAGE_BASIC: Executing operation Avoid Fusion/ReshufflePerKey/GroupByKey/Close INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:05:32.635Z: JOB_MESSAGE_BASIC: Finished operation Avoid Fusion/ReshufflePerKey/GroupByKey/Close INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:05:32.705Z: JOB_MESSAGE_BASIC: Executing operation Avoid Fusion/ReshufflePerKey/GroupByKey/Read+Avoid Fusion/ReshufflePerKey/GroupByKey/GroupByWindow+Avoid Fusion/ReshufflePerKey/FlatMap(restore_timestamps)+Avoid Fusion/RemoveRandomKeys+Measure time+WriteToKafka/Kafka ProducerRecord/Map/ParMultiDo(Anonymous)+WriteToKafka/KafkaIO.WriteRecords/ParDo(KafkaWriter)/ParMultiDo(KafkaWriter) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:12:09.097Z: JOB_MESSAGE_BASIC: Finished operation Avoid Fusion/ReshufflePerKey/GroupByKey/Read+Avoid Fusion/ReshufflePerKey/GroupByKey/GroupByWindow+Avoid Fusion/ReshufflePerKey/FlatMap(restore_timestamps)+Avoid Fusion/RemoveRandomKeys+Measure time+WriteToKafka/Kafka ProducerRecord/Map/ParMultiDo(Anonymous)+WriteToKafka/KafkaIO.WriteRecords/ParDo(KafkaWriter)/ParMultiDo(KafkaWriter) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:12:09.182Z: JOB_MESSAGE_DEBUG: Executing success step success18 INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:12:09.260Z: JOB_MESSAGE_DETAILED: Cleaning up. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:12:09.318Z: JOB_MESSAGE_DEBUG: Starting **** pool teardown. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:12:09.338Z: JOB_MESSAGE_BASIC: Stopping **** pool... INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:14:44.126Z: JOB_MESSAGE_DETAILED: Autoscaling: Resized **** pool from 5 to 0. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:14:44.169Z: JOB_MESSAGE_BASIC: Worker pool stopped. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:14:44.201Z: JOB_MESSAGE_DEBUG: Tearing down pending resources... INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-23_07_43_51-15147644868263657809 is in state JOB_STATE_DONE INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Load test results for test: 844bab2359ed4ac696b6a84cd87057c7 and timestamp: 1671812094.3216236: INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Metric: write_count_records_total_messages Value: 100000000 INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Metric: write_runtime Value: 395 INFO:apache_beam.utils.subprocess_server:Using pre-built snapshot at <https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/java/io/expansion-service/build/libs/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT.jar> INFO:root:Starting a JAR-based expansion service from JAR <https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/java/io/expansion-service/build/libs/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT.jar> INFO:apache_beam.utils.subprocess_server:Starting service with ['java' '-jar' '<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/java/io/expansion-service/build/libs/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT.jar'> '60437' '--filesToStage=<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/java/io/expansion-service/build/libs/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT.jar']> INFO:apache_beam.utils.subprocess_server:Starting expansion service at localhost:60437 INFO:apache_beam.utils.subprocess_server:Dec 23, 2022 4:14:55 PM org.apache.beam.sdk.expansion.service.ExpansionService loadRegisteredTransforms INFO:apache_beam.utils.subprocess_server:INFO: Registering external transforms: [beam:transform:org.apache.beam:kafka_read_with_metadata:v1, beam:transform:org.apache.beam:kafka_read_without_metadata:v1, beam:transform:org.apache.beam:kafka_write:v1, beam:external:java:generate_sequence:v1] INFO:apache_beam.utils.subprocess_server: INFO:apache_beam.utils.subprocess_server:Registered transforms: INFO:apache_beam.utils.subprocess_server: beam:transform:org.apache.beam:kafka_read_with_metadata:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@e50a6f6 INFO:apache_beam.utils.subprocess_server: beam:transform:org.apache.beam:kafka_read_without_metadata:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@14ec4505 INFO:apache_beam.utils.subprocess_server: beam:transform:org.apache.beam:kafka_write:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@53ca01a2 INFO:apache_beam.utils.subprocess_server: beam:external:java:generate_sequence:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@358c99f5 INFO:apache_beam.utils.subprocess_server: INFO:apache_beam.utils.subprocess_server:Registered SchemaTransformProviders: INFO:apache_beam.utils.subprocess_server: beam:schematransform:org.apache.beam:kafka_read:v1 INFO:apache_beam.utils.subprocess_server:Dec 23, 2022 4:14:57 PM org.apache.beam.sdk.expansion.service.ExpansionService expand INFO:apache_beam.utils.subprocess_server:INFO: Expanding 'ReadFromKafka' with URN 'beam:transform:org.apache.beam:kafka_read_without_metadata:v1' INFO:apache_beam.utils.subprocess_server:Dec 23, 2022 4:14:57 PM org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader payloadToConfig INFO:apache_beam.utils.subprocess_server:WARNING: Configuration class 'org.apache.beam.sdk.io.kafka.KafkaIO$Read$External$Configuration' has no schema registered. Attempting to construct with setter approach. INFO:apache_beam.utils.subprocess_server:Dec 23, 2022 4:14:57 PM org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader payloadToConfig INFO:apache_beam.utils.subprocess_server:WARNING: Configuration class 'org.apache.beam.sdk.io.kafka.KafkaIO$Read$External$Configuration' has no schema registered. Attempting to construct with setter approach. INFO:apache_beam.runners.portability.stager:Copying Beam SDK "<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/python/build/apache-beam.tar.gz";> to staging location. INFO:apache_beam.runners.dataflow.dataflow_runner:Pipeline has additional dependencies to be installed in SDK **** container, consider using the SDK container image pre-building workflow to avoid repetitive installations. Learn more on https://cloud.google.com/dataflow/docs/guides/using-custom-containers#prebuild INFO:root:Default Python SDK image for environment is apache/beam_python3.7_sdk:2.45.0.dev INFO:root:Using provided Python SDK container image: gcr.io/cloud-dataflow/v1beta3/python37-fnapi:beam-master-20221205 INFO:root:Python SDK container image set to "gcr.io/cloud-dataflow/v1beta3/python37-fnapi:beam-master-20221205" for Docker environment INFO:apache_beam.runners.dataflow.internal.apiclient:Defaulting to the temp_location as staging_location: gs://temp-storage-for-perf-tests/ INFO:apache_beam.runners.dataflow.internal.apiclient:Starting GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223161500-665258-numbip6y.1671812100.665646/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT-M9S8eOAlbHU32ueZanc7urT7Ut8avVN9__JqfoDn1k8.jar... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223161500-665258-numbip6y.1671812100.665646/beam-sdks-java-io-expansion-service-2.45.0-SNAPSHOT-M9S8eOAlbHU32ueZanc7urT7Ut8avVN9__JqfoDn1k8.jar in 3 seconds. INFO:apache_beam.runners.dataflow.internal.apiclient:Starting GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223161500-665258-numbip6y.1671812100.665646/dataflow_python_sdk.tar... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223161500-665258-numbip6y.1671812100.665646/dataflow_python_sdk.tar in 0 seconds. INFO:apache_beam.runners.dataflow.internal.apiclient:Starting GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223161500-665258-numbip6y.1671812100.665646/pipeline.pb... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1223161500-665258-numbip6y.1671812100.665646/pipeline.pb in 0 seconds. INFO:apache_beam.runners.dataflow.internal.apiclient:Create job: <Job clientRequestId: '20221223161500666806-2061' createTime: '2022-12-23T16:15:04.746104Z' currentStateTime: '1970-01-01T00:00:00Z' id: '2022-12-23_08_15_04-3289795647839610894' location: 'us-central1' name: 'beamapp-jenkins-1223161500-665258-numbip6y' projectId: 'apache-beam-testing' stageStates: [] startTime: '2022-12-23T16:15:04.746104Z' steps: [] tempFiles: [] type: TypeValueValuesEnum(JOB_TYPE_STREAMING, 2)> INFO:apache_beam.runners.dataflow.internal.apiclient:Created job with id: [2022-12-23_08_15_04-3289795647839610894] INFO:apache_beam.runners.dataflow.internal.apiclient:Submitted job: 2022-12-23_08_15_04-3289795647839610894 INFO:apache_beam.runners.dataflow.internal.apiclient:To access the Dataflow monitoring console, please navigate to https://console.cloud.google.com/dataflow/jobs/us-central1/2022-12-23_08_15_04-3289795647839610894?project=apache-beam-testing INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-23_08_15_04-3289795647839610894 is in state JOB_STATE_PENDING INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:11.123Z: JOB_MESSAGE_BASIC: Worker configuration: e2-standard-2 in us-central1-a. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.237Z: JOB_MESSAGE_DETAILED: Expanding SplittableParDo operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.280Z: JOB_MESSAGE_DETAILED: Expanding CollectionToSingleton operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.380Z: JOB_MESSAGE_DETAILED: Expanding CoGroupByKey operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.417Z: JOB_MESSAGE_DEBUG: Combiner lifting skipped for step Avoid Fusion/ReshufflePerKey/GroupByKey: GroupByKey not followed by a combiner. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.462Z: JOB_MESSAGE_DETAILED: Expanding SplittableProcessKeyed operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.520Z: JOB_MESSAGE_DETAILED: Expanding GroupByKey operations into streaming Read/Write steps INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.580Z: JOB_MESSAGE_DETAILED: Lifting ValueCombiningMappingFns into MergeBucketsMappingFns INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.629Z: JOB_MESSAGE_DEBUG: Annotating graph with Autotuner information. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.672Z: JOB_MESSAGE_DETAILED: Fusing adjacent ParDo, Read, Write, and Flatten operations INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.704Z: JOB_MESSAGE_DETAILED: Fusing consumer ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaSDF/ParDo(GenerateKafkaSourceDescriptor)/ParMultiDo(GenerateKafkaSourceDescriptor) into ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaSDF/Impulse INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.731Z: JOB_MESSAGE_DETAILED: Fusing consumer external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaSDF-KafkaIO-ReadSourceDescriptors-ParDo-Unbo/PairWithRestriction into ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaSDF/ParDo(GenerateKafkaSourceDescriptor)/ParMultiDo(GenerateKafkaSourceDescriptor) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.766Z: JOB_MESSAGE_DETAILED: Fusing consumer external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaSDF-KafkaIO-ReadSourceDescriptors-ParDo-Unbo/SplitWithSizing into external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaSDF-KafkaIO-ReadSourceDescriptors-ParDo-Unbo/PairWithRestriction INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.802Z: JOB_MESSAGE_DETAILED: Fusing consumer ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaSDF/KafkaIO.ReadSourceDescriptors/MapElements/Map/ParMultiDo(Anonymous) into external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaSDF-KafkaIO-ReadSourceDescriptors-ParDo-Unbo/ProcessElementAndRestrictionWithSizing INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.827Z: JOB_MESSAGE_DETAILED: Fusing consumer ReadFromKafka/Remove Kafka Metadata/ParMultiDo(Anonymous) into ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaSDF/KafkaIO.ReadSourceDescriptors/MapElements/Map/ParMultiDo(Anonymous) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.854Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/AddRandomKeys into ReadFromKafka/Remove Kafka Metadata/ParMultiDo(Anonymous) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.893Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/Map(reify_timestamps) into Avoid Fusion/AddRandomKeys INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.928Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/GroupByKey/WriteStream into Avoid Fusion/ReshufflePerKey/Map(reify_timestamps) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.963Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/GroupByKey/MergeBuckets into Avoid Fusion/ReshufflePerKey/GroupByKey/ReadStream INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:12.994Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/FlatMap(restore_timestamps) into Avoid Fusion/ReshufflePerKey/GroupByKey/MergeBuckets INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:13.020Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/RemoveRandomKeys into Avoid Fusion/ReshufflePerKey/FlatMap(restore_timestamps) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:13.043Z: JOB_MESSAGE_DETAILED: Fusing consumer Count records into Avoid Fusion/RemoveRandomKeys INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:13.081Z: JOB_MESSAGE_DETAILED: Fusing consumer Measure time into Count records INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:13.190Z: JOB_MESSAGE_BASIC: Running job using Streaming Engine INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:13.240Z: JOB_MESSAGE_DEBUG: Workflow config is missing a default resource spec. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:13.269Z: JOB_MESSAGE_DEBUG: Adding StepResource setup and teardown to workflow graph. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:13.293Z: JOB_MESSAGE_DEBUG: Adding workflow start and stop steps. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:13.326Z: JOB_MESSAGE_DEBUG: Assigning stage ids. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:14.423Z: JOB_MESSAGE_DEBUG: Starting **** pool setup. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:14.457Z: JOB_MESSAGE_BASIC: Starting 5 ****s in us-central1-a... INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:14.535Z: JOB_MESSAGE_DEBUG: Starting **** pool setup. INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-23_08_15_04-3289795647839610894 is in state JOB_STATE_RUNNING INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:45.656Z: JOB_MESSAGE_BASIC: Your project already contains 100 Dataflow-created metric descriptors, so new user metrics of the form custom.googleapis.com/* will not be created. However, all user metrics are also available in the metric dataflow.googleapis.com/job/user_counter. If you rely on the custom metrics, you can delete old / unused metric descriptors. See https://developers.google.com/apis-explorer/#p/monitoring/v3/monitoring.projects.metricDescriptors.list and https://developers.google.com/apis-explorer/#p/monitoring/v3/monitoring.projects.metricDescriptors.delete INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:55.087Z: JOB_MESSAGE_DETAILED: Autoscaling: Raised the number of ****s to 4 so that the pipeline can catch up with its backlog and keep up with its input rate. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:15:55.121Z: JOB_MESSAGE_DETAILED: Autoscaling: Resized **** pool to 4, though goal was 5. This could be a quota issue. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:16:04.843Z: JOB_MESSAGE_DETAILED: Autoscaling: Raised the number of ****s to 5 so that the pipeline can catch up with its backlog and keep up with its input rate. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:17:52.482Z: JOB_MESSAGE_DETAILED: All ****s have finished the startup processes and began to receive work requests. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-23T16:17:52.607Z: JOB_MESSAGE_DETAILED: Workers have started successfully. WARNING:apache_beam.runners.dataflow.dataflow_runner:Timing out on waiting for job 2022-12-23_08_15_04-3289795647839610894 after 1500 seconds INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Load test results for test: fd1282546d574201b98bfa6cbbd47fa1 and timestamp: 1671813606.157331: INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Metric: read_count_records_total_messages Value: 1251756 INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Metric: read_runtime Value: 935 Traceback (most recent call last): File "/usr/lib/python3.7/runpy.py", line 193, in _run_module_as_main "__main__", mod_spec) File "/usr/lib/python3.7/runpy.py", line 85, in _run_code exec(code, run_globals) File "<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/python/apache_beam/io/external/xlang_kafkaio_perf_test.py";,> line 144, in <module> getattr(sys.modules[__name__], test_options.test_class)().run() File "<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/python/apache_beam/io/external/xlang_kafkaio_perf_test.py";,> line 65, in run read_test.run() File "<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/python/apache_beam/testing/load_tests/load_test.py";,> line 156, in run self.cleanup() File "<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/python/apache_beam/io/external/xlang_kafkaio_perf_test.py";,> line 126, in cleanup assert total_messages == self.input_options['num_records'] AssertionError > Task :sdks:python:apache_beam:testing:load_tests:run FAILED FAILURE: Build failed with an exception. * Where: Build file '<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/python/apache_beam/testing/load_tests/build.gradle'> line: 63 * What went wrong: Execution failed for task ':sdks:python:apache_beam:testing:load_tests:run'. > error occurred * Try: > Run with --stacktrace option to get the stack trace. > Run with --info or --debug option to get more log output. * Get more help at https://help.gradle.org Deprecated Gradle features were used in this build, making it incompatible with Gradle 8.0. You can use '--warning-mode all' to show the individual deprecation warnings and determine if they come from your own scripts or plugins. See https://docs.gradle.org/7.5.1/userguide/command_line_interface.html#sec:command_line_warnings BUILD FAILED in 57m 45s 15 actionable tasks: 5 executed, 10 up-to-date Publishing build scan... https://gradle.com/s/jz4vpmmb5ckfq Build step 'Invoke Gradle script' changed build result to FAILURE Build step 'Invoke Gradle script' marked build as failure --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
