Page MenuHomePhabricator

Frequent HdfsRpcQueueLength alerts
Closed, ResolvedPublic

Description

We receive frequent alerts about the number of HDFS RPC calls being higher than the accepted threshold.
This graph: https://grafana.wikimedia.org/goto/EU00XUzNR?orgId=1 shows us that something changed at the end of september.
I think it could be the job merging content events with the entire history of content, but I might be wrong.
I would like us to find which job is causing the rise, and either we manage to make it not alert, either we raise our alert htreshold.

Details

Related Changes in Gerrit:
Related Changes in GitLab:
TitleReferenceAuthorSource BranchDest Branch
Sync up DagProperties of dumps_merge_events_to_wikitext_raw_daily with overrides.repos/data-engineering/airflow-dags!906xcollazoupdate-dag-propertiesmain
Go back to copy-on-write for MERGE INTOs and DELETEs.repos/data-engineering/mediawiki-content-pipelines!43xcollazogo-back-to-copy-on-writemain
Customize query in GitLab

Event Timeline

Did we find out the cause of this pressure in the end? I seem to remember that it might have been related to work that @xcollazo was doing for Dumps 2.0

I can see from here that the HDFS RPC queue length has remained at a normal level for some time now.

image.png (1,900×700 px, 213 KB)

Do you think that there is anything remaining to do, @JAllemandou ? We could consider whether these alerts should be moved back to the data-engineering-alerts mailing list, rather than the data-platform-alerts list.
It would mean that the person who is on Ops Week would be alerted to them. Arguably they may be closer to the tasks and/or engineers causing the pressure than the Data-Platform-SRE team. What do you think?

We did find the root cause: me 😄 .

TL;DR: spark.sql.iceberg.locality.enabled is all we need, no need for fancy caching.

Turns out that we have had a little RPC storm since we set spark.sql.iceberg.locality.enabled = false for our dumps_merge_events_to_wikitext_raw DAG.

Here is the behavior we have seen since we set this in production, with the red arrow pointing to when I turned the DAG off:

Screenshot 2024-10-10 at 12.18.20 PM.png (1,948×1,040 px, 131 KB)

On hindsight, this behavior makes sense: We used to have the default of spark.sql.iceberg.locality.enabled = true, which means that for this use case, the vast majority of HDFS reads would be local, since the task and the files would be colocated. Thus, HDFS would short circuit the reads.

Now with spark.sql.iceberg.locality.enabled = false, that is not the case anymore, and the job requires much more RPCs. Additionally, that job reads many, many files now that it has 3 separate spark jobs.

In conclusion, we need to be more careful in the future about use cases for spark.sql.iceberg.locality.enabled = false.

For this particular issue though, we are trying to revamp this whole DAG anyway via T375402#10203228, so this storm should not continue for long.

We could consider whether these alerts should be moved back to the data-engineering-alerts mailing list, rather than the data-platform-alerts list.
It would mean that the person who is on Ops Week would be alerted to them. Arguably they may be closer to the tasks and/or engineers causing the pressure than the Data-Platform-SRE team. What do you think?

+1. These alerts are more actionable by the staff that is more familiar to the workload.

Change #1081931 had a related patch set uploaded (by Btullis; author: Btullis):

[operations/alerts@master] Move some HDFS tests from data-platform to data-engineering

https://gerrit.wikimedia.org/r/1081931

Change #1081931 merged by jenkins-bot:

[operations/alerts@master] Move some HDFS tests from data-platform to data-engineering

https://gerrit.wikimedia.org/r/1081931

Change #1084098 had a related patch set uploaded (by Gmodena; author: Gmodena):

[operations/alerts@master] data-engineering: hdfs: alert on rate of rcp calls

https://gerrit.wikimedia.org/r/1084098

Change #1084098 had a related patch set uploaded (by Gmodena; author: Gmodena):

[operations/alerts@master] data-engineering: hdfs: alert on rate of rcp calls

https://gerrit.wikimedia.org/r/1084098

xcollazo claimed this task.

Reopening this to look deeper in the pressure that data ingestion of wmf_dumps.wikitext_raw_rc2 is putting on cluster.

My suspicion is that we are accumulating delete files at too big of a rate, and this, over time, makes us read way too many small files, which in turn, puts RPC pressure on the cluster to the order of opening ~140K files on each ingest.

I have cleaned old delete files via:

spark.sql("""
SELECT count(1) as count, if(content = 0, 'data', 'deletes') as content_type
FROM wmf_dumps.wikitext_raw_rc2.files
GROUP BY content
""").show(20, truncate=False)
+------+------------+
|count |content_type|
+------+------------+
|144037|data        |
|288236|deletes     |
+------+------------+



Run of `rewrite_position_delete_files()`:

spark.sql("""
CALL spark_catalog.system.rewrite_position_delete_files(
  table => 'wmf_dumps.wikitext_raw_rc2',
  options => map('max-file-group-size-bytes', '53687091200',
                 'max-concurrent-file-group-rewrites', '10',
                 'partial-progress.enabled', 'true')
)
""").show(20, truncate=False)


+----------------------------+------------------------+---------------------+-----------------+
|rewritten_delete_files_count|added_delete_files_count|rewritten_bytes_count|added_bytes_count|
+----------------------------+------------------------+---------------------+-----------------+
|266570                      |317                     |447540163            |9435834          |
+----------------------------+------------------------+---------------------+-----------------+

After:

spark.sql("""
SELECT count(1) as count, if(content = 0, 'data', 'deletes') as content_type
FROM wmf_dumps.wikitext_raw_rc2.files
GROUP BY content
""").show(20, truncate=False)

+------+------------+
|count |content_type|
+------+------------+
|147243|data        |
|25189 |deletes     |
+------+------------+

I've just disabled creating new delete files on wmf_dumps.wikitext_raw_rc2 via:

ALTER TABLE wmf_dumps.wikitext_raw_rc2 UNSET TBLPROPERTIES ('write.merge.mode', 'write.delete.mode');

Will let it run overnight to test my hypothesis.

The experiment has been successful so far.

By rewriting old delete files and switching to copy-on-write rather than merge-on-read we do fix this particular issue. However, we now have a separate issue in which the page moves MERGE INTO takes significantly more time.

I will continue monitoring for the time being.

Both the number of RPC calls, as well as the length of the call queue continue to be healthy over the last 2 days.

The page moves MERGE INTO of DAG dumps_reconcile_wikitext_raw_daily continues to improve its runtime as more and more files get rewritten naturally via copy-on-write.

From the point of view of the description of this task, we are done here. I still need to continue monitoring the runtime of dumps_reconcile_wikitext_raw_daily but I will do that elsewhere.

I still need to continue monitoring the runtime of dumps_reconcile_wikitext_raw_daily but I will do that elsewhere.

For completeness, let me add a graph here since it looks like I won't be needing a separate task to chase the runtime of dumps_reconcile_wikitext_raw_daily separately.

Screenshot 2024-11-01 at 10.09.21 AM.png (1,802×1,174 px, 139 KB)

The read arrow points to the dag run in which I enabled the changes discussed in T376713#10275310. Notice how the runtime shot to 11.1 hours, but then, it gradually tapered down to the current 2.45 hours. Most all the extra time was being spent on the page moves MERGE INTO. Comparing the 11 hour run vs recent runs, we can see that the culprit of runtime is the sorting and merging step to write the data back, now that we do copy-on-write. For the 11 hour run, that entailed 89,480 splits (info available for next ~90 days) and multiple retries due to FetchFailedExceptions, while on the 2.45 hours run it is only processing 5,638 splits. Presumably this order of magnitude difference is due to the merging of many delete files back into data files, and also due to a more globally sorted table that needs to hit less files.

So runtime is reasonable, and the big RPC stress on the cluster is gone.


On a related note, even though we have disabled merge-on-read, it was necessary to run rewrite_position_delete_files() on this table, and in the future, we may need to do it again to remove what Iceberg folks call 'dangling deletes', which do affect performance. Unfortunately, this procedure is only available on Iceberg 1.3.0+, and we have 1.2.1 in production. I was able to run it manually since we have the ability to run Iceberg 1.6.1 in PyPsark jointly with Spark 3.3.2, but this is not available in our table maintenance mechanism due to the version. Will open a ticket to potentially pursue this.

xcollazo opened https://gitlab.wikimedia.org/repos/data-engineering/airflow-dags/-/merge_requests/906

Sync up DagProperties of dumps_merge_events_to_wikitext_raw_daily with overrides.

xcollazo merged https://gitlab.wikimedia.org/repos/data-engineering/airflow-dags/-/merge_requests/906

Sync up DagProperties of dumps_merge_events_to_wikitext_raw_daily with overrides.