Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commit84f0ea3

Browse files
committed
Refactor pgbench log-writing code to a separate function.
The doCustom function was incredibly long, this makes it a little bit morereadable.
1 parent5a6c168 commit84f0ea3

File tree

1 file changed

+169
-171
lines changed

1 file changed

+169
-171
lines changed

‎contrib/pgbench/pgbench.c

Lines changed: 169 additions & 171 deletions
Original file line numberDiff line numberDiff line change
@@ -347,6 +347,9 @@ static char *select_only = {
347347
staticvoidsetalarm(intseconds);
348348
staticvoid*threadRun(void*arg);
349349

350+
staticvoiddoLog(TState*thread,CState*st,FILE*logfile,instr_time*now,
351+
AggVals*agg);
352+
350353
staticvoid
351354
usage(void)
352355
{
@@ -1016,6 +1019,16 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10161019
PGresult*res;
10171020
Command**commands;
10181021
booltrans_needs_throttle= false;
1022+
instr_timenow;
1023+
1024+
/*
1025+
* gettimeofday() isn't free, so we get the current timestamp lazily the
1026+
* first time it's needed, and reuse the same value throughout this
1027+
* function after that. This also ensures that e.g. the calculated latency
1028+
* reported in the log file and in the totals are the same. Zero means
1029+
* "not set yet".
1030+
*/
1031+
INSTR_TIME_SET_ZERO(now);
10191032

10201033
top:
10211034
commands=sql_files[st->use_file];
@@ -1049,10 +1062,10 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10491062

10501063
if (st->sleeping)
10511064
{/* are we sleeping? */
1052-
instr_timenow;
10531065
int64now_us;
10541066

1055-
INSTR_TIME_SET_CURRENT(now);
1067+
if (INSTR_TIME_IS_ZERO(now))
1068+
INSTR_TIME_SET_CURRENT(now);
10561069
now_us=INSTR_TIME_GET_MICROSEC(now);
10571070
if (st->txn_scheduled <=now_us)
10581071
{
@@ -1074,11 +1087,6 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10741087

10751088
if (st->listen)
10761089
{/* are we receiver? */
1077-
instr_timenow;
1078-
boolnow_valid= false;
1079-
1080-
INSTR_TIME_SET_ZERO(now);/* initialize to keep compiler quiet */
1081-
10821090
if (commands[st->state]->type==SQL_COMMAND)
10831091
{
10841092
if (debug)
@@ -1100,181 +1108,40 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11001108
{
11011109
intcnum=commands[st->state]->command_num;
11021110

1103-
if (!now_valid)
1104-
{
1111+
if (INSTR_TIME_IS_ZERO(now))
11051112
INSTR_TIME_SET_CURRENT(now);
1106-
now_valid= true;
1107-
}
11081113
INSTR_TIME_ACCUM_DIFF(thread->exec_elapsed[cnum],
11091114
now,st->stmt_begin);
11101115
thread->exec_count[cnum]++;
11111116
}
11121117

1113-
/* transaction finished:record latencyunder progress or throttling */
1114-
if ((progress||throttle_delay)&&commands[st->state+1]==NULL)
1118+
/* transaction finished:calculate latencyand log the transaction */
1119+
if (commands[st->state+1]==NULL)
11151120
{
1116-
int64latency;
1117-
1118-
if (!now_valid)
1121+
/* only calculate latency if an option is used that needs it */
1122+
if (progress||throttle_delay)
11191123
{
1120-
INSTR_TIME_SET_CURRENT(now);
1121-
now_valid= true;
1122-
}
1123-
1124-
latency=INSTR_TIME_GET_MICROSEC(now)-st->txn_scheduled;
1124+
int64latency;
11251125

1126-
st->txn_latencies+=latency;
1127-
1128-
/*
1129-
* XXX In a long benchmark run of high-latency transactions, this
1130-
* int64 addition eventually overflows. For example, 100 threads
1131-
* running 10s transactions will overflow it in 2.56 hours. With
1132-
* a more-typical OLTP workload of .1s transactions, overflow
1133-
* would take 256 hours.
1134-
*/
1135-
st->txn_sqlats+=latency*latency;
1136-
}
1137-
1138-
/*
1139-
* if transaction finished, record the time it took in the log
1140-
*/
1141-
if (logfile&&commands[st->state+1]==NULL)
1142-
{
1143-
doublelag;
1144-
doublelatency;
1145-
1146-
/*
1147-
* write the log entry if this row belongs to the random sample,
1148-
* or no sampling rate was given which means log everything.
1149-
*/
1150-
if (sample_rate==0.0||
1151-
pg_erand48(thread->random_state) <=sample_rate)
1152-
{
1153-
if (!now_valid)
1154-
{
1126+
if (INSTR_TIME_IS_ZERO(now))
11551127
INSTR_TIME_SET_CURRENT(now);
1156-
now_valid= true;
1157-
}
1158-
latency= (double) (INSTR_TIME_GET_MICROSEC(now)-st->txn_scheduled);
1159-
lag= (double) (INSTR_TIME_GET_MICROSEC(st->txn_begin)-st->txn_scheduled);
1160-
1161-
/* should we aggregate the results or not? */
1162-
if (agg_interval>0)
1163-
{
1164-
/*
1165-
* are we still in the same interval? if yes, accumulate
1166-
* the values (print them otherwise)
1167-
*/
1168-
if (agg->start_time+agg_interval >=INSTR_TIME_GET_DOUBLE(now))
1169-
{
1170-
agg->cnt+=1;
1171-
agg->sum_latency+=latency;
1172-
agg->sum2_latency+=latency*latency;
1173-
1174-
/* first in this aggregation interval */
1175-
if ((agg->cnt==1)|| (latency<agg->min_latency))
1176-
agg->min_latency=latency;
1177-
1178-
if ((agg->cnt==1)|| (latency>agg->max_latency))
1179-
agg->max_latency=latency;
1180-
1181-
/* and the same for schedule lag */
1182-
if (throttle_delay)
1183-
{
1184-
agg->sum_lag+=lag;
1185-
agg->sum2_lag+=lag*lag;
1186-
1187-
if ((agg->cnt==1)|| (lag<agg->min_lag))
1188-
agg->min_lag=lag;
1189-
if ((agg->cnt==1)|| (lag>agg->max_lag))
1190-
agg->max_lag=lag;
1191-
}
1192-
}
1193-
else
1194-
{
1195-
/*
1196-
* Loop until we reach the interval of the current
1197-
* transaction (and print all the empty intervals in
1198-
* between).
1199-
*/
1200-
while (agg->start_time+agg_interval<INSTR_TIME_GET_DOUBLE(now))
1201-
{
1202-
/*
1203-
* This is a non-Windows branch (thanks to the
1204-
* ifdef in usage), so we don't need to handle
1205-
* this in a special way (see below).
1206-
*/
1207-
fprintf(logfile,"%ld %d %.0f %.0f %.0f %.0f",
1208-
agg->start_time,
1209-
agg->cnt,
1210-
agg->sum_latency,
1211-
agg->sum2_latency,
1212-
agg->min_latency,
1213-
agg->max_latency);
1214-
if (throttle_delay)
1215-
fprintf(logfile," %.0f %.0f %.0f %.0f",
1216-
agg->sum_lag,
1217-
agg->sum2_lag,
1218-
agg->min_lag,
1219-
agg->max_lag);
1220-
fputc('\n',logfile);
1221-
1222-
/* move to the next inteval */
1223-
agg->start_time=agg->start_time+agg_interval;
1224-
1225-
/* reset for "no transaction" intervals */
1226-
agg->cnt=0;
1227-
agg->min_latency=0;
1228-
agg->max_latency=0;
1229-
agg->sum_latency=0;
1230-
agg->sum2_latency=0;
1231-
agg->min_lag=0;
1232-
agg->max_lag=0;
1233-
agg->sum_lag=0;
1234-
agg->sum2_lag=0;
1235-
}
1236-
1237-
/*
1238-
* and now update the reset values (include the
1239-
* current)
1240-
*/
1241-
agg->cnt=1;
1242-
agg->min_latency=latency;
1243-
agg->max_latency=latency;
1244-
agg->sum_latency=latency;
1245-
agg->sum2_latency=latency*latency;
1246-
agg->min_lag=lag;
1247-
agg->max_lag=lag;
1248-
agg->sum_lag=lag;
1249-
agg->sum2_lag=lag*lag;
1250-
}
1251-
}
1252-
else
1253-
{
1254-
/* no, print raw transactions */
1255-
#ifndefWIN32
1256-
1257-
/*
1258-
* This is more than we really ought to know about
1259-
* instr_time
1260-
*/
1261-
fprintf(logfile,"%d %d %.0f %d %ld %ld",
1262-
st->id,st->cnt,latency,st->use_file,
1263-
(long)now.tv_sec, (long)now.tv_usec);
1264-
#else
1265-
1266-
/*
1267-
* On Windows, instr_time doesn't provide a timestamp
1268-
* anyway
1269-
*/
1270-
fprintf(logfile,"%d %d %.0f %d 0 0",
1271-
st->id,st->cnt,latency,st->use_file);
1272-
#endif
1273-
if (throttle_delay)
1274-
fprintf(logfile," %.0f",lag);
1275-
fputc('\n',logfile);
1276-
}
1128+
latency=INSTR_TIME_GET_MICROSEC(now)-st->txn_scheduled;
1129+
1130+
st->txn_latencies+=latency;
1131+
1132+
/*
1133+
* XXX In a long benchmark run of high-latency transactions,
1134+
* this int64 addition eventually overflows. For example, 100
1135+
* threads running 10s transactions will overflow it in 2.56
1136+
* hours. With a more-typical OLTP workload of .1s
1137+
* transactions, overflow would take 256 hours.
1138+
*/
1139+
st->txn_sqlats+=latency*latency;
12771140
}
1141+
1142+
/* record the time it took in the log */
1143+
if (logfile)
1144+
doLog(thread,st,logfile,&now,agg);
12781145
}
12791146

12801147
if (commands[st->state]->type==SQL_COMMAND)
@@ -1734,6 +1601,137 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
17341601
return true;
17351602
}
17361603

1604+
/*
1605+
* print log entry after completing one transaction.
1606+
*/
1607+
staticvoid
1608+
doLog(TState*thread,CState*st,FILE*logfile,instr_time*now,AggVals*agg)
1609+
{
1610+
doublelag;
1611+
doublelatency;
1612+
1613+
/*
1614+
* Skip the log entry if sampling is enabled and this row doesn't belong
1615+
* to the random sample.
1616+
*/
1617+
if (sample_rate!=0.0&&
1618+
pg_erand48(thread->random_state)>sample_rate)
1619+
return;
1620+
1621+
if (INSTR_TIME_IS_ZERO(*now))
1622+
INSTR_TIME_SET_CURRENT(*now);
1623+
1624+
latency= (double) (INSTR_TIME_GET_MICROSEC(*now)-st->txn_scheduled);
1625+
lag= (double) (INSTR_TIME_GET_MICROSEC(st->txn_begin)-st->txn_scheduled);
1626+
1627+
/* should we aggregate the results or not? */
1628+
if (agg_interval>0)
1629+
{
1630+
/*
1631+
* Are we still in the same interval? If yes, accumulate the values
1632+
* (print them otherwise)
1633+
*/
1634+
if (agg->start_time+agg_interval >=INSTR_TIME_GET_DOUBLE(*now))
1635+
{
1636+
agg->cnt+=1;
1637+
agg->sum_latency+=latency;
1638+
agg->sum2_latency+=latency*latency;
1639+
1640+
/* first in this aggregation interval */
1641+
if ((agg->cnt==1)|| (latency<agg->min_latency))
1642+
agg->min_latency=latency;
1643+
1644+
if ((agg->cnt==1)|| (latency>agg->max_latency))
1645+
agg->max_latency=latency;
1646+
1647+
/* and the same for schedule lag */
1648+
if (throttle_delay)
1649+
{
1650+
agg->sum_lag+=lag;
1651+
agg->sum2_lag+=lag*lag;
1652+
1653+
if ((agg->cnt==1)|| (lag<agg->min_lag))
1654+
agg->min_lag=lag;
1655+
if ((agg->cnt==1)|| (lag>agg->max_lag))
1656+
agg->max_lag=lag;
1657+
}
1658+
}
1659+
else
1660+
{
1661+
/*
1662+
* Loop until we reach the interval of the current transaction
1663+
* (and print all the empty intervals in between).
1664+
*/
1665+
while (agg->start_time+agg_interval<INSTR_TIME_GET_DOUBLE(*now))
1666+
{
1667+
/*
1668+
* This is a non-Windows branch (thanks to the
1669+
* ifdef in usage), so we don't need to handle
1670+
* this in a special way (see below).
1671+
*/
1672+
fprintf(logfile,"%ld %d %.0f %.0f %.0f %.0f",
1673+
agg->start_time,
1674+
agg->cnt,
1675+
agg->sum_latency,
1676+
agg->sum2_latency,
1677+
agg->min_latency,
1678+
agg->max_latency);
1679+
if (throttle_delay)
1680+
fprintf(logfile," %.0f %.0f %.0f %.0f",
1681+
agg->sum_lag,
1682+
agg->sum2_lag,
1683+
agg->min_lag,
1684+
agg->max_lag);
1685+
fputc('\n',logfile);
1686+
1687+
/* move to the next inteval */
1688+
agg->start_time=agg->start_time+agg_interval;
1689+
1690+
/* reset for "no transaction" intervals */
1691+
agg->cnt=0;
1692+
agg->min_latency=0;
1693+
agg->max_latency=0;
1694+
agg->sum_latency=0;
1695+
agg->sum2_latency=0;
1696+
agg->min_lag=0;
1697+
agg->max_lag=0;
1698+
agg->sum_lag=0;
1699+
agg->sum2_lag=0;
1700+
}
1701+
1702+
/* reset the values to include only the current transaction. */
1703+
agg->cnt=1;
1704+
agg->min_latency=latency;
1705+
agg->max_latency=latency;
1706+
agg->sum_latency=latency;
1707+
agg->sum2_latency=latency*latency;
1708+
agg->min_lag=lag;
1709+
agg->max_lag=lag;
1710+
agg->sum_lag=lag;
1711+
agg->sum2_lag=lag*lag;
1712+
}
1713+
}
1714+
else
1715+
{
1716+
/* no, print raw transactions */
1717+
#ifndefWIN32
1718+
1719+
/* This is more than we really ought to know about instr_time */
1720+
fprintf(logfile,"%d %d %.0f %d %ld %ld",
1721+
st->id,st->cnt,latency,st->use_file,
1722+
(long)now->tv_sec, (long)now->tv_usec);
1723+
#else
1724+
1725+
/* On Windows, instr_time doesn't provide a timestamp anyway */
1726+
fprintf(logfile,"%d %d %.0f %d 0 0",
1727+
st->id,st->cnt,latency,st->use_file);
1728+
#endif
1729+
if (throttle_delay)
1730+
fprintf(logfile," %.0f",lag);
1731+
fputc('\n',logfile);
1732+
}
1733+
}
1734+
17371735
/* discard connections */
17381736
staticvoid
17391737
disconnect_all(CState*state,intlength)

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp