Line data    Source code

       1             : //* This file is part of the MOOSE framework
       2             : //* https://mooseframework.inl.gov
       3             : //*
       4             : //* All rights reserved, see COPYRIGHT for full restrictions
       5             : //* https://github.com/idaholab/moose/blob/master/COPYRIGHT
       6             : //*
       7             : //* Licensed under LGPL 2.1, please see LICENSE for details
       8             : //* https://www.gnu.org/licenses/lgpl-2.1.html
       9             : 
      10             : #include "PerfGraphLivePrint.h"
      11             : #include "PerfGraphRegistry.h"
      12             : #include "MooseApp.h"
      13             : 
      14       62755 : PerfGraphLivePrint::PerfGraphLivePrint(PerfGraph & perf_graph, MooseApp & app)
      15             :   : ConsoleStreamInterface(app),
      16       62755 :     _app(app),
      17       62755 :     _perf_graph(perf_graph),
      18      125510 :     _perf_graph_registry(moose::internal::getPerfGraphRegistry()),
      19       62755 :     _execution_list(perf_graph._execution_list),
      20       62755 :     _currently_destructing(false),
      21       62755 :     _time_limit(perf_graph._live_print_time_limit),
      22       62755 :     _mem_limit(perf_graph._live_print_mem_limit),
      23       62755 :     _stack_level(0),
      24       62755 :     _current_execution_list_end(0),
      25       62755 :     _current_execution_list_last(0),
      26       62755 :     _last_execution_list_end(0),
      27       62755 :     _last_printed_increment(NULL),
      28       62755 :     _last_num_printed(0),
      29       62755 :     _console_num_printed(0),
      30      125510 :     _stack_top_print_dots(true)
      31             : {
      32       62755 : }
      33             : 
      34             : void
      35        2600 : PerfGraphLivePrint::printLiveMessage(PerfGraph::SectionIncrement & section_increment)
      36             : {
      37        2600 :   auto & section_info = _perf_graph_registry.sectionInfo(section_increment._id);
      38             : 
      39             :   // If we're not printing dots - we shouldn't be printing the message at all
      40        2600 :   if (!section_info._print_dots || !_stack_top_print_dots)
      41             :   {
      42         433 :     section_increment._state = PerfGraph::IncrementState::PRINTED;
      43         433 :     _last_printed_increment = &section_increment;
      44         433 :     return;
      45             :   }
      46             : 
      47             :   // If the live_message is empty - just print the name
      48             :   auto message =
      49        2167 :       !section_info._live_message.empty() ? section_info._live_message : section_info._name;
      50             : 
      51             :   // If this section is just started - but other stuff has printed before we got to print its
      52             :   // message, we need to print it anyway because it could be lengthy and print unexplained
      53             :   // dots to the console (until the Finished message). "Currently" conveys the message
      54             :   // that we did not just start it, but we are doing that right now
      55        2167 :   if (_last_num_printed <= _console_num_printed &&
      56        1963 :       section_increment._state == PerfGraph::IncrementState::STARTED &&
      57        1140 :       section_increment._beginning_num_printed != _console_num_printed)
      58             :   {
      59         822 :     message = "Currently " + message;
      60             :     // The 10 is for "Currently "
      61         822 :     section_increment._num_dots = 10;
      62             :   }
      63             : 
      64             :   // This line is different - need to finish the last line
      65        2167 :   if (_last_printed_increment && _last_printed_increment != &section_increment &&
      66         480 :       _last_printed_increment->_state == PerfGraph::IncrementState::PRINTED &&
      67         236 :       section_info._print_dots)
      68         236 :     _console << '\n';
      69             : 
      70             :   // Do we need to print dots?
      71        2167 :   if (_last_printed_increment && _last_printed_increment == &section_increment &&
      72         808 :       section_increment._state == PerfGraph::IncrementState::PRINTED)
      73             :   {
      74         808 :     if (section_info._print_dots)
      75             :     {
      76         808 :       _console << ".";
      77         808 :       section_increment._num_dots++;
      78             :     }
      79             :   }
      80             :   // Printed before so print "Still"
      81        1359 :   else if (section_increment._state == PerfGraph::IncrementState::PRINTED)
      82             :   {
      83          15 :     _console << std::string(2 * section_increment._print_stack_level, ' ') << "Still " << message;
      84             : 
      85             :     // If we're not printing dots - just finish the line
      86          15 :     if (!section_info._print_dots)
      87           0 :       _console << '\n';
      88             : 
      89             :     // The 6 is for "Still "
      90          15 :     section_increment._num_dots = 6;
      91             :   }
      92             :   else // Just print the message
      93             :   {
      94        1344 :     _console << std::string(2 * section_increment._print_stack_level, ' ') << message;
      95             : 
      96             :     // If we're not printing dots - just finish the line
      97        1344 :     if (!section_info._print_dots)
      98           0 :       _console << '\n';
      99             : 
     100             :     // Reset the dots since we're printing, except in the "Currently" case
     101        1344 :     if (section_increment._state != PerfGraph::IncrementState::STARTED ||
     102        1344 :         _last_num_printed > _console_num_printed ||
     103        1140 :         section_increment._beginning_num_printed == _console_num_printed)
     104         522 :       section_increment._num_dots = 0;
     105             :   }
     106             : 
     107        2167 :   section_increment._state = PerfGraph::IncrementState::PRINTED;
     108             : 
     109             :   // Get the message to the screen
     110        2167 :   _console << std::flush;
     111             : 
     112             :   // Keep track of where we printed in the console
     113        2167 :   _last_num_printed = section_increment._beginning_num_printed = _console.numPrinted();
     114             : 
     115        2167 :   _last_printed_increment = &section_increment;
     116        2167 : }
     117             : 
     118             : void
     119        4127 : PerfGraphLivePrint::printStats(PerfGraph::SectionIncrement & section_increment_start,
     120             :                                PerfGraph::SectionIncrement & section_increment_finish)
     121             : {
     122        4127 :   if (_stack_level < 1)
     123           0 :     return;
     124             : 
     125             :   mooseAssert(_perf_graph_registry.sectionExists(section_increment_start._id),
     126             :               "Not found in map: " << section_increment_start._id);
     127             : 
     128        4127 :   auto & section_info_start = _perf_graph_registry.sectionInfo(section_increment_start._id);
     129             : 
     130             :   // If the live_message is empty - just print the name
     131        4127 :   auto message = !section_info_start._live_message.empty() ? section_info_start._live_message
     132        4127 :                                                            : section_info_start._name;
     133             : 
     134             :   auto time_increment =
     135        4127 :       std::chrono::duration<double>(section_increment_finish._time - section_increment_start._time)
     136        4127 :           .count();
     137             : 
     138        4127 :   auto memory_total = section_increment_finish._memory;
     139             : 
     140        4127 :   auto num_horizontal_chars = message.size() + (2 * section_increment_start._print_stack_level);
     141             : 
     142             :   // Add multiapps prefix size
     143        4127 :   if (!_app.isUltimateMaster())
     144          56 :     num_horizontal_chars += _app.name().size() + 2;
     145             : 
     146             :   // Do we need to print "Finished"?
     147             :   // This happens after something else printed in-between when this increment started and finished
     148        4127 :   if (!section_info_start._print_dots ||
     149        3025 :       (_last_printed_increment && _last_printed_increment != &section_increment_start) ||
     150        2106 :       (section_increment_start._beginning_num_printed !=
     151        2106 :        _console_num_printed)) // This means someone _else_ printed
     152             :   {
     153             :     // If we had printed some dots - we need to finish the line
     154        9328 :     if (_last_printed_increment &&
     155        4409 :         _last_printed_increment->_state == PerfGraph::IncrementState::PRINTED &&
     156         768 :         _perf_graph_registry.sectionInfo(_last_printed_increment->_id)._print_dots)
     157         682 :       _console << '\n';
     158             : 
     159        7282 :     _console << std::string(2 * section_increment_start._print_stack_level, ' ') << "Finished "
     160        3641 :              << message;
     161             : 
     162             :     // 9 is for "Finished "
     163        3641 :     num_horizontal_chars += 9;
     164             :   }
     165             :   else
     166         486 :     num_horizontal_chars += section_increment_start._num_dots;
     167             : 
     168             :   // Actually do the printing
     169        4127 :   _console << std::setw(WRAP_LENGTH - num_horizontal_chars);
     170             : 
     171        4127 :   _console << " [";
     172        4127 :   _console << COLOR_YELLOW;
     173        4127 :   _console << std::setw(6) << std::fixed << std::setprecision(2) << time_increment << " s";
     174        4127 :   _console << COLOR_DEFAULT;
     175        4127 :   _console << ']' << " [";
     176        4127 :   _console << COLOR_YELLOW << std::setw(5) << std::fixed;
     177        4127 :   _console << memory_total;
     178        4127 :   _console << " MB";
     179        4127 :   _console << COLOR_DEFAULT;
     180        4127 :   _console << ']';
     181             : 
     182             :   // If we're not printing dots - just finish the line
     183        4127 :   _console << std::endl;
     184             : 
     185        4127 :   _last_num_printed = _console.numPrinted();
     186             : 
     187        4127 :   _last_printed_increment = &section_increment_finish;
     188        4127 : }
     189             : 
     190             : void
     191        5579 : PerfGraphLivePrint::printStackUpToLast()
     192             : {
     193        5579 :   if (_stack_level < 1)
     194           0 :     return;
     195             : 
     196             :   // We need to print out everything on the stack before this that hasn't already been printed...
     197       10069 :   for (unsigned int s = 0; s < _stack_level - 1; s++)
     198             :   {
     199        4490 :     auto & section = _print_thread_stack[s];
     200             : 
     201             :     // Hasn't been printed at all and nothing else has been printed since this started
     202        4490 :     if (section._state == PerfGraph::IncrementState::STARTED)
     203        1148 :       printLiveMessage(section);
     204             : 
     205        4490 :     section._state = PerfGraph::IncrementState::PRINTED;
     206             :   }
     207             : }
     208             : 
     209             : void
     210        3445 : PerfGraphLivePrint::inSamePlace()
     211             : {
     212             :   // If someone else printed since, then we need to start over, and set everything on the stack to
     213             :   // printed Everything is set to printed because if something printed and we're still in the same
     214             :   // place then we need to NOT print out the beginning message
     215        3445 :   if (_last_num_printed != _console_num_printed)
     216             :   {
     217          25 :     _last_printed_increment = nullptr;
     218             : 
     219          74 :     for (unsigned int s = 0; s < _stack_level; s++)
     220          49 :       _print_thread_stack[s]._state = PerfGraph::IncrementState::PRINTED;
     221             : 
     222          25 :     return;
     223             :   }
     224             : 
     225             :   // Only print if there is something to print!
     226        3420 :   if (_stack_level > 0)
     227             :   {
     228        1452 :     _stack_top_print_dots =
     229        1452 :         _perf_graph_registry.sectionInfo(_print_thread_stack[_stack_level - 1]._id)._print_dots;
     230             : 
     231        1452 :     printStackUpToLast();
     232             : 
     233        1452 :     printLiveMessage(_print_thread_stack[_stack_level - 1]);
     234             : 
     235             :     // Reset this each time
     236        1452 :     _stack_top_print_dots = true;
     237             :   }
     238             : }
     239             : 
     240             : void
     241    25411016 : PerfGraphLivePrint::iterateThroughExecutionList()
     242             : {
     243             :   // Current position in the execution list
     244    25411016 :   auto p = _last_execution_list_end;
     245             : 
     246    76170306 :   while (p != _current_execution_list_end)
     247             :   {
     248             :     // The ternary here is for wrapping around
     249    50759290 :     auto next_p = p + 1 < MAX_EXECUTION_LIST_SIZE ? p + 1 : 0;
     250             : 
     251    50759290 :     auto & section_increment = _execution_list[p];
     252             : 
     253             :     // New section, add to the stack
     254    50759290 :     if (section_increment._state == PerfGraph::IncrementState::STARTED)
     255             :     {
     256    25384075 :       section_increment._print_stack_level = _stack_level;
     257             : 
     258             :       // Store this increment in the stack
     259    25384075 :       _print_thread_stack[_stack_level] = section_increment;
     260             : 
     261    25384075 :       _stack_level++;
     262             :     }
     263             :     else // This means it's finished need to see if we need to print it
     264             :     {
     265             :       mooseAssert(_stack_level, "Popping beyond the beginning of the stack!");
     266             : 
     267             :       // Get the beginning information for this section... it is the thing currently on the top of
     268             :       // the stack
     269    25375215 :       auto & section_increment_start = _print_thread_stack[_stack_level - 1];
     270             : 
     271             :       auto time_increment =
     272    25375215 :           std::chrono::duration<double>(section_increment._time - section_increment_start._time)
     273    25375215 :               .count();
     274    25375215 :       auto memory_increment = section_increment._memory - section_increment_start._memory;
     275             : 
     276             :       // If it has already been printed or meets our criteria then print it and finish it
     277    76125645 :       if (_perf_graph._live_print_all ||
     278    50748803 :           section_increment_start._state == PerfGraph::IncrementState::PRINTED ||
     279    76124018 :           time_increment > _time_limit.load(std::memory_order_relaxed) ||
     280    50742208 :           memory_increment > _mem_limit.load(std::memory_order_relaxed))
     281             :       {
     282        4127 :         printStackUpToLast();
     283             : 
     284        4127 :         printStats(section_increment_start, section_increment);
     285             :       }
     286             : 
     287    25375215 :       _stack_level--;
     288             :     }
     289             : 
     290    50759290 :     p = next_p;
     291             :   }
     292    25411016 : }
     293             : 
     294             : void
     295       48743 : PerfGraphLivePrint::start()
     296             : {
     297             :   // Keep going until we're signaled to end
     298             :   // Note that _currently_destructing can only be set to true in this thread
     299             :   // Which means that by the time we make it back to the top of the loop, either
     300             :   // there was nothing to process or everything has been processed.
     301    25459759 :   while (!_currently_destructing)
     302             :   {
     303    25457651 :     std::unique_lock<std::mutex> lock(_perf_graph._destructing_mutex);
     304             : 
     305             :     // Wait for five seconds (by default), or until notified that a section is finished
     306             :     // For a section to have finished the execution list has to have been appended to
     307             :     // This keeps spurious wakeups from happening
     308             :     // Note that the `lock` is only protecting _destructing since the execution list uses atomics.
     309             :     // It must be atomic in order to keep the main thread from having to lock as it
     310             :     // executes.  The only downside to this is that it is possible for this thread to wake,
     311             :     // check the condition, miss the notification, then wait.  In our case this is not detrimental,
     312             :     // as the only thing that will happen is we will wait 5 more seconds.  This is also very
     313             :     // unlikely.
     314             :     // One other thing: wait_for() is not guaranteed to wait for 5 seconds.  "Spurious" wakeups
     315             :     // can occur - but the predicate here keeps us from doing anything in that case.
     316             :     // This will either wait until 5 seconds have passed, the signal is sent, _or_ a spurious
     317             :     // wakeup happens to find that there is work to do.
     318    25457651 :     _perf_graph._finished_section.wait_for(
     319             :         lock,
     320    25457651 :         std::chrono::duration<Real>(_time_limit.load(std::memory_order_relaxed)),
     321   253180526 :         [this]
     322             :         {
     323             :           // Get destructing first so that the execution_list will be in sync
     324    50644772 :           this->_currently_destructing = _perf_graph._destructing;
     325             : 
     326             :           // The end will be one past the last
     327             :           // This "acquire" synchronizes with the "release" in the PerfGraph
     328             :           // to ensure that all of the writes to the execution list have been
     329             :           // published to this thread for the "end" we're reading
     330    50644772 :           this->_current_execution_list_end =
     331    50644772 :               _perf_graph._execution_list_end.load(std::memory_order_acquire);
     332             : 
     333             :           // Save off the number of things currently printed to the console
     334    50644772 :           this->_console_num_printed = _console.numPrinted();
     335             : 
     336             :           // If we are destructing or there is new work to do... allow moving on
     337   101246210 :           return this->_currently_destructing ||
     338   151890982 :                  this->_last_execution_list_end != this->_current_execution_list_end;
     339             :         });
     340             : 
     341             :     // If the PerfGraph is destructing and we don't have anything left to print - we need to quit
     342             :     // Otherwise, if there are still things to print - do it... afterwards, the loop above
     343             :     // will end because _done_future has been set in PerfGraph.
     344    25495576 :     if (this->_currently_destructing &&
     345    25495576 :         this->_last_execution_list_end == this->_current_execution_list_end)
     346       41226 :       return;
     347             : 
     348             :     // The last entry in the current execution list for convenience
     349    50822032 :     _current_execution_list_last = static_cast<long int>(_current_execution_list_end) - 1 >= 0
     350    25411016 :                                        ? _current_execution_list_end - 1
     351             :                                        : MAX_EXECUTION_LIST_SIZE;
     352             : 
     353             :     // Only happens if nothing has been added
     354    25411016 :     if (_current_execution_list_end == 0 && _last_execution_list_end == _current_execution_list_end)
     355           0 :       continue;
     356             : 
     357             :     // Iterate from the last thing printed (begin) to the last thing in the list (end)
     358             :     // If the time or memory of any section is above the threshold, print everything in between and
     359             :     // update begin
     360             : 
     361             :     // Are we still sitting in the same place as the last iteration?  If so, we need to print
     362             :     // progress and exit
     363    25411016 :     if (_last_execution_list_end == _current_execution_list_end)
     364        3445 :       inSamePlace();
     365             : 
     366             :     // This means that new stuff has been added to the execution list.  We need to iterate through
     367             :     // it, modifying the stack and printing anything that needs printing
     368    25411016 :     iterateThroughExecutionList();
     369             : 
     370    25411016 :     _last_num_printed = _console.numPrinted();
     371             : 
     372    25411016 :     _last_execution_list_end = _current_execution_list_end;
     373    25452242 :   }
     374             : }