You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@apr.apache.org by Andreas Florath <sf...@flonatel.org> on 2012/02/17 20:07:14 UTC

Questions about APR Memory Pool

Hello!

I have some questions about APR and memory handling (apr_pool_t).

I downloaded APR version 1.4.6, compiled the lib, compiled the tests,
run the 'echod' server and the sockperf in a while-true loop
(while true; do ./sockperf; done)

I observed that the echod eats up more and more memory [1].

Then I read the source, the manual and the Internet, compiled
everything with POOL DEBUG switched on - and now have the following
questions:

1) In the echod.c in the function talkTalk a memory pool is allocated
   with apr_pool_create but 'freed' with 'only' apr_pool_clear.
   If I understand the documentation correctly, the clear does not
   destroy the pool - it just clears all the objects in it that it can
   be reused.

   After second run of sockperf:
POOL DEBUG: [22145/139692759529216] PCALLOC (     25402/     25402/     25602) 0x7f0cc13fff68 "echod.c:134" <network_io/unix/sockets.c:69> (167/167/0)
POOL DEBUG: [22145/139692759529216] PCALLOC (     25594/     25594/     25794) 0x7f0cc13fff68 "echod.c:134" <network_io/unix/sockets.c:72> (168/168/0)
POOL DEBUG: [22145/139692759529216] PCALLOC (     25786/     25786/     25986) 0x7f0cc13fff68 "echod.c:134" <network_io/unix/sockets.c:75> (169/169/0)
	Answering connection
POOL DEBUG: [22145/139692759529216]  CREATE (         0/         0/     25986) 0x7f0cc02ddf68 "echod.c:45" <echod.c:45> (0/0/0)
POOL DEBUG: [22145/139692759529216]  PALLOC (      4096/      4096/     30082) 0x7f0cc02ddf68 "echod.c:45" <echod.c:49> (1/1/0)
POOL DEBUG: [22145/139692759529216]   CLEAR (      4096/      4096/     30082) 0x7f0cc02ddf68 "echod.c:45" <echod.c:63> (1/1/0)

   BUT: exchanging the apr_pool_clear with apr_pool_destroy does not
   really change things:

   After second run of sockperf:
POOL DEBUG: [22263/140608421566208] PCALLOC (     25402/     25402/     25602) 0x7fe1f2f5df68 "echod.c:134" <network_io/unix/sockets.c:69> (167/167/0)
POOL DEBUG: [22263/140608421566208] PCALLOC (     25594/     25594/     25794) 0x7fe1f2f5df68 "echod.c:134" <network_io/unix/sockets.c:72> (168/168/0)
POOL DEBUG: [22263/140608421566208] PCALLOC (     25786/     25786/     25986) 0x7fe1f2f5df68 "echod.c:134" <network_io/unix/sockets.c:75> (169/169/0)
	Answering connection
POOL DEBUG: [22263/140608421566208]  CREATE (         0/         0/     25986) 0x7fe1f1dcff68 "echod.c:45" <echod.c:45> (0/0/0)
POOL DEBUG: [22263/140608421566208]  PALLOC (      4096/      4096/     30082) 0x7fe1f1dcff68 "echod.c:45" <echod.c:49> (1/1/0)
POOL DEBUG: [22263/140608421566208] DESTROY (      4096/      4096/     30082) 0x7fe1f1dcff68 "echod.c:45" <echod.c:64> (1/1/0)

   When using BOTH methods: clear AND destroy things are getting
   better:

   After second run of sockperf:
POOL DEBUG: [22361/139932145407744] PCALLOC (     25402/     25402/     25602) 0x7f447dc29f68 "echod.c:134" <network_io/unix/sockets.c:69> (167/167/0)
POOL DEBUG: [22361/139932145407744] PCALLOC (     25594/     25594/     25794) 0x7f447dc29f68 "echod.c:134" <network_io/unix/sockets.c:72> (168/168/0)
POOL DEBUG: [22361/139932145407744] PCALLOC (     25786/     25786/     25986) 0x7f447dc29f68 "echod.c:134" <network_io/unix/sockets.c:75> (169/169/0)
	Answering connection
POOL DEBUG: [22361/139932145407744]  CREATE (         0/         0/     25986) 0x7f447ca9bf68 "echod.c:45" <echod.c:45> (0/0/0)
POOL DEBUG: [22361/139932145407744]  PALLOC (      4096/      4096/     30082) 0x7f447ca9bf68 "echod.c:45" <echod.c:49> (1/1/0)
POOL DEBUG: [22361/139932145407744]   CLEAR (      4096/      4096/     30082) 0x7f447ca9bf68 "echod.c:45" <echod.c:63> (1/1/0)
POOL DEBUG: [22361/139932145407744] DESTROY (         0/         0/     25986) 0x7f447ca9bf68 "echod.c:45" <echod.c:64> (0/1/1)

   I really do not understand this, because the documentation says:
   "void apr_pool_destroy(apr_pool_t * p ):
    Destroy the pool. This takes similar action as apr_pool_clear()
    and then frees all the memory."

   How must a pool be destroyed?
   Is a 'apr_pool_destroy()' is enough? (If so: why is the memory not
   freed if only destroy() is called?)
   Is a 'apr_pool_clear()' is enough? (If not: looks that there is a
   problem in the talkTalk function.)
   If both are needed, IMHO the documentation should clearly state
   this. (And also there is a problem in the talkTalk function.)

2) Now it looks better - but not good at all.
   Searching for the other leak, I found that the socket creation and
   destruction functions are the source of it.

   During a 'apr_socket_accept()' some memory is allocated from the
   pool.  The 'apr_socket_close()' closes the socket - but does NOT
   free the memory.  The memory is freed, when the pool is cleared /
   destroyed.

   For the current implementation of echod the 'parent' pool is used
   to allocate more and more memory for the sockets - which is never
   freed during runtime.

   Is the 'correct' way ('correct' means: write code which can run
   in a production environment) to create an extra pool for the socket
   which is cleared and destroyed after closing the socket?

   Under [2] you can find an adapted version of the for-ever loop from
   the echod function called 'glassToWall' - which has (at least in my
   environment) no leak (see [3]).

Kind regards

Andreas Florath


========== [1] ==========

$ dstat -t --top-mem 60

17-02 16:06:52|echod        702M
17-02 16:07:52|echod        723M
17-02 16:08:52|echod        743M
17-02 16:09:52|echod        763M
17-02 16:10:52|echod        783M
17-02 16:11:52|echod        802M
17-02 16:12:52|echod        822M
17-02 16:13:52|echod        841M
17-02 16:14:52|echod        861M
17-02 16:15:52|echod        880M
17-02 16:16:52|echod        900M
17-02 16:17:52|echod        920M
17-02 16:18:52|echod        940M
17-02 16:19:52|echod        961M
17-02 16:20:52|echod        980M
17-02 16:21:52|echod       1000M
17-02 16:22:52|echod       1020M
----system---- --most-expensive-
     time     |  memory process
17-02 16:23:52|echod       1040M
17-02 16:24:52|echod       1059M
17-02 16:25:52|echod       1079M
17-02 16:26:52|echod       1099M
17-02 16:27:52|echod       1119M
17-02 16:28:52|echod       1138M
17-02 16:29:52|echod       1157M
17-02 16:30:52|echod       1177M
17-02 16:31:52|echod       1197M
17-02 16:32:52|echod       1216M
17-02 16:33:52|echod       1236M
17-02 16:34:52|echod       1256M
17-02 16:35:52|echod       1276M
17-02 16:36:52|echod       1296M
17-02 16:37:52|echod       1316M
17-02 16:38:52|echod       1336M


========== [2] ==========

    for (;;) {
        apr_pool_t * socket_pool;

        if (apr_pool_create(&socket_pool, parent) != APR_SUCCESS)
           return APR_ENOPOOL;

        rv = apr_socket_accept(&accepted, listener, socket_pool);
        if (rv != APR_SUCCESS) {
            reportError("Error accepting on socket", rv, socket_pool);
            break;
        }
        printf("\tAnswering connection\n");
        rv = talkTalk(accepted, parent);
        apr_socket_close(accepted);
        apr_pool_clear(socket_pool);
        apr_pool_destroy(socket_pool);
        printf("\tConnection closed\n");
        if (rv != APR_SUCCESS)
            break;
    }

========== [3] ==========

After second run of sockperf:

POOL DEBUG: [22710/140028982032128]  CREATE (         0/         0/       898) 0x7f5b09ad1f68 "echod.c:99" <echod.c:99> (0/0/0)
POOL DEBUG: [22710/140028982032128] PCALLOC (        80/        80/       978) 0x7f5b09ad1f68 "echod.c:99" <network_io/unix/sockets.c:69> (1/1/0)
POOL DEBUG: [22710/140028982032128] PCALLOC (       272/       272/      1170) 0x7f5b09ad1f68 "echod.c:99" <network_io/unix/sockets.c:72> (2/2/0)
POOL DEBUG: [22710/140028982032128] PCALLOC (       464/       464/      1362) 0x7f5b09ad1f68 "echod.c:99" <network_io/unix/sockets.c:75> (3/3/0)
POOL DEBUG: [22710/140028982032128]  PALLOC (       496/       496/      1394) 0x7f5b09ad1f68 "echod.c:99" <memory/unix/apr_pools.c:2218> (4/4/0)
	Answering connection
POOL DEBUG: [22710/140028982032128]  CREATE (         0/         0/      1394) 0x7f5b09adff68 "echod.c:45" <echod.c:45> (0/0/0)
POOL DEBUG: [22710/140028982032128]  PALLOC (      4096/      4096/      5490) 0x7f5b09adff68 "echod.c:45" <echod.c:49> (1/1/0)
POOL DEBUG: [22710/140028982032128]   CLEAR (      4096/      4096/      5490) 0x7f5b09adff68 "echod.c:45" <echod.c:63> (1/1/0)
POOL DEBUG: [22710/140028982032128] DESTROY (         0/         0/      1394) 0x7f5b09adff68 "echod.c:45" <echod.c:64> (0/1/1)
POOL DEBUG: [22710/140028982032128]   CLEAR (       496/       496/      1394) 0x7f5b09ad1f68 "echod.c:99" <echod.c:110> (4/4/0)
POOL DEBUG: [22710/140028982032128] DESTROY (         0/         0/       898) 0x7f5b09ad1f68 "echod.c:99" <echod.c:111> (0/4/1)
	Connection closed
POOL DEBUG: [22710/140028982032128]  CREATE (         0/         0/       898) 0x7f5b09ad1f68 "echod.c:99" <echod.c:99> (0/0/0)