Mailing-List: contact dev-help@tomcat.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Tomcat Developers List" <dev@tomcat.apache.org>
Received-SPF: pass (nike.apache.org: domain of sebbaz@gmail.com designates
 209.85.216.173 as permitted sender)
DomainKey-Signature: a=rsa-sha1; c=nofws;
        d=gmail.com; s=gamma;
        h=mime-version:in-reply-to:references:date:message-id:subject:from:to
         :content-type:content-transfer-encoding;
        b=dXZDV1MFtqHhlWpbMphh16gEJshrI3cWc7/kRxsxm9MTgtOxxUCzMvwxTbk5f5DE0N
         uGzx82faD0JUrPviPEimq24iy7+pzodBxa/QDlSKso0rxqtYUdaLcbzGlHp7fEWcG3wf
         zMW9NI1KHlC5YDLcM8yanOj9AgXXcnaDWZgGA=
MIME-Version: 1.0
In-Reply-To: <4CD9BEAB.2060003@kippdata.de>
References: <4CD81450.4060200@kippdata.de>
	<4CD9BEAB.2060003@kippdata.de>
Date: Wed, 10 Nov 2010 03:38:21 +0000
Message-ID: <AANLkTinVnL8kqGU_Z4C6xUd+uDdywd=hZqG5tXiU4BKE@mail.gmail.com>
Subject: Re: Objections about formatting options to time stamp in access log
From: sebb <sebbaz@gmail.com>
To: Tomcat Developers List <dev@tomcat.apache.org>
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable

On 9 November 2010 21:35, Rainer Jung <rainer.jung@kippdata.de> wrote:
> On 08.11.2010 16:16, Rainer Jung wrote:
>>
>> A typical annoyance when combining Apache web server and Tomcat is the
>> difference in access log timestamp. Apache logs the beginning of the
>> request, Tomcat logs the end of the request.
>>
>> I added a feature to Apache trunk (will become 2.4) to make it
>> configurable for Apache, which time stamp to choose ([1]). Furthermore
>> the Apache web server allows to choose the format, in which the time
>> stamp is being logged as something different than just "Common Log
>> Format". This is all configured by an appropriate "format" in %{format}t=
.
>
> ...
>>
>> [1] http://httpd.apache.org/docs/trunk/mod/mod_log_config.html#formats
>
> A first draft patch is availabel for review at
>
> http://people.apache.org/~rjung/patches/tomcat-trunk-accesslog-extended-t=
imestamp.patch
>
> Status
> =3D=3D=3D=3D=3D=3D
>
> - docs are still missing
> - tested a bit also under load
> - not yet tested with multiple instances of the access log

The private static fields timezone and timeZone[No]DST are not final,
but appear to be shared between threads.
The method that creates them is synchronised, but methods that read
them don't appear to be.
It would be safer to make these fields final and create them in a
static block (or equivalent).

> - the aspect of async request handling is not clear to me.
> =A0There is request.getCoyoteRequest().getStartTime() and
> =A0request.setAttribute(t1Name, new Long(t1)) and I haven't
> =A0checked the relation between the two at the time of logging.
>
>
> What works
> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
>
> - %t still loggs response end time in Common Log Format
> - %t{FORMAT} logs in configurable format:
> =A0- FORMAT could be either "begin" or "end" or have a prefix of
> =A0 =A0"begin:" or "end:", which means "use the request start time"
> =A0 =A0respectively "use the response end time".
> =A0- stripping the optional prefix the remaining format can be either:
> =A0 =A0- one of the special tokens "sec" (seconds since epoch), "msec"
> =A0 =A0 =A0(milliseconds since epoch) or "msec_frac" (only sub second
> =A0 =A0 =A0milliseconds)
> =A0 =A0- any other remaining format string will be passed to
> =A0 =A0 =A0SimpleDateFormat
>
> Implementation Design
> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
>
> Common Log Format formats and SimpleDateFormat formats are cached (the ot=
her
> special formats are trivial to evaluate). Each different format
> specification occuring in the pattern has its own cache (and
> SimpleDateFormat).
>
> The cache is organized in two levels. A ThreadLocal caches the format for=
 60
> consecutive timestamps, a global synchronized cache for 300 consecutive
> timestamps. The design is more important than in the original implementat=
ion
> because request start times can jump more.
>
> All data is be consistent, i.e. begin times, end times and duration fit
> together even if multiple %{FORMAT}t entries are used in the log pattern.
>
> Finally if a general format string is used, which gets fed into
> SimpleDateFormat, I remove any "S" (milliseconds) and replace it with a
> marker string. This is necessary to allow the cache to be effective.
> Replacing the marker with the milliseconds is a trivial post-formatting t=
as
> and doesn't need complex calendar objects (I know there are leap seconds,
> but well ...).
>
> Performance Implications
> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
>
> I did a few quick stress tests on a two CPU Sparc Server with a trivial o=
ne
> byte plus no sessions JSP. There was no clear difference between the old =
and
> the new implementation (below 5%, which one was faster was not stable,
> around 7.500 requests per second for default config).
>
> Observations
> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
>
> The addElement() in the interface isn't very helpful. The date and time
> arguments are very special for the DateAndTime and ElapsedTime formatter.=
 I
> guess it would be better to have everything needed in request and respons=
e
> or pass a mre generic data object that contains additional meta data. I
> didn't change any of the interfaces though, because it might not be to
> unlikely that people have actually extended existing AccessLog
> implementations.
>
> I can't work on it during the next two days, but there will be some time
> during the weekend to proceed.
>
> Regards,
>
> Rainer
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org