[svn.haxx.se] · SVN Dev · SVN Users · SVN Org · TSVN Dev · TSVN Users · Subclipse Dev · Subclipse Users · this month's index

Re: 1.9.x JavaHL: long initial delay when performing a log

From: Branko Čibej <brane_at_wandisco.com>
Date: Fri, 13 Mar 2015 22:28:14 +0100

[Since when are we top-posting? grr...]

On 13.03.2015 21:17, Bert Huijben wrote:
> Are you requesting the results in the same order in both cases? (I
> don't know what the arguments in your code represent)
> If you retrieve oldest to youngest some delay is expected as then
> first all interesting revisions are fetched (youngest to oldest) and
> then results+detailed are spooled back the other way.

It's a standard youngest-to-oldest log; parameters for getLogs are
(paths, start-revision, end-revision, limit, ...).

> The normal svn invocation you compare to is the most efficient one...
> Bert
> ------------------------------------------------------------------------
> From: Marc Strapetz <mailto:marc.strapetz_at_syntevo.com>
> Sent: ‎13-‎3-‎2015 20:35
> To: dev_at_subversion.apache.org <mailto:dev_at_subversion.apache.org>
> Subject: 1.9.x JavaHL: long initial delay when performing a log
> I'm experiencing a strange initial delay when performing a log using
> JavaHL.
> svn log http://svn.apache.org/repos/asf/subversion/branches/1.8.x
> shows first results after 2-3 seconds, while following code snippet
> takes at least 20 seconds (sometimes significantly more, might depend on
> the server's load):
> ISVNRemote session =
> factory.openRemoteSession("http://svn.apache.org/repos/asf");
> List<String> paths =
> Collections.singletonList("subversion/branches/1.8.x");
> session.getLog(paths, Revision.SVN_INVALID_REVNUM, 0, 0, false,
> false, false, null, new LogMessageCallback() {
> public void singleMessage(Set<ChangePath> changedPaths,
> long revision, Map<String, byte[]> revprops, boolean hasChildren) {
> System.out.println("DATA");
> }
> });
> Once the log responds, a bunch of revisions are reported, so it seems
> that there is some kind of caching of log records.

I tried this with a slight change, setting the limit parameter of
getLog() to 1 instead of 0; here are the results:

$ time svn log --limit 1 http://svn.apache.org/repos/asf/subversion/branches/1.8.x

real 0m1.574s
user 0m0.007s
sys 0m0.006s

$ time java -cp ... -Djava.library.path=... TestStatus

real 0m1.430s
user 0m0.138s
sys 0m0.036s

So, no real difference here.

Without the limit, it does take a bit more than 10 seconds to begin
displaying results. So I tested when the callback was actually invoked:
I added code to print the current time just before the call to getLog(),
and the current time and revision in the log receiver callback. The
output confirms that the delay is real and not, for example, an artefact
of some caching in stdout, for example:

$ time java -cp ... -Djava.library.path=... TestStatus
2015-03-13 21:59:46.731
2015-03-13 21:59:57.223 1666354
2015-03-13 21:59:57.223 1666269
2015-03-13 22:00:27.318 836421
2015-03-13 22:00:27.318 836420

> I've tested with latest 1.9.x sources on Windows but have seen the same
> behavior with javahl-1.8-extensions branch on Linux, too.

Same here on OSX. However, I can't any place in the code that would
cause the delay. I added similar time-printing code to the C++ part of
JavaHL and got extremely strange results:

TestStatus (Java): 2015-03-13 22:21:40.403
svn_ra_get_log2: 2015-03-13T21:21:40.404731Z
callback: 2015-03-13T21:21:50.098592Z
invoke: 2015-03-13T21:21:50.098671Z
TestStatus (Java): 2015-03-13 22:21:50.098 1666354
return: 2015-03-13T21:21:50.099058Z

(note that there's an hour of difference between local time printed by
Java and UTC printed from the native code).

This confirms that there is an actual delay of 10 seconds in the
*native* code between the call to svn_ra_get_log2() and the first
invocation of the (native) callback wrapper; each callback invocation
takes about half a millisecond.

Now I'm really beginning to wonder what the native JavaHL implementation
is doing differently from libsvn_client.

-- Brane
Received on 2015-03-13 22:28:51 CET

This is an archived mail posted to the Subversion Dev mailing list.