Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Locked
1234
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
Service Engine Logging (was: svn commit: r1463863 - /ofbiz/trunk/framework/service
Re: Service Engine Logging (was: svn commit: r1463863 - /ofbiz/trunk/framework/service
1234
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
 
Administrator
|
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: <[hidden email]> > 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. > > |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
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: <[hidden email]> >> 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. >> >> |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
|
I agree it is arbitrary and sub-optimal solution but maybe I still liked it more before the last commit: the risk now is that we have too much information and no one will ever look at it.
The obvious workaround could be to set the threshold in a property file but there are probably better solutions that will require more work and design: for example it would be nice to enable usage statistical collections on services and entities (e.g. how many times a service was executed, the average time of execution, max time etc...) and then show this data in a screen; we could store this data in an entity or a file or, maybe better, keep it in memory (in a cache or similar) and let an admin enable/disable/reset this while the system is running (similarly to cache entries). Just my 2 cents, Jacopo On Apr 4, 2013, at 9:22 AM, Adrian Crum <[hidden email]> 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: <[hidden email]> >>> 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. >>> >>> > |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
|
Having a condition like that is unfair to end users.
Let's say I'm a new OFBiz user. I just wrote my first service and I try it out. I run the service, and check the logs. Weird - the service engine says my service didn't run. I check my data - it appears the service ran. I put some logging messages inside my service and run it again. Cool - my log messages appear, but the service engine still says my service didn't run. So I dig deep into the service engine source code and discover that someone decided my service wasn't important enough to log. That would be very frustrating. If you don't want to see timing messages, then turn them off. Simple. -Adrian On 4/4/2013 8:57 AM, Jacopo Cappellato wrote: > I agree it is arbitrary and sub-optimal solution but maybe I still liked it more before the last commit: the risk now is that we have too much information and no one will ever look at it. > The obvious workaround could be to set the threshold in a property file but there are probably better solutions that will require more work and design: for example it would be nice to enable usage statistical collections on services and entities (e.g. how many times a service was executed, the average time of execution, max time etc...) and then show this data in a screen; we could store this data in an entity or a file or, maybe better, keep it in memory (in a cache or similar) and let an admin enable/disable/reset this while the system is running (similarly to cache entries). > > Just my 2 cents, > > Jacopo > > > On Apr 4, 2013, at 9:22 AM, Adrian Crum <[hidden email]> 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: <[hidden email]> >>>> 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. >>>> >>>> |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
|
This would be resolved by changing the message into something that clarifies that the service took longer than a given threshold X; in this case the message would be clear and could be useful to the new user (even if of course a message based on a threshold is kind of arbitrary and doesn't tell you enough about performance) and may be ignored or not based on the nature of the service.
Jacopo On Apr 4, 2013, at 10:17 AM, Adrian Crum <[hidden email]> wrote: > Having a condition like that is unfair to end users. > > Let's say I'm a new OFBiz user. I just wrote my first service and I try it out. I run the service, and check the logs. Weird - the service engine says my service didn't run. I check my data - it appears the service ran. I put some logging messages inside my service and run it again. Cool - my log messages appear, but the service engine still says my service didn't run. So I dig deep into the service engine source code and discover that someone decided my service wasn't important enough to log. That would be very frustrating. > > If you don't want to see timing messages, then turn them off. > > Simple. > > -Adrian > > On 4/4/2013 8:57 AM, Jacopo Cappellato wrote: >> I agree it is arbitrary and sub-optimal solution but maybe I still liked it more before the last commit: the risk now is that we have too much information and no one will ever look at it. >> The obvious workaround could be to set the threshold in a property file but there are probably better solutions that will require more work and design: for example it would be nice to enable usage statistical collections on services and entities (e.g. how many times a service was executed, the average time of execution, max time etc...) and then show this data in a screen; we could store this data in an entity or a file or, maybe better, keep it in memory (in a cache or similar) and let an admin enable/disable/reset this while the system is running (similarly to cache entries). >> >> Just my 2 cents, >> >> Jacopo >> >> >> On Apr 4, 2013, at 9:22 AM, Adrian Crum <[hidden email]> 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: <[hidden email]> >>>>> 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. >>>>> >>>>> > |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
|
Isn't that what the next block of code does? If you want to have a
message that appears based on a set of conditions, then you can fuss around with the if statement that follows the timing message. -Adrian On 4/4/2013 9:58 AM, Jacopo Cappellato wrote: > This would be resolved by changing the message into something that clarifies that the service took longer than a given threshold X; in this case the message would be clear and could be useful to the new user (even if of course a message based on a threshold is kind of arbitrary and doesn't tell you enough about performance) and may be ignored or not based on the nature of the service. > > Jacopo > > On Apr 4, 2013, at 10:17 AM, Adrian Crum <[hidden email]> wrote: > >> Having a condition like that is unfair to end users. >> >> Let's say I'm a new OFBiz user. I just wrote my first service and I try it out. I run the service, and check the logs. Weird - the service engine says my service didn't run. I check my data - it appears the service ran. I put some logging messages inside my service and run it again. Cool - my log messages appear, but the service engine still says my service didn't run. So I dig deep into the service engine source code and discover that someone decided my service wasn't important enough to log. That would be very frustrating. >> >> If you don't want to see timing messages, then turn them off. >> >> Simple. >> >> -Adrian >> >> On 4/4/2013 8:57 AM, Jacopo Cappellato wrote: >>> I agree it is arbitrary and sub-optimal solution but maybe I still liked it more before the last commit: the risk now is that we have too much information and no one will ever look at it. >>> The obvious workaround could be to set the threshold in a property file but there are probably better solutions that will require more work and design: for example it would be nice to enable usage statistical collections on services and entities (e.g. how many times a service was executed, the average time of execution, max time etc...) and then show this data in a screen; we could store this data in an entity or a file or, maybe better, keep it in memory (in a cache or similar) and let an admin enable/disable/reset this while the system is running (similarly to cache entries). >>> >>> Just my 2 cents, >>> >>> Jacopo >>> >>> >>> On Apr 4, 2013, at 9:22 AM, Adrian Crum <[hidden email]> 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: <[hidden email]> >>>>>> 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. >>>>>> >>>>>> |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
|
On Apr 4, 2013, at 11:27 AM, Adrian Crum <[hidden email]> wrote: > Isn't that what the next block of code does? If you want to have a message that appears based on a set of conditions, then you can fuss around with the if statement that follows the timing message. Yeah, of course everyone can easily add log messages to get the information required (at the moment that block doesn't show time related information); in fact it is not a big deal for me, this is not the kind of commit that concerns me. By the way, I had to check in the dictionary the meaning of "to fuss" and I found: "show unnecessary or excessive concern about something" In light of this, if you think that I am wasting your time with unrealistic use cases then you can ignore me :-) I don't care much about this commit and you don't have to try to convince me; as I said I am not asking you to revert your commit, I simply added some information to the context because I felt it was missing from your arguments. Jacopo > > -Adrian > > On 4/4/2013 9:58 AM, Jacopo Cappellato wrote: >> This would be resolved by changing the message into something that clarifies that the service took longer than a given threshold X; in this case the message would be clear and could be useful to the new user (even if of course a message based on a threshold is kind of arbitrary and doesn't tell you enough about performance) and may be ignored or not based on the nature of the service. >> >> Jacopo >> >> On Apr 4, 2013, at 10:17 AM, Adrian Crum <[hidden email]> wrote: >> >>> Having a condition like that is unfair to end users. >>> >>> Let's say I'm a new OFBiz user. I just wrote my first service and I try it out. I run the service, and check the logs. Weird - the service engine says my service didn't run. I check my data - it appears the service ran. I put some logging messages inside my service and run it again. Cool - my log messages appear, but the service engine still says my service didn't run. So I dig deep into the service engine source code and discover that someone decided my service wasn't important enough to log. That would be very frustrating. >>> >>> If you don't want to see timing messages, then turn them off. >>> >>> Simple. >>> >>> -Adrian >>> >>> On 4/4/2013 8:57 AM, Jacopo Cappellato wrote: >>>> I agree it is arbitrary and sub-optimal solution but maybe I still liked it more before the last commit: the risk now is that we have too much information and no one will ever look at it. >>>> The obvious workaround could be to set the threshold in a property file but there are probably better solutions that will require more work and design: for example it would be nice to enable usage statistical collections on services and entities (e.g. how many times a service was executed, the average time of execution, max time etc...) and then show this data in a screen; we could store this data in an entity or a file or, maybe better, keep it in memory (in a cache or similar) and let an admin enable/disable/reset this while the system is running (similarly to cache entries). >>>> >>>> Just my 2 cents, >>>> >>>> Jacopo >>>> >>>> >>>> On Apr 4, 2013, at 9:22 AM, Adrian Crum <[hidden email]> 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: <[hidden email]> >>>>>>> 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. >>>>>>> >>>>>>> > |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
|
On 4/4/2013 11:18 AM, Jacopo Cappellato wrote: > On Apr 4, 2013, at 11:27 AM, Adrian Crum <[hidden email]> wrote: > >> Isn't that what the next block of code does? If you want to have a message that appears based on a set of conditions, then you can fuss around with the if statement that follows the timing message. > Yeah, of course everyone can easily add log messages to get the information required (at the moment that block doesn't show time related information); in fact it is not a big deal for me, this is not the kind of commit that concerns me. > > By the way, I had to check in the dictionary the meaning of "to fuss" and I found: > > "show unnecessary or excessive concern about something" Unfortunately, that is not the correct interpretation. Look up the words "tinker" or "fidget" to get a better understanding of what I meant. Basically I was saying you can modify/adjust the following if statement to get the results you want. > > In light of this, if you think that I am wasting your time with unrealistic use cases then you can ignore me :-) I don't care much about this commit and you don't have to try to convince me; as I said I am not asking you to revert your commit, I simply added some information to the context because I felt it was missing from your arguments. No, please don't think I'm being adversarial or dismissive. This is a good discussion, and I appreciate your input. > > Jacopo > >> -Adrian >> >> On 4/4/2013 9:58 AM, Jacopo Cappellato wrote: >>> This would be resolved by changing the message into something that clarifies that the service took longer than a given threshold X; in this case the message would be clear and could be useful to the new user (even if of course a message based on a threshold is kind of arbitrary and doesn't tell you enough about performance) and may be ignored or not based on the nature of the service. >>> >>> Jacopo >>> >>> On Apr 4, 2013, at 10:17 AM, Adrian Crum <[hidden email]> wrote: >>> >>>> Having a condition like that is unfair to end users. >>>> >>>> Let's say I'm a new OFBiz user. I just wrote my first service and I try it out. I run the service, and check the logs. Weird - the service engine says my service didn't run. I check my data - it appears the service ran. I put some logging messages inside my service and run it again. Cool - my log messages appear, but the service engine still says my service didn't run. So I dig deep into the service engine source code and discover that someone decided my service wasn't important enough to log. That would be very frustrating. >>>> >>>> If you don't want to see timing messages, then turn them off. >>>> >>>> Simple. >>>> >>>> -Adrian >>>> >>>> On 4/4/2013 8:57 AM, Jacopo Cappellato wrote: >>>>> I agree it is arbitrary and sub-optimal solution but maybe I still liked it more before the last commit: the risk now is that we have too much information and no one will ever look at it. >>>>> The obvious workaround could be to set the threshold in a property file but there are probably better solutions that will require more work and design: for example it would be nice to enable usage statistical collections on services and entities (e.g. how many times a service was executed, the average time of execution, max time etc...) and then show this data in a screen; we could store this data in an entity or a file or, maybe better, keep it in memory (in a cache or similar) and let an admin enable/disable/reset this while the system is running (similarly to cache entries). >>>>> >>>>> Just my 2 cents, >>>>> >>>>> Jacopo >>>>> >>>>> >>>>> On Apr 4, 2013, at 9:22 AM, Adrian Crum <[hidden email]> 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: <[hidden email]> >>>>>>>> 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. >>>>>>>> >>>>>>>> |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
|
On Apr 4, 2013, at 12:25 PM, Adrian Crum <[hidden email]> wrote:
> No, please don't think I'm being adversarial or dismissive. This is a good discussion, and I appreciate your input. That's great Adrian, thank you... and thanks to you I am also learning a lot of new English words :-) Jacopo |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
|
In reply to this post by Jacques Le Roux
I agree that bit of code is messy and confusing.
if ((Debug.verboseOn()... ... Debug.logTiming(... Huh? Shouldn't that be Debug.logVerbose(... ? If I have verbose on and timing off, then I will never see the log messages. I really don't understand all of this complicated decision-making about generating a log message. You don't see anything like it anywhere else. -Adrian On 4/4/2013 12:49 PM, Atul Vani wrote: > There is something wrong with the code in the next few lines too. > > > if ((Debug.verboseOn() || modelService.debug) && timeToRun > > 50 && !modelService.hideResultInLog) {// *if I have set debug to true > then it should also display for timeToRun<50* > String resultStr = result.toString(); > if (resultStr.length() > 10240) { > resultStr = resultStr.substring(0, 10226) + > "...[truncated]"; > } > if (!modelService.hideResultInLog) { > Debug.logTiming("Sync service [" + localName + "/" + > modelService.name + "] finished in [" + timeToRun + "] milliseconds > with response [" + resultStr + "]", module); > } else {// *this will never get called bacause of the > parent IF condition !modelService.hideResultInLog* > Debug.logTiming("Sync service [" + localName + "/" + > modelService.name + "] finished in [" + timeToRun + "] milliseconds", > module); > } > } else if (timeToRun > 200 && Debug.infoOn()) { > // *this code is very similar to the one above (except > logTiming and logInfo), can't we remove duplicacy somehow (might wanna > use timingOn() method)* > String resultStr = result.toString(); > if (resultStr.length() > 10240) { > resultStr = resultStr.substring(0, 10226) + > "...[truncated]"; > } > if (!modelService.hideResultInLog) { > Debug.logInfo("Sync service [" + localName + "/" + > modelService.name + "] finished in [" + timeToRun + "] milliseconds > with response [" + resultStr + "]", module); > } else { > Debug.logInfo("Sync service [" + localName + "/" + > modelService.name + "] finished in [" + timeToRun + "] milliseconds", > module); > > } > } > > > On Wed, 03 Apr 2013 13:27:25 +0530, <[hidden email]> wrote: > >> 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. >> >> > > |
|
|
In reply to this post by Jacques Le Roux
While you are at it, we can fix it. Can you please check if the changes
suggested in the diff below are satisfactory. The additional comments are just to explain the changes and are not meant to be committed. Index: framework/service/src/org/ofbiz/service/ServiceDispatcher.java =================================================================== --- framework/service/src/org/ofbiz/service/ServiceDispatcher.java (revision 1452030) +++ framework/service/src/org/ofbiz/service/ServiceDispatcher.java (working copy) @@ -586,28 +586,18 @@ } 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.verboseOn() || modelService.debug) && timeToRun > 50 && !modelService.hideResultInLog) { - // Sanity check - some service results can be multiple MB in size. Limit message size to 10K. - String resultStr = result.toString(); - if (resultStr.length() > 10240) { - resultStr = resultStr.substring(0, 10226) + "...[truncated]"; - } - if (!modelService.hideResultInLog) { - Debug.logTiming("Sync service [" + localName + "/" + modelService.name + "] finished in [" + timeToRun + "] milliseconds with response [" + resultStr + "]", module); - } else { - Debug.logTiming("Sync service [" + localName + "/" + modelService.name + "] finished in [" + timeToRun + "] milliseconds", module); - } - } else if (timeToRun > 200 && Debug.infoOn()) { + // if service instructs debugging, then definitely print it + if (modelService.debug || (Debug.verboseOn() && timeToRun > 50) || (Debug.infoOn() && timeToRun > 200)) { // Sanity check - some service results can be multiple MB in size. Limit message size to 10K. String resultStr = result.toString(); if (resultStr.length() > 10240) { resultStr = resultStr.substring(0, 10226) + "...[truncated]"; } + // we have already checked verboseOn and infoOn, so we are good to go with the log method than doing an additional check if (!modelService.hideResultInLog) { - Debug.logInfo("Sync service [" + localName + "/" + modelService.name + "] finished in [" + timeToRun + "] milliseconds with response [" + resultStr + "]", module); + Debug.log("Sync service [" + localName + "/" + modelService.name + "] finished in [" + timeToRun + "] milliseconds with response [" + resultStr + "]", module); } else { - Debug.logInfo("Sync service [" + localName + "/" + modelService.name + "] finished in [" + timeToRun + "] milliseconds", module); - + Debug.log("Sync service [" + localName + "/" + modelService.name + "] finished in [" + timeToRun + "] milliseconds", module); } } On Thu, 04 Apr 2013 17:29:51 +0530, Adrian Crum <[hidden email]> wrote: > I agree that bit of code is messy and confusing. > > if ((Debug.verboseOn()... > ... > Debug.logTiming(... > > Huh? Shouldn't that be > > Debug.logVerbose(... > > ? > > If I have verbose on and timing off, then I will never see the log > messages. > > I really don't understand all of this complicated decision-making about > generating a log message. You don't see anything like it anywhere else. > > -Adrian > > On 4/4/2013 12:49 PM, Atul Vani wrote: >> There is something wrong with the code in the next few lines too. >> >> >> if ((Debug.verboseOn() || modelService.debug) && timeToRun > 50 >> && !modelService.hideResultInLog) {// *if I have set debug to true then >> it should also display for timeToRun<50* >> String resultStr = result.toString(); >> if (resultStr.length() > 10240) { >> resultStr = resultStr.substring(0, 10226) + >> "...[truncated]"; >> } >> if (!modelService.hideResultInLog) { >> Debug.logTiming("Sync service [" + localName + "/" + >> modelService.name + "] finished in [" + timeToRun + "] milliseconds >> with response [" + resultStr + "]", module); >> } else {// *this will never get called bacause of the >> parent IF condition !modelService.hideResultInLog* >> Debug.logTiming("Sync service [" + localName + "/" + >> modelService.name + "] finished in [" + timeToRun + "] milliseconds", >> module); >> } >> } else if (timeToRun > 200 && Debug.infoOn()) { >> // *this code is very similar to the one above (except >> logTiming and logInfo), can't we remove duplicacy somehow (might wanna >> use timingOn() method)* >> String resultStr = result.toString(); >> if (resultStr.length() > 10240) { >> resultStr = resultStr.substring(0, 10226) + >> "...[truncated]"; >> } >> if (!modelService.hideResultInLog) { >> Debug.logInfo("Sync service [" + localName + "/" + >> modelService.name + "] finished in [" + timeToRun + "] milliseconds >> with response [" + resultStr + "]", module); >> } else { >> Debug.logInfo("Sync service [" + localName + "/" + >> modelService.name + "] finished in [" + timeToRun + "] milliseconds", >> module); >> >> } >> } >> >> >> On Wed, 03 Apr 2013 13:27:25 +0530, <[hidden email]> wrote: >> >>> 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/ |
Re: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
Administrator
|
In reply to this post by Adrian Crum-3
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: <[hidden email]> >>> 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. |
Service Engine Logging (was: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
|
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: <[hidden email]> >>>> 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. |
Re: Service Engine Logging (was: svn commit: r1463863 - /ofbiz/trunk/framework/service
|
Administrator
|
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" <[hidden email]> > 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: <[hidden email]> >>>>> 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. > |
|
|
Jacques,
Thanks. I will do it soon. On Sat, 06 Apr 2013 16:30:30 +0530, Jacques Le Roux <[hidden email]> 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" <[hidden email]> >> 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: <[hidden email]> >>>>>> 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/ |
|
|
In reply to this post by Jacques Le Roux
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" <[hidden email]> >> 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: <[hidden email]> >>>>>> 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. |
|
Administrator
|
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" <[hidden email]> > 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" <[hidden email]> >>> 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: <[hidden email]> >>>>>>> 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. > |
|
|
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" <[hidden email]> >> 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" <[hidden email]> >>>> 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: <[hidden email]> >>>>>>>> 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. |
|
|
In reply to this post by Adrian Crum-3
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 <[hidden email]> 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" <[hidden email]> >>> 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" <[hidden email]> >>>>> 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: <[hidden email]> >>>>>>>>> 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/ |
|
Administrator
|
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" <[hidden email]> > 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 > <[hidden email]> 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" <[hidden email]> >>>> 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" <[hidden email]> >>>>>> 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: <[hidden email]> >>>>>>>>>> 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/ |
«
Return to OFBiz - Dev
|
1 view|%1 views
| Free forum by Nabble | Edit this page |