Skip to content

Fix interleaving timetable parse #113

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
huppd wants to merge 4 commits into
base: main
Choose a base branch
from
Open

Fix interleaving timetable parse #113

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
f1b0886
first draft
huppd Aug 4, 2026
6505f28
cleanup
huppd Aug 4, 2026
d29a244
add type annotations
huppd Aug 4, 2026
65ab78c
update comentns
huppd Aug 5, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
30 changes: 30 additions & 0 deletions tests/data/add_1_data.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
11 changes: 10 additions & 1 deletion tests/data/add_1_tree.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -477,7 +477,16 @@
"ancestry": [
"root"
],
"children": []
"children": [
{
"name": "upatmo_destruction",
"ancestry": [
"root",
"upper_atmosphere"
],
"children": []
}
]
}
]
}
4 changes: 2 additions & 2 deletions tests/data/add_meta.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,11 +19,11 @@
"entries": [
[
37,
48
49
],
[
37,
48
49
]
]
}
15 changes: 15 additions & 0 deletions tests/data/reference_1_data.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
]
}
11 changes: 10 additions & 1 deletion tests/data/reference_1_tree.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -480,7 +480,16 @@
"ancestry": [
"root"
],
"children": []
"children": [
{
"name": "upatmo_destruction",
"ancestry": [
"root",
"upper_atmosphere"
],
"children": []
}
]
}
]
}
4 changes: 2 additions & 2 deletions tests/data/reference_meta.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,6 @@
"n_tables": 2,
"entries": [
37,
48
49
]
}
}
16 changes: 5 additions & 11 deletions tests/data/timing_example_1.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
26 changes: 26 additions & 0 deletions tests/data/timing_example_interleaved.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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
47 changes: 47 additions & 0 deletions tests/util/icon/test_extract_timings.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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)
1 change: 1 addition & 0 deletions tests/util/icon/test_timing_tree.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
134 changes: 83 additions & 51 deletions util/icon/extract_timings.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@
"""

import re
import sys
from typing import Optional

import numpy as np
from dateutil.parser import ParserError
Expand All @@ -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()
Expand All @@ -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 ---
Expand Down
Loading