Re: [HACKERS] WIP aPatch: Pgbench Serialization and deadlock errors - Mailing list pgsql-hackers

Hello,

On 2022-Mar-27, Tatsuo Ishii wrote:

> After:
> interval_start num_transactions sum_latency sum_latency_2 min_latency max_latency
>   { failures | serialization_failures deadlock_failures } [ sum_lag sum_lag_2 min_lag max_lag [ skipped ] ] [ retried
retries]
 

You're showing an indentation, but looking at the HTML output there is
no such.  Is the HTML processor eating leading whitespace or something
like that?

I think that the explanatory paragraph is way too long now, particularly
since it explains --failures-detailed starting in the middle.  Also, the
example output doesn't include the failures-detailed mode.  I suggest
that this should be broken down even more; first to explain the output
without failures-detailed, including an example, and then the output
with failures-detailed, and an example of that.  Something like this,
perhaps:

Aggregated Logging
With the --aggregate-interval option, a different format is used for the log files (note that the actual log line is
notfolded).
 

  interval_start num_transactions sum_latency sum_latency_2 min_latency max_latency
  failures [ sum_lag sum_lag_2 min_lag max_lag [ skipped ] ] [ retried retries ]

where interval_start is the start of the interval (as a Unix epoch time stamp), num_transactions is the number of
transactionswithin the interval, sum_latency is the sum of the transaction latencies within the interval, sum_latency_2
isthe sum of squares of the transaction latencies within the interval, min_latency is the minimum latency within the
interval,and max_latency is the maximum latency within the interval, failures is the number of transactions that ended
witha failed SQL command within the interval.
 

The next fields, sum_lag, sum_lag_2, min_lag, and max_lag, are only present if the --rate option is used. They provide
statisticsabout the time each transaction had to wait for the previous one to finish, i.e., the difference between each
transaction'sscheduled start time and the time it actually started. The next field, skipped, is only present if the
--latency-limitoption is used, too. It counts the number of transactions skipped because they would have started too
late.The retried and retries fields are present only if the --max-tries option is not equal to 1. They report the
numberof retried transactions and the sum of all retries after serialization or deadlock errors within the interval.
Eachtransaction is counted in the interval when it was committed.
 

Notice that while the plain (unaggregated) log file shows which script was used for each transaction, the aggregated
logdoes not. Therefore if you need per-script data, you need to aggregate the data on your own.
 

Here is some example output:

1345828501 5601 1542744 483552416 61 2573 0
1345828503 7884 1979812 565806736 60 1479 0
1345828505 7208 1979422 567277552 59 1391 0
1345828507 7685 1980268 569784714 60 1398 0
1345828509 7073 1979779 573489941 236 1411 0

If you use option --failures-detailed, instead of the sum of all failed transactions you will get more detailed
statisticsfor the failed transactions:
 

  interval_start num_transactions sum_latency sum_latency_2 min_latency max_latency
  serialization_failures deadlock_failures [ sum_lag sum_lag_2 min_lag max_lag [ skipped ] ] [ retried retries ]

This is similar to the above, but here the single 'failures' figure is replaced by serialization_failures which is the
numberof transactions that got a serialization error and were not retried after this, deadlock_failures which is the
numberof transactions that got a deadlock error and were not retried after this. The other fields are as above. Here is
someexample output:
 

[example with detailed failures]

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
"If you have nothing to say, maybe you need just the right tool to help you
not say it."                   (New York Times, about Microsoft PowerPoint)