luvit/luvit

Issues with code stuck

Closed this issue ยท 17 comments

There's the test code

local Emitter = require('core').Emitter
local i= 0
local Client = Emitter:extend()
function Client:initialize()
  self:on('Method1', function ()
            print('Method1 -- '..i)
            i = i + 1
  end)
end
function Client:start()
while true do
  self:emit('Method1')
end -- END while
end
local x = Client:new()
x:start()

and output stucked like this:

Method1 -- 0
Method1 -- 1
Method1 -- 2
Method1 -- 3
...
Method1 -- 954
Method1 -- 955
Method1 -- 956
Metho

It's stuck the last line. I test this because my server been stucked when I want print some log .

Is someone can help?

I'm not able to reproduce this. What platform and luvit version are you running?

I'm not able to reproduce this. What platform and luvit version are you running?

thks for reply, both macOS Mojave and centos7 with luvit 2.16, At last it will display out of memory if I didn't kill the process.

You're getting out of memory errors with the exact code you posted?

You're getting out of memory errors with the exact code you posted?

Method1 -- 118
Method1 -- 119
Method1 -- 120
Method1 -- 121
Method1 -- 122
Method1 -- not enough memory
the "not enough memory" shows after 1 or 2 minutes, the process memory increaced to 2G my RAM is 16G.
it's ok when i comment the print

there is the luvit version
luvit version: 2.16.0
luvi version: v2.7.6
rex version: 8.37 2015-04-28
libuv version: 1.9.1
ssl version: OpenSSL 1.0.2h 3 May 2016, lua-openssl 0.5.1

LuaJIT 2.0.5 -- Copyright (C) 2005-2017 Mike Pall. http://luajit.org/
Lua 5.3.5 Copyright (C) 1994-2018 Lua.org, PUC-Rio

The version of LuaJIT that Luvit uses has a hard memory limit of 2GB so that part makes sense (see luvit/luvi#211).

The lines not being printed might be something to do with your terminal and how it buffers output? Not sure. I can reproduce the out-of-memory error by running the code for quite a while, and it prints the whole time. Here's the number I get to:

Method1 -- 3449784
Method1 -- 3449785
not enough memory

Not sure why the memory is not being cleaned up, though. That might be a bug.

A simplified example also increases memory consumption.

while true do
  collectgarbage()
  collectgarbage()
  print(collectgarbage('count'))
end

The same does not happen using io.write, so there must be a leak in luvit's custom print.

Looks like it might be in uv.write. This also reproduces the leak.

local uv = require('uv')

local stdout
if uv.guess_handle(1) == 'tty' then
  stdout = assert(uv.new_tty(1, false))
else
  stdout = uv.new_pipe(false)
  uv.pipe_open(stdout, 1)
end

while true do
  collectgarbage()
  collectgarbage()
  stdout:write(collectgarbage('count'))
  stdout:write('\n')
end

this should be move to https://github.com/luvit/luv

Please try this

local uv = require('uv')

local stdout
if uv.guess_handle(1) == 'tty' then
  stdout = assert(uv.new_tty(1, false))
else
  stdout = uv.new_pipe(false)
  uv.pipe_open(stdout, 1)
end

local i=0
while true do
  collectgarbage()
  collectgarbage()
  local ret,reason = stdout:try_write(string.format("%d\t%f\n", i, collectgarbage('count')))
  if ret then
    i=i+1
  else
    if reason:match('^EAGAIN') then
      print('SHOULD TRY')
    else
      assert(ret, reason)
    end
  end
end

I see no leak with that example. Should I open an issue in luvit/luv?

I think I figured out a bit about what's happening. With the following code:

local uv = require('luv')

local stdout
if uv.guess_handle(1) == 'tty' then
  stdout = assert(uv.new_tty(1, false))
else
  stdout = uv.new_pipe(false)
  uv.pipe_open(stdout, 1)
end

for i=1,10 do
  collectgarbage()
  collectgarbage()
  stdout:write(i .. ': ' .. collectgarbage('count') .. '\n', function() print('written ' .. i .. ': ' .. collectgarbage('count')) end)
end

uv.run()

collectgarbage()
collectgarbage()
print('after uv.run(): ' .. collectgarbage('count'))

I get the output:

1: 96.4072265625
2: 96.7607421875
3: 97.1845703125
4: 97.5380859375
5: 97.8916015625
6: 98.3076171875
7: 98.6611328125
8: 99.1396484375
9: 99.4931640625
10: 99.8466796875
written 1: 100.310546875
written 2: 100.4052734375
written 3: 100.5009765625
written 4: 100.5966796875
written 5: 100.6923828125
written 6: 100.7880859375
written 7: 100.8837890625
written 8: 100.9794921875
written 9: 101.0751953125
written 10: 101.1708984375
after uv.run(): 96.6650390625

meaning that none of the callbacks get called until the entire loop is finished. In the code in this comment, this doesn't happen until loop GC during lua_close since uv.run() is never called.

In my code, uv.run() is called which then calls the write callbacks and then allows all those write reqs (and their associated strings) to be freed. try_write doesn't have this problem because it doesn't need to keep the strings around at all.

Not totally sure if this is a flaw in Luv or if it's expected behavior here. Seems like it might be expected behavior? It's kind of weird though.

In my code, uv.run() is called which then calls the write callbacks and then allows all those write reqs (and their associated strings) to be freed. try_write doesn't have this problem because it doesn't need to keep the strings around at all.

Only on tty, in libuv examples, the use try_write to output on tty device.

Maybe Luvit's print wrapper should use try_write instead of write then?

luvit/deps/pretty-print.lua

Lines 300 to 320 in d841d16

-- Print replacement that goes through libuv. This is useful on windows
-- to use libuv's code to translate ansi escape codes to windows API calls.
function _G.print(...)
local n = select('#', ...)
local arguments = {...}
for i = 1, n do
arguments[i] = tostring(arguments[i])
end
uv.write(stdout, table.concat(arguments, "\t"))
uv.write(stdout, "\n")
end
function prettyPrint(...)
local n = select('#', ...)
local arguments = {...}
for i = 1, n do
arguments[i] = dump(arguments[i])
end
uv.write(stdout, table.concat(arguments, "\t"))
uv.write(stdout, "\n")
end

From http://docs.libuv.org/en/v1.x/stream.html#c.uv_write

The memory pointed to by the buffers must remain valid until the callback gets called. This also holds for uv_write2().


From http://docs.libuv.org/en/v1.x/stream.html#c.uv_try_write

Same as uv_write(), but wonโ€™t queue a write request if it canโ€™t be completed immediately.

What implication does this have for print behavior? Is there a chance that data would not be printed? Would we have to maintain a queue?

What implication does this have for print behavior? Is there a chance that data would not be printed?

Probably. See things like #1007 / luvit/lit#222.

Looks like it's not a unique issue.

nodejs/node#3524
nodejs/node#23729

I think it's okay to leave it as is.

Agreed, closing.