|
From: Christoph B. <bar...@or...> - 2006-09-13 08:19:41
|
Hi, with the recent fixes I am able to profile the part of the code that is interessting for me. But there is one problem left. Sometimes after starting instrumentation it switches itself off again. And I have to restart it. Given this I cannot be sure that instrumentation is always done and that I do not forget to switch it on again. Here is a log of a sample session: -bash-3.00$ callgrind_control -i on 19970 PID 19970: program [requesting '+Instrumentation'...] OK. -bash-3.00$ callgrind_control -s 19970 PID 19970: program [requesting 'Status'...] Number of threads: 1 Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw Functions: 1,636 (executed 257,435, contexts 1,636) Basic blocks: 3,894 (executed 4,762,919, call sites 2,233) -bash-3.00$ callgrind_control -s 19970 PID 19970: program [requesting 'Status'...] No information available as instrumentation is switched off. -bash-3.00$ callgrind_control -i on 19970 PID 19970: program [requesting '+Instrumentation'...] OK. -bash-3.00$ callgrind_control -s 19970 PID 19970: program [requesting 'Status'...] Number of threads: 0 Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw Functions: 563 (executed 141,123, contexts 563) Basic blocks: 3,464 (executed 983,886, call sites 2,050) -bash-3.00$ callgrind_control -s 19970 PID 19970: program [requesting 'Status'...] Number of threads: 0 Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw Functions: 1,181 (executed 2,334,797, contexts 1,181) Basic blocks: 8,057 (executed 16,365,930, call sites 4,962) Christoph |
|
From: Josef W. <Jos...@gm...> - 2006-09-13 22:46:44
|
On Wednesday 13 September 2006 10:19, Christoph Bartoschek wrote: > Hi, > > with the recent fixes I am able to profile the part of the code that is > interessting for me. But there is one problem left. > > Sometimes after starting instrumentation it switches itself off again. Wow. No this bug sounds really strange. It would be interesting to see the valgrind output of this process with "-v", as this prints out changes of the instrumentation mode. Do you have VG client requests in your code? Perhaps callgrind does misinterpret one and switches instrumentation off instead (but this really should never happen...). Or another possibility for the bug: your code does a few forks and multiple Valgrind processes are somehow looking for the same command file (callgrind_control generates such command files). This also should never happen as I use the PID in the file name... I wonder because... > -bash-3.00$ callgrind_control -s 19970 > PID 19970: program [requesting 'Status'...] > Number of threads: 1 > Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw > Functions: 1,636 (executed 257,435, contexts 1,636) > Basic blocks: 3,894 (executed 4,762,919, call sites 2,233) and > -bash-3.00$ callgrind_control -s 19970 > PID 19970: program [requesting 'Status'...] > Number of threads: 0 > Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw > Functions: 563 (executed 141,123, contexts 563) > Basic blocks: 3,464 (executed 983,886, call sites 2,050) looks like coming from totally different callgrind runs. For example, I never reset the context or function count - they always increase (or stay the same). A thread count of 0 seems strange, too. Josef |
|
From: Christoph B. <bar...@or...> - 2006-09-14 08:40:55
|
Am Donnerstag, 14. September 2006 00:46 schrieb Josef Weidendorfer: > On Wednesday 13 September 2006 10:19, Christoph Bartoschek wrote: > > Hi, > > > > with the recent fixes I am able to profile the part of the code that is > > interessting for me. But there is one problem left. > > > > Sometimes after starting instrumentation it switches itself off again. > > Wow. No this bug sounds really strange. > > It would be interesting to see the valgrind output of this process > with "-v", as this prints out changes of the instrumentation mode. > > Do you have VG client requests in your code? Perhaps callgrind does > misinterpret one and switches instrumentation off instead (but this > really should never happen...). > > Or another possibility for the bug: your code does a few forks and > multiple Valgrind processes are somehow looking for the same command file > (callgrind_control generates such command files). This also > should never happen as I use the PID in the file name... > > I wonder because... > > > -bash-3.00$ callgrind_control -s 19970 > > PID 19970: program [requesting 'Status'...] > > Number of threads: 1 > > Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw > > Functions: 1,636 (executed 257,435, contexts 1,636) > > Basic blocks: 3,894 (executed 4,762,919, call sites 2,233) > > and > > > -bash-3.00$ callgrind_control -s 19970 > > PID 19970: program [requesting 'Status'...] > > Number of threads: 0 > > Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw > > Functions: 563 (executed 141,123, contexts 563) > > Basic blocks: 3,464 (executed 983,886, call sites 2,050) > > looks like coming from totally different callgrind runs. > For example, I never reset the context or function count - > they always increase (or stay the same). > A thread count of 0 seems strange, too. > Could this explain the behaviour: As I described in another thread, the program I use clones itself after startup but the newly created child does not exec itself to load another binary but continues to run. In this case the PID of the child was 19972 and I see callgrind.out.19970 and callgrind.out.19972 but only one valgrind logfile: vg.log.19970 Greetings Christoph Bartoschek |
|
From: Christoph B. <bar...@or...> - 2006-09-14 09:10:31
|
I've started the program with -v and see that both processes write to the same valgrind log file. I have process 3775 and 3776. Here is a part of the logfile vg.log.3775 with mixed messages where i play with instrumentation: --00:00:10:34.518 3775-- Reading syms from /dfs/data/bartosch/work/bonnfastopt-O.dll (0x31114000) ==00:00:10:34.519 3775== Warning: zero-sized CIE/FDE but not at section end in DWARF2 CFI reading --00:00:11:03.798 3775-- Code check found runtime_resolve: ld-2.3.4.so +0xA660=0x365860A660, length 110 --00:00:11:03.993 3776-- Code check found runtime_resolve: ld-2.3.4.so +0xA660=0x365860A660, length 110 --00:00:11:04.044 3776-- Command: instrumentation switched ON --00:00:11:04.047 3776-- REDIR: 0xFFFFFFFFFF600000 (???) redirected to 0x380275EB (???) --00:00:11:04.611 3775-- Command: instrumentation switched ON --00:00:11:04.698 3775-- REDIR: 0xFFFFFFFFFF600000 (???) redirected to 0x380275EB (???) --00:00:11:08.997 3890-- Symbol match: found runtime_resolve: ld-2.3.4.so +0x365860A660=0x365860A660 --00:00:11:19.333 3775-- REDIR: 0xFFFFFFFFFF600400 (???) redirected to 0x380275F5 (???) --00:00:11:36.143 3775-- Command: instrumentation switched OFF --00:00:11:40.114 3775-- REDIR: 0xFFFFFFFFFF600000 (???) redirected to 0x380275EB (???) --00:00:11:40.652 3775-- REDIR: 0xFFFFFFFFFF600400 (???) redirected to 0x380275F5 (???) --00:00:11:44.967 3775-- Command: instrumentation switched ON --00:00:11:48.041 3775-- REDIR: 0xFFFFFFFFFF600400 (???) redirected to 0x380275F5 (???) --00:00:11:48.586 3775-- REDIR: 0xFFFFFFFFFF600000 (???) redirected to 0x380275EB (???) --00:00:14:22.513 3775-- Command: instrumentation switched OFF --00:00:14:24.158 3775-- REDIR: 0xFFFFFFFFFF600400 (???) redirected to 0x380275F5 (???) --00:00:14:24.226 3775-- REDIR: 0xFFFFFFFFFF600000 (???) redirected to 0x380275EB (???) We see that both process 3776 and 3775 start instrumenting after the first callgrind_control -i on 3775. Then after the callgrind_control -i off 3775 only process 3775 switches off. The following on and off commands are also only executed by process 3775. If one executes callgrind_control -s 3775 long enough one sees two subsequent calls that are answered by the different processes: -bash-3.00$ callgrind_control -s 3775 PID 3775: testprogram [requesting 'Status'...] Number of threads: 1 Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw Functions: 2,674 (executed 1,589,518, contexts 2,674) Basic blocks: 5,822 (executed 28,850,193, call sites 3,594) -bash-3.00$ callgrind_control -s 3775 PID 3775: testprogram [requesting 'Status'...] No information available as instrumentation is switched off. Or when both have active instrumentation: PID 3775: testprogram [requesting 'Status'...] Number of threads: 1 Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw Functions: 2,697 (executed 1,610,896, contexts 2,697) Basic blocks: 5,905 (executed 29,037,620, call sites 3,635) -bash-3.00$ callgrind_control -s 3775 PID 3775: testprogram [requesting 'Status'...] Number of threads: 0 Events collected: Ir Dr Dw I1mr D1mr D1mw I2mr D2mr D2mw Functions: 7,509 (executed 61,323,898, contexts 7,509) Basic blocks: 45,721 (executed 404,289,730, call sites 29,331) Greetings Christoph Bartoschek |
|
From: Christoph B. <bar...@or...> - 2006-09-14 09:20:47
|
Here is a small testprogram that shows the same behaviour:
#include <cstdlib>
#include <cstdio>
extern "C" {
#include <unistd.h>
#include <sys/types.h>
}
int sum = 0;
int main() {
if (fork() == -1) {
perror("Could not create child");
exit(-1);
}
while (true) {
sleep(1);
for (int i = 0; i < 100000000; ++i) sum += i;
}
}
Start it with valgrind --tool=callgrind --instr-atstart=no -v ./a.out
And then look what happens when you iterate:
callgrind_control -i on
callgrind_control -i off
Greetings
Christoph Bartoschek
|