Annotation of /branches/cuda/src/logging/log-analyze/log-analyze.cxx

Parent Directory | Revision Log

---

Revision 5597 - (view) (download) (as text)

1 :	jhr	5597	/*! \file log-analyze.cxx
2 :			*
3 :			* \author John Reppy
4 :			*
5 :			* A program for analyzing the scheduling behavior of a Diderot application from
6 :			* a log file.
7 :			*/
8 :
9 :			/*
10 :			* This code is part of the Diderot Project (http://diderot-language.cs.uchicago.edu)
11 :			*
12 :			* COPYRIGHT (c) 2016 The University of Chicago
13 :			* All rights reserved.
14 :			*/
15 :
16 :			#include "load-log.hxx"
17 :			#include "event-desc.hxx"
18 :			#include "log-desc.hxx"
19 :			#include "default-log-paths.hxx"
20 :			#include "quantize.hxx"
21 :			#include "svg.hxx"
22 :			#include <iostream>
23 :			#include <iomanip>
24 :			#include <cstring>
25 :
26 :			#define MICROSEC 1000
27 :			#define MILLISEC (1000 * MICROSEC)
28 :			#define TIMEQ (50 * MILLISEC) // 50ms buckets
29 :
30 :			/* TODO: make these variables that are settable from command-line */
31 :			#define logDescFile DEFAULT_LOG_EVENTS_PATH
32 :			#define logViewFile DEFAULT_LOG_VIEW_PATH
33 :
34 :			// worker states
35 :			enum {
36 :			Dead = 0, // before start and after exit
37 :			Waiting, // blocked on gate or barrier
38 :			Running, // executing strands
39 :			Other, // other running time
40 :			NStates
41 :			};
42 :
43 :			void genSVG (std::ostream &outS, class buckets const &Q);
44 :
45 :			// convert nanoseconds to seconds
46 :			inline double toSeconds (uint64_t ns)
47 :			{
48 :			return static_cast<double>(ns / 1000000000) + static_cast<double>(ns % 1000000000) * 10e-9;
49 :			}
50 :
51 :			struct worker_stats {
52 :			uint32_t _id; // worker ID (0 == controller)
53 :			uint32_t _state; // current state
54 :			uint64_t _start; // time of worker start
55 :			uint64_t _end; // time of worker exit
56 :			uint64_t _last; // time of last state change
57 :			uint64_t _time[NStates];
58 :			uint32_t _nBlocks;
59 :			uint32_t _nStarts;
60 :			uint32_t _nUpdates;
61 :			uint32_t _nStabilizes;
62 :			uint32_t _nDies;
63 :
64 :			worker_stats (uint32_t id)
65 :			: _id(id), _state(Dead), _last(0), _time{0, 0, 0, 0},
66 :			_nBlocks(0), _nStarts(0), _nUpdates(0), _nStabilizes(0), _nDies(0)
67 :			{ }
68 :
69 :			void set_state (uint32_t state, uint64_t ts);
70 :
71 :			double run_time () const { return toSeconds(this->_end - this->_start); }
72 :			double time_waiting () const { return toSeconds(this->_time[Waiting]); }
73 :			double time_running () const { return toSeconds(this->_time[Running]); }
74 :			double time_overhead () const { return toSeconds(this->_time[Other]); }
75 :			double pct_waiting () const
76 :			{
77 :			return (100.0 * this->time_waiting()) / this->run_time();
78 :			}
79 :			double pct_running () const
80 :			{
81 :			return (100.0 * this->time_running()) / this->run_time();
82 :			}
83 :			double pct_overhead () const
84 :			{
85 :			return (100.0 * this->time_overhead()) / this->run_time();
86 :			}
87 :
88 :			};
89 :
90 :			// per-time quantum information
91 :			struct info {
92 :			uint32_t totTime; // total time (in ns)
93 :			uint32_t time[NStates]; // time per state (in ns)
94 :			uint32_t nStarts; // number of StrandStartEvt events
95 :			uint32_t nUpdates;
96 :			uint32_t nStabilizes;
97 :			uint32_t nDies;
98 :
99 :			info() { bzero (this, sizeof(info)); }
100 :			~info () { }
101 :
102 :			void addTime (uint32_t state, uint64_t t)
103 :			{
104 :			time[state] += (uint32_t)t;
105 :			}
106 :
107 :			// return percent (between 0 and 1) of time spent in state sid.
108 :			const double pct (uint32_t sid) const
109 :			{
110 :			uint64_t t = this->time[sid];
111 :			if (t == 0) {
112 :			return 0.0;
113 :			}
114 :			double w = static_cast<double>(t);
115 :			w /= static_cast<double>(this->totTime);
116 :			return w;
117 :			}
118 :
119 :			};
120 :
121 :			class buckets : public intervals<info> {
122 :			public:
123 :
124 :			buckets (uint32_t nThreads, uint32_t nIntervals, uint64_t timeQ)
125 :			: intervals<info> (nThreads, nIntervals, timeQ),
126 :			_lastT(new uint64_t[nThreads]),
127 :			_state(new uint32_t[nThreads])
128 :			{
129 :			// initialize arrays
130 :			for (uint32_t i = 0; i < nThreads; i++) {
131 :			this->_lastT[i] = 0;
132 :			this->_state[i] = 0;
133 :			}
134 :			}
135 :
136 :			virtual ~buckets ()
137 :			{
138 :			delete[] _lastT;
139 :			delete[] _state;
140 :			}
141 :
142 :			uint64_t time (uint32_t tid, uint32_t bid) const
143 :			{
144 :			return this->_info(tid, bid).totTime;
145 :			}
146 :
147 :			// return percent (between 0 and 1) of time spent in state sid for
148 :			// worker tid and bucket bid.
149 :			const double pct (uint32_t tid, uint32_t bid, uint32_t sid) const
150 :			{
151 :			return this->_info(tid, bid).pct(sid);
152 :			}
153 :
154 :			void setState (uint32_t tid, uint32_t sid, uint64_t t)
155 :			{
156 :			this->_addTime (tid, this->_state[tid], this->_lastT[tid], t);
157 :			this->_state[tid] = sid;
158 :			this->_lastT[tid] = t;
159 :			}
160 :
161 :			void finish (uint64_t endT);
162 :
163 :			protected:
164 :			uint64_t *_lastT; // last event time per worker
165 :			uint32_t *_state; // current state per worker
166 :
167 :			void _addTime (uint32_t tid, uint32_t sid, uint64_t startT, uint64_t endT);
168 :
169 :			};
170 :
171 :			void buckets::_addTime (uint32_t tid, uint32_t sid, uint64_t startT, uint64_t endT)
172 :			{
173 :			if (endT <= startT) {
174 :			return;
175 :			}
176 :			if (this->_runT < endT) {
177 :			std::cerr << "addTime: end time " << endT << " is after run time " << this->_runT << "\n";
178 :			exit (1);
179 :			}
180 :			uint32_t startB = startT / this->_timeQ;
181 :			uint32_t endB = endT / this->_timeQ;
182 :			if (startB == endB) {
183 :			this->_info(tid, startB).addTime(sid, endT - startT);
184 :			}
185 :			else {
186 :			uint64_t t = (startB + 1) * this->_timeQ;
187 :			while (t < endT) {
188 :			this->_info(tid, startB).addTime(sid, t - startT);
189 :			startT = t;
190 :			t += this->_timeQ;
191 :			startB++;
192 :			}
193 :			this->_info(tid, endB).addTime(sid, endT - startT);
194 :			}
195 :			}
196 :
197 :			void buckets::finish (uint64_t endT)
198 :			{
199 :			// add total time per bucket
200 :			for (uint32_t i = 0; i < this->_nThreads; i++) {
201 :			this->_addTime (i, Dead, this->_lastT[i], endT);
202 :			for (uint32_t j = 0; j < this->_nIntervals; j++) {
203 :			uint64_t t = 0;
204 :			uint32_t idx = this->_index(i, j);
205 :			for (uint32_t k = 0; k < NStates; k++) {
206 :			t += this->_interval[idx].time[k];
207 :			}
208 :			this->_interval[idx].totTime = t;
209 :			}
210 :			}
211 :			}
212 :
213 :			void report (std::ostream &outS, log_file *, std::vector<worker_stats> const &stats);
214 :
215 :			static void usage (int sts)
216 :			{
217 :			fprintf (stderr, "usage: log-analyze [-o outfile] [-log logfile] [-svg]\n");
218 :			exit (sts);
219 :			}
220 :
221 :			int main (int argc, const char **argv)
222 :			{
223 :			std::string logFile("");
224 :			std::string outFile("-");
225 :			bool outputSVG = false;
226 :			uint64_t timeQ = TIMEQ;
227 :
228 :			// process args
229 :			for (int i = 1; i < argc; ) {
230 :			if (strcmp(argv[i], "-h") == 0) {
231 :			usage (0);
232 :			}
233 :			else if (strcmp(argv[i], "-o") == 0) {
234 :			if (++i < argc) {
235 :			outFile = argv[i];
236 :			i++;
237 :			}
238 :			else {
239 :			std::cerr << "missing filename for \"-o\" option\n";
240 :			usage (1);
241 :			}
242 :			}
243 :			else if (strcmp(argv[i], "-log") == 0) {
244 :			if (++i < argc) {
245 :			logFile = argv[i];
246 :			i++;
247 :			}
248 :			else {
249 :			std::cerr << "missing filename for \"-log\" option\n";
250 :			usage (1);
251 :			}
252 :			}
253 :			else if (strcmp(argv[i], "-svg") == 0) {
254 :			i++;
255 :			outputSVG = true;
256 :			}
257 :			else if (strcmp(argv[i], "-tq") == 0) {
258 :			if (++i < argc) {
259 :			timeQ = std::stoull(argv[i]) * MILLISEC;
260 :			i++;
261 :			}
262 :			else {
263 :			std::cerr << "missing value for \"-tq\" option\n";
264 :			usage (1);
265 :			}
266 :			}
267 :			else {
268 :			std::cerr << "invalid argument \"" << argv[i] << "\"\n";
269 :			usage(1);
270 :			}
271 :			}
272 :			if (logFile.length() == 0) {
273 :			usage(1);
274 :			}
275 :
276 :			LogFileDesc *logFileDesc = LoadLogDesc (logDescFile, logViewFile);
277 :			if (logFileDesc == nullptr) {
278 :			std::cerr << "unable to load \"" << logDescFile << "\"\n";
279 :			exit (1);
280 :			}
281 :
282 :			log_file *log = load_log_file (logFile, false);
283 :			if (log == nullptr) {
284 :			std::cerr << "unable to load \"" << logFile << "\"\n";
285 :			exit (1);
286 :			}
287 :			uint64_t maxTime = log->_events.back()._ts;
288 :
289 :			std::vector<worker_stats> stats;
290 :			stats.reserve(log->_nWorkers+1);
291 :			for (uint32_t i = 0; i <= log->_nWorkers; i++) {
292 :			stats.push_back(worker_stats(i));
293 :			}
294 :
295 :			buckets Q(log->_nWorkers+1, (maxTime + timeQ - 1) / timeQ, timeQ);
296 :
297 :			// process the event log
298 :			for (auto it = log->_events.begin(); it != log->_events.end(); ++it) {
299 :			int id = it->_worker;
300 :			switch (it->_evt) {
301 :			case diderot::log::SchedulerStartEvt:
302 :			stats[id]._start = it->_ts;
303 :			stats[id].set_state (Other, it->_ts);
304 :			Q.setState (id, Other, it->_ts);
305 :			break;
306 :			case diderot::log::SchedulerShutdownEvt:
307 :			stats[id]._end = it->_ts;
308 :			stats[id].set_state (Dead, it->_ts);
309 :			Q.setState (id, Dead, it->_ts);
310 :			break;
311 :			case diderot::log::WorkerStartEvt:
312 :			stats[id]._start = it->_ts;
313 :			stats[id].set_state (Other, it->_ts);
314 :			Q.setState (id, Other, it->_ts);
315 :			break;
316 :			case diderot::log::WorkerExitEvt:
317 :			stats[id]._end = it->_ts;
318 :			stats[id].set_state (Dead, it->_ts);
319 :			Q.setState (id, Dead, it->_ts);
320 :			break;
321 :			case diderot::log::GetStrandBlockEvt:
322 :			stats[id]._nBlocks++;
323 :			stats[id].set_state (Waiting, it->_ts);
324 :			Q.setState (id, Waiting, it->_ts);
325 :			break;
326 :			case diderot::log::GotStrandBlockEvt:
327 :			stats[id]._nBlocks++;
328 :			stats[id].set_state (Running, it->_ts);
329 :			Q.setState (id, Running, it->_ts);
330 :			break;
331 :			case diderot::log::NoStrandBlockEvt:
332 :			stats[id].set_state (Other, it->_ts);
333 :			Q.setState (id, Other, it->_ts);
334 :			break;
335 :			case diderot::log::WorkerGateWaitEvt:
336 :			stats[id].set_state (Waiting, it->_ts);
337 :			Q.setState (id, Waiting, it->_ts);
338 :			break;
339 :			case diderot::log::ControllerGateWaitEvt:
340 :			stats[id].set_state (Waiting, it->_ts);
341 :			Q.setState (id, Waiting, it->_ts);
342 :			break;
343 :			case diderot::log::GateReleaseWorkersEvt:
344 :			break;
345 :			case diderot::log::WorkerGateResumeEvt:
346 :			stats[id].set_state (Other, it->_ts);
347 :			Q.setState (id, Other, it->_ts);
348 :			break;
349 :			case diderot::log::ControllerGateResumeEvt:
350 :			stats[id].set_state (Other, it->_ts);
351 :			Q.setState (id, Other, it->_ts);
352 :			break;
353 :			case diderot::log::BarrierWaitEvt:
354 :			stats[id].set_state (Waiting, it->_ts);
355 :			Q.setState (id, Waiting, it->_ts);
356 :			break;
357 :			case diderot::log::BarrierResumeEvt:
358 :			stats[id].set_state (Other, it->_ts);
359 :			Q.setState (id, Other, it->_ts);
360 :			break;
361 :			case diderot::log::StrandStartEvt:
362 :			stats[id]._nStarts++;
363 :			stats[id].set_state (Running, it->_ts);
364 :			Q.setState (id, Running, it->_ts);
365 :			break;
366 :			case diderot::log::StrandUpdateEvt:
367 :			stats[id]._nUpdates++;
368 :			stats[id].set_state (Running, it->_ts);
369 :			Q.setState (id, Running, it->_ts);
370 :			break;
371 :			case diderot::log::StrandDieEvt:
372 :			stats[id]._nDies++;
373 :			stats[id].set_state (Running, it->_ts);
374 :			Q.setState (id, Running, it->_ts);
375 :			break;
376 :			case diderot::log::StrandStabilizeEvt:
377 :			stats[id]._nStabilizes++;
378 :			stats[id].set_state (Running, it->_ts);
379 :			Q.setState (id, Running, it->_ts);
380 :			break;
381 :			default:
382 :			break;
383 :			}
384 :			}
385 :
386 :			Q.finish(maxTime);
387 :
388 :			std::ostream *outS = nullptr;
389 :			bool needsClose = false;
390 :
391 :			if (outFile.compare("-") == 0) {
392 :			outS = &std::cout;
393 :			}
394 :			else {
395 :			outS = new std::ofstream(outFile);
396 :			if (! outS->good()) {
397 :			std::cerr << "unable to open output file \"" << outFile << "\"\n";
398 :			exit (1);
399 :			}
400 :			needsClose = true;
401 :			}
402 :
403 :			if (outputSVG) {
404 :			svg::output_header (*outS);
405 :			(*outS) << "<!--\n";
406 :			report (*outS, log, stats);
407 :			(*outS) << "-->\n";
408 :			genSVG (*outS, Q);
409 :			}
410 :			else {
411 :			report (*outS, log, stats);
412 :			}
413 :
414 :			if (needsClose) {
415 :			delete outS;
416 :			}
417 :
418 :			return 0;
419 :
420 :			}
421 :
422 :			struct layout {
423 :			int32_t _topMargin;
424 :			int32_t _leftMargin;
425 :			int32_t _hSep;
426 :			int32_t _wid;
427 :
428 :			svg::Point position (int32_t thd, int32_t bucket)
429 :			{
430 :			double x = this->_leftMargin + (this->_hSep + this->_wid) * thd;
431 :			double y = this->_topMargin + this->_wid * bucket;
432 :			return svg::Point(x, y);
433 :			}
434 :
435 :			svg::Dimensions dimensions (int32_t nThreads, int32_t nBuckets)
436 :			{
437 :			double wid = this->_leftMargin + (this->_hSep * (nThreads-1)) + this->_wid * nThreads + 2;
438 :			double ht = this->_topMargin + this->_wid * nBuckets + 2;
439 :			return svg::Dimensions (wid, ht);
440 :			}
441 :
442 :			};
443 :
444 :			static layout Layout = {50, 50, 10, 20};
445 :
446 :			void genSVG (std::ostream &outS, buckets const &Q)
447 :			{
448 :			svg::Document doc (Layout.dimensions(Q.numThreads(), Q.numIntervals()));
449 :
450 :			for (int32_t tid = 0; tid < Q.numThreads(); tid++) {
451 :			svg::Group tgrp;
452 :			for (int32_t bid = 0; bid < Q.numIntervals(); bid++) {
453 :			svg::Point pt = Layout.position (tid, bid);
454 :			svg::Group bgrp;
455 :			bgrp << svg::Stroke(svg::Color("black"));
456 :			if (Q.time(tid, bid) == 0) {
457 :			bgrp << svg::Fill(svg::Color(0,0,0)) << svg::FillOpacity(0.1);
458 :			}
459 :			else {
460 :			double runFrac = Q.pct (tid, bid, Running);
461 :			double waitFrac = Q.pct (tid, bid, Waiting);
462 :			double otherFrac = Q.pct (tid, bid, Other);
463 :			double opacity;
464 :			if ((runFrac > waitFrac) && (runFrac > otherFrac)) {
465 :			bgrp << svg::Fill(svg::Color(0,128,0));
466 :			opacity = 0.3 + 0.7 * runFrac;
467 :			}
468 :			else if ((waitFrac >= runFrac) && (waitFrac >= otherFrac)) {
469 :			bgrp << svg::Fill(svg::Color(255,0,0));
470 :			opacity = 0.3 + 0.7 * waitFrac;
471 :			}
472 :			else {
473 :			bgrp << svg::Fill(svg::Color(0,0,255));
474 :			opacity = 0.3 + 0.7 * otherFrac;
475 :			}
476 :			bgrp << svg::FillOpacity(opacity);
477 :			}
478 :			bgrp << svg::Path{svg::path::M(pt),
479 :			svg::path::l(Layout._wid,0),
480 :			svg::path::l(0,Layout._wid),
481 :			svg::path::l(-Layout._wid,0),
482 :			svg::path::Z()
483 :			};
484 :			tgrp << bgrp;
485 :			}
486 :			doc << tgrp;
487 :			}
488 :
489 :			doc.serialize (outS);
490 :			}
491 :
492 :			void report (std::ostream &outS, log_file *log, std::vector<worker_stats> const &stats)
493 :			{
494 :			outS << "Log taken on " << log->_date << "\n";
495 :			outS << log->_nWorkers << " workers, "
496 :			<< log->_nCores << " cores, " << log->_events.size() << " events, clock = "
497 :			<< log->_clockName << " (" << log->_resolution << "ns resolution)\n";
498 :
499 :			outS << std::fixed;
500 :
501 :			// report on the controller
502 :
503 :			// check for any StrandDie events
504 :			bool anyDies = false;
505 :			for (uint32_t i = 1; i <= log->_nWorkers; i++) {
506 :			if (stats[i]._nDies > 0) {
507 :			anyDies = true;
508 :			break;
509 :			}
510 :			}
511 :
512 :			// report on the workers
513 :			uint64_t totRunTime = 0;
514 :			uint64_t nStabilizes = 0;
515 :			for (uint32_t i = 0; i <= log->_nWorkers; i++) {
516 :			if (i == 0) {
517 :			outS << "Controller:\n";
518 :			}
519 :			else {
520 :			totRunTime += stats[i]._time[Running];
521 :			nStabilizes += stats[i]._nStabilizes;
522 :			outS << "[" << std::setw(2) << i << "] " << stats[i]._nBlocks << " blocks";
523 :			if (stats[i]._nBlocks > 0) {
524 :			outS << "; " << stats[i]._nStarts << " starts; "
525 :			<< stats[i]._nUpdates << " updates; "
526 :			<< stats[i]._nStabilizes << " stabilizes";
527 :			if (anyDies) {
528 :			outS << "; " << stats[i]._nDies << " dies\n";
529 :			}
530 :			else {
531 :			outS << "\n";
532 :			}
533 :			}
534 :			else {
535 :			outS << "\n";
536 :			}
537 :			}
538 :			outS << " time: total = "
539 :			<< std::setw(6) << std::setprecision(3) << stats[i].run_time() << "\n";
540 :			outS << " waiting = "
541 :			<< std::setw(6) << std::setprecision(3) << stats[i].time_waiting()
542 :			<< " (" << std::setw(4) << std::setprecision(1) << stats[i].pct_waiting() << "%)\n";
543 :			outS << " running = "
544 :			<< std::setw(6) << std::setprecision(3) << stats[i].time_running()
545 :			<< " (" << std::setw(4) << std::setprecision(1) << stats[i].pct_running() << "%)\n";
546 :			outS << " overhead = "
547 :			<< std::setw(6) << std::setprecision(3) << stats[i].time_overhead()
548 :			<< " (" << std::setw(4) << std::setprecision(1) << stats[i].pct_overhead() << "%)\n";
549 :			}
550 :
551 :			outS << "Total worker runtime = "
552 :			<< std::setw(6) << std::setprecision(3) << toSeconds(totRunTime)
553 :			<< "; " << nStabilizes << " strands stabilized; throughput = "
554 :			<< (nStabilizes * 1000000000) / totRunTime << " strands/sec\n";
555 :			}
556 :
557 :			void worker_stats::set_state (uint32_t state, uint64_t ts)
558 :			{
559 :			if (this->_state == state) {
560 :			return;
561 :			}
562 :			if (ts < this->_last) {
563 :			this->_state = state;
564 :			return;
565 :			}
566 :			this->_time[this->_state] += ts - this->_last;
567 :			this->_state = state;
568 :			this->_last = ts;
569 :			}

---

root@smlnj-gforge.cs.uchicago.edu	ViewVC Help
Powered by ViewVC 1.0.0