Fix printf() being used instead of log_info()
[fio.git] / eta.c
CommitLineData
263e529f
JA
1/*
2 * Status and ETA code
3 */
4#include <unistd.h>
5#include <fcntl.h>
6#include <string.h>
7
8#include "fio.h"
263e529f 9
fca70358 10static char run_str[REAL_MAX_JOBS + 1];
263e529f
JA
11
12/*
13 * Sets the status of the 'td' in the printed status map.
14 */
15static void check_str_update(struct thread_data *td)
16{
17 char c = run_str[td->thread_number - 1];
18
19 switch (td->runstate) {
5ec10eaa
JA
20 case TD_REAPED:
21 c = '_';
22 break;
23 case TD_EXITED:
24 c = 'E';
25 break;
b29ee5b3
JA
26 case TD_RAMP:
27 c = '/';
28 break;
5ec10eaa
JA
29 case TD_RUNNING:
30 if (td_rw(td)) {
e3b3f81e
JA
31 if (td_random(td)) {
32 if (td->o.rwmix[DDIR_READ] == 100)
33 c = 'r';
34 else if (td->o.rwmix[DDIR_WRITE] == 100)
35 c = 'w';
36 else
37 c = 'm';
38 } else {
39 if (td->o.rwmix[DDIR_READ] == 100)
40 c = 'R';
41 else if (td->o.rwmix[DDIR_WRITE] == 100)
42 c = 'W';
43 else
44 c = 'M';
45 }
5ec10eaa
JA
46 } else if (td_read(td)) {
47 if (td_random(td))
48 c = 'r';
49 else
50 c = 'R';
51 } else {
52 if (td_random(td))
53 c = 'w';
54 else
55 c = 'W';
56 }
57 break;
b0f65863
JA
58 case TD_PRE_READING:
59 c = 'p';
60 break;
5ec10eaa
JA
61 case TD_VERIFYING:
62 c = 'V';
63 break;
64 case TD_FSYNCING:
65 c = 'F';
66 break;
67 case TD_CREATED:
68 c = 'C';
69 break;
70 case TD_INITIALIZED:
71 c = 'I';
72 break;
73 case TD_NOT_CREATED:
74 c = 'P';
75 break;
76 default:
77 log_err("state %d\n", td->runstate);
263e529f
JA
78 }
79
80 run_str[td->thread_number - 1] = c;
81}
82
83/*
84 * Convert seconds to a printable string.
85 */
9c02f6ef 86static void eta_to_str(char *str, unsigned long eta_sec)
263e529f
JA
87{
88 unsigned int d, h, m, s;
165faf16 89 int disp_hour = 0;
263e529f 90
263e529f
JA
91 s = eta_sec % 60;
92 eta_sec /= 60;
93 m = eta_sec % 60;
94 eta_sec /= 60;
95 h = eta_sec % 24;
96 eta_sec /= 24;
97 d = eta_sec;
98
165faf16
JA
99 if (d) {
100 disp_hour = 1;
1e97cce9 101 str += sprintf(str, "%02ud:", d);
263e529f 102 }
165faf16
JA
103
104 if (h || disp_hour)
1e97cce9 105 str += sprintf(str, "%02uh:", h);
263e529f 106
1e97cce9
JA
107 str += sprintf(str, "%02um:", m);
108 str += sprintf(str, "%02us", s);
263e529f
JA
109}
110
111/*
112 * Best effort calculation of the estimated pending runtime of a job.
113 */
b29ee5b3 114static int thread_eta(struct thread_data *td)
263e529f
JA
115{
116 unsigned long long bytes_total, bytes_done;
1e97cce9 117 unsigned long eta_sec = 0;
b29ee5b3
JA
118 unsigned long elapsed;
119
120 elapsed = (mtime_since_now(&td->epoch) + 999) / 1000;
263e529f
JA
121
122 bytes_total = td->total_io_size;
123
2e3bd4c2
JA
124 if (td->o.fill_device && td->o.size == -1ULL) {
125 if (!td->fill_device_size || td->fill_device_size == -1ULL)
126 return 0;
127
128 bytes_total = td->fill_device_size;
129 }
130
74939e38
JA
131 /*
132 * if writing, bytes_total will be twice the size. If mixing,
133 * assume a 50/50 split and thus bytes_total will be 50% larger.
134 */
0dd8377f 135 if (td->o.do_verify && td->o.verify && td_write(td)) {
74939e38
JA
136 if (td_rw(td))
137 bytes_total = bytes_total * 3 / 2;
138 else
139 bytes_total <<= 1;
140 }
141
2dc1bbeb
JA
142 if (td->o.zone_size && td->o.zone_skip)
143 bytes_total /= (td->o.zone_skip / td->o.zone_size);
263e529f
JA
144
145 if (td->runstate == TD_RUNNING || td->runstate == TD_VERIFYING) {
cf4464ca 146 double perc, perc_t;
263e529f
JA
147
148 bytes_done = td->io_bytes[DDIR_READ] + td->io_bytes[DDIR_WRITE];
149 perc = (double) bytes_done / (double) bytes_total;
150 if (perc > 1.0)
151 perc = 1.0;
152
cf4464ca
JA
153 if (td->o.time_based) {
154 perc_t = (double) elapsed / (double) td->o.timeout;
155 if (perc_t < perc)
156 perc = perc_t;
157 }
158
1e97cce9 159 eta_sec = (unsigned long) (elapsed * (1.0 / perc)) - elapsed;
263e529f 160
d3eeeabc
JA
161 if (td->o.timeout &&
162 eta_sec > (td->o.timeout + done_secs - elapsed))
163 eta_sec = td->o.timeout + done_secs - elapsed;
263e529f 164 } else if (td->runstate == TD_NOT_CREATED || td->runstate == TD_CREATED
b29ee5b3 165 || td->runstate == TD_INITIALIZED
b0f65863
JA
166 || td->runstate == TD_RAMP
167 || td->runstate == TD_PRE_READING) {
263e529f
JA
168 int t_eta = 0, r_eta = 0;
169
170 /*
171 * We can only guess - assume it'll run the full timeout
172 * if given, otherwise assume it'll run at the specified rate.
173 */
b29ee5b3 174 if (td->o.timeout) {
cda99fa0
SSP
175 t_eta = td->o.timeout + td->o.start_delay +
176 td->o.ramp_time;
b29ee5b3
JA
177
178 if (in_ramp_time(td)) {
179 unsigned long ramp_left;
180
cda99fa0 181 ramp_left = mtime_since_now(&td->epoch);
b29ee5b3
JA
182 ramp_left = (ramp_left + 999) / 1000;
183 if (ramp_left <= t_eta)
184 t_eta -= ramp_left;
185 }
186 }
581e7141 187 if (td->o.rate[0] || td->o.rate[1]) {
0b9d69ec
JA
188 r_eta = (bytes_total / 1024) /
189 (td->o.rate[0] + td->o.rate[1]);
d3eeeabc 190 r_eta += td->o.start_delay;
263e529f
JA
191 }
192
193 if (r_eta && t_eta)
194 eta_sec = min(r_eta, t_eta);
195 else if (r_eta)
196 eta_sec = r_eta;
197 else if (t_eta)
198 eta_sec = t_eta;
199 else
200 eta_sec = 0;
201 } else {
202 /*
203 * thread is already done or waiting for fsync
204 */
205 eta_sec = 0;
206 }
207
208 return eta_sec;
209}
210
46fda8d0
JA
211static void calc_rate(unsigned long mtime, unsigned long long *io_bytes,
212 unsigned long long *prev_io_bytes, unsigned int *rate)
213{
214 rate[0] = (io_bytes[0] - prev_io_bytes[0]) / mtime;
215 rate[1] = (io_bytes[1] - prev_io_bytes[1]) / mtime;
216 prev_io_bytes[0] = io_bytes[0];
217 prev_io_bytes[1] = io_bytes[1];
218}
5ec10eaa 219
adb02ba8
JA
220static void calc_iops(unsigned long mtime, unsigned long long *io_iops,
221 unsigned long long *prev_io_iops, unsigned int *iops)
222{
223 iops[0] = ((io_iops[0] - prev_io_iops[0]) * 1000) / mtime;
224 iops[1] = ((io_iops[1] - prev_io_iops[1]) * 1000) / mtime;
225 prev_io_iops[0] = io_iops[0];
226 prev_io_iops[1] = io_iops[1];
227}
228
263e529f
JA
229/*
230 * Print status of the jobs we know about. This includes rate estimates,
231 * ETA, thread state, etc.
232 */
af9c9fb3 233int calc_thread_status(struct jobs_eta *je, int force)
263e529f 234{
34572e28 235 struct thread_data *td;
b75a394f
JA
236 int i;
237 unsigned long rate_time, disp_time, bw_avg_time, *eta_secs;
238 unsigned long long io_bytes[2];
239 unsigned long long io_iops[2];
46fda8d0
JA
240 struct timeval now;
241
242 static unsigned long long rate_io_bytes[2];
243 static unsigned long long disp_io_bytes[2];
adb02ba8 244 static unsigned long long disp_io_iops[2];
46fda8d0 245 static struct timeval rate_prev_time, disp_prev_time;
d6978a32 246 int i2p = 0;
6043c579 247
af9c9fb3
JA
248 if (!force) {
249 if (temp_stall_ts || terse_output || eta_print == FIO_ETA_NEVER)
250 return 0;
e592a06b 251
af9c9fb3
JA
252 if (!isatty(STDOUT_FILENO) && (eta_print != FIO_ETA_ALWAYS))
253 return 0;
254 }
263e529f 255
46fda8d0
JA
256 if (!rate_io_bytes[0] && !rate_io_bytes[1])
257 fill_start_time(&rate_prev_time);
258 if (!disp_io_bytes[0] && !disp_io_bytes[1])
259 fill_start_time(&disp_prev_time);
6043c579 260
d3eeeabc
JA
261 eta_secs = malloc(thread_number * sizeof(unsigned long));
262 memset(eta_secs, 0, thread_number * sizeof(unsigned long));
263e529f 263
b75a394f
JA
264 je->elapsed_sec = (mtime_since_genesis() + 999) / 1000;
265
6043c579 266 io_bytes[0] = io_bytes[1] = 0;
adb02ba8 267 io_iops[0] = io_iops[1] = 0;
bb3884d8 268 bw_avg_time = ULONG_MAX;
34572e28 269 for_each_td(td, i) {
2dc1bbeb
JA
270 if (td->o.bw_avg_time < bw_avg_time)
271 bw_avg_time = td->o.bw_avg_time;
46fda8d0 272 if (td->runstate == TD_RUNNING || td->runstate == TD_VERIFYING
b0f65863
JA
273 || td->runstate == TD_FSYNCING
274 || td->runstate == TD_PRE_READING) {
b75a394f
JA
275 je->nr_running++;
276 je->t_rate += td->o.rate[0] + td->o.rate[1];
277 je->m_rate += td->o.ratemin[0] + td->o.ratemin[1];
278 je->t_iops += td->o.rate_iops[0] + td->o.rate_iops[1];
279 je->m_iops += td->o.rate_iops_min[0] +
0b9d69ec 280 td->o.rate_iops_min[1];
b75a394f 281 je->files_open += td->nr_open_files;
b29ee5b3 282 } else if (td->runstate == TD_RAMP) {
b75a394f
JA
283 je->nr_running++;
284 je->nr_ramp++;
263e529f 285 } else if (td->runstate < TD_RUNNING)
b75a394f 286 je->nr_pending++;
263e529f 287
b75a394f 288 if (je->elapsed_sec >= 3)
b29ee5b3 289 eta_secs[i] = thread_eta(td);
263e529f
JA
290 else
291 eta_secs[i] = INT_MAX;
292
293 check_str_update(td);
b29ee5b3
JA
294
295 if (td->runstate > TD_RAMP) {
296 io_bytes[0] += td->io_bytes[0];
297 io_bytes[1] += td->io_bytes[1];
adb02ba8
JA
298 io_iops[0] += td->io_blocks[0];
299 io_iops[1] += td->io_blocks[1];
b29ee5b3 300 }
263e529f
JA
301 }
302
303 if (exitall_on_terminate)
b75a394f 304 je->eta_sec = INT_MAX;
263e529f 305 else
b75a394f 306 je->eta_sec = 0;
263e529f 307
34572e28 308 for_each_td(td, i) {
d6978a32
JA
309 if (!i2p && is_power_of_2(td->o.kb_base))
310 i2p = 1;
9c5a3854 311 if (exitall_on_terminate) {
b75a394f
JA
312 if (eta_secs[i] < je->eta_sec)
313 je->eta_sec = eta_secs[i];
9c5a3854 314 } else {
b75a394f
JA
315 if (eta_secs[i] > je->eta_sec)
316 je->eta_sec = eta_secs[i];
9c5a3854 317 }
263e529f
JA
318 }
319
eecf272f
JA
320 free(eta_secs);
321
46fda8d0
JA
322 fio_gettime(&now, NULL);
323 rate_time = mtime_since(&rate_prev_time, &now);
324
b29ee5b3 325 if (write_bw_log && rate_time > bw_avg_time && !in_ramp_time(td)) {
b75a394f 326 calc_rate(rate_time, io_bytes, rate_io_bytes, je->rate);
46fda8d0 327 memcpy(&rate_prev_time, &now, sizeof(now));
b75a394f
JA
328 add_agg_sample(je->rate[DDIR_READ], DDIR_READ, 0);
329 add_agg_sample(je->rate[DDIR_WRITE], DDIR_WRITE, 0);
6043c579
JA
330 }
331
46fda8d0 332 disp_time = mtime_since(&disp_prev_time, &now);
a5b01f1b
JA
333
334 /*
335 * Allow a little slack, the target is to print it every 1000 msecs
336 */
af9c9fb3 337 if (!force && disp_time < 900)
b75a394f 338 return 0;
46fda8d0 339
b75a394f
JA
340 calc_rate(disp_time, io_bytes, disp_io_bytes, je->rate);
341 calc_iops(disp_time, io_iops, disp_io_iops, je->iops);
adb02ba8 342
46fda8d0
JA
343 memcpy(&disp_prev_time, &now, sizeof(now));
344
af9c9fb3 345 if (!force && !je->nr_running && !je->nr_pending)
b75a394f
JA
346 return 0;
347
1d1f45ae
JA
348 je->nr_threads = thread_number;
349 memcpy(je->run_str, run_str, thread_number * sizeof(char));
350
b75a394f
JA
351 return 1;
352}
353
cf451d1e 354void display_thread_status(struct jobs_eta *je)
b75a394f 355{
b75a394f
JA
356 static int linelen_last;
357 static int eta_good;
358 char output[512], *p = output;
359 char eta_str[128];
360 double perc = 0.0;
361 int i2p = 0;
362
cf451d1e
JA
363 if (je->eta_sec != INT_MAX && je->elapsed_sec) {
364 perc = (double) je->elapsed_sec / (double) (je->elapsed_sec + je->eta_sec);
365 eta_to_str(eta_str, je->eta_sec);
b75a394f
JA
366 }
367
cf451d1e
JA
368 p += sprintf(p, "Jobs: %d (f=%d)", je->nr_running, je->files_open);
369 if (je->m_rate || je->t_rate) {
581e7141
JA
370 char *tr, *mr;
371
cf451d1e
JA
372 mr = num2str(je->m_rate, 4, 0, i2p);
373 tr = num2str(je->t_rate, 4, 0, i2p);
37db14fe 374 p += sprintf(p, ", CR=%s/%s KB/s", tr, mr);
581e7141
JA
375 free(tr);
376 free(mr);
cf451d1e
JA
377 } else if (je->m_iops || je->t_iops)
378 p += sprintf(p, ", CR=%d/%d IOPS", je->t_iops, je->m_iops);
379 if (je->eta_sec != INT_MAX && je->nr_running) {
0721d11e 380 char perc_str[32];
adb02ba8 381 char *iops_str[2];
d1bd7213 382 char *rate_str[2];
adb02ba8 383 int l;
5ec10eaa 384
cf451d1e 385 if ((!je->eta_sec && !eta_good) || je->nr_ramp == je->nr_running)
cac58fd5
JA
386 strcpy(perc_str, "-.-% done");
387 else {
388 eta_good = 1;
389 perc *= 100.0;
0721d11e 390 sprintf(perc_str, "%3.1f%% done", perc);
cac58fd5 391 }
0721d11e 392
cf451d1e
JA
393 rate_str[0] = num2str(je->rate[0], 5, 10, i2p);
394 rate_str[1] = num2str(je->rate[1], 5, 10, i2p);
d1bd7213 395
cf451d1e
JA
396 iops_str[0] = num2str(je->iops[0], 4, 1, 0);
397 iops_str[1] = num2str(je->iops[1], 4, 1, 0);
adb02ba8 398
37db14fe 399 l = sprintf(p, ": [%s] [%s] [%s/%s /s] [%s/%s iops] [eta %s]",
1d1f45ae
JA
400 je->run_str, perc_str, rate_str[0],
401 rate_str[1], iops_str[0], iops_str[1], eta_str);
37db14fe 402 p += l;
adb02ba8 403 if (l >= 0 && l < linelen_last)
37db14fe 404 p += sprintf(p, "%*s", linelen_last - l, "");
adb02ba8 405 linelen_last = l;
d1bd7213
JA
406
407 free(rate_str[0]);
408 free(rate_str[1]);
adb02ba8
JA
409 free(iops_str[0]);
410 free(iops_str[1]);
263e529f 411 }
37db14fe
JA
412 p += sprintf(p, "\r");
413
cf451d1e
JA
414 printf("%s", output);
415 fflush(stdout);
263e529f
JA
416}
417
cf451d1e
JA
418void print_thread_status(void)
419{
1d1f45ae 420 struct jobs_eta *je;
b814fb26 421 size_t size;
1d1f45ae 422
b814fb26
JA
423 if (!thread_number)
424 return;
cf451d1e 425
b814fb26
JA
426 size = sizeof(*je) + thread_number * sizeof(char) + 1;
427 je = malloc(size);
428 memset(je, 0, size);
cf451d1e 429
af9c9fb3 430 if (calc_thread_status(je, 0))
1d1f45ae 431 display_thread_status(je);
cf451d1e 432
1d1f45ae 433 free(je);
cf451d1e 434}
b75a394f 435
2b13e716 436void print_status_init(int thr_number)
263e529f 437{
2b13e716 438 run_str[thr_number] = 'P';
263e529f 439}