You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@sling.apache.org by Julian Sedding <js...@gmail.com> on 2014/10/29 09:42:47 UTC

Improving the flexibility of RequestProgressTrackerLogFilter

Hi all

The RequestProgressTrackerLogFilter allows logging the information
collected by the RequestProgressTracker at debug level. Since this can
amount to several undred lines logged per request, this may be
prohibiitive on a busy production system.

I propose to reduce the size of the log file by doing the following:
1. changing the log format to include less redundant data
2. allow filtering by request duration
3. allow filtering by request extension(s)

Regarding point 1, currently each "message" of the RPT is logged with
a debug statement. The proposed "compact" format only logs one debug
statement. This spans multiple lines, space indented, similar to how
stack-traces are logged. See an example of both at the bottom of this
message.

I created SLING-4114 [0] with a patch attached that implements these
changes. Note that I made some additions to the RequestProgressTracker
API. These should be compatible for consumers, so I think they should
not do any harm.

Could someone please take a look at the patch, and if everything is
ok, commit it? Thank you.

Regards
Julian

[0] https://issues.apache.org/jira/browse/SLING-4114

Old format:
28.10.2014 10:49:20.635 *DEBUG* [127.0.0.1 [1414489760633] PUT
/libs/sling/topology/connector.json HTTP/1.1]
org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter
REQUEST_1 -       0 (2014-10-28 10:49:20) TIMER_START{Request
Processing}
28.10.2014 10:49:20.636 *DEBUG* [127.0.0.1 [1414489760633] PUT
/libs/sling/topology/connector.json HTTP/1.1]
org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter
REQUEST_1 -       0 (2014-10-28 10:49:20) COMMENT timer_end format is
{<elapsed msec>,<timer name>} <optional message>
28.10.2014 10:49:20.637 *DEBUG* [127.0.0.1 [1414489760633] PUT
/libs/sling/topology/connector.json HTTP/1.1]
org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter
REQUEST_1 -       0 (2014-10-28 10:49:20) LOG Method=PUT,
PathInfo=/libs/sling/topology/connector.json

Compact format:
28.10.2014 10:49:20.635 *DEBUG* [127.0.0.1 [1414489760633] PUT
/libs/sling/topology/connector.json HTTP/1.1]
org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter
       0 (2014-10-28 10:49:20) TIMER_START{Request Processing}
       0 (2014-10-28 10:49:20) COMMENT timer_end format is {<elapsed
msec>,<timer name>} <optional message>
       0 (2014-10-28 10:49:20) LOG Method=PUT,
PathInfo=/libs/sling/topology/connector.json

Re: Improving the flexibility of RequestProgressTrackerLogFilter

Posted by Julian Sedding <js...@gmail.com>.
Hi Bertrand

Thanks a lot! I'm looking forward to using the new bundle.

Regards
Julian

On Mon, Nov 3, 2014 at 4:26 PM, Bertrand Delacretaz
<bd...@apache.org> wrote:
> Hi Julian,
>
> On Mon, Nov 3, 2014 at 10:15 AM, Julian Sedding <js...@gmail.com> wrote:
>> ...I have attached another patch to SLING-4114 that does not change the
>> API. However, it drops the date/time from the message format...
>
> Cool, I like it, it's much better without API bundle changes.
> I have applied your patch and marked SLING-4114 as fixed.
>
> -Bertrand

Re: Improving the flexibility of RequestProgressTrackerLogFilter

Posted by Bertrand Delacretaz <bd...@apache.org>.
Hi Julian,

On Mon, Nov 3, 2014 at 10:15 AM, Julian Sedding <js...@gmail.com> wrote:
> ...I have attached another patch to SLING-4114 that does not change the
> API. However, it drops the date/time from the message format...

Cool, I like it, it's much better without API bundle changes.
I have applied your patch and marked SLING-4114 as fixed.

-Bertrand

Re: Improving the flexibility of RequestProgressTrackerLogFilter

Posted by Julian Sedding <js...@gmail.com>.
Hi Bertrand

Thank you for taking a look.

As you observed correctly, the API changes were done to allow more
flexibility when rendering the logs.

The main objective was avoiding the date/time stamp (e.g. "(2014-10-28
10:49:20)") in each line. Because it does not add any information,
because the granularity is too coarse, and we already have the
millisecond durations.

I have attached another patch to SLING-4114 that does not change the
API. However, it drops the date/time from the message format. If
dropping the date/time from the messages is not acceptable, I can
create a slightly more complicated patch.

WDYT?

Regards
Julian


On Fri, Oct 31, 2014 at 1:57 PM, Bertrand Delacretaz
<bd...@apache.org> wrote:
> Hi Julian,
>
> On Wed, Oct 29, 2014 at 9:42 AM, Julian Sedding <js...@gmail.com> wrote:
>
>> ...I propose to reduce the size of the log file by doing the following:
>> 1. changing the log format to include less redundant data
>> 2. allow filtering by request duration
>> 3. allow filtering by request extension(s)
>
> sounds good to me!
>
>> ...I created SLING-4114 [0] with a patch attached that implements these
>> changes. Note that I made some additions to the RequestProgressTracker
>> API. These should be compatible for consumers, so I think they should
>> not do any harm....
>
> Still, I'm not too happy with requiring changes to the API bundle just for this.
>
> IIUC your changes to RequestProgressTracker are only about extracting
> data from the tracker, as opposed to providing data to it, which is
> what 99% of the code that uses that API does.
>
> So one way to avoid those API bundle changes would be to create a
> SlingEngineRequestProgressTracker interface (exported) in the engine
> bundle, which is RequestProgressTracker + niceties that the actual
> engine provides (your changes). The SlingRequestProgressTracker
> implements this.
>
> As all the reporting is currently done in the engine bundle that's not
> a problem for Sling itself, the engine just gets the tracker and if it
> implements SlingEngineRequestProgressTracker uses the additional data.
>
> If someone wants to access that data they can do the same.
>
> WDYT?
> -Bertrand

Re: Improving the flexibility of RequestProgressTrackerLogFilter

Posted by Bertrand Delacretaz <bd...@apache.org>.
Hi Julian,

On Wed, Oct 29, 2014 at 9:42 AM, Julian Sedding <js...@gmail.com> wrote:

> ...I propose to reduce the size of the log file by doing the following:
> 1. changing the log format to include less redundant data
> 2. allow filtering by request duration
> 3. allow filtering by request extension(s)

sounds good to me!

> ...I created SLING-4114 [0] with a patch attached that implements these
> changes. Note that I made some additions to the RequestProgressTracker
> API. These should be compatible for consumers, so I think they should
> not do any harm....

Still, I'm not too happy with requiring changes to the API bundle just for this.

IIUC your changes to RequestProgressTracker are only about extracting
data from the tracker, as opposed to providing data to it, which is
what 99% of the code that uses that API does.

So one way to avoid those API bundle changes would be to create a
SlingEngineRequestProgressTracker interface (exported) in the engine
bundle, which is RequestProgressTracker + niceties that the actual
engine provides (your changes). The SlingRequestProgressTracker
implements this.

As all the reporting is currently done in the engine bundle that's not
a problem for Sling itself, the engine just gets the tracker and if it
implements SlingEngineRequestProgressTracker uses the additional data.

If someone wants to access that data they can do the same.

WDYT?
-Bertrand