Arcane  4.2.1.0
Documentation développeur
Chargement...
Recherche...
Aucune correspondance
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/* Statistiques sur les temps d'exécution. */
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 * Cette valeur est calculée par computeCumulativeTimes() et ne doit
188 * pas être conservée.
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 // Affiche seulement les statistiques concernant les temps
506 // pour chaque module.
507 Action* action = m_main_action.findSubActionRecursive("Loop");
508 if (!action)
509 _dumpStats(ostr, m_main_action, tt, 1, 3, nb);
510 else
511 _dumpStats(ostr, *action, tt, 1, 3, nb);
512 }
513 ostr.flags(f);
514}
515
516/*---------------------------------------------------------------------------*/
517/*---------------------------------------------------------------------------*/
518
519void TimeStats::
520dumpStats(std::ostream& ostr, bool is_verbose, Real nb, const String& name,
521 bool use_elapsed_time)
522{
523 _computeCumulativeTimes();
524 ostr << "Execution statistics (current execution)\n";
525 m_current_action_series->dumpStats(ostr, is_verbose, nb, name, use_elapsed_time, "(current execution)");
526 // N'affiche les statistiques cumulatives que s'il y a déjà eu une éxecution.
527 if (m_previous_action_series->nbIterationLoop() != 0) {
528 ostr << "\nExecution statistics (cumulative)\n";
529 ActionSeries cumul_series(*m_previous_action_series, *m_current_action_series);
530 cumul_series.dumpStats(ostr, is_verbose, nb, name, use_elapsed_time, "(cumulative execution)");
531 }
532}
533
534/*---------------------------------------------------------------------------*/
535/*---------------------------------------------------------------------------*/
536
537void TimeStats::
538dumpCurrentStats(const String& action_name)
539{
540 Action* action = m_main_action->findSubActionRecursive(action_name);
541 if (!action)
542 return;
543 _computeCumulativeTimes();
544 Real unit = 1.e3;
545 OStringStream ostr;
546 action->dumpCurrentStats(ostr(), 1, unit);
547 info() << "-- Execution statistics: Action=" << action->name()
548 << "\n"
549 << ostr.str();
550}
551
552/*---------------------------------------------------------------------------*/
553/*---------------------------------------------------------------------------*/
554
555void TimeStats::
556resetStats(const String& action_name)
557{
558 Action* action = m_main_action->findSubActionRecursive(action_name);
559 if (!action)
560 return;
561 action->reset();
562 m_need_compute_elapsed_time = true;
563}
564
565/*---------------------------------------------------------------------------*/
566/*---------------------------------------------------------------------------*/
567
568namespace
569{
570 void
571 _writeValue(std::ostream& ostr, Real value, Real unit)
572 {
573 ostr.width(12);
574 Real v2 = value * unit;
575 Integer i_unit = Convert::toInteger(unit);
576 if (i_unit == 0)
577 i_unit = 1;
578 Integer i_v2 = Convert::toInteger(v2);
579 ostr << i_v2;
580 }
581
582 /*---------------------------------------------------------------------------*/
583 /*---------------------------------------------------------------------------*/
584
585 void
586 _printIndentedName(std::ostream& ostr, const String& name, int level)
587 {
588 StringBuilder indent_str;
589 StringBuilder after_str;
590 for (int i = 0; i < level; ++i)
591 indent_str.append(" ");
592 ostr << indent_str;
593 ostr << name;
594 int alen = static_cast<int>(name.utf8().size());
595 alen += level;
596 for (int i = 0; i < 50 - alen; ++i)
597 after_str += " ";
598 ostr << after_str;
599 }
600
601 /*---------------------------------------------------------------------------*/
602 /*---------------------------------------------------------------------------*/
603
604 void
605 _printPercentage(std::ostream& ostr, Real value, Real cumulative_value)
606 {
607 Real percent = 1.0;
608 // Normalement il faut juste vérifier que cumulative_value n'est pas nul
609 // pour faire la division. Cependant, plusieurs compilateurs (icc sur ia64,
610 // clang 3.7.0) semblent un peu agressif au niveau de spéculations
611 // (avec -O2) et font la division même si le test est faux ce qui
612 // provoque un SIGFPE. Pour contourner cela, il semble que faire
613 // deux comparaisons fonctionne.
614 Real z_cumulative_value = cumulative_value;
615 if (z_cumulative_value != 0.0 && !math::isNearlyZero(z_cumulative_value)) {
616 percent = value / z_cumulative_value;
617 }
618 percent *= 1000.0;
619 Integer n_percent = Convert::toInteger(percent);
620 ostr.width(3);
621 ostr << (n_percent / 10) << '.' << (n_percent % 10);
622 }
623} // namespace
624
625/*---------------------------------------------------------------------------*/
626/*---------------------------------------------------------------------------*/
627
628void TimeStats::Action::
629dumpCurrentStats(std::ostream& ostr, int level, Real unit)
630{
631 Action& action = *this;
632 _printIndentedName(ostr, action.name(), level);
633 _writeValue(ostr, action.m_phases[TP_Computation].m_time[TT_Real][TC_Cumulative], unit);
634 _writeValue(ostr, action.m_phases[TP_Communication].m_time[TT_Real][TC_Cumulative], unit);
635 ostr << '\n';
636 for (ActionList::Enumerator i(action.m_sub_actions); ++i;) {
637 Action* a = *i;
638 a->dumpCurrentStats(ostr, level + 1, unit);
639 }
640}
641
642/*---------------------------------------------------------------------------*/
643/*---------------------------------------------------------------------------*/
644
645void TimeStats::
646_computeCumulativeTimes()
647{
648 if (!m_need_compute_elapsed_time)
649 return;
650 m_main_action->computeCumulativeTimes();
651 m_need_compute_elapsed_time = false;
652}
653
654/*---------------------------------------------------------------------------*/
655/*---------------------------------------------------------------------------*/
656
657void TimeStats::ActionSeries::
658_dumpStats(std::ostream& ostr, Action& action, eTimeType tt, int level, int max_level, Real nb)
659{
660 PhaseValue& pv = action.m_phases[TP_Computation];
661 _printIndentedName(ostr, action.name(), level);
662
663 if (pv.m_time[TT_Real][TC_Cumulative] != 0.0 || pv.m_time[TT_Virtual][TC_Cumulative] != 0.0) {
664 _dumpAllPhases(ostr, action, tt, TC_Cumulative, nb);
665 }
666 ostr << '\n';
667 if (max_level == 0 || level < max_level) {
668 for (ActionList::Enumerator i(action.m_sub_actions); ++i;) {
669 Action* a = *i;
670 _dumpStats(ostr, *a, tt, level + 1, max_level, nb);
671 }
672 }
673}
674
675/*---------------------------------------------------------------------------*/
676/*---------------------------------------------------------------------------*/
677
678void TimeStats::
679_dumpCumulativeTime(std::ostream& ostr, Action& action, eTimePhase tp, eTimeType tt)
680{
681 Real current_time = action.m_phases[tp].m_time[tt][TC_Local];
682 Real cumulative_time = action.m_phases[tp].m_time[tt][TC_Cumulative];
683
684 ostr.width(12);
685 ostr << current_time << ' ';
686 ostr.width(12);
687 ostr << cumulative_time << ' ';
688
689 _printPercentage(ostr, current_time, m_main_action->m_phases[tp].m_time[tt][TC_Cumulative]);
690 _printPercentage(ostr, cumulative_time, m_main_action->m_phases[tp].m_time[tt][TC_Cumulative]);
691 {
692 Action* parent_action = action.parent();
693 Real parent_time = cumulative_time;
694 if (parent_action)
695 parent_time = parent_action->m_phases[tp].m_time[tt][TC_Cumulative];
696 _printPercentage(ostr, cumulative_time, parent_time);
697 }
698}
699
700/*---------------------------------------------------------------------------*/
701/*---------------------------------------------------------------------------*/
702
703void TimeStats::ActionSeries::
704_dumpAllPhases(std::ostream& ostr, Action& action, eTimeType tt, int tc, Real nb)
705{
706 Real all_phase_time = action.m_total_time.m_time[tt][tc];
707
708 // Temps passé dans l'action
709 ostr << Trace::Width(11) << String::fromNumber(all_phase_time, 3);
710
711 // Temps passé dans l'action par \a nb
712 // Si nb vaut 0, prend le nombre d'appel
713 {
714 Real ct_by_call = 0;
715 Real nb_called = nb;
716 if (math::isZero(nb_called))
717 nb_called = (Real)action.nbCalled();
718 if (!math::isZero(nb_called)) {
719 Real r = all_phase_time * 1.0e6;
720 Real r_nb_called = static_cast<Real>(nb_called);
721 // Ajoute un epsilon pour éviter une exécution spéculative si \a nb_called vaut 0.
722 ct_by_call = r / (r_nb_called + 1.0e-10);
723 }
724 ostr << Trace::Width(11) << String::fromNumber(ct_by_call, 3);
725 }
726
727 // Nombre d'appel
728 ostr.width(9);
729 ostr << action.nbCalled() << ' ';
730
731 _printPercentage(ostr, all_phase_time, m_main_action.m_total_time.m_time[tt][tc]);
732 ostr << ' ';
733 {
734 Action* parent_action = action.parent();
735 Real parent_time = all_phase_time;
736 if (parent_action)
737 parent_time = parent_action->m_total_time.m_time[tt][tc];
738 _printPercentage(ostr, all_phase_time, parent_time);
739 ostr << ' ';
740 }
741
742 ostr << "[";
743 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase) {
744 _printPercentage(ostr, action.m_phases[phase].m_time[tt][tc], all_phase_time);
745 if ((phase + 1) != NB_TIME_PHASE)
746 ostr << ' ';
747 }
748 ostr << "]";
749}
750
751/*---------------------------------------------------------------------------*/
752/*---------------------------------------------------------------------------*/
753
754void TimeStats::Action::
755computeCumulativeTimes()
756{
757 Action& action = *this;
758 for (Integer tt = 0; tt < NB_TIME_TYPE; ++tt) {
759 action.m_total_time.m_time[tt][TC_Local] = 0.;
760 action.m_total_time.m_time[tt][TC_Cumulative] = 0.;
761 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase) {
762 Real r = action.m_phases[phase].m_time[tt][TC_Local];
763 action.m_phases[phase].m_time[tt][TC_Cumulative] = r;
764 action.m_total_time.m_time[tt][TC_Cumulative] += r;
765 action.m_total_time.m_time[tt][TC_Local] += r;
766 }
767 }
768
769 for (ActionList::Enumerator i(action.m_sub_actions); ++i;) {
770 Action* a = *i;
771 a->computeCumulativeTimes();
772 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase) {
773 for (Integer tt = 0; tt < NB_TIME_TYPE; ++tt) {
774 Real r = a->m_phases[phase].m_time[tt][TC_Cumulative];
775 action.m_phases[phase].m_time[tt][TC_Cumulative] += r;
776 action.m_total_time.m_time[tt][TC_Cumulative] += r;
777 }
778 }
779 }
780}
781
782/*---------------------------------------------------------------------------*/
783/*---------------------------------------------------------------------------*/
784
785TimeStats::Action* TimeStats::
786_currentAction()
787{
788 if (!m_current_action)
789 m_current_action = m_main_action;
790 return m_current_action;
791}
792
793/*---------------------------------------------------------------------------*/
794/*---------------------------------------------------------------------------*/
795
796TimeStats::PhaseValue TimeStats::
797_currentPhaseValue()
798{
799 Real real_time = m_timer_mng->getTime(m_real_timer);
800 Real virtual_time = m_timer_mng->getTime(m_virtual_timer);
801
802 Real diff_real_time = real_time - m_current_phase.m_time[TT_Real][TC_Local];
803 Real diff_virtual_time = virtual_time - m_current_phase.m_time[TT_Virtual][TC_Local];
804 if (diff_real_time < 0.0 || diff_virtual_time < 0.0)
805 info() << "BAD_CURRENT_PHASE_VALUE " << diff_real_time << " " << diff_virtual_time
806 << " phase=" << m_current_phase.m_type;
807 m_current_phase.m_time[TT_Real][TC_Local] = real_time;
808 m_current_phase.m_time[TT_Virtual][TC_Local] = virtual_time;
809 if (m_full_stats)
810 m_full_stats_str << "<time"
811 << " phase='" << m_current_phase.m_type << "'"
812 << " real_time='" << real_time << "'"
813 << "/>\n";
814 return PhaseValue(m_current_phase.m_type, diff_real_time, diff_virtual_time);
815}
816
817/*---------------------------------------------------------------------------*/
818/*---------------------------------------------------------------------------*/
819
820void TimeStats::
821_checkGathering()
822{
823 if (!m_is_gathering)
824 ARCANE_FATAL("TimeStats::beginGatherStats() not called");
825 if (!m_current_action)
826 ARCANE_FATAL("No current action");
827}
828
829/*---------------------------------------------------------------------------*/
830/*---------------------------------------------------------------------------*/
831
832bool TimeStats::
833isGathering() const
834{
835 bool is_gather = m_is_gathering && m_current_action;
836 return is_gather;
837}
838
839/*---------------------------------------------------------------------------*/
840/*---------------------------------------------------------------------------*/
841
847
848/*---------------------------------------------------------------------------*/
849/*---------------------------------------------------------------------------*/
850
851void TimeStats::
852dumpStatsJSON(JSONWriter& writer)
853{
854 _computeCumulativeTimes();
855 writer.write("Version", (Int64)1);
856
857 writer.writeKey("Current");
858 writer.beginObject();
859 m_main_action->dumpJSON(writer, TT_Real);
860 writer.endObject();
861
862 // Affiche les statistiques cumulatives que s'il y a déjà eu une éxecution.
863 if (m_previous_action_series->nbIterationLoop() != 0) {
864 ActionSeries cumul_series(*m_previous_action_series, *m_current_action_series);
865 writer.writeKey("Cumulative");
866 writer.beginObject();
867 cumul_series.mainAction()->dumpJSON(writer, TT_Real);
868 writer.endObject();
869 }
870}
871
872/*---------------------------------------------------------------------------*/
873/*---------------------------------------------------------------------------*/
874
875void TimeStats::Action::
876dumpJSON(JSONWriter& writer, eTimeType tt)
877{
878 Action& action = *this;
879 writer.writeKey(action.name());
880 writer.beginObject();
881
882 Real values[NB_TIME_PHASE];
883 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
884 values[phase] = action.m_phases[phase].m_time[tt][TC_Local];
885 writer.write("Local", RealArrayView(NB_TIME_PHASE, values));
886 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
887 values[phase] = action.m_phases[phase].m_time[tt][TC_Cumulative];
888 writer.write("Cumulative", RealArrayView(NB_TIME_PHASE, values));
889
890 if (!action.m_sub_actions.empty()) {
891 writer.writeKey("SubActions");
892 writer.beginArray();
893 for (ActionList::Enumerator i(action.m_sub_actions); ++i;) {
894 Action* a = *i;
895 a->dumpJSON(writer, tt);
896 }
897 writer.endArray();
898 }
899
900 writer.endObject();
901}
902
903/*---------------------------------------------------------------------------*/
904/*---------------------------------------------------------------------------*/
905
906/*---------------------------------------------------------------------------*/
907/*---------------------------------------------------------------------------*/
908
909TimeStats::Action::
910~Action()
911{
912 m_sub_actions.each(Deleter());
913}
914
915/*---------------------------------------------------------------------------*/
916/*---------------------------------------------------------------------------*/
917
918TimeStats::Action* TimeStats::Action::
919subAction(const String& name)
920{
921 ActionList::iterator i = m_sub_actions.find_if(NameComparer(name));
922 if (i != m_sub_actions.end())
923 return *i;
924 return nullptr;
925}
926
927/*---------------------------------------------------------------------------*/
928/*---------------------------------------------------------------------------*/
929
930void TimeStats::Action::
931addPhaseValue(const PhaseValue& new_pv)
932{
933 m_phases[new_pv.m_type].add(new_pv);
934}
935
936/*---------------------------------------------------------------------------*/
937/*---------------------------------------------------------------------------*/
938
939void TimeStats::Action::
940save(AllActionsInfo& save_info) const
941{
942 save_info.m_name_list.add(m_name);
943 save_info.m_nb_call_list.add(m_nb_called);
944 save_info.m_nb_child.add(m_sub_actions.count());
945 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
946 for (Integer i = 0; i < NB_TIME_TYPE; ++i)
947 save_info.m_time_list.add(m_phases[phase].m_time[i][TC_Local]);
948 for (Action* s : m_sub_actions)
949 s->save(save_info);
950}
951
952/*---------------------------------------------------------------------------*/
953/*---------------------------------------------------------------------------*/
954
955void TimeStats::Action::
956merge(AllActionsInfo& save_info, Integer* index_ptr)
957{
958 Integer index = *index_ptr;
959 String saved_name = save_info.m_name_list[index];
960 if (saved_name != m_name)
961 ARCANE_FATAL("Bad merge name={0} saved={1}", m_name, saved_name);
962 ++(*index_ptr);
963 Integer nb_child = save_info.m_nb_child[index];
964 m_nb_called += save_info.m_nb_call_list[index];
965 {
966 Integer pos = index * (NB_TIME_PHASE * NB_TIME_TYPE);
967 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
968 for (Integer i = 0; i < NB_TIME_TYPE; ++i) {
969 m_phases[phase].m_time[i][TC_Local] += save_info.m_time_list[pos];
970 ++pos;
971 }
972 }
973 for (Integer i = 0; i < nb_child; ++i) {
974 String next_name = save_info.m_name_list[*index_ptr];
975 Action* a = findOrCreateSubAction(next_name);
976 a->merge(save_info, index_ptr);
977 }
978}
979
980/*---------------------------------------------------------------------------*/
981/*---------------------------------------------------------------------------*/
982
986void TimeStats::Action::
987reset()
988{
989 m_nb_called = 0;
990 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
991 for (Integer i = 0; i < NB_TIME_TYPE; ++i)
992 m_phases[phase].m_time[i][TC_Local] = 0.0;
993
994 for (Action* s : m_sub_actions)
995 s->reset();
996}
997
998/*---------------------------------------------------------------------------*/
999/*---------------------------------------------------------------------------*/
1000
1001/*---------------------------------------------------------------------------*/
1002/*---------------------------------------------------------------------------*/
1003
1004ITimeMetricCollector* TimeStats::
1005metricCollector()
1006{
1007 return m_metric_collector;
1008}
1009
1010/*---------------------------------------------------------------------------*/
1011/*---------------------------------------------------------------------------*/
1012
1013void TimeStats::
1014saveTimeValues(Properties* p)
1015{
1016 info(4) << "Sauvegarde des valeurs TimeStats";
1017 Action::AllActionsInfo action_save_info;
1018 ActionSeries cumulative_series(*m_previous_action_series, *m_current_action_series);
1019 cumulative_series.save(action_save_info);
1020 const bool is_verbose = false;
1021 if (is_verbose) {
1022 info() << "Sauvegardé " << action_save_info;
1023 }
1024
1025 p->set("Version", 1);
1026 p->set("NbIterationLoop", action_save_info.m_nb_iteration_loop);
1027 p->set("Names", action_save_info.m_name_list);
1028 p->set("NbCalls", action_save_info.m_nb_call_list);
1029 p->set("NbChildren", action_save_info.m_nb_child);
1030 p->set("TimeList", action_save_info.m_time_list);
1031}
1032
1033/*---------------------------------------------------------------------------*/
1034/*---------------------------------------------------------------------------*/
1035
1036void TimeStats::
1037mergeTimeValues(Properties* p)
1038{
1039 info(4) << "Fusion des valeurs TimeStats";
1040
1041 Action::AllActionsInfo action_save_info;
1042
1043 Int32 v = p->getInt32WithDefault("Version", 0);
1044 // Ne fait rien si aucune info dans la protection
1045 if (v == 0)
1046 return;
1047 if (v != 1) {
1048 info() << "Avertissement : impossible de fusionner les valeurs de statistiques de temps car la version du point de contrôle n'est pas compatible";
1049 return;
1050 }
1051
1052 action_save_info.m_nb_iteration_loop = p->getInt64("NbIterationLoop");
1053 p->get("Names", action_save_info.m_name_list);
1054 p->get("NbCalls", action_save_info.m_nb_call_list);
1055 p->get("NbChildren", action_save_info.m_nb_child);
1056 p->get("TimeList", action_save_info.m_time_list);
1057
1058 const bool is_verbose = false;
1059 if (is_verbose) {
1060 info() << "MergedSeries=" << action_save_info;
1061 }
1062 m_previous_action_series->merge(action_save_info);
1063}
1064
1065/*---------------------------------------------------------------------------*/
1066/*---------------------------------------------------------------------------*/
1067
1068void TimeStats::
1069notifyNewIterationLoop()
1070{
1071 ++m_current_action_series->m_nb_iteration_loop;
1072}
1073
1074/*---------------------------------------------------------------------------*/
1075/*---------------------------------------------------------------------------*/
1076
1077} // End namespace Arcane
1078
1079/*---------------------------------------------------------------------------*/
1080/*---------------------------------------------------------------------------*/
ARCANE_FATAL
#define ARCANE_FATAL(...)
Macro envoyant une exception FatalErrorException.
Definition ArcaneGlobal.h:758
MathUtils.h
Fonctions mathématiques diverses.
Arcane::Array::clear
void clear()
Supprime les éléments du tableau.
Definition arccore/src/common/arccore/common/Array.h:410
Arcane::IParallelMng
Interface du gestionnaire de parallélisme pour un sous-domaine.
Definition IParallelMng.h:52
Arcane::ITimeMetricCollector
Interface gérant les statistiques sur l'exécution.
Definition ITimeMetricCollector.h:35
Arcane::ITimeStats
Interface gérant les statistiques sur les temps d'exécution.
Definition ITimeStats.h:43
Arcane::ITimerMng
Interface d'un gestionnaire de timer.
Definition ITimerMng.h:49
Arcane::ITraceMng
Interface du gestionnaire de traces.
Definition arccore/src/trace/arccore/trace/ITraceMng.h:156
Arcane::NameComparer
Classe utilitaire pour comparer le nom d'une instance.
Definition NameComparer.h:40
Arcane::OStringStream
Flot de sortie lié à une String.
Definition OStringStream.h:36
Arcane::Properties
Liste de propriétés.
Definition Properties.h:64
Arcane::Properties::set
void set(const String &name, bool value)
Positionne une propriété de type bool de nom name et de valeur value.
Definition Properties.cc:797
Arcane::StringBuilder
Constructeur de chaîne de caractère unicode.
Definition arccore/src/base/arccore/base/StringBuilder.h:47
Arcane::String
Chaîne de caractères unicode.
Definition arccore/src/base/arccore/base/String.h:70
Arcane::String::localstr
const char * localstr() const
Retourne la conversion de l'instance dans l'encodage UTF-8.
Definition String.cc:228
Arcane::TimeStats::ActionSeries::ActionSeries
ActionSeries(const ActionSeries &s1, const ActionSeries &s2)
Créé une série qui cumule les temps des deux séries passées en argument.
Definition TimeStats.cc:210
Arcane::TimeStats::Action::AllActionsInfo
Informations pour sauver/reconstruire une arborescence d'action.
Definition TimeStats.cc:113
Arcane::TimeStats::Action::m_name
String m_name
Nom de l'action.
Definition TimeStats.cc:176
Arcane::TimeStats::Action::m_parent
Action * m_parent
Action parente.
Definition TimeStats.cc:175
Arcane::TimeStats::Action::subAction
Action * subAction(const String &name)
Action fille de nom name. nullptr si aucune avec ce nom.
Definition TimeStats.cc:919
Arcane::TimeStats::Action::m_sub_actions
ActionList m_sub_actions
Actions filles.
Definition TimeStats.cc:184
Arcane::TimeStats::Action::m_nb_called
Int64 m_nb_called
Nombre de fois que l'action a été appelée.
Definition TimeStats.cc:177
Arcane::TimeStats::Action::reset
void reset()
Remet à zéro les statistiques de l'action et de ces filles.
Definition TimeStats.cc:987
Arcane::TimeStats
Statistiques sur les temps d'exécution.
Definition TimeStats.h:39
Arcane::TimeStats::elapsedTime
Real elapsedTime(eTimePhase phase) override
Temps réel écoulé pour la 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
Affiche les statistiques sur les temps d'exécution.
Definition TimeStats.cc:520
Arcane::TimeStats::endGatherStats
void endGatherStats() override
Arrête la collection des temps.
Definition TimeStats.cc:325
Arcane::TimeStats::dumpCurrentStats
void dumpCurrentStats(const String &action) override
Affiche les statistiques d'une action.
Definition TimeStats.cc:538
Arcane::TimeStats::m_previous_action_series
ActionSeries * m_previous_action_series
Statistiques sur les exécutions précédentes.
Definition TimeStats.h:153
Arcane::TimeStats::isGathering
bool isGathering() const override
Indique si les statistiques sont actives.
Definition TimeStats.cc:833
Arcane::TimeStats::dumpStatsJSON
void dumpStatsJSON(JSONWriter &writer) override
Sérialise dans l'écrivain writer les statistiques temporelles.
Definition TimeStats.cc:852
Arcane::TimeStats::metricCollector
ITimeMetricCollector * metricCollector() override
Interface de collection associée.
Definition TimeStats.cc:1005
Arcane::TimeStats::notifyNewIterationLoop
void notifyNewIterationLoop() override
Notifie qu'on commence une nouvelle itération de la boucle de calcul.
Definition TimeStats.cc:1069
Arcane::TimeStats::NB_TIME_TYPE
static const Integer NB_TIME_TYPE
Nombre de valeurs de eTimeType.
Definition TimeStats.h:55
Arcane::TimeStats::beginGatherStats
void beginGatherStats() override
Démarre la collection des temps.
Definition TimeStats.cc:301
Arcane::TimeStats::m_current_action_series
ActionSeries * m_current_action_series
Statistiques sur l'exécution en cours.
Definition TimeStats.h:151
Arcane::TimeStats::dumpTimeAndMemoryUsage
void dumpTimeAndMemoryUsage(IParallelMng *pm) override
Affiche la date actuelle et la mémoire consommée.
Definition TimeStats.cc:843
Arcane::Timer
Gestion d'un timer.
Definition Timer.h:62
Arcane::Timer::TimerReal
@ TimerReal
Timer utilisant le temps réel.
Definition Timer.h:76
Arcane::Timer::TimerVirtual
@ TimerVirtual
Timer utilisant le temps CPU (obsolète).
Definition Timer.h:74
Arcane::TraceAccessor::info
TraceMessage info() const
Flot pour un message d'information.
Definition TraceAccessor.cc:101
Arcane::TraceAccessor::traceMng
ITraceMng * traceMng() const
Gestionnaire de trace.
Definition TraceAccessor.cc:72
Arcane::TraceMessage::m_type
Trace::eMessageType m_type
Type de message.
Definition arccore/src/trace/arccore/trace/TraceMessage.h:58
Arcane::UniqueArray
Vecteur 1D de données avec sémantique par valeur (style STL).
Definition arccore/src/common/arccore/common/Array.h:888
Arcane::Convert::toInteger
Integer toInteger(Real r)
Convertit un Real en Integer.
Definition arccore/src/base/arccore/base/Convert.h:50
Arcane::MessagePassing::dumpDateAndMemoryUsage
void dumpDateAndMemoryUsage(IParallelMng *pm, ITraceMng *tm)
Écrit dans tm la date et la mémoire consommée.
Definition Parallel.cc:163
Arcane::math::isZero
bool isZero(const BuiltInProxy< _Type > &a)
Teste si une valeur est exactement égale à zéro.
Definition BuiltInProxy.h:164
Arcane::platform::getEnvironmentVariable
String getEnvironmentVariable(const String &name)
Variable d'environnement du nom name.
Definition arccore/src/base/arccore/base/PlatformUtils.cc:258
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
Type entier signé sur 64 bits.
Definition ArccoreGlobal.h:235
Arcane::Integer
Int32 Integer
Type représentant un entier.
Definition ArccoreGlobal.h:293
Arcane::arcaneCallFunctionAndCatchException
Integer arcaneCallFunctionAndCatchException(std::function< void()> function)
Definition arcane/src/arcane/utils/Exception.cc:57
Arcane::Real
double Real
Type représentant un réel.
Definition ArccoreGlobal.h:275
Arcane::eTimePhase
eTimePhase
Phase d'une action temporelle.
Definition ArcaneTypes.h:412
Arcane::RealArrayView
ArrayView< Real > RealArrayView
Equivalent C d'un tableau à une dimension de réels.
Definition UtilsTypes.h:457
Arcane::Int32
std::int32_t Int32
Type entier signé sur 32 bits.
Definition ArccoreGlobal.h:233