Add AOP-based spring method timing metrics, servlet filter for path-based metrics. #168
Conversation
andrewstuart
force-pushed
the
aop-filter
branch
4 times, most recently
from
eaf6b19 to
d3eaa76
Compare
brian-brazil
left a comment
brian-brazil
left a comment
There was a problem hiding this comment.
These are good features to have.
I'm not up enough on spring and spring boot to know if this should be a separate module. Based on your comments I'm guessing it should be.
There was a problem hiding this comment.
Inline this.
The word "seconds" should appear in the name
There was a problem hiding this comment.
This is 3 levels of indirection to find the value, please simplify.
There was a problem hiding this comment.
You'll notice in my updated PR that this is still not final, but that it's now being initialized in the init method. That was my original intent, and forgot to finalize when I temporarily moved it back out of init.
Let me know if there's a better solution that I'm not thinking of.
There was a problem hiding this comment.
Having it all in one place like you're doing now is best. It's very odd to have a metric definition spread around the place.
There was a problem hiding this comment.
servletLatency can't be null
There was a problem hiding this comment.
It's usually method rather than verb.
There was a problem hiding this comment.
Also just noticed some copypasta: "uportal" is not relevant here.
There was a problem hiding this comment.
I was wondering about that one
There was a problem hiding this comment.
Formatting is off here
There was a problem hiding this comment.
Inline, should contain the word "seconds"
There was a problem hiding this comment.
There could be rather a lot of these, I'd go with a quantileless summary by default.
There was a problem hiding this comment.
It may be better if the user provided a metric name for each use
There was a problem hiding this comment.
Please revert the formatting changes here, they're only adding noise to the PR
|
Okay, I think I've addressed most of your comments and added a few features, as well as repackaging the spring-web annotations to their own package to avoid the spring boot dependencies. Let me know if you have any other suggestions (especially around my use of HashMap in the MethodTimer class for tracking user-specified metric names). |
There was a problem hiding this comment.
why not using request.getServletPath() or request.getPathInfo() if first is empty. You don't want the full uri in the metrics
There was a problem hiding this comment.
getRequestURI is only the path, but always includes the whole path and doesn't omit the servlet context path. It's not the proper URI in the RFC3986 sense. See the example table in the docs. 😄
I did try the methods you suggest, and ended up landing on getRequestURI() as it provides the most helpful fully-contextual info from just looking at the labels in a dashboard.
There was a problem hiding this comment.
I have a similar filter that I'm using that does the following:
String handlerUrl = (String) req.getAttribute(HandlerMapping.BEST_MATCHING_PATTERN_ATTRIBUTE);
if(handlerUrl == null){
handlerUrl = req.getRequestURI();
}
This way the URI matches the RequestMapping definition that was chosen. Unfortunately it means you would have to look it up after calling doFilter and allowing Spring to add the attribute.
It also will allow you to avoid the path components/matching approach.
There was a problem hiding this comment.
This whole block need to be thread safe
There was a problem hiding this comment.
Good catch. I swapped out HashMap for ConcurrentHashMap.
There was a problem hiding this comment.
ConcurentHashMap only will not do, it handle only concurent atomic operation. You can end up creating 2 metrics. The only way is to use a syncronize block or using a Lock. Personal I would extract the if in a synchronized method returning the summary and with that you can keepthe original HashMap.
There was a problem hiding this comment.
Alright, I updated this with a ReentrantReadWriteLock since 99% of the time we will probably only be reading the map and this will offer proper multithreaded access for those cases and thus keep this from becoming a bottleneck.
Double (or triple) check my implementation, though, since I'd rather not be introducing deadlocks.
There was a problem hiding this comment.
My experience was that without this annotation, Spring ignored the @PrometheusMethodTiming annotation anywhere inside controllers. This annotation enabled that, which to me is the most applicable use case for high-level monitoring.
There was a problem hiding this comment.
Are you sure about this?
There was a problem hiding this comment.
Having it all in one place like you're doing now is best. It's very odd to have a metric definition spread around the place.
There was a problem hiding this comment.
Inline this.
The prometheus_ prefix implies this is a metric of the prometheus server
There was a problem hiding this comment.
Can you make the value the actual Summary?
You don't want something like a hashmap or mutex on this codepath, they're relatively slow.
There was a problem hiding this comment.
What would you think about making that optional and a recommended best practice?
My preference would be toward making instrumentation dead simple to get started with (and increase the positive feedback loop to encourage users onward), while still making it easy to supply your own Summary where performance is desired.
There was a problem hiding this comment.
I mean that you store the Summary as part of the annotation automatically. ConcurrentHashMaps and mutexes are slow, you don't want those as a default.
There was a problem hiding this comment.
I guess I'll have to read up on Spring AOP a little more. My understanding was that it's typically a singleton handling the methods, but it appears there can be advice instances. Any specific suggestions on implementation there?
There was a problem hiding this comment.
I've never implemented one of these
There was a problem hiding this comment.
The suggestion was that the name is required, not optional
There was a problem hiding this comment.
If you have the name being unique, then you don't need this label.
There was a problem hiding this comment.
If it's a class being annotated, we still need to differentiate between each method within the class. My goal in that design choice is that users can still get granular instrumentation without having to annotate each method individually.
There was a problem hiding this comment.
That's tending towards profiling more than metrics, what sort of metric volume are you thinking here?
There was a problem hiding this comment.
Well, for one, if it's performant enough I don't see why profiling in production would be a bad thing. Getting that level of visibility into your application's real performance, and the ability to drill down, seems like a win. But that said, my goal was really just to make it easy to set up whatever level of granularity users want, and still provide meaningful output.
In my use case, it's great to have whole spring @Controller and @Service classes annotated and get metrics on individual method performance, at least at those levels.
There was a problem hiding this comment.
It's incorrect to have a default here, as if there's multiple uses that'll throw and exception and semantically each use would mean something different.
There was a problem hiding this comment.
Are you sure this should be static? There's going to be more than one of these
There was a problem hiding this comment.
Right, good point.
There was a problem hiding this comment.
What is the purpose of pathComponents actually? Is it to find the prefix of path which would be used for metrics?
E.g. If in my applications I have paths like
/foo/bar/baz/aaa
/foo/bar/baz/bbb
/some
/other
and pathComponents==3.
Then we'll only count following:
/foo/bar/baz
/some
/other
that means first two paths are considered to be the same? Or did I get it wrong and this is something completely different?
Could you maybe move this logic into some tiny separate component (something like inteface PathMetricName { String metricName(String path);}?
In my application I'm not sure I can say that I can pick one pathComponents for all URLs, I may need to handle them in more complex way. The other benefit is that the filter does not have to deal with prefix calculation, making it bit simpler... The default implementation still can do what filter does now (taking first pathComponents).
There was a problem hiding this comment.
The reason for pathComponents is to allow easy limiting of the number of TimeSeries metrics being tracked, which reduces performance impact for queries at the expense of metric resolution. Thinking about it, though, 3 is a silly default. I've updated the default to simply track the full path.
Yeah, I could add a request matcher parameter that can be set, but I'd prefer to get at least something out there before I tack on more complexity.
|
Okay, I think this is ready for another review. There's still some thread safety I had to address, but after the first method call or two it will be read only, and so there's only the potential for thread blocking on the first few calls. The Aspect is now instantiated per target (per Let me know what you think. |
There was a problem hiding this comment.
I'm not fully sure this is safe
There was a problem hiding this comment.
If possible we should be caching the result of the labels(). Looking up a concurrent hashmap is relatively slow.
There was a problem hiding this comment.
I was talking to a user who had their devs instrumenting all functions and using Prometheus effectively for profiling, causing performance issues. Thus I think it'd be wisest to stick just with method annotations rather than class annotations.
There was a problem hiding this comment.
So were they seeing performance issues in the application itself, due to Prometheus overhead? I guess I was assuming that the metrics overhead (for metrics instances themselves) was pretty negligible compared to the methods being profiled.
I think my main concern is that the primary point of the annotation approach is ease of use, and I'm not sure we do much more than annoy users and force more typing if they really want to annotate every method of a class. If they do want to, they'll still just use the annotation on every method, which just forces them to type more and come up with more help phrases and metric names, and then make sure they maintain the code any time new methods are added in case they want those methods profiled too.
Honestly, I'm not firmly set on allowing class annotations, but to me it feels like the better experience, as long as it goes with the warning that "hey, use metrics sparingly," which seems like it applies regardless of whether the metrics were created with annotations, or by adding all the requisite code themselves.
Thoughts?
There was a problem hiding this comment.
So were they seeing performance issues in the application itself, due to Prometheus overhead?
That wasn't reported to me, but I presume not. Though with this level of instrumentation there's likely an inner loop somewhere where it'd cause a problem.
like the better experience, as long as it goes with the warning that "hey, use metrics sparingly," which seems like it applies regardless of whether the metrics were created with annotations, or by adding all the requisite code themselves.
The problem is that metrics are basically free, as long as you don't use them in an industrial fashion. Class level annotations tip the scales for me where it's too easy to run yourself into problems.
If you really want per-function data for every single function, that's more the job for a profiling tool than a metrics one.
There was a problem hiding this comment.
You know, somehow it hadn't really occurred to me that class methods would be calling each other in the same class, within loops, recursively, etc. I'm too used to languages like Go or JavaScript where methods tend to call functions not associated with an instance.
So yeah, per-method granularity makes a lot more sense.
That should make things a lot more performant too, since as you mentioned, we can cache the child and avoid a lookup.
There was a problem hiding this comment.
Not true in Spring AOP, method calling each other in the same class is ignored by aop. Aop is a proxy based stuff.
see https://docs.spring.io/spring/docs/current/spring-framework-reference/html/aop.html#aop-understanding-aop-proxies.
note: it could work with cglib base proxy but i never tested it myself
simpleclient_servlet/pom.xml
Outdated
There was a problem hiding this comment.
Put this above the test deps
There was a problem hiding this comment.
This is updated; not sure why GitHub hasn't shown the change.
There was a problem hiding this comment.
Put brackets around that comparison to make it easier to read
There was a problem hiding this comment.
Can you provide an example usage here, and in the README.md?
There was a problem hiding this comment.
Yeah, no problem. The root README, or create a new README in the simpleclient_servlet package?
There was a problem hiding this comment.
The root README.
The others should have examples too.
There was a problem hiding this comment.
Looks like I was a bit behind master, so I'm rebasing. I'll add the examples there as well.
simpleclient_spring_boot/pom.xml
Outdated
There was a problem hiding this comment.
I'd prefer to stick with the older version to be sure we maintain backwards-compatibility.
There was a problem hiding this comment.
extra space here after the =
There was a problem hiding this comment.
Please remove the debug code.
There was a problem hiding this comment.
No labels is special cased already inside the metric, so you can use the metric normally.
|
With the new change to
|
andrewstuart
force-pushed
the
aop-filter
branch
from
96316e8 to
683cffe
Compare
|
Alright, I have that issue fixed (by adding Is that something you'd definitely want to have before merging? |
|
This stuff is not something I have experience with, so tests to prevent accidental breakage with would be good. |
There was a problem hiding this comment.
I have a similar filter that I'm using that does the following:
String handlerUrl = (String) req.getAttribute(HandlerMapping.BEST_MATCHING_PATTERN_ATTRIBUTE);
if(handlerUrl == null){
handlerUrl = req.getRequestURI();
}
This way the URI matches the RequestMapping definition that was chosen. Unfortunately it means you would have to look it up after calling doFilter and allowing Spring to add the attribute.
It also will allow you to avoid the path components/matching approach.
There was a problem hiding this comment.
Please add a constructor that allows passing in any items used in the FilterConfig. This allows services using Spring Java Config to add a filter to be able to use compile time checks to provide useful values.
andrewstuart
force-pushed
the
aop-filter
branch
from
27bfc32 to
4387ffc
Compare
|
In an attempt to get below the 100ns barrier (or at least eliminate blocking reads in multi-thread situations), I went with a ReentrantReadWriteLock since 99.9% of the time we should be reading. We only need to actually write on the first time we hit a method that hasn't been called before, so the extra time taken for the lock call should be worth it in the long run since now multiple threads can access the map for reading at the same time. I'd really like to look at optimizing this out completely if there's a way to just do all the work at instantiation time and stuff things into a completely immutable map so we can just drop synchronization. Based on my research that would probably get us down to around the ~30ns average access time. Until I can get a little more time to look into how I might do that, though, I figured this was a good first pass at least. |
brian-brazil
left a comment
brian-brazil
left a comment
There was a problem hiding this comment.
The README needs updating.
| } | ||
|
|
||
| private Summary ensureSummary(ProceedingJoinPoint pjp, String key) throws IllegalStateException { | ||
| // Only one thread may get here, since this method is synchronized |
There was a problem hiding this comment.
Be consistent, have a period at the end of all your comments.
| } | ||
|
|
||
| private Summary ensureSummary(ProceedingJoinPoint pjp, String key) throws IllegalStateException { | ||
| // Only one thread may get here, since this method is synchronized |
There was a problem hiding this comment.
This method isn't synchronized
| .help(annot.help()) | ||
| .register(); | ||
|
|
||
| // Even a rehash will |
There was a problem hiding this comment.
This comment seems incomplete
| import java.lang.annotation.Target; | ||
|
|
||
| /** | ||
| * Enable Spring-AOP-based automated method timing for the annotated method or all methods in an annotated class. |
There was a problem hiding this comment.
it's just the annotated method now
| void aSecondMethod() throws Exception; | ||
| } | ||
|
|
||
| // @PrometheusTimeMethod(name = "test_two", help = "help two") |
There was a problem hiding this comment.
Don't leave commented out code lying about
| .name(annot.name()) | ||
| .help(annot.help()) | ||
| .register(); | ||
| .register();f |
| summary = Summary.build() | ||
| .name(annot.name()) | ||
| .help(annot.help()) | ||
| .register();f |
There was a problem hiding this comment.
Argh. IntelliJ autosave...
README.md
Outdated
| @Controller | ||
| public class MyController { | ||
| @RequestMapping("/") | ||
| @PrometheusTimeMethod(name = "main_path_seconds", help = "Some helpful info here") |
There was a problem hiding this comment.
Per a discussion over in the ruby client, duration_seconds is what we're doing with convention-wise.
| package io.prometheus.client.filter; | ||
|
|
||
| import io.prometheus.client.Histogram; | ||
| import org.apache.commons.lang3.StringUtils; |
There was a problem hiding this comment.
simpleclient_servlet is for exposing metrics to Prometheus, it shouldn't be pulling in something like apache commons.
This probably belongs in a separate module.
There was a problem hiding this comment.
I can definitely see not wanting to pull in Apache commons. I only needed two functions from there, and I can easily write/pull in both for our use cases.
As far as location, I'm not sure where else it would go. It's a simple servlet metrics filter that has all the same dependencies as the servlet exporter filter, except that I've pulled in Mockito for testing.
Let me know if there is a better place and I can try to update that.
There was a problem hiding this comment.
If we can avoid the dep then it can stay here, we'll just need to be clear in the readme where this comes from.
The other consideration is that we'd want a fairly new jetty for the servlet in order to fix whatever bugs/issues there are, however for instrumentation we'd want to have as old a jetty as practical to ensure we're not unintentionally using new features that users stuck on an old version wouldn't have. Try and find a good old stable version I guess.
|
I just noticed that this is touching simpleclient_servlet (after, uhm, 3 months), I had thought this was just a Spring-related PR. That'll need some care, as we can't be pulling in unnecessary deps there, as it's the "default" way users expose Prometheus metrics and we don't want to drop them in dependency hell. |
|
Yeah, I think that was there since the beginning but I forgot about it when I was titling the PR. At this point there should be no dependencies added in the simpleclient_servlet package apart from Mockito for testing, so hopefully that's acceptable there. :-) Let me know if I'm forgetting anything else. |
README.md
Outdated
| is, all reqeusts with greater than N "/" characters in the servlet URI path will | ||
| be measured in the same bucket and you will lose that granularity. | ||
|
|
||
| Example XML config: |
There was a problem hiding this comment.
It'd help if you tell the use where to place this
README.md
Outdated
| </init-param> | ||
| <init-param> | ||
| <param-name>buckets</param-name> | ||
| <param-value>.001,.002,.005,.010,.020,.040,.080,.120,.200</param-value> |
There was a problem hiding this comment.
Stick with the default buckets in examples
README.md
Outdated
| </init-param> | ||
| <init-param> | ||
| <param-name>path-components</param-name> | ||
| <param-value>5</param-value> |
There was a problem hiding this comment.
As this is a histogram which already has a cardinality of 10, we should limit this down to one component to be on the safe side.
README.md
Outdated
| SessionFactory sessionFactory = entityManagerFactory.unwrap(SessionFactory.class); | ||
| ``` | ||
|
|
||
| ### Servlet Filter |
There was a problem hiding this comment.
This should have another #
And below too.
|
Thanks! There's a few minor style nits, but this review has taken long enough. |
5 participants
I'm not entirely certain that the spring_boot module is the best place for the AOP annotation, since it should work fine in any other spring application, where users may not want to import all the baggage that spring boot will drag along with it, but I thought I'd get this PR submitted at least, and get input on where that belongs.
/cc: @beorn7 / @brian-brazil