Home My Page Projects Code Snippets Project Openings diderot
Summary Activity Tracker Tasks SCM

SCM Repository

[diderot] Annotation of /branches/cuda/src/logging/log-analyze/log-analyze.cxx
ViewVC logotype

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

Parent Directory Parent Directory | Revision Log 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