Help me debug my stack trace

rogerdpack · May 20, 2008, 12:25am

So currently ruby is hung using 100% CPU on my machine.

Some questions:

does anybody else have this happen to them?
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.

rogerdpack · May 20, 2008, 8:35am

On 20.05.2008 00:25, Roger P. wrote:

So currently ruby is hung using 100% CPU on my machine.

Some questions:

does anybody else have this happen to them?

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

rogerdpack · May 20, 2008, 12:25pm

On 20.05.2008 00:25, Roger P. wrote:

So currently ruby is hung using 100% CPU on my machine.

Some questions:

does anybody else have this happen to them?

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.

rogerdpack · May 20, 2008, 2:25pm

Kinda hard to even try help… looks like ancient egypts wrote something
and you try to translate it without rosetta-stone!

rogerdpack · June 19, 2008, 4:40am

Roger P. wrote:

So currently ruby is hung using 100% CPU on my machine.

Some questions:

does anybody else have this happen to them?

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

rogerdpack · May 20, 2008, 9:51pm

Marc H. 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