memory usage

memory usage

[John Lepikhin]

Hello,

I have developed an application and have issue with memory usage.
Application was designed for work as server, 24x7. After several hours
of work, RSS memory grows up to 40-50MB. Each thread must not use more
than 100-200KB of memory (maximum 20 threads are run at the same time).
GC debug information:

Growing heap to 3840k bytes
Growing heap to 4320k bytes
Shrinking heap to 3840k bytes
Growing heap to 4320k bytes
Growing heap to 4800k bytes
Growing heap to 5280k bytes
Shrinking heap to 4800k bytes
Shrinking heap to 4320k bytes
Shrinking heap to 3840k bytes
Growing heap to 4320k bytes
Growing heap to 4800k bytes
Growing heap to 5280k bytes
Shrinking heap to 4800k bytes
Shrinking heap to 4320k bytes
Shrinking heap to 3840k bytes
Shrinking heap to 3360k bytes
Growing heap to 3840k bytes
Growing heap to 4320k bytes
Growing heap to 4800k bytes
Growing heap to 960k bytes
Shrinking heap to 4320k bytes
Shrinking heap to 3840k bytes
Shrinking heap to 3360k bytes
Shrinking heap to 2880k bytes
Growing heap to 3360k bytes
Shrinking heap to 2880k bytes
Shrinking heap to 2400k bytes
Growing heap to 2880k bytes
Growing heap to 3360k bytes
Growing heap to 3840k bytes
Shrinking heap to 3360k bytes
Shrinking heap to 2880k bytes
Growing heap to 3360k bytes
Shrinking heap to 2880k bytes

As you can see, heap size never gets bigger 5-6MB. I made core dump of
process. 90% of memory was filled with values which are created inside
threads and never been copied outside of them. Each thread is killed
after work is done, I am absolutely sure in it; all unused file
descriptors are closed. Playing with Gc.set has not brought notable
results.

Please, give me some start point to find the roots of the problem.

Sorry for my English.

Re: [Caml-list] memory usage

[Richard Jones]

On Mon, Jan 12, 2009 at 03:41:46PM +0800, John Lepikhin wrote:
> Please, give me some start point to find the roots of the problem.

Starting point should be to call this periodically:

      Gc.compact ();
      let stat = Gc.stat () in
      let live_words = stat.Gc.live_words in
      eprintf "live words %d\n%!" live_words;

which will tell you how many words (ie 4 or 8 byte chunks) are
reachable according to the garbage collector.

If this number is going up, then somewhere you are holding a pointer
to some object that you didn't expect to be live.

Rich.

-- 
Richard Jones
Red Hat

Re: [Caml-list] memory usage

[John Lepikhin]

> Starting point should be to call this periodically:
> 
>       Gc.compact ();
>       let stat = Gc.stat () in
>       let live_words = stat.Gc.live_words in
>       eprintf "live words %d\n%!" live_words;
> 
> which will tell you how many words (ie 4 or 8 byte chunks) are
> reachable according to the garbage collector.

Richard, here is result (statistics was saved every 10 seconds):

live words - RSS:

186980 - 12380KB <-- after first 10 seconds of work
154156 - 18232KB
153923 - 19648KB
...
after 10 minutes of work:
203842 - 33436KB
170559 - 33528KB
187018 - 33664KB
71626 - 33592KB

Sometimes live words drops down to 40.000. But RSS always stay near
30-50MB.

Re: memory usage

[Sylvain Le Gall]

On 12-01-2009, John Lepikhin <john@ispsystem.com> wrote:
>> Starting point should be to call this periodically:
>> 
>>       Gc.compact ();
>>       let stat = Gc.stat () in
>>       let live_words = stat.Gc.live_words in
>>       eprintf "live words %d\n%!" live_words;
>> 
>> which will tell you how many words (ie 4 or 8 byte chunks) are
>> reachable according to the garbage collector.
>
> Richard, here is result (statistics was saved every 10 seconds):
>
> live words - RSS:
>
> 186980 - 12380KB <-- after first 10 seconds of work
> 154156 - 18232KB
> 153923 - 19648KB
> ...
> after 10 minutes of work:
> 203842 - 33436KB
> 170559 - 33528KB
> 187018 - 33664KB
> 71626 - 33592KB
>
> Sometimes live words drops down to 40.000. But RSS always stay near
> 30-50MB.
>

To get real memory used, (Sys.word_size * live_word / 8). Do you use
out-of-heap datastructure that can use memory ? (malloc-ed
datastructure).

Regards,
Sylvain Le Gall

[Caml-list] Re: memory usage

[John Lepikhin]

> To get real memory used, (Sys.word_size * live_word / 8). Do you use
> out-of-heap datastructure that can use memory ? (malloc-ed
> datastructure).

The only specific module is ocaml-fd (send file descriptors over pipes).
I have suspicion on it, but as I said before, 90% of process memory is
filled with specific text data, which is got inside threads and sent to
socket using Unix.write. This data doesn't look like file
descriptors :-)
All other modules are from distribution (Unix, String, Mutex, Threads).

I heard about ocaml-memprof patch. Will it help here?

Re: [Caml-list] Re: memory usage

[Richard Jones]

On Mon, Jan 12, 2009 at 07:28:15PM +0800, John Lepikhin wrote:
> > To get real memory used, (Sys.word_size * live_word / 8). Do you use
> > out-of-heap datastructure that can use memory ? (malloc-ed
> > datastructure).
> 
> The only specific module is ocaml-fd (send file descriptors over pipes).

What version of OCaml is this?

I had a look at the source for ocaml-fd and it doesn't seem like it
should leak memory.  Certainly if there is a memory leak, it would be
a subtle one.

> I have suspicion on it, but as I said before, 90% of process memory is
> filled with specific text data, which is got inside threads and sent to
> socket using Unix.write. This data doesn't look like file
> descriptors :-)
> All other modules are from distribution (Unix, String, Mutex, Threads).

It does seem very unlikely that Unix.write would be a problem -- it's
a very commonly used function.

I'm afraid to say that you'll have to post a short reproducer here
before I can look at this further ...

> I heard about ocaml-memprof patch. Will it help here?

I haven't used it.  Seems like you have to patch the compiler.

If you suspect a problem in a C binding somewhere, then a quicker
approach would probably be to run the program using valgrind.

Rich.

-- 
Richard Jones
Red Hat

Re: [Caml-list] Re: memory usage

[John Lepikhin]

> > The only specific module is ocaml-fd (send file descriptors over pipes).
> What version of OCaml is this?

3.10.2.

> I'm afraid to say that you'll have to post a short reproducer here
> before I can look at this further ...

Yes, it could be the simplest solution. I have this issue only under the
high load, on production server, with real client applications. At this
time, I have no idea how to reduce code from big commercial application
to something short. May be I'll create some stand-alone GC test later.

P.S. Interesting thing I found on other machine, where application works
with another load: after the same number of connections processed, only
5MB was allocated (feel the difference: 5MB and 40MB, both after
processing 250.000 connections). The only difference is the first
machine had processed 250.000 connections in 5 hours (up to ~20
concurrent threads), the second in 24 hours (up to ~10 concurrent
threads).

Re: [Caml-list] memory usage

[John Lepikhin]

> > Please, give me some start point to find the roots of the problem.
> I assume you're running on Linux.

I've got this issue on FreeBSD box. On Linux test box process grows only
up to 2MB (but there is no production data and clients). Here is partial
pmap output:

Address              Kbytes        RSS     Shared       Priv Mode
Mapped File
...
00000000408AA000        932        548        932          -
r-x   /lib/libc.so.7
0000000040993000          4          4          4          -
r-x   /lib/libc.so.7
0000000040994000       1020          0       1020          -
r-x   /lib/libc.so.7
0000000040A93000        116        116          -        116
rw-   /lib/libc.so.7
0000000040AB0000         92         44          -         92 rw-
[ anon ]
0000000040B00000       1024        904          -       1024 rw-
[ anon ]
0000000040C00000      34816      19652          -      34816 rw-
[ anon ]
0000000042E00000       1024        200          -       1024 rw-
[ anon ]
0000000042F00000       2048        400          -       2048 rw-
[ anon ]
00007FFFFB9BE000        128         20          -        128 rw-
[ anon ]
00007FFFFBBBF000        128         20          -        128 rw-
[ anon ]
...
---------------- ---------- ---------- ---------- ----------
Total Kb              48552      23736       4352      44528

Most of memory is allocated here:

0000000040C00000      34816      19652          -      34816 rw-
[ anon ]

It gets bigger and bigger:

0000000040C00000      34816      20660          -      34816 rw-
[ anon ]

0000000040C00000      34816      21216          -      34816 rw-
[ anon ]

> One other thing to check is to ensure that threads really are being killed
> at the times you expect.  (Check "/proc/<pid>/status | grep Threads", or use
> "gdb -p" to attach to the running process then "info thr".)

I checked it. Only valid threads run.

Re: [Caml-list] memory usage

[Florian Hars]

John Lepikhin schrieb:
> Each thread is killed after work is done

How do you "kill" the threads? I hope this is just a figure of
speech for "I do an orderly shutdown of each thread after work is done."

- Florian.

Re: [Caml-list] memory usage

[John Lepikhin]

> > Each thread is killed after work is done
> How do you "kill" the threads? I hope this is just a figure of
> speech for "I do an orderly shutdown of each thread after work is done."

Well, that was consequence of my bad English :-) Threads finish their
work and exit. I also made a simple wrapper to Thread.create to be sure
that all work inside threads is done:

module MyThread =
  let create f p =
    let dowork _ =
      (* log thread creation *)
      f p;
      (* log thread shutdown *)
    in
    Thread.create dowork ()
end

Re: memory usage

[Sylvain Le Gall]

On 12-01-2009, John Lepikhin <john@ispsystem.com> wrote:
>
>> > Each thread is killed after work is done
>> How do you "kill" the threads? I hope this is just a figure of
>> speech for "I do an orderly shutdown of each thread after work is done."
>
> Well, that was consequence of my bad English :-) Threads finish their
> work and exit. I also made a simple wrapper to Thread.create to be sure
> that all work inside threads is done:
>
> module MyThread =
>   let create f p =
>     let dowork _ =
>       (* log thread creation *)
>       f p;
>       (* log thread shutdown *)
>     in
>     Thread.create dowork ()
> end

Do you use some kind of Thread.join ? 

Regards
Sylvain Le Gall

Re: [Caml-list] Re: memory usage

[John Lepikhin]

> I'm afraid to say that you'll have to post a short reproducer here
> before I can look at this further ...

I'm not sure this is the same issue. Look at this test code:

================================
let threads_counter = ref 0

let counter_mutex = Mutex.create ()

let send_data data size =
	let fd = Unix.openfile "/dev/null" [ Unix.O_WRONLY ] 0o644 in
	ignore (Unix.write fd data 0 size);
	Unix.close fd

let read_data _ =
	let fd = Unix.openfile "/dev/random" [] 0o644 in
	let buffer = String.create 1024 in
	let br = Unix.read fd buffer 0 (Random.int 1000) in
	Unix.close fd;
	ignore (Unix.select [] [] [] 0.1);
	send_data buffer br

let do_work _ =
	read_data ();

	Mutex.lock counter_mutex;
	decr threads_counter;
	Mutex.unlock counter_mutex

let _ =
	while true do
		Mutex.lock counter_mutex;
		if !threads_counter < 20 then
		begin
			incr threads_counter;

			ignore (Thread.create do_work ());
		end;
		Mutex.unlock counter_mutex;
	done;
	Unix.sleep 100
================================

It checks if thread count is less than 20. If so, new thread is created
and threads_counter incremented. After thread is done, threads_counter
is decremented.

After 5 minutes of work, RSS usage was grown from 3300KB to 5670KB on
FreeBSD 7.0 and from 976KB to 1200KB on Linux. In both cases Ocaml
3.10.2 was used.

Re: [Caml-list] Re: memory usage

[John Lepikhin]

> Do you use some kind of Thread.join ? 

No. The only things that ties threads are 2-3 shared values, which
sometimes locks by mutexes, reads/modifies and then unlocks. Nothing
special.

Re: memory usage

[Sylvain Le Gall]

Can you make sure that all your function terminate and are joined
(Thread.join). I think this will help to make sure that the thread exit
and call thread_kill (see OCaml source code).

If you take a look at thread_kill there is a function stat_free + set to
NULL things called stack_low, stack_high... Maybe all the data you are
seeing come from this...

I am not sure that Thread.join will free anything, but it will help you
to be sure that your thread has exited correctly.

Regards,
Sylvain Le Gall

Re: [Caml-list] Re: memory usage

[Richard Jones]

On Mon, Jan 12, 2009 at 11:03:10PM +0800, John Lepikhin wrote:
> 
> > > The only specific module is ocaml-fd (send file descriptors over pipes).
> > What version of OCaml is this?
> 
> 3.10.2.

Low level parts of the GC were rewritten in 3.11.  Well, the way that
it gets blocks of memory off the operating system anyhow ...

https://bugzilla.redhat.com/show_bug.cgi?id=445545#c9
http://caml.inria.fr/pub/ml-archives/caml-list/2008/05/9c24581520a98afa2e11185845b5458a.en.html

So maybe upgrading to 3.11 is an option for you?  I don't know whether
it will make a difference, but it's possible it will change the
behaviour and 3.11 is quite stable so it's unlikely to introduce any
regressions.

Rich.

-- 
Richard Jones
Red Hat

Re: [Caml-list] Re: memory usage

[Richard Jones]

On Tue, Jan 13, 2009 at 01:56:39AM +0800, John Lepikhin wrote:
> > I'm afraid to say that you'll have to post a short reproducer here
> > before I can look at this further ...
> 
> I'm not sure this is the same issue. Look at this test code:

For reasons I don't fully understand, this code doesn't seem to do
anything.  A print statement after the Unix.openfile is never printed.

> let read_data _ =
> 	let fd = Unix.openfile "/dev/random" [] 0o644 in

You probably want to use something like /dev/urandom or /dev/zero
here.  This blocks after a very short time because /dev/random (on
Linux) only produces characters while there is entropy in the kernel.
(Not for very long once you start reading blocks of it from 20
threads).

Rich.

-- 
Richard Jones
Red Hat

Re: [Caml-list] Re: memory usage

[John Lepikhin]

> > I'm not sure this is the same issue. Look at this test code:
> For reasons I don't fully understand, this code doesn't seem to do
> anything.  A print statement after the Unix.openfile is never printed.

Possibly you use print_string or something like this. Such output is
cached. You should either flush stdout or use print_endline.

> > let read_data _ =
> > 	let fd = Unix.openfile "/dev/random" [] 0o644 in
> You probably want to use something like /dev/urandom or /dev/zero
> here.

I'm so sleepy at this time, it's a quick written test code :-) RSS still
grows after I changed the source of data to /dev/zero. I didn't expect
something else...

Re: [Caml-list] Re: memory usage

[Richard Jones]

On Tue, Jan 13, 2009 at 05:34:06AM +0800, John Lepikhin wrote:
> 
> > > I'm not sure this is the same issue. Look at this test code:
> > For reasons I don't fully understand, this code doesn't seem to do
> > anything.  A print statement after the Unix.openfile is never printed.
> 
> Possibly you use print_string or something like this. Such output is
> cached. You should either flush stdout or use print_endline.

Yeah, I flushed the output and I used /dev/zero - I still see no
messages.

Rich.

-- 
Richard Jones
Red Hat

Re: [Caml-list] Re: memory usage

[John Lepikhin]

> Yeah, I flushed the output and I used /dev/zero - I still see no
> messages.

That's strange. Anyway, it looks like a memory leak, isn't it?

20 threads * 1KB max = 20 KB of memory for data storage should be used
(plus 20KB*500% for heap overhead = 100KB). I changed delay to 1 ms:

ignore (Unix.select [] [] [] 0.001);

After 2 minutes of work on FreeBSD, 19MB(!) was used:

# ps auxw | grep a.out | grep -v grep
root 35136 30.1  0.2 60348 19304  p5  L+    1:36PM   2:08.07 ./a.out

# pmap <PID>:

Address              Kbytes  RSS Shared Priv Mode  Mapped File
0000000000400000        204  360      -  360 r-x   /tmp/a.out
0000000000532000         80   76      -   80 rw-   /tmp/a.out
0000000000546000         28   16      -   28 rw-     [ anon ]
0000000040532000        148  108    148    - r-x   /libexec/ld-elf.so.1
0000000040557000        132  108      -  132 rw-     [ anon ]
0000000040657000         28   28      -   28 rw-   /libexec/ld-elf.so.1
000000004065E000         24   20      -   24 rw-     [ anon ]
0000000040664000         92   76     92    - r-x   /lib/libm.so.5
000000004067B000          4    4      -    4 r-x   /lib/libm.so.5
000000004067C000       1024    0   1024    - r-x   /lib/libm.so.5
000000004077C000          8    8      -    8 rw-   /lib/libm.so.5
000000004077E000         64   64     64    - r-x   /lib/libthr.so.3
000000004078E000          4    4      -    4 r-x   /lib/libthr.so.3
000000004078F000       1024   12   1024    - r-x   /lib/libthr.so.3
000000004088F000         12   12      -   12 rw-   /lib/libthr.so.3
0000000040892000          8    8      -    8 rw-     [ anon ]
0000000040894000        932  452    932    - r-x   /lib/libc.so.7
000000004097D000          4    4      -    4 r-x   /lib/libc.so.7
000000004097E000       1020    0   1020    - r-x   /lib/libc.so.7
0000000040A7D000        116  116      -  116 rw-   /lib/libc.so.7
0000000040A9A000         92   36      -   92 rw-     [ anon ]
0000000040B00000      44032  13976    - 44032 rw-     [ anon ]
00007FFFF85A4000        128   12      -  128 rw-     [ anon ]
00007FFFF87A5000        128   12      -  128 rw-     [ anon ]
00007FFFF89A6000        128   12      -  128 rw-     [ anon ]
00007FFFF8BA7000        128   12      -  128 rw-     [ anon ]
00007FFFF8DA8000        128   12      -  128 rw-     [ anon ]
00007FFFF8FA9000        128   12      -  128 rw-     [ anon ]
...

(gdb) info thr
  18 Thread 0x40b01120 (LWP 101068)  0x00000000408e4d4c in _umtx_op ()
from /lib/libc.so.7
  17 Thread 0x40b01290 (LWP 100489)  0x0000000040971cfc in select ()
from /lib/libc.so.7
  16 Thread 0x40b01b30 (LWP 100079)  0x00000000408e4d4c in _umtx_op ()
from /lib/libc.so.7
  15 Thread 0x40b04d80 (LWP 100858)  0x0000000040971cfc in select ()
from /lib/libc.so.7
  14 Thread 0x40b02260 (LWP 101096)  0x00000000408e4d4c in _umtx_op ()
from /lib/libc.so.7
  13 Thread 0x40b04200 (LWP 101128)  0x0000000040971cfc in select ()
from /lib/libc.so.7
  12 Thread 0x40b03960 (LWP 101175)  0x00000000408e4d4c in _umtx_op ()
from /lib/libc.so.7
  11 Thread 0x40b02820 (LWP 101189)  0x00000000408e4d4c in _umtx_op ()
from /lib/libc.so.7
  10 Thread 0x40b03680 (LWP 101217)  0x00000000408e4d4c in _umtx_op ()
from /lib/libc.so.7
  9 Thread 0x40b03f20 (LWP 100057)  0x00000000408e4d4c in _umtx_op ()
from /lib/libc.so.7
  8 Thread 0x40b020f0 (LWP 100066)  0x0000000040971cfc in select ()
from /lib/libc.so.7
  7 Thread 0x40b05ec0 (LWP 100535)  0x0000000040971cfc in select ()
from /lib/libc.so.7
  6 Thread 0x40b04370 (LWP 100564)  0x00000000408e4d4c in _umtx_op ()
from /lib/libc.so.7
  5 Thread 0x40b04c10 (LWP 100698)  0x0000000040971cfc in select ()
from /lib/libc.so.7
  4 Thread 0x40b02b00 (LWP 101224)  0x0000000040971cfc in select ()
from /lib/libc.so.7
  3 Thread 0x40b03ad0 (LWP 101227)  0x0000000040971cfc in select ()
from /lib/libc.so.7
  2 Thread 0x40b037f0 (LWP 101258)  0x00000000408e4d4c in _umtx_op ()
from /lib/libc.so.7
* 1 Thread 0x40b05620 (LWP 100101)  0x00000000409643dc in open ()
from /lib/libc.so.7
(gdb) 

I also added special thread to check GC:

let print_stats _ =
  while true do
    Gc.compact ();
    Gc.print_stat stdout;
    flush stdout;
    Unix.sleep 10;
  done

Thread.create print_stats ();

GC statistics after 1 minute:

minor_words: 21929847    <-- ?
promoted_words: 2474840
major_words: 2939105
minor_collections: 1655
major_collections: 635
heap_words: 61440
heap_chunks: 1
top_heap_words: 61440
live_words: 1024
live_blocks: 115
free_words: 60416
free_blocks: 1
largest_free: 60416
fragments: 0
compactions: 7