Hi!
I have a huge problem here. On a busy server (a web system, mainly java servlets/jsp running on tomcat) running postgresql-8.0.2, all of a sudden, one of the postgres processes gets into the state "idle in transation" (revealed by `ps axU pgsql').
We use transaction very sparesly, so this is a mystery to me. I've swithed on logging of all statements, and also added the transaction id. part of the log is attached. As you can see, the transaction id is incremented, for every query, until suddenly, it is not incremented anymore, but stays the same. It seems to me, from lookin at the logs, that postgres enters a transaction although no BEGIN statement was issued? I hope I'm doing a misinterpretation of the logs here?
So, in a couple of minutes, all connections are taken and a hundred postgres procs sit here waiting for the transaction to finish so they can issue their inserts.
First, there shouldn't be a transaction here at all, how come it starts? And how come there's no BEGIN in the log, if one is actually started?
My solution when this happens (has happened a couple of times a day on a busy server) is to kill the process that is reported "idle in transaction". That way we loose data, I'd rather get it to commit. Is there a way to do that?
Here are all the logging directives in postgresql.conf:
log_destination = 'syslog' silent_mode = true log_line_prefix = '<%x>' log_statement = 'all'
The attached log was grepped on the problematic PID, btw.
postgresql-8.0.2 running on FreeBSD 4.10. jdbc 8.0.311
The icu patch is applied (http://people.freebsd.org/~girgen/postgresql-icu/) but I can't see how that would interfere with transaction handling?
Thanks, Palle
Apr 21 09:50:23 postgres[22588]: [15213-8] (nfold.node_id = n.node_id) left outer join node_item ni on (ni.node_id = n.node_id) left outer join node_portfolio np on Apr 21 09:50:23 postgres[22588]: [15213-9] (np.node_id = n.node_id) left outer join node_objective nop on (nop.node_id = np.objective_id) left outer join component nopc Apr 21 09:50:23 postgres[22588]: [15213-10] on (nopc.id = nop.objective_type_id) where nc.node_id = $1 order by nc.seq Apr 21 09:50:23 postgres[22588]: [15214-1] <14243871>LOG: statement: select p.meta_name, p.meta_info, h.start_file_id, h.use_pp_css, p.htype, p.scorm_type, p.derived_from Apr 21 09:50:23 postgres[22588]: [15214-2] from part p left outer join html_part h on (p.id = h.part_id) where p.id = $1 Apr 21 09:50:23 postgres[22588]: [15215-1] <14243872>LOG: statement: select pq.q_submit_id, qs.max_time, qs.lock_other_content from part_quiz pq join q_submit qs on Apr 21 09:50:23 postgres[22588]: [15215-2] (qs.id = pq.q_submit_id) where pq.part_id = $1 Apr 21 09:50:23 postgres[22588]: [15216-1] <14243873>LOG: statement: select count(*) from discuss_mail_queue Apr 21 09:50:23 postgres[22588]: [15217-1] <14243873>LOG: statement: select qsc.q_submit_id, qs.lock_other_content from q_submit_comp qsc join published_part_components Apr 21 09:50:23 postgres[22588]: [15217-2] ppc on (qsc.q_comp_id = ppc.component_id) join q_submit qs on (qs.id = qsc.q_submit_id) where ppc.part_id = $1 and qs.max_time Apr 21 09:50:23 postgres[22588]: [15217-3] is not null limit 1 Apr 21 09:50:23 postgres[22588]: [15218-1] <14243873>LOG: statement: select distinct p.email, p.default_language, ds.name, m.heading, m.content, m.created, Apr 21 09:50:23 postgres[22588]: [15218-2] cp.discuss_mail_only_info, c.meta_name, m.creator_name from person p join discuss_subject_subscribe dss on (dss.userid = Apr 21 09:50:23 postgres[22588]: [15218-3] p.userid) join discuss_subject ds on (ds.subject_id = dss.subject_id) join discuss_mail_queue dmq on (dmq.subject_id = Apr 21 09:50:23 postgres[22588]: [15218-4] ds.subject_id) join discuss_course dc on (dc.subject_id = ds.subject_id) join course c on (c.id = dc.course_id) join Apr 21 09:50:23 postgres[22588]: [15218-5] course_prefs cp on (cp.course_id = c.id) join message m on (m.message_id = dmq.message_id) left outer join message_read mr on Apr 21 09:50:23 postgres[22588]: [15218-6] (mr.message_id = m.message_id and mr.userid = p.userid) join group_data gd on (gd.this_group_id = dc.group_id and gd.item_text Apr 21 09:50:23 postgres[22588]: [15218-7] = p.userid) where mr.userid is null union select p.email, p.default_language, ds.name, m.heading, m.content, m.created, Apr 21 09:50:23 postgres[22588]: [15218-8] cp.discuss_mail_only_info, c.meta_name, m.creator_name from person p join discuss_subject_subscribe dss on (dss.userid = Apr 21 09:50:23 postgres[22588]: [15218-9] p.userid) join discuss_subject ds on (ds.subject_id = dss.subject_id) join discuss_mail_queue dmq on (dmq.subject_id = Apr 21 09:50:23 postgres[22588]: [15218-10] ds.subject_id) join discuss_group dg on (dg.subject_id = ds.subject_id) join group_group gg on (gg.group_id = dg.group_id) join Apr 21 09:50:23 postgres[22588]: [15218-11] course c on (c.groups_group_id = gg.this_group_id) join course_prefs cp on (cp.course_id = c.id) join message m on Apr 21 09:50:23 postgres[22588]: [15218-12] (m.message_id = dmq.message_id) left outer join message_read mr on (mr.message_id = m.message_id and mr.userid = p.userid) join Apr 21 09:50:23 postgres[22588]: [15218-13] group_data gd on (gd.this_group_id = dg.group_id and gd.item_text = p.userid) where mr.userid is null Apr 21 09:50:23 postgres[22588]: [15219-1] <14243873>LOG: statement: select poll_submit_id from part_poll where part_id = $1 Apr 21 09:50:23 postgres[22588]: [15220-1] <14243873>LOG: statement: delete from discuss_mail_queue Apr 21 09:50:23 postgres[22588]: [15221-1] <14243873>LOG: statement: select rs_id from part_report_submission where part_id = $1 Apr 21 09:50:23 postgres[22588]: [15222-1] <14243874>LOG: statement: SELECT name, value FROM item_property WHERE item_id = $1 Apr 21 09:50:23 postgres[22588]: [15223-1] <14243874>LOG: statement: select n.node_id, n.node_type, n.node_name, n.node_description, n.node_keywords, n.ts, Apr 21 09:50:23 postgres[22588]: [15223-2] n.last_changed, n.created_by, trim(p.first_name || ' ' || p.last_name) as created_by_name, nl.url, nf.file_size, Apr 21 09:50:23 postgres[22588]: [15223-3] nf.mime_type, nf.file_name, nf.file_id, nfold.folder_quota, ni.part_id, ni.nav_visible, ni.orient_visible, Apr 21 09:50:23 postgres[22588]: [15223-4] ni.separate_window, np.portfolio_type, np.course_id, np.objective_id, np.document_node_id, nopc.meta_name as Apr 21 09:50:23 postgres[22588]: [15223-5] portfolio_target_name, nopc.id as portfolio_target_id, nopc.type as portfolio_target_type, nc.seq from node_content nc join Apr 21 09:50:23 postgres[22588]: [15223-6] node n on (nc.content_node_id = n.node_id) left outer join person p on (n.created_by = p.userid) left outer join node_link nl Apr 21 09:50:23 postgres[22588]: [15223-7] on (nl.node_id = n.node_id) left outer join node_file nf on (nf.node_id = n.node_id) left outer join node_folder nfold on Apr 21 09:50:23 postgres[22588]: [15223-8] (nfold.node_id = n.node_id) left outer join node_item ni on (ni.node_id = n.node_id) left outer join node_portfolio np on Apr 21 09:50:23 postgres[22588]: [15223-9] (np.node_id = n.node_id) left outer join node_objective nop on (nop.node_id = np.objective_id) left outer join component nopc Apr 21 09:50:23 postgres[22588]: [15223-10] on (nopc.id = nop.objective_type_id) where nc.node_id = $1 order by nc.seq Apr 21 09:50:23 postgres[22588]: [15224-1] <14243874>LOG: statement: SELECT name, value FROM item_property WHERE item_id = $1 Apr 21 09:50:23 postgres[22588]: [15225-1] <14243874>LOG: statement: select n.node_id, n.node_type, n.node_name, n.node_description, n.node_keywords, n.ts, Apr 21 09:50:23 postgres[22588]: [15225-2] n.last_changed, n.created_by, trim(p.first_name || ' ' || p.last_name) as created_by_name, nl.url, nf.file_size, Apr 21 09:50:23 postgres[22588]: [15225-3] nf.mime_type, nf.file_name, nf.file_id, nfold.folder_quota, ni.part_id, ni.nav_visible, ni.orient_visible, Apr 21 09:50:23 postgres[22588]: [15225-4] ni.separate_window, np.portfolio_type, np.course_id, np.objective_id, np.document_node_id, nopc.meta_name as Apr 21 09:50:23 postgres[22588]: [15225-5] portfolio_target_name, nopc.id as portfolio_target_id, nopc.type as portfolio_target_type, nc.seq from node_content nc join Apr 21 09:50:23 postgres[22588]: [15225-6] node n on (nc.content_node_id = n.node_id) left outer join person p on (n.created_by = p.userid) left outer join node_link nl Apr 21 09:50:23 postgres[22588]: [15225-7] on (nl.node_id = n.node_id) left outer join node_file nf on (nf.node_id = n.node_id) left outer join node_folder nfold on Apr 21 09:50:23 postgres[22588]: [15225-8] (nfold.node_id = n.node_id) left outer join node_item ni on (ni.node_id = n.node_id) left outer join node_portfolio np on Apr 21 09:50:23 postgres[22588]: [15225-9] (np.node_id = n.node_id) left outer join node_objective nop on (nop.node_id = np.objective_id) left outer join component nopc Apr 21 09:50:23 postgres[22588]: [15225-10] on (nopc.id = nop.objective_type_id) where nc.node_id = $1 order by nc.seq Apr 21 09:50:23 postgres[22588]: [15226-1] <14243874>LOG: statement: SELECT * FROM course_prefs WHERE course_id = $1 Apr 21 09:50:23 postgres[22588]: [15227-1] <14243874>LOG: statement: select p.meta_name, p.meta_info, h.start_file_id, h.use_pp_css, p.htype, p.scorm_type, p.derived_from Apr 21 09:50:23 postgres[22588]: [15227-2] from part p left outer join html_part h on (p.id = h.part_id) where p.id = $1 Apr 21 09:50:23 postgres[22588]: [15228-1] <14243874>LOG: statement: select * from course_nav where course_id = $1 Apr 21 09:50:23 postgres[22588]: [15229-1] <14243874>LOG: statement: select pq.q_submit_id, qs.max_time, qs.lock_other_content from part_quiz pq join q_submit qs on Apr 21 09:50:23 postgres[22588]: [15229-2] (qs.id = pq.q_submit_id) where pq.part_id = $1 Apr 21 09:50:23 postgres[22588]: [15230-1] <14243874>LOG: statement: select * from course_nav_item where course_id = $1 Apr 21 09:50:23 postgres[22588]: [15231-1] <14243874>LOG: statement: select qsc.q_submit_id, qs.lock_other_content from q_submit_comp qsc join published_part_components Apr 21 09:50:23 postgres[22588]: [15231-2] ppc on (qsc.q_comp_id = ppc.component_id) join q_submit qs on (qs.id = qsc.q_submit_id) where ppc.part_id = $1 and qs.max_time Apr 21 09:50:23 postgres[22588]: [15231-3] is not null limit 1 Apr 21 09:50:23 postgres[22588]: [15232-1] <14243874>LOG: statement: select abstract_id, prop_id from course where id = $1 Apr 21 09:50:23 postgres[22588]: [15233-1] <14243874>LOG: statement: select poll_submit_id from part_poll where part_id = $1 Apr 21 09:50:23 postgres[22588]: [15234-1] <14243874>LOG: statement: select custom_nav_id from course_custom_nav where course_id = $1 Apr 21 09:50:23 postgres[22588]: [15235-1] <14243874>LOG: statement: select rs_id from part_report_submission where part_id = $1 Apr 21 09:50:23 postgres[22588]: [15236-1] <14243874>LOG: statement: select 1 from pim where type >= 0 and read = false and recipient = $1 limit 1 Apr 21 09:50:23 postgres[22588]: [15237-1] <14243874>LOG: statement: SELECT name, value FROM item_property WHERE item_id = $1 Apr 21 09:50:23 postgres[22588]: [15238-1] <14243874>LOG: statement: select n.node_id, n.node_type, n.node_name, n.node_description, n.node_keywords, n.ts, Apr 21 09:50:23 postgres[22588]: [15238-2] n.last_changed, n.created_by, trim(p.first_name || ' ' || p.last_name) as created_by_name, nl.url, nf.file_size, Apr 21 09:50:23 postgres[22588]: [15238-3] nf.mime_type, nf.file_name, nf.file_id, nfold.folder_quota, ni.part_id, ni.nav_visible, ni.orient_visible, Apr 21 09:50:23 postgres[22588]: [15238-4] ni.separate_window, np.portfolio_type, np.course_id, np.objective_id, np.document_node_id, nopc.meta_name as Apr 21 09:50:23 postgres[22588]: [15238-5] portfolio_target_name, nopc.id as portfolio_target_id, nopc.type as portfolio_target_type, nc.seq from node_content nc join Apr 21 09:50:23 postgres[22588]: [15238-6] node n on (nc.content_node_id = n.node_id) left outer join person p on (n.created_by = p.userid) left outer join node_link nl Apr 21 09:50:23 postgres[22588]: [15238-7] on (nl.node_id = n.node_id) left outer join node_file nf on (nf.node_id = n.node_id) left outer join node_folder nfold on Apr 21 09:50:23 postgres[22588]: [15238-8] (nfold.node_id = n.node_id) left outer join node_item ni on (ni.node_id = n.node_id) left outer join node_portfolio np on
---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@xxxxxxxxxxxxxx so that your
message can get through to the mailing list cleanly
