subversion-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Philip Martin <philip.mar...@wandisco.com>
Subject Re: 1.9.x JavaHL: long initial delay when performing a log
Date Mon, 16 Mar 2015 20:12:11 GMT
"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*

Mime
View raw message