mperham/dalli — Issue #175: Passenger processes hang on memcached poll, even with Rails.cache.reset stanza or in conservative spawn
Author: tangentialism
Created: 2012-02-27 20:11:52+00:00
State: open

Hoping to get some help on this recently-developed issue with our Passenger processes seizing up during or immediately following an exchange with memcached. We're set up on EC2, using m1.large:

- Rails 3.1.1
- Ruby 1.9.2
- Apache2 / Passenger 3.0.11(both smart_lv2 and conservative spawn methods)
- Couchbase 1.8, on its own m1.large
- have seen this with dally 1.1.5 and 1.1.4 + kgio

We're only using dalli for the Rails.cache (not for sessions), and are using the Passenger environment.rb stanza currently as below:
```if defined?(PhusionPassenger)
PhusionPassenger.on_event(:starting_worker_process) do |forked|
Rails.cache.reset if forked
end
end```

Over time, we can see our processes, using passenger-status, begin to seize up suddenly, eventually maxing out the pool and effectively shutting down passenger. This tends to happen in spurts--a box will be fine for a while, then lock up four or six processes, then coast by on the remaining processes for a while before eventually eating them all.

We're stumped at the moment, in that this happens both on smart_lv2 and conservative spawning--the latter of which we had assumed would obviate any concerns at all about shared file descriptors. Watching strace, we see the processes talk to memcache successfully for a long while, ultimately ending in in a poll(), write(), read(), and then going silent.

I'm hoping for any clues you might be able to offer on this, or, if I'm posting this in entirely the wrong place, a suggestion of somebody I'd be better off asking. Otherwise, thank you for the work on dalli--it's obviously been a great friend of ours through thick and thin.

straces--both of a request that seized up, and of one of the many that worked--follow:

```FAILED REQUEST:
select(12, [4 5 10 11], NULL, NULL, NULL) = 1 (in [10])
accept(10, {sa_family=AF_FILE, path="U\5"...}, [33861590881140738]) = 9
fstat(9, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
read(9, "\0\0\10\7", 4) = 4
read(9, "SERVER_SOFTWARE\0Apache/2.2.3 (Ce"..., 2055) = 2055
lstat("public/assets/jquery-ui-1.8.15.custom.min.js", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
lstat("public/assets/jquery-ui-1.8.15.custom.min.js.html", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
lstat("public/assets/jquery-ui-1.8.15.custom.min.js/index.html", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
sendto(12, "\200\0\0<\0\0\0\0\0\0\0<\0\0\0\0\0\0\0\0\0\0\0\0http://w"..., 84, MSG_DONTWAIT, NULL, 0) = 84
recvfrom(12, 0x6a23f40, 24, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 498000})
recvfrom(12, "\201\0\0\0\4\0\0\0\0\0\7\251\0\0\0\0\0\0\0\0\0\1\236\274", 24, MSG_DONTWAIT, NULL, NULL) = 24
recvfrom(12, "\0\0\0\1\4\10o: ActiveSupport::Cache::E"..., 1961, MSG_DONTWAIT, NULL, NULL) = 1961
rt_sigprocmask(SIG_SETMASK, ~[HUP INT QUIT ILL TRAP ABRT BUS FPE KILL USR1 SEGV USR2 PIPE TERM CONT STOP TSTP TTIN TTOU URG XCPU XFSZ VTALRM PROF WINCH IO PWR SYS RTMIN RT_1], NULL, 8) = 0
clock_gettime(CLOCK_REALTIME, {1330358448, 366983000}) = 0
sendto(12, "\200\0\0(\0\0\0\0\0\0\0(\0\0\0\0\0\0\0\0\0\0\0\0001ba6007b"..., 64, MSG_DONTWAIT, NULL, 0) = 64
recvfrom(12, 0x6dcc0f0, 24, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 498000})
recvfrom(12, "\201\0\0\0\4\0\0\0\0\0035\331\0\0\0\0\0\0\0\0\0\1\236\254", 24, MSG_DONTWAIT, NULL, NULL) = 24
recvfrom(12, "\0\0\0\1\4\10o: ActiveSupport::Cache::E"..., 210393, MSG_DONTWAIT, NULL, NULL) = 10064
recvfrom(12, 0x5ff8b60, 200329, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 498000})
recvfrom(12, "eUpDelegate);if(this._mouseStart"..., 200329, MSG_DONTWAIT, NULL, NULL) = 11584
recvfrom(12, 0x881ee30, 188745, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 498000})
recvfrom(12, "structor!=Array){a=d(a.containme"..., 188745, MSG_DONTWAIT, NULL, NULL) = 13032
recvfrom(12, 0x8cc7320, 175713, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 498000})
recvfrom(12, "a,this.ui(b))},_over:function(a)"..., 175713, MSG_DONTWAIT, NULL, NULL) = 14480
recvfrom(12, 0x884ff00, 161233, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 498000})
recvfrom(12, "ent.outerWidth()+\na,height:this."..., 161233, MSG_DONTWAIT, NULL, NULL) = 15928
recvfrom(12, 0x8cf2190, 145305, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 498000})
recvfrom(12, "c]._trigger(\"activate\",a,e._uiHa"..., 145305, MSG_DONTWAIT, NULL, NULL) = 10136
recvfrom(12, 0x88774e0, 135169, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 499000})
recvfrom(12, "_trigger(\"out\",\na,this._uiHash(t"..., 135169, MSG_DONTWAIT, NULL, NULL) = 7240
recvfrom(12, 0x88984f0, 127929, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 499000})
recvfrom(12, "[0],\nthis.direction==\"down\"?b.it"..., 127929, MSG_DONTWAIT, NULL, NULL) = 11584
recvfrom(12, 0x6824080, 116345, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 499000})
recvfrom(12, "/(i.end-i.start);a.toShow[0].sty"..., 116345, MSG_DONTWAIT, NULL, NULL) = 8688
recvfrom(12, 0x6872720, 107657, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 499000})
recvfrom(12, "vate(e,this.element.children(\".u"..., 107657, MSG_DONTWAIT, NULL, NULL) = 13032
recvfrom(12, 0x89e0210, 94625, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 499000})
recvfrom(12, "g=c(\"

\").addClass(\"ui-"..., 94625, MSG_DONTWAIT, NULL, NULL) = 10136
recvfrom(12, "._mouseDestroy();\nreturn this},_"..., 84489, MSG_DONTWAIT, NULL, NULL) = 82536
recvfrom(12, "nction(){b.dequeue()});b.dequeue"..., 1953, MSG_DONTWAIT, NULL, NULL) = 1953
rt_sigprocmask(SIG_SETMASK, ~[HUP INT QUIT ILL TRAP ABRT BUS FPE KILL USR1 SEGV USR2 PIPE TERM CONT STOP TSTP TTIN TTOU URG XCPU XFSZ VTALRM PROF WINCH IO PWR SYS RTMIN RT_1], NULL, 8) = 0
clock_gettime(CLOCK_REALTIME, {1330358448, 533944000}) = 0
clock_gettime(CLOCK_REALTIME, {1330358448, 534183000}) = 0
lstat("/opt/jbpapp/20x200-public/public/assets/jquery-ui-1.8.15.custom.min.js", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
lstat("/opt/jbpapp/20x200-public/public/assets/jquery-ui-1.8.15.custom.min.js.html", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
lstat("/opt/jbpapp/20x200-public/public/assets/jquery-ui-1.8.15.custom.min.js/index.html", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
clock_gettime(CLOCK_REALTIME, {1330358448, 534981000}) = 0
clock_gettime(CLOCK_REALTIME, {1330358448, 535155000}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
poll([{fd=13, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(13, "\1\0\0\0\16", 5) = 5
read(13, "\7\0\0\1\0\0\0\2\0\0\0", 16384) = 11
```

```FUNCTIONAL REQUEST:
select(12, [4 5 10 11], NULL, NULL, NULL) = 1 (in [10])
accept(10, {sa_family=AF_FILE, path="U\5"...}, [33861590881140738]) = 9
fstat(9, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
read(9, "\0\0\5\353", 4) = 4
read(9, "SERVER_SOFTWARE\0Apache/2.2.3 (Ce"..., 1515) = 1515
lstat("public/artworks/assets/global/arrowtiny.gif", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
lstat("public/artworks/assets/global/arrowtiny.gif.html", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
lstat("public/artworks/assets/global/arrowtiny.gif/index.html", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
sendto(12, "\200\0\0;\0\0\0\0\0\0\0;\0\0\0\0\0\0\0\0\0\0\0\0http://w"..., 83, MSG_DONTWAIT, NULL, 0) = 83
recvfrom(12, 0x6fe0570, 24, 64, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
select(13, [12], NULL, NULL, {0, 500000}) = 1 (in [12], left {0, 498000})
recvfrom(12, "\201\0\0\0\0\0\0\1\0\0\0\t\0\0\0\0\0\0\0\0\0\0\0\0", 24, MSG_DONTWAIT, NULL, NULL) = 24
recvfrom(12, "Not found", 9, MSG_DONTWAIT, NULL, NULL) = 9
lstat("/opt/jbpapp/20x200-public/public/artworks/assets/global/arrowtiny.gif", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
lstat("/opt/jbpapp/20x200-public/public/artworks/assets/global/arrowtiny.gif.html", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
lstat("/opt/jbpapp/20x200-public/public/artworks/assets/global/arrowtiny.gif/index.html", 0x7fffc0726cf0) = -1 ENOENT (No such file or directory)
clock_gettime(CLOCK_REALTIME, {1330358437, 953917000}) = 0
clock_gettime(CLOCK_REALTIME, {1330358437, 954074000}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
poll([{fd=13, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(13, "\1\0\0\0\16", 5) = 5
read(13, "\7\0\0\1\0\0\0\2\0\0\0", 16384) = 11
rt_sigprocmask(SIG_SETMASK, ~[HUP INT QUIT ILL TRAP ABRT BUS FPE KILL USR1 SEGV USR2 PIPE TERM CONT STOP TSTP TTIN TTOU URG XCPU XFSZ VTALRM PROF WINCH IO PWR SYS RTMIN RT_1], NULL, 8) = 0
stat("/opt/jbpapp/20x200-public/public/404.en.html", 0x7fffc0727440) = -1 ENOENT (No such file or directory)
stat("/opt/jbpapp/20x200-public/public/404.html", 0x7fffc0727440) = -1 ENOENT (No such file or directory)
write(3, "\n\nStarted GET \"/artworks/assets/"..., 101) = 101
write(3, "\nActionController::RoutingError "..., 102) = 102
clock_gettime(CLOCK_REALTIME, {1330358438, 70272000}) = 0
clock_gettime(CLOCK_REALTIME, {1330358438, 70486000}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
write(2, "cache: [GET /artworks/assets/glo"..., 56) = 56
writev(9, [{"Status: ", 8}, {"404", 3}, {"\r\n", 2}, {"X-Powered-By: ", 14}, {"Phusion Passenger (mod_rails/mod"..., 45}, {"\r\n", 2}, {"Content-Type", 12}, {": ", 2}, {"text/html; charset=utf-8", 24}, {"\r\n", 2}, {"Content-Length", 14}, {": ", 2}, {"0", 1}, {"\r\n", 2}, {"X-Runtime", 9}, {": ", 2}, {"0.116355", 8}, {"\r\n", 2}, {"Date", 4}, {": ", 2}, {"Mon, 27 Feb 2012 16:00:38 GMT", 29}, {"\r\n", 2}, {"Cache-Control", 13}, {": ", 2}, {"private", 7}, {"\r\n", 2}, {"X-Rack-Cache", 12}, {": ", 2}, {"miss", 4}, {"\r\n", 2}, {"\r\n", 2}], 31) = 237
shutdown(9, 1 /* send */) = 0
close(9)
```