Forum: Ruby on Rails Mongrel hangs with 100% CPU / EBADF (Bad file descriptor)

F7c6e5c96a14d1a61677c4fa8830c593?d=identicon&s=25 Front Line (frontline)
on 2008-08-31 17:46
I posted this at the mongrel forum, but got no response.,
I believe the problems isn't in mongrel itself, so maybe somebody here
has some info on this.
Anyway, here is the message:
---

We have a server with 10 running mongrel_cluster instances with apache
in front of them, and every now and then one or some of them hang.
No activity is seen in the database (we're using activerecord sessions).
Mysql with innodb tables. show innodb status shows no locks. show
processlist shows nothing.
The server is linux debian 4.0
Ruby is: ruby 1.8.6 (2008-03-03 patchlevel 114) [i486-linux]
Rails is: Rails 1.1.2 (yes, quite old)
We're using the native mysql connector (gem install mysql)

"strace -p PID" gives the following in a loop for the hung mongrel
process:

gettimeofday({1219834026, 235289}, NULL) = 0
select(4, [3], [0], [], {0, 905241})    = -1 EBADF (Bad file descriptor)
gettimeofday({1219834026, 235477}, NULL) = 0
select(4, [3], [0], [], {0, 905053})    = -1 EBADF (Bad file descriptor)
gettimeofday({1219834026, 235654}, NULL) = 0
select(4, [3], [0], [], {0, 904875})    = -1 EBADF (Bad file descriptor)
gettimeofday({1219834026, 235829}, NULL) = 0
select(4, [3], [0], [], {0, 904700})    = -1 EBADF (Bad file descriptor)
gettimeofday({1219834026, 236017}, NULL) = 0
select(4, [3], [0], [], {0, 904513})    = -1 EBADF (Bad file descriptor)
gettimeofday({1219834026, 236192}, NULL) = 0
select(4, [3], [0], [], {0, 904338})    = -1 EBADF (Bad file descriptor)
gettimeofday({1219834026, 236367}, NULL) = 0
...

I used lsof and found that the process used 67 file descriptors (lsof -p
PID |wc -l)

Is there any other way I can  debug this, so that I could for example
determine which file descriptor is "bad"?
Any other info or suggestions? Anybody else seen this?

The site is fairly used, but not overly so, load averages usually around
0.3.

---

Some additional info. I installed mongrel_proctitle to show what the
hung processes were doing, and it seems they are hanging on a method
that displays images using file_column / images from the database /
rmagick to resize and make the images greyscale. Not conclusive the
problem is here, but it is a suspicion.
Is there something obviously wrong with the following? The method
displays a static image if the order doesn't contain an image, else the
image resized from the order. The cache stuff is so that the image gets
updated in the browser every time. The image is inserted in the page
with a normal image tag.

code:
  def preview_image
    @order = session[:order]
    if @order.image.nil?
      @headers['Pragma'] = 'no-cache'
      @headers['Cache-Control'] = 'no-cache, must-revalidate'
      send_data(EMPTY_PIC.to_blob, :filename => "img.jpg", :type =>
"image/jpeg", :disposition => "inline")
       else
      @pic = Image.read(@order.image)[0]
      if (@order.crop)
       @pic.crop!(@order.crop[:x1].to_i, @order.crop[:y1].to_i,
@order.crop[:width].to_i, @order.crop[:height].to_i, true)
      end
      @pic.resize!(103,130)
      @pic = @pic.quantize(256, Magick::GRAYColorspace)
      @headers['Pragma'] = 'no-cache'
      @headers['Cache-Control'] = 'no-cache, must-revalidate'
      send_data(@pic.to_blob, :filename => "img.jpg", :type =>
"image/jpeg", :disposition => "inline")
    end
  end
18da12d67034a79c82982ab852a93286?d=identicon&s=25 Gerold Böhler (Guest)
on 2008-08-31 19:35
(Received via mailing list)
i had a simmilar problem recently. as it turned out, the server was
running without swap space configured. maybe you run out of memory?

cheers

gerold
F7c6e5c96a14d1a61677c4fa8830c593?d=identicon&s=25 Front Line (frontline)
on 2008-08-31 20:19
Thanks, but that's not it:

             total       used       free     shared    buffers
cached
Mem:       2073760    1866560     207200          0      30696
1286868
-/+ buffers/cache:     548996    1524764
Swap:      1999992        108    1999884

I had some problems also when /tmp got full (mainly the db didn't like
it), but fixed those.
F7c6e5c96a14d1a61677c4fa8830c593?d=identicon&s=25 Front Line (frontline)
on 2008-08-31 22:15
Here is the lsof output if anybody can find any problems in it. Don't
know how it will format in this message...

lsof: WARNING: can't stat() ext3 file system /dev/.static/dev
      Output information may be incomplete.
COMMAND     PID    USER   FD   TYPE     DEVICE      SIZE     NODE NAME
mongrel_r 11628 username  cwd    DIR        9,2      4096  1870688
/home/domains/example.com/usernameOrder/releases/20080831121802
mongrel_r 11628 username  rtd    DIR        9,1      4096        2 /
mongrel_r 11628 username  txt    REG        9,1      3564   167172
/usr/bin/ruby1.8
mongrel_r 11628 username  mem    REG        0,0                  0
[heap] (stat: No such file or directory)
mongrel_r 11628 username  DEL    REG        0,8           15560245
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560242
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560602
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560601
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560684
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560683
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560685
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560568
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560607
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560569
/dev/zero
mongrel_r 11628 username  mem    REG        9,1   1933648   456972
/usr/lib/libmysqlclient.so.15.0.0
mongrel_r 11628 username  DEL    REG        0,8           15442414
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560546
/dev/zero
mongrel_r 11628 username  mem    REG        9,1     67408   457393
/lib/i686/cmov/libresolv-2.7.so
mongrel_r 11628 username  mem    REG        9,1     17884   457386
/lib/i686/cmov/libnss_dns-2.7.so
mongrel_r 11628 username  DEL    REG        0,8           15560541
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560246
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560693
/dev/zero
mongrel_r 11628 username  DEL    REG        0,8           15560608
/dev/zero
mongrel_r 11628 username  mem    REG        9,1     25700   164963
/usr/lib/gconv/gconv-modules.cache
mongrel_r 11628 username  mem    REG        9,1     83708   457384
/lib/i686/cmov/libnsl-2.7.so
mongrel_r 11628 username  mem    REG        9,1    140602   506903
/var/lib/gems/1.8/gems/mysql-2.7/lib/mysql.so
mongrel_r 11628 username  mem    REG        9,1   1282816   180935
/usr/lib/locale/locale-archive
mongrel_r 11628 username  mem    REG        9,1     16672   167438
/usr/lib/libXdmcp.so.6.0.0
mongrel_r 11628 username  mem    REG        9,1      7220   167436
/usr/lib/libXau.so.6.0.0
mongrel_r 11628 username  mem    REG        9,1    434840   167477
/usr/lib/libfreetype.so.6.3.10
mongrel_r 11628 username  mem    REG        9,1   1147196   167011
/usr/lib/libxml2.so.2.6.27
mongrel_r 11628 username  mem    REG        9,1     66200   457138
/lib/libbz2.so.1.0.3
mongrel_r 11628 username  mem    REG        9,1    965952   167440
/usr/lib/libX11.so.6.2.0
mongrel_r 11628 username  mem    REG        9,1     85060   168009
/usr/lib/libICE.so.6.3.0
mongrel_r 11628 username  mem    REG        9,1     32144   168011
/usr/lib/libSM.so.6.0.0
mongrel_r 11628 username  mem    REG        9,1    320344   168013
/usr/lib/libXt.so.6.0.0
mongrel_r 11628 username  mem    REG        9,1     52848   168023
/usr/lib/libXext.so.6.4.0
mongrel_r 11628 username  mem    REG        9,1    137760   167484
/usr/lib/libpng12.so.0.15.0
mongrel_r 11628 username  mem    REG        9,1    127488   167481
/usr/lib/libjpeg.so.62.0.0
mongrel_r 11628 username  mem    REG        9,1    288776   168015
/usr/lib/libjasper-1.701.so.1.0.0
mongrel_r 11628 username  mem    REG        9,1    343712   168021
/usr/lib/libtiff.so.4.2.1
mongrel_r 11628 username  mem    REG        9,1    197880   168017
/usr/lib/liblcms.so.1.0.15
mongrel_r 11628 username  mem    REG        9,1   3637020   168025
/usr/lib/libMagick.so.9.0.0
mongrel_r 11628 username  DEL    REG        0,8           15560547
/dev/zero
mongrel_r 11628 username  mem    REG        9,1    252348   217396
/usr/lib/ruby/1.8/i486-linux/RMagick.so
mongrel_r 11628 username  mem    REG        9,1     38412   457387
/lib/i686/cmov/libnss_files-2.7.so
mongrel_r 11628 username  mem    REG        9,1    195564   457011
/lib/libncurses.so.5.6
mongrel_r 11628 username  mem    REG        9,1    188760   457143
/lib/libreadline.so.5.2
mongrel_r 11628 username  DEL    REG        0,8           15560542
/dev/zero
mongrel_r 11628 username  mem    REG        9,1     15312   214202
/usr/lib/ruby/1.8/i486-linux/readline.so
mongrel_r 11628 username  mem    REG        9,1     12192   213239
/usr/lib/ruby/1.8/i486-linux/digest/sha1.so
mongrel_r 11628 username  mem    REG        9,1     12868   213153
/usr/lib/ruby/1.8/i486-linux/iconv.so
mongrel_r 11628 username  mem    REG        9,1     11744   213164
/usr/lib/ruby/1.8/i486-linux/racc/cparse.so
mongrel_r 11628 username  mem    REG        9,1    236540   213151
/usr/lib/ruby/1.8/i486-linux/nkf.so
mongrel_r 11628 username  mem    REG        9,1      6688   213237
/usr/lib/ruby/1.8/i486-linux/digest/md5.so
mongrel_r 11628 username  mem    REG        9,1     15552   213160
/usr/lib/ruby/1.8/i486-linux/strscan.so
mongrel_r 11628 username  mem    REG        9,1     31312   213245
/usr/lib/ruby/1.8/i486-linux/zlib.so
mongrel_r 11628 username  mem    REG        9,1     12608   213243
/usr/lib/ruby/1.8/i486-linux/thread.so
mongrel_r 11628 username  mem    REG        9,1     36325   360155
/var/lib/gems/1.8/gems/fastthread-1.0.1/lib/fastthread.so
mongrel_r 11628 username  mem    REG        9,1     44423   347866
/var/lib/gems/1.8/gems/mongrel-1.1.5/lib/http11.so
mongrel_r 11628 username  mem    REG        9,1     38844   213246
/usr/lib/ruby/1.8/i486-linux/socket.so
mongrel_r 11628 username  mem    REG        9,1      7840   213249
/usr/lib/ruby/1.8/i486-linux/etc.so
mongrel_r 11628 username  mem    REG        9,1    109364   213241
/usr/lib/ruby/1.8/i486-linux/syck.so
mongrel_r 11628 username  mem    REG        9,1     15888   213244
/usr/lib/ruby/1.8/i486-linux/stringio.so
mongrel_r 11628 username  mem    REG        9,1     78500   163229
/usr/lib/libz.so.1.2.3
mongrel_r 11628 username  mem    REG        9,1   1338692   182762
/usr/lib/i686/cmov/libcrypto.so.0.9.8
mongrel_r 11628 username  mem    REG        9,1    278628   182763
/usr/lib/i686/cmov/libssl.so.0.9.8
mongrel_r 11628 username  mem    REG        9,1      3820   213247
/usr/lib/ruby/1.8/i486-linux/fcntl.so
mongrel_r 11628 username  mem    REG        9,1    224716   212332
/usr/lib/ruby/1.8/i486-linux/openssl.so
mongrel_r 11628 username  mem    REG        9,1   1360292   457376
/lib/i686/cmov/libc-2.7.so
mongrel_r 11628 username  mem    REG        9,1    149328   457382
/lib/i686/cmov/libm-2.7.so
mongrel_r 11628 username  mem    REG        9,1     38300   457378
/lib/i686/cmov/libcrypt-2.7.so
mongrel_r 11628 username  mem    REG        9,1      9684   457379
/lib/i686/cmov/libdl-2.7.so
mongrel_r 11628 username  mem    REG        9,1    112354   457392
/lib/i686/cmov/libpthread-2.7.so
mongrel_r 11628 username  mem    REG        9,1    783564   164396
/usr/lib/libruby1.8.so.1.8.6
mongrel_r 11628 username  mem    REG        9,1     10228   213152
/usr/lib/ruby/1.8/i486-linux/digest.so
mongrel_r 11628 username  mem    REG        9,1    109152   457054
/lib/ld-2.7.so
mongrel_r 11628 username    1w   REG        9,2    462923  1575329
/home/domains/example.com/usernameOrder/shared/log/mongrel.8001.log
mongrel_r 11628 username    2w   REG        9,2    462923  1575329
/home/domains/example.com/usernameOrder/shared/log/mongrel.8001.log
mongrel_r 11628 username    3u  IPv4   15442350                TCP
localhost:8001 (LISTEN)
mongrel_r 11628 username    4w   REG        9,2 118943548  1575355
/home/domains/example.com/usernameOrder/shared/log/production.log
mongrel_r 11628 username    5u   REG        9,1    145306   234226
/tmp/mongrel.11628.0 (deleted)
mongrel_r 11628 username    7u  unix 0xc3c12480           15442417
socket
mongrel_r 11628 username   11u   REG        9,1        50   234180
/tmp/CGI.11628.2
mongrel_r 11628 username   12u   REG        9,1     26228   234227
/tmp/CGI.11628.3
34fcadbf9a85db5277d46851570c8163?d=identicon&s=25 Vins (Guest)
on 2008-09-02 16:42
(Received via mailing list)
Hello,

I am facing exactly same problem and was wondering if you found the
solution for it.

Thanks
Vins

On Aug 31, 9:15 pm, Front Line <rails-mailing-l...@andreas-s.net>
F7c6e5c96a14d1a61677c4fa8830c593?d=identicon&s=25 Front Line (frontline)
on 2008-09-17 00:00
Vins wrote:
> Hello,
>
> I am facing exactly same problem and was wondering if you found the
> solution for it.
>
> Thanks
> Vins
>
> On Aug 31, 9:15�pm, Front Line <rails-mailing-l...@andreas-s.net>

Nope, not yet! Trying to reproduce it on a devel-server, quite
impossible...
But it always hangs in code that handles image resizing etc.
035687df00d162cec025302373ebc076?d=identicon&s=25 Anthony E. (chovy)
on 2008-10-08 21:14
Same problem here...CPU up to 99% -- app is unresponsive.

$ strace -p <pid>:

sigprocmask(SIG_BLOCK, NULL, [])        = 0
sigprocmask(SIG_BLOCK, NULL, [])        = 0
sigprocmask(SIG_BLOCK, NULL, [])        = 0
sigprocmask(SIG_BLOCK, NULL, [])        = 0
sigprocmask(SIG_BLOCK, NULL, [])        = 0
sigprocmask(SIG_BLOCK, NULL, [])        = 0

Over and over...

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+   PPID COMMAND
5393 ettinger  21   0  821m 810m 2680 R 97.9 40.1   2:51.87     1
/usr/bin/ruby1.8 /usr/bin/mongrel_rails start -C /h
1ca5c1a1d7b984083aa04d9ae263d510?d=identicon&s=25 Daniel Weber (dskfjl23kjflsdkf)
on 2013-08-28 00:48
I have had the same issue.  It does not always reproduce, but I have a
machine that runs into it at least once a day.

ruby 1.9.2p136

gettimeofday is being called as fast as possible, using up 99% of a CPU.

Has anyone found a solution?
Bee69cfed999cd13e3bff73d472a39ee?d=identicon&s=25 Hassan Schroeder (Guest)
on 2013-08-28 01:37
(Received via mailing list)
On Tue, Aug 27, 2013 at 3:48 PM, Daniel Weber <lists@ruby-forum.com>
wrote:

> ruby 1.9.2p136
>
> gettimeofday is being called as fast as possible, using up 99% of a CPU.

Something's probably trying desperately to catch up to the present.
( Currently: late summer, 2013. )

Seriously, you're responding to a 5-year-old post to tell us about a
problem you're having with an obsolete version of Ruby??

And with absolutely no useful details about your platform?

--
Hassan Schroeder ------------------------ hassan.schroeder@gmail.com
http://about.me/hassanschroeder
twitter: @hassan
1ca5c1a1d7b984083aa04d9ae263d510?d=identicon&s=25 Daniel Weber (dskfjl23kjflsdkf)
on 2013-08-28 22:06
Sorry, I didn't mean to hurt your feelings.
035687df00d162cec025302373ebc076?d=identicon&s=25 Anthony E. (chovy)
on 2013-08-28 22:11
you guys got my hopes up. thought this was the 2013 Revival Tour for my
post.
Please log in before posting. Registration is free and takes only a minute.
Existing account

NEW: Do you have a Google/GoogleMail, Yahoo or Facebook account? No registration required!
Log in with Google account | Log in with Yahoo account | Log in with Facebook account
No account? Register here.