[ML] Add extra debug logging to enable end-to-end profiling of jobs

[elasticmachine]

Original comment by @droberts195:

When an ML job is running time can be spent in the following areas:

• [x] Searching Elasticsearch indices for input LINK REDACTED
• [ ] Pre-processing this input in the ML Java code prior to sending it to the ML C++ process
• [ ] (Possibly) categorization inside the C++ process
• [ ] "Data gathering" in the anomaly detection part of the C++ process
• [x] End-of-bucket processing in the C++ process
• [ ] Result processing in the ML Java code

@richcollier has found that it is extremely hard to pinpoint which of these processing phases is responsible for an ML job running slower than real-time at a customer.

We calculate and store the end-of-bucket processing time in the C++ anomaly detection code, but time spent in other areas is not easy to determine (other than by using a profiler in a development environment).

Such troubleshooting would be greatly helped by the following instrumentation:

1. Debug messages at the beginning and end of every Elasticsearch search that the datafeed does
2. Debug messages at the beginning and end of post_data processing
3. Some sort of instrumentation of the categorization code in the C++ process, with debug logging to report periodically how long it is taking

Item (3) is that hardest here, as the categorization and data gathering are both done in sequence per input record. Using a millisecond timer to time the categorization part is probably not accurate enough, and using our current nanosecond timer on some platforms (Windows) is quite slow.

But even if just items (1) and (2) are added then it will improve our ability to troubleshoot certain performance problems at customer sites.

[elasticmachine]

Original comment by @richcollier:

thanks for writing this up @droberts195 - I came here to do it but found your entry first!

[droberts195]

After discussing with @sophiec20 we decided that rather than just make this information available via debug messages it would be nice to incorporate it into the output of the get jobs stats and get datafeed stats APIs.

In the first instance we will add average_bucket_processing_time_ms to the job stats and some measure of search time to the datafeed stats. Depending on what is possible this could be total time spent searching since the datafeed was created or average search time per bucket. (In the event that only total search time is possible the troubleshooter will have to look up the number of buckets in the job stats and divide the total time by this to get a number commensurate with the average bucket processing time.)

[droberts195]

average_bucket_processing_time_ms can be found by doing an aggregation on the bucket_processing_time_ms field of the ML bucket results.

[elasticsearchmachine]

Pinging @elastic/ml-core (Team:ML)