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
I can confirm this delay in native code on Windows. I've tried to dig
deeper into svn_ra_get_log2, however I'm lost at
session->vtable->get_log ... is there some kind of "core loop" which
processes incoming HTTP data, so we could place debug output there?
Now I'm really beginning to wonder what the native JavaHL implementation
is doing differently from libsvn_client.
Just a vague idea: could there be some kind of input caching in
low-level HTTP libraries before information is sent to Subversion and
converted to log entries? Maybe JavaHL would initialize this caching
differently than command line or not at all?
-Marc
On 13.03.2015 22:28, Branko Čibej wrote:
[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.strap...@syntevo.com>
Sent: 13-3-2015 20:35
To: dev@subversion.apache.org <mailto:dev@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
DATA
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
