Evgeny Kotkov <evgeny.kotkov_at_visualsvn.com> writes:
> Then, I repeated my tests against the patched and the non-patched 1.9.x
> servers. The results are attached, and they do not show any noticeable
> difference. Does anybody have a strict reproduction script with a 1.9.x
> server that shows the practical benefit from this patch?
Your server is probably too lightly loaded to demonstrate the problem,
the effect is hard to see on my machines until I load the server with
lots of CPU use to slow apache down.
My server runs 1.9.x with apache 2.4 and I am accessing it over a LAN by
running:
strace -tt -etrace=read,writev \
svn log --xml --with-no-revprops \
http://192.168.0.2:8888/repos/asf/subversion/branches/1.8.x > /dev/null
Unpatched I see:
21:23:38.077509 writev(4, [{"REPORT /repos/asf/!svn/rvr/16739"..., 71}, {"Host", 4}, {": ", 2}, {"192.168.0.2:8888", 16}, {"\r\n", 2}, {"Authorization", 13}, {": ", 2}, {"Basic xxxxxxx=", 14}, {"\r\n", 2}, {"User-Agent", 10}, {": ", 2}, {"SVN/1.9.0-dev (x86_64-unknown-li"..., 51}, {"\r\n", 2}, {"Content-Type", 12}, {": ", 2}, {"text/xml", 8}, {"\r\n", 2}, {"Accept-Encoding", 15}, {": ", 2}, {"gzip", 4}, {"\r\n", 2}, {"DAV", 3}, {": ", 2}, {"http://subversion.tigris.org/xml"..., 48}, {"\r\n", 2}, {"DAV", 3}, {": ", 2}, {"http://subversion.tigris.org/xml"..., 52}, {"\r\n", 2}, {"DAV", 3}, {": ", 2}, {"http://subversion.tigris.org/xml"..., 55}, ...], 78) = 634
21:23:39.022082 read(4, "HTTP/1.1 200 OK\r\nDate: Wed, 15 A"..., 8000) = 1448
21:23:39.023438 read(4, "D:version-name>1667532</D:versio"..., 8000) = 6774
21:23:39.028849 read(4, 0xaea894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
21:23:39.841219 read(4, "1f58\r\n</S:log-item>\n<S:log-item>"..., 8000) = 1448
21:23:39.842659 read(4, "<S:log-item>\n<D:version-name>165"..., 8000) = 6584
21:23:39.847769 read(4, 0xaea894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
21:23:40.660558 read(4, "1f58\r\n</S:log-item>\n<S:log-item>"..., 8000) = 1448
21:23:40.662103 read(4, "<S:log-item>\n<D:version-name>164"..., 8000) = 6584
21:23:40.667308 read(4, 0xaea894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
The REPORT is timestamped 21:23:38.077509, the first part of the
response is nearly a second later at 21:23:39.022082 and is 1448+6774
bytes, and each subsequent part is about 800ms after that.
With the patch I see:
21:22:42.040785 writev(4, [{"REPORT /repos/asf/!svn/rvr/16739"..., 71}, {"Host", 4}, {": ", 2}, {"192.168.0.2:8888", 16}, {"\r\n", 2}, {"Authorization", 13}, {": ", 2}, {"Basic xxxxxxx=", 14}, {"\r\n", 2}, {"User-Agent", 10}, {": ", 2}, {"SVN/1.9.0-dev (x86_64-unknown-li"..., 51}, {"\r\n", 2}, {"Content-Type", 12}, {": ", 2}, {"text/xml", 8}, {"\r\n", 2}, {"Accept-Encoding", 15}, {": ", 2}, {"gzip", 4}, {"\r\n", 2}, {"DAV", 3}, {": ", 2}, {"http://subversion.tigris.org/xml"..., 48}, {"\r\n", 2}, {"DAV", 3}, {": ", 2}, {"http://subversion.tigris.org/xml"..., 52}, {"\r\n", 2}, {"DAV", 3}, {": ", 2}, {"http://subversion.tigris.org/xml"..., 55}, ...], 78) = 634
21:22:42.049494 read(4, "HTTP/1.1 200 OK\r\nDate: Wed, 15 A"..., 8000) = 551
21:22:42.049755 read(4, 0x12eb894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
21:22:42.127824 read(4, "330\r\n<S:log-item>\n<D:version-nam"..., 8000) = 823
21:22:42.128224 read(4, 0x12eb894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
21:22:42.394406 read(4, "cc0\r\n<S:log-item>\n<D:version-nam"..., 8000) = 1448
21:22:42.395058 read(4, ":version-name>1667295</D:version"..., 8000) = 1823
21:22:42.396000 read(4, 0x12eb894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
21:22:43.009049 read(4, "1f4a\r\n<S:log-item>\n<D:version-na"..., 8000) = 1448
21:22:43.010348 read(4, "D:version-name>1660372</D:versio"..., 8000) = 6570
21:22:43.015452 read(4, 0x12eb894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
21:22:43.316093 read(4, "13b6\r\n</S:log-item>\n<S:log-item>"..., 8000) = 1448
21:22:43.317421 read(4, "<S:log-item>\n<D:version-name>164"..., 8000) = 3606
21:22:43.320363 read(4, 0x12eb894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
21:22:43.828314 read(4, "1f4a\r\n<S:log-item>\n<D:version-na"..., 8000) = 1448
21:22:43.829645 read(4, "D:version-name>1624268</D:versio"..., 8000) = 6570
21:22:43.834152 read(4, 0x12eb894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
21:22:44.340785 read(4, "1f58\r\n</S:log-item>\n<S:log-item>"..., 8000) = 4344
21:22:44.344273 read(4, "version-name>\n</S:log-item>\n<S:l"..., 8000) = 3688
21:22:44.346968 read(4, 0x12eb894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
21:22:45.057178 read(4, "1f58\r\n</S:log-item>\n<S:log-item>"..., 8000) = 1448
21:22:45.058526 read(4, "<S:log-item>\n<D:version-name>157"..., 8000) = 6584
21:22:45.063241 read(4, 0x12eb894, 8000) = -1 EAGAIN (Resource temporarily unavailable)
The first part of the response is now much quicker, about 10ms, and is
only 551 bytes, subsequent parts get larger in size and more widely
spaced in time.
--
Philip Martin | Subversion Committer
WANdisco // *Non-Stop Data*
Received on 2015-04-15 22:42:14 CEST