tomcat-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Filip Hanik - Dev Lists <devli...@hanik.com>
Subject Re: svn commit: r785952 - in /tomcat/trunk/test/org/apache/catalina/valves: ./ Benchmarks.java
Date Fri, 19 Jun 2009 16:01:57 GMT
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();
        }

fhanik@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 <sebbaz@gmail.com> wrote:
>>>  
>>>       
>>>> On 18/06/2009, Mark Thomas <markt@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-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


Mime
View raw message