Line data Source code
1 : // The libMesh Finite Element Library.
2 : // Copyright (C) 2002-2026 Benjamin S. Kirk, John W. Peterson, Roy H. Stogner
3 :
4 : // This library is free software; you can redistribute it and/or
5 : // modify it under the terms of the GNU Lesser General Public
6 : // License as published by the Free Software Foundation; either
7 : // version 2.1 of the License, or (at your option) any later version.
8 :
9 : // This library is distributed in the hope that it will be useful,
10 : // but WITHOUT ANY WARRANTY; without even the implied warranty of
11 : // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
12 : // Lesser General Public License for more details.
13 :
14 : // You should have received a copy of the GNU Lesser General Public
15 : // License along with this library; if not, write to the Free Software
16 : // Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
17 :
18 : #include "libmesh/perf_log.h"
19 :
20 : // Local includes
21 : #include "libmesh/int_range.h"
22 : #include "libmesh/timestamp.h"
23 :
24 : // C++ includes
25 : #include <algorithm>
26 : #include <iostream>
27 : #include <iomanip>
28 : #include <cstring>
29 : #include <ctime>
30 : #ifdef LIBMESH_HAVE_UNISTD_H
31 : #include <unistd.h> // for getuid()
32 : #endif
33 : #include <sys/types.h>
34 : #include <vector>
35 : #include <sstream>
36 :
37 : #ifdef LIBMESH_HAVE_SYS_UTSNAME_H
38 : #include <sys/utsname.h>
39 : #endif
40 :
41 : #ifdef LIBMESH_HAVE_PWD_H
42 : #include <pwd.h>
43 : #endif
44 :
45 : namespace libMesh
46 : {
47 :
48 :
49 : // ------------------------------------------------------------
50 : // PerfLog class member functions
51 :
52 : bool PerfLog::called = false;
53 :
54 :
55 319199 : PerfLog::PerfLog(std::string ln,
56 319199 : const bool le) :
57 312877 : label_name(std::move(ln)),
58 306147 : log_events(le),
59 306147 : summarize_logs(false),
60 319199 : total_time(0.)
61 : {
62 319199 : gettimeofday (&tstart, nullptr);
63 :
64 319199 : if (log_events)
65 1785 : this->clear();
66 319199 : }
67 :
68 :
69 :
70 325521 : PerfLog::~PerfLog()
71 : {
72 319199 : if (log_events)
73 1785 : this->print_log();
74 319199 : }
75 :
76 :
77 :
78 18452 : void PerfLog::clear()
79 : {
80 18452 : if (log_events)
81 : {
82 : // check that all events are closed
83 93628 : for (auto pos : log)
84 90840 : libmesh_error_msg_if(pos.second.open,
85 : "ERROR clearing performance log for class "
86 : << label_name
87 : << "\nevent "
88 : << pos.first.second
89 : << " is still being monitored!");
90 :
91 2788 : gettimeofday (&tstart, nullptr);
92 :
93 960 : log.clear();
94 :
95 2788 : while (!log_stack.empty())
96 0 : log_stack.pop();
97 : }
98 18452 : }
99 :
100 :
101 :
102 677259 : void PerfLog::push (const std::string & label,
103 : const std::string & header)
104 : {
105 : // The global perflog stack may not be thread-safe, but if we're
106 : // creating threads we should have disabled it already
107 52521 : libmesh_assert_equal_to(Threads::active_threads, 1);
108 : #ifdef LIBMESH_HAVE_OPENMP
109 : // Users might be doing their own non-libMesh threading. We can't
110 : // catch every case of that but we can catch OpenMP.
111 52521 : libmesh_assert_equal_to(omp_get_num_threads(), 1);
112 : #endif
113 :
114 : const char * label_c_str;
115 : const char * header_c_str;
116 :
117 677259 : if (const auto label_it = non_temporary_strings.find(label);
118 52521 : label_it != non_temporary_strings.end())
119 50257 : label_c_str = label_it->second.get();
120 : else
121 : {
122 60743 : const std::size_t labelsizep1 = label.size()+1;
123 60743 : auto newcopy = std::make_unique<char[]>(labelsizep1);
124 60743 : std::strncpy(newcopy.get(), label.c_str(), labelsizep1);
125 2264 : label_c_str = newcopy.get();
126 60743 : non_temporary_strings[label] = std::move(newcopy);
127 : }
128 :
129 677259 : if (const auto header_it = non_temporary_strings.find(header);
130 52521 : header_it != non_temporary_strings.end())
131 51607 : header_c_str = header_it->second.get();
132 : else
133 : {
134 16752 : const std::size_t headersizep1 = header.size()+1;
135 16752 : auto newcopy = std::make_unique<char[]>(headersizep1);
136 16752 : std::strncpy(newcopy.get(), header.c_str(), headersizep1);
137 914 : header_c_str = newcopy.get();
138 16752 : non_temporary_strings[header] = std::move(newcopy);
139 : }
140 :
141 677259 : if (this->log_events)
142 514745 : this->fast_push(label_c_str, header_c_str);
143 677259 : }
144 :
145 :
146 :
147 353615 : void PerfLog::push (const char * label,
148 : const char * header)
149 : {
150 664359 : this->push(std::string(label), std::string(header));
151 353615 : }
152 :
153 :
154 :
155 :
156 :
157 677259 : void PerfLog::pop (const std::string & label,
158 : const std::string & header)
159 : {
160 : // The global perflog stack may not be thread-safe, but if we're
161 : // creating threads we should have disabled it already
162 52521 : libmesh_assert_equal_to(Threads::active_threads, 1);
163 : #ifdef LIBMESH_HAVE_OPENMP
164 : // Users might be doing their own non-libMesh threading. We can't
165 : // catch every case of that but we can catch OpenMP.
166 52521 : libmesh_exceptionless_assert(omp_get_num_threads() == 1);
167 : #endif
168 :
169 677259 : const char * label_c_str = non_temporary_strings[label].get();
170 677259 : const char * header_c_str = non_temporary_strings[header].get();
171 :
172 : // This could happen if users are *mixing* string and char* APIs for
173 : // the same label/header combination. For perfect backwards
174 : // compatibility we should handle that, but there's just no fast way
175 : // to do so.
176 52521 : libmesh_assert(label_c_str);
177 52521 : libmesh_assert(header_c_str);
178 :
179 677259 : if (this->log_events)
180 514745 : this->fast_pop(label_c_str, header_c_str);
181 677259 : }
182 :
183 :
184 :
185 353615 : void PerfLog::pop (const char * label,
186 : const char * header)
187 : {
188 664359 : this->pop(std::string(label), std::string(header));
189 353615 : }
190 :
191 :
192 :
193 1516 : std::string PerfLog::get_info_header() const
194 : {
195 2328 : std::ostringstream oss;
196 :
197 1516 : if (log_events)
198 : {
199 1922 : std::string date = Utility::get_timestamp();
200 :
201 : #ifdef LIBMESH_HAVE_SYS_UTSNAME_H
202 : // Get system information
203 : struct utsname sysInfo;
204 1516 : uname(&sysInfo);
205 : #endif
206 :
207 : // Get user information
208 : //
209 : // Some systems, for example Crays, actually have getpwuid on the head-node
210 : // but (if I understand correctly) a dynamically-linked glibc is not available
211 : // on the backend, which is running a reduced operating system like Compute
212 : // Node Linux. Thus functions like getpwuid cannot be called. This makes
213 : // automatically testing for the existence of getpwuid on the login node
214 : // difficult. The configure test would work on the login node but will fail
215 : // on the backend. Hence we have added a configure flag, --disable-getpwuid,
216 : // to manually turn this off.
217 : #ifdef LIBMESH_HAVE_GETPWUID
218 1516 : struct passwd * p = getpwuid(getuid());
219 : #endif
220 1516 : oss << "\n";
221 :
222 : // Construct string stream objects for each of the outputs
223 : std::ostringstream
224 2328 : pid_stream,
225 2328 : nprocs_stream,
226 2328 : time_stream,
227 2328 : os_stream,
228 2328 : host_stream,
229 2328 : osrel_stream,
230 2328 : osver_stream,
231 2328 : machine_stream,
232 2328 : user_stream;
233 :
234 :
235 : // Put pointers to these streams in a vector
236 812 : std::vector<std::ostringstream*> v;
237 1516 : v.push_back(&pid_stream);
238 1516 : v.push_back(&nprocs_stream);
239 1516 : v.push_back(&time_stream);
240 1516 : v.push_back(&os_stream);
241 1516 : v.push_back(&host_stream);
242 1516 : v.push_back(&osrel_stream);
243 1516 : v.push_back(&osver_stream);
244 1516 : v.push_back(&machine_stream);
245 1516 : v.push_back(&user_stream);
246 :
247 : // Fill string stream objects
248 1516 : if (libMesh::global_n_processors() > 1)
249 : {
250 1091 : pid_stream << "| Processor id: " << libMesh::global_processor_id();
251 1091 : nprocs_stream << "| Num Processors: " << libMesh::global_n_processors();
252 : }
253 :
254 1516 : time_stream << "| Time: ";
255 1516 : os_stream << "| OS: ";
256 1516 : host_stream << "| HostName: ";
257 1516 : osrel_stream << "| OS Release: ";
258 1516 : osver_stream << "| OS Version: ";
259 1516 : machine_stream << "| Machine: ";
260 :
261 406 : time_stream << date;
262 : #ifdef LIBMESH_HAVE_SYS_UTSNAME_H
263 1516 : os_stream << sysInfo.sysname ;
264 1516 : host_stream << sysInfo.nodename ;
265 1516 : osrel_stream << sysInfo.release ;
266 1516 : osver_stream << sysInfo.version ;
267 1516 : machine_stream << sysInfo.machine ;
268 : #else
269 : os_stream << "Unknown";
270 : host_stream << "Unknown";
271 : osrel_stream << "Unknown";
272 : osver_stream << "Unknown";
273 : machine_stream << "Unknown";
274 :
275 : #endif
276 1516 : user_stream << "| Username: ";
277 : #ifdef LIBMESH_HAVE_GETPWUID
278 1516 : if (p && p->pw_name)
279 1516 : user_stream << p->pw_name;
280 : else
281 : #endif
282 0 : user_stream << "Unknown";
283 :
284 : // Parse the LIBMESH_CONFIGURE_INFO string literal before using it in PerfLog output
285 1922 : std::string libmesh_configure_info(LIBMESH_CONFIGURE_INFO);
286 812 : std::vector<std::string> parsed_libmesh_configure_info;
287 1516 : this->split_on_whitespace(libmesh_configure_info,
288 : parsed_libmesh_configure_info);
289 :
290 : // There should always be at at least one entry in
291 : // parsed_libmesh_configure_info, even if the user just ran
292 : // ../configure.
293 406 : libmesh_assert_greater (parsed_libmesh_configure_info.size(), 0);
294 :
295 : // Find the longest string in all the streams
296 406 : unsigned int max_length = 0;
297 15160 : for (auto & v_i : v)
298 17298 : if (v_i->str().size() > max_length)
299 : max_length = cast_int<unsigned int>
300 11076 : (v_i->str().size());
301 :
302 : // Find the longest string in the parsed_libmesh_configure_info
303 27450 : for (auto & plci_i : parsed_libmesh_configure_info)
304 25934 : if (plci_i.size() > max_length)
305 0 : max_length = cast_int<unsigned int> (plci_i.size());
306 :
307 : // Print dashed line for the header
308 : oss << ' '
309 1922 : << std::string(max_length+1, '-')
310 3032 : << '\n';
311 :
312 : // Loop over all the strings and add end formatting
313 15160 : for (auto & v_i : v)
314 : {
315 23634 : if (v_i->str().size())
316 27212 : oss << v_i->str()
317 : << std::setw (cast_int<int>
318 27212 : (max_length + 4 - v_i->str().size()))
319 3654 : << std::right
320 13606 : << "|\n";
321 : }
322 :
323 : // Print out configuration header plus first parsed string. The
324 : // magic number 18 below accounts for the length of the word
325 : // 'Configuration'.
326 : oss << "| Configuration: "
327 812 : << parsed_libmesh_configure_info[0]
328 : << std::setw (cast_int<int>
329 2328 : (max_length + 4 -
330 2220 : parsed_libmesh_configure_info[0].size() - 18))
331 406 : << std::right
332 1516 : << "|\n";
333 :
334 : // Loop over the parsed_libmesh_configure_info and add end formatting. The magic
335 : // number 3 below accounts for the leading 'pipe' character and indentation
336 25934 : for (auto i : IntRange<std::size_t>(1, parsed_libmesh_configure_info.size()))
337 : {
338 : oss << "| "
339 13804 : << parsed_libmesh_configure_info[i]
340 : << std::setw (cast_int<int>
341 31320 : (max_length + 4 -
342 41934 : parsed_libmesh_configure_info[i].size() - 3))
343 6902 : << std::right
344 24418 : << "|\n";
345 : }
346 :
347 :
348 : // Print dashed line
349 : oss << ' '
350 1922 : << std::string(max_length+1, '-')
351 3032 : << '\n';
352 1408 : }
353 :
354 1922 : return oss.str();
355 704 : }
356 :
357 :
358 :
359 :
360 1564 : std::string PerfLog::get_perf_info() const
361 : {
362 2424 : std::ostringstream oss;
363 :
364 1564 : if (!log_events || log.empty())
365 0 : return oss.str();
366 :
367 : // Stop timing for this event.
368 : struct timeval tstop;
369 :
370 1564 : gettimeofday (&tstop, nullptr);
371 :
372 2424 : const double elapsed_time = (static_cast<double>(tstop.tv_sec - tstart.tv_sec) +
373 1564 : static_cast<double>(tstop.tv_usec - tstart.tv_usec)*1.e-6);
374 :
375 : // Figure out the formatting required based on the event names
376 : // Unsigned ints for each of the column widths
377 430 : unsigned int event_col_width = 30;
378 430 : const unsigned int ncalls_col_width = 11;
379 430 : const unsigned int tot_time_col_width = 12;
380 430 : const unsigned int avg_time_col_width = 12;
381 430 : const unsigned int tot_time_incl_sub_col_width = 12;
382 430 : const unsigned int avg_time_incl_sub_col_width = 12;
383 430 : const unsigned int pct_active_col_width = 9;
384 430 : const unsigned int pct_active_incl_sub_col_width = 9;
385 :
386 : // Reset the event column width based on the longest event name plus
387 : // a possible 2-character indentation, plus a space.
388 45411 : for (auto pos : log)
389 43847 : if (std::strlen(pos.first.second)+3 > event_col_width)
390 : event_col_width = cast_int<unsigned int>
391 2057 : (std::strlen(pos.first.second)+3);
392 :
393 : // Set the total width of the column
394 1564 : const unsigned int total_col_width =
395 : event_col_width +
396 : ncalls_col_width +
397 : tot_time_col_width +
398 : avg_time_col_width +
399 : tot_time_incl_sub_col_width +
400 : avg_time_incl_sub_col_width +
401 : pct_active_col_width+
402 : pct_active_incl_sub_col_width+1;
403 :
404 : // Print dashed line
405 : oss << ' '
406 1564 : << std::string(total_col_width, '-')
407 3128 : << '\n';
408 :
409 : {
410 : // Construct temporary message string
411 1994 : std::ostringstream temp;
412 1838 : temp << "| " << label_name << " Performance: Alive time=" << elapsed_time
413 1564 : << ", Active time=" << total_time;
414 :
415 : // Get the size of the temporary string
416 : const unsigned int temp_size = cast_int<unsigned int>
417 1994 : (temp.str().size());
418 :
419 : // Send the temporary message to the output
420 1134 : oss << temp.str();
421 :
422 : // If this string is longer than the previously computed total
423 : // column width, skip the additional formatting... this shouldn't
424 : // happen often, hopefully. Add two additional characters for a
425 : // space and a "|" character at the end.
426 1564 : if (temp_size < total_col_width+2)
427 1564 : oss << std::setw(total_col_width - temp_size + 2)
428 430 : << std::right
429 1564 : << "|";
430 :
431 1564 : oss << '\n';
432 704 : }
433 :
434 : // Print dashed line
435 : oss << ' '
436 1994 : << std::string(total_col_width, '-')
437 3128 : << '\n';
438 :
439 :
440 : // Write out the header for the events listing
441 : oss << "| "
442 1564 : << std::setw(event_col_width)
443 430 : << std::left
444 : << "Event"
445 1134 : << std::setw(ncalls_col_width)
446 430 : << std::left
447 : << "nCalls"
448 1134 : << std::setw(tot_time_col_width)
449 430 : << std::left
450 : << "Total Time"
451 1134 : << std::setw(avg_time_col_width)
452 430 : << std::left
453 : << "Avg Time"
454 1134 : << std::setw(tot_time_incl_sub_col_width)
455 430 : << std::left
456 : << "Total Time"
457 1134 : << std::setw(avg_time_incl_sub_col_width)
458 430 : << std::left
459 : << "Avg Time"
460 1134 : << std::setw(pct_active_col_width+pct_active_incl_sub_col_width)
461 430 : << std::left
462 : << "% of Active Time"
463 : << "|\n"
464 : << "| "
465 1134 : << std::setw(event_col_width)
466 430 : << std::left
467 : << ""
468 1134 : << std::setw(ncalls_col_width)
469 430 : << std::left
470 : << ""
471 1134 : << std::setw(tot_time_col_width)
472 430 : << std::left
473 : << "w/o Sub"
474 1134 : << std::setw(avg_time_col_width)
475 430 : << std::left
476 : << "w/o Sub"
477 1134 : << std::setw(tot_time_incl_sub_col_width)
478 430 : << std::left
479 : << "With Sub"
480 1134 : << std::setw(avg_time_incl_sub_col_width)
481 430 : << std::left
482 : << "With Sub"
483 1134 : << std::setw(pct_active_col_width)
484 430 : << std::left
485 : << "w/o S"
486 1134 : << std::setw(pct_active_incl_sub_col_width)
487 430 : << std::left
488 : << "With S"
489 : << "|\n|"
490 1564 : << std::string(total_col_width, '-')
491 : << "|\n|"
492 1994 : << std::string(total_col_width, ' ')
493 3832 : << "|\n";
494 :
495 430 : unsigned int summed_function_calls = 0;
496 430 : double summed_total_time = 0;
497 430 : double summed_percentage = 0;
498 :
499 1994 : std::string last_header("");
500 :
501 : // Make a new log to sort entries alphabetically
502 860 : std::map<std::pair<std::string, std::string>, PerfData> string_log;
503 :
504 45411 : for (auto char_data : log)
505 43847 : if (summarize_logs)
506 : {
507 4764 : string_log[std::make_pair(std::string(), char_data.first.first)] +=
508 1588 : char_data.second;
509 : }
510 : else
511 : {
512 21372 : string_log[std::make_pair(char_data.first.first,
513 63658 : char_data.first.second)] =
514 : char_data.second;
515 : }
516 :
517 42675 : for (auto pos : string_log)
518 : {
519 21357 : const PerfData & perf_data = pos.second;
520 :
521 : // Only print the event if the count is non-zero.
522 41111 : if (perf_data.count != 0)
523 : {
524 21357 : const unsigned int perf_count = perf_data.count;
525 41111 : const double perf_time = perf_data.tot_time;
526 41111 : const double perf_avg_time = perf_time / static_cast<double>(perf_count);
527 41111 : const double perf_time_incl_sub = perf_data.tot_time_incl_sub;
528 41111 : const double perf_avg_time_incl_sub = perf_time_incl_sub / static_cast<double>(perf_count);
529 41111 : const double perf_percent = (total_time != 0.) ? perf_time / total_time * 100. : 0.;
530 41111 : const double perf_percent_incl_sub = (total_time != 0.) ? perf_time_incl_sub / total_time * 100. : 0.;
531 :
532 41111 : summed_function_calls += perf_count;
533 41111 : summed_total_time += perf_time;
534 41111 : summed_percentage += perf_percent;
535 :
536 : // Print the event name
537 41111 : if (pos.first.first == "")
538 : oss << "| "
539 2158 : << std::setw(event_col_width)
540 314 : << std::left
541 314 : << pos.first.second;
542 :
543 : else
544 : {
545 38639 : if (last_header != pos.first.first)
546 : {
547 7686 : last_header = pos.first.first;
548 :
549 : // print blank line followed by header name
550 : // (account for additional space before the
551 : // header)
552 : oss << "|"
553 22662 : << std::string(total_col_width, ' ')
554 : << "|\n| "
555 22662 : << std::setw(total_col_width-1)
556 7686 : << std::left
557 : << pos.first.first
558 14976 : << "|\n";
559 : }
560 :
561 : oss << "| "
562 38639 : << std::setw(event_col_width-2)
563 21043 : << std::left
564 21043 : << pos.first.second;
565 : }
566 :
567 :
568 : // Print the number of calls to the event.
569 21357 : oss << std::setw(ncalls_col_width)
570 21357 : << perf_count;
571 :
572 : // Save the original stream flags
573 39267 : std::ios_base::fmtflags out_flags = oss.flags();
574 :
575 : // Print the total time spent in the event
576 21357 : oss << std::fixed
577 : << std::setprecision(4)
578 21357 : << std::setw(tot_time_col_width)
579 21357 : << std::left
580 21357 : << perf_time;
581 :
582 :
583 : // Print the average time per function call
584 21357 : oss << std::fixed
585 : << std::setprecision(6)
586 21357 : << std::setw(avg_time_col_width)
587 21357 : << std::left
588 21357 : << perf_avg_time;
589 :
590 : // Print the total time spent in the event incl. sub-events
591 21357 : oss << std::fixed
592 : << std::setprecision(4)
593 21357 : << std::setw(tot_time_incl_sub_col_width)
594 21357 : << std::left
595 21357 : << perf_time_incl_sub;
596 :
597 : // Print the average time per function call incl. sub-events
598 21357 : oss << std::fixed
599 : << std::setprecision(6)
600 21357 : << std::setw(avg_time_incl_sub_col_width)
601 21357 : << std::left
602 21357 : << perf_avg_time_incl_sub;
603 :
604 : // Print the percentage of the time spent in the event
605 21357 : oss << std::fixed
606 : << std::setprecision(2)
607 21357 : << std::setw(pct_active_col_width)
608 21357 : << std::left
609 21357 : << perf_percent;
610 :
611 : // Print the percentage of the time spent in the event incl. sub-events
612 21357 : oss << std::fixed
613 : << std::setprecision(2)
614 21357 : << std::setw(pct_active_incl_sub_col_width)
615 21357 : << std::left
616 21357 : << perf_percent_incl_sub;
617 :
618 : // Reset the stream flags
619 21357 : oss.flags(out_flags);
620 :
621 41111 : oss << "|\n";
622 : }
623 : }
624 :
625 : oss << ' '
626 1564 : << std::string(total_col_width, '-')
627 : << "\n| "
628 2698 : << std::setw(event_col_width)
629 430 : << std::left
630 1564 : << "Totals:";
631 :
632 : // Print the total number of logged function calls
633 : // For routines which are called many times, summed_function_calls may
634 : // exceed 7 digits. If this happens use, scientific notation.
635 1564 : if (summed_function_calls < 9999999)
636 430 : oss << std::setw(ncalls_col_width)
637 430 : << summed_function_calls;
638 :
639 : else
640 : {
641 : // Save the original stream flags
642 0 : std::ios_base::fmtflags out_flags = oss.flags();
643 :
644 0 : oss << std::scientific
645 : << std::setprecision(3)
646 0 : << std::setw(ncalls_col_width)
647 0 : << std::left
648 0 : << static_cast<Real>(summed_function_calls);
649 :
650 : // Reset the stream flags
651 0 : oss.flags(out_flags);
652 : }
653 :
654 : // Print the total time spent in logged function calls. Don't bother saving/restoring
655 : // the flags here since we are almost done with this stream anyway...
656 430 : oss << std::fixed
657 : << std::setprecision(4)
658 430 : << std::setw(tot_time_col_width)
659 430 : << std::left
660 430 : << summed_total_time;
661 :
662 : // Null, the average time doesn't make sense as a total
663 1564 : oss << std::setw(avg_time_col_width) << "";
664 :
665 : // Same for times that include sub-events
666 : oss << std::setw(tot_time_incl_sub_col_width)
667 : << ""
668 : << std::setw(avg_time_incl_sub_col_width)
669 1564 : << "";
670 :
671 : // Print the total percentage followed by dashed line
672 430 : oss << std::fixed
673 : << std::setprecision(2)
674 430 : << std::setw(pct_active_col_width)
675 430 : << std::left
676 430 : << summed_percentage
677 : << std::setw(pct_active_incl_sub_col_width)
678 : << ""
679 : << "|\n "
680 1994 : << std::string(total_col_width, '-')
681 2698 : << '\n';
682 :
683 430 : return oss.str();
684 704 : }
685 :
686 :
687 :
688 2721 : std::string PerfLog::get_log() const
689 : {
690 4641 : std::ostringstream oss;
691 :
692 2721 : if (log_events)
693 : {
694 : // Only print the log
695 : // if it isn't empty
696 2721 : if (!log.empty())
697 : {
698 : // Possibly print machine info,
699 : // but only do this once
700 1564 : if (!called)
701 : {
702 1516 : called = true;
703 2626 : oss << get_info_header();
704 : }
705 2698 : oss << get_perf_info();
706 : }
707 : }
708 :
709 3681 : return oss.str();
710 801 : }
711 :
712 :
713 :
714 18385 : void PerfLog::print_log() const
715 : {
716 18385 : if (log_events)
717 : {
718 : // Check to see if the log_string is empty, and if so,
719 : // avoid printing an unnecessary newline.
720 3681 : std::string log_string = this->get_log();
721 2721 : if (log_string.size() > 0)
722 430 : libMesh::out << log_string << std::endl;
723 : }
724 18385 : }
725 :
726 0 : PerfData PerfLog::get_perf_data(const std::string & label, const std::string & header)
727 : {
728 0 : if (non_temporary_strings.count(label) &&
729 0 : non_temporary_strings.count(header))
730 : {
731 0 : const char * label_c_str = non_temporary_strings[label].get();
732 0 : const char * header_c_str = non_temporary_strings[header].get();
733 0 : return log[std::make_pair(header_c_str, label_c_str)];
734 : }
735 :
736 : auto iter = std::find_if
737 0 : (log.begin(), log.end(),
738 0 : [&label, &header] (log_type::const_reference a)
739 : {
740 : return
741 0 : !std::strcmp(header.c_str(), a.first.first) &&
742 0 : !std::strcmp(label.c_str(), a.first.second);
743 0 : });
744 :
745 0 : libmesh_assert(iter != log.end());
746 :
747 0 : return iter->second;
748 : }
749 :
750 0 : void PerfLog::start_event(const std::string & label,
751 : const std::string & header)
752 : {
753 0 : this->push(label,header);
754 0 : }
755 :
756 :
757 :
758 0 : void PerfLog::stop_event(const std::string & label,
759 : const std::string & header)
760 : {
761 0 : this->pop(label,header);
762 0 : }
763 :
764 :
765 :
766 0 : void PerfLog::pause_event(const std::string &,
767 : const std::string &)
768 : {
769 : // nothing to do. pushing the next object on the stack will handle it
770 0 : }
771 :
772 :
773 :
774 0 : void PerfLog::restart_event(const std::string &,
775 : const std::string &)
776 : {
777 : // nothing to do. popping the top off the stack will handle it.
778 0 : }
779 :
780 :
781 :
782 1516 : void PerfLog::split_on_whitespace(const std::string & input, std::vector<std::string> & output) const
783 : {
784 : // Check for easy return
785 1516 : if (input.size()==0)
786 0 : return;
787 :
788 : // Here we hard-code the string to split on, since the algorithm below
789 : // is somewhat specific to it...
790 1922 : const std::string split_on("' '");
791 :
792 406 : size_t current_pos = 0;
793 : while (true)
794 : {
795 : // Find next end location
796 25934 : if (size_t end_pos = input.find(split_on, current_pos);
797 : end_pos != std::string::npos)
798 : {
799 : // Create substring. Note: the second argument to substr is
800 : // the *length* of string to create, not the ending position!
801 35032 : output.push_back( input.substr(current_pos, end_pos - current_pos + 1) );
802 :
803 : // Update search starting position, make sure to go past the end of the split_on string, but
804 : // include the previous single quote (hence the -1).
805 24418 : current_pos = end_pos + split_on.size() - 1;
806 : }
807 : else
808 : {
809 : // Push back whatever remains of the string onto the output.
810 : // Note that substr with only 1 argument pushes back
811 : // whatever remains of the string. This also handles the
812 : // case where the string does not contain any matches.
813 2626 : output.push_back( input.substr(current_pos) );
814 :
815 : // We are done searching the string, so break out of the while loop
816 406 : break;
817 : }
818 24418 : }
819 : }
820 :
821 : } // namespace libMesh
|
