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