[PATCH] Enhancements to TraceInterceptor [SPR-860] #5586
Comments
|
Matthew Sgarlata commented Patch |
|
Claus Ibsen commented Take a look at #5329. I also enhanced the traceinterceptor. Maybe we could mix the best of both worlds. |
|
Matthew Sgarlata commented Hi Claus, Looks like we were thinking along the same lines! I really like how you added an elapsed time as something that could be logged. I had the same idea as you with making it possible to log as the target class rather than as the TraceInterceptor. The problem though is that the method name detected by Log4J will be the TraceInterceptor's invoke method. So if the method name is part of what you're logging, you could end up with a weird log message like this: "MyService:invoke - Here is my log message" Even though your MyService class doesn't have an invoke method. One thing I wanted to do was print out argument names, but unfortunately that information doesn't seem to be available at runtime in JDK 1.3. I see you put in parameter types as well, which is an interesting option. One thing I would wonder is what if you wanted to combine the parameter types and the parameter values such as "MyService.getSomeData(3 [java.lang.Integer], "myDatabaseName" [java.lang.String]) or something like that? I don't think either of us has a clear solution to something like that. Do you think parameter types will typically be of interest? I would think you could usually infer the types well enough by looking at the values of the arguments that are printed out. I prefer my technique of using $notiation to using numbers like {0} because it's easier to see in your configuration exactly what's going on. I'm not at all convined $whatever is best though... perhaps we should use {whatever} instead? What do you think? One thing that is confusing to me about your TraceInterceptor is the possibility of specifying an enter and exit message format, but also having elapsedTime and argument properties. I think if everything is configured in the message format then it's clearer where the elapsedTime and arguments will print and it's also more configurable. |
|
Matthew Sgarlata commented I just ran into some confusing log output with the TraceInterceptor that leads me to believe we also need to have a mechanism of letting the user know when an exception has been thrown. If we went with my code, that would mean adding an exceptionMessageTemplate property to the TraceInterceptor. Here is my confusing log output. Note that NoteDAOImpl.getRecentMeetingNoteText actually threw an exception and didn't return null, unlike what is claimed by the message below DEBUG (TraceInterceptor:invoke) - NoteDAOImpl.getRecentMeetingNoteText(5,<p><font size="1" color="#9AA4CE">There are no notes for [currentperiod]. The information below is from the last period availible, [lastperiod]</font></p>,39,org.apache.catalina.session.StandardSessionFacade@7b6617,database1110394538812) returned null etc |
|
Claus Ibsen commented Hi Matthew I do think putting in parameter types is viable when you have overloaded methods and thus want to know excatly witch method was invoked. I haven't tried it on JDK1.3 only JDK1.4. I am sure Rob Harrop can tell why the info isn't avail in JDK1.3. I think he should be assigned both #5329 and #5586. I thought about configuring the ENTER and EXIT method completely using a string format syntax along the lines you suggest. Using Combining parameter types and values is for me confusing: ENTER - foo(com.mycompany.Customer Customer[ID='123', Name='Claus'], Boolean true, Date 2005-03-29 CET 12:00) As some of the parameter values will be Object's that would have a verbose toString() such as the Customer object above. But why not give the user the choice of all 3 combinations:
About the dynamic logger. I do like it as in my code I don't get the weird logname. Again let the user decide. I would rather have the option to configure my log4j.properties as: log4j.root=WARN, console And still have the TraceInterceptor to output at DEBUG level in my code. If we don't have the dynamic logger option I need to specify: log4j.root=WARN, console If I have more than one TraceInterceptor configured I get DEBUG log for them all - I won't be able to turn on ON and the other OFF. The dynamic logger will. Can you provide a java example where the dynamic logger will use a weird name? In your example you can output the returned object. I think that is a good idea. /Claus |
|
Claus Ibsen commented A few other suggestions:
|
|
Rob Harrop commented Matt/Claus, My current feeling is that we should leave TraceInterceptor as is and introduce a new CustomizableTraceInterceptor with all these improvements included. Also - parameter names are never available at runtime, only parameter types. Rob |
|
Matthew Sgarlata commented Hi Rob, I think both Claus and I designed our enhancements to TraceInterceptor so that they would be 100% backwards compatible. In other words, the output of the enhanced version of TraceInterceptor would be the same as the old version. The only compatability difference I can think of is that if dependency checking is by default turned on for the application context in which the TraceInterceptor is registered, the bean would fail after upgrading to a new version of Spring. I think that's a very minor compatability issue. We are doing a point upgrade, after all, so minor changes like this are to be expected. On the other hand, I feel introducing a new CustomizableTraceInterceptor adds no value. Why have two classes that can do the same thing? The new enhanced version is just as easy to use as the old version for a basic use case. Namely, just register the bean in the application context. The bean has no dependencies or other required beans, etc. |
|
Rob Harrop commented There are two main reasons I want to move this into a different class:
Rob |
|
Matthew Sgarlata commented Hi again Rob, PERFORMANCE I hadn't thought much about the performance hit for these new enhancements, but you're right there would be one. However, I don't think the hit would be that significant. First of all, the hit is only in development because in other environments the logging should be turned off. Second, if you think about it there is far less String manipulation involved in the TraceInterceptor than there is in loading the XML-based Spring application context. String manipulation is certainly slow, but it isn't that slow. Further, the patch I submitted is O(n), where n is the length of the String that is output to the log file. I haven't noticed any performance difference when using the enhanced version of the interceptor. COMPATABILITY The version of the interceptor I wrote is compatible with JDK 1.3 because it does not use regular expressions. Instead, it just calls StringUtils.replace. That's probably more efficient than using regular expressions anyway. |
|
Rob Harrop commented I wouldn't compare the performance of reading the configuration, which is a startup task, with the performance of a runtime tool. Also, we can't just assume that this class won't be used in production - many applications run the first few months of production under extended QA and it is often useful to be able to turn this kind of functionality on in production without it having too much of a hit. I can't say for sure that the regex approach will be faster than using StringUtils.replace but I would assume it will be. Regex will work over the StringBuffer for all replacements whilst StringUtils is creating a new StringBuffer for every replacement. Plus, with match pattern being compiled just once, I think the overall effect will be much fast matching. I'm nearly ready with the proposed implementation which I'll be committing to sandbox soon. For now it makes sense to keep a different class name so that I can have both implementations in CVS at the same time. Rob |
|
Matthew Sgarlata commented You've convinced me of the value of having a high-performance option for the TraceInterceptor. I have an idea how we could accomplish this with only one class. When the TraceInterceptor is first created, let it have a private boolean optimizedForSpeed = true. If any of the properties in the TraceInterceptor are set to false, set optimizedForSpeed = false. If optimizedForSpeed is true, skip all the regular expressions, string replacements, etc. What do you think? |
|
Rob Harrop commented That seems like a reasonable approach, however I'm not still not sure :). I've committed CustomizableTraceInterceptor to sandbox to get some feedback and we should find out what the rest of the team and community think. Rob |
|
Matthew Sgarlata commented Hi Rob, I just took a look at your CustomizableTraceInterceptor. It looks great! Here are some minor ideas for refinement:
|
|
Claus Ibsen commented Hi Rob Looks great. Great idea about the regexp for search/replace. And using the Constants class to enlist the constants of your own class is smart. I found a few javadoc glitches, I am sure you'll have fixed anyway:
However one feature that I'll be strongly missing: |
|
Matthew Sgarlata commented I agree with Claus, there's no reason not to make elapsed time an option here. One thing I've been thinking about today is that although the regular expressions may offer slightly better performance, we are sacrificing:
Considering we don't really know the performance benefit (if any) for using regular expressions, I'm inclined to think reverting to StringUtils.replace might be better... |
|
Rob Harrop commented I'll speak to a couple of the guys regarding adding the timing, although I am uncomfortable duplicating the functionality, I might be able to structure it so that CTI extends PerformanceInterceptor. On the regex front, I spoke with Juergen about this and we are both happy with the approach - we can still do a JDK 1.3 implementation by using ORO if needs be. Rob |
|
Matthew Sgarlata commented Actually that is a really good point. This interceptor is basically becoming the catch-all CustomizableLoggingInterceptor rather than being a trivial PerformanceMonitorInterceptor or TraceInterceptor. I vote we:
I don't think duplicating the functionality of the PerformanceMonitorInterceptor should be a very big concern, because the functionality is already isolated in the o.s.util.StopWatch class. Also, we're already duplicating the functionality of the TraceInterceptor... |
|
Claus Ibsen commented Hi Matt |
|
Rob Harrop commented Sorry for the delay - I have been onsite the last two days. I'm happy with this approach so I'll start to put something together. I plan to spend Monday on Spring, but I really need to finish up the JMX docs as I'm sure you can appreciate - but this is second on my list of things to do. Rob |
|
Matthew Sgarlata commented Haha yeah I wouldn't expect this to be a top priority of yours :) Thanks for all the work you've done! |
|
Rob Harrop commented Guys, I've done a little refactoring and committed the changes to CVS. As yet I have not made the log level configurable because that makes the code somewhat more complex and I'm not sure of the value of making log level configurable for a trace interceptor. The performance interceptor is pretty much as it was before, but you can now control whether to use a dynamic log or not. I did originally start with more logic being pushed into the super class and it just called into the subclasses before, after and on throwing. However, that raises problems with synchronization - either the entire invoke() method has to be sync'd or all objects used in the tracing must be local to invoke(). For the performance interceptor this means that invoke() MUST be sync'd because the StopWatch can only be stored as a field. As it is, the super class calls into the sub class just once so there are no threading issues there. Rob |
|
Rob Harrop commented I should also add that when this code goes into the main tree I will remove the duplication of performance tracing classes and I will push assertions over to the Assert class. Rob |
|
Matthew Sgarlata commented Hi Rob, I like the way you've implemented things and avoided synchronization. I don't think separate doInMainBlock, doInCatchBlock and doInFinallyBlock methods add a lot of value anyway. The object is an interceptor, so I think it's good to go ahead and leave all the flexibility possible in there :) The reason I proposed making the log levels configurable is because the PerformanceMonitorInterceptor runs at INFO level. I think INFO is generally considered to be for initialization information and other logging statements that happen a finite number of times during program execution. Thus, having a method interceptor run at INFO level is excessive. If I were to use that interceptor, I would certainly want to set it to TRACE. Were you planning on the PerformanceTraceInterceptor to be a replacement for PerformanceMonitorInterceptor? How come the different name? Just to avoid confusion while the class is in the sandbox I hope :) Were you going to make the CustomizableTraceInterceptor able to log invocation time? I think that's really important to add. I don't think anyone is going to want to have two logging interceptors on the same method. I am not concerned about the code duplication because it's only like 2 lines. You're only duplicating calls to a completely separate class. All the truly duplicate code has already been factored into the StopWatch class. I argue that there's no way to avoid calling it if you want the functionality :) Matt |
|
Rob Harrop commented The reason for different is exactly as you say - to avoid confusion whilst in the sandbox. Whether we add performance logging to CTI will be a desicion that I'll make after discussion with Juergen. I don't see the problem of having two interceptors given that the overhead is very low. Rob |
|
Matthew Sgarlata commented Hi again Rob, I wanted to expand on the reasons I have already mentioned for making the logging level configurable in the interceptor. The current PerformanceMonitorInterceptor logs at INFO level, while the TraceInterceptor logs at DEBUG level. If the PerformanceMonitorInterceptor is committed as it currently exists in CVS, this will change the logging level of the interceptor in existing code. Normally a change in logging level like this isn't considered critical, but since this is a logging class that is specifically targeted at users of Spring, I would argue that suddenly changing the logging level should be considered a backwards incompatability since it will require the user to change their Log4J configuration to get the PerformanceMonitorInterceptor to work the way it used to. To avoid this, I propose setting the default logging level of the base interceptor to trade (for the configurabletraceinterceptor and the regular traceinterceptor) and then override the default value to be INFO level for the performancemonitorinterceptor. In addition, I think users will occasionally want to use the CustomizableLoggingInterceptor to log at INFO level. For example, say we have certain scripts that run when the application starts up or once every 24 hours that do batch data imports. We want this imports to be logged for system administrators and we want their elapsed time to be shown. In this case, INFO level logging is appropriate because the logging statements won't happen for each request. Rather, then will happen infrequently enough that a system administrator may wish to see them. |
|
Rob Harrop commented I have extend AbstractTraceInterceptor to allow for configurable log levels and CustomizableTraceInterceptor to allow for invocation timing. Let me know your thoughts. Rob |
|
Matthew Sgarlata commented Hi Rob, thanks for those changes :) These new classes are really looking good! I would suggest the following refinements, but in any case it looks to me like the classes are ready for primetime:
I understand it's kind of strange to make the default log level TRACE in the AbstractTraceInterceptor, and then immediately override it in the PerformanceMonitorInterceptor which comes with Spring. I regard this is a historical oddity since for whatever reason the old PerformanceMonitorInterceptor was at INFO when it should have been at TRACE. Note that I am sugesting we do make a slightly backwards-incompatible change by switching the default logging of the TraceInterceptor from DEBUG to TRACE. I feel pretty strongly that a Trace interceptor should do just that, even if it is slighly backwards incompatible. In reality, most people use Log4J so this won't be an issue in practice. A change from INFO to DEBUG is a bigger deal. |
|
Claus Ibsen commented Hi Rob AbstractTraceInterceptor.java Just browsing the code now and I am a bit puzzled why this code line works: And this codeline: uses the prefix and the other doesn't. The javadoc for setLogLevel() has duplicate WARN instead of FATAL. And why is the order not having FATAL as the top? I would suggest having: CustomizableTraceInterceptor.java |
|
Rob Harrop commented Matt/Claus, I'll make the modifications you suggested, although any modifications to the classes in the main tree will have to wait until Juergen has checked over the code. The FATAL level is incorrectly attributed in the code - I will fix that. Rob |
|
Claus Ibsen commented Rob / Spring Glad that any code will have quality peer review with the spring team before beging moved from sandbox to head. Spring itself is sure a really really quality product that is very rare in even closed comerical worlds. In fact our worlds are depedent on the quality and ease of use of the open world :) Hmm how strange is that - Hey that is why we care so much and pay attention to this products. Looking back to the closed worls 5 years ago where we would follow the worlds of Borland - now we are at the frontier using the internet ;). Jesus it's the 4 beers talking. Just glad that I have a chance to particpate and follow the worlds of Spring here at the jira, forum and news groups and reading the great books. Take care Claus |
|
Juergen Hoeller commented Added to the main codebase. There are no configurable log levels, though: logging always happens at "trace" level. The incompatibility with the old trace and performance monitor interceptors is acceptable, IMO: it's a new Spring major release, after all. Juergen |
|
Matthew Sgarlata commented That sounds good to me. I agree all logging should be done at the TRACE level. Matt |
spring-projects-issues
added
type: enhancement
Matthew Sgarlata opened SPR-860 and commented
I want to be able to see the arguments to and return values of the methods in my service and DAO objects. The TraceInterceptor did not support this functionality, so I wrote it and prepared a patch for potential inclusion in Spring. With no configuration parameters specified, log messages will appear as they did in Spring 1.0.2. The new enterMessageTemplate and exitMessageTemplate properties allow for customization.
In my application I set my enterMessageTemplate to "Entering $unqualifiedTargetClassName.$methodName($arguments)" and my exitMessageTemplate to "$unqualifiedTargetClassName.$methodName($arguments) returned $returnValue". This results in log output such as:
DEBUG (TraceInterceptor:invoke) - Entering OwnerUpdaterServiceImpl.getOwnerMetricsByUser(39,-1,5,database1110394538812,org.apache.catalina.session.StandardSessionFacade@1dbe1c9)
DEBUG (TraceInterceptor:invoke) - Entering OwnerUpdaterDAOImpl.getOwnerMetricsByUser(39,-1,5,database1110394538812)
DEBUG (JdbcTemplate:query) - Executing SQL query [select mc.metricid, mc.scorecardnodeid, mc.updatetype, mc.datatype, mc.aggregationtype, mc.equation, mc.lastreminded, mc.calendarid, sn.scorecardnodename, sn.scorecardrootnodeid, mc.calendarperiodid, ms.score, mv.actualvalue, sn.weighting, mv.goal, mc.goal as mgoal, mv.base, mc.base as mbase, mv.metricvalueid, s.organizationnodeid, mc.periodalias, mc.startdate, mc.enddate, cal.calendarname from ((((((select m.*, cp1.calendarperiodid, cp1.startdate, cp1.enddate, cp1.periodalias from metrics m, calendarperiods cp1, calendarperiods cp2 where m.calendarid = cp1.calendarid and cp2.calendarperiodid=? and ( (cp1.startdate >= cp2.startdate and cp1.startdate <= cp2.enddate) or (cp1.enddate >= cp2.startdate and cp1.enddate <= cp2.enddate) or (cp1.startdate < cp2.startdate and cp1.enddate > cp2.enddate) ) ) mc left outer join metricvalues mv on (mc.metricid = mv.metricid and mc.calendarperiodid = mv.calendarperiodid)) left outer join metricscores ms on (mc.metricid = ms.metricid and mc.calendarperiodid = ms.calendarperiodid)) left join scorecardnodes sn on (mc.scorecardnodeid = sn.scorecardnodeid)) left join scorecards s on (sn.scorecardrootnodeid = s.scorecardrootnodeid)) left join scorecardnodeownerusers sou on (mc.scorecardnodeid = sou.scorecardnodeid)) left join calendars cal on (mc.calendarid = cal.calendarid) where sou.userid = ? order by sn.scorecardnodename]
DEBUG (StatementCreatorUtils:setParameterValue) - Setting SQL statement parameter value: columnIndex 1, parameter value [39], valueClass [java.lang.Integer], sqlType unknown
DEBUG (StatementCreatorUtils:setParameterValue) - Setting SQL statement parameter value: columnIndex 2, parameter value [-1], valueClass [java.lang.Integer], sqlType unknown
DEBUG (TraceInterceptor:invoke) - OwnerUpdaterDAOImpl.getOwnerMetricsByUser(39,-1,5,database1110394538812) returned []
DEBUG (TraceInterceptor:invoke) - OwnerUpdaterServiceImpl.getOwnerMetricsByUser(39,-1,5,database1110394538812,org.apache.catalina.session.StandardSessionFacade@1dbe1c9) returned []
PS - I know service objects shouldn't have HttpSessions passed to them, I just haven't had time to factor that out of the code at my new company yet!
Affects: 1.2 RC1
Attachments:
Issue Links:
1 votes, 2 watchers
The text was updated successfully, but these errors were encountered: