History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: UP-1508
Type: New Feature New Feature
Status: Closed Closed
Resolution: Fixed
Priority: Minor Minor
Assignee: Nick Bolton
Reporter: Andrew Petro
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
uPortal

PerformantMessageStatsRecorder

Created: 18/May/06 10:05 PM   Updated: 03/Jul/07 04:13 PM
Component/s: Stats Recorder
Affects Version/s: None
Fix Version/s: 2.6.0 M1

Original Estimate: Unknown Remaining Estimate: Unknown Time Spent: Unknown


 Description  « Hide
Some performance test implementations depend upon the MessageStatsRecorder. However, MessageStatsRecorder has limiting performance characteristics. Introduce an alternative PerformantMessageStatsRecorder. Introducing an alternative implementation allows keeping the current MessageStatsRecorder as-is. If it is acceptable for the message formats to change, this change could be applied directly to the existing MessageStatsRecorder.

org/jasig/portal/services/stats/MessageStatsRecorder

    * Replace 'new Date()' with 'System.currentTimeMillis()'.
    * Remove 'fixMsg()' method, which required an additional StringBuffer to be created.

This change was originally developed for Academus; Unicon now seeks to include it in baseline uPortal.

 All   Comments   Work Log   Change History      Sort Order:
Jason Shao [13/Feb/07 05:27 PM]
just saw this one –

I'm OK with changing the format of messages in 2.6 – given the new freedom it seems to make sense not to ship the "non-PerformantMessageStatsRecorder"


Nick Bolton [13/Feb/07 06:21 PM]
Hey, Jason. Yeah, this is exactly the approach I was going to take.

Nick Bolton [22/Feb/07 02:06 PM]
Moved formatting of logging messages to the handler and added more performant raw timestamp versions of the printing and logging handlers.

Scott Battaglia [23/Feb/07 08:45 AM]
I've reviewed some of the source code for this JIRA issue and have some concerns:

(a) if we're really concerned about performance you should be using StringBuilder rather than concatenating strings.
(b) placing SPACE as a constant decreases readability and does nothing for performance
(c) If you're actually concerned about turning things into constants to make things easier to read, use a MessageBundle with token replacement. It would make things significantly easier to read AND add to Internationalization.
(d) you've introduced a Thread safety bug by lazily loading the Date for getTimestampAsDate (there are instances where multiple threads can be spawned to handle the same PortalEvent).
(e) Lazily loading the converted Date seems like a pre-optimization. Out of all the objects created, the couple of dates created by PortalEvents is making that huge of a performance difference? Especially since people should be using the date. System.currentTimeInMilliSeconds is not human readable. It may make your performance numbers better as it is one less object but I'm pretty sure I couldn't read a log that used that instead of a date.
(f) An Event should be able to give you its message. Its message should not be constructed from an outside resource. Proper OO design would dictate this. Proper OO design would actually dictate that no message is exposed as a getter and that the event itself would have a method that accepts some form of Writer but that might be a little extreme.
(g) if this really was to increase performance, then adding all the method calls probably isn't helping.

I think this issue should be re-opened. Also, the code committed has nothing to do with the original JIRA issue.


Scott Battaglia [23/Feb/07 09:19 AM]
I also looked a little more and noted that there are instances where it looks like optimizations were attempted to be applied but actually aren't. Creating a "SPACE" constant has created more concatenation in certain circumstances (though odds are the compiler would optimized it out since they are both constants).

Also, by moving the creation of the event message to the handlers you eliminate the ability of the Event to cache its message and give them same one to multiple eventhandlers thus creating more objects if more than one eventhandler handles an event.

I just want to note that I will readily admit that the Event subpackage is not as optimized in its original state as it could be (but that wasn't the goal) so this is not a criticism to say the original code was better. These comments are here to address that the performance has not necessarily been improved nor that the package has even necessarily been positioned to provide better performance/flexibility in the future.


Nick Bolton [23/Feb/07 09:23 AM]
a) Strings concatenations in jdk1.5 get optimized to StringBuilder sequences.
b) SPACE was not for readability. It was to reduce the creation of objects.
c) This could be done, but under a separate jira.
d) This just means one Date object will get squashed over another. Exceptable IMO for the non-performanant version.
e) The couple of Date objects by a couple of PortalEvent's no. It's under stress where the problem lies and we've found it to be a significant problem. In a stress test, we'd want to use the raw timestamp and NOT have to create a Date object. The raw date is not readable by humans very easiliy and yes you would need an external processor to read it. But now deployers have a choice. But in most production environments, you could still use the timestamp as Date option. It's just when testing does it skew results.
f ) Technically it does give you the message. Now it's just in pieces and it gives you flexibility to plug in different handlers to construct different formatting.

Nick Bolton [23/Feb/07 09:32 AM]
You can still have Event objects that cache their messages (but none do now). Using the original handlers would take advantage of this.

Scott Battaglia [23/Feb/07 11:28 AM]
a) Yes it does create StringBuilder sequences but it most likely can't detect every instance of where StringBuilder should be applied (though it may). Also, performance can be improved by explicitly using StringBuilder AND specifying a capacity for the StringBuilder. Something I believe the compiler does not do.

b) As far as I know, using the " " does not create more objects as there is the pool of String objects used by the JVM. See: http://www.precisejava.com/javaperf/j2se/StringAndStringBuffer.htm

c) Okay, but in theory most of this work should have been done under a separate JIRA issue.

d) Well there are two problems: (a) its not thread-safe whereas before it was and (b) it totally eliminates the point of lazily loading. Why even lazily load then? Just create a new one as needed. I think the result from this method should be consistent. Either you always get the same object or you always get a new object. Not, well, depending on how the threads access it, you can get different results.

e) Actually, in testing using the Timestamp skews results. Your stress testing should be indicative of real-world usage and configuration. If its not a configuration option you would use in a production system it should not be artificially used to inflate stress-testing performance. If we're looking to use that in production as a viable replacement for the current system that is a different story (though the unreadability of it makes it less effective as a logging mechanism and I would look for other improvements before eliminating the call for one Date object). I'm only mentioning this because I couldn't tell from your comments where this will be what is enabled by default or recommended for uPortal deployments.

f) The new code moves the responsibility of generating the Event message from the PortalEvent class to another class. This means that each handler would need to figure out how to construct the PortalEvent message when the message is actually the domain of the PortalEvent.

Message #2) Yes, currently no event objects cache their messages (the initial implementation was not for performance as evidence by all our suggested improvements ) and they could cache them which would probably significantly improve performance [probably more than eliminating a new Date() object]. Using the original handlers does not take advantage of any form of caching (as far as I can tell since they don't get the message from the event).

Side Note: I'm curious were the performance issues seen with the StatsRecorder or with the Events Handlers? (not that EventsHandler performance shouldn't be improved anyway). I'm just confused because of what the JIRA issue references.


Nick Bolton [23/Feb/07 11:49 AM]
Ok. I'm convinced. Actually, it was my understanding that deployers rarely ran with stats recorders on. With that assumption, we needed a stats recorder that performed better over the default. I agree with your point that if the system is meant to run with stats recording turned on, then tests should also be run with the same configuration. I have no problem with backing out these changes and we can get on with life.

Scott Battaglia [23/Feb/07 11:50 AM]
For that link I sent the section I was referring to was the "How the JVM works with Strings" section. In case you were wondering why I included the link

Scott Battaglia [23/Feb/07 11:52 AM]
I think you have brought up an important issue though. There are numerous improvements that can be made to the Events Handlers and PortalEvents. They aren't perfect and they aren't as optimized as they could be. I'm not sure how much they would improve overall portal performance but there is stuff that can be done.

Wait, there's life beyond code? :-p