apache/incubator-brooklyn — pull request #303 by ahgittin (2014-11-06 02:06:59+00:00)
Title: Persistence better logging and optimization

see commits for details

logging is now quite elegant (and code more elegant too). at `MASTER` we log this for all persistence:

```
2014-11-06 01:53:24,484 DEBUG b.e.r.PeriodicDeltaChangeListener [brooklyn-execmanager-cPHPyZLD-49]: Checkpointing delta of memento: updating entities=[NginxControllerImpl{id=yj1CnqgS}, TomcatServerImpl{id=jFLN539t}, DynamicWebAppClusterImpl{id=mOp5gagc}, ControlledDynamicWebAppClusterImpl{id=cuPk22K9}], locations=[], policies=[], enrichers=[], catalog items=[]; removing entities=[], locations=[], policies=[], enrichers=[], catalog items=[]
2014-11-06 01:53:24,510 DEBUG b.e.r.p.BrooklynMementoPersisterToObjectStore [brooklyn-execmanager-cPHPyZLD-49]: Checkpointed delta of memento in 15ms: updated 4 entities, 3 locations, 2 policies, 35 enrichers, 0 catalog items; removed 0 entities, 0 locations, 0 policies, 0 enrichers, 0 catalog items
```

at `HOT_STANDBY` you see the following most of the time (much more detail on first 5 rebinds and every 1000th, which is about every ~15m):

```
2014-11-06 01:53:24,221 DEBUG b.e.rebind.RebindManagerImpl [brooklyn-execmanager-IEUSHnfF-1]: Rebinding (HOT_STANDBY, iteration 12) from /tmp/mms-amp-data/master...
2014-11-06 01:53:24,223 DEBUG b.e.r.p.BrooklynMementoPersisterToObjectStore [brooklyn-execmanager-IEUSHnfF-1]: Loaded rebind lists; took 1ms: 7 entities, 3 locations, 2 policies, 48 enrichers, 0 feeds, 0 catalog items; from /tmp/mms-amp-data/master
2014-11-06 01:53:24,292 DEBUG b.e.r.p.BrooklynMementoPersisterToObjectStore [brooklyn-execmanager-IEUSHnfF-1]: Loaded rebind raw data; took 69ms; 7 entities, 3 locations, 2 policies, 48 enrichers, 0 feeds, 0 catalog items, from /tmp/mms-amp-data/master
2014-11-06 01:53:24,467 DEBUG b.e.r.p.BrooklynMementoPersisterToObjectStore [brooklyn-execmanager-IEUSHnfF-1]: Loaded rebind manifests; took 174ms: 7 entities, 3 locations, 2 policies, 48 enrichers, 0 feeds, 0 catalog items; from /tmp/mms-amp-data/master
2014-11-06 01:53:24,533 DEBUG b.e.r.p.BrooklynMementoPersisterToObjectStore [brooklyn-execmanager-IEUSHnfF-1]: Loaded rebind mementos; took 5ms: 7 entities, 3 locations, 2 policies, 48 enrichers, 0 feeds, 0 catalog items, from /tmp/mms-amp-data/master
2014-11-06 01:53:24,570 DEBUG b.e.rebind.RebindManagerImpl [brooklyn-execmanager-IEUSHnfF-1]: Rebind complete (HOT_STANDBY, iteration 12) in 349ms: 1 app, 7 entities, 3 locations, 2 policies, 48 enrichers, 0 feeds, 0 catalog items
```

and all nodes get such entries as this:

```
2014-11-06 01:53:24,371 DEBUG b.m.h.ManagementPlaneSyncRecordPersisterToObjectStore [brooklyn-execmanager-IEUSHnfF-3]: Checkpointed delta of manager-memento in 1ms: brooklyn.management.ha.ManagementPlaneSyncRecordDeltaImpl[nodes: [BasicManagementNodeSyncRecord{nodeId=IEUSHnfF, status=HOT_STANDBY}]]
```

each appears once per second, meaning in happy path neither standby nor master logs too much.

there is some slight hack to prevent rebind over-logging, but i don't think it's too bad!

`trace` level restores full logging