[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: Bert Huijben <bert_at_qqmail.nl>
Date: Sun, 15 Mar 2015 19:30:03 +0100

> -----Original Message-----
> From: Marc Strapetz [mailto:marc.strapetz_at_syntevo.com]
> Sent: zondag 15 maart 2015 12:02
> To: dev_at_subversion.apache.org
> Subject: Re: 1.9.x JavaHL: long initial delay when performing a log
>
> > 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?

Are you using the same libraries in both cases?
(I think TortoiseSVN still explicitly disables ipv6 support in apr)

One case where I sometimes get reports of slow operations is when the used hostname resolves to both an IPv4 and an IPv6 address. (Localhost is such a name on modern windows versions). Using 127.0.0.1 in your local testcode (or making sure the server process and network also work properly on ipv6) might help here. Declaring a specific host-/dns-name for Subversion, resolving to only the addresses really listening is usually the best approach... like it would be for a normal website.

        Bert
>
> -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 19:30:36 CET

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