Crystal: GC Warning: Repeated allocation of very large block

[stugol]

I'm getting this warning sometimes when running my code:

GC Warning: Repeated allocation of very large block (appr. size 8392704):
    May lead to memory leak and poor performance.

I understand the error, but I don't know where in my code the allocation is happening. How can I track this down?

The size of the block changes each time, incidentally. Which is strange.

[asterite]

Issue tracker warning: Repeated bug reports without code to reproduce them.
    May result in no answer.

[asterite]

See also: https://groups.google.com/d/msg/crystal-lang/aEOCoytMpAk/ZXa8eptoCgAJ

[stugol]

@asterite: I know Crystal is free and you don't owe me anything, but is it strictly necessary to go out of your way to be sarcastic and unhelpful? I can't produce code to reproduce the problem without first tracking down the source. I was asking how - given that Crystal has ZERO debugging support, without even line numbers in exceptions - I should go about it.

Seriously, debugging Crystal code is like pulling teeth. And when I ask for help you just take the piss. Rather than criticising MY attitude, I suggest you spend some time considering how yours could be improved.

Incidentally, I found the problem. If a large chunk of data is returned from a recursive function, it is copied each time up the call stack. Maybe you should fix that.

[asterite]

Yes, sorry, instead of asking you again for some code I decided to reply in a more funny way, but my intention was not to offend you, although later I saw that that might have been the case. So then I sent that link showing that I did try to track those things down but was unlucky.

I'll try again later, maybe I was doing something wrong.

Could you still provide the code that returns a large chunk of data in the recursive function?

[stugol]

All good, not to worry. I'll dig out the code when I get a chance.

Could you make Crystal easier to debug, perhaps? Like a "break into debugger and single-step" command? With variable inspection?

[asterite]

I was able to set the warning callback from GC :-)

lib LibGC
  alias WarnProc = LibC::Char*, Word ->
  fun set_warn_proc = GC_set_warn_proc(WarnProc)
  $warn_proc = GC_current_warn_proc : WarnProc
end

LibGC.set_warn_proc ->(msg, word) {
  raise String.new(msg)
}

x = [] of Pointer(Int32)
loop do
  x << Pointer.malloc(10_000_000, 0)
end

This will show the stack trace of where the problem originates.

Now we need to decide what to do in such cases. We still don't understand what's the purpose of that warning: it's just a warning, might not be an error at all. We also don't know if it's safe to allocate memory there (raise allocates).

Right now the debugger is simple, and you can use it. For example:

# foo.cr
def foo
  a = 1
  debugger
  puts a
  a
end

foo

Then:

$ bin/crystal build foo.cr
(lldb) target create "./foo"
Current executable set to './foo' (x86_64).
(lldb) run
Process 48689 launched: './foo' (x86_64)
Process 48689 stopped
* thread #1: tid = 0x228e0e, 0x0000000100002ed0 foo`*foo:Int32 + 16, queue = 'com.apple.main-thread', stop reason = EXC_BREAKPOINT (code=EXC_I386_BPT, subcode=0x0)
    frame #0: 0x0000000100002ed0 foo`*foo:Int32 + 16
foo`*foo:Int32:
->  0x100002ed0 <+16>: movl   -0x4(%rbp), %edi
    0x100002ed3 <+19>: callq  0x100002ef0               ; *puts<Int32>:Nil
    0x100002ed8 <+24>: movl   -0x4(%rbp), %eax
    0x100002edb <+27>: addq   $0x10, %rsp
(lldb) bt
* thread #1: tid = 0x228e0e, 0x0000000100002ed0 foo`*foo:Int32 + 16, queue = 'com.apple.main-thread', stop reason = EXC_BREAKPOINT (code=EXC_I386_BPT, subcode=0x0)
  * frame #0: 0x0000000100002ed0 foo`*foo:Int32 + 16
    frame #1: 0x000000010000122a foo`__crystal_main + 2266
    frame #2: 0x0000000100002e28 foo`main + 40
    frame #3: 0x00007fff99d185ad libdyld.dylib`start + 1
(lldb) ^D

If you compile with debug info (-d):

$ bin/crystal build foo.cr -d
(lldb) target create "./foo"
Current executable set to './foo' (x86_64).
(lldb) run
Process 49171 launched: './foo' (x86_64)
Process 49171 stopped
* thread #1: tid = 0x22960c, 0x00000001000035a0 foo`foo + 16 at foo.cr:1, queue = 'com.apple.main-thread', stop reason = EXC_BREAKPOINT (code=EXC_I386_BPT, subcode=0x0)
    frame #0: 0x00000001000035a0 foo`foo + 16 at foo.cr:1
-> 1    def foo
   2      a = 1
   3      debugger
   4      puts a
   5      a
   6    end
   7    
(lldb) expr a
(int) $0 = 1

It's not working very well yet, and just a few types are supported. But it's a start :-)

[sdogruyol]

Good job @asterite :+1:

[stugol]

@asterite The code was something like the following:

require "http/client"

def download_data(url)
  puts "Downloading from " + url
  response = HTTP::Client.get(url)
  case response.status_code
    when 200
      puts "  Found it"
      return response.body
    when 301, 302, 303, 307, 308
      puts "  Redirecting"
      download_data response.headers["Location"]
    else
      raise Exception.new(url)
  end
end

download_data "http://cache.ruby-lang.org/pub/ruby/stable-snapshot.tar.gz"
puts
download_data "http://sourceforge.net/projects/hd-idle/files/latest/download"

It won't run on play - it just times out. But the problem presumably occurs when a redirection happens, and therefore recursion. I have since refactored it to use a loop. But wouldn't it be a better idea to avoid copying large chunks of data during recursion?

(Is that what is known as "tail-recursion"?)

[luislavena]

@stugol perhaps also because cache.ruby-lang.org takes something between 10-15 seconds to send any header response and the file contents are 17783659 bytes (17MB) ?

That could explain a massive allocation of memory which could explain why GC returns the warning.

As you can see, the more code that you can provide at the beginning of the issue, the better people is going to be able to assist you and perhaps correct a bug (if there is one) or correct the code (if is wrong).

For future reference: http://yourbugreportneedsmore.info/

[stugol]

@luislavena Look, I'm a programmer myself. I know the difference between a good bug report and a bad one. But - for the third time! - _I didn't know what code was causing the problem at the time!_ I was asking for advice on how to narrow it down. I can't provide example code for an issue if I don't know what is causing it. If Crystal had proper debugging support, this wouldn't be so much of an issue. But it doesn't.

How can I download the file without allocating all the memory at once? Is there a way to download it in parts?

[luislavena]

@stugol to quote yourself:

I'm getting this warning sometimes when running my code:

Then there is no mention what you're doing with the code (say, for example, download a file, a chat thing, anything).

Being a programmer doesn't entitle you to be a _good bug reporter_, is a learned technique, but you should learn from several attempts from different folks, on several reported issues, to provide more context about the issue you're reporting.

Crystal does have debugging and while limited in some places (say complex data type inspection) is enough to pinpoint the culprit of such issue.

Also, once again, the key point here are the details, which these bug reports are lacking and thus, is really impossible to assist you and figure out what is going on.

You might want to look at chunked downloads and stream that directly into a temporary file.

As you can see, if you provided this information at the beginning, we could have provided all this without the pointless back and forth and entitlements (and tones) around the conversation.

[stugol]

@luislavena For the FOURTH TIME, I didn't know which part of my code was causing it! It could have been the downloading part, the stream IO part, the logging part, or any other part. Telling you the purpose of my program as a whole would not have helped in any way whatsoever.

I don't know how to do chunked downloading in Crystal. This is why I asked for information a moment ago. Which you didn't provide, incidentally.

"Entitlements"!? I politely asked for help, and was met with sarcasm. If anyone's "tone" or attitude sucks in this thread, it is yours! With respect, @luislavena, please go perform a lewd action with yourself. You are not being helpful, and frankly are getting on my wick.

[refi64]

_cough_ calm down people _cough_ not the end of the world _cough_

[asterite]

Yes, let's calm down a bit, these are just bits on some machine in github, which, if you interpret them in some arbitrary way, might look like offensive text. But they are far from really hurting anyone.

@stugol As I said before, I'm sorry for my sarcastic comment. I didn't mean it to be sarcastic. My answer would have been the same: "Without some code we can't help you, we have no way to reproduce it". I just wanted to add some humour instead of saying that for the 10th time.

The problem you are having might be because you are downloading large chunks of data and building a big string for them. You need to use HTTP Client streaming. If you read the docs you'll see it's almost the only thing that's mentioned there: you pass a block, and the response's body is available as an IO in the body_io method.

As a side note, we have to add automatic (and configurable) redirect for HTTP::Client...

[stugol]

@asterite You and I are fine. We already cleared that up. It was @luislavena's remarks I was objecting to.

Yes, an automatic redirect would be helpful. I was going to ask if such a thing existed; but decided just to code it myself instead.

I vaguely recall seeing something about body_io. So I would just repeatedly pull from it until empty, I assume?

[asterite]

Yes. It's binary data so you'd have to use read(slice) or read bytes. But if you want to download a file to disk you can do:

require "http/client"

HTTP::Client.get("http://cache.ruby-lang.org/pub/ruby/stable-snapshot.tar.gz") do |response|
  File.open("./stable-snapshot.tar.gz", "w") do |file|
    IO.copy(response.body_io, file)
  end
end

But I just tried it and it's much slower than wget (maybe because it's a specialized program), we'd have to see what can be improved there.

[waj]

@asterite It's probably fluctuations in your internet connection. Try with a local HTTP server and a really big file. In my machine I tried and it works faster than wget and I didn't even have to build in release mode :wink:

[stugol]

I didn't know about IO.copy. I notice it uses a buffer size of 1kb. Is this optimal?

[waj]

We could probably redesign the api and use IO#copy_to(target) instead. Most IO are already buffered so we could write from the internal buffer to the target instead of using intermediate memory.

[stugol]

Sounds like a decent idea. Should be pretty simple to do. Maybe if an IO is unbuffered it could automatically do what it currently does; whereas if it's buffered it copies directly?

[stugol]

I'm still getting this warning, despite using IO.copy. My program is quite large, but here are the functions I think are relevant:

def download_data(url, filename)
    $logger << "Downloading ⟨W#{url}⟩ to ⟨W#{filename}⟩"
    response = HTTP::Client.goto(url)
    $logger << "web server returned status " + response.status_code.to_s
    case response.status_code
        when 200
            File.open(filename, "w") do |file|
                IO.copy(response.body_io, file)
            end
        else
            raise FailedDownloadException.new(url)
    end
end

def get_and_extract(url, dirname, archivefile)
    I::FS::Tempdir.create(dirname) do |workingdir|
        $logger << "Created temporary directory ⟨W#{workingdir}⟩"
        local_archivefile = pathname(Dir.current) + archivefile
        Dir.cd workingdir do
            if File.file? local_archivefile
                archivefile = local_archivefile
            else
                download_data url, archivefile
            end
            execute0 %{tar -xzf "#{archivefile}"}
            yield
        end
    end
end

class HTTP::Client
    def self.goto(url)
        loop {
            response = HTTP::Client.get(url)
            case response.status_code
                when 301, 302, 303, 307, 308
                    url = response.headers["Location"]
                else
                    return response
            end
        }
    end
end

def execute0(cmd)
    execute2(cmd) { }
end

def execute3(cmd)
    begin
        $logger << "Executing ⟨b" + cmd + "⟩"
        $logger.with_indent do
            I::FS.execute!(cmd) do |input, output, err|
                yield input, output, err
            end
            Fiber.yield; Fiber.yield
        end
    rescue e
        log_error(e)
        raise e
    end
end

def execute2(cmd, &block : Symbol,String->)
    execute3(cmd) do |input, output, err|
        spawn { while !output.closed?; o = output.read_line; $logger << o; block.call :output, o; end rescue nil }
        spawn { while !err.closed?; o = err.read_line; log_error o; block.call :error, o end rescue nil }
    end
end

module I::FS
    def self.execute!(cmd, echo = false)
        puts "> " + cmd if echo
        args = shellsplit(cmd); cmd = args.shift
        ::IO.pipe { |input_io_read, input_io_write|
            ::IO.pipe { |output_io_read, output_io_write|
                ::IO.pipe { |error_io_read, error_io_write|
                    raise FileNotFoundException.new(cmd) unless (pathname(cmd).is_fully_qualified? ? File.exists?(cmd) : does_command_exist?(cmd))
                    exitcode = 0
                    result = Process.run(cmd, args, nil, false, false, input_io_read, output_io_write, error_io_write) do |p|
                        begin
                            yield input_io_write, output_io_read, error_io_read
                        ensure
                            exitcode = p.wait.exit_code
                        end
                    end
                    raise ProcessRunException.new(cmd, exitcode) unless exitcode == 0
                    return exitcode
                }
            }
        }
    end
end

I doubt it's the $logger at fault; as I use it elsewhere and it works fine there.

[stugol]

The "large block" is reported to be somewhere in the vicinity of 33MB. I don't know why.

[asterite]

It seems you aren't using the block version of http client get, so the whole body is downloaded as a big string.

[stugol]

I wasn't aware that the two versions of the function worked in different ways. Why is this?

[asterite]

Because dealing with a string is easier than dealing with an IO. Also, if we want to reuse a connection for multiple requests we must be sure to read the response before doing a next request, and the block form does that at the end of the block, so you can't forget to close it. For example in Go it's your responsibility to close it, in our case you can't forget to do it.

[stugol]

But couldn't the body property call body_io behind the scenes; and when you do the next request, it can clear the response automatically? Then the block-form and return-form functions would be identical.

[asterite]

That could work, I guess. The client would have to remember the last response and close it before doing a next one. There's always a tradeoff, I'll discuss this with @waj