[Task Manager] adds basic observability into Task Manager's runtime operations

[gmmorris]

Summary

closes #77456

This PR adds an an internal monitoring mechanism in Task Manager which keep track of a variety of metrics and a health api endpoint which makes the monitored statistics accessible.

Exposed Metrics

There are three different sections to the stats returned by the health api.

• configuration: Summarizes Task Manager's current configuration.
• workload: Summarizes the workload in the current deployment.
• runtime: Tracks Task Manager's performance.

Configuring the Stats

There are four new configurations:

• xpack.task_manager.monitored_stats_required_freshness - The required freshness of critical "Hot" stats, which means that if key stats (last polling cycle time, for example) haven't been refreshed within the specified duration, the _health endpoint and service will report an Error status. By default this is inferred from the configured poll_interval and is set to poll_interval plus a 1s buffer.
• xpack.task_manager.monitored_aggregated_stats_refresh_rate - Dictates how often we refresh the "Cold" metrics. These metrics require an aggregation against Elasticsearch and add load to the system, hence we want to limit how often we execute these. We also inffer the required freshness of these "Cold" metrics from this configuration, which means that if these stats have not been updated within the required duration then the _health endpoint and service will report an Error status. This covers the entire workload section of the stats. By default this is configured to 60s, and as a result the required freshness defaults to 61s (refresh plus a 1s buffer).
• xpack.task_manager.monitored_stats_running_average_window- Dictates the size of the window used to calculate the running average of various "Hot" stats, such as the time it takes to run a task, the drift that tasks experience etc. These stats are collected throughout the lifecycle of tasks and this window will dictate how large the queue we keep in memory would be, and how many values we need to calculate the average against. We do not calculate the average on every new value, but rather only when the time comes to summarize the stats before logging them or returning them to the API endpoint.
• xpack.task_manager.monitored_task_execution_thresholds- Configures the threshold of failed task executions at which point the warn or error health status will be set either at a default level or a custom level for specific task types. This will allow you to mark the health as error when any task type failes 90% of the time, but set it to error at 50% of the time for task types that you consider critical. This value can be set to any number between 0 to 100, and a threshold is hit when the value exceeds this number. This means that you can avoid setting the status to error by setting the threshold at 100, or hit error the moment any task failes by setting the threshold to 0 (as it will exceed 0 once a single failer occurs).

For example, in your Kibana.yml:

xpack.task_manager.monitored_stats_required_freshness: 5000
xpack.task_manager.monitored_aggregated_stats_refresh_rate: 60000
xpack.task_manager.monitored_stats_running_average_window: 50
xpack.task_manager.monitored_task_execution_thresholds:
  default:
    error_threshold: 70
    warn_threshold: 50
  custom:
    "alerting:always-firing":
      error_threshold: 50
      warn_threshold: 0

Consuming Health Stats

Task Manager exposes a /api/task_manager/_health api which returns the latest stats.
Calling this API is designed to be fast and doesn't actually perform any checks- rather it returns the result of the latest stats in the system, and is design in such a way that you could call it from an external service on a regular basis without worrying that you'll be adding substantial load to the system.

Additionally, the metrics are logged out into Task Manager's DEBUG logger at a regular cadence (dictated by the Polling Interval).
If you wish to enable DEBUG logging in your Kibana instance, you will need to add the following to your Kibana.yml:

logging:
  loggers:
      - context: plugins.taskManager
        appenders: [console]
        level: debug

Please bear in mind that these stats are logged as often as your poll_interval configuration, which means it could add substantial noise to your logs.
We would recommend only enabling this level of logging temporarily.

Understanding the Exposed Stats

As mentioned above, the health api exposes three sections: configuration, workload and runtime.
Each section has a timestamp and a status which indicates when the last update to this setion took place and whether the health of this section was evaluated as OK, Warning or Error.

The root has its own status which indicate the state of the system overall as infered from the status of the section.
An Error status in any section will cause the whole system to display as Error.
A Warning status in any section will cause the whole system to display as Warning.
An OK status will only be displayed when all sections are marked as OK.

The root timestamp is the time in which the summary was exposed (either to the DEBUG logger or the http api) and the last_update is the last time any one of the sections was updated.

The Configuration Section

The configuration section summarizes Task Manager's current configuration, including dynamic configurations which change over time, such as poll_interval and max_workers which adjust in reaction to changing load on the system.

These are "Hot" stats which are updated whenever a change happens in the configuration.

The Workload Section

The workload which summarizes the work load in the current deployment, listing the tasks in the system, their types and what their current status is.

It includes three sub sections:

• The number of tasks scheduled in the system, broken down by type and status.
• The number of idle overdue tasks, whose runAt has expired.
• Execution density in the next minute or so (configurable), which shows how many tasks are scheduled to execute in the scope of each polling interval. This can give us an idea of how much load there is on the current Kibana deployment.

These are "Cold" stat which are updated at a regular cadence, configured by the monitored_aggregated_stats_refresh_rate config.

The Runtime Section

The runtime tracks Task Manager's performance as it runs, making note of task execution time, drift etc.
These include:

• The time it takes a task to run (mean and median, using a configurable running average window, 50 by default)
• The average drift that tasks experience (mean and median, using the same configurable running average window as above). Drift tells us how long after a task's scheduled a task typically executes.
• The polling rate (the timestamp of the last time a polling cycle completed) and the result [No tasks | Filled task pool | Unexpectedly ran out of workers] frequency the past 50 polling cycles (using the same window size as the one used for running averages)
• The Success | Retry | Failure ratio by task type. This is different than the workload stats which tell you what's in the queue, but ca't keep track of retries and of non recurring tasks as they're wiped off the index when completed.

These are "Hot" stats which are updated reactively as Tasks are executed and interacted with.

Example Stats

For example, if you curl the /api/task_manager/_health endpoint, you might get these stats:

{
     /* the time these stats were returned by the api */
    "timestamp": "2020-10-05T18:26:11.346Z",
     /* the overall status of the system */
    "status": "OK",
     /* last time any stat was updated in this output */
    "last_update": "2020-10-05T17:57:55.411Z",    
    "stats": {
        "configuration": {      /* current configuration of TM */
            "timestamp": "2020-10-05T17:56:06.507Z",
            "status": "OK",
            "value": {
                "max_workers": 10,
                "poll_interval": 3000,
                "request_capacity": 1000,
                "max_poll_inactivity_cycles": 10,
                "monitored_aggregated_stats_refresh_rate": 60000,
                "monitored_stats_running_average_window": 50
            }
        },
        "workload": {  /* The workload of this deployment */
            "timestamp": "2020-10-05T17:57:06.534Z",
            "status": "OK",
            "value": {
                "count": 6,        /* count of tasks in the system */
                "task_types": {   /* what tasks are there and what status are they in */
                    "actions_telemetry": {
                        "count": 1,
                        "status": {
                            "idle": 1
                        }
                    },
                    "alerting_telemetry": {
                        "count": 1,
                        "status": {
                            "idle": 1
                        }
                    },
                    "apm-telemetry-task": {
                        "count": 1,
                        "status": {
                            "idle": 1
                        }
                    },
                    "endpoint:user-artifact-packager": {
                        "count": 1,
                        "status": {
                            "idle": 1
                        }
                    },
                    "lens_telemetry": {
                        "count": 1,
                        "status": {
                            "idle": 1
                        }
                    },
                    "session_cleanup": {
                        "count": 1,
                        "status": {
                            "idle": 1
                        }
                    }
                },

                /* Frequency of recurring tasks schedules */
                "schedule": [  
                    ["60s", 1],   /* 1 task, every 60s */
                    ["3600s", 3],  /* 3 tasks every hour */
                    ["720m", 1]
                ],
                /* There are no overdue tasks in this system at the moment */
                "overdue": 0, 
                /* This is the schedule density, it shows a histogram of all the  polling intervals in the next minute (or, if 
                    pollInterval is configured unusually high it will show a min of 2 refresh intervals into the future, and a max of 50 buckets).
                    Here we see that on the 3rd polling interval from *now* (which is ~9 seconds from now, as pollInterval is `3s`) there is one task due to run.
                    We also see that there are 5 due two intervals later, which is fine as we have a max workers of `10`
                 */
                "estimated_schedule_density": [0, 0, 1, 0, 5, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
            }
        },
        "runtime": {
            "timestamp": "2020-10-05T17:57:55.411Z",
            "status": "OK",
            "value": {
                "polling": {
                        /* When was the last polling cycle? */
                    "last_successful_poll": "2020-10-05T17:57:55.411Z",
                        /* What is the frequency of polling cycle result?
                            Here we see 94% of "NoTasksClaimed" and 6%  "PoolFilled" */
                    "result_frequency_percent_as_number": {
                        "NoTasksClaimed": 94,
                        "RanOutOfCapacity": 0, /* This is a legacy result, we might want to rename - it tells us when a polling cycle resulted in claiming more tasks than we had workers for, butt he name doesn't make much sense outside of the context of the code */
                        "PoolFilled": 6
                    }
                },
                /* on average, the tasks in this deployment run 1.7s after their scheduled time */
                "drift": {
                    "mean": 1720,
                    "median": 2276
                },
                "execution": {
                    "duration": {
                               /* on average, the `endpoint:user-artifact-packager` tasks take 15ms to run */
                        "endpoint:user-artifact-packager": {
                            "mean": 15,
                            "median": 14.5
                        },
                        "session_cleanup": {
                            "mean": 28,
                            "median": 28
                        },
                        "lens_telemetry": {
                            "mean": 100,
                            "median": 100
                        },
                        "actions_telemetry": {
                            "mean": 135,
                            "median": 135
                        },
                        "alerting_telemetry": {
                            "mean": 197,
                            "median": 197
                        },
                        "apm-telemetry-task": {
                            "mean": 1347,
                            "median": 1347
                        }
                    },
                    "result_frequency_percent_as_number": {
                               /* and 100% of `endpoint:user-artifact-packager` have completed in success (within the running average window, so the past 50 runs (by default, configrable by `monitored_stats_running_average_window`) */
                        "endpoint:user-artifact-packager": {
                            "status": "OK",
                            "Success": 100,
                            "RetryScheduled": 0,
                            "Failed": 0
                        },
                        "session_cleanup": {
                            /* `error` status as 90% of results are `Failed` */
                            "status": "error",
                            "Success": 5,
                            "RetryScheduled": 5,
                            "Failed": 90
                        },
                        "lens_telemetry": {
                            "status": "OK",
                            "Success": 100,
                            "RetryScheduled": 0,
                            "Failed": 0
                        },
                        "actions_telemetry": {
                            "status": "OK",
                            "Success": 100,
                            "RetryScheduled": 0,
                            "Failed": 0
                        },
                        "alerting_telemetry": {
                            "status": "OK",
                            "Success": 100,
                            "RetryScheduled": 0,
                            "Failed": 0
                        },
                        "apm-telemetry-task": {
                            "status": "OK",
                            "Success": 100,
                            "RetryScheduled": 0,
                            "Failed": 0
                        }
                    }
                }
            }
        }
    }
}

Checklist

Delete any items that are not applicable to this PR.

• Documentation was added for features that require explanation or tutorials
• Unit or functional tests were updated or added to match the most common scenarios

For maintainers

• This was checked for breaking API changes and was labeled appropriately

[pmuellr]

LGTM; I was hoping this wouldn't be quite so complex, but obviously it's going to be somewhat complex, so ... it is what it is :-)

I gave this a whirl on my 100 alerts w/4 active instances load, ran it for a while, checking the health, looked good, deleted all the alerts, leaving the queued actions to error (since the alert is no longer available) to look at the "error" side as well. Works as expected!

[pmuellr]

are these changes needed? I'm wondering if we will need to pre-req the apm plugin, if not now, in some future where the compilation depends on plugin deps.

[smith]

We are investigating moving these types into the JS client (see #77720.) No timeframe on that, but worth considering.

I'm always in favor of explicitly declaring dependencies, though in this case we would create a circular one since APM has Task Manager as an optional dependency.

As for the type changes here I'd like to defer to @dgieselaar on that one before approving.

[gmmorris]

Yeah I wasn't crazy about this, but checked with @dgieselaar and he gave a thumbsup.
He said he'd review on the PR 👍

[pmuellr]

fun factoid - stats-lite is from my former NodeSource colleague and all-around great person, Bryce Baril.

👋 @brycebaril

[pmuellr]

This is really more of a "NO DATA" condition, rather than an error, right? Probably worth indicating that somehow, not sure it's worthy of a new status if instead it could just be in a message somehow.

[gmmorris]

I considered it, but arguably it could also be an error if you consider that the goal of monitoring is to confirm that TM is working and having no data here indicates that TM is not working.

My thinking was that when a Kibana starts up it goes from Error to OK, and that makes sense to me fro ma monitoring perspective...
I'd opt to keep it this way until (unless) a customer complains :)

[elasticmachine]

Pinging @elastic/apm-ui (Team:apm)

[elasticmachine]

Pinging @elastic/kibana-alerting-services (Team:Alerting Services)

[dgieselaar]

Looks good, great to see more teams using these types! Left a small suggestion for type inference in aggregate.

[gmmorris]

@elasticmachine merge upstream

[mikecote]

LGTM 👍 This will be good to have insight into!

[kibanamachine]

💚 Build Succeeded

• continuous-integration/kibana-ci/pull-request
• Commit: 5d8f750

Metrics [docs]

distributable file count

id	before	after	diff
default	48089	48100	+11

History

• 💔 Build #83904 failed e59ebc0
• 💔 Build #83888 failed 314f3bc
• 💚 Build #83614 succeeded 5ea830c
• 💚 Build #83591 succeeded 13981c0
• 💚 Build #83305 succeeded 12e7866

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream

[gmmorris]

Documented as part of #89997