Add first implementation of a logger

This is needed mostly for debugging and benchmarking purposes. We tried
to make it as "out of the way" as possible.

4 files changed, 230 insertions, 129 deletions

diff --git a/src/main/scala/uk/ac/ox/cs/rsacomb/Main.scala b/src/main/scala/uk/ac/ox/cs/rsacomb/Main.scala
index d41ca8c..5246d2f 100644
--- a/src/main/scala/uk/ac/ox/cs/rsacomb/Main.scala
+++ b/src/main/scala/uk/ac/ox/cs/rsacomb/Main.scala
@@ -10,7 +10,7 @@ import tech.oxfordsemantic.jrdfox.logic.sparql.statement.SelectQuery
 import tech.oxfordsemantic.jrdfox.logic.expression.{IRI, Term}
 
 /* Local imports */
-import util.{RDFoxUtil, RSA}
+import util.{Logger, RDFoxUtil, RSA}
 import sparql.ConjunctiveQuery
 
 object RSAComb extends App {
@@ -53,15 +53,17 @@ object RSAComb extends App {
 
   val ontology = RSAOntology(ontoPaths: _*)
   if (ontology.isRSA) {
-    //println("ONTOLOGY IS RSA")
+
+    Logger print "Ontology is RSA!"
 
     /** Read SPARQL query from file */
-    val source = io.Source.fromFile(queryPath.getAbsoluteFile)
-    val query = source.getLines mkString "\n"
-    source.close()
+    val query = RDFoxUtil.loadQueryFromFile(queryPath.getAbsoluteFile)
 
     /* Compute answers to query */
-    val answers = ConjunctiveQuery(query).map(ontology ask _)
-    answers map (_.toString) foreach println
+    ConjunctiveQuery(query).map(ontology ask _) match {
+      case Some(answers) => Logger print answers
+      case None =>
+        throw new RuntimeException("Submitted query is not conjunctive")
+    }
   }
 }
diff --git a/src/main/scala/uk/ac/ox/cs/rsacomb/RSAOntology.scala b/src/main/scala/uk/ac/ox/cs/rsacomb/RSAOntology.scala
index 52d4905..87a2312 100644
--- a/src/main/scala/uk/ac/ox/cs/rsacomb/RSAOntology.scala
+++ b/src/main/scala/uk/ac/ox/cs/rsacomb/RSAOntology.scala
@@ -54,6 +54,7 @@ import uk.ac.ox.cs.rsacomb.converter._
 import uk.ac.ox.cs.rsacomb.suffix._
 import uk.ac.ox.cs.rsacomb.sparql._
 import uk.ac.ox.cs.rsacomb.util.{RDFoxUtil, RSA}
+import uk.ac.ox.cs.rsacomb.util.Logger
 
 object RSAOntology {
 
@@ -141,87 +142,91 @@ class RSAOntology(val ontology: OWLOntology) {
    *    why the ontology might not be RSA. This could help a second
    *    step of approximation of an Horn-ALCHOIQ to RSA
    */
-  lazy val isRSA: Boolean = {
-
-    val unsafe = this.unsafeRoles
-
-    /* DEBUG: print rules in DL syntax and unsafe roles */
-    //val renderer = new DLSyntaxObjectRenderer()
-    //println("\nDL rules:")
-    //axioms.foreach(x => println(renderer.render(x)))
-    //println("\nUnsafe roles:")
-    //println(unsafe)
-
-    object RSAConverter extends RDFoxConverter {
-
-      override def convert(
-          expr: OWLClassExpression,
-          term: Term,
-          unsafe: List[OWLObjectPropertyExpression],
-          skolem: SkolemStrategy,
-          suffix: RSASuffix
-      ): Shards =
-        (expr, skolem) match {
-
-          case (e: OWLObjectSomeValuesFrom, c: Constant)
-              if unsafe contains e.getProperty => {
-            val (res, ext) = super.convert(e, term, unsafe, skolem, suffix)
-            (RSA.PE(term, c.iri) :: RSA.U(c.iri) :: res, ext)
-          }
-
-          case (e: OWLDataSomeValuesFrom, c: Constant)
-              if unsafe contains e.getProperty => {
-            val (res, ext) = super.convert(e, term, unsafe, skolem, suffix)
-            (RSA.PE(term, c.iri) :: RSA.U(c.iri) :: res, ext)
+  lazy val isRSA: Boolean = Logger.timed(
+    {
+      val unsafe = this.unsafeRoles
+
+      // val renderer = new DLSyntaxObjectRenderer()
+      // println()
+      // println("Unsafe roles:")
+      // println(unsafe)
+      // println()
+      // println("DL rules:")
+      // tbox.foreach(x => println(renderer.render(x)))
+
+      object RSAConverter extends RDFoxConverter {
+
+        override def convert(
+            expr: OWLClassExpression,
+            term: Term,
+            unsafe: List[OWLObjectPropertyExpression],
+            skolem: SkolemStrategy,
+            suffix: RSASuffix
+        ): Shards =
+          (expr, skolem) match {
+
+            case (e: OWLObjectSomeValuesFrom, c: Constant)
+                if unsafe contains e.getProperty => {
+              val (res, ext) = super.convert(e, term, unsafe, skolem, suffix)
+              (RSA.PE(term, c.iri) :: RSA.U(c.iri) :: res, ext)
+            }
+
+            case (e: OWLDataSomeValuesFrom, c: Constant)
+                if unsafe contains e.getProperty => {
+              val (res, ext) = super.convert(e, term, unsafe, skolem, suffix)
+              (RSA.PE(term, c.iri) :: RSA.U(c.iri) :: res, ext)
+            }
+
+            case _ => super.convert(expr, term, unsafe, skolem, suffix)
           }
 
-          case _ => super.convert(expr, term, unsafe, skolem, suffix)
-        }
-
-    }
-
-    /* Ontology convertion into LP rules */
-    val term = RSAOntology.genFreshVariable()
-    val datalog = axioms
-      .map(a => RSAConverter.convert(a, term, unsafe, new Constant(a), Empty))
-      .unzip
-    val facts = datalog._1.flatten
-    val rules = datalog._2.flatten
-
-    /* DEBUG: print datalog rules */
-    //println("\nDatalog rules:")
-    //rules.foreach(println)
-
-    // Open connection with RDFox
-    val (server, data) = RDFoxUtil.openConnection("RSACheck")
-
-    /* Add built-in rules
-     * TODO: substitute with RDFoxUtil.addRules
-     */
-    data.importData(
-      UpdateType.ADDITION,
-      RSA.Prefixes,
-      "rsa:E[?X,?Y] :- rsa:PE[?X,?Y], rsa:U[?X], rsa:U[?Y] ."
-    )
-
-    /* Add ontology facts and rules */
-    RDFoxUtil.addFacts(data, facts)
-    RDFoxUtil.addRules(data, rules)
-
-    /* Build graph */
-    val graph = this.rsaGraph(data);
-    //println(graph)
-
-    // Close connection to RDFox
-    RDFoxUtil.closeConnection(server, data)
+      }
+
+      /* Ontology convertion into LP rules */
+      val term = RSAOntology.genFreshVariable()
+      val datalog = axioms
+        .map(a => RSAConverter.convert(a, term, unsafe, new Constant(a), Empty))
+        .unzip
+      val facts = datalog._1.flatten
+      val rules = datalog._2.flatten
+
+      //println("Datalog rules:")
+      //rules foreach println
+
+      // Open connection with RDFox
+      val (server, data) = RDFoxUtil.openConnection("RSACheck")
+
+      /* Add built-in rules
+       * TODO: substitute with RDFoxUtil.addRules
+       */
+      data.importData(
+        UpdateType.ADDITION,
+        RSA.Prefixes,
+        "rsa:E[?X,?Y] :- rsa:PE[?X,?Y], rsa:U[?X], rsa:U[?Y] ."
+      )
 
-    /* To check if the graph is tree-like we check for acyclicity in a
-     * undirected graph.
-     *
-     * TODO: Implement additional checks (taking into account equality)
-     */
-    graph.isAcyclic
-  }
+      /* Add ontology facts and rules */
+      RDFoxUtil.addFacts(data, facts)
+      RDFoxUtil.addRules(data, rules)
+
+      /* Build graph */
+      val graph = this.rsaGraph(data);
+      //println("Graph:")
+      //println(graph)
+
+      // Close connection to RDFox
+      RDFoxUtil.closeConnection(server, data)
+
+      /* To check if the graph is tree-like we check for acyclicity in a
+       * undirected graph.
+       *
+       * TODO: Implement additional checks (taking into account equality)
+       */
+      graph.isAcyclic
+    },
+    "RSA check",
+    Logger.DEBUG
+  )
 
   lazy val unsafeRoles: List[OWLObjectPropertyExpression] = {
 
@@ -288,9 +293,17 @@ class RSAOntology(val ontology: OWLOntology) {
   }
 
   def filteringProgram(query: ConjunctiveQuery): FilteringProgram =
-    new FilteringProgram(query, individuals)
+    Logger.timed(
+      new FilteringProgram(query, individuals),
+      "Generating filtering program",
+      Logger.DEBUG
+    )
 
-  lazy val canonicalModel = new CanonicalModel(this)
+  lazy val canonicalModel = Logger.timed(
+    new CanonicalModel(this),
+    "Generating canonical model program",
+    Logger.DEBUG
+  )
 
   // TODO: the following functions needs testing
   def confl(
@@ -321,27 +334,42 @@ class RSAOntology(val ontology: OWLOntology) {
     *  @param query query to execute
     *  @return a collection of answers
     */
-  def ask(query: ConjunctiveQuery): ConjunctiveQueryAnswers = {
-    import implicits.JavaCollections._
-    val (server, data) = RDFoxUtil.openConnection(RSAOntology.DataStore)
-    val filter = this.filteringProgram(query)
-    RDFoxUtil.addRules(data, this.canonicalModel.rules)
-    RDFoxUtil.addFacts(data, this.canonicalModel.facts)
-    RDFoxUtil.addRules(data, filter.rules)
-    RDFoxUtil.addFacts(data, filter.facts)
-    val answers = RDFoxUtil
-      .submitQuery(
-        data,
-        RDFoxUtil.buildDescriptionQuery("Ans", query.answer.size),
-        RSA.Prefixes
-      )
-      .map(
-        new ConjunctiveQueryAnswers(query.bcq, _)
-      )
-      .get
-    RDFoxUtil.closeConnection(server, data)
-    answers
-  }
+  def ask(query: ConjunctiveQuery): ConjunctiveQueryAnswers = Logger.timed(
+    {
+      import implicits.JavaCollections._
+      val (server, data) = RDFoxUtil.openConnection(RSAOntology.DataStore)
+      val canon = this.canonicalModel
+      val filter = this.filteringProgram(query)
+
+      Logger print s"Canonical model: ${canon.rules.length} rules"
+      RDFoxUtil.addRules(data, this.canonicalModel.rules)
+
+      Logger print s"Canonical model: ${canon.facts.length} facts"
+      RDFoxUtil.addFacts(data, this.canonicalModel.facts)
+
+      RDFoxUtil printStatisticsFor data
+
+      Logger print s"Filtering program: ${filter.rules.length} rules"
+      RDFoxUtil.addRules(data, filter.rules)
+
+      Logger print s"Filtering program: ${filter.facts.length} facts"
+      RDFoxUtil.addFacts(data, filter.facts)
+
+      RDFoxUtil printStatistics data
+
+      val answers = {
+        val ans = RDFoxUtil.buildDescriptionQuery("Ans", query.answer.size)
+        RDFoxUtil
+          .submitQuery(data, ans, RSA.Prefixes)
+          .map(new ConjunctiveQueryAnswers(query.bcq, query.variables, _))
+          .get
+      }
+      RDFoxUtil.closeConnection(server, data)
+      answers
+    },
+    "Answers computation",
+    Logger.DEBUG
+  )
 
   /** Query the RDFox data store used for query answering.
     *
diff --git a/src/main/scala/uk/ac/ox/cs/rsacomb/util/Logger.scala b/src/main/scala/uk/ac/ox/cs/rsacomb/util/Logger.scala
new file mode 100644
index 0000000..74797a2
--- /dev/null
+++ b/src/main/scala/uk/ac/ox/cs/rsacomb/util/Logger.scala
@@ -0,0 +1,45 @@
+package uk.ac.ox.cs.rsacomb.util
+
+import java.util.Calendar
+import java.io.PrintStream
+
+/** Rough implementation of a logger.
+  *
+  * This is a WIP class for debugging and benchmarking.
+  */
+object Logger {
+
+  /** Output stream for the logger. */
+  var output: PrintStream = System.out
+
+  /** Logger levels (i.e., verbosity of output) */
+  sealed abstract class Level(val level: Int, val name: String)
+      extends Ordered[Level] {
+    def compare(that: Level) = this.level - that.level
+    override def toString = name
+  }
+  case object QUIET extends Level(0, "normal")
+  case object NORMAL extends Level(1, "normal")
+  case object DEBUG extends Level(2, "debug")
+  case object VERBOSE extends Level(3, "verbose")
+
+  /** Currend logger level */
+  var level: Level = DEBUG
+
+  def print(str: Any, lvl: Level = NORMAL): Unit = {
+    if (lvl <= level) {
+      val time = Calendar.getInstance.getTime
+      output println s"[$lvl][$time] $str"
+    }
+  }
+
+  def timed[A](expr: => A, desc: String = "", lvl: Level = NORMAL): A = {
+    val t0 = System.currentTimeMillis()
+    print(s"$desc (START)", lvl)
+    val result = expr
+    val t1 = System.currentTimeMillis()
+    print(s"$desc (END): ${(t1 - t0).toFloat / 1000}s", lvl)
+    result
+  }
+
+}
diff --git a/src/main/scala/uk/ac/ox/cs/rsacomb/util/RDFoxUtil.scala b/src/main/scala/uk/ac/ox/cs/rsacomb/util/RDFoxUtil.scala
index 9dd52cf..51ef903 100644
--- a/src/main/scala/uk/ac/ox/cs/rsacomb/util/RDFoxUtil.scala
+++ b/src/main/scala/uk/ac/ox/cs/rsacomb/util/RDFoxUtil.scala
@@ -1,5 +1,6 @@
 package uk.ac.ox.cs.rsacomb.util
 
+import java.io.File
 import java.io.StringReader
 import tech.oxfordsemantic.jrdfox.Prefixes
 import tech.oxfordsemantic.jrdfox.client.{
@@ -20,6 +21,7 @@ import tech.oxfordsemantic.jrdfox.logic.datalog.{
 import tech.oxfordsemantic.jrdfox.logic.expression.{Resource}
 import tech.oxfordsemantic.jrdfox.logic.sparql.statement.SelectQuery
 import uk.ac.ox.cs.rsacomb.suffix.Nth
+import uk.ac.ox.cs.rsacomb.util.Logger
 
 /** A collection of helper methods for RDFox */
 object RDFoxUtil {
@@ -67,18 +69,21 @@ object RDFoxUtil {
     (server, data)
   }
 
-  /** Gather statistics from RDFox datastore.
+  /** Prints statistics from RDFox datastore.
+    *
+    * Prints something only when Logger level is set to DEBUG or more.
     *
     * @see [[https://docs.oxfordsemantic.tech/programmatic-access-APIs.html#in-depth-diagnostic-information]]
     * and [[https://docs.oxfordsemantic.tech/programmatic-access-APIs.html#managing-statistics]]
     * for more ways of gathering diagnostics from RDFox.
     */
-  def gatherStatistics(data: DataStoreConnection): String = {
+  def printStatisticsFor(data: DataStoreConnection): Unit = {
     val info = data.getComponentInfo(true)
-    s"${info.getName}: ${info.getPropertyValues}"
+    val stats = s"${info.getName}: ${info.getPropertyValues}"
       .replaceAll("\\{", "{\n  ")
       .replaceAll(", ", ",\n  ")
       .replaceAll("\\}", "\n}")
+    Logger.print(stats, Logger.DEBUG)
   }
 
   /** Adds a collection of rules to a data store.
@@ -87,7 +92,11 @@ object RDFoxUtil {
     * @param rules collection of rules to be added to the data store
     */
   def addRules(data: DataStoreConnection, rules: Seq[Rule]): Unit =
-    data addRules rules
+    Logger.timed(
+      data addRules rules,
+      "Loading rules",
+      Logger.DEBUG
+    )
 
   /** Adds a collection of facts to a data store.
     *
@@ -95,12 +104,25 @@ object RDFoxUtil {
     * @param facts collection of facts to be added to the data store
     */
   def addFacts(data: DataStoreConnection, facts: Seq[TupleTableAtom]): Unit =
-    data.importData(
-      UpdateType.ADDITION,
-      RSA.Prefixes,
-      facts.map(_.toString(Prefixes.s_emptyPrefixes)).mkString("", ".\n", ".")
+    Logger.timed(
+      data.importData(
+        UpdateType.ADDITION,
+        RSA.Prefixes,
+        facts.map(_.toString(Prefixes.s_emptyPrefixes)).mkString("", ".\n", ".")
+      ),
+      "Loading facts",
+      Logger.DEBUG
     )
 
+  /** Load SPARQL query from file. */
+  def loadQueryFromFile(file: File): String = {
+    val source = io.Source.fromFile(file)
+    val query = source.getLines mkString "\n"
+    Logger print s"Loaded query:\n$query"
+    source.close()
+    query
+  }
+
   /** Parse a SELECT query from a string in SPARQL format.
     *
     * @param query the string containing the SPARQL query
@@ -136,19 +158,23 @@ object RDFoxUtil {
       data: DataStoreConnection,
       query: SelectQuery,
       opts: RDFoxOpts = RDFoxOpts()
-  ): QueryAnswers = {
-    val cursor = data.createCursor(query, opts)
-    var answers = QueryAnswers()
-    var mul = cursor.open()
-    while (mul > 0) {
-      val answer =
-        (0 until cursor.getArity).map(cursor.getResource(_)).toList
-      answers = answer :: answers
-      mul = cursor.advance()
-    }
-    cursor.close();
-    answers
-  }
+  ): QueryAnswers = Logger.timed(
+    {
+      val cursor = data.createCursor(query, opts)
+      var answers = QueryAnswers()
+      var mul = cursor.open()
+      while (mul > 0) {
+        val answer =
+          (0 until cursor.getArity).map(cursor.getResource(_)).toList
+        answers = answer :: answers
+        mul = cursor.advance()
+      }
+      cursor.close();
+      answers
+    },
+    "Answer query",
+    Logger.DEBUG
+  )
 
   /** Execute a query over a given datastore connection.
     *