See <https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/2/display/redirect>
Changes: ------------------------------------------ [...truncated 84.02 KB...] > Task :sdks:python:apache_beam:testing:load_tests:run 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'> '42817' '--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:42817 INFO:apache_beam.utils.subprocess_server:Dec 22, 2022 5:27:48 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 22, 2022 5:27:51 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 22, 2022 5:27:51 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 22, 2022 5:27:51 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 0x7f9ef431aef0> ==================== INFO:apache_beam.runners.portability.fn_api_runner.translations:==================== <function sort_stages at 0x7f9ef431c710> ==================== 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-1222172754-209814-a8y7rois.1671730074.210141/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-1222172754-209814-a8y7rois.1671730074.210141/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-1222172754-209814-a8y7rois.1671730074.210141/dataflow_python_sdk.tar... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1222172754-209814-a8y7rois.1671730074.210141/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-1222172754-209814-a8y7rois.1671730074.210141/pipeline.pb... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1222172754-209814-a8y7rois.1671730074.210141/pipeline.pb in 0 seconds. INFO:apache_beam.runners.dataflow.internal.apiclient:Create job: <Job clientRequestId: '20221222172754211367-7143' createTime: '2022-12-22T17:27:57.876754Z' currentStateTime: '1970-01-01T00:00:00Z' id: '2022-12-22_09_27_57-4146640394353724665' location: 'us-central1' name: 'beamapp-jenkins-1222172754-209814-a8y7rois' projectId: 'apache-beam-testing' stageStates: [] startTime: '2022-12-22T17:27:57.876754Z' steps: [] tempFiles: [] type: TypeValueValuesEnum(JOB_TYPE_BATCH, 1)> INFO:apache_beam.runners.dataflow.internal.apiclient:Created job with id: [2022-12-22_09_27_57-4146640394353724665] INFO:apache_beam.runners.dataflow.internal.apiclient:Submitted job: 2022-12-22_09_27_57-4146640394353724665 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-22_09_27_57-4146640394353724665?project=apache-beam-testing INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-22_09_27_57-4146640394353724665 is in state JOB_STATE_PENDING INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:00.711Z: JOB_MESSAGE_BASIC: Worker configuration: e2-standard-2 in us-central1-f. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:01.640Z: JOB_MESSAGE_DETAILED: Expanding SplittableParDo operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:01.680Z: JOB_MESSAGE_DETAILED: Expanding CollectionToSingleton operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:01.757Z: JOB_MESSAGE_DETAILED: Expanding CoGroupByKey operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:01.791Z: 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-22T17:28:01.824Z: JOB_MESSAGE_DETAILED: Expanding GroupByKey operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:01.856Z: JOB_MESSAGE_DEBUG: Annotating graph with Autotuner information. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:01.899Z: JOB_MESSAGE_DETAILED: Fusing adjacent ParDo, Read, Write, and Flatten operations INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:01.937Z: 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-22T17:28:01.972Z: 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-22T17:28:02.016Z: 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-22T17:28:02.079Z: 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-22T17:28:02.115Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/AddRandomKeys into Count records INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.148Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/ReshufflePerKey/Map(reify_timestamps) into Avoid Fusion/AddRandomKeys INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.181Z: 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-22T17:28:02.214Z: 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-22T17:28:02.247Z: 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-22T17:28:02.281Z: 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-22T17:28:02.312Z: JOB_MESSAGE_DETAILED: Fusing consumer Avoid Fusion/RemoveRandomKeys into Avoid Fusion/ReshufflePerKey/FlatMap(restore_timestamps) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.336Z: JOB_MESSAGE_DETAILED: Fusing consumer Measure time into Avoid Fusion/RemoveRandomKeys INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.358Z: JOB_MESSAGE_DETAILED: Fusing consumer WriteToKafka/Kafka ProducerRecord/Map/ParMultiDo(Anonymous) into Measure time INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.389Z: 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-22T17:28:02.432Z: JOB_MESSAGE_DEBUG: Workflow config is missing a default resource spec. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.469Z: JOB_MESSAGE_DEBUG: Adding StepResource setup and teardown to workflow graph. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.504Z: JOB_MESSAGE_DEBUG: Adding workflow start and stop steps. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.537Z: JOB_MESSAGE_DEBUG: Assigning stage ids. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.673Z: JOB_MESSAGE_DEBUG: Executing wait step start20 INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.745Z: 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-22T17:28:02.795Z: JOB_MESSAGE_DEBUG: Starting **** pool setup. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:02.835Z: JOB_MESSAGE_BASIC: Starting 5 ****s in us-central1-f... INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-22_09_27_57-4146640394353724665 is in state JOB_STATE_RUNNING INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:28:17.542Z: 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-22T17:28:44.685Z: 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-22T17:30:37.978Z: JOB_MESSAGE_DETAILED: Workers have started successfully. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:37:05.893Z: 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-22T17:37:07.653Z: 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-22T17:37:07.713Z: 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-22T17:37:07.791Z: JOB_MESSAGE_BASIC: Executing operation Avoid Fusion/ReshufflePerKey/GroupByKey/Create INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:37:09.253Z: JOB_MESSAGE_BASIC: Finished operation Avoid Fusion/ReshufflePerKey/GroupByKey/Create INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:37:09.315Z: JOB_MESSAGE_DEBUG: Value "Avoid Fusion/ReshufflePerKey/GroupByKey/Session" materialized. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:37:09.370Z: 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-22T17:51:12.023Z: 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-22T17:51:12.126Z: JOB_MESSAGE_BASIC: Executing operation Avoid Fusion/ReshufflePerKey/GroupByKey/Close INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:51:12.188Z: JOB_MESSAGE_BASIC: Finished operation Avoid Fusion/ReshufflePerKey/GroupByKey/Close INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:51:12.258Z: 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-22T17:58:17.571Z: 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-22T17:58:17.628Z: JOB_MESSAGE_DEBUG: Executing success step success18 INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:58:17.711Z: JOB_MESSAGE_DETAILED: Cleaning up. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:58:17.758Z: JOB_MESSAGE_DEBUG: Starting **** pool teardown. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T17:58:17.783Z: JOB_MESSAGE_BASIC: Stopping **** pool... INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:30.464Z: JOB_MESSAGE_DETAILED: Autoscaling: Resized **** pool from 5 to 0. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:30.506Z: JOB_MESSAGE_BASIC: Worker pool stopped. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:30.534Z: JOB_MESSAGE_DEBUG: Tearing down pending resources... INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-22_09_27_57-4146640394353724665 is in state JOB_STATE_DONE INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Load test results for test: 32b9fe46583745d5b6cb1baeec963e84 and timestamp: 1671732039.5604804: 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: 425 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'> '36077' '--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'> '--experiments=use_unbounded_sdf_wrapper'] INFO:apache_beam.utils.subprocess_server:Starting expansion service at localhost:36077 INFO:apache_beam.utils.subprocess_server:Dec 22, 2022 6:00:40 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@53ca01a2 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@358c99f5 INFO:apache_beam.utils.subprocess_server: beam:transform:org.apache.beam:kafka_write:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@3ee0fea4 INFO:apache_beam.utils.subprocess_server: beam:external:java:generate_sequence:v1: org.apache.beam.sdk.expansion.service.ExpansionService$ExternalTransformRegistrarLoader$1@48524010 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 22, 2022 6:00:42 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 22, 2022 6:00:43 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 22, 2022 6:00:43 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.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 0x7f9ef431aef0> ==================== INFO:apache_beam.runners.portability.fn_api_runner.translations:==================== <function sort_stages at 0x7f9ef431c710> ==================== 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-1222180046-469714-k89c85cf.1671732046.470062/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-1222180046-469714-k89c85cf.1671732046.470062/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-1222180046-469714-k89c85cf.1671732046.470062/dataflow_python_sdk.tar... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1222180046-469714-k89c85cf.1671732046.470062/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-1222180046-469714-k89c85cf.1671732046.470062/pipeline.pb... INFO:apache_beam.runners.dataflow.internal.apiclient:Completed GCS upload to gs://temp-storage-for-perf-tests/beamapp-jenkins-1222180046-469714-k89c85cf.1671732046.470062/pipeline.pb in 0 seconds. INFO:apache_beam.runners.dataflow.internal.apiclient:Create job: <Job clientRequestId: '20221222180046471211-3063' createTime: '2022-12-22T18:00:49.893220Z' currentStateTime: '1970-01-01T00:00:00Z' id: '2022-12-22_10_00_49-5047292050603882557' location: 'us-central1' name: 'beamapp-jenkins-1222180046-469714-k89c85cf' projectId: 'apache-beam-testing' stageStates: [] startTime: '2022-12-22T18:00:49.893220Z' steps: [] tempFiles: [] type: TypeValueValuesEnum(JOB_TYPE_BATCH, 1)> INFO:apache_beam.runners.dataflow.internal.apiclient:Created job with id: [2022-12-22_10_00_49-5047292050603882557] INFO:apache_beam.runners.dataflow.internal.apiclient:Submitted job: 2022-12-22_10_00_49-5047292050603882557 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-22_10_00_49-5047292050603882557?project=apache-beam-testing INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-22_10_00_49-5047292050603882557 is in state JOB_STATE_PENDING INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:52.711Z: JOB_MESSAGE_BASIC: Worker configuration: e2-standard-2 in us-central1-f. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:53.871Z: JOB_MESSAGE_DETAILED: Expanding SplittableParDo operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:53.905Z: JOB_MESSAGE_DETAILED: Expanding CollectionToSingleton operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:53.983Z: JOB_MESSAGE_DETAILED: Expanding CoGroupByKey operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.022Z: JOB_MESSAGE_DETAILED: Expanding GroupByKey operations into optimizable parts. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.062Z: JOB_MESSAGE_DEBUG: Annotating graph with Autotuner information. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.100Z: JOB_MESSAGE_DETAILED: Fusing adjacent ParDo, Read, Write, and Flatten operations INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.127Z: JOB_MESSAGE_DETAILED: Fusing consumer ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/ParDo(OutputSingleSource)/ParMultiDo(OutputSingleSource) into ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/Impulse INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.159Z: JOB_MESSAGE_DETAILED: Fusing consumer external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U/PairWithRestriction into ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/ParDo(OutputSingleSource)/ParMultiDo(OutputSingleSource) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.190Z: JOB_MESSAGE_DETAILED: Fusing consumer external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U/SplitWithSizing into external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U/PairWithRestriction INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.222Z: JOB_MESSAGE_DETAILED: Fusing consumer ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/ParDo(StripIds)/ParMultiDo(StripIds) into external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U/ProcessElementAndRestrictionWithSizing INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.255Z: JOB_MESSAGE_DETAILED: Fusing consumer ReadFromKafka/Remove Kafka Metadata/ParMultiDo(Anonymous) into ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/ParDo(StripIds)/ParMultiDo(StripIds) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.289Z: JOB_MESSAGE_DETAILED: Fusing consumer Count records into ReadFromKafka/Remove Kafka Metadata/ParMultiDo(Anonymous) INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.323Z: JOB_MESSAGE_DETAILED: Fusing consumer Measure time into Count records INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.358Z: JOB_MESSAGE_DEBUG: Workflow config is missing a default resource spec. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.395Z: JOB_MESSAGE_DEBUG: Adding StepResource setup and teardown to workflow graph. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.427Z: JOB_MESSAGE_DEBUG: Adding workflow start and stop steps. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.459Z: JOB_MESSAGE_DEBUG: Assigning stage ids. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.595Z: JOB_MESSAGE_DEBUG: Executing wait step start10 INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.681Z: JOB_MESSAGE_BASIC: Executing operation ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/Impulse+ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/ParDo(OutputSingleSource)/ParMultiDo(OutputSingleSource)+external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U/PairWithRestriction+external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U/SplitWithSizing INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.726Z: JOB_MESSAGE_DEBUG: Starting **** pool setup. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:00:54.755Z: JOB_MESSAGE_BASIC: Starting 5 ****s in us-central1-f... INFO:apache_beam.runners.dataflow.dataflow_runner:Job 2022-12-22_10_00_49-5047292050603882557 is in state JOB_STATE_RUNNING INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:01:07.376Z: 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-22T18:01:40.188Z: 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-22T18:03:34.518Z: JOB_MESSAGE_DETAILED: Workers have started successfully. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:09:42.368Z: 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-22T18:09:46.721Z: JOB_MESSAGE_BASIC: Finished operation ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/Impulse+ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/ParDo(OutputSingleSource)/ParMultiDo(OutputSingleSource)+external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U/PairWithRestriction+external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U/SplitWithSizing INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:09:46.832Z: JOB_MESSAGE_DEBUG: Value "external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U-split-with-sizing-out3" materialized. INFO:apache_beam.runners.dataflow.dataflow_runner:2022-12-22T18:09:46.888Z: JOB_MESSAGE_BASIC: Executing operation external_2ReadFromKafka-KafkaIO-Read-KafkaIO-Read-ReadFromKafkaViaUnbounded-Read-KafkaUnboundedSource--ParDo-U/ProcessElementAndRestrictionWithSizing+ReadFromKafka/KafkaIO.Read/KafkaIO.Read.ReadFromKafkaViaUnbounded/Read(KafkaUnboundedSource)/ParDo(StripIds)/ParMultiDo(StripIds)+ReadFromKafka/Remove Kafka Metadata/ParMultiDo(Anonymous)+Count records+Measure time WARNING:apache_beam.runners.dataflow.dataflow_runner:Timing out on waiting for job 2022-12-22_10_00_49-5047292050603882557 after 1800 seconds INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Load test results for test: af2698289690454a89a5c1fb5853cb38 and timestamp: 1671733851.4777305: INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Metric: read_count_records_total_messages Value: 65153083 INFO:apache_beam.testing.load_tests.load_test_metrics_utils:Metric: read_runtime Value: 1247 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 139, 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 64, 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 120, in cleanup self.result, CountMessages.LABEL) File "<https://ci-beam.apache.org/job/beam_PerformanceTests_xlang_KafkaIO_Python/ws/src/sdks/python/apache_beam/testing/load_tests/load_test_metrics_utils.py";,> line 239, in get_counter_metric f"More than one metric result matches name: {name} in namespace "\ ValueError: More than one metric result matches name: total_messages in namespace read. Metric results count: 1 > 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 1h 4m 28s 15 actionable tasks: 5 executed, 10 up-to-date Publishing build scan... https://gradle.com/s/zmaw345ozmvfc 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]
