WIP: Feature/live wpc reconfigure #263

lust4life · 2017-08-04T17:09:58Z

remove pollServices in registry

Because supervisor will supervise minions, if an exception occurs, it will be handled according to policy. So there's no need for state polling, because we can't do much if we can get the status. the user's handle logic can be expressed by policy.
remove healthcheck & metric

The aim here is to normalise the Gauge/Derived/Message semantics into a single semantic of 'things computed from events from your app'.
- remove healthcheck
  
  Looks like metric can also be seen as a healthcheck, such as windows performance counters. when outside tick , metric generate some msg, which will be processed by user defined engine , they can decide their meaning (log or metric or healthcheck...) there.
- remove metric
  
  metric can be implemented by engine's process expression builder, what we need to do is schedule jobs for tick, in the corresponding time(like old metricConf.tickInterval) or manually tick. Metric's data sources can have two types, one is similar to WPC, generate data in real-time when ticked .the other is generate through the normal log message.
support multi targets on internallogger and apply rules when send msg to target
remove loglevel on Logger interface

message has the log level info, targets have the rules info, before putting msg to target, apply rules on message to decide if really send to target.
redefined Message

The aim here is to normalise the Gauge/Derived/Message semantics into a single semantic of 'things computed from events from your app'.
- remove FieldModule.fs
- use FsMessageTemplate for default MessageWriter
- json support will use fspickler.json
- no need SuppressPointValue
  
  gauges are stored in contexts with gauge type. so message.value is template or raw message.
errors (exceptions)

is expressed by a context, not a field. user can define their own output template for decision whether or not to show them.
todo
- more unit test
  - message
  - ewma & percentile
  - formatting
  - registry
- event format improvement mentioned by event format proposal #257
- reorganize types in Events.fs
- chiron new version in Serialisation.fs # no need use fspickler instead
- complete todo comments part in codebase
  - failwith "todo"
  - Tests.skiptest "TBD"
- maybe obsolete
  - PromisedLogger.fs
    
    create logger is no longer async, just a function with registry instance
  - service.fs
    
    because it has an abstraction Service around each service and that abstraction isn't crisp. I'm considering adding a behaviour tree which is a more natural polling mechanism with built-in compensatory logic.
  - Metrics.Ticked.fs -> replace by Events.Ticker
  - Transformers.fs -> replace by Events.xxx (should implement by events pipe style)
- misc
  
  log api 因为 pipe 的异步原因导致 Alt 失效了, 考虑重构, 提供一个默认值取代 Job<unit> 应该就好了
  
  考虑一下 logSimple timeout 是否会打破 unbound buffer 的情况
  
  time xxx 的 logging api 考虑是否用 gaugetype 取代 logger name, 会破坏 api 的兼容性

lust4life · 2017-08-05T09:47:49Z

@haf add some temporary code Events.fs for discussion.

This execution/filtering/windowing, is what I want build in a synchronous manner with Flow, we either throw the message away or we drop it into a RingBuffer.

really don't know how to build in a synchronous manner with the current Flow , beacuse flow need a source, but what we really want is just function composition ？ flow can only pass a context and run iterator ( tryAdvance or bulk), witch just iterator the source elements. how can we define the source elements ?

and is logary's own targets dispatching need to implement in Processing ?

haf · 2017-08-07T07:08:24Z

src/Logary.CSharp.Facade/Facade.cs

+                        if(_fwClock != local.Item2)
+                        {
+                            _logger = local.Item1.GetLogger(_name);
+                            _fwClock = local.Item2;


Why not bump the clock?

every time we initialize config, the clock increases by 1. and when we log message, we will check if the local config clock same as the current config's clock , if not, get new logger from new config and update the clock then log message use the new logger .

e.g.

the default fwClock is 1.

initialize logging config , config clock will be 2

if we initialize logging config twice here or between some time, config clock will be 3

then log message through facade api, it should be updating config and clock once.

so assign the current clock to the fwClock (not by adding one) can avoid more checking .

haf · 2017-08-07T07:08:30Z

src/Logary.Facade/Facade.fs

@@ -783,7 +783,7 @@ module Global =
          let cfg, cfgClock = !config
          if cfgClock <> fwClock then
            logger <- cfg.getLogger name
-            fwClock <- fwClock + 1u
+            fwClock <- cfgClock


Same here... Why?

see reply above

haf · 2017-08-07T07:08:50Z

src/Logary/Internals/Global.fs

@@ -75,7 +75,7 @@ module internal Global =
          let cfg, cfgClock = !config // reread the config's clock after taking lock
          if cfgClock <> fwClock then // recheck after taking lock to avoid races
            logger <- cfg.getLogger name // get the current logger
-            fwClock <- fwClock + 1u // update instance's clock
+            fwClock <- cfgClock // update instance's clock


...and here...

haf · 2017-08-07T07:09:53Z

src/Logary/Registry.fs

+          let targetName = Message.tryGetContext "target" message
+          match targetName with 
+          | Some (String targetName) ->
+              let subscriber = HashMap.tryFind targetName subsribers 


2 space indentation

haf · 2017-08-07T07:09:59Z

src/Logary/Registry.fs

-    let rec loop () =
+    let inputCh, emitCh, shutdownCh, subscriberCh = Ch (), Ch (), Ch (), Ch ()
+
+    let engine = { subscriptions = HashMap.empty


Format on new line

haf · 2017-08-07T07:30:38Z

I think the PR is going in the right direction, and I understand it's primarily about discussion right now.

beacuse flow need a source, but what we really want is just function composition

Yes; I was thinking an infinite source that's a synchronous/isolated/threaded thing, taking messages from the surrounding system. The "processing" function is then composed with (source |> flatMap processing) or something similar.

module Engine =
  let create config =
    let buffer = Array.zeroCreate 512
    // bridge async/sync gap
    let rec source =
      Job.server (Job.isolate (job {
      while hasValues buffer do
        Interlocked.Increment(&chaser, 1)
      }))
      // in the engine loop:
      Flow.run (readBuffer chaser head buffer |> toSinks config.targets)
      // then somewhere below
      Job.result engine

let engine =
  memo (Engine.create ())

let impl level fac: Alt<Promise<unit>> =
  engine >>= fun engine ->
  Alt.prepareFun <| fun nack ->
  // allocate index
  let i = ref 0
  let p = Promise ()
  while Interlocked.CompareAndSwap(&head, ...) <> ... && not (Promise.isFulfilled nack) then
    buffer.[i] <- (level, fac, p)
  p

let logger = { new Logger with member x.logWithAck level fac = impl level fac }

let usage =
  let a = fn ()
  logger.info (eventX "Thing {a}" >> setField "a" a)

Then Flow.run would block on the source; thereby dedicating a single thread to the single processing step in Logary.

Targets implement processing? No, I'm thinking something like (pseudo code):

let processing =
  Flow.map enrich
  >> Flow.groupBy (Flow.rollingWindow 5s) (fun x -> x.fields.['service'])
  >> Flow.sink (target "elasticsearch")

let processing2 =
  let stream1 =
    Flow.map enrich
    >> ...
  let stream2 =
    Flow.map alter
    >> ...
  Flow.joinBy (Flow.rollingWindow 5s) (fun a b -> a.name = b.context.["relatedTo"])

Each sink could then be a source of a de-multiplexer/fan-in function that writes to the RingBuffers of the named targets (found by config lookup). Flow.sink should block synchronously if the buffers it is writing to are full and the policies for them aren't allowing dropping messages.

lust4life · 2017-08-18T09:32:24Z

@haf

are we going build an processing through Flow/Events expression to achieve something like Logary.Transformers (Counters,Reservoirs,ExpWeightedMovAvg,SlidingWindow...) ?

previous question :

and is logary's own targets dispatching need to implement in Processing ?

i mean in previous version , when we get a logger, we will find the corresponding targets, and put message to targets buffer when logging. but now, when we get a logger and logging, all message will go to the engine and through processing , and put to targets buffer if the message has sink to a specific target . what If the user does not provide any processing, will all the messages be discarded ?

haf · 2017-08-18T13:19:16Z

Yes, then all messages are discarded; because the new processing will take the place of Rule and the configuration of where messages go.

are we going build an processing through Flow/Events expression to achieve something like Logary.Transformers (Counters,Reservoirs,ExpWeightedMovAvg,SlidingWindow...) ?

Yes

lust4life · 2017-08-18T14:12:14Z

thanks for confirming, it is getting clearer. will try to carry on

lust4life · 2017-08-22T10:42:20Z

@haf Can you help me check if Pipe in Events.fs meets the requirements?

lust4life · 2017-08-31T07:25:20Z

@haf

I was thinking, when we implemented the event processing builder, the logger itself need less state, it is just an logging API feed message into engine. If so, we can make Global.getStaticLogger lighter. no need to communicate through client-server (promise wrappers), what we need for creating a logger is the current 'engine' . so we can capture it by a function when we initialize Registry , inject it into Global.getLogger .

and getlogger api on LogManager can become synchronous. if that, message middleware compose and messagefactory is invoked at user's call-site through log/logack. issue like this #255 can be solved.

haf · 2017-08-31T08:31:13Z

the logger becomes stateless

It doesn't have any state, but a reference to the engine.

just the API

yes

getLogger on LogManager

Is needed, because you may have multiple logary instances running concurrently and the LogManager/Registry/Engine needs an API to expose to the user.

getStaticLogger lighter

How? Given the above requirement for not-just-globals.

No need to communicate client-server

But there still is; we still need a way of accepting the message into a given target and then ack on send.

lust4life · 2017-08-31T08:52:08Z

change my previous thoughts a bit , yes you are right, the api is need, because multiple logary/registry instances.
but no need to be an async(fake sync) style.

commit some changes, if you have time to look at it .

haf · 2017-09-03T16:00:36Z

We should have the IClock interface extracted everywhere so that time can be ticked manually.

My environment is improving and I can almost always use F# now.

lust4life · 2017-09-04T02:56:15Z

right now, time auto tick ticker is implement by hopac.timeout which rely on Environment.TickCount , but ticker itself can support manually tick, so seems in theory we can simulate time auto tick for just test.

  let inline tick (ticker:Ticker<'state,_,_>) pipe =
    pipe
    |> chain (fun cont -> 
         let updateMb = Mailbox ()
         
         let rec loop state =
           Alt.choose [
             ticker.Ticked ^=> fun _ ->
               let state', res = ticker.HandleTick state
               cont res
               >>=. loop state'
   
             updateMb ^=> (ticker.Folder state >> loop)
           ]
           
         loop ticker.InitialState |> Hopac.start
   
         fun prev -> updateMb *<<+ prev)

[<AbstractClass>]
type Ticker<'state,'t,'r> (initialState:'state) =
  let tickCh = Ch<unit> ()

  abstract member Folder     : 'state -> 't -> 'state
  abstract member HandleTick : 'state -> 'state * 'r

  member this.InitialState = initialState
  member this.Ticked = tickCh :> Alt<_>
  member this.Tick () = tickCh *<- ()

  member this.TickEvery timespan =
    let cancellation = Cancellation.create ()
    let rec loop () =
      Alt.choose [
        timeOut timespan ^=> fun _ ->
          this.Tick () ^=> fun _ ->
          loop ()

        Cancellation.isCancelled cancellation
      ]

    loop () 
    |> Job.start 
    >>-. cancellation

but i think processing here is not intended for high precision timing, i just print info to console to see whether the effect is roughly right or not 😅.

My environment is improving and I can almost always use F# now

🎉

lust4life · 2017-09-05T03:25:03Z

@haf i was thinking, SamplePeriod in ExpWeightedMovAvg now is 5 seconds, and is used for calculate alpha and instantRate, should we calculate them (alpha,instantRate) real-time based on every tick's real interval?

lust4life · 2017-09-05T16:17:21Z

@haf add percentile and EWMA event processing ,

Metrics/Streams

The aim is to port something of Nessos Streams into a metrics engine, so that the configuration of where to send what names/hieras/messages/metrics/etc is done with code rather than the rules. That way we can add in calculating metrics, like finding the 99th percentile of request latency every rolling 5 second window.

i think aim here can work now. processing builder like this :

Pipe.start |> Events.tag "metric request latency" 
|> Pipe.bufferTime (TimeSpan.FromSeconds 5.)
|> Events.percentile 0.99
|> Pipe.map (fun num -> Message.event Info (sprintf "99th percentile of request latency every rolling 5 second window is %A" num))


let fiveMinutesEWMATicker = EWMATicker (Duration.FromSeconds 1L, Duration.FromMinutes 5L)
Pipe.start |> Events.tag "metric request latency" 
|> Pipe.map (fun msg -> msg.value |> function Gauge (Int64 v,_) -> v | _ -> 1L)
|> Pipe.withTickJob (fiveMinutesEWMATicker.TickEvery (TimeSpan.FromSeconds 10.))
|> Pipe.tick fiveMinutesEWMATicker
|> Pipe.map (fun rate -> Message.event Info (sprintf "fiveMinutesEWMA of request latency's rate(sample/sec) is %A" rate))

lust4life · 2017-09-11T09:33:35Z

Ping ?

haf · 2017-09-11T10:45:15Z

@lust4life Yes, that could work. How do would you design the filtering and end-to-end declaration of the processing pipeline?

I don't really understand the code though; you have fiveMinutesEWMATicker.TickEvery (Ti... but then you have another line with tick? Why do we have an instance of a ticker used twice? And if you tag with Events.tag at the top, how come you get a numeric rate at the last line? Why not use Duration throughout?

lust4life · 2017-09-11T11:29:27Z

you have fiveMinutesEWMATicker.TickEvery (Ti... but then you have another line with tick? Why do we have an instance of a ticker used twice?

Pipe.tick accept a ticker. a ticker define how to folder with each item from last stream/pipe and handler tick (generate output for next stream/pipe) and can be ticked manually by the user who hold the ticker. or automatically on a timer.

generally, most of the time-related pipe are encapsulating them as one like this:

  let inline bufferTime timespan pipe =
    let ticker = BufferTicker ()
    pipe
    |> withTickJob (ticker.TickEvery timespan)
    |> tick ticker

because a timer need be managed, so we should append them to pipe (there is what withTickJob and TickEvery do), so when shutdown registry, we should stop them, like ctss below:

    let rec running ctss =
      Alt.choose [
        ...
        shutdownCh ^=> fun (res, timeout) ->
          rlogger.infoWithAck (eventX "Shutting down")
          ^=>. Seq.Con.iterJob Cancellation.cancel ctss
          >>=. shutdown targets timeout
          >>= fun shutdownInfo -> res *<= shutdownInfo
      ]

    let state =
      { runtimeInfo = ri
        msgProcessing = msgProcessing
        flushCh = flushCh
        shutdownCh = shutdownCh }

    createGlobals conf.runtimeInfo.logger state
    >>=. Seq.Con.mapJob id conf.processing.tickTimerJobs
    >>= fun ctss -> Job.supervise rlogger (Policy.restartDelayed 500u) (running ctss) 
    >>-. state

so, first instance usage is for setup a tick timer, second instance usage if for setup a ticker.

in a situation which user want to control when to tick manually (like when some url route has been matched), they can tick through a ticker, by invoke ticker.Tick ().

And if you tag with Events.tag at the top, how come you get a numeric rate at the last line?

tag here is a filter, not a setter. here means it filter messages which has tag 'metric request latency', and EWMATicker here generate rate info for next pipe (see HandleTick below), so at last we get a numeric rate. the message itself should carry the request duration info, here is just a fake example.

type EWMATicker<'t> (rateUnit, alphaPeriod) =
  inherit Ticker<ExpWeightedMovAvg.EWMAState,int64,float>(ExpWeightedMovAvg.create alphaPeriod)
    override this.Folder ewma item = 
      ExpWeightedMovAvg.update ewma item

    override this.HandleTick ewma =
      let ewma' = ExpWeightedMovAvg.tick ewma
      let rate = ewma' |> ExpWeightedMovAvg.rateInUnit rateUnit
      ewma', rate

lust4life · 2017-09-11T11:38:16Z

How do would you design the filtering and end-to-end declaration of the processing pipeline?

what does this mean, don't get the point. can you explain that a little bit more?

haf · 2017-09-11T19:15:15Z

I understand; I think the next point for me is to test your code a bit. What state is it in?

lust4life · 2017-09-12T06:26:01Z

lust4life · 2017-09-12T06:43:15Z

think about how to GC ticker jobs on events, these may leak mem ?

maybe we can support DisposeAsync at LogManager/Registry.T to solve these problem.

lust4life · 2017-09-23T03:37:07Z

@haf ping ? 😸

haf · 2017-10-01T12:28:15Z

Hey @lust4life

You've proven that you're ready to stick to this project and help out, so I'm going to give you commit access; I'm looking forward to you merging this PR (and using your code!).

We're using Logary throughout everything at my company, so I'm absolutely not abandoning this project, but I may have to keep a slightly lower profile. Let's keep the discussions going none the less.

What do you say? Are you up for finishing up this PR and merging it to master as v5?

Cheers

lust4life · 2017-10-10T15:27:51Z

@haf Last few days i was on holiday in my hometown. Next, I will follow up to finish it. If there are any problems, i will ping you 😸

lust4life · 2017-10-15T15:00:01Z

module Registry =
  /// The holder for the channels of communicating with the registry.
  type T =
    private {
      runtimeInfo : RuntimeInfo
      msgProcessing : Message -> Middleware option -> Alt<unit>

      /// Flush all pending messages from the registry to await shutdown and
      /// ack on the `ackCh` when done. If the client nacks the request, the
      /// `nack` promise is filled with a unit value. Optional duration of how
      /// long the flush 'waits' for targets before returning a FlushInfo.
      flushCh : Ch<Ch<FlushInfo> * Promise<unit> * Duration option>

      /// Shutdown the registry in full. This operation cannot be cancelled and
      /// so the caller is promised a ShutdownInfo.
      shutdownCh : Ch<IVar<ShutdownInfo> * Duration option>
    }

    member private x.Dispose (disposing : bool) =
      (x :> IAsyncDisposable).DisposeAsync () |> Hopac.start

    override x.Finalize () = x.Dispose false

    interface IDisposable with
      override x.Dispose () = 
        x.Dispose true
        GC.SuppressFinalize(x)
        

    interface IAsyncDisposable with
      override x.DisposeAsync () =
        x.shutdownCh *<+=>- fun reply -> reply, None
        |> Job.startIgnore

maybe need think about how to GC tick jobs when initialize another logary instance ,and the previous logary instance go out of its lifetime, these auto tick jobs need stop.

@haf should we support something like this ? or let the users shutdown it manually, don't rely on GC. Because DisposeAsync in IDisposable.Dispose is not very robust.

…bals directly

…ossible with obj (instead of Value Modle)

prepare for testing logary,ensure it can work mostly,then focus on breaking changes in other prjects.

lust4life · 2017-11-06T19:22:45Z

Work continues at #219

lust4life added 6 commits May 17, 2017 20:21

add build/test task to vs

ae0c955

set fwclock to cfgclock after updating

d8ab7d5

remove redundant code

2e2db85

set fwclock to cfgclock after updating

0baf135

events demo

2fd67a9

remove type service for weird compile error

fa045fb

lust4life mentioned this pull request Aug 5, 2017

WIP: support log event stream processing and format improvement #219

Merged

18 tasks

haf reviewed Aug 7, 2017

View reviewed changes

lust4life added 4 commits August 18, 2017 14:02

make event pipes processing work

bdc9b1c

fix service type duplicate compile error

5991d43

make test passed

1d22310

newline format

9af221f

migrate some transformers

9af79f0

lust4life added 3 commits August 27, 2017 16:33

remove healthcheck and metric, replace with event processing builder

36bad17

fill the gap between registry and engine

78cdba9

basic tests pass

21da916

make getlogger more lighter, no channel request involved

2763422

add percentile and EWMA pipe

1e1efe0

add test for healthcheck

826afbc

lust4life mentioned this pull request Sep 16, 2017

event format proposal #257

Closed

lust4life added 9 commits October 15, 2017 23:32

temporarily remove GlobalService module to service.fs, initialise glo…

77f9224

…bals directly

add some todos

2eb12dd

try use obj instead of Value model

3fb857f

Temporarily exclude files that may not be needed

0d07ce3

use FsMessageTemplates format Message,try keep consistent as far as p…

6f8c763

…ossible with obj (instead of Value Modle)

fix graphite format message template, generate message for gauges

4be8791

make logary build success, then run some test for making progress

c9744b7

focus on logary and logary.tests project first

307ad64

prepare for testing logary,ensure it can work mostly,then focus on breaking changes in other prjects.

add test for Message

ed621f9

lust4life merged commit baa1853 into causiq:feature/live-wpc-reconfigure Nov 6, 2017

lust4life deleted the feature/live-wpc-reconfigure branch November 6, 2017 19:18

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

WIP: Feature/live wpc reconfigure #263

WIP: Feature/live wpc reconfigure #263

lust4life commented Aug 4, 2017 •

edited

Loading

lust4life commented Aug 5, 2017

haf Aug 7, 2017

lust4life Aug 14, 2017

haf Aug 7, 2017

lust4life Aug 14, 2017

haf Aug 7, 2017

haf Aug 7, 2017

haf Aug 7, 2017

haf commented Aug 7, 2017 •

edited

Loading

lust4life commented Aug 18, 2017

haf commented Aug 18, 2017 •

edited

Loading

lust4life commented Aug 18, 2017

lust4life commented Aug 22, 2017

lust4life commented Aug 31, 2017 •

edited

Loading

haf commented Aug 31, 2017

lust4life commented Aug 31, 2017

haf commented Sep 3, 2017 •

edited

Loading

lust4life commented Sep 4, 2017 •

edited

Loading

lust4life commented Sep 5, 2017

lust4life commented Sep 5, 2017 •

edited

Loading

lust4life commented Sep 11, 2017

haf commented Sep 11, 2017

lust4life commented Sep 11, 2017 •

edited

Loading

lust4life commented Sep 11, 2017

haf commented Sep 11, 2017

lust4life commented Sep 12, 2017

lust4life commented Sep 12, 2017

lust4life commented Sep 23, 2017

haf commented Oct 1, 2017

lust4life commented Oct 10, 2017

lust4life commented Oct 15, 2017

lust4life commented Nov 6, 2017 •

edited

Loading

WIP: Feature/live wpc reconfigure #263

WIP: Feature/live wpc reconfigure #263

Conversation

lust4life commented Aug 4, 2017 • edited Loading

lust4life commented Aug 5, 2017

haf Aug 7, 2017

Choose a reason for hiding this comment

lust4life Aug 14, 2017

Choose a reason for hiding this comment

haf Aug 7, 2017

Choose a reason for hiding this comment

lust4life Aug 14, 2017

Choose a reason for hiding this comment

haf Aug 7, 2017

Choose a reason for hiding this comment

haf Aug 7, 2017

Choose a reason for hiding this comment

haf Aug 7, 2017

Choose a reason for hiding this comment

haf commented Aug 7, 2017 • edited Loading

lust4life commented Aug 18, 2017

haf commented Aug 18, 2017 • edited Loading

lust4life commented Aug 18, 2017

lust4life commented Aug 22, 2017

lust4life commented Aug 31, 2017 • edited Loading

haf commented Aug 31, 2017

lust4life commented Aug 31, 2017

haf commented Sep 3, 2017 • edited Loading

lust4life commented Sep 4, 2017 • edited Loading

lust4life commented Sep 5, 2017

lust4life commented Sep 5, 2017 • edited Loading

lust4life commented Sep 11, 2017

haf commented Sep 11, 2017

lust4life commented Sep 11, 2017 • edited Loading

lust4life commented Sep 11, 2017

haf commented Sep 11, 2017

lust4life commented Sep 12, 2017

lust4life commented Sep 12, 2017

lust4life commented Sep 23, 2017

haf commented Oct 1, 2017

lust4life commented Oct 10, 2017

lust4life commented Oct 15, 2017

lust4life commented Nov 6, 2017 • edited Loading

lust4life commented Aug 4, 2017 •

edited

Loading

haf commented Aug 7, 2017 •

edited

Loading

haf commented Aug 18, 2017 •

edited

Loading

lust4life commented Aug 31, 2017 •

edited

Loading

haf commented Sep 3, 2017 •

edited

Loading

lust4life commented Sep 4, 2017 •

edited

Loading

lust4life commented Sep 5, 2017 •

edited

Loading

lust4life commented Sep 11, 2017 •

edited

Loading

lust4life commented Nov 6, 2017 •

edited

Loading