Instrument Scheduled-annotated methods for observability

[bclozel]

We should consider whether we can safely instrument @Scheduled-annotated methods with the Observation API and report relevant metrics and traces.

[edyda99]

Hi there! I noticed this issue and I'm interested in working on it, but I wanted to ask if it's okay if I take some time to get up to speed on the codebase and the Observation API before I start making changes. I'm a new contributor and I want to make sure that I understand everything before I start making modifications. Please let me know if that's okay, and I'll be sure to keep you updated on my progress as I work on the issue.

[bclozel]

@edyda99 I don't think that this issue is a good first issue for contributing to Spring Framework. Maybe consider contributing on a different one?

[edyda99]

Thanks for letting me know. I'll look for another issue. I'd still like to learn from your contributions on this issue, so I'll do my research and keep an eye on your pull requests. Thanks!!

[skshyamal]

Is there any plan to have this issue fixed soon? Since after spring boot 3.x upgrade simply vanished.

[jonatan-ivanov]

@skshyamal Hope this helps until this is implemented: right now, as a workaround, you can add an @Observerved annotation (+create an ObservedAspect bean) on your @Scheduled method or create an Observation manually.

[wojciechcwek]

@jonatan-ivanov could you please show an example of the workaround you described?

[jonatan-ivanov]

Example with @Observed: https://micrometer.io/docs/observation#_using_annotations_with_observed
Example with .observe(...): https://micrometer.io/docs/observation#_introduction

[bclozel]

I have an initial implementation for this feature and I've scheduled it for 6.1.0-M2 as M1 is about to be released and I'd like to gather some feedback before releasing this in a milestone.

I have worked on several designs and will share some thoughts about those here.

One solution was to build infrastructure directly on the TaskScheduler and TaskExecutor. The problem is, there is not much opinion we can build there as contracts are based on Runnable and we have no clue about the task being run/scheduled. A more practical way of observing such tasks would be to instrument them directly and use a custom name and a custom convention:

@Service
public class MyService {

    private final ObservationRegistry observationRegistry;
    private final TaskScheduler taskScheduler;

    public void indexBlogEntries() {
        Observation observation = Observation.createNotStarted("index.blogs", this.observationRegistry);
        this.taskScheduler.schedule(
                observation.wrap(() -> {
                    List<BlogEntry> blogEntries = findBlogEntries();
                    observation.lowCardinalityKeyValue("count", String.valueOf(blogEntries.size()));
                    findBlogEntries().forEach(this::indexBlogEntry);
                }), Instant.now());
    }

Instead, we can focus on the main use case, @Scheduled methods: we can observe scheduled tasks with a minimum of changes in the existing contracts. The ObservationRegistry must be configured on the ScheduledTaskRegistrar by using a SchedulingConfigurer bean. Once that's done all scheduled methods for both blocking and reactive variants (as introduced in #29924) will have recorded observations.

We can schedule methods like:

    @Scheduled(cron = "0,10,20,30,40,50 * * * * *")
    public void blockingError() {
        logger.info("Executing 'blockingError' @Scheduled method");
        throw new IllegalStateException("Blocking method failed");
    }

    @Scheduled(cron = "2,12,22,32,42,52 * * * * *")
    public Mono<String> reactiveSuccess() {
        return Mono.just("success")
                .delayElement(Duration.ofSeconds(2))
                .doOnNext(element -> logger.info("Done executing 'reactiveSuccess' @Scheduled method"));
    }

and see in the logs that the current observation is propagated in the scheduled methods as ThreadLocal or in the reactive context:

INFO [,648a1a62e677b6f19d024f06151527c8,9d024f06151527c8] 65741 --- [     parallel-1] com.example.scheduling.MyComponent       : Done executing 'reactiveSuccess' @Scheduled method
INFO [,648a1a6a05b9f16cb6ba3cff96b94bf6,b6ba3cff96b94bf6] 65741 --- [pool-4-thread-1] com.example.scheduling.MyComponent       : Executing 'blockingError' @Scheduled method

If configured accordingly, the application can exports timers as metrics and traces:

As we can see in the screenshots above, recorded observations do not have any parent as they're not scheduled in the context of any active observation. In case the scheduled work is cancelled in-flight because the application is being shut down, the "outcome" keyvalue will be "UNKNOWN".

[alicanhaman]

Hey I updated to the spring boot 3.2 SNAPSHOT version which should contain these changes. But I still did not get the traceId and spanId in the @scheduled annotated method logs.

Am I missing something or did the changes not fully function?

[bclozel]

@alicanhaman you would need the following auto-configuration, which is not done yet: spring-projects/spring-boot#36119

[alicanhaman]

Thanks for providing the missing piece of the puzzle.