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       68498 : PerfGraphLivePrint::PerfGraphLivePrint(PerfGraph & perf_graph, MooseApp & app)
      15             :   : ConsoleStreamInterface(app),
      16       68498 :     _app(app),
      17       68498 :     _perf_graph(perf_graph),
      18      136996 :     _perf_graph_registry(moose::internal::getPerfGraphRegistry()),
      19       68498 :     _execution_list(perf_graph._execution_list),
      20       68498 :     _currently_destructing(false),
      21       68498 :     _time_limit(perf_graph._live_print_time_limit),
      22       68498 :     _mem_limit(perf_graph._live_print_mem_limit),
      23       68498 :     _stack_level(0),
      24       68498 :     _current_execution_list_end(0),
      25       68498 :     _current_execution_list_last(0),
      26       68498 :     _last_execution_list_end(0),
      27       68498 :     _last_printed_increment(NULL),
      28       68498 :     _last_num_printed(0),
      29       68498 :     _console_num_printed(0),
      30      136996 :     _stack_top_print_dots(true)
      31             : {
      32       68498 : }
      33             : 
      34             : void
      35        1224 : PerfGraphLivePrint::printLiveMessage(PerfGraph::SectionIncrement & section_increment)
      36             : {
      37        1224 :   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        1224 :   if (!section_info._print_dots || !_stack_top_print_dots)
      41             :   {
      42         268 :     section_increment._state = PerfGraph::IncrementState::PRINTED;
      43         268 :     _last_printed_increment = &section_increment;
      44         268 :     return;
      45             :   }
      46             : 
      47             :   // If the live_message is empty - just print the name
      48             :   auto message =
      49         956 :       !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         956 :   if (_last_num_printed <= _console_num_printed &&
      56         824 :       section_increment._state == PerfGraph::IncrementState::STARTED &&
      57         328 :       section_increment._beginning_num_printed != _console_num_printed)
      58             :   {
      59         195 :     message = "Currently " + message;
      60             :     // The 10 is for "Currently "
      61         195 :     section_increment._num_dots = 10;
      62             :   }
      63             : 
      64             :   // This line is different - need to finish the last line
      65         956 :   if (_last_printed_increment && _last_printed_increment != &section_increment &&
      66         252 :       _last_printed_increment->_state == PerfGraph::IncrementState::PRINTED &&
      67         148 :       section_info._print_dots)
      68         148 :     _console << '\n';
      69             : 
      70             :   // Do we need to print dots?
      71         956 :   if (_last_printed_increment && _last_printed_increment == &section_increment &&
      72         482 :       section_increment._state == PerfGraph::IncrementState::PRINTED)
      73             :   {
      74         482 :     if (section_info._print_dots)
      75             :     {
      76         482 :       _console << ".";
      77         482 :       section_increment._num_dots++;
      78             :     }
      79             :   }
      80             :   // Printed before so print "Still"
      81         474 :   else if (section_increment._state == PerfGraph::IncrementState::PRINTED)
      82             :   {
      83          28 :     _console << std::string(2 * section_increment._print_stack_level, ' ') << "Still " << message;
      84             : 
      85             :     // If we're not printing dots - just finish the line
      86          14 :     if (!section_info._print_dots)
      87           0 :       _console << '\n';
      88             : 
      89             :     // The 6 is for "Still "
      90          14 :     section_increment._num_dots = 6;
      91             :   }
      92             :   else // Just print the message
      93             :   {
      94         920 :     _console << std::string(2 * section_increment._print_stack_level, ' ') << message;
      95             : 
      96             :     // If we're not printing dots - just finish the line
      97         460 :     if (!section_info._print_dots)
      98           0 :       _console << '\n';
      99             : 
     100             :     // Reset the dots since we're printing, except in the "Currently" case
     101         460 :     if (section_increment._state != PerfGraph::IncrementState::STARTED ||
     102         460 :         _last_num_printed > _console_num_printed ||
     103         328 :         section_increment._beginning_num_printed == _console_num_printed)
     104         265 :       section_increment._num_dots = 0;
     105             :   }
     106             : 
     107         956 :   section_increment._state = PerfGraph::IncrementState::PRINTED;
     108             : 
     109             :   // Get the message to the screen
     110         956 :   _console << std::flush;
     111             : 
     112             :   // Keep track of where we printed in the console
     113         956 :   _last_num_printed = section_increment._beginning_num_printed = _console.numPrinted();
     114             : 
     115         956 :   _last_printed_increment = &section_increment;
     116         956 : }
     117             : 
     118             : void
     119         736 : PerfGraphLivePrint::printStats(PerfGraph::SectionIncrement & section_increment_start,
     120             :                                PerfGraph::SectionIncrement & section_increment_finish)
     121             : {
     122         736 :   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         736 :   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         736 :   auto message = !section_info_start._live_message.empty() ? section_info_start._live_message
     132         736 :                                                            : section_info_start._name;
     133             : 
     134             :   auto time_increment =
     135         736 :       std::chrono::duration<double>(section_increment_finish._time - section_increment_start._time)
     136         736 :           .count();
     137             : 
     138         736 :   auto memory_total = section_increment_finish._memory;
     139             : 
     140         736 :   auto num_horizontal_chars = message.size() + (2 * section_increment_start._print_stack_level);
     141             : 
     142             :   // Add multiapps prefix size
     143         736 :   if (!_app.isUltimateMaster())
     144          49 :     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         736 :   if (!section_info_start._print_dots ||
     149         506 :       (_last_printed_increment && _last_printed_increment != &section_increment_start) ||
     150         266 :       (section_increment_start._beginning_num_printed !=
     151         266 :        _console_num_printed)) // This means someone _else_ printed
     152             :   {
     153             :     // If we had printed some dots - we need to finish the line
     154        1462 :     if (_last_printed_increment &&
     155         635 :         _last_printed_increment->_state == PerfGraph::IncrementState::PRINTED &&
     156         139 :         _perf_graph_registry.sectionInfo(_last_printed_increment->_id)._print_dots)
     157         111 :       _console << '\n';
     158             : 
     159        1488 :     _console << std::string(2 * section_increment_start._print_stack_level, ' ') << "Finished "
     160         496 :              << message;
     161             : 
     162             :     // 9 is for "Finished "
     163         496 :     num_horizontal_chars += 9;
     164             :   }
     165             :   else
     166         240 :     num_horizontal_chars += section_increment_start._num_dots;
     167             : 
     168             :   // Actually do the printing
     169         736 :   _console << std::setw(WRAP_LENGTH - num_horizontal_chars);
     170             : 
     171         736 :   _console << " [";
     172         736 :   _console << COLOR_YELLOW;
     173         736 :   _console << std::setw(6) << std::fixed << std::setprecision(2) << time_increment << " s";
     174         736 :   _console << COLOR_DEFAULT;
     175         736 :   _console << ']' << " [";
     176         736 :   _console << COLOR_YELLOW << std::setw(5) << std::fixed;
     177         736 :   _console << memory_total;
     178         736 :   _console << " MB";
     179         736 :   _console << COLOR_DEFAULT;
     180         736 :   _console << ']';
     181             : 
     182             :   // If we're not printing dots - just finish the line
     183         736 :   _console << std::endl;
     184             : 
     185         736 :   _last_num_printed = _console.numPrinted();
     186             : 
     187         736 :   _last_printed_increment = &section_increment_finish;
     188         736 : }
     189             : 
     190             : void
     191        1589 : PerfGraphLivePrint::printStackUpToLast()
     192             : {
     193        1589 :   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        3673 :   for (unsigned int s = 0; s < _stack_level - 1; s++)
     198             :   {
     199        2084 :     auto & section = _print_thread_stack[s];
     200             : 
     201             :     // Hasn't been printed at all and nothing else has been printed since this started
     202        2084 :     if (section._state == PerfGraph::IncrementState::STARTED)
     203         371 :       printLiveMessage(section);
     204             : 
     205        2084 :     section._state = PerfGraph::IncrementState::PRINTED;
     206             :   }
     207             : }
     208             : 
     209             : void
     210         992 : 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         992 :   if (_last_num_printed != _console_num_printed)
     216             :   {
     217           0 :     _last_printed_increment = nullptr;
     218             : 
     219           0 :     for (unsigned int s = 0; s < _stack_level; s++)
     220           0 :       _print_thread_stack[s]._state = PerfGraph::IncrementState::PRINTED;
     221             : 
     222           0 :     return;
     223             :   }
     224             : 
     225             :   // Only print if there is something to print!
     226         992 :   if (_stack_level > 0)
     227             :   {
     228         853 :     _stack_top_print_dots =
     229         853 :         _perf_graph_registry.sectionInfo(_print_thread_stack[_stack_level - 1]._id)._print_dots;
     230             : 
     231         853 :     printStackUpToLast();
     232             : 
     233         853 :     printLiveMessage(_print_thread_stack[_stack_level - 1]);
     234             : 
     235             :     // Reset this each time
     236         853 :     _stack_top_print_dots = true;
     237             :   }
     238             : }
     239             : 
     240             : void
     241      967110 : PerfGraphLivePrint::iterateThroughExecutionList()
     242             : {
     243             :   // Current position in the execution list
     244      967110 :   auto p = _last_execution_list_end;
     245             : 
     246     2892854 :   while (p != _current_execution_list_end)
     247             :   {
     248             :     // The ternary here is for wrapping around
     249     1925744 :     auto next_p = p + 1 < MAX_EXECUTION_LIST_SIZE ? p + 1 : 0;
     250             : 
     251     1925744 :     auto & section_increment = _execution_list[p];
     252             : 
     253             :     // New section, add to the stack
     254     1925744 :     if (section_increment._state == PerfGraph::IncrementState::STARTED)
     255             :     {
     256      962983 :       section_increment._print_stack_level = _stack_level;
     257             : 
     258             :       // Store this increment in the stack
     259      962983 :       _print_thread_stack[_stack_level] = section_increment;
     260             : 
     261      962983 :       _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      962761 :       auto & section_increment_start = _print_thread_stack[_stack_level - 1];
     270             : 
     271             :       auto time_increment =
     272      962761 :           std::chrono::duration<double>(section_increment._time - section_increment_start._time)
     273      962761 :               .count();
     274      962761 :       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     2888283 :       if (_perf_graph._live_print_all ||
     278     1924934 :           section_increment_start._state == PerfGraph::IncrementState::PRINTED ||
     279     2887695 :           time_increment > _time_limit.load(std::memory_order_relaxed) ||
     280     1924062 :           memory_increment > _mem_limit.load(std::memory_order_relaxed))
     281             :       {
     282         736 :         printStackUpToLast();
     283             : 
     284         736 :         printStats(section_increment_start, section_increment);
     285             :       }
     286             : 
     287      962761 :       _stack_level--;
     288             :     }
     289             : 
     290     1925744 :     p = next_p;
     291             :   }
     292      967110 : }
     293             : 
     294             : void
     295        3438 : 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      970548 :   while (!_currently_destructing)
     302             :   {
     303      970457 :     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      970457 :     _perf_graph._finished_section.wait_for(
     319             :         lock,
     320      970457 :         std::chrono::duration<Real>(_time_limit.load(std::memory_order_relaxed)),
     321     1924475 :         [this]
     322             :         {
     323             :           // Get destructing first so that the execution_list will be in sync
     324     1924475 :           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     3848950 :           this->_current_execution_list_end =
     331     1924475 :               _perf_graph._execution_list_end.load(std::memory_order_acquire);
     332             : 
     333             :           // Save off the number of things currently printed to the console
     334     1924475 :           this->_console_num_printed = _console.numPrinted();
     335             : 
     336             :           // If we are destructing or there is new work to do... allow moving on
     337     3845561 :           return this->_currently_destructing ||
     338     5770036 :                  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      973797 :     if (this->_currently_destructing &&
     345      973797 :         this->_last_execution_list_end == this->_current_execution_list_end)
     346        3298 :       return;
     347             : 
     348             :     // The last entry in the current execution list for convenience
     349     1934220 :     _current_execution_list_last = static_cast<long int>(_current_execution_list_end) - 1 >= 0
     350      967110 :                                        ? _current_execution_list_end - 1
     351             :                                        : MAX_EXECUTION_LIST_SIZE;
     352             : 
     353             :     // Only happens if nothing has been added
     354      967110 :     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      967110 :     if (_last_execution_list_end == _current_execution_list_end)
     364         992 :       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      967110 :     iterateThroughExecutionList();
     369             : 
     370      967110 :     _last_num_printed = _console.numPrinted();
     371             : 
     372      967110 :     _last_execution_list_end = _current_execution_list_end;
     373      970408 :   }
     374             : }