24 #include <sys/param.h>
25 #include <unordered_map>
33 #include <boost/format.hpp>
97 #ifdef FLOW123D_DEBUG_PROFILER
102 const int timer_no_child=-1;
104 Timer::Timer(
const CodePoint &cp,
int parent)
110 full_hash_(cp.hash_),
111 hash_idx_(cp.hash_idx_),
112 parent_timer(parent),
114 total_deallocated_(0),
116 current_allocated_(0),
119 #ifdef FLOW123D_HAVE_PETSC
120 , petsc_start_memory(0),
121 petsc_end_memory (0),
122 petsc_memory_difference(0),
123 petsc_peak_memory(0),
124 petsc_local_peak_memory(0)
127 for(
unsigned int i=0; i< max_n_childs ;i++) child_timers[i]=timer_no_child;
135 os <<
" Timer: " << timer.tag() << endl;
136 os <<
" malloc: " << timer.total_allocated_ << endl;
137 os <<
" dalloc: " << timer.total_deallocated_ << endl;
138 #ifdef FLOW123D_HAVE_PETSC
139 os <<
" start: " << timer.petsc_start_memory << endl;
140 os <<
" stop : " << timer.petsc_end_memory << endl;
141 os <<
" diff : " << timer.petsc_memory_difference <<
" (" << timer.petsc_end_memory - timer.petsc_start_memory <<
")" << endl;
142 os <<
" peak : " << timer.petsc_peak_memory <<
" (" << timer.petsc_local_peak_memory <<
")" << endl;
149 double Timer::cumulative_time()
const {
153 void Profiler::accept_from_child(
Timer &parent,
Timer &child) {
155 for (
unsigned int i = 0; i < Timer::max_n_childs; i++) {
156 child_timer = child.child_timers[i];
157 if (child_timer != timer_no_child) {
159 accept_from_child(child, timers_[child_timer]);
163 parent.total_allocated_ += child.total_allocated_;
164 parent.total_deallocated_ += child.total_deallocated_;
165 parent.alloc_called += child.alloc_called;
166 parent.dealloc_called += child.dealloc_called;
168 #ifdef FLOW123D_HAVE_PETSC
169 if (petsc_monitor_memory) {
171 parent.petsc_memory_difference += child.petsc_memory_difference;
172 parent.current_allocated_ += child.current_allocated_;
176 parent.petsc_peak_memory = max(parent.petsc_peak_memory, child.petsc_peak_memory);
180 parent.max_allocated_ = max(parent.max_allocated_, child.max_allocated_);
184 void Timer::pause() {
185 #ifdef FLOW123D_HAVE_PETSC
186 if (Profiler::get_petsc_memory_monitoring()) {
188 PetscMemoryGetMaximumUsage(&petsc_local_peak_memory);
189 if (petsc_peak_memory < petsc_local_peak_memory)
190 petsc_peak_memory = petsc_local_peak_memory;
195 void Timer::resume() {
196 #ifdef FLOW123D_HAVE_PETSC
197 if (Profiler::get_petsc_memory_monitoring()) {
200 PetscMemorySetGetMaximumUsage();
206 #ifdef FLOW123D_HAVE_PETSC
207 if (Profiler::get_petsc_memory_monitoring()) {
210 PetscMemorySetGetMaximumUsage();
211 PetscMemoryGetCurrentUsage (&petsc_start_memory);
215 if (start_count == 0) {
225 #ifdef FLOW123D_HAVE_PETSC
226 if (Profiler::get_petsc_memory_monitoring()) {
228 PetscMemoryGetCurrentUsage (&petsc_end_memory);
229 petsc_memory_difference += petsc_end_memory - petsc_start_memory;
232 PetscMemoryGetMaximumUsage(&petsc_local_peak_memory);
233 if (petsc_peak_memory < petsc_local_peak_memory)
234 petsc_peak_memory = petsc_local_peak_memory;
238 if (forced) start_count=1;
240 if (start_count == 1) {
241 cumul_time += (
TimePoint() - start_time);
252 void Timer::add_child(
int child_index,
const Timer &child)
254 unsigned int idx = child.hash_idx_;
255 if (child_timers[idx] != timer_no_child) {
259 i=( i < max_n_childs ? i+1 : 0);
260 }
while (i!=idx && child_timers[i] != timer_no_child);
265 child_timers[idx] = child_index;
270 string Timer::code_point_str()
const {
272 code_point_->file_, code_point_->line_, code_point_->func_ );
285 if (_instance != NULL) {
292 if (_instance == NULL) {
293 MemoryAlloc::malloc_map().reserve(Profiler::malloc_map_reserve);
302 const long Profiler::malloc_map_reserve = 100 * 1000;
307 start_time( time(NULL) ),
309 none_timer_(CODE_POINT(
"NONE TIMER"), 0),
310 calibration_time_(-1)
313 static CONSTEXPR_ CodePoint main_cp = CODE_POINT(
"Whole Program");
314 set_memory_monitoring(
true,
true);
315 #ifdef FLOW123D_DEBUG_PROFILER
316 MemoryAlloc::malloc_map().reserve(Profiler::malloc_map_reserve);
317 timers_.push_back(
Timer(main_cp, 0) );
325 uint SIZE = 64 * 1024;
326 uint HALF = SIZE / 2;
328 Timer &timer = timers_[actual_node];
331 while(
TimePoint() - timer.start_time < 0.1) {
332 double * block =
new double[SIZE];
333 for(
uint i=0; i<HALF; i++) {
334 block[HALF+i] = block[i]*block[i] + i;
344 const double reference_count = 7730;
348 calibration_time_ = 10 * timer.cumul_time * reference_count / count;
349 LogOut() <<
"Profiler calibration count: " << count << std::endl;
350 LogOut() <<
"Profiler calibration time: " << calibration_time_ << std::endl;
356 void Profiler::propagate_timers() {
357 for (
unsigned int i = 0; i < Timer::max_n_childs; i++) {
358 unsigned int child_timer = timers_[0].child_timers[i];
359 if ((
signed int)child_timer != timer_no_child) {
361 accept_from_child(timers_[0], timers_[child_timer]);
369 task_description_ = description;
376 flow_name_ = program_name;
377 flow_version_ = program_version;
378 flow_branch_ = branch;
379 flow_revision_ = revision;
385 int Profiler::start_timer(
const CodePoint &cp) {
386 unsigned int parent_node = actual_node;
388 int child_idx = find_child(cp);
392 child_idx=timers_.size();
393 timers_.push_back(
Timer(cp, actual_node) );
394 timers_[actual_node].add_child(child_idx , timers_.back() );
396 actual_node=child_idx;
399 timers_[parent_node].pause();
401 timers_[actual_node].start();
408 int Profiler::find_child(
const CodePoint &cp) {
409 Timer &timer =timers_[actual_node];
410 unsigned int idx = cp.hash_idx_;
411 unsigned int child_idx;
413 if (timer.child_timers[idx] == timer_no_child)
break;
415 child_idx=timer.child_timers[idx];
417 if (timers_[child_idx].full_hash_ == cp.hash_)
return child_idx;
418 idx = ( (
unsigned int)(idx)==(Timer::max_n_childs - 1) ? 0 : idx+1 );
419 }
while ( (
unsigned int)(idx) != cp.hash_idx_ );
425 void Profiler::stop_timer(
const CodePoint &cp) {
426 #ifdef FLOW123D_DEBUG_ASSERTS
428 Timer &timer=timers_[actual_node];
429 for(
unsigned int i=0; i < Timer::max_n_childs; i++)
430 if (timer.child_timers[i] != timer_no_child)
431 ASSERT_PERMANENT(! timers_[timer.child_timers[i]].running())(timers_[timer.child_timers[i]].tag())(timer.tag())
432 .error(
"Child timer running while closing timer.");
434 unsigned int child_timer = actual_node;
435 if ( cp.hash_ != timers_[actual_node].full_hash_) {
437 for(
unsigned int node=actual_node; node != 0; node=timers_[node].parent_timer) {
438 if ( cp.hash_ == timers_[node].full_hash_) {
440 for(; (
unsigned int)(actual_node) != node; actual_node=timers_[actual_node].parent_timer) {
441 WarningOut() <<
"Timer to close '" << cp.tag_ <<
"' do not match actual timer '"
442 << timers_[actual_node].tag() <<
"'. Force closing actual." << std::endl;
443 timers_[actual_node].stop(
true);
446 timers_[actual_node].stop(
false);
447 actual_node = timers_[actual_node].parent_timer;
450 if (actual_node == child_timer)
454 timers_[actual_node].resume();
462 timers_[actual_node].stop(
false);
463 actual_node = timers_[actual_node].parent_timer;
466 if (actual_node == child_timer)
470 timers_[actual_node].resume();
475 void Profiler::stop_timer(
int timer_index) {
479 if (timers_[timer_index].running()) {
481 stop_timer(*timers_[timer_index].code_point_);
488 void Profiler::add_calls(
unsigned int n_calls) {
489 timers_[actual_node].call_count += n_calls-1;
495 MemoryAlloc::malloc_map()[p] =
static_cast<int>(size);
496 timers_[actual_node].total_allocated_ += size;
497 timers_[actual_node].current_allocated_ += size;
498 timers_[actual_node].alloc_called++;
500 if (timers_[actual_node].current_allocated_ > timers_[actual_node].max_allocated_)
501 timers_[actual_node].max_allocated_ = timers_[actual_node].current_allocated_;
507 int size =
sizeof(p);
508 if (MemoryAlloc::malloc_map()[(long)p] > 0) {
509 size = MemoryAlloc::malloc_map()[(long)p];
510 MemoryAlloc::malloc_map().erase((
long)p);
512 timers_[actual_node].total_deallocated_ += size;
513 timers_[actual_node].current_allocated_ -= size;
514 timers_[actual_node].dealloc_called++;
519 const int measurements = 100;
523 for (
unsigned int i = 1; i < measurements; i++) {
528 while ((t2 - t1) == 0) t2 =
TimePoint ();
534 return (result / measurements) * 1000;
538 Timer Profiler::find_timer(
string tag) {
539 for(
auto t : timers_) {
540 if (t.tag() == tag)
return t;
546 std::string common_prefix( std::string a, std::string b ) {
547 if( a.size() > b.size() )
std::swap(a,b) ;
548 return std::string( a.begin(), std::mismatch( a.begin(), a.end(), b.begin() ).first ) ;
553 template<
typename ReduceFunctor>
554 void Profiler::add_timer_info(ReduceFunctor reduce,
nlohmann::json* holder,
int timer_idx,
double parent_time) {
557 Timer &timer = timers_[timer_idx];
562 string filepath = timer.code_point_->file_;
565 #ifdef FLOW123D_SOURCE_DIR
566 string common_path = common_prefix (
string(FLOW123D_SOURCE_DIR), filepath);
567 filepath.erase (0, common_path.size());
574 double cumul_time_sum;
575 node[
"tag"] = timer.tag();
576 node[
"file-path"] = filepath;
577 node[
"file-line"] = timer.code_point_->line_;
578 node[
"function"] = timer.code_point_->func_;
579 cumul_time_sum = reduce(timer, node);
583 if (timer_idx == 0) parent_time = cumul_time_sum;
584 double percent = parent_time > 1.0e-10 ? cumul_time_sum / parent_time * 100.0 : 0.0;
585 node[
"percent"] = percent;
592 for (
unsigned int i = 0; i < Timer::max_n_childs; i++) {
593 if (timer.child_timers[i] != timer_no_child)
594 child_timers_values.push_back(timer.child_timers[i]);
596 std::sort(child_timers_values.begin(), child_timers_values.end());
598 for(
int idx : child_timers_values)
599 add_timer_info(reduce, &children, idx, cumul_time_sum);
602 if (child_timers_values.size() > 0) {
603 node[
"children"] = children;
612 void save_nonmpi_metric (
nlohmann::json &node, T * ptr,
string name) {
613 node[name +
"-min"] = *ptr;
614 node[name +
"-max"] = *ptr;
615 node[name +
"-sum"] = *ptr;
620 string _profiler_output_path(
string path) {
621 if (path ==
"") path =
"profiler_info.log.json";
625 std::shared_ptr<std::ostream> _profiler_output_stream(
const string &path) {
626 return make_shared<ofstream>(path.c_str());
630 #ifdef FLOW123D_HAVE_MPI
639 int mpi_rank, mpi_size;
646 bool temp_memory_monitoring = global_monitor_memory;
647 set_memory_monitoring(
false, petsc_monitor_memory);
659 int call_count = timer.call_count;
660 double cumul_time = timer.cumulative_time ();
662 long memory_allocated = (long)timer.total_allocated_;
663 long memory_deallocated = (
long)timer.total_deallocated_;
664 long memory_peak = (long)timer.max_allocated_;
666 int alloc_called = timer.alloc_called;
667 int dealloc_called = timer.dealloc_called;
670 save_mpi_metric<double>(node, comm, &cumul_time,
"cumul-time");
671 save_mpi_metric<int>(node, comm, &call_count,
"call-count");
673 save_mpi_metric<long>(node, comm, &memory_allocated,
"memory-alloc");
674 save_mpi_metric<long>(node, comm, &memory_deallocated,
"memory-dealloc");
675 save_mpi_metric<long>(node, comm, &memory_peak,
"memory-peak");
677 save_mpi_metric<int>(node, comm, &alloc_called,
"memory-alloc-called");
678 save_mpi_metric<int>(node, comm, &dealloc_called,
"memory-dealloc-called");
680 #ifdef FLOW123D_HAVE_PETSC
681 long petsc_memory_difference = (long)timer.petsc_memory_difference;
682 long petsc_peak_memory = (
long)timer.petsc_peak_memory;
683 save_mpi_metric<long>(node, comm, &petsc_memory_difference,
"memory-petsc-diff");
684 save_mpi_metric<long>(node, comm, &petsc_peak_memory,
"memory-petsc-peak");
690 add_timer_info (reduce, &jsonChildren, 0, 0.0);
691 jsonRoot[
"children"] = jsonChildren;
692 output_header(jsonRoot, mpi_size);
703 const int FLOW123D_JSON_HUMAN_READABLE = 2;
705 os << jsonRoot.
dump(FLOW123D_JSON_HUMAN_READABLE) << endl;
707 }
catch (exception & e) {
709 ss <<
"nlohmann::json::dump error: " << e.what() <<
"\n";
710 THROW( ExcMessage() << EI_Message(ss.str()) );
714 set_memory_monitoring(temp_memory_monitoring, petsc_monitor_memory);
724 string out_path = _profiler_output_path(profiler_path);
725 output(comm, *_profiler_output_stream(out_path));
747 const int FLOW123D_MPI_SINGLE_PROCESS = 1;
748 output_header(jsonRoot, FLOW123D_MPI_SINGLE_PROCESS);
755 int call_count = timer.call_count;
756 double cumul_time = timer.cumulative_time ();
758 long memory_allocated = (long)timer.total_allocated_;
759 long memory_deallocated = (
long)timer.total_deallocated_;
760 long memory_peak = (long)timer.max_allocated_;
762 int alloc_called = timer.alloc_called;
763 int dealloc_called = timer.dealloc_called;
765 save_nonmpi_metric<double>(node, &cumul_time,
"cumul-time");
766 save_nonmpi_metric<int>(node, &call_count,
"call-count");
768 save_nonmpi_metric<long>(node, &memory_allocated,
"memory-alloc");
769 save_nonmpi_metric<long>(node, &memory_deallocated,
"memory-dealloc");
770 save_nonmpi_metric<long>(node, &memory_peak,
"memory-peak");
772 save_nonmpi_metric<int>(node, &alloc_called,
"memory-alloc-called");
773 save_nonmpi_metric<int>(node, &dealloc_called,
"memory-dealloc-called");
775 #ifdef FLOW123D_HAVE_PETSC
776 long petsc_memory_difference = (long)timer.petsc_memory_difference;
777 long petsc_peak_memory = (
long)timer.petsc_peak_memory;
778 save_nonmpi_metric<long>(node, &petsc_memory_difference,
"memory-petsc-diff");
779 save_nonmpi_metric<long>(node, &petsc_peak_memory,
"memory-petsc-peak");
785 add_timer_info(reduce, &jsonChildren, 0, 0.0);
786 jsonRoot[
"children"] = jsonChildren;
793 const int FLOW123D_JSON_HUMAN_READABLE = 2;
795 os << jsonRoot.
dump(FLOW123D_JSON_HUMAN_READABLE) << endl;
797 }
catch (exception & e) {
799 ss <<
"nlohmann::json::dump error: " << e.what() <<
"\n";
800 THROW( ExcMessage() << EI_Message(ss.str()) );
806 string out_path = _profiler_output_path(profiler_path);
807 output(*_profiler_output_stream(out_path));
811 void Profiler::output_header (
nlohmann::json &root,
int mpi_size) {
812 time_t end_time = time(NULL);
814 const char format[] =
"%x %X";
815 char start_time_string[BUFSIZ] = {0};
816 strftime(start_time_string,
sizeof (start_time_string) - 1,
format, localtime(&start_time));
818 char end_time_string[BUFSIZ] = {0};
819 strftime(end_time_string,
sizeof (end_time_string) - 1,
format, localtime(&end_time));
821 if (timers_[0].cumul_time > 60) {
825 root[
"program-name"] = flow_name_;
826 root[
"program-version"] = flow_version_;
827 root[
"program-branch"] = flow_branch_;
828 root[
"program-revision"] = flow_revision_;
829 root[
"program-build"] = flow_build_;
831 root[
"timer-calibration"] = calibration_time_;
834 root[
"task-description"] = task_description_;
835 root[
"task-size"] = task_size_;
838 root[
"run-process-count"] = mpi_size;
839 root[
"run-started-at"] = start_time_string;
840 root[
"run-finished-at"] = end_time_string;
849 .error(
"Forbidden to uninitialize the Profiler when actual timer is not zero.");
851 set_memory_monitoring(
false,
false);
855 bool Profiler::global_monitor_memory =
false;
856 bool Profiler::petsc_monitor_memory =
true;
857 void Profiler::set_memory_monitoring(
const bool global_monitor,
const bool petsc_monitor) {
858 global_monitor_memory = global_monitor;
859 petsc_monitor_memory = petsc_monitor;
862 unordered_map_with_alloc & MemoryAlloc::malloc_map() {
863 static unordered_map_with_alloc static_malloc_map;
864 return static_malloc_map;
867 void * Profiler::operator
new (
size_t size) {
868 return malloc (size);
871 void Profiler::operator
delete (
void* p) {
876 void * p = malloc(size);
877 if (Profiler::get_global_memory_monitoring())
883 void * p = malloc(size);
884 if (Profiler::get_global_memory_monitoring())
889 void *
operator new[] (std::size_t size,
const std::nothrow_t&)
throw() {
890 void * p = malloc(size);
891 if (Profiler::get_global_memory_monitoring())
896 void operator delete(
void *p)
throw() {
897 if (Profiler::get_global_memory_monitoring())
902 void operator delete(
void *p, std::size_t)
throw() {
903 if (Profiler::get_global_memory_monitoring())
908 void operator delete[](
void *p)
throw() {
909 if (Profiler::get_global_memory_monitoring())
914 void operator delete[](
void *p, std::size_t)
throw() {
915 if (Profiler::get_global_memory_monitoring())
#define ASSERT_PERMANENT_LT(a, b)
Definition of comparative assert macro (Less Than)
#define ASSERT_PERMANENT(expr)
Allow use shorter versions of macro names if these names is not used with external library.
#define ASSERT_PERMANENT_EQ(a, b)
Definition of comparative assert macro (EQual)
Dedicated class for storing path to input and output files.
static int sum(int *val, MPI_Comm comm)
static int min(int *val, MPI_Comm comm)
static int max(int *val, MPI_Comm comm)
static void uninitialize()
void notify_malloc(const size_t)
void output(MPI_Comm, ostream &)
void notify_free(const size_t)
static Profiler * instance(bool clear=false)
void set_program_info(string, string, string, string, string)
void set_task_info(string, int)
double get_resolution() const
a class to store JSON values
void push_back(basic_json &&val)
add an object to an array
string_t dump(const int indent=-1) const
serialization
#define THROW(whole_exception_expr)
Wrapper for throw. Saves the throwing point.
#define WarningOut()
Macro defining 'warning' record of log.
#define LogOut()
Macro defining 'log' record of log.
manipulators::Array< T, Delim > format(T const &deduce, Delim delim=", ")
#define MPI_Barrier(comm)
#define MPI_Reduce(sendbuf, recvbuf, count, datatype, op, root, comm)
std::string format(CStringRef format_str, ArgList args)
void swap(nlohmann::json &j1, nlohmann::json &j2) noexcept(is_nothrow_move_constructible< nlohmann::json >::value and is_nothrow_move_assignable< nlohmann::json >::value)
exchanges the values of two JSON objects
#define END_TIMER(tag)
Ends a timer with specified tag.
#define START_TIMER(tag)
Starts a timer with specified tag.
#define OPERATOR_NEW_THROW_EXCEPTION
void chkerr(unsigned int ierr)
Replacement of new/delete operator in the spirit of xmalloc.
STREAM & operator<<(STREAM &s, UpdateFlags u)