-
-
Notifications
You must be signed in to change notification settings - Fork 3.2k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
profile middleware #219
Comments
some jstrace probes + scripts would be betta |
also statsd stuff would be cool as well |
how about something like only issue i can think of is that some loggers like statds have special commands like |
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 |
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 |
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 |
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 |
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 |
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 |
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 |
that's more or less what my wrapping branch does, except there's no reason to have .log() or events |
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 |
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 |
ya i'm just trying to somewhat combine them because i don't see how they are totally different. |
let's just solve this once in for all in 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 |
(Replying to #196 (comment)) 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 a module exporting middlewares could have a profiling name a-la debug. Then at runtime via 2 environment variables, I could
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 Adding the
Regarding the API, I proposed something in #196 (comment) (maybe the code is not very clear). Basically, the idea to compose
var myprofiler = function(fn) {
return function*(next){
// things to do before
yield *fn.call(this, next);
// things to do after
}
}
The difference I see is that you version is synchronous (there is no way to wait on The API should probably give the user the choice of sync vs async.
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:https://restify.com/#dtrace . Maybe that could be something to explore too. |
👍 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. |
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 |
though i'm not sure about the "choosing middleware by name" part. you could just use |
What about having a 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'
}) |
@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. |
@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
For logging purpose, I try to give names the middlewares sometimes, I pre-compose middlewares like
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 :
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 ? |
@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. One could also just not use the Koa provided 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. |
@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.
implementation questions (less important):
@koajs anyone else have questions? if someone wants to start a gist about the specs, that would be great |
I think everybody is assuming that yes, they should. This would be the same way as compose handles it.
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?
Yes, I think this makes the most sense and would allow for profilers to create a nice tree.
My newest PR implements this as
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.
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. |
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 |
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. |
@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. |
they decorate middleware. all the wrappers will decorate all the middleware. |
@PlasmaPower @jonathanong Right, so that's equivalent to the very very first example I did. |
@fl0w Because compose doesn't reduce - with compose wrappers would just be middleware that ran before every middleware. |
This would be a really handy feature to have. Are there any plans to continue this? |
@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. |
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. |
@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`)
}) |
@fl0w yep you're right, completely misread this thread 🤦♂ |
just a reminder to myself: use compose hook to create a profiler layer that will report durations spend in each layer
The text was updated successfully, but these errors were encountered: