Mailing-List: contact dev-help@subversion.apache.org; run by ezmlm
Precedence: bulk
Received-SPF: pass (athena.apache.org: domain of philip.martin@wandisco.com
 designates 209.85.212.178 as permitted sender)
From: Philip Martin <philip.martin@wandisco.com>
To: "Bert Huijben" <bert@qqmail.nl>
Cc: "'Julian Foad'" <julianfoad@btopenworld.com>,
  "'Marc Strapetz'" <marc.strapetz@syntevo.com>,
  "'dev'" <dev@subversion.apache.org>
Subject: Re: 1.9.x JavaHL: long initial delay when performing a log
References: <55033BBE.2000905@syntevo.com>
	<089f01d05f83$2673c460$735b4d20$@qqmail.nl>
	<5506B7BD.3090406@syntevo.com>
	<CAEcU=1YWSgUz2EPRBK3acm0K9JdN_BxJ1HAiyVh0GZ5=sizTVA@mail.gmail.com>
	<091201d05ff4$7491de40$5db59ac0$@qqmail.nl>
	<CAEcU=1ZsW99y3MLfkYZoWdp70dGcLRdZzBweb1Yv93r2MyfARA@mail.gmail.com>
	<871tkozx5e.fsf@wandisco.com>
	<002601d0601b$cd44dc50$67ce94f0$@qqmail.nl>
Date: Mon, 16 Mar 2015 20:12:11 +0000
In-Reply-To: <002601d0601b$cd44dc50$67ce94f0$@qqmail.nl> (Bert Huijben's
	message of "Mon, 16 Mar 2015 20:02:50 +0100")
Message-ID: <87r3soya5g.fsf@wandisco.com>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/24.4 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain

"Bert Huijben" <bert@qqmail.nl> writes:

> Nice idea on the concept, but this patch doesn't implement that behavior
>
> You will see the first result very fast. (No behavior change)

I don't understand, I see a behaviour change when I try it.

The first few writes with my patch:

[pid  8814] writev(17, [{"HTTP/1.1 200 OK\r\nDate: Mon, 16 M"..., 189}, {"1f53\r\n", 6}, {"<?xml version=\"1.0\" encoding=\"ut"..., 7965}, {"<S:log-item>\n<D:version-name>166"..., 54}, {"\r\n", 2}], 5) = 8216
[pid  8814] writev(17, [{"1f55\r\n", 6}, {"<D:creator-displayname>rhuijben<"..., 7976}, {"<S:date>2015-02-14T00:17:25.9215"..., 45}, {"\r\n", 2}], 4) = 8029
[pid  8814] writev(17, [{"1f6d\r\n", 6}, {"</S:log-item>\n<S:log-item>\n<D:ve"..., 8000}, {"<S:date>2015-01-15T04:00:33.4982"..., 45}, {"\r\n", 2}], 4) = 8053
[pid  8814] writev(17, [{"1f4e\r\n", 6}, {"</S:log-item>\n<S:log-item>\n<D:ve"..., 7958}, {"<D:creator-displayname>rhuijben<"..., 56}, {"\r\n", 2}], 4) = 8022
[pid  8814] writev(17, [{"1f47\r\n", 6}, {"<S:date>2014-11-25T12:20:06.2266"..., 7953}, {"<S:log-item>\n<D:version-name>162"..., 54}, {"\r\n", 2}], 4) = 8015
[pid  8814] writev(17, [{"ba0\r\n", 5}, {"<D:creator-displayname>stsp</D:c"..., 2976}, {"\r\n", 2}], 3) = 2983
[pid  8814] writev(17, [{"1f52\r\n", 6}, {"<S:log-item>\n<D:version-name>161"..., 7973}, {"<S:date>2014-06-30T13:46:18.9128"..., 45}, {"\r\n", 2}], 4) = 8026

The current code without my patch:

[pid  9113] writev(17, [{"HTTP/1.1 200 OK\r\nDate: Mon, 16 M"..., 189}, {"fd\r\n", 4}, {"<?xml version=\"1.0\" encoding=\"ut"..., 253}, {"\r\n", 2}], 4) = 448
[pid  9113] writev(17, [{"a9\r\n", 4}, {"<S:log-item>\n<D:version-name>166"..., 169}, {"\r\n", 2}], 3) = 175
[pid  9113] writev(17, [{"14e\r\n", 5}, {"<S:log-item>\n<D:version-name>166"..., 334}, {"\r\n", 2}], 3) = 341
[pid  9113] writev(17, [{"294\r\n", 5}, {"<S:log-item>\n<D:version-name>166"..., 660}, {"\r\n", 2}], 3) = 667
[pid  9113] writev(17, [{"53a\r\n", 5}, {"<S:log-item>\n<D:version-name>166"..., 1338}, {"\r\n", 2}], 3) = 1345
[pid  9113] writev(17, [{"a7c\r\n", 5}, {"<S:log-item>\n<D:version-name>166"..., 2684}, {"\r\n", 2}], 3) = 2691
[pid  9113] writev(17, [{"1511\r\n", 6}, {"<S:log-item>\n<D:version-name>166"..., 5393}, {"\r\n", 2}], 3) = 5401
[pid  9113] writev(17, [{"1f46\r\n", 6}, {"<S:log-item>\n<D:version-name>166"..., 7951}, {"<D:creator-displayname>stefan2</"..., 55}, {"\r\n", 2}], 4) = 8014
[pid  9113] writev(17, [{"aba\r\n", 5}, {"<S:date>2015-02-13T10:00:18.5170"..., 2746}, {"\r\n", 2}], 3) = 2753
[pid  9113] writev(17, [{"1f61\r\n", 6}, {"<S:log-item>\n<D:version-name>165"..., 7988}, {"<S:date>2014-12-06T02:05:01.7811"..., 45}, {"\r\n", 2}], 4) = 8041
[pid  9113] writev(17, [{"1f60\r\n", 6}, {"</S:log-item>\n<S:log-item>\n<D:ve"..., 7976}, {"<D:creator-displayname>rhuijben<"..., 56}, {"\r\n", 2}], 4) = 8040
[pid  9113] writev(17, [{"153a\r\n", 6}, {"<S:date>2014-10-20T12:44:19.4131"..., 5434}, {"\r\n", 2}], 3) = 5442


> BTW 500 msec is about two or three the time you expect for google page of
> results.... Why this arbritrary number?

How do you explain the 2 and 2048 in the current code?  They are all
just arbitrary numbers.  Make it 100ms instead of 500ms.  The trace
above is what I got for a debug build and 200ms.  Several 8K writes in
the first 200ms followed by a short 3K write when the first extra flush
triggers after 200ms.  That's a very fast server that doesn't need the
extra flushes.

If I introduce a delay into the log loop, 50ms between revisions, I see
more of the extra flushes:

[pid  9751] writev(17, [{"HTTP/1.1 200 OK\r\nDate: Mon, 16 M"..., 189}, {"588\r\n", 5}, {"<?xml version=\"1.0\" encoding=\"ut"..., 1416}, {"\r\n", 2}], 4) = 1612
[pid  9751] writev(17, [{"53a\r\n", 5}, {"<S:log-item>\n<D:version-name>166"..., 1338}, {"\r\n", 2}], 3) = 1345
[pid  9751] writev(17, [{"a7c\r\n", 5}, {"<S:log-item>\n<D:version-name>166"..., 2684}, {"\r\n", 2}], 3) = 2691
[pid  9751] writev(17, [{"1511\r\n", 6}, {"<S:log-item>\n<D:version-name>166"..., 5393}, {"\r\n", 2}], 3) = 5401
[pid  9751] writev(17, [{"1f46\r\n", 6}, {"<S:log-item>\n<D:version-name>166"..., 7951}, {"<D:creator-displayname>stefan2</"..., 55}, {"\r\n", 2}], 4) = 8014
[pid  9751] writev(17, [{"aba\r\n", 5}, {"<S:date>2015-02-13T10:00:18.5170"..., 2746}, {"\r\n", 2}], 3) = 2753
[pid  9751] writev(17, [{"1f61\r\n", 6}, {"<S:log-item>\n<D:version-name>165"..., 7988}, {"<S:date>2014-12-06T02:05:01.7811"..., 45}, {"\r\n", 2}], 4) = 8041
[pid  9751] writev(17, [{"1f60\r\n", 6}, {"</S:log-item>\n<S:log-item>\n<D:ve"..., 7976}, {"<D:creator-displayname>rhuijben<"..., 56}, {"\r\n", 2}], 4) = 8040
[pid  9751] writev(17, [{"153a\r\n", 6}, {"<S:date>2014-10-20T12:44:19.4131"..., 5434}, {"\r\n", 2}], 3) = 5442
[pid  9751] writev(17, [{"1f52\r\n", 6}, {"<S:log-item>\n<D:version-name>161"..., 7973}, {"<S:date>2014-06-30T13:46:18.9128"..., 45}, {"\r\n", 2}], 4) = 8026

The first flush happens after 8 revisions because the first 4 revisions
all get written within the first 200ms.  The 8th revision is the first
flush after 200ms.

I'm not claiming this is the best algorithm, I just want to know if it
is the sort of thing we want.

-- 
Philip Martin | Subversion Committer
WANdisco // *Non-Stop Data*