Delay between fleet service submit and actual systemd service start

[paveltiunov]

Hi guys!
Great job on CoreOS!
We're using fleet to run high frequency services: there are many starts and stops and they should be performed as fast as possible.
We're experiencing significant delays about 2-3 seconds between submit of a service to fleet and it's actual start with systemd.
Tried to tweak engine_reconcile_interval and no effect so far.
What I see in logs with verbosity=10 and journalctl -f -u fleet.service | grep Reconciler:

Sep 26 11:15:48 core-01 fleetd[2225]: INFO reconciler.go:161: EngineReconciler completed task: {Type: AttemptScheduleUnit, JobName: allcountjs-app-allcount-tasks.service, MachineID: 22c5d548565e4643b76d2119ab925394, Reason: "target state launched and unit not scheduled"}
Sep 26 11:15:49 core-01 fleetd[2225]: DEBUG reconcile.go:84: Reconciler tick
Sep 26 11:15:50 core-01 fleetd[2225]: DEBUG reconcile.go:84: Reconciler tick
Sep 26 11:15:51 core-01 fleetd[2225]: DEBUG reconcile.go:84: Reconciler tick
Sep 26 11:15:51 core-01 fleetd[2225]: DEBUG reconcile.go:321: AgentReconciler attempting tasks [{LoadUnit unit scheduled here but not loaded %!s...
Sep 26 11:15:51 core-01 fleetd[2225]: INFO reconcile.go:330: AgentReconciler completed task: type=LoadUnit job=allcountjs-app-allcount-tasks.service reason="unit scheduled here but not loaded"
Sep 26 11:15:51 core-01 fleetd[2225]: INFO reconcile.go:330: AgentReconciler completed task: type=ReloadUnitFiles job=N/A reason="always reload unit files"
Sep 26 11:15:51 core-01 fleetd[2225]: INFO reconcile.go:330: AgentReconciler completed task: type=StartUnit job=allcountjs-app-allcount-tasks.service reason="unit currently loaded but desired state is launched"
Sep 26 11:15:51 core-01 fleetd[2225]: DEBUG reconcile.go:61: AgentReconciler completed reconciliation in 158.214102ms

Looks like there is lack of "Reconciler triggered" message for AgentReconciler.
Do you have any suggestions we can start from to solve this problem?
Fleet version is 0.10.2.

[paveltiunov]

Fixed problem for us just by adding AfterIndex watcher option.

[paveltiunov]

Hi guys!
Any thoughts on it? Would you fix it or it seems to be not critical?

[jonboulle]

Could you explain in a little more detail how the afterindex change helped? (how were the events getting missed?). thanks!

[jonboulle]

history: https://github.com/coreos/fleet/pull/751/commits /cc @tixxdz

[jonboulle]

The concern with this approach is running into #408 again. I think we'd need to add a mitigation, similar to #411 , but could be much simpler: rather than having to "catch up", we can just go straight to 0 again (i.e. latest)

[jonboulle]

Would love to know more about how you're missing events, though

[paveltiunov]

Hi @jonboulle !
Looks like when 0 is used as AfterIndex then when multiple events arrived at same time you could miss some of events in case event processing time is big enough. Particularly there's a situation where "Reconciler triggered" event is missed and reconciliation is delayed for couple of seconds.

[paveltiunov]

Very tricky thing here is that const in agent/reconcile.go

const (
    // time between triggering reconciliation routine
    reconcileInterval = 5 * time.Second
)

^ Update is tied to that time. So no matter what engine_reconcile_interval you have you won't be able to update more frequently than once per 5 second.

[paveltiunov]

This commit bcwaldon@bdf5f72 states

Since the content of events is no longer used to drive the Engine or the Agent, handling all events in order no longer matters.

Actually content of events is used here:

    switch path.Base(res.Node.Key) {
    case "target-state":
        ev = JobTargetStateChangeEvent
        ok = true
    case "target":
        ev = JobTargetChangeEvent
        ok = true
    }

So 0 AfterIndex can be used if this code will return always ok = true -- it's where events are missed I believe.

[kayrus]

@paveltiunov which etcd version do you use for fleet?

[paveltiunov]

etcd version 0.4.9

[kayrus]

@paveltiunov etcd 0.4.x has lots of bugs and architectural flaws. can you upgrade your etcd cluster to the latest 2.2?

Please note that you have to upgrade 0.4.x to 2.0.x, then 2.0.x to 2.1.x, and then 2.1.x to 2.2.x.

[kayrus]

Relates to #1363

[kayrus]

@paveltiunov were you able to upgrade etcd cluster and test fleet with the new one?

[jonboulle]

Bumping milestone for now.

@paveltiunov As @kayrus mentioned, we'd love to know if you can replicate the problem with a recent (2.2+) version of etcd

[paveltiunov]

@kayrus is there some automatic way to upgrade? Upgrading production environment with proposed method doesn't seem reasonable for us. What release version of CoreOS is using etcd 2.2?

[kayrus]

@paveltiunov latest coreos stable release ships etcd 2.2.0. and I would like to inform you that etcd v0.4.x binary will be removed in future coreos releases.

[kayrus]

@paveltiunov, automatic upgrades work in 2.x branch only. but I strongly recommend you to create a backup before each upgrade.

[paveltiunov]

@kayrus Sorry. My bad. I forgot etcd 2 is etcd2 binary. Thanks for pointing this out. Our version is

etcd Version: 2.2.0
Git SHA: e4561dd
Go Version: go1.5.1
Go OS/Arch: linux/amd64

So we're up to date here.

[kayrus]

@paveltiunov great. so we have to get more info at this point.

1. how many units are scheduled in your cluster?
2. how many etcd members do you have?
3. how many fleet machines do you have?
4. do you use custom configuration for etcd and fleet? can you provide your cloud-config you use to configure your coreos nodes?
5. which coreos release do you use?

[dongsupark]

I had a closer look into this issue.

Even if etcd.WatcherOptions.AfterIndex becomes non-zero, it doesn't mean that it could prevent events from being missed. The WatcherOptions is passed to kAPI.Watcher in etcd, and httpWatcher.Next() always updates hw.nextWait.WaitIndex the ModifiedIndex, regardless of the initial AfterIndex.

Also it's true that fleet doesn't make use of content of the returned event, in agent or engine, as noted in bcwaldon@bdf5f72. I think it's hard to find a logical relation between AfterIndex and the missing events.

The only scenario I can imagine is etcd being overloaded due to a well-known issue, which results in temporary event misses. That could be eventually fixed by using etcd v3 and fleet's recent versions.

Even if it's worth setting AfterIndex to non-zero, I think the long term plan should be just to change fleet to use new API from etcd v3, based on protobuf.

So I would suggest closing this issue and #1363, unless the original author could give another feedback.