Track scheduled function delay

[Shubham8287]

Summary

fixes: https://github.com/clockworklabs/SpacetimeDBPrivate/issues/3441.

It chooses an arbitrary threshold of 50ms, if a scheduled function starts more than that threshold after its expected time, we emit a warning and record a metric.

Note that, metric does not necessarily tells If something is wrong with Host as drift can also happen due to module's previous schedule function taking long time to finish.

[gefjon]

How much additional work would it be to make the threshold be, say, 25% of the requested delay, rather than a flat 50ms? I worry that 50ms is quite a long time, especially for games which want to run relatively frequent and relatively fast "tick" reducers.

[gefjon]

It looks like record_scheduled_function_delay calls Timestamp::now(), in this case after call_scheduled_reducer_with_tx has already returned. This appears to mean that we'll measure and report the delay plus the reducer's execution time. It also appears that the params already include params.timestamp, the invocation time reported to the reducer. Can we just use that timestamp to report the delay?

[Shubham8287]

record_scheduled_function_delay does not call Timestamp::now(). scheduled_function_delay_for_item does that which is called correctly before calling reducer.

I think, I can do better with naming.

[gefjon]

Oh, I see. I'd still prefer to use the same timestamp to compute delay as gets passed to the reducer.

[gefjon]

Why not observe every function in the metric?

[Shubham8287]

I didn't because of perfomance reasons with with_label_value (as it will lead to drift itself) but maybe we can do if we cache it.

[gefjon]

Can we cache this with_label_values call someplace rather than calling with_label_values on every report? And also, can we clean it up with remove_label_values, either when dropping whatever holds it, or in fn remove_database_gauges in crates/core/src/host/host_controller.rs?

[Shubham8287]

How much additional work would it be to make the threshold be, say, 25% of the requested delay, rather than a flat 50ms?

The scheduling function has precision of few milliseconds, so we would still need some minimum threshold. On top of that, as I mentioned in the description, long running schedule functions can itself contribute to the delay, potentially causing many false positives.

As you already suggested to record a metric for every run, we will be using this value only logging purpose, so it may be fine?

[gefjon]

How much additional work would it be to make the threshold be, say, 25% of the requested delay, rather than a flat 50ms?

The scheduling function has precision of few milliseconds, so we would still need some minimum threshold. On top of that, as I mentioned in the description, long running schedule functions can itself contribute to the delay, potentially causing many false positives.

As you already suggested to record a metric for every run, we will be using this value only logging purpose, so it may be fine?

Yeah, I don't plan to directly alert on any single schedule invocation violating the threshold, I want to detect patterns of functions deviating significantly.