From: "Adrian Crum" <adrian.c...@sandglass-software.com> > On 4/7/2013 10:30 AM, Jacques Le Roux wrote: >> From: "Adrian Crum" <adrian.c...@sandglass-software.com> >>> From my perspective, you are the one complicating things. If you don't >>> want to slow down the system with logging I/O, then turn logging off. >> When you are continously developping a system, removing all log info/timing >> from production can be problematic. >> It's sometimes the only way you have to understand why and how a random >> issue appears. > > > That is helpful. So, when you are troubleshooting a production > installation, you enable TIMING and INFO logging to see what's going on. > Understood. Now, what is the purpose of using a threshold?
To separate slow services and, for the 2nd threshold, possibly very slow ones. Sometimes, it depends not only on external system but also on a whole "ecosystem" (net connections, firewalls, etc.) We know things always changes, it's like a chaos sometimes. At this stage you are yet sure not what for looking for. So you need a 1st rough filter to better understand what's going on Putting thresholds on services durations can then help to separate cases. > You mentioned marking slow services, but a single threshold value for > all services will not do that - because every service is different and > each one will have a unique typical elapsed time. That was the reason > why I changed the text of the message - because services that were > completed in timely manner were being logged as "slow" - which was not true. There were slow and very slow, that why I used 2 properties, and set the 1st to 0, to have the behaviour you introduced and I agree with for OOTB setting (show all services duration) > Have you considered using the metrics feature? Ha forgot to ask about it, now I see and remember this thread and I will digg in http://markmail.org/message/x4lzvda66ju6gdg5 Of course, I'd not be against a brief briefing, or a link to explain. Thanks for the reminder Jacques > > >> >>> "We've always done it that way" is not a valid argument. >> I was just saying that personally I did not have problems whith how it was >> before your change. I was easy to adapt to my need. I have also no problems >> with your change, it's sill easy to adapt. >> >>> You still haven't given us any requirements that demonstrate the need to >>> put complicated decision making around a single log entry. >> My solution is not complicated at all 2 properties for 2 thresholds. Why do >> you feel it as complicated? >> Actually I'm not stuck with this solution. If you want, comment it out or >> even revert and the chapter is closed. >> >> Jacques >> >>> -Adrian >>> >>> On 4/7/2013 9:18 AM, Jacques Le Roux wrote: >>>> This seems over complicated to me. Don't arbitrarily slow OFBiz by storing >>>> (IOs) services durations at each service call. Let's keep it simple and >>>> easy tunable. >>>> >>>> The way it was before ( >50 => slow; > 200 => very slow) was there for >>>> years. I did not code it, and after a decade we want to change it, OK. >>>> >>>> Most of the time you don't care about that. When you do, you simply want >>>> to separate slow services from others. >>>> >>>> I believe OOTB 2 properties are enough. I set them to allow to see all >>>> services durations and to specifically mark slow services. I picked 1 sec, >>>> why? It would be terribly slow services internally, but externals ones can >>>> vary much more. >>>> If you need more thresholds/separations it's easy from what is coded now >>>> to add suiting your needs. >>>> >>>> From my experience, when looking at logs on a system you quickly know >>>> which are these values, when you are interested by them >>>> >>>> The most important point here is not slow the system and to follow >>>> KISS/YAGNI ways. >>>> >>>> Please don't complicate things, thanks! >>>> >>>> Jacques >>>> >>>> >>>> From: "Atul Vani" <atul.v...@hotwaxmedia.com> >>>>> Here's what I think, it's all raw though :) >>>>> * As suggested by Jacopo, we maintain stats in some kind of entity. Let's >>>>> say average running time. >>>>> * We use this average running time to decide if a timing log should be >>>>> printed. The thing is, not all services are same, some are complex and are >>>>> supposed to take longer than others, so a static number would never >>>>> suffice. We do not have any means to calculate the complexity of a service >>>>> (by looking at the mini-lang code) to decide this number, so either a user >>>>> will tell it or we can compute it on the basis of past run times. >>>>> * There can come cases when user would want to tell the number (all past >>>>> experiences were bad ones, or he just optimized), so we can add some >>>>> attribute to the service definition. There is something like metric >>>>> already present, not sure how that works. >>>>> * A single number for all services does not make sense to me, because (as >>>>> mentioned above) not all services are same. >>>>> >>>>> On Sun, 07 Apr 2013 04:14:58 +0530, Adrian Crum >>>>> <adrian.c...@sandglass-software.com> wrote: >>>>> >>>>>> No, a commit is NOT a reply to an email. >>>>>> >>>>>> Please, let's discuss this. You seem to be forcing your perception of >>>>>> how logging should be done on the rest of the community. I would prefer >>>>>> that we all participate in a discussion and come up with a design that >>>>>> works for everyone. >>>>>> >>>>>> -Adrian >>>>>> >>>>>> On 4/6/2013 5:32 PM, Jacques Le Roux wrote: >>>>>>> I thought the commit comment answered your question >>>>>>> >>>>>>> OOTB, there is only 1 change from what you committed: now services >>>>>>> longer than 1 sec will also show as slow in log >>>>>>> >>>>>>> Jacques >>>>>>> >>>>>>> From: "Adrian Crum" <adrian.c...@sandglass-software.com> >>>>>>>> Please don't change the timing logging - there should not be any >>>>>>>> conditions placed on it. >>>>>>>> >>>>>>>> You didn't answer my question. I was hoping we could avoid a commit war >>>>>>>> by discussing your requirements and designing a solution that makes >>>>>>>> everyone happy. >>>>>>>> >>>>>>>> -Adrian >>>>>>>> >>>>>>>> On 4/6/2013 12:00 PM, Jacques Le Roux wrote: >>>>>>>>> Hi Adrian, >>>>>>>>> >>>>>>>>> Thanks for asking, I committed and commented at revision: 1465223 >>>>>>>>> >>>>>>>>> Atul, >>>>>>>>> >>>>>>>>> It was not easy to read your patch in the email (cut at 80 chars). >>>>>>>>> Please open a Jira if you want to improve my commit. >>>>>>>>> >>>>>>>>> Thanks >>>>>>>>> >>>>>>>>> Jacques >>>>>>>>> >>>>>>>>> >>>>>>>>> From: "Adrian Crum" <adrian.c...@sandglass-software.com> >>>>>>>>>> Jacques, >>>>>>>>>> >>>>>>>>>> What are your requirements? What are you looking for in the logs? >>>>>>>>>> >>>>>>>>>> -Adrian >>>>>>>>>> >>>>>>>>>> On 4/4/2013 10:54 PM, Jacques Le Roux wrote: >>>>>>>>>>> These numbers are from experience of hours and hours staring at >>>>>>>>>>> clusters logs, but yes it's arbitrary and depend on context (as I >>>>>>>>>>> guess were picked the initial numbers which are there for years >>>>>>>>>>> Then why not the obvious solution Jacopo proposed of properties, >>>>>>>>>>> easy to change even dynamically... >>>>>>>>>>> I can't see anything more flexible, at least at 23:43 after days of >>>>>>>>>>> works. >>>>>>>>>>> AS you said, once you spot one such line in log it's not a biggie >>>>>>>>>>> to get there (you have the class line in log) and adapt suiting >>>>>>>>>>> your needs. >>>>>>>>>>> So maybe "like you proposed" we could indeed put a very low value >>>>>>>>>>> (I mean 0) as property. >>>>>>>>>>> >>>>>>>>>>> For Atul's proposition, sorry not the courage to check tonight >>>>>>>>>>> (maybe a patch in a Jira would help to read) >>>>>>>>>>> >>>>>>>>>>> Jacques >>>>>>>>>>> PS: I guessed "fuss around", knew tinker, not fidget :D >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> Adrian Crum wrote: >>>>>>>>>>>> Why not 20 or 30 or 40? >>>>>>>>>>>> >>>>>>>>>>>> That's the problem with arbitrary values - they don't mean >>>>>>>>>>>> anything. >>>>>>>>>>>> >>>>>>>>>>>> From my perspective, if anyone has timing enabled, then they >>>>>>>>>>>> want to >>>>>>>>>>>> see what's going on in the system. >>>>>>>>>>>> >>>>>>>>>>>> Feel free to change it. >>>>>>>>>>>> >>>>>>>>>>>> -Adrian >>>>>>>>>>>> >>>>>>>>>>>> On 4/3/2013 9:22 AM, Jacques Le Roux wrote: >>>>>>>>>>>>> Hi Adrian, All, >>>>>>>>>>>>> >>>>>>>>>>>>> Should we really show the timing for all services? >>>>>>>>>>>>> Maybe increasing from 50 to 75 or even 100 for the 1st case would >>>>>>>>>>>>> be enough? >>>>>>>>>>>>> >>>>>>>>>>>>> Jacques >>>>>>>>>>>>> >>>>>>>>>>>>> From: <adri...@apache.org> >>>>>>>>>>>>>> Author: adrianc >>>>>>>>>>>>>> Date: Wed Apr 3 07:57:24 2013 >>>>>>>>>>>>>> New Revision: 1463863 >>>>>>>>>>>>>> >>>>>>>>>>>>>> URL: http://svn.apache.org/r1463863 >>>>>>>>>>>>>> Log: >>>>>>>>>>>>>> Log message cleanup in ServiceDispatcher.java. Removed confusing >>>>>>>>>>>>>> text about services taking too long. >>>>>>>>>>>>>> >>>>>>>>>>>>>> Modified: >>>>>>>>>>>>>> >>>>>>>>>>>>>> ofbiz/trunk/framework/service/src/org/ofbiz/service/ServiceDispatcher.java >>>>>>>>>>>>>> >>>>>>>>>>>>>> Modified: >>>>>>>>>>>>>> ofbiz/trunk/framework/service/src/org/ofbiz/service/ServiceDispatcher.java >>>>>>>>>>>>>> URL: >>>>>>>>>>>>>> http://svn.apache.org/viewvc/ofbiz/trunk/framework/service/src/org/ofbiz/service/ServiceDispatcher.java?rev=1463863&r1=1463862&r2=1463863&view=diff >>>>>>>>>>>>>> ============================================================================== >>>>>>>>>>>>>> --- >>>>>>>>>>>>>> ofbiz/trunk/framework/service/src/org/ofbiz/service/ServiceDispatcher.java >>>>>>>>>>>>>> (original) +++ >>>>>>>>>>>>>> ofbiz/trunk/framework/service/src/org/ofbiz/service/ServiceDispatcher.java >>>>>>>>>>>>>> Wed Apr 3 07:57:24 2013 @@ -571,10 +571,8 @@ public >>>>>>>>>>>>>> class ServiceDispatcher { rs.setEndStamp(); >>>>>>>>>>>>>> >>>>>>>>>>>>>> long timeToRun = System.currentTimeMillis() - >>>>>>>>>>>>>> serviceStartTime; >>>>>>>>>>>>>> - if (Debug.timingOn() && timeToRun > 50) { >>>>>>>>>>>>>> - Debug.logTiming("Slow sync service execution >>>>>>>>>>>>>> detected: service [" + localName + "/" + modelService.name + "] >>>>>>>>>>>>>> finished in [" + timeToRun + "] milliseconds", module); >>>>>>>>>>>>>> - } else if (Debug.infoOn() && timeToRun > 200) { >>>>>>>>>>>>>> - Debug.logInfo("Very slow sync service execution >>>>>>>>>>>>>> detected: service [" + localName + "/" + modelService.name + "] >>>>>>>>>>>>>> finished in [" + timeToRun + "] milliseconds", module); + >>>>>>>>>>>>>> if (Debug.timingOn()) { >>>>>>>>>>>>>> + Debug.logTiming("Sync service [" + localName + "/" >>>>>>>>>>>>>> + modelService.name + "] finished in [" + timeToRun + "] >>>>>>>>>>>>>> milliseconds", module); } >>>>>>>>>>>>>> if ((Debug.verboseOn() || modelService.debug) && >>>>>>>>>>>>>> timeToRun > 50 && !modelService.hideResultInLog) { >>>>>>>>>>>>>> // Sanity check - some service results can be >>>>>>>>>>>>>> multiple MB in size. Limit message size to 10K. >>>>> -- >>>>> Using Opera's revolutionary email client: http://www.opera.com/mail/ >
