Requests slow/unreliable in 4.2.0-alpha

[melink14]

I just installed 4.2.0 on ubuntu to be used in public server mode and it seems quite flaky.

Often, clicking on an action will take many seconds to resolve and it seems to lose state as well. For example, warnings dismissed "until I log out" come back after these slow requests finally resolve.

using kol directly is fast and great.

I tried turning off fast connections but the problem persisted.

Let me know if there's something else I can do to debug the problems. it's hard to play without kolproxy but currently the waits are something else.

(github did not keep the formatting at all so also at http://pastebin.com/pyCVz7uc)
Sample request from timing log:
request: /place.php?whichplace=desertbeach [2016-12-03 22:53:39.333712 UTC :<] make ref for: /place.php?whichplace=desertbeach ( 683.4ms) [2016-12-03 22:53:39.336002 UTC ::::<] setup lua: scripts/kolproxy-internal/browser-request.lua ( 2.3ms) [2016-12-03 22:53:41.559621 UTC ::::<] do lua loading code: scripts/kolproxy-internal/browser-request.lua ( 2223.6ms) [2016-12-03 22:53:41.559658 UTC :::<] setup lua instance: scripts/kolproxy-internal/browser-request.lua|BROWSERREQUEST ( 2225.9ms) [2016-12-03 22:53:41.839426 UTC :::::<] fetchpage: /charsheet.php ( 270.4ms) [2016-12-03 22:53:41.840901 UTC ::::::<] setup lua: scripts/kolproxy-internal/process-page.lua ( 1.5ms) [2016-12-03 22:53:43.786897 UTC ::::::<] do lua loading code: scripts/kolproxy-internal/process-page.lua ( 1946.0ms) [2016-12-03 22:53:43.787147 UTC :::::<] setup lua instance: scripts/kolproxy-internal/process-page.lua|PROCESS ( 1947.7ms) [2016-12-03 22:53:43.79323 UTC ::::::<] run lua code: scripts/kolproxy-internal/process-page.lua ( 4.2ms) [2016-12-03 22:53:43.793469 UTC ::::<] processing: /charsheet.php ( 1954.0ms) [2016-12-03 22:53:44.024671 UTC :::::<] fetchpage: /place.php?whichplace=desertbeach ( 200.4ms) [2016-12-03 22:53:44.213651 UTC :::::<] run lua code: scripts/kolproxy-internal/process-page.lua ( 188.3ms) [2016-12-03 22:53:44.213686 UTC ::::<] processing: /place.php?whichplace=desertbeach ( 189.0ms) [2016-12-03 22:53:44.42232 UTC ::::<] fetchpage: /council.php ( 205.8ms) [2016-12-03 22:53:44.620427 UTC :::::<] run lua code: scripts/kolproxy-internal/process-page.lua ( 197.4ms) [2016-12-03 22:53:44.620511 UTC ::::<] processing: /council.php ( 198.2ms) [2016-12-03 22:53:44.840382 UTC ::::<] fetchpage: /campground.php ( 219.6ms) [2016-12-03 22:53:45.218028 UTC :::::<] fetchpage: /campground.php ( 596.0ms) [2016-12-03 22:53:45.407482 UTC ::::::<] run lua code: scripts/kolproxy-internal/process-page.lua ( 566.4ms) [2016-12-03 22:53:45.407542 UTC :::::<] processing: /campground.php ( 567.2ms) [2016-12-03 22:53:45.420362 UTC ::::::<] run lua code: scripts/kolproxy-internal/process-page.lua ( 12.0ms) [2016-12-03 22:53:45.420435 UTC ::::::<] processing: /campground.php ( 202.4ms) [2016-12-03 22:53:45.635648 UTC :::::<] fetchpage: /diary.php?whichpage=1 ( 189.8ms) [2016-12-03 22:53:46.00542 UTC ::::::<] fetchpage: /diary.php?textversion=1 ( 559.1ms) [2016-12-03 22:53:46.196399 UTC :::::::<] run lua code: scripts/kolproxy-internal/process-page.lua ( 560.1ms) [2016-12-03 22:53:46.196554 UTC ::::::<] processing: /diary.php?whichpage=1 ( 560.9ms) [2016-12-03 22:53:46.198566 UTC :::::<] run lua code: scripts/kolproxy-internal/process-page.lua ( 1.6ms) [2016-12-03 22:53:46.198588 UTC :::::::<] processing: /diary.php?textversion=1 ( 193.2ms) [2016-12-03 22:53:46.251099 UTC :::<] run lua code: scripts/kolproxy-internal/browser-request.lua ( 4687.6ms) [2016-12-03 22:53:46.251379 UTC ::<] browser request: /place.php?whichplace=desertbeach ( 6917.7ms) [2016-12-03 22:53:46.251383 UTC :<] run handler for: /place.php?whichplace=desertbeach ( 6917.7ms) [2016-12-03 22:53:46.251385 UTC <] creating response for: /place.php?whichplace=desertbeach ( 7601.2ms)

[melink14]

In order to debug more, are there flags/env variables I can set to get more logging? The next step seems to be profiling browser-request.lua at least. Which seems to be very slow.