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