Fix performance problem at login

webapi/src/main/resources/application.conf

@@ -443,6 +443,12 @@ app {
 
         ]
 
+        // If true, the time taken by each SPARQL query is logged at DEBUG level. To see these messages,
+        // set loglevel = "DEBUG" above, and
+        // <logger name="org.knora.webapi.store.triplestore.http.HttpTriplestoreConnector" level="DEBUG"/>
+        // in logback.xml.
+        profile-queries = false
+
         ///////////////////////////////////////////////////////////////////////////////////////////////////////////////
         // Fake triplestore settings
         //

webapi/src/main/scala/org/knora/webapi/Main.scala

@@ -29,15 +29,15 @@ object Main extends App with LiveCore with KnoraService  {
     //Kamon.start()
 
     /* Check and wait until all actors are running */
-    checkActorSystem
+    checkActorSystem()
 
     val arglist = args.toList
 
     if (arglist.contains("loadDemoData")) StartupFlags.loadDemoData send true
     if (arglist.contains("allowResetTriplestoreContentOperationOverHTTP")) StartupFlags.allowResetTriplestoreContentOperationOverHTTP send true
 
     /* Start the HTTP layer, allowing access */
-    startService
+    startService()
 
     sys.addShutdownHook(stopService)
 }

webapi/src/main/scala/org/knora/webapi/Settings.scala

@@ -132,6 +132,8 @@ class SettingsImpl(config: Config) extends Extension {
     val skipAuthentication: Boolean = config.getBoolean("app.skip-authentication")
 
     val fallbackLanguage: String = config.getString("user.default-language")
+
+    val profileQueries: Boolean = config.getBoolean("app.triplestore.profile-queries")
 }
 
 object Settings extends ExtensionId[SettingsImpl] with ExtensionIdProvider {

webapi/src/main/scala/org/knora/webapi/messages/v1/responder/permissionmessages/PermissionMessagesV1.scala

@@ -54,8 +54,8 @@ case class PermissionDataGetV1(projectIris: Seq[IRI],
   * In the case of an existing project, this operation behaves destructive, in the sense that all existing permissions
   * attached to a project are deleted, before any new permissions are created.
   *
-  * @param projectIri          the IRI of the project.
-  * @param permissionsTemplate the permissions template.
+  * param projectIri          the IRI of the project.
+  * param permissionsTemplate the permissions template.
   */
 //case class TemplatePermissionsCreateRequestV1(projectIri: IRI, permissionsTemplate: PermissionsTemplate, userProfileV1: UserProfileV1) extends PermissionsResponderRequestV1
 
@@ -362,10 +362,9 @@ case class DefaultObjectAccessPermissionOperationResponseV1(success: Boolean,
   * @param administrativePermissionsPerProject      the user's administrative permissions for each project.
   * @param defaultObjectAccessPermissionsPerProject the user's default object access permissions for each project.
   */
-case class PermissionDataV1(groupsPerProject: Map[IRI, List[IRI]] = Map.empty[IRI, List[IRI]],
+case class PermissionDataV1(groupsPerProject: Map[IRI, Seq[IRI]] = Map.empty[IRI, Seq[IRI]],
                             administrativePermissionsPerProject: Map[IRI, Set[PermissionV1]] = Map.empty[IRI, Set[PermissionV1]],
-                            defaultObjectAccessPermissionsPerProject: Map[IRI, Set[PermissionV1]] = Map.empty[IRI, Set[PermissionV1]]
-                           ) {
+                            defaultObjectAccessPermissionsPerProject: Map[IRI, Set[PermissionV1]] = Map.empty[IRI, Set[PermissionV1]]) {
 
     /**
       * Returns [[PermissionDataV1]] of the requested type.

webapi/src/main/scala/org/knora/webapi/responders/v1/ProjectsResponderV1.scala

@@ -31,7 +31,7 @@ import org.knora.webapi.messages.v1.responder.usermessages.UserProfileV1
 import org.knora.webapi.messages.v1.store.triplestoremessages._
 import org.knora.webapi.responders.IriLocker
 import org.knora.webapi.util.ActorUtil._
-import org.knora.webapi.util.{KnoraIdUtil, MessageUtil, PermissionUtilV1}
+import org.knora.webapi.util.{KnoraIdUtil, PermissionUtilV1}
 
 import scala.concurrent.Future
 
@@ -122,14 +122,14 @@ class ProjectsResponderV1 extends ResponderV1 {
             //_ = log.debug(s"getProjectsResponseV1 - query: $sparqlQueryString")
 
             projectsResponse <- (storeManager ? SparqlSelectRequest(sparqlQueryString)).mapTo[SparqlSelectResponse]
-            //_ = log.debug(s"getProjectsResponseV1 - result: ${MessageUtil.toSource(projectsResponse)}")
+            //_ = log.debug(s"getProjectsResponseV1 - result: $projectsResponse")
 
             projectsResponseRows: Seq[VariableResultsRow] = projectsResponse.results.bindings
 
             projectsWithProperties: Map[String, Map[String, String]] = projectsResponseRows.groupBy(_.rowMap("s")).map {
                 case (projIri: String, rows: Seq[VariableResultsRow]) => (projIri, rows.map(row => (row.rowMap("p"), row.rowMap("o"))).toMap)
             }
-            //_ = log.debug(s"getProjectsResponseV1 - projectsWithProperties: ${MessageUtil.toSource(projectsWithProperties)}")
+            //_ = log.debug(s"getProjectsResponseV1 - projectsWithProperties: $projectsWithProperties")
 
             projects = projectsWithProperties.map {
                 case (projectIri: String, propsMap: Map[String, String]) =>
@@ -166,14 +166,14 @@ class ProjectsResponderV1 extends ResponderV1 {
             //_ = log.debug(s"getProjectsResponseV1 - query: $sparqlQueryString")
 
             projectsResponse <- (storeManager ? SparqlSelectRequest(sparqlQueryString)).mapTo[SparqlSelectResponse]
-            //_ = log.debug(s"getProjectsResponseV1 - result: ${MessageUtil.toSource(projectsResponse)}")
+            //_ = log.debug(s"getProjectsResponseV1 - result: $projectsResponse")
 
             projectsResponseRows: Seq[VariableResultsRow] = projectsResponse.results.bindings
 
             projectsWithProperties: Map[String, Map[String, String]] = projectsResponseRows.groupBy(_.rowMap("s")).map {
                 case (projIri: String, rows: Seq[VariableResultsRow]) => (projIri, rows.map(row => (row.rowMap("p"), row.rowMap("o"))).toMap)
             }
-            //_ = log.debug(s"getProjectsResponseV1 - projectsWithProperties: ${MessageUtil.toSource(projectsWithProperties)}")
+            //_ = log.debug(s"getProjectsResponseV1 - projectsWithProperties: $projectsWithProperties")
 
             namedGraphs: Seq[NamedGraphV1] = projectsWithProperties.map {
                 case (projectIri: String, propsMap: Map[String, String]) =>
@@ -254,7 +254,7 @@ class ProjectsResponderV1 extends ResponderV1 {
             //_ = log.debug(s"getProjectInfoByShortnameGetRequest - query: $sparqlQueryString")
 
             projectResponse <- (storeManager ? SparqlSelectRequest(sparqlQueryString)).mapTo[SparqlSelectResponse]
-            //_ = log.debug(s"getProjectInfoByShortnameGetRequest - result: ${MessageUtil.toSource(projectResponse)}")
+            //_ = log.debug(s"getProjectInfoByShortnameGetRequest - result: $projectResponse")
 
 
             // get project Iri from results rows
@@ -286,7 +286,7 @@ class ProjectsResponderV1 extends ResponderV1 {
 
             projectInfoQueryResponse <- (storeManager ? SparqlSelectRequest(sparqlQueryString)).mapTo[SparqlSelectResponse]
             projectResponse = projectInfoQueryResponse.results.bindings
-            //_ = log.debug(s"createNewProjectV1 - check duplicate shortname response:  ${MessageUtil.toSource(projectInfoQueryResponse)}")
+            //_ = log.debug(s"createNewProjectV1 - check duplicate shortname response: $projectInfoQueryResponse")
 
             _ = if (projectResponse.nonEmpty) {
                 throw DuplicateValueException(s"Project with the shortname: '${createRequest.shortname}' already exists")
@@ -325,7 +325,7 @@ class ProjectsResponderV1 extends ResponderV1 {
             ).toString
             projectInfoQueryResponse <- (storeManager ? SparqlSelectRequest(sparqlQuery)).mapTo[SparqlSelectResponse]
             projectResponse = projectInfoQueryResponse.results.bindings
-            //_ = log.debug(s"createNewProjectV1 - verify query response: ${MessageUtil.toSource(projectResponse)}")
+            //_ = log.debug(s"createNewProjectV1 - verify query response: $projectResponse")
 
             _ = if (projectResponse.isEmpty) {
                 throw UpdateNotPerformedException(s"Project $newProjectIRI was not created. Please report this as a possible bug.")
@@ -365,15 +365,16 @@ class ProjectsResponderV1 extends ResponderV1 {
       */
     private def createProjectInfoV1(projectResponse: Seq[VariableResultsRow], projectIri: IRI, userProfile: Option[UserProfileV1]): ProjectInfoV1 = {
 
-        log.debug(s"createProjectInfoV1FromProjectResponse - projectResponse: ${MessageUtil.toSource(projectResponse)}")
+        // log.debug(s"createProjectInfoV1FromProjectResponse - projectResponse: $projectResponse")
 
         if (projectResponse.nonEmpty) {
 
             val projectProperties = projectResponse.foldLeft(Map.empty[IRI, String]) {
                 case (acc, row: VariableResultsRow) =>
                     acc + (row.rowMap("p") -> row.rowMap("o"))
             }
-            log.debug(s"createProjectInfoV1FromProjectResponse - projectProperties: ${MessageUtil.toSource(projectProperties)}")
+
+            // log.debug(s"createProjectInfoV1FromProjectResponse - projectProperties: $projectProperties")
 
             /* create and return the project info */
             ProjectInfoV1(

webapi/src/main/scala/org/knora/webapi/routing/Authenticator.scala

@@ -20,14 +20,15 @@
 
 package org.knora.webapi.routing
 
+import java.util.UUID
+
 import akka.actor.ActorSystem
 import akka.http.scaladsl.model._
 import akka.http.scaladsl.model.headers.{HttpCookie, HttpCookiePair}
 import akka.http.scaladsl.server.RequestContext
 import akka.pattern._
 import akka.util.{ByteString, Timeout}
 import com.typesafe.scalalogging.Logger
-import org.knora.webapi
 import org.knora.webapi._
 import org.knora.webapi.messages.v1.responder.usermessages._
 import org.knora.webapi.responders.RESPONDER_MANAGER_ACTOR_PATH
@@ -229,7 +230,7 @@ trait Authenticator {
                             log.debug("Supplied credentials pass authentication, get the UserProfileV1")
 
                             val userProfileV1 = getUserProfileByEmail(e)
-                            log.debug (s"I got a UserProfileV1 '${userProfileV1.toString}', which means that the password is a match")
+                            log.debug(s"I got a UserProfileV1 '${userProfileV1.toString}', which means that the password is a match")
                             /* we return the userProfileV1 without sensitive information */
                             userProfileV1.ofType(UserProfileType.RESTRICTED)
 
@@ -264,7 +265,6 @@ object Authenticator {
     val log = Logger(LoggerFactory.getLogger(this.getClass))
 
 
-
     /**
       * Tries to extract and then authenticate the credentials.
       *
@@ -287,7 +287,7 @@ object Authenticator {
       * password matches. Caches the user profile after successful authentication under a generated session id if 'session=true', and
       * returns that said session id (or 0 if no session is needed).
       *
-      * @param email the email of the user
+      * @param email    the email of the user
       * @param password the password of th user
       * @param session  a [[Boolean]] if set true then a session id will be created and the user profile cached
       * @param system   the current [[ActorSystem]]
@@ -310,7 +310,7 @@ object Authenticator {
             // create session id and cache user profile under this id
             log.debug("authenticateCredentials - password matched")
             if (session) {
-                val sId = System.currentTimeMillis().toString
+                val sId = UUID.randomUUID().toString
                 CacheUtil.put(AUTHENTICATION_CACHE_NAME, sId, userProfileV1)
                 sId
             } else {
@@ -438,6 +438,7 @@ object Authenticator {
             case nfe: NotFoundException => throw BadCredentialsException(s"$BAD_CRED_USER_NOT_FOUND: ${nfe.message}")
         }
 
+        // TODO: return the future here instead of using Await.
         Await.result(userProfileV1Future, Duration(3, SECONDS))
     }
 
@@ -476,6 +477,7 @@ object Authenticator {
                         }
                     }
 
+                    // TODO: return the future here instead of using Await.
                     Await.result(userProfileV1Future, Duration(3, SECONDS))
             }
         } else {

webapi/src/main/scala/org/knora/webapi/store/triplestore/http/HttpTriplestoreConnector.scala

@@ -385,6 +385,12 @@ class HttpTriplestoreConnector extends Actor with ActorLogging {
 
             // _ = println(request.toString())
 
+            requestStartTime: Long = if (settings.profileQueries) {
+                System.currentTimeMillis()
+            } else {
+                0
+            }
+
             // Send the HTTP request.
             response <- http.singleRequest(request)
 
@@ -394,6 +400,11 @@ class HttpTriplestoreConnector extends Actor with ActorLogging {
             _ = if (!response.status.isSuccess) {
                 throw TriplestoreResponseException(s"Triplestore responded with HTTP code ${response.status}: $responseString")
             }
+
+            _ = if (settings.profileQueries) {
+                val requestDuration = System.currentTimeMillis() - requestStartTime
+                log.debug(s"${logDelimiter}Query took $requestDuration millis:\n\n$sparql$logDelimiter")
+            }
         } yield responseString
 
         // If an exception was thrown during the connection to the triplestore, wrap it in

webapi/src/main/scala/org/knora/webapi/util/FakeTriplestore.scala

@@ -21,15 +21,10 @@
 package org.knora.webapi.util
 
 import java.io.File
-import java.nio.charset.StandardCharsets
-import java.nio.file.{Files, Paths}
 
 import akka.event.LoggingAdapter
 import org.apache.commons.io.FileUtils
 
-import scala.collection.breakOut
-import scala.io.{Codec, Source}
-
 /**
   * A fake triplestore for use in performance testing. This feature is activated in `application.conf`.
   */
@@ -41,23 +36,24 @@ object FakeTriplestore {
 
     var data = Map.empty[String, String]
 
-    def init(dataDir: File) = {
+    def init(dataDir: File): Unit = {
         fakeTriplestoreDir = Some(dataDir)
     }
 
-    def clear() = {
+    def clear(): Unit = {
         FileUtils.deleteDirectory(fakeTriplestoreDir.get)
         fakeTriplestoreDir.get.mkdirs()
         ()
     }
 
-    def load() = {
-        val dataToWrap: Map[String, String] = fakeTriplestoreDir.get.listFiles.map {
+    def load(): Unit = {
+        val dataToWrap = fakeTriplestoreDir.get.listFiles.map {
             queryDir =>
-                val sparql = readFile(queryDir.listFiles.filter(_.getName.endsWith(".rq")).head)
-                val result = readFile(queryDir.listFiles.filter(_.getName.endsWith(".json")).head)
-                (sparql, result)
-        }(breakOut)
+                val sparql = FileUtil.readFile(queryDir.listFiles.filter(_.getName.endsWith(".rq")).head)
+                val result = FileUtil.readFile(queryDir.listFiles.filter(_.getName.endsWith(".json")).head)
+                sparql -> result
+        }.toMap
+
         data = new ErrorHandlingMap(dataToWrap, { key: String => s"No result has been stored in the fake triplestore for this query: $key" })
     }
 
@@ -68,18 +64,11 @@ object FakeTriplestore {
             val queryDir = new File(fakeTriplestoreDir.get, paddedQueryNum)
             queryDir.mkdirs()
             val sparqlFile = new File(queryDir, s"query-$paddedQueryNum.rq")
-            writeFile(sparqlFile, sparql)
+            FileUtil.writeFile(sparqlFile, sparql)
             val resultFile = new File(queryDir, s"response-$paddedQueryNum.json")
-            writeFile(resultFile, result)
+            FileUtil.writeFile(resultFile, result)
             queryNum += 1
         }
     }
 
-    private def writeFile(file: File, content: String) = {
-        Files.write(Paths.get(file.getCanonicalPath), content.getBytes(StandardCharsets.UTF_8))
-    }
-
-    private def readFile(file: File) = {
-        Source.fromFile(file)(Codec.UTF8).mkString
-    }
 }

webapi/src/main/scala/org/knora/webapi/util/FileUtil.scala

@@ -0,0 +1,52 @@
+/*
+ * Copyright © 2015 Lukas Rosenthaler, Benjamin Geer, Ivan Subotic,
+ * Tobias Schweizer, André Kilchenmann, and Sepideh Alassi.
+ *
+ * This file is part of Knora.
+ *
+ * Knora is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU Affero General Public License as published
+ * by the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * Knora is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public
+ * License along with Knora.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+package org.knora.webapi.util
+
+import java.io.File
+import java.nio.charset.StandardCharsets
+import java.nio.file.{Files, Paths}
+
+import scala.io.{Codec, Source}
+
+/**
+  * Functions for reading and writing files.
+  */
+object FileUtil {
+    /**
+      * Writes a string to a file.
+      *
+      * @param file the destination file.
+      * @param content the string to write.
+      */
+    def writeFile(file: File, content: String): Unit = {
+        Files.write(Paths.get(file.getCanonicalPath), content.getBytes(StandardCharsets.UTF_8))
+    }
+
+    /**
+      * Reads a file into a string.
+      *
+      * @param file the source file.
+      * @return the contents of the file.
+      */
+    def readFile(file: File): String = {
+        Source.fromFile(file)(Codec.UTF8).mkString
+    }
+}