STXXL  1.4-dev
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Groups Pages
iostats.cpp
Go to the documentation of this file.
1 /***************************************************************************
2  * lib/io/iostats.cpp
3  *
4  * Part of the STXXL. See http://stxxl.sourceforge.net
5  *
6  * Copyright (C) 2002-2004 Roman Dementiev <[email protected]>
7  * Copyright (C) 2008-2010 Andreas Beckmann <[email protected]>
8  * Copyright (C) 2009, 2010 Johannes Singler <[email protected]>
9  *
10  * Distributed under the Boost Software License, Version 1.0.
11  * (See accompanying file LICENSE_1_0.txt or copy at
12  * http://www.boost.org/LICENSE_1_0.txt)
13  **************************************************************************/
14 
15 #include <stxxl/bits/io/iostats.h>
16 #include <stxxl/bits/common/log.h>
17 #include <stxxl/bits/verbose.h>
21 #include <stxxl/bits/namespace.h>
22 
23 #include <string>
24 #include <sstream>
25 #include <iomanip>
26 
28 
29 stats::stats()
30  : reads(0),
31  writes(0),
32  volume_read(0),
33  volume_written(0),
34  c_reads(0),
35  c_writes(0),
36  c_volume_read(0),
37  c_volume_written(0),
38  t_reads(0.0),
39  t_writes(0.0),
40  p_reads(0.0),
41  p_writes(0.0),
42  p_begin_read(0.0),
43  p_begin_write(0.0),
44  p_ios(0.0),
45  p_begin_io(0.0),
46  t_waits(0.0),
47  p_waits(0.0),
48  p_begin_wait(0.0),
49  t_wait_read(0.0),
50  p_wait_read(0.0),
51  p_begin_wait_read(0.0),
52  t_wait_write(0.0),
53  p_wait_write(0.0),
54  p_begin_wait_write(0.0),
55  acc_reads(0), acc_writes(0),
56  acc_ios(0),
57  acc_waits(0),
58  acc_wait_read(0), acc_wait_write(0),
59  last_reset(timestamp())
60 { }
61 
62 #ifndef STXXL_IO_STATS_RESET_FORBIDDEN
64 {
65  {
66  scoped_mutex_lock ReadLock(read_mutex);
67 
68  //assert(acc_reads == 0);
69  if (acc_reads)
70  STXXL_ERRMSG("Warning: " << acc_reads <<
71  " read(s) not yet finished");
72 
73  reads = 0;
74  volume_read = 0;
75  c_reads = 0;
76  c_volume_read = 0;
77  t_reads = 0;
78  p_reads = 0.0;
79  }
80  {
81  scoped_mutex_lock WriteLock(write_mutex);
82 
83  //assert(acc_writes == 0);
84  if (acc_writes)
85  STXXL_ERRMSG("Warning: " << acc_writes <<
86  " write(s) not yet finished");
87 
88  writes = 0;
89  volume_written = 0;
90  c_writes = 0;
91  c_volume_written = 0;
92  t_writes = 0.0;
93  p_writes = 0.0;
94  }
95  {
97 
98  //assert(acc_ios == 0);
99  if (acc_ios)
100  STXXL_ERRMSG("Warning: " << acc_ios <<
101  " io(s) not yet finished");
102 
103  p_ios = 0.0;
104  }
105  {
106  scoped_mutex_lock WaitLock(wait_mutex);
107 
108  //assert(acc_waits == 0);
109  if (acc_waits)
110  STXXL_ERRMSG("Warning: " << acc_waits <<
111  " wait(s) not yet finished");
112 
113  t_waits = 0.0;
114  p_waits = 0.0;
115  t_wait_read = 0.0;
116  p_wait_read = 0.0;
117  t_wait_write = 0.0;
118  p_wait_write = 0.0;
119  }
120 
121  last_reset = timestamp();
122 }
123 #endif
124 
125 #if STXXL_IO_STATS
126 void stats::write_started(unsigned_type size_, double now)
127 {
128  if (now == 0.0)
129  now = timestamp();
130  {
131  scoped_mutex_lock WriteLock(write_mutex);
132 
133  ++writes;
134  volume_written += size_;
135  double diff = now - p_begin_write;
136  t_writes += double(acc_writes) * diff;
137  p_begin_write = now;
138  p_writes += (acc_writes++) ? diff : 0.0;
139  }
140  {
141  scoped_mutex_lock IOLock(io_mutex);
142 
143  double diff = now - p_begin_io;
144  p_ios += (acc_ios++) ? diff : 0.0;
145  p_begin_io = now;
146  }
147 }
148 
150 {
151  {
152  scoped_mutex_lock WriteLock(write_mutex);
153 
154  --writes;
155  volume_written -= size_;
156  }
157  write_finished();
158 }
159 
161 {
162  double now = timestamp();
163  {
164  scoped_mutex_lock WriteLock(write_mutex);
165 
166  double diff = now - p_begin_write;
167  t_writes += double(acc_writes) * diff;
168  p_begin_write = now;
169  p_writes += (acc_writes--) ? diff : 0.0;
170  }
171  {
172  scoped_mutex_lock IOLock(io_mutex);
173 
174  double diff = now - p_begin_io;
175  p_ios += (acc_ios--) ? diff : 0.0;
176  p_begin_io = now;
177  }
178 }
179 
181 {
182  scoped_mutex_lock WriteLock(write_mutex);
183 
184  ++c_writes;
185  c_volume_written += size_;
186 }
187 
188 void stats::read_started(unsigned_type size_, double now)
189 {
190  if (now == 0.0)
191  now = timestamp();
192  {
193  scoped_mutex_lock ReadLock(read_mutex);
194 
195  ++reads;
196  volume_read += size_;
197  double diff = now - p_begin_read;
198  t_reads += double(acc_reads) * diff;
199  p_begin_read = now;
200  p_reads += (acc_reads++) ? diff : 0.0;
201  }
202  {
203  scoped_mutex_lock IOLock(io_mutex);
204 
205  double diff = now - p_begin_io;
206  p_ios += (acc_ios++) ? diff : 0.0;
207  p_begin_io = now;
208  }
209 }
210 
212 {
213  {
214  scoped_mutex_lock ReadLock(read_mutex);
215 
216  --reads;
217  volume_read -= size_;
218  }
219  read_finished();
220 }
221 
223 {
224  double now = timestamp();
225  {
226  scoped_mutex_lock ReadLock(read_mutex);
227 
228  double diff = now - p_begin_read;
229  t_reads += double(acc_reads) * diff;
230  p_begin_read = now;
231  p_reads += (acc_reads--) ? diff : 0.0;
232  }
233  {
234  scoped_mutex_lock IOLock(io_mutex);
235 
236  double diff = now - p_begin_io;
237  p_ios += (acc_ios--) ? diff : 0.0;
238  p_begin_io = now;
239  }
240 }
241 
243 {
244  scoped_mutex_lock ReadLock(read_mutex);
245 
246  ++c_reads;
247  c_volume_read += size_;
248 }
249 #endif
250 
251 #ifndef STXXL_DO_NOT_COUNT_WAIT_TIME
253 {
254  double now = timestamp();
255  {
256  scoped_mutex_lock WaitLock(wait_mutex);
257 
258  double diff = now - p_begin_wait;
259  t_waits += double(acc_waits) * diff;
260  p_begin_wait = now;
261  p_waits += (acc_waits++) ? diff : 0.0;
262 
263  if (wait_op == WAIT_OP_READ) {
264  diff = now - p_begin_wait_read;
265  t_wait_read += double(acc_wait_read) * diff;
266  p_begin_wait_read = now;
267  p_wait_read += (acc_wait_read++) ? diff : 0.0;
268  }
269  else /* if (wait_op == WAIT_OP_WRITE) */ {
270  // wait_any() is only used from write_pool and buffered_writer, so account WAIT_OP_ANY for WAIT_OP_WRITE, too
271  diff = now - p_begin_wait_write;
272  t_wait_write += double(acc_wait_write) * diff;
273  p_begin_wait_write = now;
274  p_wait_write += (acc_wait_write++) ? diff : 0.0;
275  }
276  }
277 }
278 
280 {
281  double now = timestamp();
282  {
283  scoped_mutex_lock WaitLock(wait_mutex);
284 
285  double diff = now - p_begin_wait;
286  t_waits += double(acc_waits) * diff;
287  p_begin_wait = now;
288  p_waits += (acc_waits--) ? diff : 0.0;
289 
290  if (wait_op == WAIT_OP_READ) {
291  double diff2 = now - p_begin_wait_read;
292  t_wait_read += double(acc_wait_read) * diff2;
293  p_begin_wait_read = now;
294  p_wait_read += (acc_wait_read--) ? diff2 : 0.0;
295  }
296  else /* if (wait_op == WAIT_OP_WRITE) */ {
297  double diff2 = now - p_begin_wait_write;
298  t_wait_write += double(acc_wait_write) * diff2;
299  p_begin_wait_write = now;
300  p_wait_write += (acc_wait_write--) ? diff2 : 0.0;
301  }
302 #ifdef STXXL_WAIT_LOG_ENABLED
303  std::ofstream* waitlog = stxxl::logger::get_instance()->waitlog_stream();
304  if (waitlog)
305  *waitlog << (now - last_reset) << "\t"
306  << ((wait_op == WAIT_OP_READ) ? diff : 0.0) << "\t"
307  << ((wait_op != WAIT_OP_READ) ? diff : 0.0) << "\t"
308  << t_wait_read << "\t" << t_wait_write << std::endl << std::flush;
309 #endif
310  }
311 }
312 #endif
313 
315 {
316 #ifndef STXXL_DO_NOT_COUNT_WAIT_TIME
317  {
318  scoped_mutex_lock WaitLock(wait_mutex);
319 
320  //assert(acc_waits == 0);
321  if (acc_waits)
322  STXXL_ERRMSG("Warning: " << acc_waits <<
323  " wait(s) not yet finished");
324 
325  t_waits = 0.0;
326  p_waits = 0.0;
327  }
328 #endif
329 }
330 
331 std::string format_with_SI_IEC_unit_multiplier(uint64 number, const char* unit, int multiplier)
332 {
333  // may not overflow, std::numeric_limits<uint64>::max() == 16 EB
334  static const char* endings[] = { "", "k", "M", "G", "T", "P", "E" };
335  static const char* binary_endings[] = { "", "Ki", "Mi", "Gi", "Ti", "Pi", "Ei" };
336  std::ostringstream out;
337  out << number << ' ';
338  int scale = 0;
339  double number_d = (double)number;
340  double multiplier_d = multiplier;
341  while (number_d >= multiplier_d)
342  {
343  number_d /= multiplier_d;
344  ++scale;
345  }
346  if (scale > 0)
347  out << '(' << std::fixed << std::setprecision(3) << number_d << ' '
348  << (multiplier == 1024 ? binary_endings[scale] : endings[scale])
349  << (unit ? unit : "") << ") ";
350  else if (unit && *unit)
351  out << unit << ' ';
352  return out.str();
353 }
354 
355 std::ostream& operator << (std::ostream& o, const stats_data& s)
356 {
357 #define hr add_IEC_binary_multiplier
358  o << "STXXL I/O statistics" << std::endl;
359 #if STXXL_IO_STATS
360  o << " total number of reads : " << hr(s.get_reads()) << std::endl;
361  o << " average block size (read) : "
362  << hr(s.get_reads() ? s.get_read_volume() / s.get_reads() : 0, "B") << std::endl;
363  o << " number of bytes read from disks : " << hr(s.get_read_volume(), "B") << std::endl;
364  o << " time spent in serving all read requests : " << s.get_read_time() << " s"
365  << " @ " << ((double)s.get_read_volume() / 1048576.0 / s.get_read_time()) << " MiB/s"
366  << std::endl;
367  o << " time spent in reading (parallel read time) : " << s.get_pread_time() << " s"
368  << " @ " << ((double)s.get_read_volume() / 1048576.0 / s.get_pread_time()) << " MiB/s"
369  << std::endl;
370  if (s.get_cached_reads()) {
371  o << " total number of cached reads : " << hr(s.get_cached_reads()) << std::endl;
372  o << " average block size (cached read) : " << hr(s.get_cached_read_volume() / s.get_cached_reads(), "B") << std::endl;
373  o << " number of bytes read from cache : " << hr(s.get_cached_read_volume(), "B") << std::endl;
374  }
375  if (s.get_cached_writes()) {
376  o << " total number of cached writes : " << hr(s.get_cached_writes()) << std::endl;
377  o << " average block size (cached write) : " << hr(s.get_cached_written_volume() / s.get_cached_writes(), "B") << std::endl;
378  o << " number of bytes written to cache : " << hr(s.get_cached_written_volume(), "B") << std::endl;
379  }
380  o << " total number of writes : " << hr(s.get_writes()) << std::endl;
381  o << " average block size (write) : "
382  << hr(s.get_writes() ? s.get_written_volume() / s.get_writes() : 0, "B") << std::endl;
383  o << " number of bytes written to disks : " << hr(s.get_written_volume(), "B") << std::endl;
384  o << " time spent in serving all write requests : " << s.get_write_time() << " s"
385  << " @ " << ((double)s.get_written_volume() / 1048576.0 / s.get_write_time()) << " MiB/s"
386  << std::endl;
387  o << " time spent in writing (parallel write time): " << s.get_pwrite_time() << " s"
388  << " @ " << ((double)s.get_written_volume() / 1048576.0 / s.get_pwrite_time()) << " MiB/s"
389  << std::endl;
390  o << " time spent in I/O (parallel I/O time) : " << s.get_pio_time() << " s"
391  << " @ " << ((double)(s.get_read_volume() + s.get_written_volume()) / 1048576.0 / s.get_pio_time()) << " MiB/s"
392  << std::endl;
393 #else
394  o << " n/a" << std::endl;
395 #endif
396 #ifndef STXXL_DO_NOT_COUNT_WAIT_TIME
397  o << " I/O wait time : " << s.get_io_wait_time() << " s" << std::endl;
398  if (s.get_wait_read_time() != 0.0)
399  o << " I/O wait4read time : " << s.get_wait_read_time() << " s" << std::endl;
400  if (s.get_wait_write_time() != 0.0)
401  o << " I/O wait4write time : " << s.get_wait_write_time() << " s" << std::endl;
402 #endif
403  o << " Time since the last reset : " << s.get_elapsed_time() << " s" << std::endl;
404  return o;
405 #undef hr
406 }
407 
409 // vim: et:ts=4:sw=4
int64 volume_written
Definition: iostats.h:47
int64 get_written_volume() const
Definition: iostats.h:551
void wait_finished(wait_op_type wait_op)
Definition: iostats.cpp:279
double get_pio_time() const
Definition: iostats.h:596
double p_begin_wait
Definition: iostats.h:56
int64 get_cached_read_volume() const
Definition: iostats.h:566
int64 volume_read
Definition: iostats.h:47
unsigned get_reads() const
Definition: iostats.h:536
double p_wait_read
Definition: iostats.h:57
int acc_reads
Definition: iostats.h:61
double t_wait_read
Definition: iostats.h:57
double last_reset
Definition: iostats.h:65
double p_begin_wait_read
Definition: iostats.h:58
unsigned long long int uint64
Definition: types.h:39
void read_finished()
int acc_writes
Definition: iostats.h:61
std::string format_with_SI_IEC_unit_multiplier(uint64 number, const char *unit="", int multiplier=1000)
Definition: iostats.cpp:331
double get_wait_read_time() const
Definition: iostats.h:611
mutex write_mutex
Definition: iostats.h:66
void _reset_io_wait_time()
Resets I/O wait time counter.
Definition: iostats.cpp:314
int acc_waits
Definition: iostats.h:63
double p_begin_read
Definition: iostats.h:52
double p_reads
Definition: iostats.h:51
double t_waits
Definition: iostats.h:55
unsigned get_cached_writes() const
Definition: iostats.h:561
double p_writes
Definition: iostats.h:51
void reset()
Resets I/O time counters (including I/O wait counter).
Definition: iostats.cpp:63
int acc_wait_read
Definition: iostats.h:64
double get_wait_write_time() const
Definition: iostats.h:616
double get_io_wait_time() const
Definition: iostats.h:606
unsigned reads
Definition: iostats.h:46
double p_begin_write
Definition: iostats.h:52
int acc_ios
Definition: iostats.h:62
double get_write_time() const
Definition: iostats.h:581
static instance_pointer get_instance()
Definition: singleton.h:38
double t_wait_write
Definition: iostats.h:59
int64 c_volume_read
Definition: iostats.h:49
Aquire a lock that&#39;s valid until the end of scope.
Definition: mutex.h:123
#define STXXL_BEGIN_NAMESPACE
Definition: namespace.h:16
void read_canceled(unsigned_type size_)
mutex wait_mutex
Definition: iostats.h:66
void write_finished()
unsigned c_writes
Definition: iostats.h:48
mutex read_mutex
Definition: iostats.h:66
double p_wait_write
Definition: iostats.h:59
double p_begin_wait_write
Definition: iostats.h:60
unsigned c_reads
Definition: iostats.h:48
double p_waits
Definition: iostats.h:55
unsigned get_writes() const
Definition: iostats.h:541
int acc_wait_write
Definition: iostats.h:64
int64 c_volume_written
Definition: iostats.h:49
double p_ios
Definition: iostats.h:53
unsigned get_cached_reads() const
Definition: iostats.h:556
#define STXXL_ERRMSG(x)
Definition: verbose.h:94
double get_read_time() const
Definition: iostats.h:576
double get_pwrite_time() const
Definition: iostats.h:591
choose_int_types< my_pointer_size >::unsigned_type unsigned_type
Definition: types.h:64
double timestamp()
Returns number of seconds since the epoch, high resolution.
Definition: timer.h:44
void read_started(unsigned_type size_, double now=0.0)
int64 get_cached_written_volume() const
Definition: iostats.h:571
double p_begin_io
Definition: iostats.h:54
void write_cached(unsigned_type size_)
int64 get_read_volume() const
Definition: iostats.h:546
void read_cached(unsigned_type size_)
double get_elapsed_time() const
Definition: iostats.h:601
void write_canceled(unsigned_type size_)
unsigned writes
Definition: iostats.h:46
double t_reads
Definition: iostats.h:50
std::ostream & operator<<(std::ostream &o, const matrix_operation_statistic_data &statsd)
double get_pread_time() const
Definition: iostats.h:586
#define STXXL_END_NAMESPACE
Definition: namespace.h:17
#define hr
double t_writes
Definition: iostats.h:50
void wait_started(wait_op_type wait_op)
Definition: iostats.cpp:252
mutex io_mutex
Definition: iostats.h:66
void write_started(unsigned_type size_, double now=0.0)