Cosa misura esattamente la profilazione C ++ (google cpu perf tools)?

Question

Sto cercando di iniziare a utilizzare Google Perf Tools per profilare alcune applicazioni ad alta intensità di CPU. È un calcolo statistico che scarica ogni passaggio in un file usando `ofstream '. Non sono un esperto di C ++, quindi ho problemi a trovare il collo di bottiglia. Il mio primo passaggio dà risultati:

Total: 857 samples
     357  41.7%  41.7%      357  41.7% _write$UNIX2003
     134  15.6%  57.3%      134  15.6% _exp$fenv_access_off
     109  12.7%  70.0%      276  32.2% scythe::dnorm
     103  12.0%  82.0%      103  12.0% _log$fenv_access_off
      58   6.8%  88.8%       58   6.8% scythe::const_matrix_forward_iterator::operator*
      37   4.3%  93.1%       37   4.3% scythe::matrix_forward_iterator::operator*
      15   1.8%  94.9%       47   5.5% std::transform
      13   1.5%  96.4%      486  56.7% SliceStep::DoStep
      10   1.2%  97.5%       10   1.2% 0x0002726c
       5   0.6%  98.1%        5   0.6% 0x000271c7
       5   0.6%  98.7%        5   0.6% _write$NOCANCEL$UNIX2003

Questo è sorprendente, poiché tutto il calcolo reale si verifica in SliceStep :: DoStep. Il & Quot; _write $ UNIX2003 & Quot; (dove posso scoprire di cosa si tratta?) sembra provenire dalla scrittura del file di output. Ora, ciò che mi confonde è che se commento tutte le outfile << "text" istruzioni ed eseguo pprof, il 95% è in SliceStep::DoStep e `_write $ UNIX2003 'scompare. Tuttavia, la mia applicazione non accelera, misurata dal tempo totale. Il tutto accelera meno dell'1 percento.

Cosa mi sto perdendo?

Aggiunto: L'output di pprof senza le outfile << istruzioni è:

Total: 790 samples
     205  25.9%  25.9%      205  25.9% _exp$fenv_access_off
     170  21.5%  47.5%      170  21.5% _log$fenv_access_off
     162  20.5%  68.0%      437  55.3% scythe::dnorm
      83  10.5%  78.5%       83  10.5% scythe::const_matrix_forward_iterator::operator*
      70   8.9%  87.3%       70   8.9% scythe::matrix_forward_iterator::operator*
      28   3.5%  90.9%       78   9.9% std::transform
      26   3.3%  94.2%       26   3.3% 0x00027262
      12   1.5%  95.7%       12   1.5% _write$NOCANCEL$UNIX2003
      11   1.4%  97.1%      764  96.7% SliceStep::DoStep
       9   1.1%  98.2%        9   1.1% 0x00027253
       6   0.8%  99.0%        6   0.8% 0x000274a6

Sembra quello che mi aspetterei, tranne per il fatto che non vedo alcun aumento visibile delle prestazioni (0,1 secondi su un calcolo di 10 secondi). Il codice è essenzialmente:

ofstream outfile("out.txt");
for loop:
  SliceStep::DoStep()
  outfile << 'result'
outfile.close()

Aggiornamento: I tempismo usando boost :: timer, iniziando da dove inizia il profiler e finendo dove finisce. Non uso discussioni o altro di fantasia.

Answer 1

Dai miei commenti:

I numeri che ottieni dal tuo profiler dicono che il programma dovrebbe essere circa il 40% più veloce senza le dichiarazioni di stampa.

Il runtime, tuttavia, rimane quasi lo stesso.

Ovviamente una delle misure deve essere sbagliata. Ciò significa che devi fare di più e misurazioni migliori.

Per prima cosa suggerisco di iniziare con un altro strumento semplice: il comando time. Questo dovrebbe farti un'idea approssimativa di dove trascorri il tuo tempo.

Se i risultati non sono ancora conclusivi è necessario un testcase migliore:

• Usa un problema più grande
• Fai un riscaldamento prima di misurare. Esegui alcuni loop e avvia successivamente qualsiasi misurazione (nello stesso processo).

---

  

Tiristan: è tutto in utente. Quello che sto facendo è piuttosto semplice, penso ... Il fatto che il file sia aperto tutto il tempo significa qualcosa?

Ciò significa che il profiler è sbagliato.

La stampa di 100000 linee sulla console usando Python produce qualcosa del tipo:

for i in xrange(100000):
    print i

Per console:

time python print.py
[...]
real    0m2.370s
user    0m0.156s
sys     0m0.232s

Versus:

time python test.py > /dev/null

real    0m0.133s
user    0m0.116s
sys     0m0.008s

Il mio punto è: Le tue misurazioni interne e indicano che non guadagni nulla disabilitando l'output. Google Perf Tools dice che dovresti. Chi ha torto?

Answer 2

_write $ UNIX2003 si riferisce probabilmente alla write chiamata di sistema POSIX, che emette sul terminale. L'I / O è molto lento rispetto a quasi ogni altra cosa, quindi ha senso che il tuo programma passi molto tempo lì se stai scrivendo un bel po 'di output.

Non sono sicuro del motivo per cui il tuo programma non acceleri quando rimuovi l'output, ma non riesco davvero a indovinare solo le informazioni che hai fornito. Sarebbe bello vedere parte del codice, o anche l'output di perftools quando viene rimossa l'istruzione cout.

Answer 3

Google perftools raccoglie campioni dello stack di chiamate, quindi ciò di cui hai bisogno è ottenere visibilità su quelli.

Secondo il documento, è possibile visualizzare il grafico della chiamata in base alla dichiarazione o alla granularità dell'indirizzo. Questo dovrebbe dirti ciò che devi sapere.