Skip to content

rework scheduler wait time metric to include total time in scheduler #5258

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Jun 15, 2022
Merged

rework scheduler wait time metric to include total time in scheduler #5258

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 4 additions & 2 deletions common/scala/src/main/scala/org/apache/openwhisk/common/Logging.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -591,8 +591,9 @@ object LoggingMarkers {

// Time that is needed to produce message in kafka
val SCHEDULER_KAFKA = LogMarkerToken(scheduler, kafka, start)(MeasurementUnit.time.milliseconds)
val SCHEDULER_WAIT_TIME =
LogMarkerToken(scheduler, "waitTime", counter)(MeasurementUnit.none)
val SCHEDULER_KAFKA_WAIT_TIME =
LogMarkerToken(scheduler, "kafkaWaitTime", counter)(MeasurementUnit.none)
def SCHEDULER_WAIT_TIME(action: String) = LogMarkerToken(scheduler, "waitTime", counter, Some(action), Map("action" -> action))(MeasurementUnit.none)

def SCHEDULER_KEEP_ALIVE(leaseId: Long) =
LogMarkerToken(scheduler, "keepAlive", counter, None, Map("leaseId" -> leaseId.toString))(MeasurementUnit.none)
Expand All @@ -603,6 +604,7 @@ object LoggingMarkers {
LogMarkerToken(scheduler, "queueUpdate", counter, None, Map("reason" -> reason))(MeasurementUnit.none)
def SCHEDULER_QUEUE_WAITING_ACTIVATION(action: String) =
LogMarkerToken(scheduler, "queueActivation", counter, Some(action), Map("action" -> action))(MeasurementUnit.none)

/*
* General markers
*/
Expand Down
20 changes: 12 additions & 8 deletions core/scheduler/src/main/scala/org/apache/openwhisk/core/scheduler/queue/MemoryQueue.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,6 @@ package org.apache.openwhisk.core.scheduler.queue

import java.time.{Duration, Instant}
import java.util.concurrent.atomic.AtomicInteger

import akka.actor.Status.{Failure => FailureMessage}
import akka.actor.{ActorRef, ActorSystem, Cancellable, FSM, Props, Stash}
import akka.util.Timeout
Expand All @@ -28,19 +27,15 @@ import org.apache.openwhisk.core.ConfigKeys
import org.apache.openwhisk.core.ack.ActiveAck
import org.apache.openwhisk.core.connector.ContainerCreationError.{TooManyConcurrentRequests, ZeroNamespaceLimit}
import org.apache.openwhisk.core.connector._
import org.apache.openwhisk.core.containerpool.Interval
import org.apache.openwhisk.core.database.{NoDocumentException, UserContext}
import org.apache.openwhisk.core.entity._
import org.apache.openwhisk.core.entity.size._
import org.apache.openwhisk.core.etcd.EtcdClient
import org.apache.openwhisk.core.etcd.EtcdKV.ContainerKeys.containerPrefix
import org.apache.openwhisk.core.etcd.EtcdKV.{ContainerKeys, QueueKeys, ThrottlingKeys}
import org.apache.openwhisk.core.scheduler.grpc.{GetActivation, ActivationResponse => GetActivationResponse}
import org.apache.openwhisk.core.scheduler.message.{
ContainerCreation,
ContainerDeletion,
FailedCreationJob,
SuccessfulCreationJob
}
import org.apache.openwhisk.core.scheduler.message.{ContainerCreation, ContainerDeletion, FailedCreationJob, SuccessfulCreationJob}
import org.apache.openwhisk.core.scheduler.{SchedulerEndpoints, SchedulingConfig}
import org.apache.openwhisk.core.service._
import org.apache.openwhisk.http.Messages.{namespaceLimitUnderZero, tooManyConcurrentRequests}
Expand All @@ -52,7 +47,7 @@ import scala.annotation.tailrec
import scala.collection.immutable.Queue
import scala.collection.mutable
import scala.concurrent.duration._
import scala.concurrent.{duration, ExecutionContextExecutor, Future, Promise}
import scala.concurrent.{ExecutionContextExecutor, Future, Promise, duration}
import scala.util.{Failure, Success}

// States
Expand Down Expand Up @@ -769,6 +764,10 @@ class MemoryQueue(private val etcdClient: EtcdClient,
this,
s"[$invocationNamespace:$action:$stateName] complete activation ${activation.activationId} with error $message")(
activation.transid)

val totalTimeInScheduler = Interval(activation.transid.meta.start, Instant.now()).duration
MetricEmitter.emitHistogramMetric(LoggingMarkers.SCHEDULER_WAIT_TIME(action.asString), totalTimeInScheduler.toMillis)

val activationResponse =
if (isWhiskError)
generateFallbackActivation(activation, ActivationResponse.whiskError(message))
Expand Down Expand Up @@ -938,6 +937,8 @@ class MemoryQueue(private val etcdClient: EtcdClient,
in.incrementAndGet()
takeUncompletedRequest()
.map { res =>
val totalTimeInScheduler = Interval(msg.transid.meta.start, Instant.now()).duration
MetricEmitter.emitHistogramMetric(LoggingMarkers.SCHEDULER_WAIT_TIME(action.asString), totalTimeInScheduler.toMillis)
res.trySuccess(Right(msg))
in.decrementAndGet()
stay
Expand All @@ -958,6 +959,9 @@ class MemoryQueue(private val etcdClient: EtcdClient,
logging.info(
this,
s"[$invocationNamespace:$action:$stateName] Get activation request ${request.containerId}, send one message: ${msg.activationId}")
val totalTimeInScheduler = Interval(msg.transid.meta.start, Instant.now()).duration
MetricEmitter.emitHistogramMetric(LoggingMarkers.SCHEDULER_WAIT_TIME(action.asString), totalTimeInScheduler.toMillis)

sender ! GetActivationResponse(Right(msg))
tryDisableActionThrottling()
} else {
Expand Down
2 changes: 1 addition & 1 deletion core/scheduler/src/main/scala/org/apache/openwhisk/core/scheduler/queue/QueueManager.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -391,7 +391,7 @@ class QueueManager(

// Drop the message that has not been scheduled for a long time
val schedulingWaitTime = Interval(msg.transid.meta.start, Instant.now()).duration
MetricEmitter.emitHistogramMetric(LoggingMarkers.SCHEDULER_WAIT_TIME, schedulingWaitTime.toMillis)
MetricEmitter.emitHistogramMetric(LoggingMarkers.SCHEDULER_KAFKA_WAIT_TIME, schedulingWaitTime.toMillis)

if (schedulingWaitTime > queueManagerConfig.maxSchedulingTime) {
logging.warn(
Expand Down