CGI request takes way longer than actual process

[mierenhoop]

Hi,
I'm trying out fm.serveContent("cgi", ...) with cgit. Cgit itself takes ~20ms on a simple page, but when running it through fullmoon's CGI module the request takes ~520 ms (measured with time curl ...).
The issue seems to occur at

fullmoon/fullmoon.lua

Line 1728 in 9d62cff

local se = (unix.poll({[rfd1] = unix.POLLIN}, maxtime*1000/10) or {})[rfd1] or 0

When using the default maxtime of 5, maxtime*1000/10 makes a 500ms timeout which makes up all the unexpected added time. It seems that the poll will not return even when the process is closed. When hardcoding the timeout to 1ms the request is finished in the expected ~20ms, with the downside that this poll is called >100 times.
Maybe a solution would be to make poll react to the process closing or if that's not possible starting at a low timeout and each iteration exponentially increasing that until maxtime is reached.
Tested on Debian 12 with the latest redbean and latest fullmoon.

[pkulchenko]

@mierenhoop, thank you for the report. I think you're correct both in your analysis and in your proposed resolution. Let me see if I can find a proper fix for it.

[pkulchenko]

@mierenhoop, can you try the following patch:

diff --git a/fullmoon.lua b/fullmoon.lua
index 10f5bf5..fcd47c1 100644
--- a/fullmoon.lua
+++ b/fullmoon.lua
@@ -1723,9 +1723,11 @@ fm.setTemplate("cgi", function(cmd)
     assert(unix.sigaction(unix.SIGALRM, function() isactive = false end))
     assert(unix.setitimer(unix.ITIMER_REAL, 0, 0, maxtime, 0))
     local cfd = GetClientFd()
+    local waittime = 1/2
     while true do
       -- block for a bit until there is output from the launched process
-      local se = (unix.poll({[rfd1] = unix.POLLIN}, maxtime*1000/10) or {})[rfd1] or 0
+      waittime = math.min(waittime * 2, maxtime*1000/10)
+      local se = (unix.poll({[rfd1] = unix.POLLIN}, waittime) or {})[rfd1] or 0
       if se & (unix.POLLHUP + unix.POLLERR) > 0 then break end
 
       -- check if the client is (still) writable

[mierenhoop]

Thanks, that's a big improvement.
Here's some benchmarks:
$ wrk --latency http://localhost:8080/cgit
Fullmoon at HEAD:

  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   513.12ms   63.30ms   1.01s    98.40%
    Req/Sec    13.13     12.49    40.00     80.85%
  Latency Distribution
     50%  504.76ms
     75%  506.16ms
     90%  507.37ms
     99%    1.01s

With your patch applied:

  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    65.38ms   96.48ms 537.72ms   90.65%
    Req/Sec    83.67     45.31   202.00     69.00%
  Latency Distribution
     50%   22.67ms
     75%   71.69ms
     90%  151.77ms
     99%  504.16ms

With a constant timeout of 1ms (shown in patch below), this should be the fastest possible.

diff --git a/fullmoon.lua b/fullmoon.lua
index 10f5bf5..8b02da6 100644
--- a/fullmoon.lua
+++ b/fullmoon.lua
@@ -1725,7 +1725,7 @@ fm.setTemplate("cgi", function(cmd)
     local cfd = GetClientFd()
     while true do
       -- block for a bit until there is output from the launched process
-      local se = (unix.poll({[rfd1] = unix.POLLIN}, maxtime*1000/10) or {})[rfd1] or 0
+      local se = (unix.poll({[rfd1] = unix.POLLIN}, 1) or {})[rfd1] or 0
       if se & (unix.POLLHUP + unix.POLLERR) > 0 then break end

       -- check if the client is (still) writable

  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     9.77ms    2.32ms  20.45ms   69.35%
    Req/Sec   178.48     35.61   292.00     64.50%
  Latency Distribution
     50%    9.56ms
     75%   11.18ms
     90%   12.84ms
     99%   15.86ms

[mierenhoop]

Hi, I have found a fix that appears to completely resolve the issue.

diff --git a/fullmoon.lua b/fullmoon.lua
index 10f5bf5..7195e84 100644
--- a/fullmoon.lua
+++ b/fullmoon.lua
@@ -1721,6 +1721,7 @@ fm.setTemplate("cgi", function(cmd)
     local header = true
     local done = false
     assert(unix.sigaction(unix.SIGALRM, function() isactive = false end))
+    assert(unix.sigaction(unix.SIGCHLD, function() isactive = false end))
     assert(unix.setitimer(unix.ITIMER_REAL, 0, 0, maxtime, 0))
     local cfd = GetClientFd()
     while true do

SIGCHLD is sent when the child process exits, it happens before the poll() that runs out the entire timeout. We can break out of the loop before that call by setting isactive to false.

[pkulchenko]

I like it; that's a great find. Does this work for you even with the "original" 500ms poll timeout? So, that would be the only change needed?

Would you like to submit a PR for it or do you want me to apply it? I'd probably do something like this:

    local header = true
    local done = false
    local isactive = true
    local function stop() isactive = false end)
    assert(unix.sigaction(unix.SIGCHLD, stop))
    assert(unix.sigaction(unix.SIGALRM, stop))

[mierenhoop]

Does this work for you even with the "original" 500ms poll timeout? So, that would be the only change needed?

Yes.

Apparently, we instead can just check if wait() returns the child pid to indicate it has been terminated. If that is the case, we should probably poll/read once more with a timeout of 0.

diff --git a/fullmoon.lua b/fullmoon.lua
index 10f5bf5..a3c4b87 100644
--- a/fullmoon.lua
+++ b/fullmoon.lua
@@ -1720,12 +1720,13 @@ fm.setTemplate("cgi", function(cmd)
     local isactive = true
     local header = true
     local done = false
+    local timeout = maxtime*1000/10
     assert(unix.sigaction(unix.SIGALRM, function() isactive = false end))
     assert(unix.setitimer(unix.ITIMER_REAL, 0, 0, maxtime, 0))
     local cfd = GetClientFd()
     while true do
       -- block for a bit until there is output from the launched process
-      local se = (unix.poll({[rfd1] = unix.POLLIN}, maxtime*1000/10) or {})[rfd1] or 0
+      local se = (unix.poll({[rfd1] = unix.POLLIN}, timeout) or {})[rfd1] or 0
       if se & (unix.POLLHUP + unix.POLLERR) > 0 then break end

       -- check if the client is (still) writable
@@ -1791,8 +1792,15 @@ fm.setTemplate("cgi", function(cmd)
         break
       end
       -- stop reading if the process is already done
-      done = not unix.wait(pid, unix.WNOHANG)
-      if done then break end
+      local termpid = unix.wait(pid, unix.WNOHANG)
+      if not termpid then
+        done = true
+        break
+      elseif termpid == pid then
+        done = true
+        isactive = false
+        timeout = 0
+      end
     end
     unix.close(rfd1)
     unix.close(wfd1)

If you're OK with this, I'll make a pull request.