Merge pull request #65 from oqc-community/jd/profiling-hooks

Logging, cleanup

src/rasqal/rasqal/runtime.py

@@ -2,19 +2,11 @@
 # Copyright (c) 2024 Oxford Quantum Circuits Ltd
 
 from os import remove
-from os.path import dirname, exists, join
 from tempfile import NamedTemporaryFile
 from typing import Any, List, Union
 
-from .utils import initialize_logger
 from .adaptors import RuntimeAdaptor
-from ._native import DEFAULT_LOG_FILE, Executor
-
-dev_directory = join(dirname(__file__), "..", "..", "..", "rasqalkin")
-
-# Enable file logging if we're in a development environment.
-if exists(dev_directory):
-    initialize_logger(join(f"{dev_directory}", f"{DEFAULT_LOG_FILE}"))
+from ._native import Executor
 
 
 class RasqalRunner:

src/rasqal/src/evaluator.rs

@@ -25,13 +25,14 @@ use llvm_sys::core::{
 };
 use llvm_sys::prelude::LLVMValueRef;
 use llvm_sys::LLVMTypeKind;
-use log::warn;
+use log::{log, warn, Level};
 use regex::Regex;
 use std::borrow::{Borrow, BorrowMut};
 use std::collections::HashMap;
 use std::f64::consts::PI;
 use std::ffi::{c_uint, CStr};
 use std::ops::Deref;
+use std::time::Instant;
 
 macro_rules! operand_to_value {
   ($target:ident, $index:expr) => {
@@ -231,7 +232,10 @@ impl QIREvaluator {
       target_global = global.get_next_global();
     }
 
+    let start = Instant::now();
     let builder = self.walk_function(entry_point, context.borrow());
+    let took = start.elapsed();
+    log!(Level::Info, "Evaluation took {}ms.", took.as_millis());
 
     // Create a callable graph with its arguments, but the values set as empty (validly).
     let mut callable = Ptr::from(CallableAnalysisGraph::new(&builder.graph));

src/rasqal/src/execution.rs

@@ -24,6 +24,7 @@ use inkwell::{
 
 use crate::config::RasqalConfig;
 use crate::exceptions::catch_panics;
+use log::{log, Level};
 use std::ops::Deref;
 use std::{ffi::OsStr, path::Path};
 
@@ -38,6 +39,11 @@ pub fn run_file(
 pub fn parse_file(
   path: impl AsRef<Path>, entry_point: Option<&str>
 ) -> Result<Ptr<ExecutableAnalysisGraph>, String> {
+  log!(
+    Level::Info,
+    "Parsing from {}.",
+    path.as_ref().to_str().unwrap()
+  );
   let context = Context::create();
   let module = file_to_module(path, &context)?;
   catch_panics(|| build_graph_from_module(&module, entry_point))
@@ -78,11 +84,15 @@ pub fn build_graph_from_module(
     Target::initialize_native(&InitializationConfig::default())?;
     inkwell::support::load_library_permanently(Path::new(""));
 
+    let entry_point = choose_entry_point(module_functions(module), entry_point)?;
+
+    log!(
+      Level::Info,
+      "{} is the entry-point.",
+      entry_point.get_name().to_str().unwrap()
+    );
     let evaluator = QIREvaluator::new();
-    evaluator.evaluate(
-      &choose_entry_point(module_functions(module), entry_point)?,
-      &Ptr::from(module)
-    )
+    evaluator.evaluate(&entry_point, &Ptr::from(module))
   })
 }
 

src/rasqal/src/lib.rs

@@ -41,7 +41,6 @@ const DEFAULT_LOG_FILE: &str = "rasqal_logs.txt";
 
 /// Native initialization of the loggers. Defaults to executable position if deployed, if it
 /// detects it's in development mode it'll move log file back up the folder tree.
-#[ctor::ctor]
 fn native_logger_initialize() {
   let path = if let Ok(val) = current_exe() {
     // If we're embedded we need to be given a different file path to log too.

src/rasqal/src/runtime.rs

@@ -18,6 +18,7 @@ use std::borrow::{Borrow, BorrowMut};
 use std::collections::{HashMap, HashSet, VecDeque};
 use std::fmt::{Display, Formatter};
 use std::ops::{Add, AddAssign, Deref, DerefMut};
+use std::time::Instant;
 
 /// Assign an order to nodes so we're able to tell trivially when one is further in the graph
 /// or not.
@@ -410,7 +411,13 @@ impl QuantumRuntime {
       log!(Level::Info, "Currently executing graph:\n{}", exe_graph);
     }
 
-    self
+    log!(
+      Level::Info,
+      "Starting execution at {}.",
+      exe_graph.callable_graph.analysis_graph.identity
+    );
+    let start = Instant::now();
+    let results = self
       ._execute(
         exe_graph.callable_graph.analysis_graph.borrow(),
         &mut context
@@ -419,10 +426,6 @@ impl QuantumRuntime {
         val.as_ref()?;
         let val = follow_reference(&val.unwrap(), &context);
 
-        if self.is_tracing() {
-          log!(Level::Info, "Total steps taken: {}", context.step_count)
-        }
-
         // TODO: Centralize resolution, think we already have this elsewhere.
         Some(match val.deref() {
           Value::QuantumPromise(qbs, proj) => Ptr::from(Value::AnalysisResult(Ptr::from(
@@ -442,7 +445,22 @@ impl QuantumRuntime {
           )),
           _ => val.clone()
         })
-      })
+      });
+
+    let took = start.elapsed();
+    log!(
+      Level::Info,
+      "Run {} after {:?}ms with {} steps taken.",
+      if results.is_ok() {
+        "succeeded"
+      } else {
+        "failed"
+      },
+      took.as_millis(),
+      context.step_count
+    );
+
+    results
   }
 
   fn _execute(
@@ -472,7 +490,6 @@ impl QuantumRuntime {
     loop {
       context.step_count.add_assign(1);
       if let Some(limit) = &self.constraints.step_limit {
-        let stuff = context.step_count.deref().clone();
         if context.step_count.deref() > limit {
           return Err(String::from(format!(
             "Execution step count limitation of {limit} exceeded."
@@ -584,7 +601,7 @@ impl QuantumRuntime {
           };
 
           // Trim since we're just logging per-line.
-          log!(Level::Info, "{}", message.trim());
+          log!(target: &graph.identity, Level::Info, "{}", message.trim());
         }
         Instruction::Subgraph(subgraph, var) => {
           let subgraph = follow_reference(subgraph, context).as_callable();