Ruby Forum Ruby > help me debug my stack trace

Posted by Roger Pack (rogerdpack)
on 20.05.2008 00:25
So currently ruby is hung using 100% CPU on my machine.

Some questions:
1) does anybody else have this happen to them?
2) does anybody else have a chunk of code that reliably causes ruby to
leak memory?

Anyway here are some sample stack traces, if anybody has any pointers.
Thanks!
-R

  1  24540            select$UNIX2003:entry
  1  24523        select$DARWIN_EXTSN:entry
  1  23368             _sysenter_trap:entry
  1  22941          ruby_stack_length:entry
  1  23392                     memcpy:entry
  1  23094            rb_lastline_get:entry
  1  22804                    rb_svar:entry
  1  23095            rb_lastline_set:entry
  1  22804                    rb_svar:entry
  1  23092             rb_backref_get:entry
  1  22804                    rb_svar:entry
  1  23093             rb_backref_set:entry
  1  22804                    rb_svar:entry
  1  23991                    _setjmp:entry
  1  23392                     memcpy:entry
  1  23094            rb_lastline_get:entry
  1  22804                    rb_svar:entry
  1  23095            rb_lastline_set:entry
  1  22804                    rb_svar:entry
  1  23092             rb_backref_get:entry
  1  22804                    rb_svar:entry
  1  23093             rb_backref_set:entry
  1  22804                    rb_svar:entry
  1  23992                   _longjmp:entry
  1  24032                       time:entry
  1  28005                   fegetenv:entry
  1  23952               gettimeofday:entry
  1  23953    __commpage_gettimeofday:entry
  1  28000                   fesetenv:entry
  1  22874         rb_thread_schedule:entry
  1  22806      is_ruby_native_thread:entry
  1  23481               pthread_self:entry
  1  23868              pthread_equal:entry
  1  23356                     memset:entry
  1  23356                     memset:entry
  1  23356                     memset:entry
  1  23952               gettimeofday:entry
  1  23953    __commpage_gettimeofday:entry
  1  24540            select$UNIX2003:entry
  1  24523        select$DARWIN_EXTSN:entry
  1  23368             _sysenter_trap:entry
  1  22943        rb_gc_force_recycle:entry
  1  22871              rb_need_block:entry
  1  22960                  rb_newobj:entry
  1  23991                    _setjmp:entry
  1  22749               rb_scan_args:entry
  1  22987          rb_io_taint_check:entry
  1  22790            rb_check_frozen:entry
  1  23015         rb_io_check_closed:entry
  1  24902                     fseeko:entry
  1  23383                    __error:entry
  1  24293                  flockfile:entry
  1  23481               pthread_self:entry
  1  23409         pthread_mutex_lock:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  24177                    _fseeko:entry
  1  24180                    _ftello:entry
  1  24155                   __sflush:entry
  1  24181                     _sseek:entry
  1  23383                    __error:entry
  1  23383                    __error:entry

these errors are disconcerting

  1  24182                    __sseek:entry
  1  23895                      lseek:entry
  1  23383                    __error:entry
  1  23383                    __error:entry
  1  23383                    __error:entry
  1  24184                  __srefill:entry
  1  24185                     _sread:entry
  1  24186                    __sread:entry
  1  23377                       read:entry
  1  23368             _sysenter_trap:entry
  1  24294                funlockfile:entry
  1  23481               pthread_self:entry
  1  23410       pthread_mutex_unlock:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  23383                    __error:entry
  1  24919                   clearerr:entry
  1  24293                  flockfile:entry
  1  23481               pthread_self:entry
  1  23409         pthread_mutex_lock:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  24294                funlockfile:entry
  1  23481               pthread_self:entry
  1  23410       pthread_mutex_unlock:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  22987          rb_io_taint_check:entry
  1  22790            rb_check_frozen:entry
  1  23015         rb_io_check_closed:entry
  1  24212                     fileno:entry
  1  24293                  flockfile:entry
  1  23481               pthread_self:entry
  1  23409         pthread_mutex_lock:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  24294                funlockfile:entry
  1  23481               pthread_self:entry
  1  23410       pthread_mutex_unlock:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  23887                      fstat:entry
  1  23368             _sysenter_trap:entry
  1  23242                rb_time_new:entry
  1  22962               ruby_xmalloc:entry
  1  23385                     malloc:entry
  1  23386         malloc_zone_malloc:entry
  1  23387               szone_malloc:entry
  1  23471                  spin_lock:entry
  1  23416 tiny_malloc_from_free_list:entry
  1  23448     tiny_free_list_add_ptr:entry
  1  23472               _spin_unlock:entry
  1  22961       rb_data_object_alloc:entry
  1  22960                  rb_newobj:entry
  1  22788              rb_check_type:entry
  1  22788              rb_check_type:entry
  1  22867                 rb_funcall:entry
  1  22788              rb_check_type:entry
  1  22788              rb_check_type:entry
  1  22756                  rb_cmpint:entry
  1  24032                       time:entry
  1  28005                   fegetenv:entry
  1  23952               gettimeofday:entry
  1  23953    __commpage_gettimeofday:entry
  1  28000                   fesetenv:entry
  1  23244           rb_time_interval:entry
  1  22883         rb_thread_wait_for:entry
  1  23952               gettimeofday:entry
  1  23953    __commpage_gettimeofday:entry
  1  22874         rb_thread_schedule:entry
  1  22806      is_ruby_native_thread:entry
  1  23481               pthread_self:entry
  1  23868              pthread_equal:entry
  1  23356                     memset:entry
  1  23356                     memset:entry
  1  23356                     memset:entry
  1  23952               gettimeofday:entry
  1  23953    __commpage_gettimeofday:entry
  1  24540            select$UNIX2003:entry
  1  24523        select$DARWIN_EXTSN:entry
  1  23368             _sysenter_trap:entry
  1  23367                     cerror:entry
  1  23382     cthread_set_errno_self:entry
  1  23383                    __error:entry
  1  23383                    __error:entry

there seem to be some thread problems?

  1  23899 pthread_testcancel$UNIX2003:entry
  1  23399        _pthread_testcancel:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  23398         nanosleep$UNIX2003:entry
  1  23399        _pthread_testcancel:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  24628             clock_get_time:entry
  1  23406         mig_get_reply_port:entry
  1  23407                   mach_msg:entry
  1  23327              mach_msg_trap:entry
  1  23368             _sysenter_trap:entry
  1  23400           __semwait_signal:entry
  1  23368             _sysenter_trap:entry
  1  23367                     cerror:entry
  1  23382     cthread_set_errno_self:entry
  1  23383                    __error:entry
  1  23383                    __error:entry
  1  23899 pthread_testcancel$UNIX2003:entry
  1  23399        _pthread_testcancel:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  23398         nanosleep$UNIX2003:entry
  1  23399        _pthread_testcancel:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  24628             clock_get_time:entry
  1  23406         mig_get_reply_port:entry
  1  23407                   mach_msg:entry
  1  23327              mach_msg_trap:entry
  1  23368             _sysenter_trap:entry
  1  23400           __semwait_signal:entry
  1  23368             _sysenter_trap:entry
  1  23356                     memset:entry
  1  23356                     memset:entry
  1  23356                     memset:entry
  1  23952               gettimeofday:entry
  1  23953    __commpage_gettimeofday:entry
  1  24540            select$UNIX2003:entry
  1  24523        select$DARWIN_EXTSN:entry
  1  23368             _sysenter_trap:entry
  1  22941          ruby_stack_length:entry
  1  23392                     memcpy:entry
  1  23094            rb_lastline_get:entry
  1  22804                    rb_svar:entry
  1  23095            rb_lastline_set:entry
  1  22804                    rb_svar:entry
  1  23092             rb_backref_get:entry
  1  22804                    rb_svar:entry
  1  23093             rb_backref_set:entry
  1  22804                    rb_svar:entry
  1  23991                    _setjmp:entry
  1  23392                     memcpy:entry
  1  23094            rb_lastline_get:entry
  1  22804                    rb_svar:entry
  1  23095            rb_lastline_set:entry
  1  22804                    rb_svar:entry
  1  23092             rb_backref_get:entry
  1  22804                    rb_svar:entry

...
but most of the time it loops doing this:
  1  23899 pthread_testcancel$UNIX2003:entry
  1  23399        _pthread_testcancel:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  23398         nanosleep$UNIX2003:entry
  1  23399        _pthread_testcancel:entry
  1  23471                  spin_lock:entry
  1  23472               _spin_unlock:entry
  1  24628             clock_get_time:entry
  1  23406         mig_get_reply_port:entry
  1  23407                   mach_msg:entry
  1  23327              mach_msg_trap:entry
  1  23368             _sysenter_trap:entry
  1  23400           __semwait_signal:entry
  1  23368             _sysenter_trap:entry
  1  23367                     cerror:entry
  1  23382     cthread_set_errno_self:entry
  1  23383                    __error:entry
  1  23383                    __error:entry
  1  23899 pthread_testcancel$UNIX2003:entry




Oh wait--the problem just resolved itself and ruby has returned to
running 3% cpu instead of 100.  This is bizarre.
Posted by Robert Klemme (Guest)
on 20.05.2008 08:35
(Received via mailing list)
On 20.05.2008 00:25, Roger Pack wrote:
> So currently ruby is hung using 100% CPU on my machine.
> 
> Some questions:
> 1) does anybody else have this happen to them?
> 2) does anybody else have a chunk of code that reliably causes ruby to
> leak memory?
> 
> Anyway here are some sample stack traces, if anybody has any pointers.
> Thanks!

You'd probably get more replies if you supply some more environmental
information like the OS, Ruby version, compiler, Ruby code executed etc.

Kind regards

  robert
Posted by DJ Jazzy Linefeed (Guest)
on 20.05.2008 12:25
(Received via mailing list)
> On 20.05.2008 00:25, Roger Pack wrote:
>
> > So currently ruby is hung using 100% CPU on my machine.
>
> > Some questions:
> > 1) does anybody else have this happen to them?
> > 2) does anybody else have a chunk of code that reliably causes ruby to
> > leak memory?

It's more than just possible to write rickety code in Ruby, it's
encouraged. If you've got a chunk that's bleeding, let us see.
Posted by Marc Heiler (shevegen)
on 20.05.2008 14:25
Kinda hard to even try help... looks like ancient egypts wrote something 
and you try to translate it without rosetta-stone!
Posted by Roger Pack (rogerdpack)
on 20.05.2008 21:51
Marc Heiler wrote:
> Kinda hard to even try help... looks like ancient egypts wrote something 
> and you try to translate it without rosetta-stone!
Exactly! :)
sorry to post without much specs.
This is OS X 5.1 and Ruby 1.8.6 patchlevel 111 running what seems to be 
a 'normal' rails app and it just started sky-rocketing cpu between 
requests and wouldn't answer requests for awhile.
Now that I think of it, though, I wonder if the patchlevel 11 is the 
culprit.  I'll upgrade and see if the problem occurs again.
Thanks!
-R
Posted by Roger Pack (rogerdpack)
on 19.06.2008 04:40
Roger Pack wrote:
> So currently ruby is hung using 100% CPU on my machine.
> 
> Some questions:
> 1) does anybody else have this happen to them?
> 2) does anybody else have a chunk of code that reliably causes ruby to
> leak memory?
> 
> Anyway here are some sample stack traces, if anybody has any pointers.
> Thanks!
> -R
> 
>   1  24540            select$UNIX2003:entry
>   1  24523        select$DARWIN_EXTSN:entry
>   1  23368             _sysenter_trap:entry
>   1  22941          ruby_stack_length:entry
>   1  23392                     memcpy:entry
appears that this might be something in common only to mac os 10.5 based 
on this thread [1].  Apparently it returns a 'weird' error message for 
forcedly closed sockets, so ruby just keeps writing to it and writing to 
it [trying to] without successfully writing anything [and select fails, 
etc. etc.]

At least, that's my hypothesis.  Hard to know if we should come up with 
a patch for ruby just to accomodate Leopard.  Except that it's pretty 
common :)
-R

http://www.nabble.com/RabbitMQ-running-at-100--CPU.-td16024387.html