[ML] Jobs fail to auto-close due to timeout when stopping the datafeed

[elasticmachine]

Original comment by @sophiec20:

Found in 6.3.0 { "build" : { "hash" : "a47564f", "date" : "2018-04-09T21:45:51.347364Z" },

Showcase server, 2 node cluster on gcp

Some jobs failed to auto-close due to a timeout when trying to remove the datafeed persistent task.

System was running 6 concurrent jobs, all on gallery2018 data. These jobs were started 5s apart using the same script. All configs were identifal, except for the function used. The datafeed start request contained the same start and end dates Datafeed started (from: 1970-01-02T10:00:00.000Z to: 2018-12-31T00:00:00.000Z). The 6 jobs had the following configs:

min(bytes) partition=status influencers=clientip,status bucket=1h *
max(bytes) partition=status influencers=clientip,status bucket=1h *
mean(bytes) partition=status influencers=clientip,status bucket=1h *
median(bytes) partition=status influencers=clientip,status bucket=1h
varp(bytes) partition=status influencers=clientip,status bucket=1h
sum(bytes) partition=status influencers=clientip,status bucket=1h

An end date was specified, so I would expect the jobs to auto-close after they had finished processing the data in the index.

All jobs completed, however 3 of the jobs (see *) remained open. Their datafeeds were stopped. The errors are logged below.

[2018-04-11T23:30:34,129][INFO ][o.e.x.m.j.p.DataCountsReporter] [node2] [ga-mean-bytes-p-status-clientip-status-1h] 900000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:30:54,324][INFO ][o.e.x.m.j.p.DataCountsReporter] [node2] [ga-min-bytes-p-status-clientip-status-1h] 1000000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:31:01,912][INFO ][o.e.x.m.j.p.DataCountsReporter] [node2] [ga-sum-bytes-p-status-clientip-status-1h] 700000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:31:16,142][INFO ][o.e.x.m.d.DatafeedJob    ] [ga-min-bytes-p-status-clientip-status-1h] Lookback has finished
[2018-04-11T23:31:16,142][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] attempt to stop datafeed [datafeed-ga-min-bytes-p-status-clientip-status-1h] for job [ga-min-bytes-p-status-clientip-status-1h]
[2018-04-11T23:31:16,143][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] try lock [20s] to stop datafeed [datafeed-ga-min-bytes-p-status-clientip-status-1h] for job [ga-min-bytes-p-status-clientip-status-1h]...
[2018-04-11T23:31:16,143][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] stopping datafeed [datafeed-ga-min-bytes-p-status-clientip-status-1h] for job [ga-min-bytes-p-status-clientip-status-1h], acquired [true]...
[2018-04-11T23:31:16,143][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] datafeed [datafeed-ga-min-bytes-p-status-clientip-status-1h] for job [ga-min-bytes-p-status-clientip-status-1h] has been stopped
[2018-04-11T23:31:16,736][INFO ][o.e.x.m.j.p.DataCountsReporter] [node2] [ga-mean-bytes-p-status-clientip-status-1h] 1000000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:31:31,956][INFO ][o.e.x.m.d.DatafeedJob    ] [ga-mean-bytes-p-status-clientip-status-1h] Lookback has finished
[2018-04-11T23:31:31,956][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] attempt to stop datafeed [datafeed-ga-mean-bytes-p-status-clientip-status-1h] for job [ga-mean-bytes-p-status-clientip-status-1h]
[2018-04-11T23:31:31,956][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] try lock [20s] to stop datafeed [datafeed-ga-mean-bytes-p-status-clientip-status-1h] for job [ga-mean-bytes-p-status-clientip-status-1h]...
[2018-04-11T23:31:31,956][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] stopping datafeed [datafeed-ga-mean-bytes-p-status-clientip-status-1h] for job [ga-mean-bytes-p-status-clientip-status-1h], acquired [true]...
[2018-04-11T23:31:31,957][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] datafeed [datafeed-ga-mean-bytes-p-status-clientip-status-1h] for job [ga-mean-bytes-p-status-clientip-status-1h] has been stopped
[2018-04-11T23:31:36,150][ERROR][o.e.x.m.d.DatafeedManager] Failed to remove datafeed persistent task - will not auto close job [ga-min-bytes-p-status-clientip-status-1h]
java.lang.IllegalStateException: timed out after 20s
        at org.elasticsearch.persistent.PersistentTasksService$WaitForPersistentTaskStatusListener.onTimeout(PersistentTasksService.java:199) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.persistent.PersistentTasksService$1.onTimeout(PersistentTasksService.java:164) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.cluster.ClusterStateObserver$ContextPreservingListener.onTimeout(ClusterStateObserver.java:317) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.cluster.ClusterStateObserver$ObserverClusterStateListener.onTimeout(ClusterStateObserver.java:244) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.cluster.service.ClusterApplierService$NotifyTimeout.run(ClusterApplierService.java:576) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:573) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_151]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_151]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_151]
[2018-04-11T23:31:36,154][INFO ][o.e.x.m.j.p.DataCountsReporter] [node2] [ga-sum-bytes-p-status-clientip-status-1h] 800000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:31:51,958][ERROR][o.e.x.m.d.DatafeedManager] Failed to remove datafeed persistent task - will not auto close job [ga-mean-bytes-p-status-clientip-status-1h]
java.lang.IllegalStateException: timed out after 20s
        at org.elasticsearch.persistent.PersistentTasksService$WaitForPersistentTaskStatusListener.onTimeout(PersistentTasksService.java:199) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.persistent.PersistentTasksService$1.onTimeout(PersistentTasksService.java:164) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.cluster.ClusterStateObserver$ContextPreservingListener.onTimeout(ClusterStateObserver.java:317) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.cluster.ClusterStateObserver$ObserverClusterStateListener.onTimeout(ClusterStateObserver.java:244) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.cluster.service.ClusterApplierService$NotifyTimeout.run(ClusterApplierService.java:576) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:573) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_151]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_151]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_151]
[2018-04-11T23:32:07,180][INFO ][o.e.x.m.j.p.DataCountsReporter] [node2] [ga-sum-bytes-p-status-clientip-status-1h] 900000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:32:34,798][INFO ][o.e.x.m.j.p.DataCountsReporter] [node2] [ga-sum-bytes-p-status-clientip-status-1h] 1000000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:32:44,739][INFO ][o.e.x.m.d.DatafeedJob    ] [ga-sum-bytes-p-status-clientip-status-1h] Lookback has finished
[2018-04-11T23:32:44,739][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] attempt to stop datafeed [datafeed-ga-sum-bytes-p-status-clientip-status-1h] for job [ga-sum-bytes-p-status-clientip-status-1h]
[2018-04-11T23:32:44,739][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] try lock [20s] to stop datafeed [datafeed-ga-sum-bytes-p-status-clientip-status-1h] for job [ga-sum-bytes-p-status-clientip-status-1h]...
[2018-04-11T23:32:44,739][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] stopping datafeed [datafeed-ga-sum-bytes-p-status-clientip-status-1h] for job [ga-sum-bytes-p-status-clientip-status-1h], acquired [true]...
[2018-04-11T23:32:44,739][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] datafeed [datafeed-ga-sum-bytes-p-status-clientip-status-1h] for job [ga-sum-bytes-p-status-clientip-status-1h] has been stopped
[2018-04-11T23:33:04,477][INFO ][o.e.x.m.j.p.a.AutodetectProcessManager] [node2] Closing job [ga-sum-bytes-p-status-clientip-status-1h], because [close job (api)]
[2018-04-11T23:33:04,488][INFO ][o.e.x.m.j.p.l.CppLogMessageHandler] [ga-sum-bytes-p-status-clientip-status-1h] [autodetect/10435] EMAIL REDACTED Handled 1023038 records
[2018-04-11T23:33:04,488][INFO ][o.e.x.m.j.p.l.CppLogMessageHandler] [ga-sum-bytes-p-status-clientip-status-1h] [autodetect/10435] EMAIL REDACTED Pruning all models
[2018-04-11T23:33:04,589][INFO ][o.e.x.m.j.p.a.NativeAutodetectProcess] [ga-sum-bytes-p-status-clientip-status-1h] State output finished
[2018-04-11T23:33:04,897][INFO ][o.e.x.m.j.p.a.o.AutoDetectResultProcessor] [ga-sum-bytes-p-status-clientip-status-1h] 7259 buckets parsed from autodetect output
[2018-04-11T23:33:09,161][INFO ][o.e.x.m.j.p.a.AutodetectCommunicator] [ga-sum-bytes-p-status-clientip-status-1h] job closed

The Job messages looked fine, although it was missing the final Job is closing message.

[elasticmachine]

Original comment by @dimitris-athanasiou:

When we autoclose a job at the end of a datafeed, we wait for the datafeed task to be removed from the cluster state. This is done LINK REDACTED . We set a timeout of 20 seconds for this. It appears in those cases this timeout was not enough. There is nothing else going on there apart from the fact that the node that was running that job did not receive the update that the datafeed task was removed within 20 seconds. Thus, the close-job action was never invoked.

I am not sure what the cause for this delay could be, but I imagine the factors are many and beyond our control (think long GC event for example). I think the strategy to avoid this issue is pretty much to either increase the timeout or add a retry strategy.

Any thoughts @droberts195 ?

[elasticmachine]

Original comment by @droberts195:

If the timeout was caused because the master node was busy then I agree the solution is simply to increase the timeout.

I think in other places where we have long timeouts they are configurable and our tests set timeouts that are much lower than the defaults. This means that a bug doesn't cause CI to spend, say, 30 minutes waiting for a timeout to expire before reporting a failure.

So I think we need to do the same for this timeout if we increase it to a large value.

It would be interesting to see the logs from the other node in the cluster around the time of this problem. If the other node was the master node then (a) its logs might confirm that it was very busy and confirm that this is the root cause or (b) show some other problem, not caused by high load, that caused the message to be lost. In case (b) the fix may be something different to increasing the timeout.

[elasticmachine]

Original comment by @sophiec20:

The 3rd job was having a persistent task timeout at this time, on node1:

[2018-04-11T23:23:42,063][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 90000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:23:42,951][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 50000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:23:44,530][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 100000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:23:44,740][INFO ][o.e.m.j.JvmGcMonitorService] [node1] [gc][120623] overhead, spent [259ms] collecting in the last [1s]
[2018-04-11T23:24:05,377][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 60000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:24:09,520][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 70000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:24:13,391][INFO ][o.e.m.j.JvmGcMonitorService] [node1] [gc][120651] overhead, spent [338ms] collecting in the last [1.1s]
[2018-04-11T23:24:14,392][INFO ][o.e.m.j.JvmGcMonitorService] [node1] [gc][120652] overhead, spent [267ms] collecting in the last [1s]
[2018-04-11T23:24:26,496][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 80000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:24:36,626][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 90000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:24:41,292][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 100000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:24:43,312][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-max-bytes-p-status-clientip-status-1h] 400000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:24:55,463][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 200000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:26:08,094][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-max-bytes-p-status-clientip-status-1h] 500000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:26:31,702][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 300000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:26:56,518][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 200000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:27:31,218][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-max-bytes-p-status-clientip-status-1h] 600000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:28:12,422][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 400000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:28:17,605][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-max-bytes-p-status-clientip-status-1h] 700000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:28:49,686][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 300000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:29:22,261][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 500000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:29:29,472][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-max-bytes-p-status-clientip-status-1h] 800000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:30:09,077][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-max-bytes-p-status-clientip-status-1h] 900000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:30:13,790][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 600000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:30:17,182][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 400000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:30:40,409][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 700000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:30:57,210][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-max-bytes-p-status-clientip-status-1h] 1000000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:31:17,603][INFO ][o.e.x.m.d.DatafeedJob    ] [ga-max-bytes-p-status-clientip-status-1h] Lookback has finished
[2018-04-11T23:31:17,603][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] attempt to stop datafeed [datafeed-ga-max-bytes-p-status-clientip-status-1h] for job [ga-max-bytes-p-status-clientip-status-1h]
[2018-04-11T23:31:17,603][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] try lock [20s] to stop datafeed [datafeed-ga-max-bytes-p-status-clientip-status-1h] for job [ga-max-bytes-p-status-clientip-status-1h]...
[2018-04-11T23:31:17,603][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] stopping datafeed [datafeed-ga-max-bytes-p-status-clientip-status-1h] for job [ga-max-bytes-p-status-clientip-status-1h], acquired [true]...
[2018-04-11T23:31:17,603][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] datafeed [datafeed-ga-max-bytes-p-status-clientip-status-1h] for job [ga-max-bytes-p-status-clientip-status-1h] has been stopped
[2018-04-11T23:31:21,645][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 500000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:31:26,632][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 800000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:31:37,626][ERROR][o.e.x.m.d.DatafeedManager] Failed to remove datafeed persistent task - will not auto close job [ga-max-bytes-p-status-clientip-status-1h]
java.lang.IllegalStateException: timed out after 20s
        at org.elasticsearch.persistent.PersistentTasksService$WaitForPersistentTaskStatusListener.onTimeout(PersistentTasksService.java:199) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.persistent.PersistentTasksService$1.onTimeout(PersistentTasksService.java:164) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.cluster.ClusterStateObserver$ContextPreservingListener.onTimeout(ClusterStateObserver.java:317) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.cluster.ClusterStateObserver$ObserverClusterStateListener.onTimeout(ClusterStateObserver.java:244) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.cluster.service.ClusterApplierService$NotifyTimeout.run(ClusterApplierService.java:576) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:573) [elasticsearch-6.3.0-SNAPSHOT.jar:6.3.0-SNAPSHOT]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_151]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_151]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_151]
[2018-04-11T23:31:50,853][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 900000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:32:04,759][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 600000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:32:17,410][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-varp-bytes-p-status-clientip-status-1h] 1000000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:32:29,102][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 700000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:32:31,721][INFO ][o.e.x.m.d.DatafeedJob    ] [ga-varp-bytes-p-status-clientip-status-1h] Lookback has finished
[2018-04-11T23:32:31,721][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] attempt to stop datafeed [datafeed-ga-varp-bytes-p-status-clientip-status-1h] for job [ga-varp-bytes-p-status-clientip-status-1h]
[2018-04-11T23:32:31,721][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] try lock [20s] to stop datafeed [datafeed-ga-varp-bytes-p-status-clientip-status-1h] for job [ga-varp-bytes-p-status-clientip-status-1h]...
[2018-04-11T23:32:31,721][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] stopping datafeed [datafeed-ga-varp-bytes-p-status-clientip-status-1h] for job [ga-varp-bytes-p-status-clientip-status-1h], acquired [true]...
[2018-04-11T23:32:31,721][INFO ][o.e.x.m.d.DatafeedManager] [no_realtime] datafeed [datafeed-ga-varp-bytes-p-status-clientip-status-1h] for job [ga-varp-bytes-p-status-clientip-status-1h] has been stopped
[2018-04-11T23:32:52,996][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 800000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:32:59,774][INFO ][o.e.x.m.j.p.a.AutodetectProcessManager] [node1] Closing job [ga-varp-bytes-p-status-clientip-status-1h], because [close job (api)]
[2018-04-11T23:32:59,779][INFO ][o.e.x.m.j.p.l.CppLogMessageHandler] [ga-varp-bytes-p-status-clientip-status-1h] [autodetect/10362] EMAIL REDACTED Handled 1023038 records
[2018-04-11T23:32:59,779][INFO ][o.e.x.m.j.p.l.CppLogMessageHandler] [ga-varp-bytes-p-status-clientip-status-1h] [autodetect/10362] EMAIL REDACTED Pruning all models
[2018-04-11T23:32:59,841][INFO ][o.e.x.m.j.p.a.NativeAutodetectProcess] [ga-varp-bytes-p-status-clientip-status-1h] State output finished
[2018-04-11T23:32:59,983][INFO ][o.e.x.m.j.p.a.o.AutoDetectResultProcessor] [ga-varp-bytes-p-status-clientip-status-1h] 7259 buckets parsed from autodetect output
[2018-04-11T23:33:06,396][INFO ][o.e.x.m.j.p.a.AutodetectCommunicator] [ga-varp-bytes-p-status-clientip-status-1h] job closed
[2018-04-11T23:33:08,646][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 900000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:33:24,027][INFO ][o.e.x.m.j.p.DataCountsReporter] [node1] [ga-median-bytes-p-status-clientip-status-1h] 1000000 records written to autodetect; missingFieldCount=0, invalidDateCount=0, outOfOrderCount=0
[2018-04-11T23:33:29,659][INFO ][o.e.x.m.d.DatafeedJob    ] [ga-median-bytes-p-status-clientip-status-1h] Lookback has finished

[elasticmachine]

Original comment by @sophiec20:

I can repeat this issue fairly consistently on a 2-node secured cluster in GCP (4 vCPUs, 15 GB memory) with 6.3.0 and 6.2.4, using 6 concurrently jobs running lookbacks (4G and 2G jvm). Busy nodes take more than 20s to respond. (it's not happening with 4 concurrent jobs).

It did not happen on a single node cluster.

[elasticmachine]

Original comment by @dimitris-athanasiou:

OK, I think this suggests increasing the timeout should mitigate the issue.

Regarding @droberts195 comment on tests, I'm not sure we can do anything for this timeout as it is not exposed as a parameter.

[elasticmachine]

Original comment by @sophiec20:

On the busy machine (more jobs than cores) I am now seeing this:
(as prev: GCP, 4 vCPU, 2x nodes, 6.3.0 a47564f)

Occasional timeouts when starting jobs

[2018-04-17T18:44:32,044][WARN ][r.suppressed             ] path: /_xpack/ml/datafeeds/datafeed-ga-min-bytes-pa-status-clientip-status-1h/_start, params: {datafeed_id=datafeed-ga-min-bytes-pa-status-clientip-status-1h, start=1970-01-02T10:00:00Z, end=2018-12-31T00:00:00Z}
org.elasticsearch.ElasticsearchException: Starting datafeed [datafeed-ga-min-bytes-pa-status-clientip-status-1h] timed out after [20s]
        at org.elasticsearch.xpack.ml.action.TransportStartDatafeedAction$2.onTimeout(TransportStartDatafeedAction.java:192) [x-pack-ml-6.2.4.jar:6.2.4]
        at org.elasticsearch.xpack.core.persistent.PersistentTasksService$1.onTimeout(PersistentTasksService.java:155) [x-pack-core-6.2.4.jar:6.2.4]
        at org.elasticsearch.cluster.ClusterStateObserver$ContextPreservingListener.onTimeout(ClusterStateObserver.java:317) [elasticsearch-6.2.4.jar:6.2.4]
        at org.elasticsearch.cluster.ClusterStateObserver$ObserverClusterStateListener.onTimeout(ClusterStateObserver.java:244) [elasticsearch-6.2.4.jar:6.2.4]
        at org.elasticsearch.cluster.service.ClusterApplierService$NotifyTimeout.run(ClusterApplierService.java:581) [elasticsearch-6.2.4.jar:6.2.4]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:573) [elasticsearch-6.2.4.jar:6.2.4]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_151]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_151]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_151]

Failures to update established model size:

[2018-04-17T18:45:14,540][ERROR][o.e.x.m.j.p.a.o.AutoDetectResultProcessor] [ga-varp-bytes-by-status-clientip-status-1h] Failed to update job with new established model memory [407944]
org.elasticsearch.cluster.metadata.ProcessClusterEventTimeoutException: failed to process cluster event (update-job-ga-varp-bytes-by-status-clientip-status-1h) within 30s
        at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$0(MasterService.java:125) ~[elasticsearch-6.2.4.jar:6.2.4]
        at java.util.ArrayList.forEach(ArrayList.java:1255) ~[?:1.8.0_151]
        at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$1(MasterService.java:124) ~[elasticsearch-6.2.4.jar:6.2.4]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:573) [elasticsearch-6.2.4.jar:6.2.4]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_151]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_151]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_151]

Concurrent lookbacks did not use to result in these timeouts. The following is different since previous busy-load tests:

• test env now on GCP, was on AWS
• later version of elasticsearch (6.2 and 6.3 includes established model memory cluster updates)
• updated test scripts (now running similar jobs concurrently, rather than diverse jobs)

Next steps will be to replicate with debug turned on.

[elasticmachine]

Original comment by @davidkyle:

I recreated the error with monitoring enabled and JVM heap usage is within bounds when the failures occur. Nor are there any log messages about high garbage collection overhead.

Note both nodes are on the same machine I'm not entirely certain what the CPU usage is showing. Is it total usage of the machine with the data sampled a different times accounting for the small differences.
CPU Utilization (%) is 'Percentage of CPU usage for the Elasticsearch process'

Master Node

Data Node

[elasticmachine]

Original comment by @davidkyle:

The problem is the large number of clusterstate updates invoked to set the established model memory limit.

AutoDetectResultProcessor::updateEstablishedModelMemoryOnJob logs a message on success and failure, greping through the debug level log files for a single job:

• 243 successful updates
• 53 failures
• = 296 updates total

Clusterstate updates are tagged with the job id update-$JOB_ID so I can correlate these to the calls to update established model memory:

• 231 successful updates
• 12 no-op updates (no change to cluster state/established model mem)
• = 243 == number of successful updates

After a time there was a problem with the node and the remaining requests are accounted for by 53 instances of this message

MasterService    ] [node1] processing [$JOB_ID]: ignoring, master service not started

The cluster state updates fall further behind the requests until they start timing out. This is also the cause of the PersistentTasksService timeout stopping the datafeed.

Actions

1. Optimise out the no-op cluster update requests. LINK REDACTED
2. Use ClusterStateUpdateTask instead of AckedClusterStateUpdateTask when updating established model memory. LINK REDACTED
3. Compare 6.x to earlier releases to see if the frequency of established memory updates has changed. These are triggered by model size stats writes by autodetect so a change there may be causing the problem.
4. Consider not updating established model memory if the new value isn't significantly different to the current.

[elasticmachine]

Original comment by @davidkyle:

3. Compare 6.x to earlier releases to see if the frequency of established memory updates has changed. These are triggered by model size stats writes by autodetect so a change there may be causing the problem.

I compared the number of model size stats updates for a number of jobs in 6.0.1, 6.1.0 and the latest snapshot 6.3.0. The results are consistent across all versions for the handful of jobs I tested, for example one job gave these counts:

6.0.1 = 408 Model Size Stats updates
6.1.0 = 422 Model Size Stats updates
6.3.0 = 418 Model Size Stats updates

No regression has been introduced, the behaviour of the 6.3 branch is consistent with previous releases.

[droberts195]

Should be fixed in 6.3.2 by #31768