Print Execution duration in completion message

docs/changelog.md

@@ -21,6 +21,8 @@
   Reorganized configuration to separate targets,
   triggers (formerly "lifecycles"),
   and flows (graphs of targets and triggers)."
+- [#41](https://github.com/JoshKarpel/synthesize/pull/41)
+  Execution duration is printed in the completion message.
 
 ## `0.0.2`
 

synthesize/execution.py

@@ -4,9 +4,11 @@
 from asyncio import Queue, Task, create_task
 from asyncio.subprocess import PIPE, STDOUT, Process, create_subprocess_exec
 from dataclasses import dataclass, field
+from datetime import timedelta
 from pathlib import Path
 from signal import SIGKILL, SIGTERM
 from stat import S_IEXEC
+from time import monotonic
 
 from synthesize.config import Args, Envs, FlowNode
 from synthesize.messages import ExecutionCompleted, ExecutionOutput, ExecutionStarted, Message
@@ -39,6 +41,7 @@ class Execution:
     events: Queue[Message] = field(repr=False)
 
     process: Process
+    start_time: float
     reader: Task[None]
 
     @classmethod
@@ -53,6 +56,8 @@ async def start(
     ) -> Execution:
         path = write_script(node=node, args=args, tmp_dir=tmp_dir)
 
+        start_time = monotonic()
+
         process = await create_subprocess_exec(
             program=path,
             stdout=PIPE,
@@ -86,6 +91,7 @@ async def start(
             node=node,
             events=events,
             process=process,
+            start_time=start_time,
             reader=reader,
         )
 
@@ -115,6 +121,7 @@ def kill(self) -> None:
 
     async def wait(self) -> Execution:
         exit_code = await self.process.wait()
+        end_time = monotonic()
 
         await self.reader
 
@@ -123,6 +130,7 @@ async def wait(self) -> Execution:
                 node=self.node,
                 pid=self.pid,
                 exit_code=exit_code,
+                duration=timedelta(seconds=end_time - self.start_time),
             )
         )
 

synthesize/messages.py

@@ -1,4 +1,4 @@
-from datetime import datetime
+from datetime import datetime, timedelta
 
 from pydantic import Field
 from watchfiles import Change
@@ -20,6 +20,7 @@ class ExecutionCompleted(Message):
     node: FlowNode
     pid: int
     exit_code: int
+    duration: timedelta
 
 
 class ExecutionOutput(Message):

synthesize/renderer.py

@@ -120,11 +120,12 @@ def handle_lifecycle_message(
                     (node.id, node.color),
                     f" started (pid {pid})",
                 )
-            case ExecutionCompleted(node=node, pid=pid, exit_code=exit_code):
+            case ExecutionCompleted(node=node, pid=pid, exit_code=exit_code, duration=duration):
                 parts = (
                     (node.id, node.color),
                     f" (pid {pid}) exited with code ",
                     (str(exit_code), "green" if exit_code == 0 else "red"),
+                    f" in {duration.total_seconds() :.3f} seconds",
                 )
             case WatchPathChanged(node=node):
                 changes = Text(" ").join(

tests/test_execution.py

@@ -49,6 +49,7 @@ async def test_execution_lifecycle(tmp_path: Path) -> None:
     assert msg.node is node
     assert msg.pid == ex.pid
     assert msg.exit_code == ex.exit_code == 0
+    assert msg.duration.total_seconds() > 0
 
 
 async def test_termination_before_completion(tmp_path: Path) -> None: