Fixes #14922: Missing timing logs in ldap queries (especially for dyn…

…amic groups)
Normation · May 21, 2019 · 72082aa · 72082aa
1 parent da11982
commit 72082aa
Show file tree

Hide file tree

Showing 3 changed files with 23 additions and 10 deletions.
diff --git a/...er-core/src/main/scala/com/normation/rudder/services/queries/DynGroupUpdaterService.scala b/...er-core/src/main/scala/com/normation/rudder/services/queries/DynGroupUpdaterService.scala
@@ -93,11 +93,14 @@ class DynGroupUpdaterServiceImpl(
 
   override def computeDynGroup (group : NodeGroup): Box[NodeGroup] = {
     for {
-      _          <- if(group.isDynamic) Full("OK") else Failure("Can not update a not dynamic group")
-      query      <- Box(group.query) ?~! s"No query defined for group '${group.name}' (${group.id.value})"
-      newMembers <- queryProcessor.process(query) ?~! s"Error when processing request for updating dynamic group '${group.name}' (${group.id.value})"
+      _              <- if(group.isDynamic) Full("OK") else Failure("Can not update a not dynamic group")
+      timePreCompute =  System.currentTimeMillis
+      query          <- Box(group.query) ?~! s"No query defined for group '${group.name}' (${group.id.value})"
+      newMembers     <- queryProcessor.process(query) ?~! s"Error when processing request for updating dynamic group '${group.name}' (${group.id.value})"
       //save
       newMemberIdsSet = newMembers.map(_.id).toSet
+      timeGroupCompute=  (System.currentTimeMillis - timePreCompute)
+      _               =  logger.debug(s"Dynamic group ${group.id.value} with name ${group.name} computed in ${timeGroupCompute} ms")
     } yield {
       group.copy(serverList = newMemberIdsSet)
     }
@@ -122,11 +125,13 @@ class DynGroupUpdaterServiceImpl(
   }
 
   override def update(dynGroupId:NodeGroupId, modId: ModificationId, actor:EventActor, reason:Option[String]) : Box[DynGroupDiff] = {
-
+    val timePreUpdate =  System.currentTimeMillis
     for {
-      (group,_)  <- roNodeGroupRepository.getNodeGroup(dynGroupId)
-      newGroup   <- computeDynGroup(group)
-      savedGroup <- woNodeGroupRepository.updateDynGroupNodes(newGroup, modId, actor, reason) ?~! s"Error when saving update for dynamic group '${group.name}' (${group.id.value})"
+      (group,_)        <- roNodeGroupRepository.getNodeGroup(dynGroupId)
+      newGroup         <- computeDynGroup(group)
+      savedGroup       <- woNodeGroupRepository.updateDynGroupNodes(newGroup, modId, actor, reason) ?~! s"Error when saving update for dynamic group '${group.name}' (${group.id.value})"
+      timeGroupUpdate  =  (System.currentTimeMillis - timePreUpdate)
+      _                =  logger.debug(s"Dynamic group ${group.id.value} with name ${group.name} updated in ${timeGroupUpdate} ms")
     } yield {
       DynGroupDiff(newGroup, group)
     }

diff --git a/...rudder-core/src/main/scala/com/normation/rudder/services/queries/LdapQueryProcessor.scala b/...rudder-core/src/main/scala/com/normation/rudder/services/queries/LdapQueryProcessor.scala
@@ -162,10 +162,15 @@ class AcceptedNodesLDAPQueryProcessor(
   ) : Box[Seq[QueryResult]] = {
 
     val debugId = if(logger.isDebugEnabled) Helpers.nextNum else 0L
+    val timePreCompute =  System.currentTimeMillis
 
     for {
-      res         <- processor.internalQueryProcessor(query,select,limitToNodeIds,debugId)
-      ldapEntries <- nodeInfoService.getLDAPNodeInfo(res.entries.flatMap(x => x(A_NODE_UUID).map(NodeId(_))).toSet, res.nodeFilters, query.composition)
+      res            <- processor.internalQueryProcessor(query,select,limitToNodeIds,debugId)
+      timeres        =  (System.currentTimeMillis - timePreCompute)
+      _              =  logger.debug(s"Result obtained in ${timeres}ms for query ${query.toString}")
+      ldapEntries    <- nodeInfoService.getLDAPNodeInfo(res.entries.flatMap(x => x(A_NODE_UUID).map(NodeId(_))).toSet, res.nodeFilters, query.composition)
+      ldapEntryTime  =  (System.currentTimeMillis - timePreCompute - timeres)
+      _              =  logger.trace(s"Result of query converted in LDAP Entry in ${ldapEntryTime} ms")
     } yield {
 
       val inNodes = ldapEntries.map { case LDAPNodeInfo(nodeEntry, nodeInv, machineInv) =>

diff --git a/webapp/sources/rudder/rudder-web/src/main/resources/logback.xml b/webapp/sources/rudder/rudder-web/src/main/resources/logback.xml
@@ -173,6 +173,9 @@ along with Rudder.  If not, see <http://www.gnu.org/licenses/>.
   -->
   <logger name="com.normation.rudder.services.queries" level="info" />
 
+  <!-- Specific logger for Dynamic group update -->
+  <logger name="com.normation.rudder.services.queries.DynGroupUpdaterServiceImpl" level="info" />
+
   <!--
     Dump Node Configurations
     ========================
@@ -360,7 +363,7 @@ along with Rudder.  If not, see <http://www.gnu.org/licenses/>.
     ================
     This logger is in charge of all scheduled jobs and batches
   -->
-  <logger name="scheduledJob" level="info" additivity="false">
+  <logger name="scheduledJob" level="debug" additivity="false">
     <appender-ref ref="OPSLOG" />
     <appender-ref ref="STDOUT" />
   </logger>