> 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.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
> 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
>
Received on 2015-03-15 12:01:57 CET