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 👍

[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?