1 /***************************************************************************
2 * foxxll/io/iostats.hpp
3 *
4 * Part of FOXXLL. See http://foxxll.org
5 *
6 * Copyright (C) 2002-2004 Roman Dementiev <dementiev@mpi-sb.mpg.de>
7 * Copyright (C) 2008-2010 Andreas Beckmann <beckmann@cs.uni-frankfurt.de>
8 * Copyright (C) 2009, 2010 Johannes Singler <singler@kit.edu>
9 * Copyright (C) 2016 Alex Schickedanz <alex@ae.cs.uni-frankfurt.de>
10 * Copyright (C) 2017 Manuel Penschuck <manuel@ae.cs.uni-frankfurt.de>
11 *
12 * Distributed under the Boost Software License, Version 1.0.
13 * (See accompanying file LICENSE_1_0.txt or copy at
14 * http://www.boost.org/LICENSE_1_0.txt)
15 **************************************************************************/
16
17 #ifndef FOXXLL_IO_IOSTATS_HEADER
18 #define FOXXLL_IO_IOSTATS_HEADER
19
20 #include <algorithm>
21 #include <iostream>
22 #include <limits>
23 #include <list>
24 #include <mutex>
25 #include <string>
26 #include <utility>
27 #include <vector>
28
29 #include <tlx/logger/core.hpp>
30 #include <tlx/string.hpp>
31 #include <tlx/unused.hpp>
32
33 #include <foxxll/common/error_handling.hpp>
34 #include <foxxll/common/timer.hpp>
35 #include <foxxll/common/types.hpp>
36 #include <foxxll/common/utils.hpp>
37 #include <foxxll/singleton.hpp>
38
39 namespace foxxll {
40
41 //! \addtogroup foxxll_iolayer
42 //!
43 //! \{
44
45 class file_stats
46 {
47 //! associated device id
48 const unsigned device_id_;
49
50 //! number of operations: read/write
51 unsigned read_count_, write_count_;
52 //! number of bytes read/written
53 external_size_type read_bytes_, write_bytes_;
54 //! seconds spent in operations
55 double read_time_, write_time_;
56 //! start time of parallel operation
57 double p_begin_read_, p_begin_write_;
58
59 //! number of requests, participating in parallel operation
60 int acc_reads_, acc_writes_;
61
62 std::mutex read_mutex_, write_mutex_;
63
64 public:
65 //! construct zero initialized
66 explicit file_stats(unsigned int device_id);
67
68 class scoped_read_write_timer
69 {
70 using size_type = size_t;
71 file_stats& file_stats_;
72
73 bool is_write_;
74 bool running_ = false;
75
76 public:
scoped_read_write_timer(file_stats * file_stats,size_type size,bool is_write=false)77 explicit scoped_read_write_timer(
78 file_stats* file_stats, size_type size, bool is_write = false)
79 : file_stats_(*file_stats), is_write_(is_write)
80 {
81 start(size);
82 }
83
~scoped_read_write_timer()84 ~scoped_read_write_timer()
85 {
86 stop();
87 }
88
start(size_type size)89 void start(size_type size)
90 {
91 if (!running_) {
92 running_ = true;
93 if (is_write_)
94 file_stats_.write_started(size);
95 else
96 file_stats_.read_started(size);
97 }
98 }
99
stop()100 void stop()
101 {
102 if (running_) {
103 if (is_write_)
104 file_stats_.write_finished();
105 else
106 file_stats_.read_finished();
107 running_ = false;
108 }
109 }
110 };
111
112 class scoped_write_timer
113 {
114 using size_type = size_t;
115 file_stats& file_stats_;
116
117 bool running_ = false;
118
119 public:
scoped_write_timer(file_stats * file_stats,size_type size)120 explicit scoped_write_timer(file_stats* file_stats, size_type size)
121 : file_stats_(*file_stats)
122 {
123 start(size);
124 }
125
~scoped_write_timer()126 ~scoped_write_timer()
127 {
128 stop();
129 }
130
start(size_type size)131 void start(size_type size)
132 {
133 if (!running_) {
134 running_ = true;
135 file_stats_.write_started(size);
136 }
137 }
138
stop()139 void stop()
140 {
141 if (running_) {
142 file_stats_.write_finished();
143 running_ = false;
144 }
145 }
146 };
147
148 class scoped_read_timer
149 {
150 using size_type = size_t;
151 file_stats& file_stats_;
152
153 bool running_ = false;
154
155 public:
scoped_read_timer(file_stats * file_stats,size_type size)156 explicit scoped_read_timer(file_stats* file_stats, size_type size)
157 : file_stats_(*file_stats)
158 {
159 start(size);
160 }
161
~scoped_read_timer()162 ~scoped_read_timer()
163 {
164 stop();
165 }
166
start(size_type size)167 void start(size_type size)
168 {
169 if (!running_) {
170 running_ = true;
171 file_stats_.read_started(size);
172 }
173 }
174
stop()175 void stop()
176 {
177 if (running_) {
178 file_stats_.read_finished();
179 running_ = false;
180 }
181 }
182 };
183
184 public:
185 //! Returns the device id.
186 //! \return device id
get_device_id() const187 unsigned get_device_id() const
188 {
189 return device_id_;
190 }
191
192 //! Returns total number of read_count_.
193 //! \return total number of read_count_
get_read_count() const194 unsigned get_read_count() const
195 {
196 return read_count_;
197 }
198
199 //! Returns total number of write_count_.
200 //! \return total number of write_count_
get_write_count() const201 unsigned get_write_count() const
202 {
203 return write_count_;
204 }
205
206 //! Returns number of bytes read from disks.
207 //! \return number of bytes read
get_read_bytes() const208 external_size_type get_read_bytes() const
209 {
210 return read_bytes_;
211 }
212
213 //! Returns number of bytes written to the disks.
214 //! \return number of bytes written
get_write_bytes() const215 external_size_type get_write_bytes() const
216 {
217 return write_bytes_;
218 }
219
220 //! Time that would be spent in read syscalls if all parallel read_count_
221 //! were serialized.
222 //! \return seconds spent in reading
get_read_time() const223 double get_read_time() const
224 {
225 return read_time_;
226 }
227
228 //! Time that would be spent in write syscalls if all parallel write_count_
229 //! were serialized.
230 //! \return seconds spent in writing
get_write_time() const231 double get_write_time() const
232 {
233 return write_time_;
234 }
235
236 // for library use
237 void write_started(const size_t size_, double now = 0.0);
238 void write_canceled(const size_t size_);
239 void write_finished();
240 void write_op_finished(const size_t size_, double duration);
241
242 void read_started(const size_t size_, double now = 0.0);
243 void read_canceled(const size_t size_);
244 void read_finished();
245 void read_op_finished(const size_t size_, double duration);
246 };
247
248 class file_stats_data
249 {
250 //! device id
251 unsigned device_id_;
252 //! number of operations
253 unsigned read_count_, write_count_;
254 //! number of bytes read/written
255 external_size_type read_bytes_, write_bytes_;
256 //! seconds spent in operations
257 double read_time_, write_time_;
258
259 public:
file_stats_data()260 file_stats_data()
261 : device_id_(std::numeric_limits<unsigned>::max()),
262 read_count_(0), write_count_(0),
263 read_bytes_(0), write_bytes_(0),
264 read_time_(0.0), write_time_(0.0)
265 { }
266
267 //! construct file_stats_data by taking current values from file_stats
file_stats_data(const file_stats & fs)268 explicit file_stats_data(const file_stats& fs)
269 : device_id_(fs.get_device_id()),
270 read_count_(fs.get_read_count()),
271 write_count_(fs.get_write_count()),
272 read_bytes_(fs.get_read_bytes()),
273 write_bytes_(fs.get_write_bytes()),
274 read_time_(fs.get_read_time()),
275 write_time_(fs.get_write_time())
276 { }
277
278 file_stats_data operator + (const file_stats_data& a) const;
279 file_stats_data operator - (const file_stats_data& a) const;
280
get_device_id() const281 unsigned get_device_id() const
282 {
283 return device_id_;
284 }
285
get_read_count() const286 unsigned get_read_count() const
287 {
288 return read_count_;
289 }
290
get_write_count() const291 unsigned get_write_count() const
292 {
293 return write_count_;
294 }
295
get_read_bytes() const296 external_size_type get_read_bytes() const
297 {
298 return read_bytes_;
299 }
300
get_write_bytes() const301 external_size_type get_write_bytes() const
302 {
303 return write_bytes_;
304 }
305
get_read_time() const306 double get_read_time() const
307 {
308 return read_time_;
309 }
310
get_write_time() const311 double get_write_time() const
312 {
313 return write_time_;
314 }
315 };
316
317 //! Collects various I/O statistics.
318 //! \remarks is a singleton
319 class stats : public singleton<stats>
320 {
321 friend class singleton<stats>;
322 friend class file_stats;
323
324 const double creation_time_;
325
326 //! need std::list here, because the io::file objects keep a pointer to the
327 //! enclosed file_stats objects and this list may grow.
328 std::list<file_stats> file_stats_list_;
329
330 mutable std::mutex list_mutex_;
331
332 // *** parallel times have to be counted globally ***
333
334 //! seconds spent in parallel operations
335 double p_reads_, p_writes_;
336 //! start time of parallel operation
337 double p_begin_read_, p_begin_write_;
338 // seconds spent in all parallel I/O operations (read and write)
339 double p_ios_;
340 double p_begin_io_;
341
342 // number of requests, participating in parallel operation
343 int acc_reads_, acc_writes_;
344 int acc_ios_;
345
346 // *** waits are measured globally ***
347
348 // seconds spent waiting for completion of I/O operations
349 double t_waits_, p_waits_;
350 double p_begin_wait_;
351 double t_wait_read_, p_wait_read_;
352 double p_begin_wait_read_;
353 double t_wait_write_, p_wait_write_;
354 double p_begin_wait_write_;
355 int acc_waits_;
356 int acc_wait_read_, acc_wait_write_;
357
358 std::mutex wait_mutex_, read_mutex_, write_mutex_, io_mutex_;
359
360 //! private construction from singleton
361 stats();
362
363 public:
364 enum wait_op_type {
365 WAIT_OP_ANY,
366 WAIT_OP_READ,
367 WAIT_OP_WRITE
368 };
369
370 class scoped_wait_timer
371 {
372 #ifndef FOXXLL_DO_NOT_COUNT_WAIT_TIME
373 bool running_ = false;
374 wait_op_type wait_op_;
375 #endif
376
377 public:
scoped_wait_timer(wait_op_type wait_op,bool measure_time=true)378 explicit scoped_wait_timer(wait_op_type wait_op, bool measure_time = true)
379 #ifndef FOXXLL_DO_NOT_COUNT_WAIT_TIME
380 : wait_op_(wait_op)
381 #endif
382 {
383 if (measure_time)
384 start();
385 }
386
~scoped_wait_timer()387 ~scoped_wait_timer()
388 {
389 stop();
390 }
391
start()392 void start()
393 {
394 #ifndef FOXXLL_DO_NOT_COUNT_WAIT_TIME
395 if (!running_) {
396 running_ = true;
397 stats::get_instance()->wait_started(wait_op_);
398 }
399 #endif
400 }
401
stop()402 void stop()
403 {
404 #ifndef FOXXLL_DO_NOT_COUNT_WAIT_TIME
405 if (running_) {
406 stats::get_instance()->wait_finished(wait_op_);
407 running_ = false;
408 }
409 #endif
410 }
411 };
412
413 public:
414 //! return list of file's stats data (deeply copied from each file_stats)
415 std::vector<file_stats_data> deepcopy_file_stats_data_list() const;
416
get_creation_time() const417 double get_creation_time() const
418 {
419 return creation_time_;
420 }
421
422 //! create new instance of a file_stats for an io::file to collect
423 //! statistics. (for internal library use.)
424 file_stats * create_file_stats(unsigned device_id);
425
426 //! I/O wait time counter.
427 //! \return number of seconds spent in I/O waiting functions \link
428 //! request::wait request::wait \endlink, \c wait_any and \c wait_all
get_io_wait_time() const429 double get_io_wait_time() const
430 {
431 return t_waits_;
432 }
433
get_wait_read_time() const434 double get_wait_read_time() const
435 {
436 return t_wait_read_;
437 }
438
get_wait_write_time() const439 double get_wait_write_time() const
440 {
441 return t_wait_write_;
442 }
443
444 //! Period of time when at least one I/O thread was executing a read.
445 //! \return seconds spent in reading
get_pread_time() const446 double get_pread_time() const
447 {
448 return p_reads_;
449 }
450
451 //! Period of time when at least one I/O thread was executing a write.
452 //! \return seconds spent in writing
get_pwrite_time() const453 double get_pwrite_time() const
454 {
455 return p_writes_;
456 }
457
458 //! Period of time when at least one I/O thread was executing a read or a write.
459 //! \return seconds spent in I/O
get_pio_time() const460 double get_pio_time() const
461 {
462 return p_ios_;
463 }
464
465 friend std::ostream& operator << (std::ostream& o, const stats& s);
466
467 // for library use
468
469 private:
470 // only called from file_stats
471 void p_write_started(double now);
472 void p_write_finished(double now);
473 void p_read_started(double now);
474 void p_read_finished(double now);
475
476 public:
477 void wait_started(wait_op_type wait_op_);
478 void wait_finished(wait_op_type wait_op_);
479 };
480
481 #ifdef FOXXLL_DO_NOT_COUNT_WAIT_TIME
wait_started(wait_op_type)482 inline void stats::wait_started(wait_op_type) { }
wait_finished(wait_op_type)483 inline void stats::wait_finished(wait_op_type) { }
484 #endif
485
486 class stats_data
487 {
488 //! seconds spent in parallel io
489 double p_reads_, p_writes_, p_ios_;
490
491 //! seconds spent waiting for completion of I/O operations
492 double t_wait;
493 double t_wait_read_, t_wait_write_;
494
495 double elapsed_;
496
497 //! list of individual file statistics.
498 std::vector<file_stats_data> file_stats_data_list_;
499
500 //! aggregator
501 template <typename T, typename Functor>
502 T fetch_sum(const Functor& get_value) const;
503
504 public:
505 template <typename T>
506 struct summary
507 {
508 T total, min, max;
509 double average, median;
510 std::vector<std::pair<T, unsigned> > values_per_device;
511
512 template <typename Functor>
513 summary(const std::vector<file_stats_data>& fs,
514 const Functor& get_value);
515 };
516
517 public:
stats_data()518 stats_data()
519 : p_reads_(0.0), p_writes_(0.0),
520 p_ios_(0.0),
521 t_wait(0.0),
522 t_wait_read_(0.0), t_wait_write_(0.0),
523 elapsed_(0.0)
524 { }
525
stats_data(const stats & s)526 stats_data(const stats& s) // implicit conversion -- NOLINT
527 : p_reads_(s.get_pread_time()),
528 p_writes_(s.get_pwrite_time()),
529 p_ios_(s.get_pio_time()),
530 t_wait(s.get_io_wait_time()),
531 t_wait_read_(s.get_wait_read_time()),
532 t_wait_write_(s.get_wait_write_time()),
533 elapsed_(timestamp() - s.get_creation_time()),
534 file_stats_data_list_(s.deepcopy_file_stats_data_list())
535 { }
536
537 stats_data operator + (const stats_data& a) const;
538 stats_data operator - (const stats_data& a) const;
539
540 //! Returns the number of file_stats_data objects
541 size_t num_files() const;
542
543 //! Returns the sum of all read_count_.
544 //! \return the sum of all read_count_
545 unsigned get_read_count() const;
546
547 //! Retruns sum, min, max, avarage and median of all read_count_.
548 //! \return a summary of the read measurements
549 stats_data::summary<unsigned> get_read_count_summary() const;
550
551 //! Returns the sum of all write_count_.
552 //! \return the sum of all write_count_
553 unsigned get_write_count() const;
554
555 //! Returns sum, min, max, avarage and median of all write_count_.
556 //! \returns a summary of the write measurements
557 stats_data::summary<unsigned> get_write_count_summary() const;
558
559 //! Returns number of bytes read from disks in total.
560 //! \return number of bytes read
561 external_size_type get_read_bytes() const;
562
563 //! Returns sum, min, max, avarage and median of all read bytes.
564 //! \returns a summary of the write measurements
565 stats_data::summary<external_size_type> get_read_bytes_summary() const;
566
567 //! Returns number of bytes written to the disks in total.
568 //! \return number of bytes written
569 external_size_type get_write_bytes() const;
570
571 //! Returns sum, min, max, avarage and median of all written bytes.
572 //! \return a summary of the written bytes
573 stats_data::summary<external_size_type> get_write_bytes_summary() const;
574
575 //! Time that would be spent in read syscalls if all parallel read_count_
576 //! were serialized.
577 //! \return seconds spent in reading
578 double get_read_time() const;
579
580 //! Returns sum, min, max, avarage and median of all read times
581 //! \return a summary of the read times
582 stats_data::summary<double> get_read_time_summary() const;
583
584 //! Time that would be spent in write syscalls if all parallel write_count_
585 //! were serialized.
586 //! \return the sum of the write times of all files
587 double get_write_time() const;
588
589 //! Returns sum, min, max, avarage and median of all write times
590 //! \return a summary of the write times
591 stats_data::summary<double> get_write_time_summary() const;
592
593 //! Period of time when at least one I/O thread was executing a read.
594 //! \return seconds spent in reading
595 double get_pread_time() const;
596
597 //! Period of time when at least one I/O thread was executing a write.
598 //! \return seconds spent in writing
599 double get_pwrite_time() const;
600
601 //! Period of time when at least one I/O thread was executing a read or a write.
602 //! \return seconds spent in I/O
603 double get_pio_time() const;
604
605 stats_data::summary<double> get_read_speed_summary() const;
606
607 stats_data::summary<double> get_pread_speed_summary() const;
608
609 stats_data::summary<double> get_write_speed_summary() const;
610
611 stats_data::summary<double> get_pwrite_speed_summary() const;
612
613 stats_data::summary<double> get_pio_speed_summary() const;
614
615 //! Retruns elapsed_ time
616 //! \remark If stats_data is not the difference between two other stats_data
617 //! objects, then this value is measures the time since the first file object
618 //! was initialized.
619 //! \return elapsed_ time
get_elapsed_time() const620 double get_elapsed_time() const
621 {
622 return elapsed_;
623 }
624
625 //! I/O wait time counter.
626 //! \return number of seconds spent in I/O waiting functions
627 double get_io_wait_time() const;
628
629 double get_wait_read_time() const;
630
631 double get_wait_write_time() const;
632
633 void to_ostream(std::ostream& o, const std::string line_prefix = "") const;
634
operator <<(std::ostream & o,const stats_data & s)635 friend std::ostream& operator << (std::ostream& o, const stats_data& s)
636 {
637 s.to_ostream(o);
638 return o;
639 }
640 };
641
642 static inline
add_IEC_binary_multiplier(const external_size_type number,const std::string & unit="")643 std::string add_IEC_binary_multiplier(
644 const external_size_type number, const std::string& unit = "")
645 {
646 return tlx::format_iec_units(number) + unit;
647 }
648
649 static inline
add_SI_multiplier(external_size_type number,const std::string & unit="")650 std::string add_SI_multiplier(
651 external_size_type number, const std::string& unit = "")
652 {
653 return tlx::format_si_units(number) + unit;
654 }
655
656 /*!
657 * Simple scoped iostats reporter which takes a message and reports the relative
658 * IO performance on destruction
659 */
660 class scoped_print_iostats
661 {
662 protected:
663 //! message
664 std::string message_;
665 std::string key_;
666
667 //! initial io-stats
668 foxxll::stats_data begin_;
669
670 //! bytes processed
671 uint64_t bytes_;
672
673 //! report on destruction
674 bool report_on_destruction_;
675
676 public:
677 /*!
678 * Start time and configure report-style
679 *
680 * \param message Description displayed on the first line of the report
681 * \param key Line prefix displayed at the beginning of every line but the first
682 * \param bytes Used to compute MB/s as an initial overview
683 */
scoped_print_iostats(const std::string & message,const std::string key,uint64_t bytes)684 scoped_print_iostats(const std::string& message, const std::string key, uint64_t bytes)
685 : message_(message),
686 key_(key),
687 begin_(*foxxll::stats::get_instance()),
688 bytes_(bytes),
689 report_on_destruction_(true)
690 {
691 TLX_LOG1 << "Starting " << message;
692 }
693
scoped_print_iostats(const std::string & message,uint64_t bytes=0)694 explicit scoped_print_iostats(const std::string& message, uint64_t bytes = 0)
695 : scoped_print_iostats(message, "", bytes)
696 { }
697
scoped_print_iostats(uint64_t bytes=0)698 explicit scoped_print_iostats(uint64_t bytes = 0)
699 : scoped_print_iostats("", bytes)
700 { }
701
702 //! stats at initialization
initial_stats() const703 const foxxll::stats_data & initial_stats() const
704 {
705 return begin_;
706 }
707
708 //! print out relative stats via LOG
709 void report() const;
710
711 //! Same as report() but disables reporting on destruction
final_report()712 void final_report()
713 {
714 report_on_destruction_ = false;
715 report();
716 }
717
718 //! on destruction: report stats
~scoped_print_iostats()719 ~scoped_print_iostats()
720 {
721 if (report_on_destruction_)
722 report();
723 }
724 };
725
726 //! \}
727
728 } // namespace foxxll
729
730 #endif // !FOXXLL_IO_IOSTATS_HEADER
731
732 /**************************************************************************/
733