Merge branch 'logger' into master

5 files changed, 298 insertions, 143 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 c7ace0f..eaacedc 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,38 @@ 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 strQuery = RDFoxUtil.loadQueryFromFile(queryPath.getAbsoluteFile)
+    val query = ConjunctiveQuery parse strQuery
+
+    query match {
+      case Some(query) => {
+        val answers = ontology ask query
+        Logger.print(s"$answers", Logger.QUIET)
+        Logger print s"Number of answer: ${answers.length}"
+
+        val unfiltered = ontology askUnfiltered query
+        val percentage = unfiltered match {
+          case Some(u) => {
+            Logger.print(
+              s"Number of spurious answers: ${u.length}.",
+              Logger.DEBUG
+            )
+            if (u.length > 0) (1 - answers.length / u.length) * 100 else 0
+          }
+          case None => 0
+        }
+        Logger.print(
+          s"Percentage of spurious answers: $percentage%",
+          Logger.DEBUG
+        )
+      }
+      case None =>
+        throw new RuntimeException("Submitted query is not conjunctive")
+    }
 
-    /* Compute answers to query */
-    val answers = ConjunctiveQuery.parse(query).map(ontology ask _)
-    answers map (_.toString) foreach println
   }
 }
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 0fb6c96..0f1cd5e 100644
--- a/src/main/scala/uk/ac/ox/cs/rsacomb/RSAOntology.scala
+++ b/src/main/scala/uk/ac/ox/cs/rsacomb/RSAOntology.scala
@@ -56,6 +56,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 {
 
@@ -109,6 +110,10 @@ class RSAOntology(val ontology: OWLOntology) {
 
   val axioms: List[OWLLogicalAxiom] = abox ::: tbox ::: rbox
 
+  Logger.print(s"Original TBox: ${tbox.length} axioms", Logger.DEBUG)
+  Logger.print(s"Original RBox: ${rbox.length} axioms", Logger.DEBUG)
+  Logger.print(s"Original ABox: ${abox.length} axioms", Logger.DEBUG)
+
   /* Retrieve individuals in the original ontology
    */
   val individuals: List[IRI] =
@@ -149,87 +154,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)
+  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 (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)
-        }
-
-    }
-
-    /* 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] = {
 
@@ -289,16 +298,23 @@ class RSAOntology(val ontology: OWLOntology) {
   ): Graph[Resource, UnDiEdge] = {
     val query = "SELECT ?X ?Y WHERE { ?X rsa:E ?Y }"
     val answers = RDFoxUtil.submitQuery(data, query, RSA.Prefixes).get
-    var edges: Seq[UnDiEdge[Resource]] = answers.map { case Seq(n1, n2) =>
-      UnDiEdge(n1, n2)
-    }
+    var edges: Seq[UnDiEdge[Resource]] =
+      answers.collect { case (_, Seq(n1, n2)) => UnDiEdge(n1, n2) }
     Graph(edges: _*)
   }
 
   def filteringProgram(query: ConjunctiveQuery): FilteringProgram =
-    new FilteringProgram(query, individuals ++ literals)
+    Logger.timed(
+      new FilteringProgram(query, individuals ++ literals),
+      "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(
@@ -329,27 +345,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, query.variables, _)
-      )
-      .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 printStatisticsFor 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.
     *
@@ -370,13 +401,29 @@ class RSAOntology(val ontology: OWLOntology) {
       query: String,
       prefixes: Prefixes = new Prefixes(),
       opts: ju.Map[String, String] = new ju.HashMap[String, String]()
-  ): Option[Seq[Seq[Resource]]] = {
+  ): Option[Seq[(Long, Seq[Resource])]] = {
     val (server, data) = RDFoxUtil.openConnection(RSAOntology.DataStore)
     val answers = RDFoxUtil.submitQuery(data, query, prefixes, opts)
     RDFoxUtil.closeConnection(server, data)
     answers
   }
 
+  /** Returns set of unfiltered answers.
+    *
+    * This is equivalent to quering just the canonical model.
+    *
+    * @note this method does not load any data to RDFox. The return
+    * value is considered well defined only after
+    * [[uk.ac.ox.cs.rsacomb.RSAOntology.ask RSAOntology.ask]]
+    * for the corresponding query has been called.
+    */
+  def askUnfiltered(
+      cq: ConjunctiveQuery
+  ): Option[Seq[(Long, Seq[Resource])]] = {
+    val query = RDFoxUtil.buildDescriptionQuery("QM", cq.variables.length)
+    queryDataStore(cq, query, RSA.Prefixes)
+  }
+
   def self(axiom: OWLSubClassOfAxiom): Set[Term] = {
     // Assuming just one role in the signature of a T5 axiom
     val role = axiom.objectPropertyExpressionsInSignature(0)
diff --git a/src/main/scala/uk/ac/ox/cs/rsacomb/sparql/ConjunctiveQueryAnswers.scala b/src/main/scala/uk/ac/ox/cs/rsacomb/sparql/ConjunctiveQueryAnswers.scala
index 3db5500..7edc867 100644
--- a/src/main/scala/uk/ac/ox/cs/rsacomb/sparql/ConjunctiveQueryAnswers.scala
+++ b/src/main/scala/uk/ac/ox/cs/rsacomb/sparql/ConjunctiveQueryAnswers.scala
@@ -19,9 +19,15 @@ import tech.oxfordsemantic.jrdfox.logic.expression.{
 class ConjunctiveQueryAnswers(
     bcq: Boolean,
     val variables: Seq[Variable],
-    val answers: Seq[Seq[Resource]]
+    val answers: Seq[(Long, Seq[Resource])]
 ) {
 
+  /** Returns number of distinct answers. */
+  val length: Int = if (bcq) 0 else answers.length
+
+  /** Returns number of answers taking into account multiplicity. */
+  val lengthWithMultiplicity: Long = answers.map(_._1).sum
+
   override def toString(): String =
     if (bcq) {
       if (answers.isEmpty) "FALSE" else "TRUE"
@@ -31,11 +37,15 @@ class ConjunctiveQueryAnswers(
       else {
         val header = variables map (_.getName) mkString "\t"
         val body = answers
-          .map(_.map {
-            case x: IRI     => x.getIRI
-            case x: Literal => x.getLexicalForm
-            case x          => x.toString
-          }.mkString("\t"))
+          .map(
+            _._2
+              .map {
+                case x: IRI     => x.getIRI
+                case x: Literal => x.getLexicalForm
+                case x          => x.toString
+              }
+              .mkString("\t")
+          )
           .mkString("\n")
         s"$header\n$body"
       }
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..76f720c 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 {
@@ -35,8 +37,8 @@ object RDFoxUtil {
   /** Type alias for a collection of answers to a
     * [[tech.oxfordsemantic.jrdfox.logic.sparql.statement.Query]].
     */
-  private type QueryAnswers = Seq[Seq[Resource]]
-  private def QueryAnswers() = List.empty[Seq[Resource]]
+  private type QueryAnswers = Seq[(Long, Seq[Resource])]
+  private def QueryAnswers() = List.empty[(Long, Seq[Resource])]
 
   /** Type alias for <option => value> RDFox options. */
   private type RDFoxOpts = java.util.Map[String, String]
@@ -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,29 @@ 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
     )
 
+  /** Force materialization in RDFox. */
+  def materialize(data: DataStoreConnection): Unit =
+    Logger.timed(data.updateMaterialization(), "Materialization", 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 +162,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 = (mul, answer) :: answers
+        mul = cursor.advance()
+      }
+      cursor.close();
+      answers
+    },
+    "Answer query",
+    Logger.DEBUG
+  )
 
   /** Execute a query over a given datastore connection.
     *
@@ -188,7 +218,7 @@ object RDFoxUtil {
           .map(i => s"?S rsa:${pred :: Nth(i)} ?X$i .")
           .mkString("WHERE {\n", "\n", "\n}")
     } else {
-      s"ASK { ?X a rsa:$pred }"
+      s"ASK { ?X a rsa:${pred :: Nth(0)} }"
     }
   }