[ActsAsFerret] Fatal failed to allocate memory in DRb

I’m using DRb with edge [AAF] and my server is really fast reaching 3GB+
of memory and soon it will crash with this message:

[FATAL] failed to allocate memory

Now its like this:

10542 bbs 2 59 0 3649M 3647M sleep 1:27 0.10% runner

Anybody has any ideas on this?

What is the best way to debug this?

Manoel L. wrote:

I’m using DRb with edge [AAF] and my server is really fast reaching 3GB+
of memory and soon it will crash with this message:

[FATAL] failed to allocate memory

Now its like this:

10542 bbs 2 59 0 3649M 3647M sleep 1:27 0.10% runner

Anybody has any ideas on this?

My production server with AAF (DRb) is suddenly (I can’t precise when)
reaching 3GB+ of memory allocations, see:

16701 bbs 2 59 0 3656M 3653M sleep 2:55 0.03% runner

Then, soon it will fail with this message:

[FATAL] failed to allocate memory

My environment is like this:

OS > SunOS 92140-AA 5.11 snv_43 i86pc i386 i86pc
Rails > 1.1.6
Ruby > 1.8.4 (2005-12-24) [i386-solaris2.8]
Ferret > 0.11.3 (native C bindings)
AAF > Revision: 179 (trunk) URL:
svn://projects.jkraemer.net/acts_as_ferret/trunk/plugin/acts_as_ferret

Any idea on how to debug this?

I could discover that it fails when it reaches 4GB of memory alocation.

My production server with AAF (DRb) is suddenly (I can’t precise when)
reaching 3GB+ of memory allocations, see:

More, apparently there is serious memory leaking with long queries with
operators and wildcards. In my tests a single (a* OR e* OR i* OR o* OR
u*) query made the memory allocation jumps from 30MB to 365MB
immediately.

Running the same query again the memory increased just a little bit.

Running (b* OR c* OR d* OR f* OR g*) the increase was also incremental
(small).

Running (c* b* d* f* g*) it jumped to 412MB.

Running (a* OR b* OR c* OR d*) in another (the ones before were all on
the Post model, now we are searching the Blog model) model made it jump
to 462MB.

Running (a* OR b* OR c* OR d*) on the new model made it jump to 611MB.

As we can see, its getting bigger and bigger and will soon reach the 4GB
and fail.

However I can’t see what is really causing the error or where its
happening. The unique message appears on the DRb server and is the
[FATAL] failed to allocate memory.

Any help is welcome!!!

I updated Ferret to 0.11.4 and I’m with the same behavior.

Now, the few queries bellow made the memory allocation jumps from 30MB
to 764MB:

call index method: find_id_by_contents with [“manoel*”,
{:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}]call index
method: find_id_by_contents with [“a* OR e* OR i* OR o* OR u*”,
{:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“a* OR e* OR i* OR o* OR
u*”, {:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“a* OR e* OR i* OR o* OR
u*”, {:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“a* OR e* OR i* OR o* OR
u*”, {:sort=>[last_updated_at_sort:!], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“a* OR e* OR i* OR o* OR
u*”, {:sort=>[login_sort:], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“a* OR e* OR i* OR o* OR
u*”, {:sort=>[login_sort:], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“b* OR c* OR d* OR f* OR
g*”, {:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“b* OR c* OR d* OR f* OR
g*”, {:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“b* OR c* OR d* OR f* OR
g*”, {:sort=>[last_updated_at_sort:!], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“b* OR c* OR d* OR f* OR
g*”, {:sort=>[last_updated_at_sort:!], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“b* OR c* OR d* OR f* OR
g*”, {:sort=>[login_sort:], :offset=>0, :limit=>10}]
call index method: find_id_by_contents with [“b* OR c* OR d* OR f* OR
g*”, {:sort=>[login_sort:], :offset=>0, :limit=>10}]

[]s

I’m trying to monitor the memory usage growth at each command to the
ferret DRb server, to do this I modified ferret_server.rb method_missing
definition to:

def method_missing(name, *args)
clazz = args.shift.constantize
begin
@logger.debug “call index method: #{name} with #{args.inspect} -
server memory: #{ps -o rss -p #{Process.pid}.split(”\n").last} KB"
clazz.aaf_index.send name, *args
rescue NoMethodError
@logger.debug “no luck, trying to call class method instead”
clazz.send name, *args
end
rescue
@logger.error “ferret server error #{$!}\n#{$!.backtrace.join ‘\n’}”
raise
end

I added this: server memory: #{ps -o rss -p #{Process.pid}.split("\n").last} KB

to the log of each command, so we’ll be able to see how memory was just
before the command.

I don’t know if this will help, but we’ll be to see how the memory is
growing.

The modification to monitor the memory usage growth worked and I got a
very strange result: the memory usage jumped from 41.9MB to 3.7GB at
command #305 which is find_id_by_contents with [“it\264s sucker”,
{:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}].

Ferret Server Memory Jump

Note that the chart is in logarithmic scale on the Y axis.

Ahh, the failures (memory allocation jump) happens when the queries has
the ‘u’ character accented and is encoded in ISO-8859-1.

Now I was able to reproduce the error.
Analyzing a series of logs when the memory allocation jump happens I
discovered a pattern: the jump occurs when the query string contains
‘accented characters’. Specially when the query has the U with accents
in the end.

So, after searching for “fas jús”, “videos nús” and others it causes the
allocated memory to instantly jump from ~40MB to ~3.7GB and fail on the
next search with similar queries.

Also, I noted that on the ferret_server.log que query appears sometimes
different with extras chars on its ends, see:

I searched for “fas jús” and the log showed this: call index method:
find_id_by_contents with ["faz j?s ",
{:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}] - server
memory: 36288 KB

In the next call we could see that the memory jump just happened: call
index method: find_id_by_contents with [“PORTA ABERTA”,
{:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}] - server
memory: 3720856 KB

Again, when searching for “videos manús” the log shows “video man?s(?”
(not the garbage in the end). And the memory jumped to 3.7GB.

Then searching for “urubús” the log shows "urub?s " (note the extra
spaces) and the server fails with the FATAL error.

Once I could also got this message on the DRb server:

/opt/csw/lib/ruby/1.8/drb/drb.rb:941: warning: setvbuf() can’t be
honoured (fd=37)

Finally a sequence alternating the accented char to á, é, í, ó and ú to
see if the same happens with other chars. But it only happened with the
U accented and not the other chars, see:

[Sun Apr 08 17:26:09 BRT 2007] Info > Starting…
QUERY “deverás” > call index method: find_id_by_contents with
[“dever?s”, {:sort=>[posted_at_sort:!], :offset=>0,
:limit=>10}] - server memory: 30744 KB
QUERY “deverés” > call index method: find_id_by_contents with
[“dever?s”, {:sort=>[posted_at_sort:!], :offset=>0,
:limit=>10}] - server memory: 34168 KB
QUERY “deverís” > call index method: find_id_by_contents with
[“dever?s”, {:sort=>[posted_at_sort:!], :offset=>0,
:limit=>10}] - server memory: 34956 KB
QUERY “deveros” > call index method: find_id_by_contents with [“dever?”,
{:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}] - server
memory: 35156 KB
QUERY “deverús” > call index method: find_id_by_contents with ["dever?s
", {:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}] -
server memory: 35696 KB ===> MEMORY JUMP & GARBAGE ON LOG!!!
QUERY “jump”> call index method: find_id_by_contents with [“jump”,
{:sort=>[posted_at_sort:!], :offset=>0, :limit=>10}] - server
memory: 3724812 KB <<< THIS IS THE MEMORY AFTER THE “deverús” QUERY!!!

I’m finishing this thread and opening a new one.
The problem is more understood now.

More, it happens with the ‘O’ with tildes also. The query search
“religiões” will cause the memory allocation jump and then the FATAL
error.