Mark Thomas wrote:
Filip Hanik - Dev Lists wrote:
I'm not sure what we are trying to do in this test, in my mind we are
proving nothing with this test :)
The only purpose of the test is to provide a representative micro
benchmark of the current code vs your suggestion to use ThreadLocals
instead (in the 5.5.x patch file). I wanted to see how much faster
ThreadLocals would be and was surprised to see that they were slower. I
haven't given any thought to why this might be although I am curious.
if you are using thread locals, why would you then do comparison with
the thread local variable with a currentDate volatile variable.
That code for example is wrong.
for example
public Object doLocal() {
StringBuffer buf = new StringBuffer();
Date date = getDateLocal();
if (currentDate != date) {
This doesn't make sense in a thread local environment. That you do a
comparison between a volatile global variable to something that only
gets set in the local variable.
The thread safety in AccessLogValve is the fact that the formatters are
not thread safe and can yield some funky dates showing up.
Agreed.
And in the ideal solution its just not to wrap everything up in a
synchronized statement.
Not agreed. This needs to be considered in context.
- Syncs aren't that expensive.
yes they are, when number of cores go up and clock frequency drops down.
- The microbenchmarks suggest ThreadLocals are actually slightly slower
that's cause the test code is wrong.
(at least on the machines I have been testing on - others may have
different results in which case I'd be interested to see what they are)
- If there is a slight delay, it won't impact the request processing
time, it will just delay the thread being released back to the pool. Any
delay harms scalability rather than response time.
- The microbenchmark suggests the times in question are so small as to
not be worth worrying about in the grand scheme of things.
However, now we have the benchmarch, if anyone wants to propose an
alternative scheme they can use the benchmark to a) test out their idea
and b) prove the relative performance improvements.
I accept the test isn't perfect. It is only meant to give an idea of
relative performance but if an alternative approach took 50% of the time
of the current one I'd +1 it in a heartbeat.
The other thread safety issue in AccessLogValve is the the rotation of
files, since it seems as one thread can close the file
Agreed. I have a simple patch for this. As the writer already uses a
sync, it will cost very little to put a sync around the use of the
writer to fix this.
There are more efficient AccessLogValve, instead of doing all this
comparison crap on every single request, and writing to the file on
every single request.
The comparison really isn't that expensive and the writing is buffered
by default.
put some serious traffic on a system, and you'll see a big difference as
buffers will fill up, and blocking takes place.
An example:
1. single back thread updates the currentDateString once a second.
Yep, that is an alternative solution. Obviously currentDateString would
need to be volatile but as long as only the background thread was doing
the updates you could ditch all the syncs.
that's fine, since even volatile variables get cached on processor
caches during reads, and wont get invalidated unless there is a write to
the variable.
There is already the background processor but this would need to be
separate as the frequency of that is user configurable (and can be
disabled).
2. Add the log entries to the queue, who writes out the buffer once a
second.
The writer is buffered by default anyway.
That's correct.
If you don't want a background thread, then still the stuff going on in
the Benchmark test is not needed, and the bench mark is far from
efficient and there are other ways of doing it much better than we have
today.
The purpose of the benchmark was to give us some concrete numbers to
compare different approaches. The aim was to get relative performance
numbers rather than absolute ones.
I was a little surprised that ThreadLocal seems to be slower. I still
wonder if I got the test wrong for that but I can't see anything.
Writing to a file the way we do it is synchronized, anyway, so the goal
was only to achieve non funky dates.
PrintWriter.java
public void println(String x) {
synchronized (lock) {
print(x);
println();
}
}
Yep. As I noted above, this means adding the sync to fix the issue you
identified of trying to write during roll-over is relatively low cost.
All I merely pointed out, was that the micro benchmark doesn't seem
really related to the actual stuff in AccessLogValve, as it does some
funky comparisons.
If it was me doing the date, and making it all threadlocal, with no
global variables at all
And this will run faster, even though initially creating the thread
local map incurs overhead, it doesn't do unnecessary object creation or
assignment. And there is no need, since we are local at all times.
private void getDateLocal() {
long systime = System.currentTimeMillis();
if ((systime - currentDateLocal.get().getTime()) > 1000) {
currentDateLocal.get().setTime(systime);
localFormatString.set(null);
}
}
public Object doLocal() {
getDateLocal();
if (localFormatString.get()==null) {
StringBuffer current = new StringBuffer(32);
current.append('[');
current.append(dayFormatterLocal.get().format(currentDateLocal.get()));
// Day
current.append('/');
current.append(lookup(monthFormatterLocal.get().format(currentDateLocal.get())));
// Month
current.append('/');
current.append(yearFormatterLocal.get().format(currentDateLocal.get()));
// Year
current.append(':');
current.append(timeFormatterLocal.get().format(currentDateLocal.get()));
// Time
current.append(']');
localFormatString.set(current.toString());
}
return localFormatString.get();
}
fha...@solaris-hp 10:03:08: ~$ java -cp $CLASSPATH:.
org.junit.runner.JUnitCore FHBenchmarks
JUnit version 4.3.1
testAccessLogGetDate: 16 threads and 1000000 iterations using Syncs took
2252ms
testAccessLogGetDate: 16 threads and 1000000 iterations using
ThreadLocals took 738ms
testAccessLogGetDate: 16 threads and 2000000 iterations using Syncs took
4514ms
testAccessLogGetDate: 16 threads and 2000000 iterations using
ThreadLocals took 1587ms
testAccessLogGetDate: 16 threads and 3000000 iterations using Syncs took
2204ms
testAccessLogGetDate: 16 threads and 3000000 iterations using
ThreadLocals took 1984ms
testAccessLogGetDate: 16 threads and 4000000 iterations using Syncs took
2875ms
testAccessLogGetDate: 16 threads and 4000000 iterations using
ThreadLocals took 2644ms
testAccessLogGetDate: 16 threads and 5000000 iterations using Syncs took
3702ms
testAccessLogGetDate: 16 threads and 5000000 iterations using
ThreadLocals took 3257ms
testAccessLogGetDate: 16 threads and 6000000 iterations using Syncs took
4331ms
testAccessLogGetDate: 16 threads and 6000000 iterations using
ThreadLocals took 3924ms
testAccessLogGetDate: 16 threads and 7000000 iterations using Syncs took
5375ms
testAccessLogGetDate: 16 threads and 7000000 iterations using
ThreadLocals took 4485ms
testAccessLogGetDate: 16 threads and 8000000 iterations using Syncs took
5920ms
testAccessLogGetDate: 16 threads and 8000000 iterations using
ThreadLocals took 5081ms
testAccessLogGetDate: 16 threads and 9000000 iterations using Syncs took
6542ms
testAccessLogGetDate: 16 threads and 9000000 iterations using
ThreadLocals took 5878ms
testAccessLogGetDate: 16 threads and 10000000 iterations using Syncs
took 7461ms
testAccessLogGetDate: 16 threads and 10000000 iterations using
ThreadLocals took 6433ms
Time: 81.207
OK (2 tests)
Mark
Filip
sebb wrote:
On 18/06/2009, sebb <seb...@gmail.com> wrote:
On 18/06/2009, Mark Thomas <ma...@apache.org> wrote:
> Tim Funk wrote:
> > I think this needs to be volatile ?
> > In (GetDateBenchmarkTest)
> >> + private long currentMillis = 0;
> >
> > Same for (in TimeDateElementBenchmarkTest)
> >> + private Date currentDate = null;
> >
> > Of course - since the test is single threaded - it doesn't
really matter.
>
>
> The test should be multi-threaded unless I got something badly
wrong. I'll
> double check.
>
> Making those volatile gets them closer to the real code. I doubt
it will make a
> difference but worth changing to be sure. You never know with
these things.
The field GetDateBenchmarkTest.currentDate is set in a synch. block in
doSynch(), but for the return it is fetched outside the synch. block -
so it could potentially be changed by another thread. Also if the
synch. block is not entered, the thread might not see the correct
version of the field as there is no synch. on the read.
Similarly in TimeDateElementBenchmarkTest.getDateSync() - although the
field is volatile, it is set in the synch. block but fetched for the
return outside the block.
If it is intended to allow currentDate to be updated by another thread
before the return, then the field needs to be volatile. Otherwise the
return value needs to be established in the synch. block.
Oops, forgot to mention - there are only 5 threads in the test; it
might be useful to try tests with increasing numbers of threads to see
if the relative numbers change.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
