From f1b0886cc0511bdd23bf7f7f64d9c6cfbc9f6b5d Mon Sep 17 00:00:00 2001 From: Daniel Hupp Date: Tue, 4 Aug 2026 12:25:07 +0200 Subject: [PATCH 1/4] first draft --- tests/data/timing_example_1.txt | 16 +--- tests/util/icon/test_extract_timings.py | 85 +++++++++++++++++ util/icon/extract_timings.py | 116 ++++++++++++++---------- 3 files changed, 157 insertions(+), 60 deletions(-) create mode 100644 tests/util/icon/test_extract_timings.py diff --git a/tests/data/timing_example_1.txt b/tests/data/timing_example_1.txt index 039d8909..3490a5d2 100644 --- a/tests/data/timing_example_1.txt +++ b/tests/data/timing_example_1.txt @@ -1602,25 +1602,19 @@ problem: sub-timers inconsistent! read_fg, 120, 41, 3 destruct_atmo_nonhydrostatic: finalize meteogram output destruct_atmo_nonhydrostatic: clean-up finished - Timer report, ranks 0-7 - - Timer report - + ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- ------------- + name # calls t_min min rank t_avg t_max max rank total min (s) total min rank total max (s) total max rank total avg (s) + ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- ------------- ------------------------ ------- ------------ ------------ ------------ ------------- ------------- ------------- name # calls t_min t_avg t_max total min (s) total max (s) total avg (s) ------------------------ ------- ------------ ------------ ------------ ------------- ------------- ------------- wrt_output 2 0.00000s 7.1658s 14.3315s 14.332 14.332 1.791 - model_init 1 35.9140s 35.9140s 35.9140s 35.914 35.914 4.489 - L compute_domain_decomp 1 35.9139s 35.9139s 35.9139s 35.914 35.914 4.489 ------------------------------------------------------------------------------------------------------------------------------- - - ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- ------------- - name # calls t_min min rank t_avg t_max max rank total min (s) total min rank total max (s) total max rank total avg (s) - ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- ------------- - total 8 15.8031s [1] 15.8762s 16.0712s [0] 15.803 [1] 16.071 [0] 15.876 + model_init 1 35.9140s 35.9140s 35.9140s 35.914 35.914 4.489 + L compute_domain_decomp 1 35.9139s 35.9139s 35.9139s 35.914 35.914 4.489 L integrate_nh 8 2.5080s [0] 3.0333s 3.1584s [3] 2.508 [0] 3.158 [3] 3.033 L nh_solve 40 0.03204s [0] 0.11028s 0.40723s [1] 0.536 [0] 0.557 [3] 0.551 L nh_solve.veltend 48 0.00327s [1] 0.01176s 0.30161s [2] 0.024 [6] 0.331 [2] 0.071 diff --git a/tests/util/icon/test_extract_timings.py b/tests/util/icon/test_extract_timings.py new file mode 100644 index 00000000..af5dda1d --- /dev/null +++ b/tests/util/icon/test_extract_timings.py @@ -0,0 +1,85 @@ +""" +This module contains a focused regression test for read_logfile's handling of +timing tables whose rows are interleaved in the log file, instead of appearing +as clean, separate, contiguous blocks (as can happen with certain MPI rank +output orderings from ICON). +""" + +import logging + +from util.icon.extract_timings import read_logfile + +# each data row needs at least one trailing space after its last value: +# TIMING_ELEMENT_REGEX requires a trailing "+" after every numeric token, +# including the last one, so a padding suffix is added to every row below. +_PAD = " " + +_LINES = [ + "Sun Jun 26 20:00:00 CEST 2022", + "", + "Timer report, ranks 0-3", + " ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- -------------", + " name # calls t_min min rank t_avg t_max max rank total min (s) total min rank total max (s) total max rank total avg (s)", + " ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- -------------", + " ------------------------ ------- ------------ ------------ ------------ ------------- ------------- -------------", + " name # calls t_min t_avg t_max total min (s) total max (s) total avg (s)", + " ------------------------ ------- ------------ ------------ ------------ ------------- ------------- -------------", + "", + " wrt_output 2 0.00000s 7.1658s 14.3315s 14.332 14.332 1.791" + _PAD, + " -------------------------------------------------------------------------------------------------------------------------------", + "", + " total 8 15.8031s [1] 15.8762s 16.0712s [0] 15.803 [1] 16.071 [0] 15.876" + _PAD, + " model_init 1 35.9140s 35.9140s 35.9140s 35.914 35.914 4.489" + _PAD, + " L compute_domain_decomp 1 35.9139s 35.9139s 35.9139s 35.914 35.914 4.489" + _PAD, + " L integrate_nh 8 2.5080s [0] 3.0333s 3.1584s [3] 2.508 [0] 3.158 [3] 3.033" + _PAD, + " L nh_solve 40 0.03204s [0] 0.11028s 0.40723s [1] 0.536 [0] 0.557 [3] 0.551" + _PAD, + " L nh_hdiff 16 0.00706s [0] 0.26922s 0.64131s [3] 0.016 [0] 0.654 [3] 0.538" + _PAD, + " L physics 8 1.7170s [0] 1.7191s 1.7200s [6] 1.717 [0] 1.720 [6] 1.719" + _PAD, + " L transport 8 0.19864s [4] 0.19974s 0.20102s [2] 0.199 [4] 0.201 [2] 0.200" + _PAD, + " orphan_row 1 2.0s 3.0s 4.0s 5.0s 6.0s 7.0s 8.0s" + _PAD, + " L write_restart 16 0.00000s [0] 0.00002s 0.00003s [0] 0.000 [5] 0.000 [6] 0.000" + _PAD, + " exch_data 328 0.00015s [0] 0.02736s 0.63455s [3] 0.107 [0] 1.678 [3] 1.122" + _PAD, + " --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------", + "", + "Sun Jun 26 20:11:23 CEST 2022", + "", +] + +INTERLEAVED_LOG = "\n".join(_LINES) + + +def test_read_logfile_handles_interleaved_tables(tmp_path, caplog): + """ + The 13-column ("total" tree) table's header is immediately followed by + the 8-column ("wrt_output") table's header, and rows from the two tables + end up mixed together rather than in two contiguous blocks. read_logfile + must route each row to the table matching its column count instead of + crashing or silently mis-assigning rows. + """ + logfile = tmp_path / "interleaved.txt" + logfile.write_text(INTERLEAVED_LOG) + + with caplog.at_level(logging.WARNING): + timing_data, meta_data = read_logfile(str(logfile)) + + # the small (wrt_output) table only has 3 rows and is dropped by the + # "not interested in small tables" filter, same as today; what matters is + # that its rows don't leak into the big table below + assert meta_data["n_tables"] == 1 + + big_table = timing_data[0] + assert big_table["name"] == [ + "total", + "integrate_nh", + "nh_solve", + "nh_hdiff", + "physics", + "transport", + "write_restart", + ] + + # the orphan row matches no known header's column count and must be + # skipped with a warning, not silently mis-assigned or fatal + assert any( + "matches no known header" in record.message for record in caplog.records + ) diff --git a/util/icon/extract_timings.py b/util/icon/extract_timings.py index 38ca251d..92b9ec9b 100644 --- a/util/icon/extract_timings.py +++ b/util/icon/extract_timings.py @@ -4,7 +4,6 @@ """ import re -import sys import numpy as np from dateutil.parser import ParserError @@ -39,59 +38,78 @@ def read_logfile(filename): # store line numbers of timing table headers header_lines = [i for i, e in enumerate(data) if re.search(HEADER_REGEX, e)] + header_positions = set(header_lines) - # initialize storage for all tables - timing_data = [] - - # construct timing tables - for k, i_header in enumerate(header_lines): - # make sure stay within header_line bounds - i_end = header_lines[k + 1] if k + 1 < len(header_lines) else -1 - - # get data from this table (starting one line after header) - table = data[i_header + 1 : i_end] - - # parse table header - header_elements = [ + # parse each table's header up front, so rows can be routed to the + # right table even if two tables' rows end up interleaved in the log + # (this can happen with certain MPI rank output orderings) + header_elements_list = [ + [ e.lstrip().rstrip() for e in data[i_header].split(" ") if e not in ["", " "] ] - timing_data_k = {e: [] for e in header_elements} - - # parse table elements - timing_data_k["indent"] = [] - timing_data_k["name"] = [] - - for table_line in table: - elements = [ - e.replace("[", "").replace("]", "") - for e in table_line.split(" ") - if e not in ["", "L"] - ] - if len(elements) != len(header_elements): - logger.critical( - ( - "Number of header elements (%s) " - + "does not match number of table elements (%s)" - ), - len(header_elements), - len(elements), - ) - logger.critical("header: %s", " -- ".join(header_elements)) - logger.critical("table : %s", " -- ".join(elements)) - sys.exit(1) - # find indentation level for each table line - first = re.search(INDENT_REGEX, table_line).group(0) - # assume 1 indent is 3 white spaces - timing_data_k["indent"].append(len(first) // 3) - - timing_data_k["name"].append(elements[0]) - for i in np.arange(1, len(elements)): - timing_data_k[header_elements[i]].append(parse_time(elements[i])) - # We are not interested in the small wrt_output table - if len(timing_data_k["indent"]) > 5: - timing_data.append(timing_data_k) + for i_header in header_lines + ] + timing_data = [ + {**{e: [] for e in header_elements}, "indent": [], "name": []} + for header_elements in header_elements_list + ] + + # walk the file once, routing each row to the table whose header + # column count it matches: prefer the most recently seen header, but + # fall back to any earlier header with a matching column count so + # interleaved rows still land in their real table + # (the historical parser silently dropped the very last matching line + # of the file, e.g. in case a job was killed mid-write; kept here for + # compatibility) + current_table = None + for i, line in enumerate(data[:-1]): + if i in header_positions: + current_table = header_lines.index(i) + continue + + elements = [ + e.replace("[", "").replace("]", "") + for e in line.split(" ") + if e not in ["", "L"] + ] + + target = None + if current_table is not None and len(elements) == len( + header_elements_list[current_table] + ): + target = current_table + else: + for k in range(len(header_elements_list) - 1, -1, -1): + if k != current_table and len(elements) == len( + header_elements_list[k] + ): + target = k + break + + if target is None: + logger.warning( + "Skipping table row that matches no known header: %s", line + ) + continue + + header_elements = header_elements_list[target] + timing_data_k = timing_data[target] + + # find indentation level for each table line + first = re.search(INDENT_REGEX, line).group(0) + # assume 1 indent is 3 white spaces + timing_data_k["indent"].append(len(first) // 3) + + timing_data_k["name"].append(elements[0]) + for i_element in np.arange(1, len(elements)): + timing_data_k[header_elements[i_element]].append( + parse_time(elements[i_element]) + ) + + # We are not interested in the small wrt_output table + timing_data = [t for t in timing_data if len(t["indent"]) > 5] # start parsing meta data from log meta_data = {} From 6505f28302e426ac33323ebd8b7df9b7c3969a21 Mon Sep 17 00:00:00 2001 From: Daniel Hupp Date: Tue, 4 Aug 2026 13:56:36 +0200 Subject: [PATCH 2/4] cleanup --- tests/data/add_1_data.json | 30 ++++++++++++++ tests/data/add_1_tree.json | 11 ++++- tests/data/add_meta.json | 4 +- tests/data/reference_1_data.json | 15 +++++++ tests/data/reference_1_tree.json | 11 ++++- tests/data/reference_meta.json | 4 +- tests/data/timing_example_interleaved.txt | 26 ++++++++++++ tests/util/icon/test_extract_timings.py | 49 ++--------------------- tests/util/icon/test_timing_tree.py | 1 + util/icon/extract_timings.py | 37 +++++++++-------- 10 files changed, 121 insertions(+), 67 deletions(-) create mode 100644 tests/data/timing_example_interleaved.txt diff --git a/tests/data/add_1_data.json b/tests/data/add_1_data.json index bbdd1f2e..a01fa8a0 100644 --- a/tests/data/add_1_data.json +++ b/tests/data/add_1_data.json @@ -1381,6 +1381,36 @@ "total max rank":5.0, "total avg (s)":0.158 }, + { + "level_0":"upatmo_destruction", + "level_1":"2022-06-26T20:11:23", + "# calls":16.0, + "t_min":0.0, + "min rank":2.0, + "t_avg":0.0, + "t_max":0.00001, + "max rank":1.0, + "total min (s)":0.0, + "total min rank":2.0, + "total max (s)":0.0, + "total max rank":1.0, + "total avg (s)":0.0 + }, + { + "level_0":"upatmo_destruction", + "level_1":"2022-06-26T23:54:52", + "# calls":16.0, + "t_min":0.0, + "min rank":1.0, + "t_avg":0.0, + "t_max":0.00001, + "max rank":0.0, + "total min (s)":0.0, + "total min rank":6.0, + "total max (s)":0.0, + "total max rank":0.0, + "total avg (s)":0.0 + }, { "level_0":"upper_atmosphere", "level_1":"2022-06-26T20:11:23", diff --git a/tests/data/add_1_tree.json b/tests/data/add_1_tree.json index 7a9c1750..83a1c471 100644 --- a/tests/data/add_1_tree.json +++ b/tests/data/add_1_tree.json @@ -477,7 +477,16 @@ "ancestry": [ "root" ], - "children": [] + "children": [ + { + "name": "upatmo_destruction", + "ancestry": [ + "root", + "upper_atmosphere" + ], + "children": [] + } + ] } ] } \ No newline at end of file diff --git a/tests/data/add_meta.json b/tests/data/add_meta.json index da4d9f10..f33cc817 100644 --- a/tests/data/add_meta.json +++ b/tests/data/add_meta.json @@ -19,11 +19,11 @@ "entries": [ [ 37, - 48 + 49 ], [ 37, - 48 + 49 ] ] } \ No newline at end of file diff --git a/tests/data/reference_1_data.json b/tests/data/reference_1_data.json index 52b958ab..3e609deb 100644 --- a/tests/data/reference_1_data.json +++ b/tests/data/reference_1_data.json @@ -780,6 +780,21 @@ "total max (s)":0.0, "total max rank":1.0, "total avg (s)":0.0 + }, + { + "level_0":"upatmo_destruction", + "level_1":"2022-06-26T20:11:23", + "# calls":16.0, + "t_min":0.0, + "min rank":2.0, + "t_avg":0.0, + "t_max":0.00001, + "max rank":1.0, + "total min (s)":0.0, + "total min rank":2.0, + "total max (s)":0.0, + "total max rank":1.0, + "total avg (s)":0.0 } ] } \ No newline at end of file diff --git a/tests/data/reference_1_tree.json b/tests/data/reference_1_tree.json index 3946c091..a751b34d 100644 --- a/tests/data/reference_1_tree.json +++ b/tests/data/reference_1_tree.json @@ -480,7 +480,16 @@ "ancestry": [ "root" ], - "children": [] + "children": [ + { + "name": "upatmo_destruction", + "ancestry": [ + "root", + "upper_atmosphere" + ], + "children": [] + } + ] } ] } \ No newline at end of file diff --git a/tests/data/reference_meta.json b/tests/data/reference_meta.json index 538ae99e..93e26e92 100644 --- a/tests/data/reference_meta.json +++ b/tests/data/reference_meta.json @@ -6,6 +6,6 @@ "n_tables": 2, "entries": [ 37, - 48 + 49 ] -} +} \ No newline at end of file diff --git a/tests/data/timing_example_interleaved.txt b/tests/data/timing_example_interleaved.txt new file mode 100644 index 00000000..558941e0 --- /dev/null +++ b/tests/data/timing_example_interleaved.txt @@ -0,0 +1,26 @@ +Sun Jun 26 20:00:00 CEST 2022 + +Timer report, ranks 0-3 + ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- ------------- + name # calls t_min min rank t_avg t_max max rank total min (s) total min rank total max (s) total max rank total avg (s) + ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- ------------- + ------------------------ ------- ------------ ------------ ------------ ------------- ------------- ------------- + name # calls t_min t_avg t_max total min (s) total max (s) total avg (s) + ------------------------ ------- ------------ ------------ ------------ ------------- ------------- ------------- + + wrt_output 2 0.00000s 7.1658s 14.3315s 14.332 14.332 1.791 + ------------------------------------------------------------------------------------------------------------------------------- + + total 8 15.8031s [1] 15.8762s 16.0712s [0] 15.803 [1] 16.071 [0] 15.876 + model_init 1 35.9140s 35.9140s 35.9140s 35.914 35.914 4.489 + L compute_domain_decomp 1 35.9139s 35.9139s 35.9139s 35.914 35.914 4.489 + L integrate_nh 8 2.5080s [0] 3.0333s 3.1584s [3] 2.508 [0] 3.158 [3] 3.033 + L nh_solve 40 0.03204s [0] 0.11028s 0.40723s [1] 0.536 [0] 0.557 [3] 0.551 + L nh_hdiff 16 0.00706s [0] 0.26922s 0.64131s [3] 0.016 [0] 0.654 [3] 0.538 + L physics 8 1.7170s [0] 1.7191s 1.7200s [6] 1.717 [0] 1.720 [6] 1.719 + L transport 8 0.19864s [4] 0.19974s 0.20102s [2] 0.199 [4] 0.201 [2] 0.200 + orphan_row 1 2.0s 3.0s 4.0s 5.0s 6.0s 7.0s 8.0s + L write_restart 16 0.00000s [0] 0.00002s 0.00003s [0] 0.000 [5] 0.000 [6] 0.000 + -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- + +Sun Jun 26 20:11:23 CEST 2022 diff --git a/tests/util/icon/test_extract_timings.py b/tests/util/icon/test_extract_timings.py index af5dda1d..1a9cc731 100644 --- a/tests/util/icon/test_extract_timings.py +++ b/tests/util/icon/test_extract_timings.py @@ -9,46 +9,10 @@ from util.icon.extract_timings import read_logfile -# each data row needs at least one trailing space after its last value: -# TIMING_ELEMENT_REGEX requires a trailing "+" after every numeric token, -# including the last one, so a padding suffix is added to every row below. -_PAD = " " +TIMING_FILE_INTERLEAVED = "tests/data/timing_example_interleaved.txt" -_LINES = [ - "Sun Jun 26 20:00:00 CEST 2022", - "", - "Timer report, ranks 0-3", - " ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- -------------", - " name # calls t_min min rank t_avg t_max max rank total min (s) total min rank total max (s) total max rank total avg (s)", - " ----------------------------------- ------- ------------ -------- ------------ ------------ -------- ------------- -------------- ------------- -------------- -------------", - " ------------------------ ------- ------------ ------------ ------------ ------------- ------------- -------------", - " name # calls t_min t_avg t_max total min (s) total max (s) total avg (s)", - " ------------------------ ------- ------------ ------------ ------------ ------------- ------------- -------------", - "", - " wrt_output 2 0.00000s 7.1658s 14.3315s 14.332 14.332 1.791" + _PAD, - " -------------------------------------------------------------------------------------------------------------------------------", - "", - " total 8 15.8031s [1] 15.8762s 16.0712s [0] 15.803 [1] 16.071 [0] 15.876" + _PAD, - " model_init 1 35.9140s 35.9140s 35.9140s 35.914 35.914 4.489" + _PAD, - " L compute_domain_decomp 1 35.9139s 35.9139s 35.9139s 35.914 35.914 4.489" + _PAD, - " L integrate_nh 8 2.5080s [0] 3.0333s 3.1584s [3] 2.508 [0] 3.158 [3] 3.033" + _PAD, - " L nh_solve 40 0.03204s [0] 0.11028s 0.40723s [1] 0.536 [0] 0.557 [3] 0.551" + _PAD, - " L nh_hdiff 16 0.00706s [0] 0.26922s 0.64131s [3] 0.016 [0] 0.654 [3] 0.538" + _PAD, - " L physics 8 1.7170s [0] 1.7191s 1.7200s [6] 1.717 [0] 1.720 [6] 1.719" + _PAD, - " L transport 8 0.19864s [4] 0.19974s 0.20102s [2] 0.199 [4] 0.201 [2] 0.200" + _PAD, - " orphan_row 1 2.0s 3.0s 4.0s 5.0s 6.0s 7.0s 8.0s" + _PAD, - " L write_restart 16 0.00000s [0] 0.00002s 0.00003s [0] 0.000 [5] 0.000 [6] 0.000" + _PAD, - " exch_data 328 0.00015s [0] 0.02736s 0.63455s [3] 0.107 [0] 1.678 [3] 1.122" + _PAD, - " --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------", - "", - "Sun Jun 26 20:11:23 CEST 2022", - "", -] -INTERLEAVED_LOG = "\n".join(_LINES) - - -def test_read_logfile_handles_interleaved_tables(tmp_path, caplog): +def test_read_logfile_handles_interleaved_tables(caplog): """ The 13-column ("total" tree) table's header is immediately followed by the 8-column ("wrt_output") table's header, and rows from the two tables @@ -56,11 +20,8 @@ def test_read_logfile_handles_interleaved_tables(tmp_path, caplog): must route each row to the table matching its column count instead of crashing or silently mis-assigning rows. """ - logfile = tmp_path / "interleaved.txt" - logfile.write_text(INTERLEAVED_LOG) - with caplog.at_level(logging.WARNING): - timing_data, meta_data = read_logfile(str(logfile)) + timing_data, meta_data = read_logfile(TIMING_FILE_INTERLEAVED) # the small (wrt_output) table only has 3 rows and is dropped by the # "not interested in small tables" filter, same as today; what matters is @@ -80,6 +41,4 @@ def test_read_logfile_handles_interleaved_tables(tmp_path, caplog): # the orphan row matches no known header's column count and must be # skipped with a warning, not silently mis-assigned or fatal - assert any( - "matches no known header" in record.message for record in caplog.records - ) + assert any("matches no known header" in record.message for record in caplog.records) diff --git a/tests/util/icon/test_timing_tree.py b/tests/util/icon/test_timing_tree.py index b1cce16d..f1d43968 100644 --- a/tests/util/icon/test_timing_tree.py +++ b/tests/util/icon/test_timing_tree.py @@ -112,6 +112,7 @@ def test_intersection(): "root>total>integrate_nh>physics>phys_acc_sync", "root>total>integrate_nh>physics>radheat", "root>total>integrate_nh>physics>nwp_radiation>nwp_ecrad_ecrad", + "root>upper_atmosphere>upatmo_destruction", } assert names == ref_names, "set of intersecting nodes does not match reference" diff --git a/util/icon/extract_timings.py b/util/icon/extract_timings.py index 92b9ec9b..bc459bc3 100644 --- a/util/icon/extract_timings.py +++ b/util/icon/extract_timings.py @@ -25,6 +25,25 @@ DICT_REGEX = r"^\s*{} *: *(.*)" +def _find_target_table(elements, current_table, header_elements_list): + """ + Return the index of the table whose header column count matches + `elements`: prefer `current_table`, falling back to any earlier header + with a matching column count (needed when two tables' rows interleave). + Returns None if no header matches. + """ + if current_table is not None and len(elements) == len( + header_elements_list[current_table] + ): + return current_table + + for k in range(len(header_elements_list) - 1, -1, -1): + if k != current_table and len(elements) == len(header_elements_list[k]): + return k + + return None + + def read_logfile(filename): with open(filename, "r", encoding="latin-1") as f: # read file into list of lines, remove empty lines @@ -60,11 +79,8 @@ def read_logfile(filename): # column count it matches: prefer the most recently seen header, but # fall back to any earlier header with a matching column count so # interleaved rows still land in their real table - # (the historical parser silently dropped the very last matching line - # of the file, e.g. in case a job was killed mid-write; kept here for - # compatibility) current_table = None - for i, line in enumerate(data[:-1]): + for i, line in enumerate(data): if i in header_positions: current_table = header_lines.index(i) continue @@ -75,18 +91,7 @@ def read_logfile(filename): if e not in ["", "L"] ] - target = None - if current_table is not None and len(elements) == len( - header_elements_list[current_table] - ): - target = current_table - else: - for k in range(len(header_elements_list) - 1, -1, -1): - if k != current_table and len(elements) == len( - header_elements_list[k] - ): - target = k - break + target = _find_target_table(elements, current_table, header_elements_list) if target is None: logger.warning( From d29a24487f9a67995d6bbbcb9c016a4d9ede9459 Mon Sep 17 00:00:00 2001 From: Daniel Hupp Date: Tue, 4 Aug 2026 14:27:45 +0200 Subject: [PATCH 3/4] add type annotations --- tests/util/icon/test_extract_timings.py | 10 +++++--- util/icon/extract_timings.py | 33 ++++++++++++++++--------- 2 files changed, 28 insertions(+), 15 deletions(-) diff --git a/tests/util/icon/test_extract_timings.py b/tests/util/icon/test_extract_timings.py index 1a9cc731..a857a260 100644 --- a/tests/util/icon/test_extract_timings.py +++ b/tests/util/icon/test_extract_timings.py @@ -7,12 +7,16 @@ import logging +import pytest + from util.icon.extract_timings import read_logfile -TIMING_FILE_INTERLEAVED = "tests/data/timing_example_interleaved.txt" +TIMING_FILE_INTERLEAVED: str = "tests/data/timing_example_interleaved.txt" -def test_read_logfile_handles_interleaved_tables(caplog): +def test_read_logfile_handles_interleaved_tables( + caplog: pytest.LogCaptureFixture, +) -> None: """ The 13-column ("total" tree) table's header is immediately followed by the 8-column ("wrt_output") table's header, and rows from the two tables @@ -28,7 +32,7 @@ def test_read_logfile_handles_interleaved_tables(caplog): # that its rows don't leak into the big table below assert meta_data["n_tables"] == 1 - big_table = timing_data[0] + big_table: dict[str, list] = timing_data[0] assert big_table["name"] == [ "total", "integrate_nh", diff --git a/util/icon/extract_timings.py b/util/icon/extract_timings.py index bc459bc3..06300388 100644 --- a/util/icon/extract_timings.py +++ b/util/icon/extract_timings.py @@ -4,6 +4,7 @@ """ import re +from typing import Optional import numpy as np from dateutil.parser import ParserError @@ -25,7 +26,11 @@ DICT_REGEX = r"^\s*{} *: *(.*)" -def _find_target_table(elements, current_table, header_elements_list): +def _find_target_table( + elements: list[str], + current_table: Optional[int], + header_elements_list: list[list[str]], +) -> Optional[int]: """ Return the index of the table whose header column count matches `elements`: prefer `current_table`, falling back to any earlier header @@ -44,7 +49,7 @@ def _find_target_table(elements, current_table, header_elements_list): return None -def read_logfile(filename): +def read_logfile(filename: str) -> tuple[list[dict[str, list]], dict[str, object]]: with open(filename, "r", encoding="latin-1") as f: # read file into list of lines, remove empty lines full_file = f.read() @@ -57,12 +62,12 @@ def read_logfile(filename): # store line numbers of timing table headers header_lines = [i for i, e in enumerate(data) if re.search(HEADER_REGEX, e)] - header_positions = set(header_lines) + header_positions: set[int] = set(header_lines) # parse each table's header up front, so rows can be routed to the # right table even if two tables' rows end up interleaved in the log # (this can happen with certain MPI rank output orderings) - header_elements_list = [ + header_elements_list: list[list[str]] = [ [ e.lstrip().rstrip() for e in data[i_header].split(" ") @@ -70,7 +75,7 @@ def read_logfile(filename): ] for i_header in header_lines ] - timing_data = [ + timing_data: list[dict[str, list]] = [ {**{e: [] for e in header_elements}, "indent": [], "name": []} for header_elements in header_elements_list ] @@ -79,19 +84,21 @@ def read_logfile(filename): # column count it matches: prefer the most recently seen header, but # fall back to any earlier header with a matching column count so # interleaved rows still land in their real table - current_table = None + current_table: Optional[int] = None for i, line in enumerate(data): if i in header_positions: current_table = header_lines.index(i) continue - elements = [ + elements: list[str] = [ e.replace("[", "").replace("]", "") for e in line.split(" ") if e not in ["", "L"] ] - target = _find_target_table(elements, current_table, header_elements_list) + target: Optional[int] = _find_target_table( + elements, current_table, header_elements_list + ) if target is None: logger.warning( @@ -99,11 +106,13 @@ def read_logfile(filename): ) continue - header_elements = header_elements_list[target] - timing_data_k = timing_data[target] + header_elements: list[str] = header_elements_list[target] + timing_data_k: dict[str, list] = timing_data[target] # find indentation level for each table line - first = re.search(INDENT_REGEX, line).group(0) + indent_match = re.search(INDENT_REGEX, line) + assert indent_match is not None + first = indent_match.group(0) # assume 1 indent is 3 white spaces timing_data_k["indent"].append(len(first) // 3) @@ -116,7 +125,7 @@ def read_logfile(filename): # We are not interested in the small wrt_output table timing_data = [t for t in timing_data if len(t["indent"]) > 5] # start parsing meta data from log - meta_data = {} + meta_data: dict[str, object] = {} # get start and finish time from job # --- robust start/finish datetime extraction --- From 65ab78cd08b57caa4fb4d0bbf3600f2e1ca93f0e Mon Sep 17 00:00:00 2001 From: Daniel Hupp Date: Wed, 5 Aug 2026 10:59:56 +0200 Subject: [PATCH 4/4] update comentns --- tests/util/icon/test_extract_timings.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/tests/util/icon/test_extract_timings.py b/tests/util/icon/test_extract_timings.py index a857a260..f23cadb6 100644 --- a/tests/util/icon/test_extract_timings.py +++ b/tests/util/icon/test_extract_timings.py @@ -28,8 +28,7 @@ def test_read_logfile_handles_interleaved_tables( timing_data, meta_data = read_logfile(TIMING_FILE_INTERLEAVED) # the small (wrt_output) table only has 3 rows and is dropped by the - # "not interested in small tables" filter, same as today; what matters is - # that its rows don't leak into the big table below + # "not interested in small tables" filter assert meta_data["n_tables"] == 1 big_table: dict[str, list] = timing_data[0]