Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1ndHr7-0001gb-GS for pgsql-hackers@arkaria.postgresql.org; Sat, 09 Apr 2022 20:38:49 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1ndHr5-0007wk-F0 for pgsql-hackers@arkaria.postgresql.org; Sat, 09 Apr 2022 20:38:47 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1ndHr4-0007wb-U1 for pgsql-hackers@lists.postgresql.org; Sat, 09 Apr 2022 20:38:47 +0000 Received: from sss.pgh.pa.us ([66.207.139.130]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1ndHqx-0008RA-Tg for pgsql-hackers@postgresql.org; Sat, 09 Apr 2022 20:38:45 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.15.2/8.15.2) with ESMTP id 239KcPmo4183050; Sat, 9 Apr 2022 16:38:26 -0400 From: Tom Lane To: Tatsuo Ishii cc: coelho@cri.ensmp.fr, alvherre@alvh.no-ip.org, nagata@sraoss.co.jp, thomas.munro@gmail.com, m.polyakova@postgrespro.ru, pgsql-hackers@postgresql.org, teodor@sigaev.ru Subject: Re: [HACKERS] WIP aPatch: Pgbench Serialization and deadlock errors In-reply-to: <20220406.100005.1796406557268900302.t-ishii@sranhm.sra.co.jp> References: <20220404.101431.333095021655639605.t-ishii@sranhm.sra.co.jp> <20220405.083805.1138012899895218258.t-ishii@sranhm.sra.co.jp> <20220406.100005.1796406557268900302.t-ishii@sranhm.sra.co.jp> Comments: In-reply-to Tatsuo Ishii message dated "Wed, 06 Apr 2022 10:00:05 +0900" MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0" Content-ID: <4183019.1649536675.0@sss.pgh.pa.us> Date: Sat, 09 Apr 2022 16:38:25 -0400 Message-ID: <4183048.1649536705@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk ------- =_aaaaaaaaaa0 Content-Type: text/plain; charset="us-ascii" Content-ID: <4183019.1649536675.1@sss.pgh.pa.us> Tatsuo Ishii writes: > Patch pushed. Thanks. The buildfarm is still complaining about the synopsis being too wide for PDF format. I think what we ought to do is give up on using a for log lines at all, and instead convert the documentation into a tabular list of fields. Proposal attached, which also fixes a couple of outright errors. One thing that this doesn't fix is that the existing text appears to suggest that the "failures" column is something different from the sum of the serialization_failures and deadlock_failures columns, which it's obvious from the code is not so. If this isn't a code bug then I think we ought to just drop that column entirely, because it's redundant. (BTW, now that I've read this stuff I am quite horrified by how the non-aggregated log format has been mangled for error retries, and will be probably be submitting a proposal to change that. But that's a different issue.) regards, tom lane ------- =_aaaaaaaaaa0 Content-Type: text/x-diff; name="change-log-line-docs-layout.patch"; charset="us-ascii" Content-ID: <4183019.1649536675.2@sss.pgh.pa.us> Content-Description: change-log-line-docs-layout.patch Content-Transfer-Encoding: quoted-printable diff --git a/doc/src/sgml/ref/pgbench.sgml b/doc/src/sgml/ref/pgbench.sgml index 9ba26e5e86..d12cbaa8ab 100644 --- a/doc/src/sgml/ref/pgbench.sgml +++ b/doc/src/sgml/ref/pgbench.sgml @@ -2289,33 +2289,95 @@ END; = - The format of the log is: - - -client_id transaction_no time script_no= time_epoch time_us = schedule_lag = retries - - - where - client_id indicates which client session ra= n the transaction, - transaction_no counts how many transactions= have been - run by that session, - time is the total elapsed transaction time = in microseconds, - script_no identifies which script file was = used (useful when - multiple scripts were specified with or ), - and time_epoch/time_us are a - Unix-epoch time stamp and an offset - in microseconds (suitable for creating an ISO 8601 - time stamp with fractional seconds) showing when - the transaction completed. - The schedule_lag field is the difference be= tween the - transaction's scheduled start time, and the time it actually started, = in - microseconds. It is only present when the opti= on is used. + Each line in a log file describes one transaction. + It contains the following space-separated fields: + + + + client_id + + + identifies the client session that ran the transaction + + + + + + transaction_no + + + counts how many transactions have been run by that session + + + + + + time + + + transaction's elapsed time, in microseconds + + + + + + script_no + + + identifies the script file that was used for the transaction + (useful when multiple scripts are specified + with or ) + + + + + + time_epoch + + + transaction's completion time, as a Unix-epoch time stamp + + + + + + time_us + + + fractional-second part of transaction's completion time, in + microseconds + + + + + + schedule_lag + + + difference between the transaction's scheduled start time and the + time it actually started, in microseconds + (present only if is specified) + + + + + + retries + + + count of retries after serialization or deadlock errors during the + transaction + (present only if is not equal to one) + + + + + + + When both and = are used, the time for a skipped transaction will be = reported as skipped. - retries is the sum of all retries after the - serialization or deadlock errors during the current script execution. = It is - present only if the option is not equal t= o 1. If the transaction ends with a failure, its time will be reported as failed. If you use the option, the @@ -2398,66 +2460,171 @@ END; = With the option, a different - format is used for the log files: - - -interval_start num_transactions sum_latency sum_laten= cy_2 min_latency max= _latency -sum_lag sum_lag_2 <= replaceable>min_lag max_lag skipped -retried retries failures serialization_failures deadlock_failures - - - where - interval_start is the start of the interval= (as a Unix - epoch time stamp), - num_transactions is the number of transacti= ons - within the interval, - sum_latency is the sum of the transaction - latencies within the interval, - sum_latency_2 is the sum of squares of the - transaction latencies within the interval, - min_latency is the minimum latency within t= he interval, - and - max_latency is the maximum latency within t= he interval, - failures is the number of transactions that= ended - with a failed SQL command within the interval. - - - The next fields, - sum_lag, sum_lag_2, min_lag, - and max_lag, only meaningful if the --rate - option is used. Otherwise, they are all 0.0. - They provide statistics about the time each transaction had to wait fo= r the - previous one to finish, i.e., the difference between each transaction'= s - scheduled start time and the time it actually started. - The next field, skipped, - is only meaningful if the option is u= sed, too. Otherwise it is 0. - It counts the number of transactions skipped because they would have - started too late. - - - The retried - and retries fields are only meaningful if - the option is not equal to 1. Otherwise t= hey - are 0. They report the number of retried transactions and the sum of a= ll - retries after serialization or deadlock errors within the interval. E= ach - transaction is counted in the interval when it was committed. - - - failures is the sum of all failed transacti= ons. - If is specified, instead of the s= um of - all failed transactions you will get more detailed statistics for the - failed transactions grouped by the following types: - serialization_failures is the number of - transactions that got a serialization error and were not retried after= this, - deadlock_failures is the number of transact= ions - that got a deadlock error and were not retried after this. - If is not - specified, serialization_failures - and deadlock_failures are always 0. + format is used for the log files. Each log line describes one + aggregation interval. It contains the following space-separated + fields: + + + + interval_start + + + start time of the interval, as a Unix-epoch time stamp + + + + + + num_transactions + + + number of transactions within the interval + + + + + + sum_latency + + + sum of transaction latencies + + + + + + sum_latency_2 + + + sum of squares of transaction latencies + + + + + + min_latency + + + minimum transaction latency + + + + + + max_latency + + + maximum transaction latency + + + + + + sum_lag + + + sum of transaction start delays + (zero unless is specified) + + + + + + sum_lag_2 + + + sum of squares of transaction start delays + (zero unless is specified) + + + + + + min_lag + + + minimum transaction start delay + (zero unless is specified) + + + + + + max_lag + + + maximum transaction start delay + (zero unless is specified) + + + + + + skipped + + + number of transactions skipped because they would have started too= late + (zero unless + and are specified) + + + + + + retried + + + number of retried transactions + (zero unless is not equal to one) + + + + + + retries + + + number of retries after serialization or deadlock errors + (zero unless is not equal to one) + + + + + + failures + + + number of transactions that ended with a failed SQL command + + + + + + serialization_failures + + + number of transactions that got a serialization error and were not + retried afterwards + (zero unless is specified) + + + + + + deadlock_failures + + + number of transactions that got a deadlock error and were not + retried afterwards + (zero unless is specified) + + + + = - Here is some example output with following options: + Here is some example output generated with these options: pgbench --aggregate-interval=3D10 --time=3D20 --client=3D10 --= log --rate=3D1000 --latency-limit=3D10 --failures-detailed --max-tries=3D10 test @@ -2468,8 +2635,8 @@ END; = - Notice that while the plain (unaggregated) log file shows which script - was used for each transaction, the aggregated log does not. Therefore = if + Notice that while the plain (unaggregated) log format shows which scri= pt + was used for each transaction, the aggregated format does not. Therefo= re if you need per-script data, you need to aggregate the data on your own. = ------- =_aaaaaaaaaa0--