Newsgroup: it.comp.lang.c++
Titolo: Profiling

Chiedo scusa se la cosa e' un po' OT, ma forse piu' che un prodotto 
specifico, mi serve un suggerimento su qualche tecnica.
Supponiamo, semplificando molto, che io abbia qualcosa del genere:
class A {
  public:
   A*sub1,*sub2;
   A(A*sub1,A*sub2):sub1(sub1),sub2(sub2) {}
   virtual void f() {
    ...
    if (sub1) sub1->f()
    ...
    if (sub2) sub2->f()
    ...
   }
};
Supponiamo quindi che io mi crei un albero di oggetti A (o derivati da 
A, magari sovrascrivendo f()): alla radice avro' a1, che fara' 
riferimento a uno o due altri A, che a loro volta faranno riferimento ad 
uno o piu' altri A e cosi' via.
Chiamando a1.f(), in pratica, va a finire che chiamo f() di molti altri 
oggetti.
Se faccio il profiling di tutto cio', trovo (almeno con gprof, che uso 
al momento) il tempo totale di tutte le f() di tutti gli oggetti (poi mi 
si perde nel grafico delle chiamate a causa della notevole ricorsione, 
ma quello e' un altro discorso).
Quello che invece mi servirebbe sono i tempi spesi nelle chiamate f() di 
ogni singola istanza della classe A; in altre parole, quello che ottengo e'
Tot f() 10s.
Invece vorrei:
a1.f() 2s
a1.sub1->f() 1s
a1.sub2->f() 2s
a1.sub2->sub1->f() 3s
...
Idee su come ottenere questi dati?
  Ciao e grazie
	Andrea Venturoli



In passato ho creato una classe Profiler per misurare proprio questo 
genere di cose. L'ho postato tempo fa su clc++, adesso non ce l'ho 
sottomano e dovrei ricercarlo.
La tecnica che ho utilizzato consiste nel creare delle classi che 
vengono istanziate all'interno delle funzioni che vuoi profilare, 
passando una etichetta, una cosa del tipo:
void fun() {
     Profiler p("fun()");
     // codice della funzione da misurare
}
L'oggetto p tiene traccia del tempo di inizio durante la sua creazione e 
del tempo di fine alla sua distruzione (uscendo dal campo di visibilità).
Alla fine dell'esecuzione di tutto il codice che devi profilare c'è una 
chiamata a Profiler::get_report() (o qualcosa del genere, non ricordo) 
che stampa il dettaglio di quante volte una determinata parte di codice 
è stata chiamata e quanto tempo è stato speso al suo interno.
Si tratta a tutti gli effetti di un processo di misura invasivo che ti 
costringe a modificare il codice che vuoi profilare, inoltre tale metodo 
implica l'aggiunta di alcuni cicli - quindi le misure sono lievemente 
"falsate" restituendo valori maggiori rispetto al codice che stai 
effettivamente misurando, ma permette comunque di determinare quale 
delle funzioni sta "mangiando" la maggior parte dei cicli.
In teoria potresti includere tali istanziazioni con delle macro 
condizionali che escludano il codice di profilazione, se intendi 
lasciare tale codice nel sorgente (per questioni di 
debugging/maintenance) ma escluderlo dalla release.
Sempre che ti interessi, fammi sapere se riesci a trovare il thread 
(cercando il mio nome assieme a "profiling" su google dovrebbe 
funzionare). Sono a disposizione per qualsiasi domanda o chiarimento, 
eventualmente servisse.
Purtroppo non sono a conoscenza di nessuno strumento esterno che faccia 
questo stesso lavoro senza modificare il codice da misurare, sorry.
-- 
  FSC - 
http://userscripts.org/scripts/show/59948
 
http://fscode.altervista.org
 - 
http://sardinias.com

 funzionare).
Cavolo, un altro po' e non lo trovavo nemmeno io (al tempo mi firmavo 
solo come "Francesco", me ne ero dimenticato).
Comunque, questo è il link all'ultima versione che avevo postato in quel 
thread:
http://groups.google.com/group/comp.lang.c++/msg/273e059a12460527
Mi sono appena reso conto che dovrai comunque "adattarlo" (come 
utilizzo) alle tue esigenze: in particolare, se vuoi che misuri una 
"sottochiamata" devi fare in modo che gli venga assegnata una etichetta 
appropriata, diversa dalle "chiamate dirette", non basta semplicemente 
passare il nome della funzione come ho fatto nel mio esempio del post 
precedente.
Spero comunque ti sia d'aiuto, buon divertimento :-)


, on 21/07/2010 13:54:46, wrote:

Nuova versione del Profiler che ho linkato nell'altro post, ho aggiunto 
un test case paragonabile al codice che devi profilare, inoltre ho 
aggiunto alcuni commenti, una funzione che restituisce i record più 
importanti e alcuni parametri per limitare il numero di record 
restituiti dai rapporti.
Per ottenere il tipo di output che desideri - ossia vedere il path di 
ogni singola chiamata - credo tu debba per forza aggiungere un campo 
"parent" alle tue classi, creare una stringa con tale path per ogni 
classe e passarlo come etichetta all'oggetto Profiler.
Per curiosità, fammi sapere se hai provato il mio codice e se lo hai 
trovato utile - no, in verità lo chiedo solo per soddisfare il mio ego 
smisurato ;-)
Spassiadi', cia' :-)
// **********************************
// profiler utility, version 3.1
// all files grouped together
// **********************************
// **********************************
// profiler_utils.h
// (double-inclusion checks snipped)
// **********************************
#include <iostream>
#include <string>
#include <vector>
#include <ctime>
namespace profiler_utils {
     class Profiler {
     public:
         Profiler(const std::string& sid)
                 : id(sid),
// start_time must be initialized last (as per decl below)
                 start_time(std::clock()) {}
         ~Profiler();
     private:
         Profiler(const Profiler&);
         const Profiler& operator=(const Profiler&);
         std::string id;
// start_time must be declared last
         std::clock_t start_time;
     };
     struct TimingRec {
         std::string id;
         double avg_time;
         double total_time;
         int calls_count;
         TimingRec() : avg_time(0), total_time(0), calls_count(0) {}
     };
     inline std::ostream&
     operator<<(std::ostream& os, const TimingRec& r) {
         using std::endl;
         os << "         Id: " << 
r.id
 << endl;
         os << "   Avg time: " << r.avg_time << " msecs" << endl;
         os << " Total time: " << r.total_time << " msecs" << endl;
         os << "Calls count: " << r.calls_count << endl;
         return os;
     }
     // reset all profiler statistics
     void reset();
     // get a single record by id
     TimingRec get_record(const std::string&);
     // get most notable records
     // returns a vector because two or more records
     // could score equally at the top of each list
     std::vector<TimingRec> most_called();
     std::vector<TimingRec> most_expensive();
     std::vector<TimingRec> most_timespent();
     // get the report, results are sorted by record id
     // omit the optional value (or pass a number < 1)
     // for unlimited results
     void report(std::ostream&, int = 0);
     std::string report(int = 0);
     // get a report about notable records
     // passing any number < 1 for the optional parameter
     // will still return one record (if there is any)
     void top_report(std::ostream&, int = 3);
     std::string top_report(int = 3);
} // end profiler namespace
// **********************************
// profiler.cpp
// **********************************
//#include "profiler_utils.h"
#include <map>
#include <sstream>
namespace {
     struct timing_record {
         std::clock_t total_time;
         int calls_count;
         timing_record(): total_time(0), calls_count(0) {}
     };
     inline profiler_utils::TimingRec
     makeTimingRec(const std::string& s,
                   const timing_record& r) {
         profiler_utils::TimingRec res;
 
res.id
 = s;
         if (r.calls_count) {
             res.avg_time = 1000.0 * r.total_time / CLOCKS_PER_SEC /
                            r.calls_count;
         } else {
 
res.id
 += " [bad record]";
         }
         res.total_time = 1000.0 * r.total_time / CLOCKS_PER_SEC;
         res.calls_count = r.calls_count;
         return res;
     }
     typedef std::map<std::string, timing_record> timing_map_type;
     typedef timing_map_type::const_iterator t_map_iter;
// main data depot
     timing_map_type t_map;
// stats indices
     std::map<double, std::vector<std::string> > avg_t_map;
     std::map<std::clock_t, std::vector<std::string> > total_t_map;
     std::map<int, std::vector<std::string> > calls_map;
     bool must_rebuild = true;
     void rebuild_indices() {
         if (must_rebuild) {
             avg_t_map.clear();
             total_t_map.clear();
             calls_map.clear();
             for (t_map_iter it = t_map.begin(), end = t_map.end();
                     it != end;
                     ++it) {
                 const std::string& id = it->first;
                 const timing_record& tr = it->second;
                 if (tr.calls_count) {
                     avg_t_map[
                         double(tr.total_time) / tr.calls_count
                     ].push_back(id);
                 }
                 total_t_map[tr.total_time].push_back(id);
                 calls_map[tr.calls_count].push_back(id);
             }
             must_rebuild = false;
         }
     }
// helper function used by:
// most_called(), most_expensive(), most_timespent()
// converts the internal timing_record structs
// to the public TimingRec structs and fills
// the passed vector with them
     void fill_vector(const std::vector<std::string>& ids,
                      std::vector<profiler_utils::TimingRec>* recs) {
         for (size_t i = 0, end = ids.size(); i < end; ++i) {
             t_map_iter it = t_map.find(ids[i]);
             if (it != t_map.end()) {
                 recs->push_back(makeTimingRec(it->first, it->second));
             }
         }
     }
} // end anonymous namespace
profiler_utils::Profiler::~Profiler() {
     std::clock_t ct = std::clock() - start_time;
     timing_record& tr = t_map[id];
     tr.total_time += ct;
     ++tr.calls_count;
     must_rebuild = true;
}
void profiler_utils::report(std::ostream& stream, int max_results) {
     using std::endl;
     stream << "\n---[ profiler report ]---\n" << endl;
     if (t_map.size()) {
         if (max_results > 0) {
             int count = 0;
             for (t_map_iter it = t_map.begin(),
                     end = t_map.end();
                     it != end;
                     ++it) {
                 if (++count > max_results) break;
                 stream << makeTimingRec(it->first, it->second) << endl;
             }
         } else {
             for (t_map_iter it = t_map.begin(),
                     end = t_map.end();
                     it != end;
                     ++it) {
                 stream << makeTimingRec(it->first, it->second) << endl;
             }
         }
     } else {
         stream << "Nothing to report.\n" << endl;
     }
     stream << "---[ end report ]--------" << endl;
}
std::string profiler_utils::report(int max_results) {
     std::ostringstream res;
     report(res, max_results);
     return res.str();
}
void profiler_utils::top_report(std::ostream& stream, int max_results) {
     using std::endl;
     stream << "\n---[ profiler TOP report ]---\n" << endl;
     if (max_results < 1) max_results = 1;
     std::vector<TimingRec> mc = most_called();
     std::vector<TimingRec> me = most_expensive();
     std::vector<TimingRec> mt = most_timespent();
     if (mc.size()) {
         stream << "Most called:" << endl;
         for (int i = 0;
                 i < mc.size() && i <= max_results;
                 ++i) {
             stream << mc[i] << endl;
         }
     }
     if (me.size()) {
         stream << "Most expensive:" << endl;
         for (int i = 0;
                 i < me.size() && i <= max_results;
                 ++i) {
             stream << me[i] << endl;
         }
     }
     if (mt.size()) {
         stream << "Most time spent:" << endl;
         for (int i = 0;
                 i < mt.size() && i <= max_results;
                 ++i) {
             stream << mt[i] << endl;
         }
     }
     stream << "---[ end TOP report ]--------" << endl;
}
std::string profiler_utils::top_report(int max_results) {
     std::ostringstream res;
     top_report(res, max_results);
     return res.str();
}
void profiler_utils::reset() {
     t_map.clear();
     must_rebuild = true;
}
profiler_utils::TimingRec
profiler_utils::get_record(const std::string& id) {
     t_map_iter it = t_map.find(id);
     if (it != t_map.end()) {
         return makeTimingRec(it->first, it->second);
     } else {
         return makeTimingRec("!!! Record ID not found !!!",
                              timing_record());
     }
}
std::vector<profiler_utils::TimingRec>
profiler_utils::most_called() {
     rebuild_indices();
     std::vector<TimingRec> res;
     if (calls_map.size()) {
         fill_vector(calls_map.rbegin()->second, &res);
     }
     return res;
}
std::vector<profiler_utils::TimingRec>
profiler_utils::most_expensive() {
     rebuild_indices();
     std::vector<TimingRec> res;
     if (avg_t_map.size()) {
         fill_vector(avg_t_map.rbegin()->second, &res);
     }
     return res;
}
std::vector<profiler_utils::TimingRec>
profiler_utils::most_timespent() {
     rebuild_indices();
     std::vector<TimingRec> res;
     if (total_t_map.size()) {
         fill_vector(total_t_map.rbegin()->second, &res);
     }
     return res;
}
// **********************************
// main.cpp - recursive test case
// **********************************
//#include "profiler_utils.h"
#include <iostream>
#include <sstream>
#include <cstdlib>
#include <ctime>
using namespace std;
using namespace profiler_utils;
template<class T>
string to_string(const T& t) {
     stringstream ss;
     ss << t;
     return ss.str();
}
int random(int max) {
     if (max > 0) {
         return 1 + rand() % max;
     }
     return 0;
}
const int max_instances = 20;
const string delay_string = ".\b";
const int max_delay = 5;
const int max_calls = 2;
struct RecursiveItem {
     static int instances_count;
     vector<RecursiveItem*> children;
     string id;
     RecursiveItem() : id(to_string(++instances_count)) {
         if(instances_count < max_instances)
             children.push_back(new RecursiveItem);
         if(instances_count < max_instances)
             children.push_back(new RecursiveItem);
     }
     void foo() const {
         Profiler p(id);
         int delay = random(max_delay);
         for (int i = 0; i < delay; ++i) {
             cout << delay_string;
         }
         for (int i = 0; i < children.size(); ++i) {
             int call_count = random(max_calls);
             for (int call = 0; call < call_count; ++call) {
                 children[i]->foo();
             }
         }
     }
};
int RecursiveItem::instances_count = 0;
int main() {
     srand(time(0));
     RecursiveItem item;
     item.foo();
     cout << top_report(3);
}
/*
Example output:
---[ profiler TOP report ]---
Most called:
          Id: 20
    Avg time: 0.279913 msecs
  Total time: 896 msecs
Calls count: 3201
Most expensive:
          Id: 1
    Avg time: 2668 msecs
  Total time: 2668 msecs
Calls count: 1
Most time spent:
          Id: 1
    Avg time: 2668 msecs
  Total time: 2668 msecs
Calls count: 1
          Id: 2
    Avg time: 1334 msecs
  Total time: 2668 msecs
Calls count: 2
          Id: 3
    Avg time: 889.333 msecs
  Total time: 2668 msecs
Calls count: 3
---[ end TOP report ]--------
Process returned 0 (0x0)   execution time : 2.726 s
Press any key to continue.
*/


 smisurato ;-)
Lo provero', ovviamente adattandolo al mio caso; probabilmente non sara' 
a breve, pero'.
Grazie mille.
  bye
	av.


Eh, il problema è proprio che tu vuoi fare la distinzione tra una 
chiamata alla funzione effettuata da una istanza e una chiamata alla 
stessa funzione effettuata da un'altra istanza... non mi sembra facile 
che un profiler "esterno" riesca a fare questa distinzione, ma non sono 
un grande esperto di profiler e quindi non lo posso escludere.
Quello che ti posso consigliare è di chiedere in un gruppo in lingua 
Inglese come comp.lang.c++ o meglio comp.programming, là di sicuro 
troverai maggiore "pubblico" e maggiori possibilità di trovare il tool 
che ti serve.
Non dovresti avere problemi a comunicare in Inglese - mi sembra di aver 
visto uno o due post tuoi, da quelle parti - comunque se sei incasinato 
e non ne hai il tempo provo ad indagare io e riporto i risultati in 
questo thread.
Fammi sapere, buon proseguimento nel frattempo :-)


 Fammi sapere, buon proseguimento nel frattempo :-)
Ok.
  Ciao
	Andrea Venturoli



Perfetto, se ti riesce di trovare un tool adatto a risolvere il problema 
ripassa in questo thread e faccelo sapere - giusto per completezza di 
informazione per chi dovesse incappare in questi articoli in futuro.
Buon proseguimento!
