io.micrometer.core.instrument.LongTaskTimer Java Examples

@Test
public void givenLongTimer_whenRunTasks_thenTimerRecorded() {
    SimpleMeterRegistry registry = new SimpleMeterRegistry();
    LongTaskTimer longTaskTimer = LongTaskTimer
      .builder("3rdPartyService")
      .register(registry);

    long currentTaskId = longTaskTimer.start();
    try {
        TimeUnit.MILLISECONDS.sleep(2);
    } catch (InterruptedException ignored) {
    }
    long timeElapsed = longTaskTimer.stop(currentTaskId);

    assertEquals(2L, timeElapsed/((int) 1e6),1L);
}
 

private void record(TimingSampleContext timingContext, HttpServletResponse response, HttpServletRequest request,
                    Object handlerObject, Throwable e) {
    for (Timed timedAnnotation : timingContext.timedAnnotations) {
        timingContext.timerSample.stop(Timer.builder(timedAnnotation, metricName)
            .tags(tagsProvider.httpRequestTags(request, response, handlerObject, e))
            .register(registry));
    }

    if (timingContext.timedAnnotations.isEmpty() && autoTimeRequests) {
        timingContext.timerSample.stop(Timer.builder(metricName)
            .tags(tagsProvider.httpRequestTags(request, response, handlerObject, e))
            .register(registry));
    }

    for (LongTaskTimer.Sample sample : timingContext.longTaskTimerSamples) {
        sample.stop();
    }
}
 

@SuppressWarnings("ConstantConditions")
@Override
LongTaskTimer registerNewMeter(MeterRegistry registry) {
    LongTaskTimer.Builder builder = LongTaskTimer.builder(getId().getName())
            .tags(getId().getTagsAsIterable())
            .description(getId().getDescription())
            .maximumExpectedValue(Duration.ofNanos(distributionStatisticConfig.getMaximumExpectedValueAsDouble().longValue()))
            .minimumExpectedValue(Duration.ofNanos(distributionStatisticConfig.getMinimumExpectedValueAsDouble().longValue()))
            .publishPercentiles(distributionStatisticConfig.getPercentiles())
            .publishPercentileHistogram(distributionStatisticConfig.isPercentileHistogram())
            .distributionStatisticBufferLength(distributionStatisticConfig.getBufferLength())
            .distributionStatisticExpiry(distributionStatisticConfig.getExpiry())
            .percentilePrecision(distributionStatisticConfig.getPercentilePrecision());

    final double[] sloNanos = distributionStatisticConfig.getServiceLevelObjectiveBoundaries();
    if (sloNanos != null) {
        Duration[] slo = new Duration[sloNanos.length];
        for (int i = 0; i < sloNanos.length; i++) {
            slo[i] = Duration.ofNanos((long) sloNanos[i]);
        }
        builder = builder.serviceLevelObjectives(slo);
    }

    return builder.register(registry);
}
 

private Object processWithLongTaskTimer(ProceedingJoinPoint pjp, Timed timed, String metricName, boolean stopWhenCompleted) throws Throwable {

        Optional<LongTaskTimer.Sample> sample = buildLongTaskTimer(pjp, timed, metricName).map(LongTaskTimer::start);

        if (stopWhenCompleted) {
            try {
                return ((CompletionStage<?>) pjp.proceed()).whenComplete((result, throwable) -> sample.ifPresent(this::stopTimer));
            } catch (Exception ex) {
                sample.ifPresent(this::stopTimer);
                throw ex;
            }
        }

        try {
            return pjp.proceed();
        } finally {
            sample.ifPresent(this::stopTimer);
        }
    }
 

private void record(TimingSampleContext timingContext, HttpServletResponse response, HttpServletRequest request,
                    Object handlerObject, Throwable e) {
    for (Timed timedAnnotation : timingContext.timedAnnotations) {
        timingContext.timerSample.stop(Timer.builder(timedAnnotation, metricName)
            .tags(tagsProvider.httpRequestTags(request, response, handlerObject, e))
            .register(registry));
    }

    if (timingContext.timedAnnotations.isEmpty() && autoTimeRequests) {
        timingContext.timerSample.stop(Timer.builder(metricName)
            .tags(tagsProvider.httpRequestTags(request, response, handlerObject, e))
            .register(registry));
    }

    for (LongTaskTimer.Sample sample : timingContext.longTaskTimerSamples) {
        sample.stop();
    }
}
 

@Test
@DisplayName("total time is preserved for a single timing")
default void record(MeterRegistry registry) {
    LongTaskTimer t = registry.more().longTaskTimer("my.timer");

    LongTaskTimer.Sample sample = t.start();
    clock(registry).add(10, TimeUnit.NANOSECONDS);

    assertAll(() -> assertEquals(10, t.duration(TimeUnit.NANOSECONDS)),
        () -> assertEquals(0.01, t.duration(TimeUnit.MICROSECONDS)),
        () -> assertEquals(10, sample.duration(TimeUnit.NANOSECONDS)),
        () -> assertEquals(0.01, sample.duration(TimeUnit.MICROSECONDS)),
        () -> assertEquals(1, t.activeTasks()));

    clock(registry).add(10, TimeUnit.NANOSECONDS);
    sample.stop();

    assertAll(() -> assertEquals(0, t.duration(TimeUnit.NANOSECONDS)),
        () -> assertEquals(-1, sample.duration(TimeUnit.NANOSECONDS)),
        () -> assertEquals(0, t.activeTasks()));
}
 

@Test
@DisplayName("supports sending histograms of active task duration")
void histogram() {
    MeterRegistry registry = new SimpleMeterRegistry(SimpleConfig.DEFAULT, new MockClock());

    LongTaskTimer t = LongTaskTimer.builder("my.timer")
            .serviceLevelObjectives(Duration.ofSeconds(10), Duration.ofSeconds(40), Duration.ofMinutes(1))
            .register(registry);

    List<Integer> samples = Arrays.asList(48, 42, 40, 35, 22, 16, 13, 8, 6, 4, 2);
    int prior = samples.get(0);
    for (Integer value : samples) {
        clock(registry).add(prior - value, TimeUnit.SECONDS);
        t.start();
        prior = value;
    }
    clock(registry).add(samples.get(samples.size() - 1), TimeUnit.SECONDS);

    CountAtBucket[] countAtBuckets = t.takeSnapshot().histogramCounts();

    assertThat(countAtBuckets[0].bucket(TimeUnit.SECONDS)).isEqualTo(10);
    assertThat(countAtBuckets[0].count()).isEqualTo(4);

    assertThat(countAtBuckets[1].bucket(TimeUnit.SECONDS)).isEqualTo(40);
    assertThat(countAtBuckets[1].count()).isEqualTo(9);

    assertThat(countAtBuckets[2].bucket(TimeUnit.MINUTES)).isEqualTo(1);
    assertThat(countAtBuckets[2].count()).isEqualTo(11);
}
 

public void onTaskStartup(TaskExecution taskExecution) {
	LongTaskTimer longTaskTimer = LongTaskTimer
			.builder(SPRING_CLOUD_TASK_ACTIVE_METER).description("Long task duration")
			.tags(commonTags(taskExecution)).register(Metrics.globalRegistry);

	this.longTaskSample = longTaskTimer.start();
	this.taskSample = Timer.start(Metrics.globalRegistry);
}
 

private void addLongTask(LongTaskTimer longTaskTimer, int sleepMills) {
    new Thread(() -> {
        longTaskTimer.record(() -> {
            try {
                TimeUnit.MILLISECONDS.sleep(sleepMills);
            } catch (InterruptedException e) {
            }
        });
    }).start();
}
 

@Test
public void testSimple() throws InterruptedException {
    // Creating a simplify long task timer
    final SkywalkingMeterRegistry registry = new SkywalkingMeterRegistry();
    final LongTaskTimer longTaskTimer = registry.more().longTaskTimer("test_simple_long_task_timer", "skywalking", "test");

    // Adding tasks
    addLongTask(longTaskTimer, 450);
    addLongTask(longTaskTimer, 20);

    // Make sure the second task has finished
    TimeUnit.MILLISECONDS.sleep(200);

    // Check Skywalking type
    Assert.assertTrue(longTaskTimer instanceof SkywalkingLongTaskTimer);
    final SkywalkingLongTaskTimer timer = (SkywalkingLongTaskTimer) longTaskTimer;

    // Check Original data
    Assert.assertEquals(1, timer.activeTasks());
    Assert.assertTrue(timer.duration(TimeUnit.MILLISECONDS) > 0);
    Assert.assertTrue(timer.max(TimeUnit.MILLISECONDS) > 0);

    // Check Skywalking data
    assertGauge((Gauge) meterMap.values().stream().filter(m -> m.getName().endsWith("_active_count")).findFirst().orElse(null),
        "test_simple_long_task_timer_active_count", Arrays.asList(new MeterId.Tag("skywalking", "test")), 1);
    assertGauge((Gauge) meterMap.values().stream().filter(m -> m.getName().endsWith("_duration_sum")).findFirst().orElse(null),
        "test_simple_long_task_timer_duration_sum", Arrays.asList(new MeterId.Tag("skywalking", "test")), 0, true);
    assertGauge((Gauge) meterMap.values().stream().filter(m -> m.getName().endsWith("_max")).findFirst().orElse(null),
        "test_simple_long_task_timer_max", Arrays.asList(new MeterId.Tag("skywalking", "test")), 0, true);
}
 

public static void main(String[] args) {
    MeterRegistry registry = SampleConfig.myMonitoringSystem();
    LongTaskTimer timer = registry.more().longTaskTimer("longTaskTimer");

    RandomEngine r = new MersenneTwister64(0);
    Normal incomingRequests = new Normal(0, 1, r);
    Normal duration = new Normal(30, 50, r);

    AtomicInteger latencyForThisSecond = new AtomicInteger(duration.nextInt());
    Flux.interval(Duration.ofSeconds(1))
            .doOnEach(d -> latencyForThisSecond.set(duration.nextInt()))
            .subscribe();

    final Map<LongTaskTimer.Sample, CountDownLatch> tasks = new ConcurrentHashMap<>();

    // the potential for an "incoming request" every 10 ms
    Flux.interval(Duration.ofSeconds(1))
            .doOnEach(d -> {
                if (incomingRequests.nextDouble() + 0.4 > 0 && tasks.isEmpty()) {
                    int taskDur;
                    while ((taskDur = duration.nextInt()) < 0);
                    synchronized (tasks) {
                        tasks.put(timer.start(), new CountDownLatch(taskDur));
                    }
                }

                synchronized (tasks) {
                    for (Map.Entry<LongTaskTimer.Sample, CountDownLatch> e : tasks.entrySet()) {
                        e.getValue().countDown();
                        if (e.getValue().getCount() == 0) {
                            e.getKey().stop();
                            tasks.remove(e.getKey());
                        }
                    }
                }
            })
            .blockLast();
}
 

@Test
@DisplayName("supports sending histograms of active task duration")
default void histogram(MeterRegistry registry) {
    LongTaskTimer t = LongTaskTimer.builder("my.timer")
            .serviceLevelObjectives(Duration.ofSeconds(10), Duration.ofSeconds(40), Duration.ofMinutes(1))
            .register(registry);

    List<Integer> samples = Arrays.asList(48, 42, 40, 35, 22, 16, 13, 8, 6, 4, 2);
    int prior = samples.get(0);
    for (Integer value : samples) {
        clock(registry).add(prior - value, TimeUnit.SECONDS);
        t.start();
        prior = value;
    }
    clock(registry).add(samples.get(samples.size() - 1), TimeUnit.SECONDS);

    CountAtBucket[] countAtBuckets = t.takeSnapshot().histogramCounts();

    assertThat(countAtBuckets[0].bucket(TimeUnit.SECONDS)).isEqualTo(10);
    assertThat(countAtBuckets[0].count()).isEqualTo(4);

    assertThat(countAtBuckets[1].bucket(TimeUnit.SECONDS)).isEqualTo(40);
    assertThat(countAtBuckets[1].count()).isEqualTo(9);

    assertThat(countAtBuckets[2].bucket(TimeUnit.MINUTES)).isEqualTo(1);
    assertThat(countAtBuckets[2].count()).isEqualTo(11);
}
 

@Override
public void onEvent(RequestEvent event) {
    ContainerRequest containerRequest = event.getContainerRequest();
    Set<Timed> timedAnnotations;

    switch (event.getType()) {
        case ON_EXCEPTION:
            if (!(event.getException() instanceof NotFoundException)) {
                break;
            }
        case REQUEST_MATCHED:
            timedAnnotations = annotations(event);

            timedAnnotationsOnRequest.put(containerRequest, timedAnnotations);
            shortTaskSample.put(containerRequest, Timer.start(registry));

            List<LongTaskTimer.Sample> longTaskSamples = longTaskTimers(timedAnnotations, event).stream().map(LongTaskTimer::start).collect(Collectors.toList());
            if (!longTaskSamples.isEmpty()) {
                this.longTaskSamples.put(containerRequest, longTaskSamples);
            }
            break;
        case FINISHED:
            timedAnnotations = timedAnnotationsOnRequest.remove(containerRequest);
            Timer.Sample shortSample = shortTaskSample.remove(containerRequest);

            if (shortSample != null) {
                for (Timer timer : shortTimers(timedAnnotations, event)) {
                    shortSample.stop(timer);
                }
            }

            Collection<LongTaskTimer.Sample> longSamples = this.longTaskSamples.remove(containerRequest);
            if (longSamples != null) {
                for (LongTaskTimer.Sample longSample : longSamples) {
                    longSample.stop();
                }
            }
            break;
    }
}
 

TimingSampleContext(HttpServletRequest request, Object handlerObject) {
    timedAnnotations = annotations(handlerObject);
    timerSample = Timer.start(registry);
    longTaskTimerSamples = timedAnnotations.stream()
        .filter(Timed::longTask)
        .map(t -> LongTaskTimer.builder(t)
            .tags(tagsProvider.httpLongRequestTags(request, handlerObject))
            .register(registry)
            .start())
        .collect(Collectors.toList());
}
 

TimingSampleContext(HttpServletRequest request, Object handlerObject) {
    timedAnnotations = annotations(handlerObject);
    timerSample = Timer.start(registry);
    longTaskTimerSamples = timedAnnotations.stream()
        .filter(Timed::longTask)
        .map(t -> LongTaskTimer.builder(t)
            .tags(tagsProvider.httpLongRequestTags(request, handlerObject))
            .register(registry)
            .start())
        .collect(Collectors.toList());
}
 

private void stopTimer(LongTaskTimer.Sample sample) {
    try {
        sample.stop();
    } catch (Exception e) {
        // ignoring on purpose
    }
}
 

/**
 * Secure long task timer creation - it should not disrupt the application flow in case of exception
 */
private Optional<LongTaskTimer> buildLongTaskTimer(ProceedingJoinPoint pjp, Timed timed, String metricName) {
    try {
        return Optional.of(LongTaskTimer.builder(metricName)
                                   .description(timed.description().isEmpty() ? null : timed.description())
                                   .tags(timed.extraTags())
                                   .tags(tagsBasedOnJoinPoint.apply(pjp))
                                   .register(registry));
    } catch (Exception e) {
        return Optional.empty();
    }
}
 

private Set<LongTaskTimer> longTaskTimers(Set<Timed> timed, RequestEvent event) {
    return timed.stream()
        .filter(Timed::longTask)
        .map(LongTaskTimer::builder)
        .map(b -> b.tags(tagsProvider.httpLongRequestTags(event)).register(registry))
        .collect(Collectors.toSet());
}
 

@Test
void addLongTaskTimer() {
    LongTaskTimer longTaskTimer = LongTaskTimer.builder("my.long.task.timer").register(this.registry);
    assertThat(this.registry.addLongTaskTimer(longTaskTimer)).hasSize(2);
}
 

SpectatorLongTaskTimer(Meter.Id id, com.netflix.spectator.api.LongTaskTimer timer, Clock clock,
                       DistributionStatisticConfig distributionStatisticConfig) {
    super(id, clock, TimeUnit.NANOSECONDS, distributionStatisticConfig, true);
    this.timer = timer;
}
 

@Override
protected LongTaskTimer newLongTaskTimer(final Meter.Id id) {
    return new NoopLongTaskTimer(id);
}
 

@Override
protected LongTaskTimer newLongTaskTimer(Id id) {
    return new NoopLongTaskTimer(id);
}
 

@Override
protected LongTaskTimer newLongTaskTimer(Meter.Id id, DistributionStatisticConfig distributionStatisticConfig) {
    final MeterId meterId = convertId(id);
    return new SkywalkingLongTaskTimer(id, meterId, clock, TimeUnit.MILLISECONDS, distributionStatisticConfig, true);
}
 

@Override
LongTaskTimer newNoopMeter() {
    return new NoopLongTaskTimer(getId());
}
 

@Override
protected LongTaskTimer newLongTaskTimer(Meter.Id id) {
	return new DefaultLongTaskTimer(id, this.clock);
}
 

@NonNull
@Override
protected LongTaskTimer newLongTaskTimer(@Nonnull Id id, @Nonnull DistributionStatisticConfig distributionStatisticConfig) {
    throw new RuntimeException();
}
 

@Test
public void successfulTask() {

	TaskExecution taskExecution = new TaskExecution(123L, 0, "myTask72", new Date(),
			new Date(), null, new ArrayList<>(), null, null, -1L);

	// Start Task
	taskMetrics.onTaskStartup(taskExecution);

	//// Test Long Task Timer while the task is running.
	LongTaskTimer longTaskTimer = simpleMeterRegistry
			.find(TaskMetrics.SPRING_CLOUD_TASK_ACTIVE_METER).longTaskTimer();
	assertThat(longTaskTimer)
			.withFailMessage("LongTask timer should be created on Task start")
			.isNotNull();
	// assertThat(longTaskTimer.activeTasks()).isEqualTo(1);
	assertThat(longTaskTimer.getId().getTag(TaskMetrics.TASK_NAME_TAG))
			.isEqualTo("myTask72");
	assertThat(longTaskTimer.getId().getTag(TaskMetrics.TASK_EXECUTION_ID_TAG))
			.isEqualTo("123");

	// Finish Task
	taskMetrics.onTaskEnd(taskExecution);

	// Test Timer
	Timer taskTimer = simpleMeterRegistry.find(TaskMetrics.SPRING_CLOUD_TASK_METER)
			.timer();
	assertThat(taskTimer).isNotNull();
	// assertThat(taskTimer.count()).isEqualTo(1L);
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_NAME_TAG))
			.isEqualTo("myTask72");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_EXECUTION_ID_TAG))
			.isEqualTo("123");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_EXTERNAL_EXECUTION_ID_TAG))
			.isEqualTo("unknown");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_PARENT_EXECUTION_ID_TAG))
			.isEqualTo("-1");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_EXIT_CODE_TAG))
			.isEqualTo("0");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_EXCEPTION_TAG))
			.isEqualTo("none");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_STATUS_TAG))
			.isEqualTo(TaskMetrics.STATUS_SUCCESS);

	// Test Long Task Timer after the task has completed.
	// LongTaskTimer longTaskTimer = simpleMeterRegistry
	// .find(TaskMetrics.SPRING_CLOUD_TASK_ACTIVE_METER).longTaskTimer();
	assertThat(longTaskTimer.activeTasks()).isEqualTo(0);
	assertThat(longTaskTimer.getId().getTag(TaskMetrics.TASK_NAME_TAG))
			.isEqualTo("myTask72");
	assertThat(longTaskTimer.getId().getTag(TaskMetrics.TASK_EXECUTION_ID_TAG))
			.isEqualTo("123");
}
 

@Test
public void failingTask() {

	TaskExecution taskExecution = new TaskExecution(123L, 0, "myTask", new Date(),
			new Date(), null, new ArrayList<>(), null, null, -1L);

	// Start Task
	taskMetrics.onTaskStartup(taskExecution);

	// Test Long Task Timer while the task is running.
	LongTaskTimer longTaskTimer = simpleMeterRegistry
			.find(TaskMetrics.SPRING_CLOUD_TASK_ACTIVE_METER).longTaskTimer();
	assertThat(longTaskTimer)
			.withFailMessage("LongTask timer should be created on Task start")
			.isNotNull();
	assertThat(longTaskTimer.activeTasks()).isEqualTo(1);
	assertThat(longTaskTimer.getId().getTag(TaskMetrics.TASK_NAME_TAG))
			.isEqualTo("myTask");
	assertThat(longTaskTimer.getId().getTag(TaskMetrics.TASK_EXECUTION_ID_TAG))
			.isEqualTo("123");

	taskMetrics.onTaskFailed(new RuntimeException("Test"));

	// Finish Task. TaskLifecycleListen calls onTaskEnd after the onTaskFailed. Make
	// sure that the counter status
	// is not affected by this.
	taskMetrics.onTaskEnd(taskExecution);

	Timer taskTimer = simpleMeterRegistry.find(TaskMetrics.SPRING_CLOUD_TASK_METER)
			.timer();
	assertThat(taskTimer).isNotNull();

	assertThat(taskTimer).isNotNull();
	// assertThat(taskTimer.count()).isEqualTo(1L);
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_NAME_TAG))
			.isEqualTo("myTask");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_EXECUTION_ID_TAG))
			.isEqualTo("123");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_EXTERNAL_EXECUTION_ID_TAG))
			.isEqualTo("unknown");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_PARENT_EXECUTION_ID_TAG))
			.isEqualTo("-1");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_EXIT_CODE_TAG))
			.isEqualTo("0");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_EXCEPTION_TAG))
			.isEqualTo("RuntimeException");
	assertThat(taskTimer.getId().getTag(TaskMetrics.TASK_STATUS_TAG))
			.isEqualTo(TaskMetrics.STATUS_FAILURE);

	// Test Long Task Timer after the task has completed.
	assertThat(longTaskTimer.activeTasks()).isEqualTo(0);
	assertThat(longTaskTimer.getId().getTag(TaskMetrics.TASK_NAME_TAG))
			.isEqualTo("myTask");
	assertThat(longTaskTimer.getId().getTag(TaskMetrics.TASK_EXECUTION_ID_TAG))
			.isEqualTo("123");
}
 

Object writeLongTaskTimer(LongTaskTimer timer);