apache / apache/hudi

[SUPPORT] Metaserver read/write errors

Open
#9,814 8 comments 0 reactions 0 assignees View on GitHub
area:performance area:writer engine:spark
Dominant language
Java
Stars
6.2k
Forks
2.5k
Avg merge
2d 8h
Merged PRs (30d)
111

Description

**Describe the problem you faced**

_see this [slack thread](https://apache-hudi.slack.com/archives/C4D716NPQ/p1695661749131259), I was told to raise an issue. I don't have a lot of time to debug this as the upgrade isn't essential right now_

After upgrading Hudi from 0.12.1 to 0.13.1 via an EMR upgrade I’m seeing a lot of these when using the spark writer:

```
23/09/25 16:51:57 INFO RemoteHoodieTableFileSystemView: Sending request : (http://ip-10-0-107-14.eu-west-1.compute.internal:38427/v1/hoodie/view/datafiles/beforeoron/latest/?partition=story_published_partition_date%3D2023-08-26&maxinstant=20230925101228159&basepath=s3%3A%2F%2Fprod-signal-articles-store%2Farticles_hudi_copy_on_write&lastinstantts=20230925142837150&timelinehash=839a7f3760bd309b411eecb46f32635c0eb8d06daac3fba349cb7713a6a698c7)
23/09/25 16:52:36 INFO RetryExec: I/O exception (org.apache.hudi.org.apache.http.NoHttpResponseException) caught when processing request to {}->http://ip-10-0-107-14.eu-west-1.compute.internal:38427/: The target server failed to respond
23/09/25 16:52:36 INFO RetryExec: Retrying request to {}->http://ip-10-0-107-14.eu-west-1.compute.internal:38427/
23/09/25 16:53:06 INFO RetryExec: I/O exception (org.apache.hudi.org.apache.http.NoHttpResponseException) caught when processing request to {}->http://ip-10-0-107-14.eu-west-1.compute.internal:38427/: The target server failed to respond
23/09/25 16:53:06 INFO RetryExec: Retrying request to {}->http://ip-10-0-107-14.eu-west-1.compute.internal:38427/
23/09/25 16:53:36 INFO RetryExec: I/O exception (org.apache.hudi.org.apache.http.NoHttpResponseException) caught when processing request to {}->http://ip-10-0-107-14.eu-west-1.compute.internal:38427/: The target server failed to respond
23/09/25 16:53:36 INFO RetryExec: Retrying request to {}->http://ip-10-0-107-14.eu-west-1.compute.internal:38427/
23/09/25 16:54:07 WARN RetryHelper: Catch Exception for Sending request, will retry after 100 ms.
org.apache.hudi.org.apache.http.NoHttpResponseException: ip-10-0-107-14.eu-west-1.compute.internal:38427 failed to respond
```

I’ve enabled retries, but it seems to be slowing down various write tasks a lot as they retry/fallover to secondary methods. Why would this be happening?
Between these, and seemingly slower bloom filter lookups, jobs are taking 2x longer or more.

I'm unsure if these correspond to these warnings on the driver logs:

```
WARN RequestHandler: Bad request response due to client view behind server view. Last known instant from client was 20230925142837150 but server has the following timeline [[20230405172930640__rollback__COMPLETED], [20230405220408317__rollback__COMPLETED], [20230405230726307__rollback__COMPLETED], [20230406004821619__rollback__COMPLETED], [20230406022626456__rollback__COMPLETED], [20230406040217179__rollback__COMPLETED], [20230406053604634__rollback__COMPLETED], [20230406071500195__rollback__COMPLETED], [20230406085932605__rollback__COMPLETED], [20230406091145473__rollback__COMPLETED], [20230904040946183__rollback__COMPLETED], [20230904200935082__rollback__COMPLETED], [20230905102904696__rollback__COMPLETED], [20230920120910043__commit__COMPLETED], [20230920161015352__commit__COMPLETED], [20230920200916636__commit__COMPLETED], [20230921000922099__commit__COMPLETED], [20230921040951133__commit__COMPLETED], [20230921081133533__commit__COMPLETED], [20230921081136531__clean__COMPLETED], [20230921120938905__commit__COMPLETED], [20230921120941970__clean__COMPLETED], [20230921161019209__commit__COMPLETED], [20230921161022485__clean__COMPLETED], [20230921200920596__commit__COMPLETED], [20230921200923858__clean__COMPLETED], [20230922001011936__commit__COMPLETED], [20230922001014953__clean__COMPLETED], [20230922040943645__commit__COMPLETED], [20230922040946795__clean__COMPLETED], [20230922080911829__commit__COMPLETED], [20230922080915209__clean__COMPLETED], [20230922120928185__commit__COMPLETED], [20230922120931568__clean__COMPLETED], [20230922161014635__commit__COMPLETED], [20230922161017634__clean__COMPLETED], [20230922200911764__commit__COMPLETED], [20230922200914501__clean__COMPLETED], [20230923000928118__commit__COMPLETED], [20230923000931194__clean__COMPLETED], [20230923040937860__commit__COMPLETED], [20230923040940748__clean__COMPLETED], [20230923080919659__commit__COMPLETED], [20230923080922740__clean__COMPLETED], [20230923120913393__commit__COMPLETED], [20230923120916656__clean__COMPLETED], [20230923160937358__commit__COMPLETED], [20230923160940858__clean__COMPLETED], [20230923200914761__commit__COMPLETED], [20230923200917719__clean__COMPLETED], [20230924000958223__commit__COMPLETED], [20230924001001271__clean__COMPLETED], [20230924040915658__commit__COMPLETED], [20230924040918676__clean__COMPLETED], [20230924080919687__commit__COMPLETED], [20230924080922913__clean__COMPLETED], [20230924120907571__commit__COMPLETED], [20230924120910946__clean__COMPLETED], [20230924160910339__commit__COMPLETED], [20230924160913410__clean__COMPLETED], [20230924200912759__commit__COMPLETED], [20230924200915964__clean__COMPLETED], [20230925000926377__commit__COMPLETED], [20230925000931547__clean__COMPLETED], [20230925041024449__commit__COMPLETED], [20230925041027798__clean__COMPLETED], [20230925080953746__commit__COMPLETED], [20230925080957003__clean__COMPLETED], [20230925101228159__commit__COMPLETED], [20230925101231993__clean__COMPLETED], [20230925114607821__clean__COMPLETED], [20230925142837150__rollback__COMPLETED], [20230925161210335__rollback__COMPLETED]]
23/09/25 17:12:41 INFO HoodieActiveTimeline: Loaded instants upto : Option{val=[20230925161210335__rollback__COMPLETED]}
```

I’m also seeing similar errors on writes:

```
Caused by: org.apache.hudi.exception.HoodieRemoteException: Failed to create marker file story_published_partition_date=2023-01-06/47d20ede-bbbe-4cd9-91d1-41993c76752a-0_668-25-96261_20230925161205373.parquet.marker.MERGE
ip-10-0-107-14.eu-west-1.compute.internal:38427 failed to respond
```

I had to rollback the upgrade as it was causing writes to fail (in addition to the successes taking 2x time)

**To Reproduce**

Unknown

**Expected behavior**

The performance to not degrade after upgrading.

**Environment Description**

* Hudi version : 0.13.1-amzn-1 (EMR 6.13.0)

* Spark version : 3.4.1

* Hive version : 3.1.3

* Hadoop version : 3.3.3

* Storage (HDFS/S3/GCS..) : S3

* Running on Docker? (yes/no) : no

**Additional context**

Upgrading from EMR emr-6.9.0 to emr-6.13.0.

This affected both tables we ingest, write times increased 2x for each cluster when succeeding, and failed for large writes.

EMR config:

```
[
{
"Classification": "spark",
"Properties": {
"maximizeResourceAllocation": "false"
}
},
{
"Classification": "spark-defaults",
"Properties": {
"spark.default.parallelism": "6712",
"spark.driver.cores": "4",
"spark.driver.extraJavaOptions": "-XX:+UseG1GC -XX:+UnlockDiagnosticVMOptions -XX:+G1SummarizeConcMark -XX:InitiatingHeapOccupancyPercent=35",
"spark.driver.memory": "25g",
"spark.driver.memoryOverhead": "3g",
"spark.dynamicAllocation.enabled": "false",
"spark.executor.cores": "4",
"spark.executor.extraJavaOptions": "-XX:+UseG1GC -XX:+UnlockDiagnosticVMOptions -XX:+G1SummarizeConcMark -XX:InitiatingHeapOccupancyPercent=35",
"spark.executor.instances": "839",
"spark.executor.memory": "25g",
"spark.executor.memoryOverhead": "3g",
"spark.executor.processTreeMetrics.enabled": "true",
"spark.executorEnv.PEX_INHERIT_PATH": "fallback",
"spark.kryoserializer.buffer.max": "256m",
"spark.metrics.namespace": "spark",
"spark.rdd.compress": "true",
"spark.scheduler.mode": "FAIR",
"spark.serializer": "org.apache.spark.serializer.KryoSerializer",
"spark.shuffle.service.enabled": "true",
"spark.sql.adaptive.coalescePartitions.enabled": "true",
"spark.sql.shuffle.partitions": "6712",
"spark.task.maxFailures": "10",
"spark.ui.prometheus.enabled": "true",
"spark.yarn.appMasterEnv.PEX_INHERIT_PATH": "fallback",
"spark.yarn.max.executor.failures": "100",
"spark.yarn.maxAppAttempts": "1"
}
},
{
"Classification": "spark-log4j2",
"Properties": {
"logger.hudi.level": "INFO",
"logger.hudi.name": "org.apache.hudi"
}
},
{
"Classification": "spark-metrics",
"Properties": {
"*.sink.prometheusServlet.class": "org.apache.spark.metrics.sink.PrometheusServlet",
"*.sink.prometheusServlet.path": "/metrics/prometheus",
"applications.sink.prometheusServlet.path": "/metrics/applications/prometheus",
"driver.source.jvm.class": "org.apache.spark.metrics.source.JvmSource",
"executor.source.jvm.class": "org.apache.spark.metrics.source.JvmSource",
"master.sink.prometheusServlet.path": "/metrics/master/prometheus",
"master.source.jvm.class": "org.apache.spark.metrics.source.JvmSource",
"worker.source.jvm.class": "org.apache.spark.metrics.source.JvmSource"
}
},
{
"Classification": "capacity-scheduler",
"Properties": {
"yarn.scheduler.capacity.resource-calculator": "org.apache.hadoop.yarn.util.resource.DefaultResourceCalculator "
}
},
{
"Classification": "yarn-site",
"Properties": {
"yarn.nodemanager.disk-health-checker.max-disk-utilization-per-disk-percentage": "99.0",
"yarn.nodemanager.pmem-check-enabled": "false",
"yarn.nodemanager.vmem-check-enabled": "false"
}
},
{
"Classification": "hive-site",
"Properties": {
"hive.metastore.client.factory.class": "com.amazonaws.glue.catalog.metastore.AWSGlueDataCatalogHiveClientFactory"
}
},
{
"Classification": "hdfs-site",
"Properties": {
"dfs.replication": "2"
}
},
{
"Classification": "presto-connector-hive",
"Properties": {
"hive.metastore.glue.datacatalog.enabled": "true",
"hive.parquet.use-column-names": "true"
}
},
{
"Classification": "spark-hive-site",
"Properties": {
"hive.metastore.client.factory.class": "com.amazonaws.glue.catalog.metastore.AWSGlueDataCatalogHiveClientFactory"
}
},
{
"Classification": "spark-env",
"Configurations": [
{
"Classification": "export",
"Properties": {
"PYSPARK_PYTHON": "./data_platform_spark_jobs.pex"
}
}
],
"Properties": {}
},
{
"Classification": "hadoop-env",
"Configurations": [
{
"Classification": "export",
"Properties": {
"HADOOP_DATANODE_OPTS": "-javaagent:/etc/prometheus/jmx_prometheus_javaagent.jar=7001:/etc/hadoop/conf/hdfs_jmx_config_datanode.yaml -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.port=50103",
"HADOOP_NAMENODE_OPTS": "-javaagent:/etc/prometheus/jmx_prometheus_javaagent.jar=7001:/etc/hadoop/conf/hdfs_jmx_config_namenode.yaml -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.port=50103"
}
}
],
"Properties": {}
},
{
"Classification": "yarn-env",
"Configurations": [
{
"Classification": "export",
"Properties": {
"YARN_NODEMANAGER_OPTS": "-javaagent:/etc/prometheus/jmx_prometheus_javaagent.jar=7005:/etc/hadoop/conf/yarn_jmx_config_node_manager.yaml -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.port=50111",
"YARN_RESOURCEMANAGER_OPTS": "-javaagent:/etc/prometheus/jmx_prometheus_javaagent.jar=7005:/etc/hadoop/conf/yarn_jmx_config_resource_manager.yaml -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.port=50111"
}
}
],
"Properties": {}
},
{
"Classification": "hudi-defaults",
"Properties": {
"hoodie.archive.async": "true",
"hoodie.bulkinsert.shuffle.parallelism": "6712",
"hoodie.bulkinsert.sort.mode": "GLOBAL_SORT",
"hoodie.clean.async": "true",
"hoodie.cleaner.commits.retained": "1",
"hoodie.cleaner.policy.failed.writes": "LAZY",
"hoodie.datasource.hive_sync.support_timestamp": "true",
"hoodie.delete.shuffle.parallelism": "6712",
"hoodie.enable.data.skipping": "true",
"hoodie.filesystem.operation.retry.enable": "true",
"hoodie.filesystem.view.remote.retry.enable": "true",
"hoodie.insert.shuffle.parallelism": "6712",
"hoodie.metadata.index.bloom.filter.enable": "true",
"hoodie.metadata.index.column.stats.enable": "true",
"hoodie.metrics.on": "true",
"hoodie.metrics.reporter.type": "PROMETHEUS",
"hoodie.parquet.compression.codec": "snappy",
"hoodie.parquet.max.file.size": "536870912",
"hoodie.parquet.small.file.limit": "429496729",
"hoodie.upsert.shuffle.parallelism": "6712",
"hoodie.write.concurrency.mode": "optimistic_concurrency_control",
"hoodie.write.lock.dynamodb.billing_mode": "PAY_PER_REQUEST",
"hoodie.write.lock.dynamodb.endpoint_url": "dynamodb.eu-west-1.amazonaws.com",
"hoodie.write.lock.dynamodb.region": "eu-west-1",
"hoodie.write.lock.dynamodb.table": "data-platform-hudi-locks",
"hoodie.write.lock.provider": "org.apache.hudi.aws.transaction.lock.DynamoDBBasedLockProvider"
}
}
]
```

Additional Hudi config:

```
hoodie.datasource.write.recordkey.field=id
hoodie.datasource.write.precombine.field=version

hoodie.datasource.write.partitionpath.field=story_published_partition_date
hoodie.datasource.write.keygenerator.class=org.apache.hudi.keygen.SimpleKeyGenerator
hoodie.datasource.hive_sync.partition_extractor_class=org.apache.hudi.hive.MultiPartKeysValueExtractor
hoodie.datasource.write.hive_style_partitioning=true

hoodie.avro.schema.validate=true
hoodie.datasource.write.reconcile.schema=false

hoodie.table.name=${TABLE_NAME}

hoodie.datasource.hive_sync.enable=true
hoodie.datasource.hive_sync.database=articles
hoodie.datasource.hive_sync.table=${TABLE_NAME}
hoodie.datasource.hive_sync.partition_fields=story_published_partition_date

hoodie.write.lock.dynamodb.partition_key=${TABLE_NAME}

hoodie.bloom.index.prune.by.ranges=false

hoodie.index.type=BLOOM
hoodie.metadata.enable=true
```

![hudi](https://github.com/apache/hudi/assets/3199181/5d853dbc-c965-4a87-8d50-7f947fdb7b61)

The hours number seems to have become nonsense above (this is from persistent spark logs on EMR)

![Screenshot 2023-10-02 at 09-35-16 write_hudi_table - Details for Job 16](https://github.com/apache/hudi/assets/3199181/c9773393-12b1-4355-afb4-56498402f7a9)
![Screenshot 2023-10-02 at 09-35-29 write_hudi_table - Details for Stage 25 (Attempt 0)](https://github.com/apache/hudi/assets/3199181/6bd386f0-6280-4cc2-aef2-8d6f3fcaa6d3)

Contributor guide

No contributing guide indexed for this repository

Research direction

Start with the RemoteHoodieTableFileSystemView and RequestHandler log paths shown in the report, then compare behavior between EMR 6.9.0/Hudi 0.12.1 and EMR 6.13.0/Hudi 0.13.1 using the supplied Spark and S3 configuration. Reproduction is currently unknown; done means identifying the cause of the failed metaserver requests and documenting a reproducible fix or configuration change that restores successful write performance.

Written by the indexing model from the issue text.

Assessment

Tech stack
aws, java, spark
Domain
data-engineering, distributed-systems, stream-processing
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.