profile middleware

[tj]

just a reminder to myself: use compose hook to create a profiler layer that will report durations spend in each layer

[tj]

some jstrace probes + scripts would be betta

[tj]

also statsd stuff would be cool as well

[jonathanong]

how about something like .log('some.event', obj), then have something like app.trace(fn*) middleware that hook on these events? instead of wrapping all the middleware, which probably won't give us exactly what we want, we could have middleware log themselves and have devs decide how to store it. now all middleware would implement these, which would be nice, though maybe noisy if they log too much shit.

only issue i can think of is that some loggers like statds have special commands like .increment() and stuff, which would hard to abstract.

[hallas]

I like the idea of not imposing a trace into the middleware (by like wrapping them) but instead let the middleware opt-in kind of

[tj]

i think it's a lot to impose on every middleware, we would have to have start/end calls etc if we can't wrap :( emitting some stuff in koa-compose would be ok but sort of ugly. hooking into it at the koa-compose level is really weird, then it doesn't really become a first-class feature, and various libs could use the wrong version of koa-compose etc

[jonathanong]

well you don't want every middleware to trace stuff. that would get too noisy. just the important ones. which is why i prefer something like .log() where you only log the important stuff and have the devs filter out the logs themselves via loggers or something.

[tj]

sometimes you do, the general use-case for me is to see where middleware are a) stuck or b) slow. As far as generic tracing goes accepting jstrace is fine. with a log method people would have to do:

function *(next){
  this.log('static:start')
  if (!something) return this.log('static:stop'), yield next;
  ....
  this.log('static:stop')

contrived example but it's too much stuff

[jonathanong]

oh i've never seen middleware stuck. lol. it's too much stuff if you put them everywhere, but i don't think you need to put them everywhere. ex, logging the response time middleware.

main thing for me is that it's easier than implementing wrapping and potentially more powerful since you can do more than just "start" and "stop". ex. i want to log how long it takes to parse a body

[tj]

I sure have haha, it's really difficult to debug without some kind of middleware-level tracing, but then it's easy.

yeah for sure, but that's a different concern all together, jstrace/statsd/loggers are better for that sort of thing, this wrapping stuff is pretty much exclusively for seeing how middleware manipulate the request/response, and profiling them

[jonathanong]

yeah i'm just thinking of a more generic solution. here's what i'm thinking right now:

function compose(middleware){
  return function *(next){
    var i = middleware.length;
    var prev = next || noop();
    var curr;

    while (i--) {
      curr = middleware[i];
      // wrap `next`s in logs
      prev = curr.call(this, wrap(this, curr, prev, prev._name || prev.name || 'anonymous'));
    }

    yield *prev;

    function* wrap(ctx, curr, prev, name) {
      ctx.log('koa-compose:start:' + name);
      yield* curr.call(ctx, prev);
      ctx.log('koa-compose:end:' + name);
    }
  }
}

app.with = function (logger) {
  // hook into `.log()`s
}

// do some useful version of debug statements in non-production environments
app.debug = function () {
  app.with(function (event, ctx, date, args...) {
    // add some useful context properties maybe
    ctx.id = ctx.id || uid(24);
    ctx.start = ctx.start || Date.now();
    debug(event + ':' + ctx.id)(Date.now() - ctx.start);
  })
}
if (process.env.NODE_ENV !== 'production') app.debug();

way easier and more extensible than middleware of middleware ;D

[tj]

that's more or less what my wrapping branch does, except there's no reason to have .log() or events

[jonathanong]

similarly, i don't see the need to limit it only to when the middleware starts and ends. i'm not sure how your branch works now, but i'd like to hook into these events outside of debug

[tj]

I think we're conflating two different issues. one is logging/tracing generic stuff, one is profiling/debugging middleware. I'm not against having a .log() or a .trace() potentially since it does increase observability but the wrapping of middleware is a different thing all together (but could use .trace like you say)

[jonathanong]

ya i'm just trying to somewhat combine them because i don't see how they are totally different.

[jonathanong]

let's just solve this once in for all in koa-compose. how about something like this:

function compose(middleware, profiler){
  return function *(next){
    if (!next) next = noop();

    var i = middleware.length;

    while (i--) {
      var fn = middleware[i]
      var profile = profiler(fn)
      next = function *(next) {
        profile.start()
        try {
          yield fn.call(this, next)
        } finally {
          profile.end()
        }
      }.call(this)
    }

    return yield *next;
  }
}

not exactly how it'll be implemented (especially because we need to wrap the profile in a closure) but the that's the API of profiler

[jeromew]

(Replying to https://github.com/koajs/koa/issues/196#issuecomment-192083703)

What I would like to do with profiling is to have a way to profile whole koa application, even if I am using middlewares that have already been composed in other libraries. In production, you never know where a bottleneck is going to come from so a view on other modules would be a +.

the profiling system should also have close to no impact in production if profiling is not activated.

The way I see it (I have no implementation and am not sure if it makes sense) would be something like the debug module.

a module exporting middlewares could have a profiling name a-la debug.

Then at runtime via 2 environment variables, I could

• choose by name which middlewares I want to profile
• define which profiler I want to use

I don't know if this makes sense to you.

Regarding the modification of koa-compose, I once proposed that we should be able to define our own composer (use koa-compose if you want no profiling, use `koa-compose-myprofiler' to have the behavior of myprofiler.

Adding the profiler variable directly to koa-compose adds some of this behavior but :

• there is a systematic perf hit on the profiler mechanism even if I want no profiling
• I don't see how I could profile third-party koa middlewares modules

Regarding the API, I proposed something in https://github.com/koajs/koa/issues/196#issuecomment-61021512 (maybe the code is not very clear). Basically, the idea to compose middleware was to

• first map the middlewarearray to myprofiler(middleware[i])

    var myprofiler = function(fn) {
       return function*(next){
         // things to do before
         yield *fn.call(this, next);
         // things to do after
      }
    }

• and then call compose on this new array

The difference I see is that you version is synchronous (there is no way to wait on profile.start() and profile.end())

The API should probably give the user the choice of sync vs async.

• I could see a usage for a "step by step" profiler/debugger where I need to click "next" at every stage.
• I could also see scenarios where I could want to make sure something is logged before going to the next step even if it at a perf cost

But those scenarios are maybe far-fetched and I can live without them now.

Do we have some kind of list of applications that will be done with this profile mechanism / real world scenarios ? Do you know how the express, hapi or restify community handles profiling ?

I have heard (but never tried to confirm) that restify has done a good job for profiling via its DTrace probes - http://restify.com/#dtrace . Maybe that could be something to explore too.

[PlasmaPower]

:+1: on that API. Wrapping the middleware seems like the best way to provide opportunities to profile it. In addition, there would be no need to check if there are profilers every time a request is received.

[jonathanong]

oh yeah, no problem making the profiler async.

i don't think we want to integrate any specific tracing because there are just so many of them.

@jeromew would you like to make a PR to koa-compose? i think we're on the same page

[jonathanong]

though i'm not sure about the "choosing middleware by name" part. you could just use debug in the profiler as the profiler should receive the fn as an argument

[fl0w]

What about having a app.profiler available, which Application.callback() passes when composeing?

koajs/compose/index.js (next)

function compose (middleware, profiler) {
  if (!Array.isArray(middleware)) throw new TypeError('Middleware stack must be an array!')
  if (profiler && typeof profiler !== 'function') throw new TypeError('Profiler needs be a function!')
  for (const fn of middleware) {
    if (typeof fn !== 'function') throw new TypeError('Middleware must be composed of functions!')
  }

  return function (context, next) {
    // last called middleware #
    let index = -1
    return dispatch(0)
    function dispatch (i) {
      if (i <= index) return Promise.reject(new Error('next() called multiple times'))
      index = i
      let fn
      if (profiler) fn = middleware[i] ? profiler(middleware[i]) : next
      else fn = middleware[i] || next
      if (!fn) return Promise.resolve()
      try {
        return Promise.resolve(fn(context, function next () {
          return dispatch(i + 1)
        }))
      } catch (err) {
        return Promise.reject(err)
      }
    }
  }
}

koajs/koa/lib/application.js#callback (v2.x)

callback() {
  const fn = compose(this.middleware, this.profiler);
  // ... rest
}

example.js

app.profiler = function(fn) {
  return (ctx, next) => {
    const start = process.hrtime()[1]
    console.log(fn.name + ' > ' + start)
    return Promise.resolve(fn(ctx, next)).then(() => {
      const end = process.hrtime()[1] - start
      console.log(fn.name + ' < ' + end + ' (' + end/1000000 + ')')
    })    
  }
}

app.use((ctx, next) => {
  console.log('start a')
  return next().then(() => {
    console.log('end of a')
  })
})

app.use((ctx, next) => {
  console.log('start b')
  return next().then(() => {
    console.log('end of b')
  })
})

app.use((ctx, next) => {
  console.log('start c')
  return next().then(() => {
    console.log('end of c')
  })
})

app.use((ctx, next) => {
  ctx.body = 'hello world'
})

[PlasmaPower]

@fl0w I like the idea, I think that was the API discussed above. However, I'd prefer if it was called something more general than profiler, as the API isn't profiler specific. We should also consider if it should be an array, or just a single function.

[jeromew]

@fl0w I think this is in line with what we are discussing (for the promise based version) but I don't know if we want a compulsory "everything-is-profiled" approach.

@jonathanong I haven't tried to push a PR because I am working on other subjects right now and even though this feature has been long standing I do not want to rush it in koa. profiling is a key feature for a mature framework and I think that options should be compared on real life scenarios - at least performance wise since wrapping every middleware is not a cheap operation.

As I see it profiling can already be done by somebody who accepts to wrap all its middlewares

app.use(wrap(mw1))
app.use(wrap(mw2))
app.use(wrap(mw3))

For logging purpose, I try to give names the middlewares

sometimes, I pre-compose middlewares like app.use(compose(mws)). This could be replaced by

app.use(composewrapper(mws, logger, "myname"))

which would compose a logger version of all the mws and give the name "myname" to the resulting middleware.

This gets burdensome at some point + there are probably subtleties when dealing with middlewares coming from other npm modules, or middlewares created/composed at runtime in specific branches inside a middleware.

What I would want is :

• to be able to profile all the middlewares in an application or specific parts of an application ; maybe have a guideline for external modules so that they can become profileable.
• with a clean API that would avoid the need to wrap every single middleware.
• the profiler should be able to output an clear view of the middleware chain that the request went through

Is there already a big user-facing open source projet that use koa (like ghost or nodebb) that we could use as a testbed an say "let's add profiling to this project" to help it see what are the bottlenecks in the application ?

[fl0w]

@PlasmaPower I agree, I used the term profiler for illustration-purposes. I think I agree the act of "wrapping" or "wrap" is more appropriate as you and @jeromew highlight.

@jeromew I think your cases are entirely possible with the proposition, but instead of hard-coding a "one size fits all"-solution, just delegate it to user space.

You could just have a wrap-mw that simulates what debug does, which listens to desired env. E.g. process.env.PROFILE=my:personal*.

One could also just not use the Koa provided app.profiler, instead opt to compose manually

app.wrap = false // default
app.use(compose(['my', 'middleware', 'stack', 'im', 'interested', 'in'], aProfilerIMade)

If I had some specific use cases or desires, I wouldn't expect Koa to solve app-specific probe:ing anyway.

[jonathanong]

@PlasmaPower @fl0w @jeromew sorry for not being more active. been a little busy. there's a bunch of PRs open that I haven't really looked into. here are my questions, and as long as we have a consensus on these, we should write them down somewhere in the docs and have tests for them. then, it is about implementation details, of which i prefer the simplest solution.

• should mounted apps/routers wrap their middleware too?
  • for example, app.use(router) or app.use(anotherApp)
  • how do you handle apps with wrappers mounted onto another app with wrappers? parent app wrappers wrap the child app wrappers?
• should every "decorator" be wrapped as well?
  • for example, koa-route wraps another middleware as an if-statement. should the koa-route decorator be wrapped as well the actual middleware being decorated? this allows you to debug that the routing logic was executed, but not the main logic
  • this could be chosen on a per-middleware basis (implementatiors will decide). we would then need some exposed function like app.wrap() or this.wrap() to make this easy for every middleware. or have middleware require a 3rd party module that calls the wrapped function

implementation questions (less important):

• should we store the wrappers on app or on context? @PlasmaPower has convinced me that only having it on app would make routers more difficult since you would need to pass app to every middleware. maybe app.wrappers and have ctx.wrappers delegate to it?
• should we wrap the last middleware (response)?

@koajs anyone else have questions? if someone wants to start a gist about the specs, that would be great

[PlasmaPower]

should mounted apps/routers wrap their middleware too?

I think everybody is assuming that yes, they should. This would be the same way as compose handles it.

how do you handle apps with wrappers mounted onto another app with wrappers? parent app wrappers wrap the child app wrappers?

I'd assume the child wrappers would get applied first, then the parent wrappers. However, I don't think you can currently mount a Koa app with use(), correct?

should every "decorator" be wrapped as well?

Yes, I think this makes the most sense and would allow for profilers to create a nice tree.

we would then need some exposed function like app.wrap() or this.wrap() to make this easy for every middleware

My newest PR implements this as app.prepareMiddleware (it also does some other stuff, hence the name). My older PR has this as it's own library.

should we store the wrappers on app or on context?

Most implementations store them in the context, but with mw._wrappers or mw.onUsed (the two most recent PRs) they can be stored in the app.

should we wrap the last middleware (response)?

I don't think any PRs currently do that, but I think we could (at least with my most recent PR, haven't checked the others). If we decide to do that, I can easily change my PR.

[jonathanong]

it seems like i'm the only collaborator really involved in this, and it's not something i want to be decide on alone.

@PlasmaPower thanks for your hardwork. do you want to try making this a separate module first that augments a koa app? we can add it to the org

[fl0w]

Out of curiosity, would a wrapper be a middleware or a function returning a wrapped middleware? I'm so confused at this point I'm stalled.

[PlasmaPower]

@fl0w A function returning a wrapped middleware. For example, here's an extremely simple profiler:

let wrapper = function (mw) {
  return function (ctx, next) {
     console.time('mw');
     return Promise.resolve().then(mw.bind(undefined, [ctx, next]).then(() => console.timeEnd('mw');
   };
};

Edit: pretty sure console.time might not work with multiple middleware, but you get the point.

[jonathanong]

they decorate middleware. all the wrappers will decorate all the middleware.

[fl0w]

@PlasmaPower @jonathanong Right, so that's equivalent to the very very first example I did. So what's the negative about assigning the wrappers to mw._wrappers and let compose reduce by those if provided?

[PlasmaPower]

@fl0w Because compose doesn't reduce - with compose wrappers would just be middleware that ran before every middleware.

[RobertHerhold]

This would be a really handy feature to have. Are there any plans to continue this?

[fl0w]

@RobertHerhold There's been so much bikesheeding at this point I'm not sure. Even then, I'm personally getting a feeling that composing middleware at large through Koa is sort of useless since async-await. It's an anti-pattern as far as I'm concerned. I don't see any benefit (except for current statue quo mw ecosystem) over just having a single mw and calling whatever feature with await, e.g.

const myAppMiddleware = async (ctx, next) => {
  await middlewareOne(ctx)
  await middlewareTwo(ctx)
  if (logic) {
    await myRouter(ctx)
  }
  ...
}

At which point it's easy to just profile in between, or wrap, each call with whatever profiler poison you choose. They're all just mutating and using ctx anyway. I do see the benefit, however. Such as parallelism (if some mw do IO), less clutter in stack (no extra wrapping with promises), and just generally not needing compose for Koa :).

edit Woah, when I originally answered this I thought this was an issue in koajs/compose. Appologies.

[joemckie]

For anyone interested, I just released a package that does exactly this. It works via dependency injection, so you can pass in your own logging function, if you happen to use something like winston.

https://www.npmjs.com/package/koa-profiler-middleware

[fl0w]

@joemckie that doesn't profile a middleware, it simply counts how long the full request takes.

Equivalent to e.g.

app.use(async (ctx, next) => {
  const start = process.hrtime.bigint()
  await next()
  const end = process.hrtime.bigint()
  console.log(`Request took ${end - start} nanoseconds`)
})

... or https://github.com/koajs/response-time

[joemckie]

@fl0w yep you're right, completely misread this thread 🤦‍♂

[jonathanong]

closing this, better to just profile each async function