Arcane  v3.14.10.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-2024 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-2024 */
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
25#include "arcane/Timer.h"
26#include "arcane/IParallelMng.h"
27#include "arcane/ITimerMng.h"
28#include "arcane/MathUtils.h"
29#include "arcane/Properties.h"
30
31#include "arcane/impl/TimeStats.h"
32
33#include "arccore/trace/ITimeMetricCollector.h"
34#include "arccore/trace/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 explicit MetricCollector(ITimeStats* ts)
61 : m_time_stats(ts)
62 , m_id(1)
63 {}
64
65 public:
66 TimeMetricAction getAction(const TimeMetricActionBuildInfo& x) override
67 {
68 return { this, x };
69 }
70 TimeMetricId beginAction(const TimeMetricAction& handle) override
71 {
72 auto name = handle.name();
73 if (!name.null())
74 m_time_stats->beginAction(name);
75 int phase = handle.phase();
76 if (phase >= 0)
77 m_time_stats->beginPhase(static_cast<eTimePhase>(phase));
78 return TimeMetricId(handle, ++m_id);
79 }
80 void endAction(const TimeMetricId& metric_id) override
81 {
82 const TimeMetricAction& action = metric_id.action();
83 int phase = action.phase();
84 if (phase >= 0)
85 m_time_stats->endPhase(static_cast<eTimePhase>(phase));
86 auto name = action.name();
87 if (!name.null())
88 m_time_stats->endAction(name, false);
89 }
90
91 private:
92 ITimeStats* m_time_stats;
93 std::atomic<Int64> m_id;
94};
95
96/*---------------------------------------------------------------------------*/
97/*---------------------------------------------------------------------------*/
101class TimeStats::Action
102{
103 public:
107 class AllActionsInfo
108 {
109 public:
110 UniqueArray<String> m_name_list;
111 UniqueArray<Int32> m_nb_child;
112 UniqueArray<Int64> m_nb_call_list;
113 UniqueArray<Real> m_time_list;
114 Int64 m_nb_iteration_loop = 0;
115 public:
116 friend std::ostream& operator<<(std::ostream& o,const AllActionsInfo& x)
117 {
118 o << "NbLoop=" << x.m_nb_iteration_loop << "\n";
119 o << "Name=" << x.m_name_list << "\n";
120 o << "NbCall=" << x.m_nb_call_list << "\n";
121 o << "NbChild=" << x.m_nb_child << "\n";
122 o << "Time=" << x.m_time_list << "\n";
123 return o;
124 }
125 public:
126 void clear()
127 {
128 m_nb_iteration_loop = 0;
129 m_name_list.clear();
130 m_nb_child.clear();
131 m_nb_call_list.clear();
132 m_time_list.clear();
133 }
134 };
135 public:
136 Action(Action* parent,const String& name)
137 : m_parent(parent), m_name(name), m_nb_called(0) {}
138 ~Action();
139 public:
141 Action* subAction(const String& name);
142 const String& name() const { return m_name; }
143 Action* parent() const { return m_parent; }
144 Int64 nbCalled() const { return m_nb_called; }
145 Action* findOrCreateSubAction(const String& name);
146 void addPhaseValue(const PhaseValue& new_pv);
147 void addNbCalled() { ++m_nb_called; }
148 Action* findSubActionRecursive(const String& action_name) const;
149 void save(AllActionsInfo& save_info) const;
150 void merge(AllActionsInfo& save_info,Integer* index);
151 void dumpJSON(JSONWriter& writer,eTimeType tt);
152 void computeCumulativeTimes();
153 void dumpCurrentStats(std::ostream& ostr,int level,Real unit);
154 void reset();
155 private:
156 Action* m_parent;
157 String m_name;
158 Int64 m_nb_called;
159 private:
160 void _addSubAction(Action* sub) { m_sub_actions.add(sub); }
161 public:
162 ActionList m_sub_actions;
163 PhaseValue m_phases[NB_TIME_PHASE];
164 /*
165 * Cette valeur est calculée par computeCumulativeTimes() et ne doit
166 * pas être conservée.
167 */
168 TimeValue m_total_time;
169};
170
171/*---------------------------------------------------------------------------*/
172/*---------------------------------------------------------------------------*/
176class TimeStats::ActionSeries
177{
178 using AllActionsInfo = TimeStats::Action::AllActionsInfo;
179 public:
180 ActionSeries()
181 : m_main_action(nullptr,"Main")
182 {
183 }
185 ActionSeries(const ActionSeries& s1,const ActionSeries& s2)
186 : m_main_action(nullptr,"Main")
187 {
188 Action::AllActionsInfo action_info;
189 s1.save(action_info);
190 this->merge(action_info);
191 s2.save(action_info);
192 this->merge(action_info);
193 }
194 ~ActionSeries()
195 {
196 }
197 public:
198 Action* mainAction() { return &m_main_action; }
199 Int64 nbIterationLoop() const { return m_nb_iteration_loop; }
200 void save(AllActionsInfo& all_actions_info) const
201 {
202 all_actions_info.clear();
203 m_main_action.save(all_actions_info);
204 all_actions_info.m_nb_iteration_loop = m_nb_iteration_loop;
205 }
206 void merge(AllActionsInfo& all_actions_info)
207 {
208 m_nb_iteration_loop += all_actions_info.m_nb_iteration_loop;
209 Integer index = 0;
210 m_main_action.merge(all_actions_info,&index);
211 m_main_action.computeCumulativeTimes();
212 }
213 void dumpStats(std::ostream& ostr,bool is_verbose,Real nb,const String& name,
214 bool use_elapsed_time,const String& message);
215 public:
216
217 Action m_main_action;
218 Int64 m_nb_iteration_loop = 0;
219
220 private:
221 void _dumpStats(std::ostream& ostr,Action& action,eTimeType tt,int level,int max_level,Real nb);
222 void _dumpAllPhases(std::ostream& ostr,Action& action,eTimeType tt,int tc,Real nb);
223 void _dumpCurrentStats(std::ostream& ostr,Action& action,int level,Real unit);
224};
225
226/*---------------------------------------------------------------------------*/
227/*---------------------------------------------------------------------------*/
228
229/*---------------------------------------------------------------------------*/
230/*---------------------------------------------------------------------------*/
231
232TimeStats::
233TimeStats(ITimerMng* timer_mng, ITraceMng* trace_mng, const String& name)
234: TraceAccessor(trace_mng)
235, m_timer_mng(timer_mng)
236, m_virtual_timer(nullptr)
237, m_real_timer(nullptr)
238, m_is_gathering(false)
239, m_current_action_series(new ActionSeries())
240, m_previous_action_series(new ActionSeries())
241, m_main_action(m_current_action_series->mainAction())
242, m_current_action(m_main_action)
243, m_need_compute_elapsed_time(true)
244, m_full_stats(false)
245, m_name(name)
246, m_metric_collector(new MetricCollector(this))
247{
248 m_phases_type.push(TP_Computation);
249 if (platform::getEnvironmentVariable("ARCANE_FULLSTATS") == "TRUE")
250 m_full_stats = true;
251}
252
253/*---------------------------------------------------------------------------*/
254/*---------------------------------------------------------------------------*/
255
256TimeStats::
257~TimeStats()
258{
259 delete m_metric_collector;
260 if (m_is_gathering)
261 arcaneCallFunctionAndCatchException([&]() { endGatherStats(); });
262 delete m_virtual_timer;
263 delete m_real_timer;
264 delete m_previous_action_series;
265 delete m_current_action_series;
266}
267
268/*---------------------------------------------------------------------------*/
269/*---------------------------------------------------------------------------*/
270
271void TimeStats::
272beginGatherStats()
273{
274 if (m_is_gathering)
275 ARCANE_FATAL("Already gathering");
276
277 if (!m_virtual_timer)
278 m_virtual_timer = new Timer(m_timer_mng, "SubDomainVirtual", Timer::TimerVirtual);
279 if (!m_real_timer)
280 m_real_timer = new Timer(m_timer_mng, "SubDomainReal", Timer::TimerReal);
281
282 m_is_gathering = true;
283
284 m_current_phase = PhaseValue();
285
286 m_virtual_timer->start();
287 m_real_timer->start();
288 m_full_stats_str << "<? xml version='1.0'?>\n";
289 m_full_stats_str << "<stats>\n";
290}
291
292/*---------------------------------------------------------------------------*/
293/*---------------------------------------------------------------------------*/
294
295void TimeStats::
296endGatherStats()
297{
298 m_virtual_timer->stop();
299 m_real_timer->stop();
300
301 m_is_gathering = false;
302 if (m_full_stats) {
303 m_full_stats_str << "</stats>\n";
304 StringBuilder sb = "stats-";
305 sb += m_name;
306 sb += ".xml";
307 String s(sb);
308 std::ofstream ofile(s.localstr());
309 ofile << m_full_stats_str.str();
310 }
311}
312
313/*---------------------------------------------------------------------------*/
314/*---------------------------------------------------------------------------*/
315
316TimeStats::Action* TimeStats::Action::
317findOrCreateSubAction(const String& name)
318{
319 Action* sa = subAction(name);
320 if (!sa){
321 sa = new Action(this,name);
322 _addSubAction(sa);
323 }
324 return sa;
325}
326
327/*---------------------------------------------------------------------------*/
328/*---------------------------------------------------------------------------*/
329
330void TimeStats::
331beginAction(const String& action_name)
332{
333 _checkGathering();
334 Action* current_action = _currentAction();
335 current_action->addPhaseValue(_currentPhaseValue());
336 Action* sa = current_action->findOrCreateSubAction(action_name);
337 if (m_full_stats)
338 m_full_stats_str << "<action name='" << sa->name() << "'"
339 << ">\n";
340 m_current_action = sa;
341}
342
343/*---------------------------------------------------------------------------*/
344/*---------------------------------------------------------------------------*/
345
346void TimeStats::
347endAction(const String& action_name,bool print_time)
348{
349 ARCANE_UNUSED(action_name);
350 _checkGathering();
351 m_need_compute_elapsed_time = true;
352 TimeStats::PhaseValue pv = _currentPhaseValue();
353 m_current_action->addPhaseValue(pv);
354 m_current_action->addNbCalled();
355 if (print_time){
356 elapsedTime(TP_Computation,m_current_action->name());
357 elapsedTime(TP_Communication,m_current_action->name());
358 }
359 if (m_full_stats)
360 m_full_stats_str << "</action><!-- " << m_current_action->name() << " -->\n";
361 m_current_action = m_current_action->parent();
362}
363
364/*---------------------------------------------------------------------------*/
365/*---------------------------------------------------------------------------*/
366
367void TimeStats::
368beginPhase(eTimePhase phase_type)
369{
370 _checkGathering();
371 TimeStats::PhaseValue pv = _currentPhaseValue();
372 m_current_action->addPhaseValue(pv);
373 m_current_phase.m_type = phase_type;
374 m_phases_type.push(pv.m_type);
375}
376
377/*---------------------------------------------------------------------------*/
378/*---------------------------------------------------------------------------*/
379
380void TimeStats::
381endPhase(eTimePhase phase_type)
382{
383 ARCANE_UNUSED(phase_type);
384 _checkGathering();
385 m_need_compute_elapsed_time = true;
386 TimeStats::PhaseValue pv = _currentPhaseValue();
387 m_current_action->addPhaseValue(pv);
388 if (m_phases_type.empty())
389 ARCANE_FATAL("No previous phases");
390 eTimePhase old_phase_type = m_phases_type.top();
391 m_phases_type.pop();
392 m_current_phase.m_type = old_phase_type;
393}
394
395/*---------------------------------------------------------------------------*/
396/*---------------------------------------------------------------------------*/
397
398Real TimeStats::
399elapsedTime(eTimePhase phase)
400{
401 _computeCumulativeTimes();
402 return m_main_action->m_phases[phase].m_time[TT_Real][TC_Cumulative];
403}
404
405/*---------------------------------------------------------------------------*/
406/*---------------------------------------------------------------------------*/
407
408Real TimeStats::
409elapsedTime(eTimePhase phase,const String& action_name)
410{
411 _computeCumulativeTimes();
412 Action* action = m_main_action->findSubActionRecursive(action_name);
413 if (!action)
414 return 0.0;
415 info() << "TimeStat: type=" << phase << " action=" << action_name
416 << " local_Real=" << action->m_phases[phase].m_time[TT_Real][TC_Local]
417 << " total_Real=" << action->m_phases[phase].m_time[TT_Real][TC_Cumulative]
418 << " local_Virt=" << action->m_phases[phase].m_time[TT_Virtual][TC_Local]
419 << " total_Virt=" << action->m_phases[phase].m_time[TT_Virtual][TC_Cumulative];
420 return action->m_phases[phase].m_time[TT_Real][TC_Cumulative];
421}
422
423/*---------------------------------------------------------------------------*/
424/*---------------------------------------------------------------------------*/
425
426TimeStats::Action* TimeStats::Action::
427findSubActionRecursive(const String& action_name) const
428{
429 for( ActionList::Enumerator i(this->m_sub_actions); ++i; ){
430 Action* action = *i;
431 if (action->name()==action_name)
432 return action;
433 Action* find_action = action->findSubActionRecursive(action_name);
434 if (find_action)
435 return find_action;
436 }
437 return nullptr;
438}
439
440/*---------------------------------------------------------------------------*/
441/*---------------------------------------------------------------------------*/
442
443void TimeStats::ActionSeries::
444dumpStats(std::ostream& ostr,bool is_verbose,Real nb,const String& name,
445 bool use_elapsed_time,const String& message)
446{
447 Int64 nb_iteration_loop = this->nbIterationLoop();
448 if (nb_iteration_loop!=0)
449 nb = nb * ((Real)nb_iteration_loop);
450 eTimeType tt = TT_Virtual;
451 if (use_elapsed_time)
452 tt = TT_Real;
453 ostr << "-- Execution statistics " << message
454 << " (divide=" << nb << ", nb_loop=" << nb_iteration_loop << ")";
455 if (tt==TT_Real)
456 ostr << " (clock time)";
457 else if (tt==TT_Virtual)
458 ostr << " (CPU time)";
459 ostr << ":\n";
460 std::ios_base::fmtflags f = ostr.flags(std::ios::right);
461
462 ostr << Trace::Width(50) << " Action "
463 << Trace::Width(11) << " Time "
464 << Trace::Width(11) << " Time "
465 << Trace::Width(8) << "N"
466 << '\n';
467 ostr << Trace::Width(50) << " "
468 << Trace::Width(11) << "Total(s)"
469 << Trace::Width(11) << (String("/")+name+"(us)")
470 << '\n';
471 ostr << '\n';
472 if (is_verbose){
473 _dumpStats(ostr,m_main_action,tt,1,0,nb);
474 }
475 else{
476 // Affiche seulement les statistiques concernant les temps
477 // pour chaque module.
478 Action* action = m_main_action.findSubActionRecursive("Loop");
479 if (!action)
480 _dumpStats(ostr,m_main_action,tt,1,3,nb);
481 else
482 _dumpStats(ostr,*action,tt,1,3,nb);
483 }
484 ostr.flags(f);
485}
486
487/*---------------------------------------------------------------------------*/
488/*---------------------------------------------------------------------------*/
489
490void TimeStats::
491dumpStats(std::ostream& ostr,bool is_verbose,Real nb,const String& name,
492 bool use_elapsed_time)
493{
494 _computeCumulativeTimes();
495 ostr << "Execution statistics (current execution)\n";
496 m_current_action_series->dumpStats(ostr,is_verbose,nb,name,use_elapsed_time,"(current execution)");
497 // N'affiche les statistiques cumulatives que s'il y a déjà eu une éxecution.
498 if (m_previous_action_series->nbIterationLoop()!=0){
499 ostr << "\nExecution statistics (cumulative)\n";
500 ActionSeries cumul_series(*m_previous_action_series,*m_current_action_series);
501 cumul_series.dumpStats(ostr,is_verbose,nb,name,use_elapsed_time,"(cumulative execution)");
502 }
503}
504
505/*---------------------------------------------------------------------------*/
506/*---------------------------------------------------------------------------*/
507
508void TimeStats::
509dumpCurrentStats(const String& action_name)
510{
511 Action* action = m_main_action->findSubActionRecursive(action_name);
512 if (!action)
513 return;
514 _computeCumulativeTimes();
515 Real unit = 1.e3;
516 OStringStream ostr;
517 action->dumpCurrentStats(ostr(),1,unit);
518 info() << "-- Execution statistics: Action=" << action->name()
519 << "\n"
520 << ostr.str();
521}
522
523/*---------------------------------------------------------------------------*/
524/*---------------------------------------------------------------------------*/
525
526void TimeStats::
527resetStats(const String& action_name)
528{
529 Action* action = m_main_action->findSubActionRecursive(action_name);
530 if (!action)
531 return;
532 action->reset();
533 m_need_compute_elapsed_time = true;
534}
535
536/*---------------------------------------------------------------------------*/
537/*---------------------------------------------------------------------------*/
538
539namespace
540{
541void
542_writeValue(std::ostream& ostr,Real value,Real unit)
543{
544 ostr.width(12);
545 Real v2 = value * unit;
546 Integer i_unit = Convert::toInteger(unit);
547 if (i_unit==0)
548 i_unit = 1;
549 Integer i_v2 = Convert::toInteger(v2);
550 ostr << i_v2;
551}
552
553/*---------------------------------------------------------------------------*/
554/*---------------------------------------------------------------------------*/
555
556void
557_printIndentedName(std::ostream& ostr,const String& name,int level)
558{
559 StringBuilder indent_str;
560 StringBuilder after_str;
561 for( int i=0; i<level; ++i )
562 indent_str.append(" ");
563 ostr << indent_str;
564 ostr << name;
565 int alen = static_cast<int>(name.utf8().size());
566 alen += level;
567 for( int i=0; i<50-alen; ++i )
568 after_str += " ";
569 ostr << after_str;
570}
571
572/*---------------------------------------------------------------------------*/
573/*---------------------------------------------------------------------------*/
574
575void
576_printPercentage(std::ostream& ostr,Real value,Real cumulative_value)
577{
578 Real percent = 1.0;
579 // Normalement il faut juste vérifier que cumulative_value n'est pas nul
580 // pour faire la division. Cependant, plusieurs compilateurs (icc sur ia64,
581 // clang 3.7.0) semblent un peu agressif au niveau de spéculations
582 // (avec -O2) et font la division même si le test est faux ce qui
583 // provoque un SIGFPE. Pour contourner cela, il semble que faire
584 // deux comparaisons fonctionne.
585 Real z_cumulative_value = cumulative_value;
586 if (z_cumulative_value!=0.0 && !math::isNearlyZero(z_cumulative_value)){
587 percent = value / z_cumulative_value;
588 }
589 percent *= 1000.0;
590 Integer n_percent = Convert::toInteger(percent);
591 ostr.width(3);
592 ostr << (n_percent / 10) << '.' << (n_percent % 10);
593}
594}
595
596/*---------------------------------------------------------------------------*/
597/*---------------------------------------------------------------------------*/
598
599void TimeStats::Action::
600dumpCurrentStats(std::ostream& ostr,int level,Real unit)
601{
602 Action& action = *this;
603 _printIndentedName(ostr,action.name(),level);
604 _writeValue(ostr,action.m_phases[TP_Computation].m_time[TT_Real][TC_Cumulative],unit);
605 _writeValue(ostr,action.m_phases[TP_Communication].m_time[TT_Real][TC_Cumulative],unit);
606 ostr << '\n';
607 for( ActionList::Enumerator i(action.m_sub_actions); ++i; ){
608 Action* a = *i;
609 a->dumpCurrentStats(ostr,level+1,unit);
610 }
611}
612
613/*---------------------------------------------------------------------------*/
614/*---------------------------------------------------------------------------*/
615
616void TimeStats::
617_computeCumulativeTimes()
618{
619 if (!m_need_compute_elapsed_time)
620 return;
621 m_main_action->computeCumulativeTimes();
622 m_need_compute_elapsed_time = false;
623}
624
625/*---------------------------------------------------------------------------*/
626/*---------------------------------------------------------------------------*/
627
628void TimeStats::ActionSeries::
629_dumpStats(std::ostream& ostr,Action& action,eTimeType tt,int level,int max_level,Real nb)
630{
631 PhaseValue& pv = action.m_phases[TP_Computation];
632 _printIndentedName(ostr,action.name(),level);
633
634 if (pv.m_time[TT_Real][TC_Cumulative]!=0.0 || pv.m_time[TT_Virtual][TC_Cumulative]!=0.0){
635 _dumpAllPhases(ostr,action,tt,TC_Cumulative,nb);
636 }
637 ostr << '\n';
638 if (max_level==0 || level<max_level){
639 for( ActionList::Enumerator i(action.m_sub_actions); ++i; ){
640 Action* a = *i;
641 _dumpStats(ostr,*a,tt,level+1,max_level,nb);
642 }
643 }
644}
645
646/*---------------------------------------------------------------------------*/
647/*---------------------------------------------------------------------------*/
648
649void TimeStats::
650_dumpCumulativeTime(std::ostream& ostr,Action& action,eTimePhase tp,eTimeType tt)
651{
652 Real current_time = action.m_phases[tp].m_time[tt][TC_Local];
653 Real cumulative_time = action.m_phases[tp].m_time[tt][TC_Cumulative];
654
655 ostr.width(12);
656 ostr << current_time << ' ';
657 ostr.width(12);
658 ostr << cumulative_time << ' ';
659
660 _printPercentage(ostr,current_time,m_main_action->m_phases[tp].m_time[tt][TC_Cumulative]);
661 _printPercentage(ostr,cumulative_time,m_main_action->m_phases[tp].m_time[tt][TC_Cumulative]);
662 {
663 Action* parent_action = action.parent();
664 Real parent_time = cumulative_time;
665 if (parent_action)
666 parent_time = parent_action->m_phases[tp].m_time[tt][TC_Cumulative];
667 _printPercentage(ostr,cumulative_time,parent_time);
668 }
669}
670
671/*---------------------------------------------------------------------------*/
672/*---------------------------------------------------------------------------*/
673
674void TimeStats::ActionSeries::
675_dumpAllPhases(std::ostream& ostr,Action& action,eTimeType tt,int tc,Real nb)
676{
677 Real all_phase_time = action.m_total_time.m_time[tt][tc];
678
679 // Temps passé dans l'action
680 ostr << Trace::Width(11) << String::fromNumber(all_phase_time,3);
681
682 // Temps passé dans l'action par \a nb
683 // Si nb vaut 0, prend le nombre d'appel
684 {
685 Real ct_by_call = 0;
686 Real nb_called = nb;
687 if (math::isZero(nb_called))
688 nb_called = (Real)action.nbCalled();
689 if (!math::isZero(nb_called)){
690 Real r = all_phase_time * 1.0e6;
691 Real r_nb_called = static_cast<Real>(nb_called);
692 // Ajoute un epsilon pour éviter une exécution spéculative si \a nb_called vaut 0.
693 ct_by_call = r / (r_nb_called + 1.0e-10);
694 }
695 ostr << Trace::Width(11) << String::fromNumber(ct_by_call,3);
696 }
697
698 // Nombre d'appel
699 ostr.width(9);
700 ostr << action.nbCalled() << ' ';
701
702 _printPercentage(ostr,all_phase_time,m_main_action.m_total_time.m_time[tt][tc]);
703 ostr << ' ';
704 {
705 Action* parent_action = action.parent();
706 Real parent_time = all_phase_time;
707 if (parent_action)
708 parent_time = parent_action->m_total_time.m_time[tt][tc];
709 _printPercentage(ostr,all_phase_time,parent_time);
710 ostr << ' ';
711 }
712
713 ostr << "[";
714 for( Integer phase=0; phase<NB_TIME_PHASE; ++phase ){
715 _printPercentage(ostr,action.m_phases[phase].m_time[tt][tc],all_phase_time);
716 if ((phase+1)!=NB_TIME_PHASE)
717 ostr << ' ';
718 }
719 ostr << "]";
720}
721
722/*---------------------------------------------------------------------------*/
723/*---------------------------------------------------------------------------*/
724
725void TimeStats::Action::
726computeCumulativeTimes()
727{
728 Action& action = *this;
729 for( Integer tt=0; tt<NB_TIME_TYPE; ++tt ){
730 action.m_total_time.m_time[tt][TC_Local] = 0.;
731 action.m_total_time.m_time[tt][TC_Cumulative] = 0.;
732 for( Integer phase=0; phase<NB_TIME_PHASE; ++phase ){
733 Real r = action.m_phases[phase].m_time[tt][TC_Local];
734 action.m_phases[phase].m_time[tt][TC_Cumulative] = r;
735 action.m_total_time.m_time[tt][TC_Cumulative] += r;
736 action.m_total_time.m_time[tt][TC_Local] += r;
737 }
738 }
739
740 for( ActionList::Enumerator i(action.m_sub_actions); ++i; ){
741 Action* a = *i;
742 a->computeCumulativeTimes();
743 for( Integer phase=0; phase<NB_TIME_PHASE; ++phase ){
744 for( Integer tt=0; tt<NB_TIME_TYPE; ++tt ){
745 Real r = a->m_phases[phase].m_time[tt][TC_Cumulative];
746 action.m_phases[phase].m_time[tt][TC_Cumulative] += r;
747 action.m_total_time.m_time[tt][TC_Cumulative] += r;
748 }
749 }
750 }
751}
752
753/*---------------------------------------------------------------------------*/
754/*---------------------------------------------------------------------------*/
755
756TimeStats::Action* TimeStats::
757_currentAction()
758{
759 if (!m_current_action)
760 m_current_action = m_main_action;
761 return m_current_action;
762}
763
764/*---------------------------------------------------------------------------*/
765/*---------------------------------------------------------------------------*/
766
767TimeStats::PhaseValue TimeStats::
768_currentPhaseValue()
769{
770 Real real_time = m_timer_mng->getTime(m_real_timer);
771 Real virtual_time = m_timer_mng->getTime(m_virtual_timer);
772
773 Real diff_real_time = real_time - m_current_phase.m_time[TT_Real][TC_Local];
774 Real diff_virtual_time = virtual_time - m_current_phase.m_time[TT_Virtual][TC_Local];
775 if (diff_real_time<0.0 || diff_virtual_time<0.0)
776 info() << "BAD_CURRENT_PHASE_VALUE " << diff_real_time << " " << diff_virtual_time
777 << " phase=" << m_current_phase.m_type;
778 m_current_phase.m_time[TT_Real][TC_Local] = real_time;
779 m_current_phase.m_time[TT_Virtual][TC_Local] = virtual_time;
780 if (m_full_stats)
781 m_full_stats_str << "<time"
782 << " phase='" << m_current_phase.m_type << "'"
783 << " real_time='" << real_time << "'"
784 << "/>\n";
785 return PhaseValue(m_current_phase.m_type,diff_real_time,diff_virtual_time);
786}
787
788/*---------------------------------------------------------------------------*/
789/*---------------------------------------------------------------------------*/
790
791void TimeStats::
792_checkGathering()
793{
794 if (!m_is_gathering)
795 ARCANE_FATAL("TimeStats::beginGatherStats() not called");
796 if (!m_current_action)
797 ARCANE_FATAL("No current action");
798}
799
800/*---------------------------------------------------------------------------*/
801/*---------------------------------------------------------------------------*/
802
803bool TimeStats::
804isGathering() const
805{
806 bool is_gather = m_is_gathering && m_current_action;
807 return is_gather;
808}
809
810/*---------------------------------------------------------------------------*/
811/*---------------------------------------------------------------------------*/
812
818
819/*---------------------------------------------------------------------------*/
820/*---------------------------------------------------------------------------*/
821
822void TimeStats::
823dumpStatsJSON(JSONWriter& writer)
824{
825 _computeCumulativeTimes();
826 writer.write("Version",(Int64)1);
827
828 writer.writeKey("Current");
829 writer.beginObject();
830 m_main_action->dumpJSON(writer,TT_Real);
831 writer.endObject();
832
833 // Affiche les statistiques cumulatives que s'il y a déjà eu une éxecution.
834 if (m_previous_action_series->nbIterationLoop()!=0){
835 ActionSeries cumul_series(*m_previous_action_series,*m_current_action_series);
836 writer.writeKey("Cumulative");
837 writer.beginObject();
838 cumul_series.mainAction()->dumpJSON(writer,TT_Real);
839 writer.endObject();
840 }
841}
842
843/*---------------------------------------------------------------------------*/
844/*---------------------------------------------------------------------------*/
845
846void TimeStats::Action::
847dumpJSON(JSONWriter& writer,eTimeType tt)
848{
849 Action& action = *this;
850 writer.writeKey(action.name());
851 writer.beginObject();
852
853 Real values[NB_TIME_PHASE];
854 for( Integer phase=0; phase<NB_TIME_PHASE; ++phase )
855 values[phase] = action.m_phases[phase].m_time[tt][TC_Local];
856 writer.write("Local",RealArrayView(NB_TIME_PHASE,values));
857 for( Integer phase=0; phase<NB_TIME_PHASE; ++phase )
858 values[phase] = action.m_phases[phase].m_time[tt][TC_Cumulative];
859 writer.write("Cumulative",RealArrayView(NB_TIME_PHASE,values));
860
861 if (!action.m_sub_actions.empty()){
862 writer.writeKey("SubActions");
863 writer.beginArray();
864 for( ActionList::Enumerator i(action.m_sub_actions); ++i; ){
865 Action* a = *i;
866 a->dumpJSON(writer,tt);
867 }
868 writer.endArray();
869 }
870
871 writer.endObject();
872}
873
874/*---------------------------------------------------------------------------*/
875/*---------------------------------------------------------------------------*/
876
877/*---------------------------------------------------------------------------*/
878/*---------------------------------------------------------------------------*/
879
880TimeStats::Action::
881~Action()
882{
883 m_sub_actions.each(Deleter());
884}
885
886/*---------------------------------------------------------------------------*/
887/*---------------------------------------------------------------------------*/
888
889TimeStats::Action* TimeStats::Action::
890subAction(const String& name)
891{
892 ActionList::iterator i = m_sub_actions.find_if(NameComparer(name));
893 if (i!=m_sub_actions.end())
894 return *i;
895 return nullptr;
896}
897
898/*---------------------------------------------------------------------------*/
899/*---------------------------------------------------------------------------*/
900
901void TimeStats::Action::
902addPhaseValue(const PhaseValue& new_pv)
903{
904 m_phases[new_pv.m_type].add(new_pv);
905}
906
907/*---------------------------------------------------------------------------*/
908/*---------------------------------------------------------------------------*/
909
910void TimeStats::Action::
911save(AllActionsInfo& save_info) const
912{
913 save_info.m_name_list.add(m_name);
914 save_info.m_nb_call_list.add(m_nb_called);
915 save_info.m_nb_child.add(m_sub_actions.count());
916 for( Integer phase=0; phase<NB_TIME_PHASE; ++phase )
917 for( Integer i=0; i<NB_TIME_TYPE; ++i )
918 save_info.m_time_list.add(m_phases[phase].m_time[i][TC_Local]);
919 for( Action* s : m_sub_actions )
920 s->save(save_info);
921}
922
923/*---------------------------------------------------------------------------*/
924/*---------------------------------------------------------------------------*/
925
926void TimeStats::Action::
927merge(AllActionsInfo& save_info,Integer* index_ptr)
928{
929 Integer index = *index_ptr;
930 String saved_name = save_info.m_name_list[index];
931 if (saved_name!=m_name)
932 ARCANE_FATAL("Bad merge name={0} saved={1}",m_name,saved_name);
933 ++(*index_ptr);
934 Integer nb_child = save_info.m_nb_child[index];
935 m_nb_called += save_info.m_nb_call_list[index];
936 {
937 Integer pos = index * (NB_TIME_PHASE*NB_TIME_TYPE);
938 for (Integer phase = 0; phase < NB_TIME_PHASE; ++phase)
939 for (Integer i = 0; i < NB_TIME_TYPE; ++i) {
940 m_phases[phase].m_time[i][TC_Local] += save_info.m_time_list[pos];
941 ++pos;
942 }
943 }
944 for( Integer i=0; i<nb_child; ++i ) {
945 String next_name = save_info.m_name_list[*index_ptr];
946 Action* a = findOrCreateSubAction(next_name);
947 a->merge(save_info,index_ptr);
948 }
949}
950
951/*---------------------------------------------------------------------------*/
952/*---------------------------------------------------------------------------*/
956void TimeStats::Action::
957reset()
958{
959 m_nb_called = 0;
960 for( Integer phase=0; phase<NB_TIME_PHASE; ++phase )
961 for (Integer i = 0; i < NB_TIME_TYPE; ++i)
962 m_phases[phase].m_time[i][TC_Local] = 0.0;
963
964 for( Action* s : m_sub_actions )
965 s->reset();
966}
967
968/*---------------------------------------------------------------------------*/
969/*---------------------------------------------------------------------------*/
970
971/*---------------------------------------------------------------------------*/
972/*---------------------------------------------------------------------------*/
973
974ITimeMetricCollector* TimeStats::
975metricCollector()
976{
977 return m_metric_collector;
978}
979
980/*---------------------------------------------------------------------------*/
981/*---------------------------------------------------------------------------*/
982
983void TimeStats::
984saveTimeValues(Properties* p)
985{
986 info(4) << "Saving TimeStats values";
987 Action::AllActionsInfo action_save_info;
988 ActionSeries cumulative_series(*m_previous_action_series,*m_current_action_series);
989 cumulative_series.save(action_save_info);
990 const bool is_verbose = false;
991 if (is_verbose) {
992 info() << "Saved " << action_save_info;
993 }
994
995 p->set("Version",1);
996 p->set("NbIterationLoop",action_save_info.m_nb_iteration_loop);
997 p->set("Names",action_save_info.m_name_list);
998 p->set("NbCalls",action_save_info.m_nb_call_list);
999 p->set("NbChildren",action_save_info.m_nb_child);
1000 p->set("TimeList",action_save_info.m_time_list);
1001}
1002
1003/*---------------------------------------------------------------------------*/
1004/*---------------------------------------------------------------------------*/
1005
1006void TimeStats::
1007mergeTimeValues(Properties* p)
1008{
1009 info(4) << "Merging TimeStats values";
1010
1011 Action::AllActionsInfo action_save_info;
1012
1013 Int32 v = p->getInt32WithDefault("Version",0);
1014 // Ne fait rien si aucune info dans la protection
1015 if (v==0)
1016 return;
1017 if (v!=1){
1018 info() << "Warning: can not merge time stats values because checkpoint version is not compatible";
1019 return;
1020 }
1021
1022 action_save_info.m_nb_iteration_loop = p->getInt64("NbIterationLoop");
1023 p->get("Names",action_save_info.m_name_list);
1024 p->get("NbCalls",action_save_info.m_nb_call_list);
1025 p->get("NbChildren",action_save_info.m_nb_child);
1026 p->get("TimeList",action_save_info.m_time_list);
1027
1028 const bool is_verbose = false;
1029 if (is_verbose) {
1030 info() << "MergedSeries=" << action_save_info;
1031 }
1032 m_previous_action_series->merge(action_save_info);
1033}
1034
1035/*---------------------------------------------------------------------------*/
1036/*---------------------------------------------------------------------------*/
1037
1038void TimeStats::
1039notifyNewIterationLoop()
1040{
1041 ++m_current_action_series->m_nb_iteration_loop;
1042}
1043
1044/*---------------------------------------------------------------------------*/
1045/*---------------------------------------------------------------------------*/
1046
1047} // End namespace Arcane
1048
1049/*---------------------------------------------------------------------------*/
1050/*---------------------------------------------------------------------------*/
ARCANE_FATAL
#define ARCANE_FATAL(...)
Macro envoyant une exception FatalErrorException.
Definition ArcaneGlobal.h:809
Arcane::IParallelMng
Interface du gestionnaire de parallélisme pour un sous-domaine.
Definition IParallelMng.h:52
Arcane::ITimeStats
Interface gérant les statistiques sur les temps d'exécution.
Definition ITimeStats.h:48
Arcane::ITimerMng::getTime
virtual Real getTime(Timer *timer)=0
Temps écoulé depuis le dernier appel à beginTimer().
Arcane::JSONWriter
Ecrivain au format JSON.
Definition JSONWriter.h:33
Arcane::LimaWrapper
Lecteur des fichiers de maillage via la bibliothèque LIMA.
Definition Lima.cc:120
Arcane::List< Action * >::Enumerator
ListEnumeratorT< Action * > Enumerator
Type d'un itérateur constant sur tout le tableau.
Definition List.h:243
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::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:185
Arcane::TimeStats::Action::AllActionsInfo
Informations pour sauver/reconstruire une arborescence d'action.
Definition TimeStats.cc:108
Arcane::TimeStats::Action::m_name
String m_name
Nom de l'action.
Definition TimeStats.cc:157
Arcane::TimeStats::Action::m_parent
Action * m_parent
Action parente.
Definition TimeStats.cc:156
Arcane::TimeStats::Action::subAction
Action * subAction(const String &name)
Action fille de nom name. nullptr si aucune avec ce nom.
Definition TimeStats.cc:890
Arcane::TimeStats::Action::m_sub_actions
ActionList m_sub_actions
Actions filles.
Definition TimeStats.cc:162
Arcane::TimeStats::Action::m_nb_called
Int64 m_nb_called
Nombre de fois que l'action a été appelée.
Definition TimeStats.cc:158
Arcane::TimeStats::Action::reset
void reset()
Remet à zéro les statistiques de l'action et de ces filles.
Definition TimeStats.cc:957
Arcane::TimeStats::elapsedTime
Real elapsedTime(eTimePhase phase) override
Temps réel écoulé pour la phase phase.
Definition TimeStats.cc:399
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:491
Arcane::TimeStats::endGatherStats
void endGatherStats() override
Arrête la collection des temps.
Definition TimeStats.cc:296
Arcane::TimeStats::dumpCurrentStats
void dumpCurrentStats(const String &action) override
Affiche les statistiques d'une action.
Definition TimeStats.cc:509
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:804
Arcane::TimeStats::dumpStatsJSON
void dumpStatsJSON(JSONWriter &writer) override
Sérialise dans l'écrivain writer les statistiques temporelles.
Definition TimeStats.cc:823
Arcane::TimeStats::metricCollector
ITimeMetricCollector * metricCollector() override
Interface de collection associée.
Definition TimeStats.cc:975
Arcane::TimeStats::notifyNewIterationLoop
void notifyNewIterationLoop() override
Notifie qu'on commence une nouvelle itération de la boucle de calcul.
Definition TimeStats.cc:1039
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:272
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:814
Arcane::Timer
Gestion d'un timer.
Definition Timer.h:62
Arcane::Timer::stop
Real stop()
Désactive le timer.
Definition Timer.cc:89
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::Timer::start
void start()
Active le timer.
Definition Timer.cc:72
Arccore::ITimeMetricCollector
Interface gérant les statistiques sur l'exécution.
Definition ITimeMetricCollector.h:35
Arccore::StringBuilder
Constructeur de chaîne de caractère unicode.
Definition arccore/src/base/arccore/base/StringBuilder.h:47
Arccore::String
Chaîne de caractères unicode.
Definition arccore/src/base/arccore/base/String.h:70
Arccore::String::localstr
const char * localstr() const
Retourne la conversion de l'instance dans l'encodage UTF-8.
Definition String.cc:227
Arccore::TraceAccessor::traceMng
ITraceMng * traceMng() const
Gestionnaire de trace.
Definition TraceAccessor.cc:72
Arccore::TraceAccessor::info
TraceMessage info() const
Flot pour un message d'information.
Definition TraceAccessor.cc:101
Arccore::Trace::Width
Formattage du flot en longueur.
Definition arccore/src/trace/arccore/trace/Trace.h:77
Arcane::Convert::toInteger
Integer toInteger(Real r)
Converti un Real en Integer.
Definition Convert.h:53
Arcane::MessagePassing::dumpDateAndMemoryUsage
void dumpDateAndMemoryUsage(IParallelMng *pm, ITraceMng *tm)
Écrit dans tm la date et la mémoire consommée.
Definition Parallel.cc:162
Arcane::math::isZero
bool isZero(const BuiltInProxy< _Type > &a)
Teste si une valeur est exactement égale à zéro.
Definition BuiltInProxy.h:164
Arcane
-*- tab-width: 2; indent-tabs-mode: nil; coding: utf-8-with-signature -*-
Definition AcceleratorGlobal.h:36
Arcane::arcaneCallFunctionAndCatchException
Integer arcaneCallFunctionAndCatchException(std::function< void()> function)
Definition arcane/src/arcane/utils/Exception.cc:90
Arcane::eTimePhase
eTimePhase
Phase d'une action temporelle.
Definition ArcaneTypes.h:290
Arcane::RealArrayView
ArrayView< Real > RealArrayView
Equivalent C d'un tableau à une dimension de réels.
Definition UtilsTypes.h:617
Arccore::Integer
Int32 Integer
Type représentant un entier.
Definition ArccoreGlobal.h:240