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_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/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 new file mode 100644 index 00000000..f23cadb6 --- /dev/null +++ b/tests/util/icon/test_extract_timings.py @@ -0,0 +1,47 @@ +""" +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 + +import pytest + +from util.icon.extract_timings import read_logfile + +TIMING_FILE_INTERLEAVED: str = "tests/data/timing_example_interleaved.txt" + + +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 + 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. + """ + with caplog.at_level(logging.WARNING): + 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 + assert meta_data["n_tables"] == 1 + + big_table: dict[str, list] = 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/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 38ca251d..06300388 100644 --- a/util/icon/extract_timings.py +++ b/util/icon/extract_timings.py @@ -4,7 +4,7 @@ """ import re -import sys +from typing import Optional import numpy as np from dateutil.parser import ParserError @@ -26,7 +26,30 @@ DICT_REGEX = r"^\s*{} *: *(.*)" -def read_logfile(filename): +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 + 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: 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() @@ -39,61 +62,70 @@ 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[int] = 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: list[list[str]] = [ + [ 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: list[dict[str, list]] = [ + {**{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 + current_table: Optional[int] = None + for i, line in enumerate(data): + if i in header_positions: + current_table = header_lines.index(i) + continue + + elements: list[str] = [ + e.replace("[", "").replace("]", "") + for e in line.split(" ") + if e not in ["", "L"] + ] + + target: Optional[int] = _find_target_table( + elements, current_table, header_elements_list + ) + + if target is None: + logger.warning( + "Skipping table row that matches no known header: %s", line + ) + continue + + header_elements: list[str] = header_elements_list[target] + timing_data_k: dict[str, list] = timing_data[target] + + # find indentation level for each table line + 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) + + 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 = {} + meta_data: dict[str, object] = {} # get start and finish time from job # --- robust start/finish datetime extraction ---