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 <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 *
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>
18 #include <stxxl/bits/common/mutex.h>
19 #include <stxxl/bits/common/timer.h>
20 #include <stxxl/bits/common/types.h>
21 #include <stxxl/bits/namespace.h>
22
23 #include <string>
24 #include <sstream>
25 #include <iomanip>
26
27 STXXL_BEGIN_NAMESPACE
28
stats()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
reset()63 void stats::reset()
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 {
96 scoped_mutex_lock IOLock(io_mutex);
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
write_started(unsigned_type size_,double now)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
write_canceled(unsigned_type size_)149 void stats::write_canceled(unsigned_type size_)
150 {
151 {
152 scoped_mutex_lock WriteLock(write_mutex);
153
154 --writes;
155 volume_written -= size_;
156 }
157 write_finished();
158 }
159
write_finished()160 void stats::write_finished()
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
write_cached(unsigned_type size_)180 void stats::write_cached(unsigned_type size_)
181 {
182 scoped_mutex_lock WriteLock(write_mutex);
183
184 ++c_writes;
185 c_volume_written += size_;
186 }
187
read_started(unsigned_type size_,double now)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
read_canceled(unsigned_type size_)211 void stats::read_canceled(unsigned_type size_)
212 {
213 {
214 scoped_mutex_lock ReadLock(read_mutex);
215
216 --reads;
217 volume_read -= size_;
218 }
219 read_finished();
220 }
221
read_finished()222 void stats::read_finished()
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
read_cached(unsigned_type size_)242 void stats::read_cached(unsigned_type size_)
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
wait_started(wait_op_type wait_op)252 void stats::wait_started(wait_op_type wait_op)
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 } else /* if (wait_op == WAIT_OP_WRITE) */ {
269 // wait_any() is only used from write_pool and buffered_writer, so account WAIT_OP_ANY for WAIT_OP_WRITE, too
270 diff = now - p_begin_wait_write;
271 t_wait_write += double(acc_wait_write) * diff;
272 p_begin_wait_write = now;
273 p_wait_write += (acc_wait_write++) ? diff : 0.0;
274 }
275 }
276 }
277
wait_finished(wait_op_type wait_op)278 void stats::wait_finished(wait_op_type wait_op)
279 {
280 double now = timestamp();
281 {
282 scoped_mutex_lock WaitLock(wait_mutex);
283
284 double diff = now - p_begin_wait;
285 t_waits += double(acc_waits) * diff;
286 p_begin_wait = now;
287 p_waits += (acc_waits--) ? diff : 0.0;
288
289 if (wait_op == WAIT_OP_READ) {
290 double diff = now - p_begin_wait_read;
291 t_wait_read += double(acc_wait_read) * diff;
292 p_begin_wait_read = now;
293 p_wait_read += (acc_wait_read--) ? diff : 0.0;
294 } else /* if (wait_op == WAIT_OP_WRITE) */ {
295 double diff = now - p_begin_wait_write;
296 t_wait_write += double(acc_wait_write) * diff;
297 p_begin_wait_write = now;
298 p_wait_write += (acc_wait_write--) ? diff : 0.0;
299 }
300 #ifdef STXXL_WAIT_LOG_ENABLED
301 std::ofstream* waitlog = stxxl::logger::get_instance()->waitlog_stream();
302 if (waitlog)
303 *waitlog << (now - last_reset) << "\t"
304 << ((wait_op == WAIT_OP_READ) ? diff : 0.0) << "\t"
305 << ((wait_op != WAIT_OP_READ) ? diff : 0.0) << "\t"
306 << t_wait_read << "\t" << t_wait_write << std::endl << std::flush;
307 #endif
308 }
309 }
310 #endif
311
_reset_io_wait_time()312 void stats::_reset_io_wait_time()
313 {
314 #ifndef STXXL_DO_NOT_COUNT_WAIT_TIME
315 {
316 scoped_mutex_lock WaitLock(wait_mutex);
317
318 //assert(acc_waits == 0);
319 if (acc_waits)
320 STXXL_ERRMSG("Warning: " << acc_waits <<
321 " wait(s) not yet finished");
322
323 t_waits = 0.0;
324 p_waits = 0.0;
325 }
326 #endif
327 }
328
format_with_SI_IEC_unit_multiplier(uint64 number,const char * unit,int multiplier)329 std::string format_with_SI_IEC_unit_multiplier(uint64 number, const char* unit, int multiplier)
330 {
331 // may not overflow, std::numeric_limits<uint64>::max() == 16 EB
332 static const char* endings[] = { "", "k", "M", "G", "T", "P", "E" };
333 static const char* binary_endings[] = { "", "Ki", "Mi", "Gi", "Ti", "Pi", "Ei" };
334 std::ostringstream out;
335 out << number << ' ';
336 int scale = 0;
337 double number_d = (double)number;
338 double multiplier_d = multiplier;
339 while (number_d >= multiplier_d)
340 {
341 number_d /= multiplier_d;
342 ++scale;
343 }
344 if (scale > 0)
345 out << '(' << std::fixed << std::setprecision(3) << number_d << ' '
346 << (multiplier == 1024 ? binary_endings[scale] : endings[scale])
347 << (unit ? unit : "") << ") ";
348 else if (unit && *unit)
349 out << unit << ' ';
350 return out.str();
351 }
352
operator <<(std::ostream & o,const stats_data & s)353 std::ostream& operator << (std::ostream& o, const stats_data& s)
354 {
355 #define hr add_IEC_binary_multiplier
356 o << "STXXL I/O statistics" << std::endl;
357 #if STXXL_IO_STATS
358 o << " total number of reads : " << hr(s.get_reads()) << std::endl;
359 o << " average block size (read) : "
360 << hr(s.get_reads() ? s.get_read_volume() / s.get_reads() : 0, "B") << std::endl;
361 o << " number of bytes read from disks : " << hr(s.get_read_volume(), "B") << std::endl;
362 o << " time spent in serving all read requests : " << s.get_read_time() << " s"
363 << " @ " << ((double)s.get_read_volume() / 1048576.0 / s.get_read_time()) << " MiB/s"
364 << std::endl;
365 o << " time spent in reading (parallel read time) : " << s.get_pread_time() << " s"
366 << " @ " << ((double)s.get_read_volume() / 1048576.0 / s.get_pread_time()) << " MiB/s"
367 << std::endl;
368 if (s.get_cached_reads()) {
369 o << " total number of cached reads : " << hr(s.get_cached_reads()) << std::endl;
370 o << " average block size (cached read) : " << hr(s.get_cached_read_volume() / s.get_cached_reads(), "B") << std::endl;
371 o << " number of bytes read from cache : " << hr(s.get_cached_read_volume(), "B") << std::endl;
372 }
373 if (s.get_cached_writes()) {
374 o << " total number of cached writes : " << hr(s.get_cached_writes()) << std::endl;
375 o << " average block size (cached write) : " << hr(s.get_cached_written_volume() / s.get_cached_writes(), "B") << std::endl;
376 o << " number of bytes written to cache : " << hr(s.get_cached_written_volume(), "B") << std::endl;
377 }
378 o << " total number of writes : " << hr(s.get_writes()) << std::endl;
379 o << " average block size (write) : "
380 << hr(s.get_writes() ? s.get_written_volume() / s.get_writes() : 0, "B") << std::endl;
381 o << " number of bytes written to disks : " << hr(s.get_written_volume(), "B") << std::endl;
382 o << " time spent in serving all write requests : " << s.get_write_time() << " s"
383 << " @ " << ((double)s.get_written_volume() / 1048576.0 / s.get_write_time()) << " MiB/s"
384 << std::endl;
385 o << " time spent in writing (parallel write time): " << s.get_pwrite_time() << " s"
386 << " @ " << ((double)s.get_written_volume() / 1048576.0 / s.get_pwrite_time()) << " MiB/s"
387 << std::endl;
388 o << " time spent in I/O (parallel I/O time) : " << s.get_pio_time() << " s"
389 << " @ " << ((double)(s.get_read_volume() + s.get_written_volume()) / 1048576.0 / s.get_pio_time()) << " MiB/s"
390 << std::endl;
391 #else
392 o << " n/a" << std::endl;
393 #endif
394 #ifndef STXXL_DO_NOT_COUNT_WAIT_TIME
395 o << " I/O wait time : " << s.get_io_wait_time() << " s" << std::endl;
396 if (s.get_wait_read_time() != 0.0)
397 o << " I/O wait4read time : " << s.get_wait_read_time() << " s" << std::endl;
398 if (s.get_wait_write_time() != 0.0)
399 o << " I/O wait4write time : " << s.get_wait_write_time() << " s" << std::endl;
400 #endif
401 o << " Time since the last reset : " << s.get_elapsed_time() << " s" << std::endl;
402 return o;
403 #undef hr
404 }
405
406 STXXL_END_NAMESPACE
407 // vim: et:ts=4:sw=4
408