diff --git a/orca-queue/src/main/kotlin/com/netflix/spinnaker/orca/q/handler/CompleteStageHandler.kt b/orca-queue/src/main/kotlin/com/netflix/spinnaker/orca/q/handler/CompleteStageHandler.kt index d773619498..b46e5bc8de 100644 --- a/orca-queue/src/main/kotlin/com/netflix/spinnaker/orca/q/handler/CompleteStageHandler.kt +++ b/orca-queue/src/main/kotlin/com/netflix/spinnaker/orca/q/handler/CompleteStageHandler.kt @@ -179,9 +179,17 @@ class CompleteStageHandler( } ?: id } + // If startTime was not set, then assume this was instantaneous. + // In practice 0 startTimes can happen if there is + // an exception in StartStageHandler or guard causing skipping. + // Without a startTime, we cannot record a meaningful time, + // and assuming a start of 0 makes the values ridiculously large. + val endTime = stage.endTime ?: clock.millis() + val startTime = stage.startTime ?: endTime + PercentileTimer .get(registry, id) - .record((stage.endTime ?: clock.millis()) - (stage.startTime ?: 0), TimeUnit.MILLISECONDS) + .record(endTime - startTime, TimeUnit.MILLISECONDS) } override val messageType = CompleteStage::class.java diff --git a/orca-queue/src/main/kotlin/com/netflix/spinnaker/orca/q/handler/StartStageHandler.kt b/orca-queue/src/main/kotlin/com/netflix/spinnaker/orca/q/handler/StartStageHandler.kt index 54f741b887..64f46d6e64 100644 --- a/orca-queue/src/main/kotlin/com/netflix/spinnaker/orca/q/handler/StartStageHandler.kt +++ b/orca-queue/src/main/kotlin/com/netflix/spinnaker/orca/q/handler/StartStageHandler.kt @@ -88,12 +88,14 @@ class StartStageHandler( queue.push(SkipStage(stage)) } else { try { + // Set the startTime in case we throw an exception. + stage.startTime = clock.millis() + repository.storeStage(stage) + stage.withAuth { stage.plan() } - stage.status = RUNNING - stage.startTime = clock.millis() repository.storeStage(stage) stage.start() diff --git a/orca-queue/src/test/kotlin/com/netflix/spinnaker/orca/q/handler/StartStageHandlerTest.kt b/orca-queue/src/test/kotlin/com/netflix/spinnaker/orca/q/handler/StartStageHandlerTest.kt index 97fe4ffeb0..84a7622bd8 100644 --- a/orca-queue/src/test/kotlin/com/netflix/spinnaker/orca/q/handler/StartStageHandlerTest.kt +++ b/orca-queue/src/test/kotlin/com/netflix/spinnaker/orca/q/handler/StartStageHandlerTest.kt @@ -172,14 +172,14 @@ object StartStageHandlerTest : SubjectSpek({ } it("updates the stage status") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.status).isEqualTo(RUNNING) assertThat(it.startTime).isEqualTo(clock.millis()) }) } it("attaches tasks to the stage") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.tasks.size).isEqualTo(1) it.tasks.first().apply { assertThat(id).isEqualTo("1") @@ -226,7 +226,7 @@ object StartStageHandlerTest : SubjectSpek({ } it("updates the stage status") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.status).isEqualTo(RUNNING) assertThat(it.startTime).isEqualTo(clock.millis()) }) @@ -267,7 +267,7 @@ object StartStageHandlerTest : SubjectSpek({ } it("updates the stage status") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.status).isEqualTo(RUNNING) assertThat(it.startTime).isEqualTo(clock.millis()) }) @@ -308,7 +308,7 @@ object StartStageHandlerTest : SubjectSpek({ afterGroup(::resetMocks) it("attaches tasks to the stage") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.tasks.size).isEqualTo(3) it.tasks[0].apply { assertThat(id).isEqualTo("1") @@ -646,7 +646,7 @@ object StartStageHandlerTest : SubjectSpek({ } it("starts the stage") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.type).isEqualTo("bar") assertThat(it.status).isEqualTo(RUNNING) assertThat(it.startTime).isEqualTo(clock.millis()) @@ -654,7 +654,7 @@ object StartStageHandlerTest : SubjectSpek({ } it("attaches a task to the stage") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.tasks.size).isEqualTo(1) it.tasks.first().apply { assertThat(id).isEqualTo("1") @@ -731,7 +731,7 @@ object StartStageHandlerTest : SubjectSpek({ } it("attaches the exception to the stage context") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.context["exception"]).isEqualTo(exceptionDetails) }) } @@ -761,13 +761,13 @@ object StartStageHandlerTest : SubjectSpek({ } it("attaches the exception to the stage context") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.context["exception"]).isEqualTo(exceptionDetails) }) } it("attaches flag to the stage context to indicate that before stage planning failed") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.context["beforeStagePlanningFailed"]).isEqualTo(true) }) } @@ -797,13 +797,13 @@ object StartStageHandlerTest : SubjectSpek({ } it("attaches the exception to the stage context") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.context["exception"]).isEqualTo(exceptionDetails) }) } it("attaches flag to the stage context to indicate that before stage planning failed") { - verify(repository).storeStage(check { + verify(repository, times(2)).storeStage(check { assertThat(it.context["beforeStagePlanningFailed"]).isEqualTo(true) }) }