|
|
|
|
|
The comment from Robert Haas is correct. Your analysis does not seem to show any evidence of real memory leak. About your customer's report. I need more details: configuration(pgpool.conf) and the result of valgrind after 8 hours run(or at least long enough run until memory leak is observed). |
|
|
|
|
|
|
|
|
Below is the information requested: - val.log.27681 (when it's memory leak)(attached) - pgpool_ps_20120828_01.log (this was taken when they're executing valgrind)- As the size of file is larger than 2097K, we have upload at the below link: http://uploads.enterprisedb.com/download.php?file=bd3d686fc3395bec9992d246018f41a9 - pgpool.conf (customer's configuration)(attached) |
|
|
Thanks. I would like to see source code around pool_process_query.c:2566, where malloc is called. I'm asking this because your pgpool seems different from community version of pgpool-II 3.1. ==27681== at 0x4A05E1C: malloc (vg_replace_malloc.c:195) ==27681== by 0x413D5F: do_query (pool_process_query.c:2566) ==27681== by 0x4352A3: pool_search_relcache (pool_relcache.c:170) ==27681== by 0x43C9F0: rewrite_timestamp (pool_timestamp.c:407) ==27681== by 0x44244F: Parse (pool_proto_modules.c:738) ==27681== by 0x443559: ProcessFrontendResponse (pool_proto_modules.c:2081) ==27681== by 0x417ACC: pool_process_query (pool_process_query.c:345) ==27681== by 0x409871: do_child (child.c:354) ==27681== by 0x403F04: fork_a_child (main.c:1073) ==27681== by 0x406C00: main (main.c:550) |
|
|
pool_process_query_line2566.png (111,733 bytes) |
|
|
Hi, My preliminary investigation shows that line 2566 in pool_process_query.c is this line in do_query() function, under switch-case 'D' (data row processing): res->data[num_data] = malloc(len + 1); I have attached ascreenshot of the relevant section of this file for your reference. Best regards, |
|
|
The problem seems to be that the callers of do_query() do not call 'free_select_result(res)' if do_query() call fails (that is, if do_query() does not return POOL_CONTINUE (0)). And, the return statements in do_query() that exit the function with error conditions do not care to free the locally allocated 'POOL_SELECT_RESULT *res' structure and its members. So, if a do_query() call fails after allocating the res struct and some of its members, then all the memory allocated for the result descriptor POOL_SELECT_RESULT is leaked. I believe the fix is to replace every return statement in do_query() with a macro that calls free_select_result(res) before exiting the function. #define RETURN(EXIT_CODE) \ do { \ if (EXIT_CODE != POOL_CONTINUE) \ free_select_result(res); \ return EXIT_CODE; \ } while(0) And then replace every occurrence of 'return POOL_XYZ;' in do_query() with 'RETURN(POOL_XYZ);'. This fix also requires that the code that allocates the attribute info under "case 'T'" be modified such that the free()'ing code can cope with the struct if only some of the fields were successfully allocated. That is, this line: rowdesc->num_attrs = num_fields; should be converted to rowdesc->num_attrs += 1; after this line: attrinfo->attrname = malloc(len); PS: I don't have the exact version of the code that was compiled and shipped with pgpool-II 3.1 along with Postgres Plus Advanced Server 9.1. I will review the code again when I get access to that version of pgpool source code. |
|
|
free_select_result.patch (696 bytes) |
|
|
Thanks for the info. With the source location info of valgrind you provide, I have identified memory leak in free_select_result. It misunderstands the POOL_SELECT_RESULT structure. It keeps row data in "data" field, which is a one dimension array: that is, if do_query get 2 rows and 3 attributes data, the array would be: [row 0 attribute 0][row 0 attribute 1][row 0 attribute 2][row 1 attribute 0][row 1 attribute 1][row 1 attribute 2]. However free_select_result thinks as:[whole row 0 data][whole row 1 data]. As a result, it frees only 2 data, while it should free 6 data. Attached patch should fix the problem. Please try it. BTW, your analysis on do_query error case might worth to consider, but I don't think that's your customer's case since your test did not resulted in do_query error case(correct me if I am wrong). So I think I don't want to risk to make patch for it for now. |
|
|
Aha! I didn't catch that glaring bug. I was treating 'res->numrows++' and 'num_data++' as equivalent and was going to complain as to why we have two variables recording the same info. Now I see that they are actually tracking different info. res->numrows is for number of rows processed and num_data is for number of cells (cross-section of a row and a column) allocated. I blame deeply nested, multi-page code blocks for misleading me :) It was a cursory look at the code for leaks before I got hold of the actual version of the code being used at customer's installation. I agree this is quite a serious bug, and there's a high possibility that our customer is encountering this bug. But I'll let the tests with a patched pgpool prove that. An OLTP-like environment combined with a high setting of 'child_max_connections = 1000' may be one of the reasons why we could see this leak balloon up so much that it became obvious to the observer. In other setups, a lower value of child_max_connections may lead to child processes to exit/die early and hence memory leaks would vanish soon with the process' death. IMHO, the leaks in do_query() on error conditions also need to be addressed nonetheless. |
|
|
I think the most significant factor to the memory leak problem is long running client connection. If clients keep on connecting to pgpool for hours, the leak will be quickly accumulated. I believe that's the case for your customer. As far as I know, most pgpool users use child_life_time or child_max_connections parameter to allow to restart pgpool child process, which results in avoiding memory leak problems. Also please note that the leak will not appear in other than replication mode by unintended reason. Most calles to do_query expect one row and one attribute returned. So the leak actually will not appear. However in replication mode, the time rewriting routine calls do_query expecting several fields returned. In summary, long running client connection and replication mode are the key factor to trigger the memory leak. I think that's the reason why we didn't hear complains from field (the bug has been there since 2009, when pgpool-II 2.3 was released). BTW I think do_query() on error conditions you are talking about does not cause memory leak since it goes to here anyway(in child.c): /* error occured. discard backend connection pool and disconnect connection to the frontend */ case POOL_ERROR: pool_log("do_child: exits with status 1 due to error"); child_exit(1); child_exits() calls exit() and the process exits thus memory are freed by kernel. |
|
|
I had a look at the pgpool.conf(Attached) file which was sent by the user and the parameter child_life_time is set to 300 and child_max_connections = 1000. 300 is the default value for child_life_time and default value for child_max_connections is 0 which is set to 1000. Could you please advice whether we should lower these values. |
|
|
|
|
|
These parameters have no effect if client connections last for hours like your customer's case. So I think you don't need to touch those parameters. |
|
|
I have found a memory leak that our customer is facing. When I run the testDsgwInsert.pgc ECPG program against pgpool, I can see these two strings leaking: "tbl_com" (quotes included) pooldb These strings leak as much as 2000 to 3000 times per minute. I was able to ascertain this by attaching to the pgpool backend using gdb, generating core file using generate-core-file command, and the running `strings` utility on the resulting core file, and then processing the strings-generated output using this command chain: cat strings.out | sort | uniq -c | sort -g | tail I was able to track down the cause of the first leak ("tbl_com"), and am attaching a proposed fix (fix_memory_leak.patch). The trouble seems to be caused by the fact that get_insert_command_table_name() function uses session_context->memory_context to perform nodeToString() which allocates a new string "tbl_com" for the table name; and since session_context->memory_context is not released until the frontend disconnects, this memory allocation shows up as a leak on a long-running frontend-connection. The fix I have devised is to create a free*() function to free the string generated by get_insert_command_table_name(), and call this new function from the callers of get_insert_command_table_name() before the caller returns. This makes sure that the memory gets freed immediately. The patch also moves a small piece of code in insert_lock() function to avoid a potential crash if table == NULL. The code with the comment /* trim quotes */ tries to use the return value of get_insert_command_table_name() without checking if the returned pointer is NULL. I haven't been able to find the source of 'pooldb' leak yet. But I have a strong suspicion that this string is part of the string (sql_stmt_cm_insspooldb) the program uses for the name of the prepared statement. I haven't yet been lucky to find this leak's location. PS: Please note that the .pgc file uses PPAS (EDB) specific syntax, so it very likely won't run as is on Postgres. But I am assuming this program can be made to work with Postgres, if reallly needed. PPS: For some reason valgrind's memcheck and massif tools did not help in catching the leaks even when I ran them for 20+ minutes with the all the child processes being traced simultaneously. Perhaps there's something about pgpool's memory allocator that confuses the valgrind tools, pr maybe I haven't grasped yet how to use these tools correctly. |
|
|
|
|
|
fix_memory_leak.patch (4,236 bytes) |
|
|
fix_memory_leak_v2.patch (4,140 bytes) |
|
|
I have attached updated version of the patch: fix_memory_leak_v2.patch. Previous patch had a log line leftover from my debugging sessions. |
|
|
I wonder why query_context was not created when get_insert_command_table_name() is called. Anyway, if query_context was not set, yes the memory allocated by get_insert_command_table_name() will not be freed until the session ends. However the fix you propose looks overkill to me. The function is called only in two places and one caller copies the string allocated by the function immediately. The other just needs to keep the string while calling a function. So I would like fix the problem in following way: Add static buffer to get_insert_command_table_name() and copy the result of nodeToString() to the buffer then free the string returned by nodeToString() immediately. I'm going create a patch and attach it soon. Regarding your concern about insert_lock(), you are correct. Thanks for the patch. |
|
|
I have committed and push to master to V3_0_STABLE. For V3_1_STABLE diff, please look at: http://git.postgresql.org/gitweb/?p=pgpool2.git;a=commitdiff;h=2922349e07f3c585814d7d1f7557101544219e56 |
|
|
I believe the static buffer in get_insert_command_table_name() should be NAMEDATALEN+1, or at least take NAMEDATALEN into account somehow, because if someone compiles pgpool with NAMEDATALEN > 128, bad things can happen. I haven't looked at 3.2 code yet, but I believe this patch should be applied to all supported branches. PS: I would have liked to see some attribution, like we do in Postgres. Also, a mention about the fact that we moved some code to avoid a crash. |
|
|
I have committed to all supported branches. Regarding NAMEDATALEN, problem is there's no reliable way to know how long it is in the pgpool's client and/or PostgreSQL. You will have similar problem even if you don't use pgpool. It will be even possible NAMEDATALEN does not match among PostgeSQL's client and PostgreSQL itself if they are compiled differently. So I think we actually cannot change NAMEDATALEN to other than 63. Regarding string "pooldb", I suspect the leak is caused by pool_create_sent_message() in pool_session_context.c because it's related to prepared statement names and the memory context used by is session context. |
|
|
Hi Tatsuo, I have tracked down the send leak too. Attaching the patch (fix_second_memory_leak.patch) for the fix. Apparently running massif for 20 minutes wasn't enough to make this leak surface to be anywhere in the report. I ran valgrind's massif for 3 hours this time and it pointed to this stack. This stack, which didn't even show up in 20 minute runs, was the only one in the 3-hour run's report; other stacks' allocation paled in comparison to this one. 90 52,383,985,818 15,116,288 14,888,280 228,008 0 98.49% (14,888,280B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. ->97.68% (14,764,992B) 0x46717F: pool_memory_strdup (pool_memory.c:307) |-->97.68% (14,764,992B) 0x449304: pool_create_sent_message (pool_session_context.c:515) |---->97.68% (14,764,992B) 0x447966: Parse (pool_proto_modules.c:741) |------>97.68% (14,764,992B) 0x4482F2: ProcessFrontendResponse (pool_proto_modules.c:2112) |-------->97.68% (14,764,992B) 0x4180AC: pool_process_query (pool_process_query.c:372) |---------->97.68% (14,764,992B) 0x40B340: do_child (child.c:358) |------------>97.68% (14,764,992B) 0x406563: fork_a_child (main.c:1106) |-------------->97.68% (14,764,992B) 0x404A5A: main (main.c:550) | ->00.82% (123,288B) in 1+ places, all below ms_print's threshold (01.00%) Although this stack points to pool_create_sent_message() as the culprit, just as you suspected, but debugging the allocations and frees showed that these objects were being promptly return to freelist on the session_context->memory_context. Tracking the allocations further showed that the same block of memory was being handed from freelist when get_insert_command_table_name() -> nodeToString() -> init_string() was called for the next query. And init_string() makes two allocations, the String object itself, and Srting->data. Yesterday's fix freed the String->data object, but the String object is left behind, and causes the leak. The "pooldb" string was in fact part of the name of the cursor (sql_stmt_cm_insspooldb), and hence the contents of the POOL_SENT_MESSAGE->name, but as explained above, it was promptly freed. Subsequent allocation of the same buffer as a String object overwrites the first 16 bytes of this block, hence only the trailing string "pooldb" shows up in the leak. For the archives, this is how I ran the valgrind-massif tool: valgrind --tool=massif --alloc-fn=pool_memory_alloc --ignore-fn=pool_create_sent_message --ignore-fn=pool_create_relcache inst/bin/pgpool -f ../pgpool_memory_leak/pgpool.conf -F ../pgpool_memory_leak/pcp.conf -n I have also attached the output of massif's output to this bug report (massif.out.17603). One needs to use ms_print utility to view this file's contents. PS: Attribution in commit message please (for 2 leaks and crash-fix, if project policy allows). |
|
|
fix_second_memory_leak.patch (336 bytes) |
|
|
|
|
|
Good catch! I will test your patch and commit it as soon as possible. |
- Anonymous
