Received: from maia.hub.org (maia-2.hub.org [200.46.204.251]) by mail.postgresql.org (Postfix) with ESMTP id 5829B633324 for ; Thu, 2 Sep 2010 15:11:03 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.251]) (amavisd-maia, port 10024) with ESMTP id 49362-04-2 for ; Thu, 2 Sep 2010 18:10:53 +0000 (UTC) X-Greylist: domain auto-whitelisted by SQLgrey-1.7.6 Received: from n3-vm0.bullet.mail.gq1.yahoo.com (n3-vm0.bullet.mail.gq1.yahoo.com [67.195.23.156]) by mail.postgresql.org (Postfix) with SMTP id D53CD6336A6 for ; Thu, 2 Sep 2010 15:10:47 -0300 (ADT) Received: from [98.137.27.132] by n3.bullet.mail.gq1.yahoo.com with NNFMP; 02 Sep 2010 18:10:46 -0000 Received: from [98.137.27.217] by t4.bullet.mail.gq1.yahoo.com with NNFMP; 02 Sep 2010 18:10:46 -0000 Received: from [127.0.0.1] by omp127.mail.gq1.yahoo.com with NNFMP; 02 Sep 2010 18:10:46 -0000 X-Yahoo-Newman-Property: ymail-3 X-Yahoo-Newman-Id: 175220.9662.bm@omp127.mail.gq1.yahoo.com Received: (qmail 48897 invoked by uid 60001); 2 Sep 2010 18:10:45 -0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yahoo.com; s=s1024; t=1283451045; bh=ZaUxPtHEUnDoOoaAs+dlII8PU4OxT121xtIFKQVaCDc=; h=Message-ID:X-YMail-OSG:Received:X-Mailer:References:Date:From:Subject:To:Cc:In-Reply-To:MIME-Version:Content-Type; b=SoLvp8M8I1X/5ZY9r/df3FA0ccAOXp8kDSCwqDNfpTzy8F60PR6smqSiJyrv84RgAH7DqX0SusjaiD3tIZ5LeWZRH1q13Nw/h9vH/GY0R5D/JJp4Gr0Kag2c7XhVJrQvpMp6Tg9vCeOyiIB+MoQz8pwn8gu48m4hZ6p+kkcoKHc= DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=s1024; d=yahoo.com; h=Message-ID:X-YMail-OSG:Received:X-Mailer:References:Date:From:Subject:To:Cc:In-Reply-To:MIME-Version:Content-Type; b=O5+U5VMRuWJ7dDYzWB3bJOMEu5QhXiGRA3qjsretoy/Kr6YjQZ66JKQ7eU1zVg1Zw65HssfQ6tAUgYpixDBkAoou0B6zknoWpeWT+NRNu5w/S8OXliOEYwTaPLvBEjuSIoytOo7YyU3jcFp2shY1mS1fxPbsgLBB5NMnI2EBCoo=; Message-ID: <825153.47733.qm@web120009.mail.ne1.yahoo.com> X-YMail-OSG: GRG1oa0VM1mddBZ2MaIeDNVvmTTj9PC4EACBXdkVnyInrq3 KhNy1lOXsCb6gYf78r6J7aBwDdX.BlyAp5LfJ5N1M0bDHtbCIET7j40x1DtN ZKQx8Sun4nQGYN0HDkl5Y65DJH44lMLHHJZmwikPNMx7SbhEIiTvUp8CepiZ P1sT2Ljvk.5yGQ63ItJycWW.qbWSjl58TCZNxIMXdKkk81zmZNsj.bpyoDwP slWqFBqHJIFCPCqc15g-- Received: from [68.36.215.11] by web120009.mail.ne1.yahoo.com via HTTP; Thu, 02 Sep 2010 11:10:45 PDT X-Mailer: YahooMailRC/470 YahooMailWebService/0.8.105.279950 References: <788866.21140.qm@web120020.mail.ne1.yahoo.com> <4C7D00330200002500034ED2@gw.wicourts.gov> <19320.56933.qm@web120013.mail.ne1.yahoo.com> <529329.89885.qm@web120007.mail.ne1.yahoo.com> <4C7F8F2A0200002500035037@gw.wicourts.gov> <294404.58402.qm@web120007.mail.ne1.yahoo.com> <27124.1283450803@sss.pgh.pa.us> Date: Thu, 2 Sep 2010 11:10:45 -0700 (PDT) From: A J Subject: Re: Confused by 'timing' results To: Tom Lane Cc: Kevin Grittner , Scott Marlowe , pgsql-admin@postgresql.org In-Reply-To: <27124.1283450803@sss.pgh.pa.us> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="0-314020238-1283451045=:47733" X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-1.909 tagged_above=-10 required=5 tests=BAYES_00=-1.9, HTML_MESSAGE=0.001, RCVD_IN_DNSWL_NONE=-0.0001, T_RP_MATCHES_RCVD=-0.01 X-Spam-Level: X-Archive-Number: 201009/22 X-Sequence-Number: 35566 --0-314020238-1283451045=:47733 Content-Type: text/plain; charset=us-ascii The performance as seen from the clients dropped substantially after turning on the extra logging. The numbers were real but the performance dropped significantly. All the log related settings in postgresql.conf are below: log_destination = 'stderr' # Valid values are combinations of #log_directory = 'pg_log' # directory where log files are written, #log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log' # log file name pattern, #log_truncate_on_rotation = off # If on, an existing log file of the #log_rotation_age = 1d # Automatic rotation of logfiles will #log_rotation_size = 10MB # Automatic rotation of logfiles will #syslog_facility = 'LOCAL0' #syslog_ident = 'postgres' #log_min_messages = warning # values in order of decreasing detail: #log_error_verbosity = default # terse, default, or verbose messages #log_min_error_statement = error # values in order of decreasing detail: log_min_duration_statement = 0 # -1 is disabled, 0 logs all statements log_checkpoints = on #log_connections = off #log_disconnections = off #log_duration = off #log_hostname = off log_line_prefix = '%t ' # special values: #log_lock_waits = off # log lock waits >= deadlock_timeout log_statement = 'none' # none, ddl, mod, all #log_temp_files = -1 # log temporary files equal or larger #log_timezone = unknown # actually, defaults to TZ environment #log_parser_stats = off #log_planner_stats = off #log_executor_stats = off #log_statement_stats = off #log_autovacuum_min_duration = -1 # -1 disables, 0 logs all actions and ________________________________ From: Tom Lane To: A J Cc: Kevin Grittner ; Scott Marlowe ; pgsql-admin@postgresql.org Sent: Thu, September 2, 2010 2:06:43 PM Subject: Re: [ADMIN] Confused by 'timing' results A J writes: > On second try, by trying to log to log_directory/log_filename by > setting log_min_duration_statement=0, seems to be doing something weird. The > durations are very very high in the file and cannot be true. You're not being very clear here. Did the logged durations not correspond to reality? Or did the performance as seen from the clients drop substantially when you turned on extra logging? Also, exactly how are you doing logging (ie, what are your settings for log_destination and related parameters)? regards, tom lane --0-314020238-1283451045=:47733 Content-Type: text/html; charset=us-ascii
The performance as seen from the clients dropped substantially after turning on the extra logging. The numbers were real but the performance dropped significantly.

All the log related settings in postgresql.conf are below:
log_destination = 'stderr'              # Valid values are combinations of
#log_directory = 'pg_log'               # directory where log files are written,
#log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log'        # log file name pattern,
#log_truncate_on_rotation = off         # If on, an existing log file of the
#log_rotation_age = 1d                  # Automatic rotation of logfiles will
#log_rotation_size = 10MB               # Automatic rotation of logfiles will
#syslog_facility = 'LOCAL0'
#syslog_ident = 'postgres'
#log_min_messages = warning             # values in order of decreasing detail:
#log_error_verbosity = default          # terse, default, or verbose messages
#log_min_error_statement = error        # values in order of decreasing detail:
log_min_duration_statement = 0 # -1 is disabled, 0 logs all statements
log_checkpoints = on
#log_connections = off
#log_disconnections = off
#log_duration = off
#log_hostname = off
log_line_prefix = '%t '                 # special values:
#log_lock_waits = off                   # log lock waits >= deadlock_timeout
log_statement = 'none'                  # none, ddl, mod, all
#log_temp_files = -1                    # log temporary files equal or larger
#log_timezone = unknown                 # actually, defaults to TZ environment
#log_parser_stats = off
#log_planner_stats = off
#log_executor_stats = off
#log_statement_stats = off
#log_autovacuum_min_duration = -1       # -1 disables, 0 logs all actions and


From: Tom Lane <tgl@sss.pgh.pa.us>
To: A J <s5aly@yahoo.com>
Cc: Kevin Grittner <Kevin.Grittner@wicourts.gov>; Scott Marlowe <scott.marlowe@gmail.com>; pgsql-admin@postgresql.org
Sent: Thu, September 2, 2010 2:06:43 PM
Subject: Re: [ADMIN] Confused by 'timing' results

A J <s5aly@yahoo.com> writes:
> On second try, by trying to log to log_directory/log_filename by
> setting log_min_duration_statement=0, seems to be doing something weird. The
> durations are very very high in the file and cannot be true.

You're not being very clear here.  Did the logged durations not
correspond to reality?  Or did the performance as seen from the clients
drop substantially when you turned on extra logging?  Also, exactly
how are you doing logging (ie, what are your settings for
log_destination and related parameters)?

            regards, tom lane

--0-314020238-1283451045=:47733--