@@ -210,10 +210,10 @@ typedef struct
210210 * sent */
211211 int sleeping ; /* 1 indicates that the client is napping */
212212 bool throttling ; /* whether nap is for throttling */
213- int64 until ; /* napping until (usec) */
214213 Variable * variables ; /* array of variable definitions */
215214 int nvariables ;
216- instr_time txn_begin ; /* used for measuring transaction latencies */
215+ int64 txn_scheduled ; /* scheduled start time of transaction (usec) */
216+ instr_time txn_begin ; /* used for measuring schedule lag times */
217217 instr_time stmt_begin ; /* used for measuring statement latencies */
218218 int64 txn_latencies ; /* cumulated latencies */
219219 int64 txn_sqlats ; /* cumulated square latencies */
@@ -284,12 +284,17 @@ typedef struct
284284
285285 long start_time ; /* when does the interval start */
286286 int cnt ; /* number of transactions */
287- double min_duration ; /* min/max durations */
288- double max_duration ;
289- double sum ; /* sum(duration), sum(duration^2) - for
287+
288+ double min_latency ; /* min/max latencies */
289+ double max_latency ;
290+ double sum_latency ; /* sum(latency), sum(latency^2) - for
290291 * estimates */
291- double sum2 ;
292+ double sum2_latency ;
292293
294+ double min_lag ;
295+ double max_lag ;
296+ double sum_lag ; /* sum(lag) */
297+ double sum2_lag ; /* sum(lag*lag) */
293298} AggVals ;
294299
295300static Command * * sql_files [MAX_FILES ]; /* SQL script files */
@@ -968,12 +973,18 @@ agg_vals_init(AggVals *aggs, instr_time start)
968973{
969974 /* basic counters */
970975 aggs -> cnt = 0 ; /* number of transactions */
971- aggs -> sum = 0 ; /* SUM(duration ) */
972- aggs -> sum2 = 0 ; /* SUM(duration*duration ) */
976+ aggs -> sum_latency = 0 ; /* SUM(latency ) */
977+ aggs -> sum2_latency = 0 ; /* SUM(latency*latency ) */
973978
974979 /* min and max transaction duration */
975- aggs -> min_duration = 0 ;
976- aggs -> max_duration = 0 ;
980+ aggs -> min_latency = 0 ;
981+ aggs -> max_latency = 0 ;
982+
983+ /* schedule lag counters */
984+ aggs -> sum_lag = 0 ;
985+ aggs -> sum2_lag = 0 ;
986+ aggs -> min_lag = 0 ;
987+ aggs -> max_lag = 0 ;
977988
978989 /* start of the current interval */
979990 aggs -> start_time = INSTR_TIME_GET_DOUBLE (start );
@@ -1016,7 +1027,7 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10161027
10171028 thread -> throttle_trigger += wait ;
10181029
1019- st -> until = thread -> throttle_trigger ;
1030+ st -> txn_scheduled = thread -> throttle_trigger ;
10201031 st -> sleeping = 1 ;
10211032 st -> throttling = true;
10221033 st -> is_throttled = true;
@@ -1032,13 +1043,13 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10321043
10331044 INSTR_TIME_SET_CURRENT (now );
10341045 now_us = INSTR_TIME_GET_MICROSEC (now );
1035- if (st -> until <= now_us )
1046+ if (st -> txn_scheduled <= now_us )
10361047 {
10371048 st -> sleeping = 0 ; /* Done sleeping, go ahead with next command */
10381049 if (st -> throttling )
10391050 {
10401051 /* Measure lag of throttled transaction relative to target */
1041- int64 lag = now_us - st -> until ;
1052+ int64 lag = now_us - st -> txn_scheduled ;
10421053
10431054 thread -> throttle_lag += lag ;
10441055 if (lag > thread -> throttle_lag_max )
@@ -1052,6 +1063,11 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10521063
10531064 if (st -> listen )
10541065 { /* are we receiver? */
1066+ instr_time now ;
1067+ bool now_valid = false;
1068+
1069+ INSTR_TIME_SET_ZERO (now ); /* initialize to keep compiler quiet */
1070+
10551071 if (commands [st -> state ]-> type == SQL_COMMAND )
10561072 {
10571073 if (debug )
@@ -1071,10 +1087,13 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10711087 */
10721088 if (is_latencies )
10731089 {
1074- instr_time now ;
10751090 int cnum = commands [st -> state ]-> command_num ;
10761091
1077- INSTR_TIME_SET_CURRENT (now );
1092+ if (!now_valid )
1093+ {
1094+ INSTR_TIME_SET_CURRENT (now );
1095+ now_valid = true;
1096+ }
10781097 INSTR_TIME_ACCUM_DIFF (thread -> exec_elapsed [cnum ],
10791098 now , st -> stmt_begin );
10801099 thread -> exec_count [cnum ]++ ;
@@ -1083,12 +1102,16 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
10831102 /* transaction finished: record latency under progress or throttling */
10841103 if ((progress || throttle_delay ) && commands [st -> state + 1 ] == NULL )
10851104 {
1086- instr_time diff ;
10871105 int64 latency ;
10881106
1089- INSTR_TIME_SET_CURRENT (diff );
1090- INSTR_TIME_SUBTRACT (diff , st -> txn_begin );
1091- latency = INSTR_TIME_GET_MICROSEC (diff );
1107+ if (!now_valid )
1108+ {
1109+ INSTR_TIME_SET_CURRENT (now );
1110+ now_valid = true;
1111+ }
1112+
1113+ latency = INSTR_TIME_GET_MICROSEC (now ) - st -> txn_scheduled ;
1114+
10921115 st -> txn_latencies += latency ;
10931116
10941117 /*
@@ -1106,9 +1129,8 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11061129 */
11071130 if (logfile && commands [st -> state + 1 ] == NULL )
11081131 {
1109- instr_time now ;
1110- instr_time diff ;
1111- double usec ;
1132+ double lag ;
1133+ double latency ;
11121134
11131135 /*
11141136 * write the log entry if this row belongs to the random sample,
@@ -1117,10 +1139,13 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11171139 if (sample_rate == 0.0 ||
11181140 pg_erand48 (thread -> random_state ) <= sample_rate )
11191141 {
1120- INSTR_TIME_SET_CURRENT (now );
1121- diff = now ;
1122- INSTR_TIME_SUBTRACT (diff , st -> txn_begin );
1123- usec = (double ) INSTR_TIME_GET_MICROSEC (diff );
1142+ if (!now_valid )
1143+ {
1144+ INSTR_TIME_SET_CURRENT (now );
1145+ now_valid = true;
1146+ }
1147+ latency = (double ) (INSTR_TIME_GET_MICROSEC (now ) - st -> txn_scheduled );
1148+ lag = (double ) (INSTR_TIME_GET_MICROSEC (st -> txn_begin ) - st -> txn_scheduled );
11241149
11251150 /* should we aggregate the results or not? */
11261151 if (agg_interval > 0 )
@@ -1132,15 +1157,27 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11321157 if (agg -> start_time + agg_interval >= INSTR_TIME_GET_DOUBLE (now ))
11331158 {
11341159 agg -> cnt += 1 ;
1135- agg -> sum += usec ;
1136- agg -> sum2 += usec * usec ;
1160+ agg -> sum_latency += latency ;
1161+ agg -> sum2_latency += latency * latency ;
11371162
11381163 /* first in this aggregation interval */
1139- if ((agg -> cnt == 1 ) || (usec < agg -> min_duration ))
1140- agg -> min_duration = usec ;
1164+ if ((agg -> cnt == 1 ) || (latency < agg -> min_latency ))
1165+ agg -> min_latency = latency ;
1166+
1167+ if ((agg -> cnt == 1 ) || (latency > agg -> max_latency ))
1168+ agg -> max_latency = latency ;
1169+
1170+ /* and the same for schedule lag */
1171+ if (throttle_delay )
1172+ {
1173+ agg -> sum_lag += lag ;
1174+ agg -> sum2_lag += lag * lag ;
11411175
1142- if ((agg -> cnt == 1 ) || (usec > agg -> max_duration ))
1143- agg -> max_duration = usec ;
1176+ if ((agg -> cnt == 1 ) || (lag < agg -> min_lag ))
1177+ agg -> min_lag = lag ;
1178+ if ((agg -> cnt == 1 ) || (lag > agg -> max_lag ))
1179+ agg -> max_lag = lag ;
1180+ }
11441181 }
11451182 else
11461183 {
@@ -1156,34 +1193,49 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11561193 * ifdef in usage), so we don't need to handle
11571194 * this in a special way (see below).
11581195 */
1159- fprintf (logfile , "%ld %d %.0f %.0f %.0f %.0f\n " ,
1196+ fprintf (logfile , "%ld %d %.0f %.0f %.0f %.0f" ,
11601197 agg -> start_time ,
11611198 agg -> cnt ,
1162- agg -> sum ,
1163- agg -> sum2 ,
1164- agg -> min_duration ,
1165- agg -> max_duration );
1199+ agg -> sum_latency ,
1200+ agg -> sum2_latency ,
1201+ agg -> min_latency ,
1202+ agg -> max_latency );
1203+ if (throttle_delay )
1204+ fprintf (logfile , " %.0f %.0f %.0f %.0f" ,
1205+ agg -> sum_lag ,
1206+ agg -> sum2_lag ,
1207+ agg -> min_lag ,
1208+ agg -> max_lag );
1209+ fputc ('\n' , logfile );
11661210
11671211 /* move to the next inteval */
11681212 agg -> start_time = agg -> start_time + agg_interval ;
11691213
11701214 /* reset for "no transaction" intervals */
11711215 agg -> cnt = 0 ;
1172- agg -> min_duration = 0 ;
1173- agg -> max_duration = 0 ;
1174- agg -> sum = 0 ;
1175- agg -> sum2 = 0 ;
1216+ agg -> min_latency = 0 ;
1217+ agg -> max_latency = 0 ;
1218+ agg -> sum_latency = 0 ;
1219+ agg -> sum2_latency = 0 ;
1220+ agg -> min_lag = 0 ;
1221+ agg -> max_lag = 0 ;
1222+ agg -> sum_lag = 0 ;
1223+ agg -> sum2_lag = 0 ;
11761224 }
11771225
11781226 /*
11791227 * and now update the reset values (include the
11801228 * current)
11811229 */
11821230 agg -> cnt = 1 ;
1183- agg -> min_duration = usec ;
1184- agg -> max_duration = usec ;
1185- agg -> sum = usec ;
1186- agg -> sum2 = usec * usec ;
1231+ agg -> min_latency = latency ;
1232+ agg -> max_latency = latency ;
1233+ agg -> sum_latency = latency ;
1234+ agg -> sum2_latency = latency * latency ;
1235+ agg -> min_lag = lag ;
1236+ agg -> max_lag = lag ;
1237+ agg -> sum_lag = lag ;
1238+ agg -> sum2_lag = lag * lag ;
11871239 }
11881240 }
11891241 else
@@ -1195,18 +1247,21 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
11951247 * This is more than we really ought to know about
11961248 * instr_time
11971249 */
1198- fprintf (logfile , "%d %d %.0f %d %ld %ld\n " ,
1199- st -> id , st -> cnt , usec , st -> use_file ,
1250+ fprintf (logfile , "%d %d %.0f %d %ld %ld" ,
1251+ st -> id , st -> cnt , latency , st -> use_file ,
12001252 (long ) now .tv_sec , (long ) now .tv_usec );
12011253#else
12021254
12031255 /*
12041256 * On Windows, instr_time doesn't provide a timestamp
12051257 * anyway
12061258 */
1207- fprintf (logfile , "%d %d %.0f %d 0 0\n " ,
1259+ fprintf (logfile , "%d %d %.0f %d 0 0" ,
12081260 st -> id , st -> cnt , usec , st -> use_file );
12091261#endif
1262+ if (throttle_delay )
1263+ fprintf (logfile , " %.0f" , lag );
1264+ fputc ('\n' , logfile );
12101265 }
12111266 }
12121267 }
@@ -1295,8 +1350,17 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
12951350
12961351 /* Record transaction start time under logging, progress or throttling */
12971352 if ((logfile || progress || throttle_delay ) && st -> state == 0 )
1353+ {
12981354 INSTR_TIME_SET_CURRENT (st -> txn_begin );
12991355
1356+ /*
1357+ * When not throttling, this is also the transaction's scheduled start
1358+ * time.
1359+ */
1360+ if (!throttle_delay )
1361+ st -> txn_scheduled = INSTR_TIME_GET_MICROSEC (st -> txn_begin );
1362+ }
1363+
13001364 /* Record statement start time if per-command latencies are requested */
13011365 if (is_latencies )
13021366 INSTR_TIME_SET_CURRENT (st -> stmt_begin );
@@ -1620,7 +1684,7 @@ doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVa
16201684 usec *= 1000000 ;
16211685
16221686 INSTR_TIME_SET_CURRENT (now );
1623- st -> until = INSTR_TIME_GET_MICROSEC (now ) + usec ;
1687+ st -> txn_scheduled = INSTR_TIME_GET_MICROSEC (now ) + usec ;
16241688 st -> sleeping = 1 ;
16251689
16261690 st -> listen = 1 ;
@@ -3309,7 +3373,7 @@ threadRun(void *arg)
33093373 now_usec = INSTR_TIME_GET_MICROSEC (now );
33103374 }
33113375
3312- this_usec = st -> until - now_usec ;
3376+ this_usec = st -> txn_scheduled - now_usec ;
33133377 if (min_usec > this_usec )
33143378 min_usec = this_usec ;
33153379 }
0 commit comments