EVS v2.0 Eval - jevs_plots_mesoscale_grid2obs walltime failure

[RussellManser-NCO]

On Tuesday, March 17, 00/evs/v2.0/plots/mesoscale/jevs_plots_mesoscale_grid2obs failed on walltime for EVS v2.0 in eval mode.

Here are two important points before getting into details:

• Production implementation is still scheduled for Tuesday, March 24. NCO does not anticipate changing the implementation date at this time.
• This issue is to request an investigation into the failure.

Runtimes

• EVS v2.0 Eval: typically ~125-140 minutes
• EVS v2.0 NCO para: typically ~118-143 minutes
• EVS v1.0 NCO prod: typically ~108-148 minutes (job: 00/evs/v1.0/mesoscale/plots/jevs_mesoscale_grid2obs_plots)

These runtimes are fairly consistent. I don't see any concerning values, but I can provide more data if it's useful for debugging.

Analysis of $DATA and individual tasks

I saved related files to /lfs/h1/nco/idsb/noscrub/russell.manser/projects/evs/eval_failures/

• $DATA directory: evs_plots_mesoscale_grid2obs_last90days.eval.failed/
• Job output: evs_plots_mesoscale_grid2obs_last90days.o101934296

GDIT helped with an analysis of slow tasks in the failed job

• Many tasks were running for over 60 minutes, with the longest tasks running for 120+ minutes
• A list of task runtimes is in the temporary data directory at grid2obs/out/workdirs/job_times.out
• The tasks that were running slow seemed to slow down at ush/mesoscale/df_preprocessing.py

Some examples of slowdowns at ush/mesoscale/df_preprocessing.py:

• job88/logs/EVS_verif_plotting_job88_grid2obs_747261.out - ran for 90 minutes
• job233/logs/EVS_verif_plotting_job233_grid2obs_747261.out - ran for 89 minutes

I ran a test job in NCO test space and saved the $DATA directory. I found that the longest tasks typically run for ~50 minutes in a "normal" run.

GDIT did not find any evidence of disk slowdowns, node issues, or other system problems while this job was running.

Analysis of ush/mesoscale/df_preprocessing.py

The slowdown was reported in df_preprocessing.py at line 70. It looks like the next line that performs work is calling prune_data on line 81.

EVS/ush/mesoscale/df_preprocessing.py

Lines 70 to 88 in dd3247c

	logger.info(f"Looking for stat files in {stats_dir} using the"
	+ f" template: {output_base_template}")
	if type(fcst_lev) == str:
	fcst_lev = [fcst_lev]
	elif type(fcst_lev) != list:
	e = (f"fcst_lev ({fcst_lev}) is neither a string nor a list."
	+ f" Please check the plotting script"
	+ f" (e.g., \"lead_average.py\") to make sure"
	+ f" fcst_level(s) is preprocessed correctly.")
	logger.error(e)
	raise TypeError(e)
	prune_data(
	stats_dir, prune_dir, tmp_dir, output_base_template,
	valid_range, str(eval_period).upper(), str(verif_case).lower(),
	str(verif_type).lower(), str(line_type).upper(), str(domain),
	[' '+str(fcst_var_name)+' ' for fcst_var_name in fcst_var_names],
	str(var_name).upper(), model_list,
	[' '+str(lev)+' ' for lev in fcst_lev]
	)

Following this to ush/mesoscale/prune_stat_files.py, I found a subprocess call to grep -R

EVS/ush/mesoscale/prune_stat_files.py

Lines 114 to 118 in dd3247c

	for met_stat_file in met_stat_files:
	ps = subprocess.run('grep -R "'+model+'" '+met_stat_file+filter_cmd,
	shell=True, stdout=subprocess.PIPE,
	stderr=subprocess.STDOUT, encoding='UTF-8')
	grep_output = ps.stdout

This looks like a potential area where a slowdown could occur if multiple tasks are working on the same files, or if there are many linked files. However, I am not sure if that is a possibility as I was not able to easily trace the work that each task was performing.

Questions

• Are there any file links that grep -R could get stuck on?
• Do these tasks need to follow file links, or do they only look at regular files?
• Do we expect that multiple tasks might run prune_data at the same time on the same files?

Please investigate the walltime failure further. I am able to perform more tests as requested. If the tasks are indeed working on the same files, GDIT has offered to provide support for streamlining this workflow.

[malloryprow]

Thank you for bringing this to our attention! One question I have is you haven't noticed that the run time of the job has been growing with time or has it otherwise been consistent aside from this failure?

[malloryprow]

I don't see the job ouput /lfs/h1/nco/idsb/noscrub/russell.manser/projects/evs/eval_failures/evs_plots_mesoscale_grid2obs_last90days.o101934296

[malloryprow]

@MarcelCaron-NOAA tagging to make you aware

[RussellManser-NCO]

Hi @malloryprow. No, the job times fluctuate, but I don't see a pattern of increasing runtimes for any of the environments. I just copied the job output file to Cactus, you should be able to find it at that path now.

[malloryprow]

Thank you! I wanted to try to recreate that failure so I can try and debug. I wanted to make sure I had COMIN set up correctly.

[malloryprow]

Sorry another question!

Is the data on Cactus at /lfs/h1/ops/prod/com/evs/v2.0 the same as Dogwood? I want to make sure I'm running on the right data. I don't have prod access to run there.

[malloryprow]

And it looks like it failed on Tuesday 3/17? How have subsequent runs been?

[RussellManser-NCO]

• Yes, the data on Cactus is the same as on Dogwood
• All subsequent runs have completed normally
• Additional note: I have not been able to reproduce the failure, even when using prod data with PDY=20260317

[MarcelCaron-NOAA]

@RussellManser-NCO While we're troubleshooting this, I figure I can answer some of your questions since I was the original developer of this job.

Questions

• Are there any file links that grep -R could get stuck on?
• Do these tasks need to follow file links, or do they only look at regular files?
• Do we expect that multiple tasks might run prune_data at the same time on the same files?

• There are no links that grep -R is operating on as far as I'm aware.
• Regular files
• Yes, this job runs many processes in parallel, each of which runs prune_data() on a similar list of EVS stats files, so it's possible that several of the grep -R commands are running simultaneously on the same file while the job is running.

[malloryprow]

I was not able to recreate the error on Cactus with my run yesterday.

[RussellManser-NCO]

@malloryprow Thank you for the update. It may be difficult to find root cause for this failure since none of us have recreated it so far. But I don't think we're at a dead end yet.

@MarcelCaron-NOAA Thank you for your answers. I have a couple of follow up questions:

• Do any of the tasks wait for another specific task to complete? I am trying to figure out if the slowdown is related to prune_data, if tasks are waiting for a signal to continue, or a mix of both.
• Do the tasks always run in the same order?

[MarcelCaron-NOAA]

@RussellManser-NCO

• There are no task dependencies between plotting tasks. Each task is written as a job card, and run in parallel based on the configured process limit. There is no waiting or signaling between tasks.
• Tasks are generated in a consistent order and submitted in that order. Execution begins with the first batch of tasks, but since they run in parallel, completion order is not guaranteed.

prune_data() is one of the heavier parts of the workflow (looping over a list of large stat files and aggregating grep output to a python variable).

[RussellManser-NCO]

Thanks @MarcelCaron-NOAA. I am running 5 simultaneous tests of jevs_plots_mesoscale_grid2obs right now using prod data. I'm hoping these tests will provide some insight into runtime variability and potentially any issues with tasks reading the same files at the same time. I will follow up with results this afternoon.

[malloryprow]

Thanks @RussellManser-NCO!

[RussellManser-NCO]

Below are the results of the tests I ran today. In short, I don't see anything worrisome.

Job runtime checks

All 5 tests completed successfully with a runtime range of ~8 minutes.

job                                                                  start          end              qt  rt
00/evs/v2.0/plots/mesoscale/jevs_plots_mesoscale_grid2obs_last90days 20260320 13:20 20260320 15:41   12  141.7
00/evs/v2.0/plots/mesoscale/jevs_plots_mesoscale_grid2obs_last90days 20260320 13:20 20260320 15:48   11  147.8
00/evs/v2.0/plots/mesoscale/jevs_plots_mesoscale_grid2obs_last90days 20260320 13:21 20260320 15:48   12  147.4
00/evs/v2.0/plots/mesoscale/jevs_plots_mesoscale_grid2obs_last90days 20260320 13:21 20260320 15:50   12  149.1
00/evs/v2.0/plots/mesoscale/jevs_plots_mesoscale_grid2obs_last90days 20260320 13:21 20260320 15:49   13  147.4

where qt is number of seconds the job waited in the queue and rt is the job runtime in minutes.

For reference, here are the runtime statistics for the NCO eval and NCO para runs of the same job on the same day.

para

job                                                                  start          end              qt  rt
00/evs/v2.0/plots/mesoscale/jevs_plots_mesoscale_grid2obs_last90days 20260320 03:50 20260320 06:08   13  138.3

eval

job                                                                  start          end              qt  rt
00/evs/v2.0/plots/mesoscale/jevs_plots_mesoscale_grid2obs_last90days 20260320 01:00 20260320 03:21   14  141.5

File size and count checks

All 5 tests produced 1370 image files and had total directory volumes of 2.8 GB. I don't see anything concerning here, but I can share the directories if anyone wants to inspect them. Just let me know.

Task runtimes

I estimated task runtimes from the first timestamp printed to each task output file in workdirs and its modification date. The tasks that take the longest are fairly consistent between runs.

Test 1

    job_name           delta
768  job2030 0 days 00:50:10
672  job2144 0 days 00:50:31
524  job2112 0 days 00:51:26
897  job2145 0 days 00:51:34
423  job2118 0 days 00:51:46
143  job2063 0 days 00:52:17
400  job2072 0 days 00:53:06
72   job2157 0 days 00:53:14
56   job2159 0 days 00:54:40
51   job2103 0 days 00:54:46

Test 2

    job_name           delta
768  job2030 0 days 00:51:28
672  job2144 0 days 00:51:53
400  job2072 0 days 00:52:33
216  job2070 0 days 00:53:13
423  job2118 0 days 00:53:20
213  job2160 0 days 00:53:20
221  job2164 0 days 00:53:22
72   job2157 0 days 00:53:31
56   job2159 0 days 00:56:47
51   job2103 0 days 00:56:48

Test 3 - workdirs empty, I did not have a chance to look into it.

Test 4

    job_name           delta
897  job2145 0 days 00:51:02
143  job2063 0 days 00:51:25
400  job2072 0 days 00:51:54
423  job2118 0 days 00:53:01
216  job2070 0 days 00:53:35
72   job2157 0 days 00:53:41
213  job2160 0 days 00:53:47
221  job2164 0 days 00:53:50
56   job2159 0 days 00:56:14
51   job2103 0 days 00:56:15

Test 5

    job_name           delta
897  job2145 0 days 00:51:38
672  job2144 0 days 00:51:52
423  job2118 0 days 00:52:20
216  job2070 0 days 00:52:30
143  job2063 0 days 00:52:37
221  job2164 0 days 00:52:53
213  job2160 0 days 00:53:02
72   job2157 0 days 00:53:29
56   job2159 0 days 00:55:16
51   job2103 0 days 00:55:24