Arcane  4.2.1.0
Developer documentation
Loading...
Searching...
No Matches
TimeStats.cc
1// -*- tab-width: 2; indent-tabs-mode: nil; coding: utf-8-with-signature -*-
2//-----------------------------------------------------------------------------
3// Copyright 2000-2026 CEA (www.cea.fr) IFPEN (www.ifpenergiesnouvelles.com)
4// See the top-level COPYRIGHT file for details.
5// SPDX-License-Identifier: Apache-2.0
6//-----------------------------------------------------------------------------
7/*---------------------------------------------------------------------------*/
8/* TimeStats.cc (C) 2000-2026 */
9/* */
10/* Statistics on execution times. */
11/*---------------------------------------------------------------------------*/
12/*---------------------------------------------------------------------------*/
13
14#include "arcane/utils/ArrayView.h"
15#include "arcane/utils/Deleter.h"
16#include "arcane/utils/FatalErrorException.h"
17#include "arcane/utils/NameComparer.h"
18#include "arcane/utils/OStringStream.h"
19#include "arcane/utils/PlatformUtils.h"
20#include "arcane/utils/StringBuilder.h"
21#include "arcane/utils/TraceInfo.h"
22#include "arcane/utils/JSONWriter.h"
23#include "arcane/utils/Exception.h"
24#include "arcane/utils/Convert.h"
25
26#include "arcane/core/Timer.h"
27#include "arcane/core/IParallelMng.h"
28#include "arcane/core/ITimerMng.h"
29#include "arcane/core/MathUtils.h"
30#include "arcane/core/Properties.h"
31
32#include "arcane/impl/TimeStats.h"
33
34#include "arccore/trace/internal/ITimeMetricCollector.h"
35#include "arccore/trace/internal/TimeMetric.h"
36
37#include <algorithm>
38
39/*---------------------------------------------------------------------------*/
40/*---------------------------------------------------------------------------*/
41
42namespace Arcane
43{
44
45/*---------------------------------------------------------------------------*/
46/*---------------------------------------------------------------------------*/
47
48extern "C++" ITimeStats*
49arcaneCreateTimeStats(ITimerMng* timer_mng, ITraceMng* trace_mng, const String& name)
50{
51 return new TimeStats(timer_mng, trace_mng, name);
52}
53
54/*---------------------------------------------------------------------------*/
55/*---------------------------------------------------------------------------*/
56
57class TimeStats::MetricCollector
58: public ITimeMetricCollector
59{
60 public:
61
62 explicit MetricCollector(ITimeStats* ts)
63 : m_time_stats(ts)
64 , m_id(1)
65 {}
66
67 public:
68
69 TimeMetricAction getAction(const TimeMetricActionBuildInfo& x) override
70 {
71 return { this, x };
72 }
73 TimeMetricId beginAction(const TimeMetricAction& handle) override
74 {
75 auto name = handle.name();
76 if (!name.null())
77 m_time_stats->beginAction(name);
78 int phase = handle.phase();
79 if (phase >= 0)
80 m_time_stats->beginPhase(static_cast<eTimePhase>(phase));
81 return TimeMetricId(handle, ++m_id);
82 }
83 void endAction(const TimeMetricId& metric_id) override
84 {
85 const TimeMetricAction& action = metric_id.action();
86 int phase = action.phase();
87 if (phase >= 0)
88 m_time_stats->endPhase(static_cast<eTimePhase>(phase));
89 auto name = action.name();
90 if (!name.null())
91 m_time_stats->endAction(name, false);
92 }
93
94 private:
95
96 ITimeStats* m_time_stats;
97 std::atomic<Int64> m_id;
98};
99
100/*---------------------------------------------------------------------------*/
101/*---------------------------------------------------------------------------*/
105class TimeStats::Action
106{
107 public:
108
112 class AllActionsInfo
113 {
114 public:
115
116 UniqueArray<String> m_name_list;
117 UniqueArray<Int32> m_nb_child;
118 UniqueArray<Int64> m_nb_call_list;
119 UniqueArray<Real> m_time_list;
120 Int64 m_nb_iteration_loop = 0;
121
122 public:
123
124 friend std::ostream& operator<<(std::ostream& o, const AllActionsInfo& x)
125 {
126 o << "NbLoop=" << x.m_nb_iteration_loop << "\n";
127 o << "Name=" << x.m_name_list << "\n";
128 o << "NbCall=" << x.m_nb_call_list << "\n";
129 o << "NbChild=" << x.m_nb_child << "\n";
130 o << "Time=" << x.m_time_list << "\n";
131 return o;
132 }
133
134 public:
135
136 void clear()
137 {
138 m_nb_iteration_loop = 0;
139 m_name_list.clear();
140 m_nb_child.clear();
141 m_nb_call_list.clear();
142 m_time_list.clear();
143 }
144 };
145
146 public:
147
148 Action(Action* parent, const String& name)
149 : m_parent(parent)
150 , m_name(name)
151 , m_nb_called(0)
152 {}
153 ~Action();
154
155 public:
156
158 Action* subAction(const String& name);
159 const String& name() const { return m_name; }
160 Action* parent() const { return m_parent; }
161 Int64 nbCalled() const { return m_nb_called; }
162 Action* findOrCreateSubAction(const String& name);
163 void addPhaseValue(const PhaseValue& new_pv);
164 void addNbCalled() { ++m_nb_called; }
165 Action* findSubActionRecursive(const String& action_name) const;
166 void save(AllActionsInfo& save_info) const;
167 void merge(AllActionsInfo& save_info, Integer* index);
168 void dumpJSON(JSONWriter& writer, eTimeType tt);
169 void computeCumulativeTimes();
170 void dumpCurrentStats(std::ostream& ostr, int level, Real unit);
171 void reset();
172
173 private:
174
175 Action* m_parent;
176 String m_name;
177 Int64 m_nb_called;
178 private:
179
180 void _addSubAction(Action* sub) { m_sub_actions.add(sub); }
181
182 public:
183
184 ActionList m_sub_actions;
185 PhaseValue m_phases[NB_TIME_PHASE];
186 /*
187 * This value is calculated by computeCumulativeTimes() and should
188 * not be preserved.
189 */
190 TimeValue m_total_time;
191};
192
193/*---------------------------------------------------------------------------*/
194/*---------------------------------------------------------------------------*/
195
199class TimeStats::ActionSeries
200{
201 using AllActionsInfo = TimeStats::Action::AllActionsInfo;
202
203 public:
204
205 ActionSeries()
206 : m_main_action(nullptr, "Main")
207 {
208 }
210 ActionSeries(const ActionSeries& s1, const ActionSeries& s2)
211 : m_main_action(nullptr, "Main")
212 {
213 Action::AllActionsInfo action_info;
214 s1.save(action_info);
215 this->merge(action_info);
216 s2.save(action_info);
217 this->merge(action_info);
218 }
219 ~ActionSeries()
220 {
221 }
222
223 public:
224
225 Action* mainAction() { return &m_main_action; }
226 Int64 nbIterationLoop() const { return m_nb_iteration_loop; }
227 void save(AllActionsInfo& all_actions_info) const
228 {
229 all_actions_info.clear();
230 m_main_action.save(all_actions_info);
231 all_actions_info.m_nb_iteration_loop = m_nb_iteration_loop;
232 }
233 void merge(AllActionsInfo& all_actions_info)
234 {
235 m_nb_iteration_loop += all_actions_info.m_nb_iteration_loop;
236 Integer index = 0;
237 m_main_action.merge(all_actions_info, &index);
238 m_main_action.computeCumulativeTimes();
239 }
240 void dumpStats(std::ostream& ostr, bool is_verbose, Real nb, const String& name,
241 bool use_elapsed_time, const String& message);
242
243 public:
244
245 Action m_main_action;
246 Int64 m_nb_iteration_loop = 0;
247
248 private:
249
250 void _dumpStats(std::ostream& ostr, Action& action, eTimeType tt, int level, int max_level, Real nb);
251 void _dumpAllPhases(std::ostream& ostr, Action& action, eTimeType tt, int tc, Real nb);
252 void _dumpCurrentStats(std::ostream& ostr, Action& action, int level, Real unit);
253};
254
255/*---------------------------------------------------------------------------*/
256/*---------------------------------------------------------------------------*/
257
258/*---------------------------------------------------------------------------*/
259/*---------------------------------------------------------------------------*/
260
261TimeStats::
262TimeStats(ITimerMng* timer_mng, ITraceMng* trace_mng, const String& name)
263: TraceAccessor(trace_mng)
264, m_timer_mng(timer_mng)
265, m_virtual_timer(nullptr)
266, m_real_timer(nullptr)
267, m_is_gathering(false)
268, m_current_action_series(new ActionSeries())
269, m_previous_action_series(new ActionSeries())
270, m_main_action(m_current_action_series->mainAction())
271, m_current_action(m_main_action)
272, m_need_compute_elapsed_time(true)
273, m_full_stats(false)
274, m_name(name)
275, m_metric_collector(new MetricCollector(this))
276{
277 m_phases_type.push(TP_Computation);
278 if (platform::getEnvironmentVariable("ARCANE_FULLSTATS") == "TRUE")
279 m_full_stats = true;
280}
281
282/*---------------------------------------------------------------------------*/
283/*---------------------------------------------------------------------------*/
284
285TimeStats::
286~TimeStats()
287{
288 delete m_metric_collector;
289 if (m_is_gathering)
290 arcaneCallFunctionAndCatchException([&]() { endGatherStats(); });
291 delete m_virtual_timer;
292 delete m_real_timer;
293 delete m_previous_action_series;
294 delete m_current_action_series;
295}
296
297/*---------------------------------------------------------------------------*/
298/*---------------------------------------------------------------------------*/
299
300void TimeStats::
301beginGatherStats()
302{
303 if (m_is_gathering)
304 ARCANE_FATAL("Already gathering");
305
306 if (!m_virtual_timer)
307 m_virtual_timer = new Timer(m_timer_mng, "SubDomainVirtual", Timer::TimerVirtual);
308 if (!m_real_timer)
309 m_real_timer = new Timer(m_timer_mng, "SubDomainReal", Timer::TimerReal);
310
311 m_is_gathering = true;
312
313 m_current_phase = PhaseValue();
314
315 m_virtual_timer->start();
316 m_real_timer->start();
317 m_full_stats_str << "<? xml version='1.0'?>\n";
318 m_full_stats_str << "<stats>\n";
319}
320
321/*---------------------------------------------------------------------------*/
322/*---------------------------------------------------------------------------*/
323
324void TimeStats::
325endGatherStats()
326{
327 m_virtual_timer->stop();
328 m_real_timer->stop();
329
330 m_is_gathering = false;
331 if (m_full_stats) {
332 m_full_stats_str << "</stats>\n";
333 StringBuilder sb = "stats-";
334 sb += m_name;
335 sb += ".xml";
336 String s(sb);
337 std::ofstream ofile(s.localstr());
338 ofile << m_full_stats_str.str();
339 }
340}
341
342/*---------------------------------------------------------------------------*/
343/*---------------------------------------------------------------------------*/
344
345TimeStats::Action* TimeStats::Action::
346findOrCreateSubAction(const String& name)
347{
348 Action* sa = subAction(name);
349 if (!sa) {
350 sa = new Action(this, name);
351 _addSubAction(sa);
352 }
353 return sa;
354}
355
356/*---------------------------------------------------------------------------*/
357/*---------------------------------------------------------------------------*/
358
359void TimeStats::
360beginAction(const String& action_name)
361{
362 _checkGathering();
363 Action* current_action = _currentAction();
364 current_action->addPhaseValue(_currentPhaseValue());
365 Action* sa = current_action->findOrCreateSubAction(action_name);
366 if (m_full_stats)
367 m_full_stats_str << "<action name='" << sa->name() << "'"
368 << ">\n";
369 m_current_action = sa;
370}
371
372/*---------------------------------------------------------------------------*/
373/*---------------------------------------------------------------------------*/
374
375void TimeStats::
376endAction(const String& action_name, bool print_time)
377{
378 ARCANE_UNUSED(action_name);
379 _checkGathering();
380 m_need_compute_elapsed_time = true;
381 TimeStats::PhaseValue pv = _currentPhaseValue();
382 m_current_action->addPhaseValue(pv);
383 m_current_action->addNbCalled();
384 if (print_time) {
385 elapsedTime(TP_Computation, m_current_action->name());
386 elapsedTime(TP_Communication, m_current_action->name());
387 }
388 if (m_full_stats)
389 m_full_stats_str << "</action><!-- " << m_current_action->name() << " -->\n";
390 m_current_action = m_current_action->parent();
391}
392
393/*---------------------------------------------------------------------------*/
394/*---------------------------------------------------------------------------*/
395
396void TimeStats::
397beginPhase(eTimePhase phase_type)
398{
399 _checkGathering();
400 TimeStats::PhaseValue pv = _currentPhaseValue();
401 m_current_action->addPhaseValue(pv);
402 m_current_phase.m_type = phase_type;
403 m_phases_type.push(pv.m_type);
404}
405
406/*---------------------------------------------------------------------------*/
407/*---------------------------------------------------------------------------*/
408
409void TimeStats::
410endPhase(eTimePhase phase_type)
411{
412 ARCANE_UNUSED(phase_type);
413 _checkGathering();
414 m_need_compute_elapsed_time = true;
415 TimeStats::PhaseValue pv = _currentPhaseValue();
416 m_current_action->addPhaseValue(pv);
417 if (m_phases_type.empty())
418 ARCANE_FATAL("No previous phases");
419 eTimePhase old_phase_type = m_phases_type.top();
420 m_phases_type.pop();
421 m_current_phase.m_type = old_phase_type;
422}
423
424/*---------------------------------------------------------------------------*/
425/*---------------------------------------------------------------------------*/
426
427Real TimeStats::
428elapsedTime(eTimePhase phase)
429{
430 _computeCumulativeTimes();
431 return m_main_action->m_phases[phase].m_time[TT_Real][TC_Cumulative];
432}
433
434/*---------------------------------------------------------------------------*/
435/*---------------------------------------------------------------------------*/
436
437Real TimeStats::
438elapsedTime(eTimePhase phase, const String& action_name)
439{
440 _computeCumulativeTimes();
441 Action* action = m_main_action->findSubActionRecursive(action_name);
442 if (!action)
443 return 0.0;
444 info() << "TimeStat: type=" << phase << " action=" << action_name
445 << " local_Real=" << action->m_phases[phase].m_time[TT_Real][TC_Local]
446 << " total_Real=" << action->m_phases[phase].m_time[TT_Real][TC_Cumulative]
447 << " local_Virt=" << action->m_phases[phase].m_time[TT_Virtual][TC_Local]
448 << " total_Virt=" << action->m_phases[phase].m_time[TT_Virtual][TC_Cumulative];
449 return action->m_phases[phase].m_time[TT_Real][TC_Cumulative];
450}
451
452/*---------------------------------------------------------------------------*/
453/*---------------------------------------------------------------------------*/
454
455TimeStats::Action* TimeStats::Action::
456findSubActionRecursive(const String& action_name) const
457{
458 for (ActionList::Enumerator i(this->m_sub_actions); ++i;) {
459 Action* action = *i;
460 if (action->name() == action_name)
461 return action;
462 Action* find_action = action->findSubActionRecursive(action_name);
463 if (find_action)
464 return find_action;
465 }
466 return nullptr;
467}
468
469/*---------------------------------------------------------------------------*/
470/*---------------------------------------------------------------------------*/
471
472void TimeStats::ActionSeries::
473dumpStats(std::ostream& ostr, bool is_verbose, Real nb, const String& name,
474 bool use_elapsed_time, const String& message)
475{
476 Int64 nb_iteration_loop = this->nbIterationLoop();
477 if (nb_iteration_loop != 0)
478 nb = nb * ((Real)nb_iteration_loop);
479 eTimeType tt = TT_Virtual;
480 if (use_elapsed_time)
481 tt = TT_Real;
482 ostr << "-- Execution statistics " << message
483 << " (divide=" << nb << ", nb_loop=" << nb_iteration_loop << ")";
484 if (tt == TT_Real)
485 ostr << " (clock time)";
486 else if (tt == TT_Virtual)
487 ostr << " (CPU time)";
488 ostr << ":\n";
489 std::ios_base::fmtflags f = ostr.flags(std::ios::right);
490
491 ostr << Trace::Width(50) << " Action "
492 << Trace::Width(11) << " Time "
493 << Trace::Width(11) << " Time "
494 << Trace::Width(8) << "N"
495 << '\n';
496 ostr << Trace::Width(50) << " "
497 << Trace::Width(11) << "Total(s)"
498 << Trace::Width(11) << (String("/") + name + "(us)")
499 << '\n';
500 ostr << '\n';
501 if (is_verbose) {
502 _dumpStats(ostr, m_main_action, tt, 1, 0, nb);
503 }
504 else {
505 // Only displays statistics concerning the times for each module.
506 Action* action = m_main_action.findSubActionRecursive("Loop");
507 if (!action)
508 _dumpStats(ostr, m_main_action, tt, 1, 3, nb);
509 else
510 _dumpStats(ostr, *action, tt, 1, 3, nb);
511 }
512 ostr.flags(f);
513}
514
515/*---------------------------------------------------------------------------*/
516/*---------------------------------------------------------------------------*/
517
518void TimeStats::
519dumpStats(std::ostream& ostr, bool is_verbose, Real nb, const String& name,
520 bool use_elapsed_time)
521{
522 _computeCumulativeTimes();
523 ostr << "Execution statistics (current execution)\n";
524 m_current_action_series->dumpStats(ostr, is_verbose, nb, name, use_elapsed_time, "(current execution)");
525 // Only displays cumulative statistics if there has already been an execution.
526 if (m_previous_action_series->nbIterationLoop() != 0) {
527 ostr << "\nExecution statistics (cumulative)\n";
528 ActionSeries cumul_series(*m_previous_action_series, *m_current_action_series);
529 cumul_series.dumpStats(ostr, is_verbose, nb, name, use_elapsed_time, "(cumulative execution)");
530 }
531}
532
533/*---------------------------------------------------------------------------*/
534/*---------------------------------------------------------------------------*/
535
536void TimeStats::
537dumpCurrentStats(const String& action_name)
538{
539 Action* action = m_main_action->findSubActionRecursive(action_name);
540 if (!action)
541 return;
542 _computeCumulativeTimes();
543 Real unit = 1.e3;
544 OStringStream ostr;
545 action->dumpCurrentStats(ostr(), 1, unit);
546 info() << "-- Execution statistics: Action=" << action->name()
547 << "\n"
548 << ostr.str();
549}
550
551/*---------------------------------------------------------------------------*/
552/*---------------------------------------------------------------------------*/
553
554void TimeStats::
555resetStats(const String& action_name)
556{
557 Action* action = m_main_action->findSubActionRecursive(action_name);
558 if (!action)
559 return;
560 action->reset();
561 m_need_compute_elapsed_time = true;
562}
563
564/*---------------------------------------------------------------------------*/
565/*---------------------------------------------------------------------------*/
566
567namespace
568{
569 void
570 _writeValue(std::ostream& ostr, Real value, Real unit)
571 {
572 ostr.width(12);
573 Real v2 = value * unit;
574 Integer i_unit = Convert::toInteger(unit);
575 if (i_unit == 0)
576 i_unit = 1;
577 Integer i_v2 = Convert::toInteger(v2);
578 ostr << i_v2;
579 }
580
581 /*---------------------------------------------------------------------------*/
582 /*---------------------------------------------------------------------------*/
583
584 void
585 _printIndentedName(std::ostream& ostr, const String& name, int level)
586 {
587 StringBuilder indent_str;
588 StringBuilder after_str;
589 for (int i = 0; i < level; ++i)
590 indent_str.append(" ");
591 ostr << indent_str;
592 ostr << name;
593 int alen = static_cast<int>(name.utf8().size());
594 alen += level;
595 for (int i = 0; i < 50 - alen; ++i)
596 after_str += " ";
597 ostr << after_str;
598 }
599
600 /*---------------------------------------------------------------------------*/
601 /*---------------------------------------------------------------------------*/
602
603 void
604 _printPercentage(std::ostream& ostr, Real value, Real cumulative_value)
605 {
606 Real percent = 1.0;
607 // Normally, you just need to check that cumulative_value is not zero
608 // to perform the division. However, several compilers (icc on ia64,
609 // clang 3.7.0) seem a bit aggressive regarding speculation
610 // (with -O2) and perform the division even if the test is false, which
611 // causes a SIGFPE. To circumvent this, it seems that making
612 // two comparisons works.
613 Real z_cumulative_value = cumulative_value;
614 if (z_cumulative_value != 0.0 && !math::isNearlyZero(z_cumulative_value)) {
615 percent = value / z_cumulative_value;
616 }
617 percent *= 1000.0;
618 Integer n_percent = Convert::toInteger(percent);
619 ostr.width(3);
620 ostr << (n_percent / 10) << '.' << (n_percent % 10);
621 }
622} // namespace
623
624/*---------------------------------------------------------------------------*/
625/*---------------------------------------------------------------------------*/
626
627void TimeStats::Action::
628dumpCurrentStats(std::ostream& ostr, int level, Real unit)
629{
630 Action& action = *this;
631 _printIndentedName(ostr, action.name(), level);
632 _writeValue(ostr, action.m_phases[TP_Computation].m_time[TT_Real][TC_Cumulative], unit);
633 _writeValue(ostr, action.m_phases[TP_Communication].m_time[TT_Real][TC_Cumulative], unit);
634 ostr << '\n';
635 for (ActionList::Enumerator i(action.m_sub_actions); ++i;) {
636 Action* a = *i;
637 a->dumpCurrentStats(ostr, level + 1, unit);
638 }
639}
640
641/*---------------------------------------------------------------------------*/
642/*---------------------------------------------------------------------------*/
643
644void TimeStats::
645_computeCumulativeTimes()
646{
647 if (!m_need_compute_elapsed_time)
648 return;
649 m_main_action->computeCumulativeTimes();
650 m_need_compute_elapsed_time = false;
651}
652
653/*---------------------------------------------------------------------------*/
654/*---------------------------------------------------------------------------*/
655
656void TimeStats::ActionSeries::
657_dumpStats(std::ostream& ostr, Action& action, eTimeType tt, int level, int max_level, Real nb)
658{
659 PhaseValue& pv = action.m_phases[TP_Computation];
660 _printIndentedName(ostr, action.name(), level);
661
662 if (pv.m_time[TT_Real][TC_Cumulative] != 0.0 || pv.m_time[TT_Virtual][TC_Cumulative] != 0.0) {
663 _dumpAllPhases(ostr, action, tt, TC_Cumulative, nb);
664 }
665 ostr << '\n';
666 if (max_level == 0 || level < max_level) {
667 for (ActionList::Enumerator i(action.m_sub_actions); ++i;) {
668 Action* a = *i;
669 _dumpStats(ostr, *a, tt, level + 1, max_level, nb);
670 }
671 }
672}
673
674/*---------------------------------------------------------------------------*/
675/*---------------------------------------------------------------------------*/
676
677void TimeStats::
678_dumpCumulativeTime(std::ostream& ostr, Action& action, eTimePhase tp, eTimeType tt)
679{
680 Real current_time = action.m_phases[tp].m_time[tt][TC_Local];
681 Real cumulative_time = action.m_phases[tp].m_time[tt][TC_Cumulative];
682
683 ostr.width(12);
684 ostr << current_time << ' ';
685 ostr.width(12);
686 ostr << cumulative_time << ' ';
687
688 _printPercentage(ostr, current_time, m_main_action->m_phases[tp].m_time[tt][TC_Cumulative]);
689 _printPercentage(ostr, cumulative_time, m_main_action->m_phases[tp].m_time[tt][TC_Cumulative]);
690 {
691 Action* parent_action = action.parent();
692 Real parent_time = cumulative_time;
693 if (parent_action)
694 parent_time = parent_action->m_phases[tp].m_time[tt][TC_Cumulative];
695 _printPercentage(ostr, cumulative_time, parent_time);
696 }
697}
698
699/*---------------------------------------------------------------------------*/
700/*---------------------------------------------------------------------------*/
701
702void TimeStats::ActionSeries::
703_dumpAllPhases(std::ostream& ostr, Action& action, eTimeType tt, int tc, Real nb)
704{
705 Real all_phase_time = action.m_total_time.m_time[tt][tc];
706
707 // Time spent in the action
708 ostr << Trace::Width(11) << String::fromNumber(all_phase_time, 3);
709
710 // Time spent in the action per \a nb
711 // If nb is 0, use the number of calls
712 {
713 Real ct_by_call = 0;
714 Real nb_called = nb;
715 if (math::isZero(nb_called))
716 nb_called = (Real)action.nbCalled();
717 if (!math::isZero(nb_called)) {
718 Real r = all_phase_time * 1.0e6;
719 Real r_nb_called = static_cast<Real>(nb_called);
720 // Add an epsilon to avoid speculative execution if \a nb_called is 0.
721 ct_by_call = r / (r_nb_called + 1.0e-10);
722 }
723 ostr << Trace::Width(11) << String::fromNumber(ct_by_call, 3);
724 }
725
726 // Number of calls
727 ostr.width(9);
728 ostr << action.nbCalled() << ' ';
729
730 _printPercentage(ostr, all_phase_time, m_main_action.m_total_time.m_time[tt][tc]);
731 ostr << ' ';
732 {
733 Action* parent_action = action.parent();
734 Real parent_time = all_phase_time;
735 if (parent_action)
736 parent_time = parent_action->m_total_time.m_time[tt][tc];
737 _printPercentage(ostr, all_phase_time, parent_time);
738 ostr << ' ';
739 }
740
741 ostr << "[";
742 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase) {
743 _printPercentage(ostr, action.m_phases[phase].m_time[tt][tc], all_phase_time);
744 if ((phase + 1) != NB_TIME_PHASE)
745 ostr << ' ';
746 }
747 ostr << "]";
748}
749
750/*---------------------------------------------------------------------------*/
751/*---------------------------------------------------------------------------*/
752
753void TimeStats::Action::
754computeCumulativeTimes()
755{
756 Action& action = *this;
757 for (Integer tt = 0; tt < NB_TIME_TYPE; ++tt) {
758 action.m_total_time.m_time[tt][TC_Local] = 0.;
759 action.m_total_time.m_time[tt][TC_Cumulative] = 0.;
760 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase) {
761 Real r = action.m_phases[phase].m_time[tt][TC_Local];
762 action.m_phases[phase].m_time[tt][TC_Cumulative] = r;
763 action.m_total_time.m_time[tt][TC_Cumulative] += r;
764 action.m_total_time.m_time[tt][TC_Local] += r;
765 }
766 }
767
768 for (ActionList::Enumerator i(action.m_sub_actions); ++i;) {
769 Action* a = *i;
770 a->computeCumulativeTimes();
771 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase) {
772 for (Integer tt = 0; tt < NB_TIME_TYPE; ++tt) {
773 Real r = a->m_phases[phase].m_time[tt][TC_Cumulative];
774 action.m_phases[phase].m_time[tt][TC_Cumulative] += r;
775 action.m_total_time.m_time[tt][TC_Cumulative] += r;
776 }
777 }
778 }
779}
780
781/*---------------------------------------------------------------------------*/
782/*---------------------------------------------------------------------------*/
783
784TimeStats::Action* TimeStats::
785_currentAction()
786{
787 if (!m_current_action)
788 m_current_action = m_main_action;
789 return m_current_action;
790}
791
792/*---------------------------------------------------------------------------*/
793/*---------------------------------------------------------------------------*/
794
795TimeStats::PhaseValue TimeStats::
796_currentPhaseValue()
797{
798 Real real_time = m_timer_mng->getTime(m_real_timer);
799 Real virtual_time = m_timer_mng->getTime(m_virtual_timer);
800
801 Real diff_real_time = real_time - m_current_phase.m_time[TT_Real][TC_Local];
802 Real diff_virtual_time = virtual_time - m_current_phase.m_time[TT_Virtual][TC_Local];
803 if (diff_real_time < 0.0 || diff_virtual_time < 0.0)
804 info() << "BAD_CURRENT_PHASE_VALUE " << diff_real_time << " " << diff_virtual_time
805 << " phase=" << m_current_phase.m_type;
806 m_current_phase.m_time[TT_Real][TC_Local] = real_time;
807 m_current_phase.m_time[TT_Virtual][TC_Local] = virtual_time;
808 if (m_full_stats)
809 m_full_stats_str << "<time"
810 << " phase='" << m_current_phase.m_type << "'"
811 << " real_time='" << real_time << "'"
812 << "/>\n";
813 return PhaseValue(m_current_phase.m_type, diff_real_time, diff_virtual_time);
814}
815
816/*---------------------------------------------------------------------------*/
817/*---------------------------------------------------------------------------*/
818
819void TimeStats::
820_checkGathering()
821{
822 if (!m_is_gathering)
823 ARCANE_FATAL("TimeStats::beginGatherStats() not called");
824 if (!m_current_action)
825 ARCANE_FATAL("No current action");
826}
827
828/*---------------------------------------------------------------------------*/
829/*---------------------------------------------------------------------------*/
830
831bool TimeStats::
832isGathering() const
833{
834 bool is_gather = m_is_gathering && m_current_action;
835 return is_gather;
836}
837
838/*---------------------------------------------------------------------------*/
839/*---------------------------------------------------------------------------*/
840
846
847/*---------------------------------------------------------------------------*/
848/*---------------------------------------------------------------------------*/
849
850void TimeStats::
851dumpStatsJSON(JSONWriter& writer)
852{
853 _computeCumulativeTimes();
854 writer.write("Version", (Int64)1);
855
856 writer.writeKey("Current");
857 writer.beginObject();
858 m_main_action->dumpJSON(writer, TT_Real);
859 writer.endObject();
860
861 // Displays the cumulative statistics if there has already been an execution.
862 if (m_previous_action_series->nbIterationLoop() != 0) {
863 ActionSeries cumul_series(*m_previous_action_series, *m_current_action_series);
864 writer.writeKey("Cumulative");
865 writer.beginObject();
866 cumul_series.mainAction()->dumpJSON(writer, TT_Real);
867 writer.endObject();
868 }
869}
870
871/*---------------------------------------------------------------------------*/
872/*---------------------------------------------------------------------------*/
873
874void TimeStats::Action::
875dumpJSON(JSONWriter& writer, eTimeType tt)
876{
877 Action& action = *this;
878 writer.writeKey(action.name());
879 writer.beginObject();
880
881 Real values[NB_TIME_PHASE];
882 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
883 values[phase] = action.m_phases[phase].m_time[tt][TC_Local];
884 writer.write("Local", RealArrayView(NB_TIME_PHASE, values));
885 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
886 values[phase] = action.m_phases[phase].m_time[tt][TC_Cumulative];
887 writer.write("Cumulative", RealArrayView(NB_TIME_PHASE, values));
888
889 if (!action.m_sub_actions.empty()) {
890 writer.writeKey("SubActions");
891 writer.beginArray();
892 for (ActionList::Enumerator i(action.m_sub_actions); ++i;) {
893 Action* a = *i;
894 a->dumpJSON(writer, tt);
895 }
896 writer.endArray();
897 }
898
899 writer.endObject();
900}
901
902/*---------------------------------------------------------------------------*/
903/*---------------------------------------------------------------------------*/
904
905/*---------------------------------------------------------------------------*/
906/*---------------------------------------------------------------------------*/
907
908TimeStats::Action::
909~Action()
910{
911 m_sub_actions.each(Deleter());
912}
913
914/*---------------------------------------------------------------------------*/
915/*---------------------------------------------------------------------------*/
916
917TimeStats::Action* TimeStats::Action::
918subAction(const String& name)
919{
920 ActionList::iterator i = m_sub_actions.find_if(NameComparer(name));
921 if (i != m_sub_actions.end())
922 return *i;
923 return nullptr;
924}
925
926/*---------------------------------------------------------------------------*/
927/*---------------------------------------------------------------------------*/
928
929void TimeStats::Action::
930addPhaseValue(const PhaseValue& new_pv)
931{
932 m_phases[new_pv.m_type].add(new_pv);
933}
934
935/*---------------------------------------------------------------------------*/
936/*---------------------------------------------------------------------------*/
937
938void TimeStats::Action::
939save(AllActionsInfo& save_info) const
940{
941 save_info.m_name_list.add(m_name);
942 save_info.m_nb_call_list.add(m_nb_called);
943 save_info.m_nb_child.add(m_sub_actions.count());
944 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
945 for (Integer i = 0; i < NB_TIME_TYPE; ++i)
946 save_info.m_time_list.add(m_phases[phase].m_time[i][TC_Local]);
947 for (Action* s : m_sub_actions)
948 s->save(save_info);
949}
950
951/*---------------------------------------------------------------------------*/
952/*---------------------------------------------------------------------------*/
953
954void TimeStats::Action::
955merge(AllActionsInfo& save_info, Integer* index_ptr)
956{
957 Integer index = *index_ptr;
958 String saved_name = save_info.m_name_list[index];
959 if (saved_name != m_name)
960 ARCANE_FATAL("Bad merge name={0} saved={1}", m_name, saved_name);
961 ++(*index_ptr);
962 Integer nb_child = save_info.m_nb_child[index];
963 m_nb_called += save_info.m_nb_call_list[index];
964 {
965 Integer pos = index * (NB_TIME_PHASE * NB_TIME_TYPE);
966 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
967 for (Integer i = 0; i < NB_TIME_TYPE; ++i) {
968 m_phases[phase].m_time[i][TC_Local] += save_info.m_time_list[pos];
969 ++pos;
970 }
971 }
972 for (Integer i = 0; i < nb_child; ++i) {
973 String next_name = save_info.m_name_list[*index_ptr];
974 Action* a = findOrCreateSubAction(next_name);
975 a->merge(save_info, index_ptr);
976 }
977}
978
979/*---------------------------------------------------------------------------*/
980/*---------------------------------------------------------------------------*/
981
985void TimeStats::Action::
986reset()
987{
988 m_nb_called = 0;
989 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
990 for (Integer i = 0; i < NB_TIME_TYPE; ++i)
991 m_phases[phase].m_time[i][TC_Local] = 0.0;
992
993 for (Action* s : m_sub_actions)
994 s->reset();
995}
996
997/*---------------------------------------------------------------------------*/
998/*---------------------------------------------------------------------------*/
999
1000/*---------------------------------------------------------------------------*/
1001/*---------------------------------------------------------------------------*/
1002
1003ITimeMetricCollector* TimeStats::
1004metricCollector()
1005{
1006 return m_metric_collector;
1007}
1008
1009/*---------------------------------------------------------------------------*/
1010/*---------------------------------------------------------------------------*/
1011
1012void TimeStats::
1013saveTimeValues(Properties* p)
1014{
1015 info(4) << "Saving TimeStats values";
1016 Action::AllActionsInfo action_save_info;
1017 ActionSeries cumulative_series(*m_previous_action_series, *m_current_action_series);
1018 cumulative_series.save(action_save_info);
1019 const bool is_verbose = false;
1020 if (is_verbose) {
1021 info() << "Saved " << action_save_info;
1022 }
1023
1024 p->set("Version", 1);
1025 p->set("NbIterationLoop", action_save_info.m_nb_iteration_loop);
1026 p->set("Names", action_save_info.m_name_list);
1027 p->set("NbCalls", action_save_info.m_nb_call_list);
1028 p->set("NbChildren", action_save_info.m_nb_child);
1029 p->set("TimeList", action_save_info.m_time_list);
1030}
1031
1032/*---------------------------------------------------------------------------*/
1033/*---------------------------------------------------------------------------*/
1034
1035void TimeStats::
1036mergeTimeValues(Properties* p)
1037{
1038 info(4) << "Merging TimeStats values";
1039
1040 Action::AllActionsInfo action_save_info;
1041
1042 Int32 v = p->getInt32WithDefault("Version", 0);
1043 // Does nothing if there is no info in the checkpoint
1044 if (v == 0)
1045 return;
1046 if (v != 1) {
1047 info() << "Warning: can not merge time stats values because checkpoint version is not compatible";
1048 return;
1049 }
1050
1051 action_save_info.m_nb_iteration_loop = p->getInt64("NbIterationLoop");
1052 p->get("Names", action_save_info.m_name_list);
1053 p->get("NbCalls", action_save_info.m_nb_call_list);
1054 p->get("NbChildren", action_save_info.m_nb_child);
1055 p->get("TimeList", action_save_info.m_time_list);
1056
1057 const bool is_verbose = false;
1058 if (is_verbose) {
1059 info() << "MergedSeries=" << action_save_info;
1060 }
1061 m_previous_action_series->merge(action_save_info);
1062}
1063
1064/*---------------------------------------------------------------------------*/
1065/*---------------------------------------------------------------------------*/
1066
1067void TimeStats::
1068notifyNewIterationLoop()
1069{
1070 ++m_current_action_series->m_nb_iteration_loop;
1071}
1072
1073/*---------------------------------------------------------------------------*/
1074/*---------------------------------------------------------------------------*/
1075
1076} // End namespace Arcane
1077
1078/*---------------------------------------------------------------------------*/
1079/*---------------------------------------------------------------------------*/
ARCANE_FATAL
#define ARCANE_FATAL(...)
Macro throwing a FatalErrorException.
Definition ArcaneGlobal.h:745
MathUtils.h
Various mathematical functions.
Arcane::Array::clear
void clear()
Removes the elements from the array.
Definition arccore/src/common/arccore/common/Array.h:411
Arcane::IParallelMng
Interface of the parallelism manager for a subdomain.
Definition IParallelMng.h:53
Arcane::ITimeMetricCollector
Interface managing statistics on execution.
Definition ITimeMetricCollector.h:37
Arcane::ITimeStats
Interface managing execution time statistics.
Definition ITimeStats.h:44
Arcane::ITimerMng
Interface of a timer manager.
Definition ITimerMng.h:50
Arcane::NameComparer
Utility class for comparing an instance's name.
Definition NameComparer.h:42
Arcane::OStringStream
Output stream linked to a String.
Definition OStringStream.h:34
Arcane::Properties
List of properties.
Definition Properties.h:65
Arcane::Properties::set
void set(const String &name, bool value)
Sets a boolean property of name name and value value.
Definition Properties.cc:848
Arcane::StringBuilder
Unicode character string constructor.
Definition arccore/src/base/arccore/base/StringBuilder.h:48
Arcane::String::localstr
const char * localstr() const
Returns the conversion of the instance into UTF-8 encoding.
Definition String.cc:229
Arcane::TimeStats::ActionSeries::ActionSeries
ActionSeries(const ActionSeries &s1, const ActionSeries &s2)
Creates a series that accumulates the times of the two previous series passed as arguments.
Definition TimeStats.cc:210
Arcane::TimeStats::Action::AllActionsInfo
Information to save/reconstruct an action tree.
Definition TimeStats.cc:113
Arcane::TimeStats::Action::m_name
String m_name
Action name.
Definition TimeStats.cc:176
Arcane::TimeStats::Action::m_parent
Action * m_parent
Parent action.
Definition TimeStats.cc:175
Arcane::TimeStats::Action::subAction
Action * subAction(const String &name)
Child action with name name. nullptr if none with this name.
Definition TimeStats.cc:918
Arcane::TimeStats::Action::m_sub_actions
ActionList m_sub_actions
Child actions.
Definition TimeStats.cc:184
Arcane::TimeStats::Action::m_nb_called
Int64 m_nb_called
Number of times the action has been called.
Definition TimeStats.cc:177
Arcane::TimeStats::Action::reset
void reset()
Resets the statistics of the action and its children.
Definition TimeStats.cc:986
Arcane::TimeStats
Statistics on execution times.
Definition TimeStats.h:40
Arcane::TimeStats::elapsedTime
Real elapsedTime(eTimePhase phase) override
Real elapsed time for phase phase.
Definition TimeStats.cc:428
Arcane::TimeStats::dumpStats
void dumpStats(std::ostream &ostr, bool is_verbose, Real nb, const String &name, bool use_elapsed_time) override
Displays execution time statistics.
Definition TimeStats.cc:519
Arcane::TimeStats::endGatherStats
void endGatherStats() override
Stops time collection.
Definition TimeStats.cc:325
Arcane::TimeStats::dumpCurrentStats
void dumpCurrentStats(const String &action) override
Displays statistics for an action.
Definition TimeStats.cc:537
Arcane::TimeStats::m_previous_action_series
ActionSeries * m_previous_action_series
Statistics on previous executions.
Definition TimeStats.h:161
Arcane::TimeStats::isGathering
bool isGathering() const override
Indicates if statistics are active.
Definition TimeStats.cc:832
Arcane::TimeStats::dumpStatsJSON
void dumpStatsJSON(JSONWriter &writer) override
Serializes the temporal statistics into the writer writer.
Definition TimeStats.cc:851
Arcane::TimeStats::metricCollector
ITimeMetricCollector * metricCollector() override
Associated collection interface.
Definition TimeStats.cc:1004
Arcane::TimeStats::notifyNewIterationLoop
void notifyNewIterationLoop() override
Notifies that a new iteration of the calculation loop begins.
Definition TimeStats.cc:1068
Arcane::TimeStats::NB_TIME_TYPE
static const Integer NB_TIME_TYPE
Number of eTimeType values.
Definition TimeStats.h:56
Arcane::TimeStats::beginGatherStats
void beginGatherStats() override
Starts time collection.
Definition TimeStats.cc:301
Arcane::TimeStats::m_current_action_series
ActionSeries * m_current_action_series
Statistics on current execution.
Definition TimeStats.h:159
Arcane::TimeStats::dumpTimeAndMemoryUsage
void dumpTimeAndMemoryUsage(IParallelMng *pm) override
Displays the current date and memory consumption.
Definition TimeStats.cc:842
Arcane::Timer
Management of a timer.
Definition Timer.h:63
Arcane::Timer::TimerReal
@ TimerReal
Timer using real time.
Definition Timer.h:77
Arcane::Timer::TimerVirtual
@ TimerVirtual
Timer using CPU time (obsolete).
Definition Timer.h:75
Arcane::TraceAccessor::info
TraceMessage info() const
Flow for an information message.
Definition TraceAccessor.cc:101
Arcane::TraceAccessor::traceMng
ITraceMng * traceMng() const
Trace manager.
Definition TraceAccessor.cc:72
Arcane::UniqueArray
1D data vector with value semantics (STL style).
Definition arccore/src/common/arccore/common/Array.h:890
Arcane::Convert::toInteger
Integer toInteger(Real r)
Converts a Real to Integer.
Definition arccore/src/base/arccore/base/Convert.h:50
Arcane::MessagePassing::dumpDateAndMemoryUsage
void dumpDateAndMemoryUsage(IParallelMng *pm, ITraceMng *tm)
Writes the date and memory consumed into tm.
Definition Parallel.cc:164
Arcane::math::isZero
bool isZero(const BuiltInProxy< _Type > &a)
Tests if a value is exactly equal to zero.
Definition BuiltInProxy.h:190
Arcane::platform::getEnvironmentVariable
String getEnvironmentVariable(const String &name)
Environment variable named name.
Definition arccore/src/base/arccore/base/PlatformUtils.cc:256
Arcane
-- tab-width: 2; indent-tabs-mode: nil; coding: utf-8-with-signature --
Definition arcane/src/arcane/accelerator/AcceleratorGlobal.h:37
Arcane::Int64
std::int64_t Int64
Signed integer type of 64 bits.
Definition ArccoreGlobal.h:235
Arcane::Integer
Int32 Integer
Type representing an integer.
Definition ArccoreGlobal.h:293
Arcane::arcaneCallFunctionAndCatchException
Integer arcaneCallFunctionAndCatchException(std::function< void()> function)
Calls the function function while catching potential exceptions.
Definition arcane/src/arcane/utils/Exception.cc:54
Arcane::Real
double Real
Type representing a real number.
Definition ArccoreGlobal.h:275
Arcane::eTimePhase
eTimePhase
Phase of a temporal action.
Definition ArcaneTypes.h:411
Arcane::RealArrayView
ArrayView< Real > RealArrayView
C equivalent of a 1D array of reals.
Definition UtilsTypes.h:453
Arcane::Int32
std::int32_t Int32
Signed integer type of 32 bits.
Definition ArccoreGlobal.h:233