-
Notifications
You must be signed in to change notification settings - Fork 2.2k
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.
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
CI Timing Statistics #38598
CI Timing Statistics #38598
Changes from all commits
c75c23a
c51704d
73c8dca
3650f38
8520aef
dadaf4e
9cd73b1
76c8871
16ed939
587b945
d936549
5f35f44
5bd713c
a86c3ad
c8449ac
891b6d4
99c0f1c
7d23c7a
9e5ec41
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -13,31 +13,32 @@ | |
import sys | ||
import time | ||
from contextlib import contextmanager | ||
from typing import Dict | ||
from typing import Callable, Dict, List | ||
|
||
from llnl.util.lang import pretty_seconds_formatter | ||
|
||
import spack.util.spack_json as sjson | ||
|
||
Interval = collections.namedtuple("Interval", ("begin", "end")) | ||
TimerEvent = collections.namedtuple("TimerEvent", ("time", "running", "label")) | ||
TimeTracker = collections.namedtuple("TimeTracker", ("total", "start", "count", "path")) | ||
|
||
#: name for the global timer (used in start(), stop(), duration() without arguments) | ||
global_timer_name = "_global" | ||
|
||
|
||
class BaseTimer: | ||
def start(self, name=global_timer_name): | ||
def start(self, name=None): | ||
pass | ||
|
||
def stop(self, name=global_timer_name): | ||
def stop(self, name=None): | ||
pass | ||
|
||
def duration(self, name=global_timer_name): | ||
def duration(self, name=None): | ||
return 0.0 | ||
|
||
@contextmanager | ||
def measure(self, name): | ||
yield | ||
yield self | ||
|
||
@property | ||
def phases(self): | ||
|
@@ -60,16 +61,18 @@ class NullTimer(BaseTimer): | |
class Timer(BaseTimer): | ||
"""Simple interval timer""" | ||
|
||
def __init__(self, now=time.time): | ||
def __init__(self, now: Callable[[], float] = time.time): | ||
""" | ||
Arguments: | ||
now: function that gives the seconds since e.g. epoch | ||
""" | ||
self._now = now | ||
self._timers: Dict[str, Interval] = collections.OrderedDict() | ||
self._timers: Dict[str, TimeTracker] = {} | ||
self._timer_stack: List[str] = [] | ||
|
||
# _global is the overal timer since the instance was created | ||
self._timers[global_timer_name] = Interval(self._now(), end=None) | ||
self._events: List[TimerEvent] = [] | ||
# Push start event | ||
self._events.append(TimerEvent(self._now(), True, global_timer_name)) | ||
|
||
def start(self, name=global_timer_name): | ||
""" | ||
|
@@ -79,7 +82,7 @@ def start(self, name=global_timer_name): | |
name (str): Optional name of the timer. When no name is passed, the | ||
global timer is started. | ||
""" | ||
self._timers[name] = Interval(self._now(), None) | ||
self._events.append(TimerEvent(self._now(), True, name)) | ||
|
||
def stop(self, name=global_timer_name): | ||
""" | ||
|
@@ -90,10 +93,7 @@ def stop(self, name=global_timer_name): | |
name (str): Optional name of the timer. When no name is passed, all | ||
timers are stopped. | ||
""" | ||
interval = self._timers.get(name, None) | ||
if not interval: | ||
return | ||
self._timers[name] = Interval(interval.begin, self._now()) | ||
self._events.append(TimerEvent(self._now(), False, name)) | ||
|
||
def duration(self, name=global_timer_name): | ||
""" | ||
|
@@ -107,13 +107,13 @@ def duration(self, name=global_timer_name): | |
Returns: | ||
float: duration of timer. | ||
""" | ||
try: | ||
interval = self._timers[name] | ||
except KeyError: | ||
self._flatten() | ||
if name in self._timers: | ||
if name in self._timer_stack: | ||
return self._timers[name].total + (self._now() - self._timers[name].start) | ||
return self._timers[name].total | ||
else: | ||
return 0.0 | ||
# Take either the interval end, the global timer, or now. | ||
end = interval.end or self._timers[global_timer_name].end or self._now() | ||
return end - interval.begin | ||
|
||
@contextmanager | ||
def measure(self, name): | ||
|
@@ -123,23 +123,72 @@ def measure(self, name): | |
Arguments: | ||
name (str): Name of the timer | ||
""" | ||
begin = self._now() | ||
yield | ||
self._timers[name] = Interval(begin, self._now()) | ||
self.start(name) | ||
yield self | ||
self.stop(name) | ||
|
||
@property | ||
def phases(self): | ||
"""Get all named timers (excluding the global/total timer)""" | ||
return [k for k in self._timers.keys() if k != global_timer_name] | ||
|
||
def write_json(self, out=sys.stdout): | ||
self._flatten() | ||
return [k for k in self._timers.keys() if not k == global_timer_name] | ||
|
||
def _flatten(self): | ||
for event in self._events: | ||
if event.running: | ||
if event.label not in self._timer_stack: | ||
self._timer_stack.append(event.label) | ||
# Only start the timer if it is on top of the stack | ||
# restart doesn't work after a subtimer is started | ||
if event.label == self._timer_stack[-1]: | ||
timer_path = "/".join(self._timer_stack[1:]) | ||
tracker = self._timers.get( | ||
event.label, TimeTracker(0.0, event.time, 0, timer_path) | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. (let's fix this in a follow-up PR) This always allocates a There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I was not aware of deafultdict, noted for the update later to improve the code clarity. |
||
) | ||
assert tracker.path == timer_path | ||
self._timers[event.label] = TimeTracker( | ||
tracker.total, event.time, tracker.count, tracker.path | ||
) | ||
else: # if not event.running: | ||
if event.label in self._timer_stack: | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. What if this is not true? (let's fix this in a follow-up PR if necessary) There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. If it isn't true, you are stopping a timer that was never started, so it is just a noop. Is there something you think should be done in that case? |
||
index = self._timer_stack.index(event.label) | ||
for label in self._timer_stack[index:]: | ||
tracker = self._timers[label] | ||
self._timers[label] = TimeTracker( | ||
tracker.total + (event.time - tracker.start), | ||
None, | ||
tracker.count + 1, | ||
tracker.path, | ||
) | ||
self._timer_stack = self._timer_stack[: max(0, index)] | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. (let's fix this in a follow-up PR) there's no need to use There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Basically I am trying to truncate all of the timer labels in the timer stack after and including "index" |
||
# clear events | ||
self._events = [] | ||
Comment on lines
+136
to
+165
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Can you follow up with a PR that makes this code actually readable? It's hard to see the intent, probably also for you after a couple months. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Like more comments, or re-written in a more pythonic way? |
||
|
||
def write_json(self, out=sys.stdout, extra_attributes={}): | ||
"""Write a json object with times to file""" | ||
phases = [{"name": p, "seconds": self.duration(p)} for p in self.phases] | ||
times = {"phases": phases, "total": {"seconds": self.duration()}} | ||
out.write(sjson.dump(times)) | ||
self._flatten() | ||
data = { | ||
"total": self._timers[global_timer_name].total, | ||
"phases": [ | ||
{ | ||
"name": phase, | ||
"path": self._timers[phase].path, | ||
"seconds": self._timers[phase].total, | ||
"count": self._timers[phase].count, | ||
} | ||
for phase in self.phases | ||
], | ||
} | ||
if extra_attributes: | ||
data.update(extra_attributes) | ||
if out: | ||
out.write(sjson.dump(data)) | ||
else: | ||
return data | ||
|
||
def write_tty(self, out=sys.stdout): | ||
"""Write a human-readable summary of timings""" | ||
"""Write a human-readable summary of timings (depth is 1)""" | ||
self._flatten() | ||
|
||
times = [self.duration(p) for p in self.phases] | ||
|
||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,38 @@ | ||
#!/usr/bin/env spack-python | ||
""" | ||
kwryankrattiger marked this conversation as resolved.
Show resolved
Hide resolved
|
||
This script is meant to be run using: | ||
`spack python aggregate_logs.spack.py` | ||
""" | ||
|
||
import os | ||
|
||
|
||
def find_logs(prefix, filename): | ||
for root, _, files in os.walk(prefix): | ||
if filename in files: | ||
yield os.path.join(root, filename) | ||
|
||
|
||
if __name__ == "__main__": | ||
import json | ||
from argparse import ArgumentParser | ||
|
||
parser = ArgumentParser("aggregate_logs") | ||
parser.add_argument("output_file") | ||
parser.add_argument("--log", default="install_times.json") | ||
parser.add_argument("--prefix", required=True) | ||
|
||
args = parser.parse_args() | ||
|
||
prefixes = [p for p in args.prefix.split(":") if os.path.exists(p)] | ||
|
||
# Aggregate the install timers into a single json | ||
data = [] | ||
kwryankrattiger marked this conversation as resolved.
Show resolved
Hide resolved
|
||
for prefix in prefixes: | ||
time_logs = find_logs(prefix, args.log) | ||
for log in time_logs: | ||
with open(log) as fd: | ||
data.append(json.load(fd)) | ||
|
||
with open(args.output_file, "w") as fd: | ||
json.dump(data, fd) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
this try really shouldn't be required, but for some reason the
_install_from_cache
routine doesn't actually install anything in thetest_install_from_cache_ok
test.