Professional Web Applications Themes

capturing/viewing sort_mem utilization on a per query basis - PostgreSQL / PGSQL

Greetings, I've got a pesky J2EE based app that is using PostgreSQL-7.4.x on the backend. Lately i've been getting a disturbing large number of PostgreSQL out of memory exceptions on the J2EE side when running queries that have some huge joins in them. I've tried increasing the sort_mem value for the DB , but that hasn't had any noticable impact. Rather than fumbling blindly in the dark, i'd like to get a better idea of how much memory this query really needs. Is there a way for me to capture that in the log? Note, i'm not the person who ...

  1. #1

    Default capturing/viewing sort_mem utilization on a per query basis

    Greetings,
    I've got a pesky J2EE based app that is using PostgreSQL-7.4.x on the
    backend. Lately i've been getting a disturbing large number of
    PostgreSQL out of memory exceptions on the J2EE side when running
    queries that have some huge joins in them. I've tried increasing the
    sort_mem value for the DB , but that hasn't had any noticable impact.
    Rather than fumbling blindly in the dark, i'd like to get a better
    idea of how much memory this query really needs.

    Is there a way for me to capture that in the log?

    Note, i'm not the person who wrote this app or the query, i'm just the
    guy responsible for the DB. I've already castigated the folks who
    wrote this resource hog.

    thanks,
    Lonni

    --
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~
    L. Friedman [email]netllama[/email]
    LlamaLand [url]http://netllama.linux-sxs.org[/url]

    ---------------------------(end of broadcast)---------------------------
    TIP 8: explain yze is your friend

    Lonni J Friedman Guest

  2. #2

    Default Re: capturing/viewing sort_mem utilization on a per query basis

    On Wed, 02 Feb 2005 11:17:59 -0500, Tom Lane <pgh.pa.us> wrote: 
    >
    > Such an error on the client side would indicate that the query retrieved
    > more rows than the client app had memory for. Perhaps your problem is
    > incorrectly-constrained joins that are returning way more rows than
    > you expect?[/ref]

    You might be right, i'm honestly not sure. What we're seeing on the
    client side is:
    org.postgresql.util.PSQLException: ERROR: out of memory

    Although, looking in the log postgresql is generating, I'm seeing the
    following at the same time as that OOM above so it certainly looks
    like the DB is barfing:
    ###############
    TopMemoryContext: 71448 total in 7 blocks; 22544 free (120 chunks); 48904 used
    TopTransactionContext: 8192 total in 1 blocks; 8136 free (0 chunks); 56 used
    DeferredTriggerXact: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    MessageContext: 1040384 total in 7 blocks; 395024 free (1021 chunks);
    645360 used
    PortalMemory: 8192 total in 1 blocks; 8040 free (0 chunks); 152 used
    PortalHeapMemory: 1024 total in 1 blocks; 800 free (0 chunks); 224 used
    ExecutorState: 2121752 total in 9 blocks; 538864 free (12 chunks); 1582888 used
    HashTableContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    HashBatchContext: 451796 total in 2 blocks; 260800 free (0 chunks); 190996 used
    HashTableContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    HashBatchContext: -1934683632 total in 295 blocks; 135760 free (879
    chunks); -1934819392 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    DynaHashTable: 24576 total in 2 blocks; 11128 free (4 chunks); 13448 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    CacheMemoryContext: 2088960 total in 8 blocks; 1595032 free (3190
    chunks); 493928 used
    relationship_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    relation_type: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    relation_target: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    relation_origin: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    field_value_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    field_class_idx: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    field_value_idx: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    f_val_fid_val_idx: 1024 total in 1 blocks; 320 free (0 chunks); 704 used
    report_param_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    report_parm_report: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    projectmember_pk: 1024 total in 1 blocks; 320 free (0 chunks); 704 used
    projmember_member: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_opclass_oid_index: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    role_user_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    role_user_proj_idx: 2048 total in 1 blocks; 768 free (0 chunks); 1280 used
    role_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    sfuser_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    sfuser_username: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    role_operation_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    role_oper_obj_oper: 2048 total in 1 blocks; 768 free (0 chunks); 1280 used
    artifact_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    artifact_status: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_amop_opr_opc_index: 1024 total in 1 blocks; 320 free (0 chunks); 704 used
    pg_statistic_relid_att_index: 1024 total in 1 blocks; 320 free (0
    chunks); 704 used
    project_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    project_path: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    folder_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    folder_parent: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    folder_project: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    folder_path: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    item_pk: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    item_name: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    item_folder: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_index_indrelid_index: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_type_typname_nsp_index: 1024 total in 1 blocks; 320 free (0 chunks); 704 used
    pg_proc_oid_index: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_cast_source_target_index: 1024 total in 1 blocks; 320 free (0
    chunks); 704 used
    pg_type_oid_index: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_operator_oprname_l_r_n_index: 2048 total in 1 blocks; 704 free (0
    chunks); 1344 used
    pg_namespace_nspname_index: 1024 total in 1 blocks; 640 free (0
    chunks); 384 used
    pg_shadow_usesysid_index: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_trigger_tgrelid_tgname_index: 1024 total in 1 blocks; 320 free (0
    chunks); 704 used
    pg_operator_oid_index: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_amproc_opc_procnum_index: 1024 total in 1 blocks; 320 free (0
    chunks); 704 used
    pg_amop_opc_strategy_index: 1024 total in 1 blocks; 320 free (0
    chunks); 704 used
    pg_index_indexrelid_index: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_attribute_relid_attnum_index: 1024 total in 1 blocks; 320 free (0
    chunks); 704 used
    pg_class_oid_index: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_amproc_opc_procnum_index: 1024 total in 1 blocks; 320 free (0
    chunks); 704 used
    pg_operator_oid_index: 1024 total in 1 blocks; 640 free (0 chunks); 384 used
    pg_amop_opc_strategy_index: 1024 total in 1 blocks; 320 free (0
    chunks); 704 used
    pg_class_relname_nsp_index: 1024 total in 1 blocks; 320 free (0
    chunks); 704 used
    MdSmgr: 8192 total in 1 blocks; 6120 free (0 chunks); 2072 used
    DynaHash: 8192 total in 1 blocks; 6912 free (0 chunks); 1280 used
    DynaHashTable: 8192 total in 1 blocks; 2008 free (0 chunks); 6184 used
    DynaHashTable: 8192 total in 1 blocks; 5080 free (0 chunks); 3112 used
    DynaHashTable: 8192 total in 1 blocks; 2008 free (0 chunks); 6184 used
    DynaHashTable: 24576 total in 2 blocks; 15256 free (4 chunks); 9320 used
    DynaHashTable: 8192 total in 1 blocks; 1960 free (0 chunks); 6232 used
    DynaHashTable: 24576 total in 2 blocks; 13240 free (4 chunks); 11336 used
    DynaHashTable: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    DynaHashTable: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    DynaHashTable: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    DynaHashTable: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    DynaHashTable: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    ErrorContext: 49152 total in 4 blocks; 49088 free (27 chunks); 64 used
    2005-02-02 01:33:51 ERROR: out of memory
    DETAIL: Failed on request of size 364.

    --
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~
    L. Friedman com
    LlamaLand http://netllama.linux-sxs.org

    ---------------------------(end of broadcast)---------------------------
    TIP 1: subscribe and unsubscribe commands go to org

    Lonni Guest

  3. #3

    Default Re: capturing/viewing sort_mem utilization on a per query basis

    Lonni J Friedman <com> writes: [/ref]
     

    One of the three Hash steps must be absorbing a whole lot more rows than
    the planner is expecting, but all of them look like fairly
    straightforward estimation situations:

    -> Hash (cost=108.96..108.96 rows=28 width=24)
    -> Index Scan using mntr_subscr_usrevt on mntr_subscription sfmain_monitoringsubscriptio0 (cost=0.00..108.96 rows=28 width=24)
    Index Cond: (((user_id)::text = 'user1187'::text) AND ((event_operation)::text = 'update'::text))

    -> Hash (cost=701.44..701.44 rows=34444 width=24)
    -> Seq Scan on field_value tracker_artifact_group0 (cost=0.00..701.44 rows=34444 width=24)

    -> Hash (cost=5.74..5.74 rows=1 width=80)
    -> Index Scan using project_path on project tracker_artifact_extension_f1 (cost=0.00..5.74 rows=1 width=80)
    Index Cond: (("path")::text = 'projects.meeting_broker_v3'::text)
    Filter: ((("path")::text = 'projects.meeting_broker_v3'::text) OR (("path")::text ~~ 'projects.meeting_broker_v3.%'::text))

    Perhaps one of these tables hasn't been vacuumed/yzed and is way
    bigger than the planner thinks? Can you check into how many rows
    actually meet the identified conditions?

    regards, tom lane

    ---------------------------(end of broadcast)---------------------------
    TIP 5: Have you checked our extensive FAQ?

    http://www.postgresql.org/docs/faq

    Tom Guest

  4. #4

    Default Re: capturing/viewing sort_mem utilization on a per query basis

    On Wed, 02 Feb 2005 12:58:49 -0500, Tom Lane <tglsss.pgh.pa.us> wrote:
    > Lonni J Friedman <netllama> writes:
    > > On Wed, 02 Feb 2005 12:13:59 -0500, Tom Lane <tglsss.pgh.pa.us> wrote:
    > >> Hmm, looks like a hash join ran out of memory. What PG version is this
    > >> again, and what do you have sort_mem set to? Can you show an EXPLAIN
    > >> for the query that is failing like this?
    >
    > > I've attached the explain for the query that is ing up.
    >
    > One of the three Hash steps must be absorbing a whole lot more rows than
    > the planner is expecting, but all of them look like fairly
    > straightforward estimation situations:
    >
    > -> Hash (cost=108.96..108.96 rows=28 width=24)
    > -> Index Scan using mntr_subscr_usrevt on mntr_subscription sfmain_monitoringsubscriptio0 (cost=0.00..108.96 rows=28 width=24)
    > Index Cond: (((user_id)::text = 'user1187'::text) AND ((event_operation)::text = 'update'::text))
    >
    > -> Hash (cost=701.44..701.44 rows=34444 width=24)
    > -> Seq Scan on field_value tracker_artifact_group0 (cost=0.00..701.44 rows=34444 width=24)
    >
    > -> Hash (cost=5.74..5.74 rows=1 width=80)
    > -> Index Scan using project_path on project tracker_artifact_extension_f1 (cost=0.00..5.74 rows=1 width=80)
    > Index Cond: (("path")::text = 'projects.meeting_broker_v3'::text)
    > Filter: ((("path")::text = 'projects.meeting_broker_v3'::text) OR (("path")::text ~~ 'projects.meeting_broker_v3.%'::text))
    >
    > Perhaps one of these tables hasn't been vacuumed/yzed and is way
    I'm doing a 'vacuumdb -a -z' every 15 minutes, and a full vacuum once/day.
    > bigger than the planner thinks? Can you check into how many rows
    > actually meet the identified conditions?
    I'm afraid i'm not clear on what i'm supposed to be checking here.
    Which conditions should I be looking at? thanks.

    --
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~
    L. Friedman [email]netllama[/email]
    LlamaLand [url]http://netllama.linux-sxs.org[/url]

    ---------------------------(end of broadcast)---------------------------
    TIP 4: Don't 'kill -9' the postmaster

    Lonni J Friedman Guest

  5. #5

    Default Re: capturing/viewing sort_mem utilization on a per query basis

    Lonni J Friedman <com> writes: 

    Well, for instance,
     [/ref]

    select count(*) from mntr_subscription where (((user_id)::text =
    'user1187'::text) AND ((event_operation)::text = 'update'::text));

    regards, tom lane

    ---------------------------(end of broadcast)---------------------------
    TIP 6: Have you searched our list archives?

    http://archives.postgresql.org

    Tom Guest

  6. #6

    Default Re: capturing/viewing sort_mem utilization on a per query basis

    Lonni J Friedman <netllama> writes:
    > OK, i think i see what you're requesting. How's this:
    What about field_value, does it in fact have circa 34444 rows?

    These tables are surely nowhere near big enough to bloat a hash table to
    upwards of 2Gb, as your log shows happened. I'm thinking that you must
    have found some sort of bug, or memory leak maybe. Is there a way I can
    get access to your data set to trace through the behavior with a debugger?

    (We should probably take the discussion offlist at this point.)

    regards, tom lane

    ---------------------------(end of broadcast)---------------------------
    TIP 8: explain yze is your friend

    Tom Lane Guest

Similar Threads

  1. Viewing/Save Access Query Objects from CF
    By mpalsf in forum Coldfusion Database Access
    Replies: 2
    Last Post: February 16th, 05:48 PM
  2. changing sort_mem on the fly?
    By Lonni J Friedman in forum PostgreSQL / PGSQL
    Replies: 19
    Last Post: January 30th, 10:09 PM
  3. Incrementing a value on a rolling basis
    By Jim in forum Microsoft SQL / MS SQL Server
    Replies: 3
    Last Post: July 10th, 02:45 PM

Bookmarks

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •  

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139