Re: notification output bottleneck

On Wed, Aug 29, 2012 at 1:22 AM, Johan Corveleyn <jcorvel_at_gmail.com> wrote:
> On Wed, Aug 29, 2012 at 12:13 AM, Stefan Fuhrmann
> <stefan.fuhrmann_at_wandisco.com> wrote:
>>
>>
>> On Wed, Aug 29, 2012 at 12:00 AM, Johan Corveleyn <jcorvel_at_gmail.com> wrote:
>>>
>>> On Mon, Aug 27, 2012 at 10:45 AM, Johan Corveleyn <jcorvel_at_gmail.com>
>>> wrote:
>>> > On Mon, Aug 27, 2012 at 2:09 AM, Bert Huijben <bert_at_qqmail.nl> wrote:
>>> >>> -----Original Message-----
>>> >>> From: Johan Corveleyn [mailto:jcorvel_at_gmail.com]
>>> >>> Sent: maandag 27 augustus 2012 00:39
>>> >>> To: Subversion Development
>>> >>> Subject: notification output bottleneck
>>> >>>
>>> >>> I've never noticed this before (slow server, but now I'm testing a
>>> >>> new,
>>> >> faster
>>> >>> server), but it seems that the writing of notification output on
>>> >>> stdout is
>>> >> a
>>> >>> bottleneck for checkout, update or export on Windows (cmd.exe). With a
>>> >>> fast server, hot caches, and everything on a Gb LAN, checkout of a
>>> >>> large
>>> >>> working copy is twice as fast (from 79 minutes down to 35 minutes)
>>> >>> when I
>>> >>> redirect output to NUL. I tested with both 1.7.5 (SlikSVN) and trunk,
>>> >>> the
>>> >>> results were about the same.
>>> >>>
>>> >>> Is there anything that could be done in svn to remove that bottleneck
>>> >>> (buffering, ...)?
>>> >>>
>>> >>> (there might have been some discussion about this before, but I can't
>>> >>> find
>>> >> it)
>>> >>
>>> >> I found this problem too while profiling.
>>> >>
>>> >> The console apis on Windows in the Microsoft libraries are slow because
>>> >> they
>>> >> try to be safe for multithreaded applications. There are some defines
>>> >> that
>>> >> can be used to speed this up (which will avoid the most costly thread
>>> >> synchronisations), but we can't just apply these to our code as that
>>> >> would
>>> >> make libsvn_subr no longer multithread safe.
>>> >
>>> > Interesting.
>>> >
>>> > Am I correct in saying that this is really only a problem for the
>>> > commandline 'svn' client (and perhaps 'svnadmin' and 'svnlook' etc
>>> > ...)? Other clients can do their own fast notification handling,
>>> > right?
>>> >
>>> > And Isn't 'svn' always single-threaded?
>>> >
>>> > In that case: couldn't we make the necessary multithread-unsafe, but
>>> > fast, output functions for 'svn' only?
>>>
>>> Is the above idea possible / sane / desirable?
>>>
>>> Bert, what are those defines to speed up console access at the expense
>>> of thread safety? I'd like to give them a quick try just to see how
>>> much it would impact.
>>>
>>> ISTR from before we migrated to SVN that CVS did not have this
>>> problem: console output would just fly by very quickly. At least
>>> that's how I remember it :-), I haven't run CVS for some time now
>>> (it's also possible that I am misremembering, or that it is because I
>>> was running the client on WinXP back then).
>>
>>
>> 2D (XP) vs. 3D (Vista+) text rendering?
>>
>> If that is the root cause, redirecting to some
>> text file should eliminate the bottleneck - just
>> for testing purposes. From a client perspective,
>> the same API would be used and that also
>> gives us a clearer idea of what part of the
>> system is to blame.
>
> Yep, redirecting to a file eliminates the bottleneck (almost the same
> as redirecting to NUL) (I ran it a couple of times to make sure the
> server cache was hot):
>
> [[[
> C:\Temp\svnperf>timeit svn export https://playsvn/repos export1
> ... snip output ...
> start: 2012-29-08 00:48:49,06
> end : 2012-29-08 00:53:29,07
> total runtime: 280010 ms

BTW, for who's interested, 'timeit' is the following BAT script:

[[[
@ECHO OFF
REM oneliner: cmd /v:on /c "set
start=!date:~9,4!-!date:~3,2!-!date:~6,2! !TIME! & THECOMMAND & echo
start: !start! & echo einde: !date:~9,4!-!date:~3,2!-!date:~6,2!
!TIME!"
SETLOCAL EnableDelayedExpansion

SET T0=!TIME: =0!
SET START=!DATE:~9,4!-!DATE:~3,2!-!DATE:~6,2! !T0!

CALL %*

SET T=!TIME: =0!
SET END=!DATE:~9,4!-!DATE:~3,2!-!DATE:~6,2! !T!

rem make t0 into a scaler in 100ths of a second, being careful not
rem to let SET/A misinterpret 08 and 09 as octal
set /a h=1%t0:~0,2%-100
set /a m=1%t0:~3,2%-100
set /a s=1%t0:~6,2%-100
set /a c=1%t0:~9,2%-100
set /a starttime = %h% * 360000 + %m% * 6000 + 100 * %s% + %c%

rem make t into a scaler in 100ths of a second
set /a h=1%t:~0,2%-100
set /a m=1%t:~3,2%-100
set /a s=1%t:~6,2%-100
set /a c=1%t:~9,2%-100
set /a endtime = %h% * 360000 + %m% * 6000 + 100 * %s% + %c%

rem runtime in 100ths is now just end - start
set /a runtime = %endtime% - %starttime%
set runtime = %s%.%c%

ECHO start: !START! >&2
ECHO end : !END! >&2
ECHO total runtime: %runtime%0 ms >&2

ENDLOCAL
]]]

It doesn't work perfectly (e.g. the calculation fails if the command
spans midnight), but it works well enough for my purposes :-). And I
find it better than timethis.exe, because the latter always writes its
timings to stdout, so if that gets redirected (e.g. to NUL) you lose
the timings. Timeit.bat writes its timings to stderr.

(I didn't write this all by myself, got most of if from some answer on
StackOverflow)

-- 
Johan