profiling always shows equal values for exclusive and inclusive

ellisonch commented 9 years ago

No matter how I try compiling, sleepy is giving me identical values for exclusive and inclusive times for all functions. It appears to actually be the Exclusive time, since they all add up to 100%.

I'm using msys2's gcc with arguments -std=c11 -O3 -Wall -gdwarf-2 -fno-omit-frame-pointer. I've tried adding -g, but it doesn't seem to change things.

I'm running Very Sleepy CS 0.90 and gcc 4.9.2.

CyberShadow commented 9 years ago

That sounds like Sleepy is unable to read stack traces, although -fno-omit-frame-pointer should ensure that's not the case.

Is this a 32-bit program?

Can you post the .sleepy file? If not, on the Call Stacks tab, do you ever see more than one entry when you click around the function list?

ellisonch commented 9 years ago

Sleepy file: https://drive.google.com/file/d/0B_snSKcb4wIyQTRGTWM5RzJUbkk/view?usp=sharing Original source: https://drive.google.com/file/d/0B_snSKcb4wIyZ1dyTld0dmZ4SVE/view?usp=sharing

Google seems to know these are both zips, but it looks like you can click the download link at the top to download the original.

To compile, I ran: $ gcc -std=c11 -O0 -g -m64 -Wall -fno-omit-frame-pointer -gdwarf-2 driver.c nsort.c orig.c

and to profile, I ran: $ cmd /C "sleepy /r:\"a.exe\""

I also pasted a screenshot of what running sleepy looks like to me.

Also, fwiw, this is the second program I tried profiling, and in both cases got equal exclusive/inclusive. It looks like some of them are slightly different (e.g., nibble_sort() says 0.35/0.45), but they're all really exclusive. E.g., nibble_sort() calls build_histogram() and sort_using_histogram(), so its inclusive should be at least as big.

Let me know if there's any more info I can provide. I'm really liking sleepy otherwise :)

CyberShadow commented 9 years ago

Can you give this version a try? http://dump.thecybershadow.net/58c4691eb50f22da99ad2adbce0a2644/verysleepy-0.91-test-2015-02-17.exe

ellisonch commented 9 years ago

It's somewhat better, but mostly things don't add up.

I would expect main() to have around 99% inclusive, but it only has 34%.
I would also expect the inclusive of main > bench > nibble_sort_orig > nibble_sort_word_orig > read_nibble, since those are the only functions that call those functions. Similarly, main > bench > nibble_sort > sort_using_histogram.
Bench should be approx nibble_sort + nibble_sort_orig
One more e.g.: how could it possibly be that any of my real, named functions takes up more inclusive time than main? main() has less inclusive time than bench(), but main() is the only function that calls bench().

Here is the same profile sorted by inclusive:

CyberShadow commented 9 years ago

Please try this version: http://dump.thecybershadow.net/98079a7c593fd4142330f634c22903ab/verysleepy-0.91-test-2015-02-26.exe

CyberShadow commented 9 years ago

Could you please give the above version a try?

It uses a new MinGW debug information parser.

I would like to release a new version of Very Sleepy, but it needs testing, so I would appreciate if you could see how well it works in your case.

ellisonch commented 9 years ago

I tried it today, but it actually seems worse than before. Now all of the Names are hex numbers, in addition to all of the inclusives == exclusives.

As before, I'm compiling the example I attached above with

$ gcc -std=c11 -O0 -g -m64 -Wall -fno-omit-frame-pointer -gdwarf-2 driver.c nsort.c orig.c

and now running with

$ sleepy.exe //r:a.exe

I also tried compiling with clang, same arguments as above. Same problem. I also tried removing the -gdwarf-2 flag, same problem. Is there a set of flags I should be using?

Additional information, in case it helps:

$ uname
MSYS_NT-6.1

$ gcc -v
Using built-in specs.
COLLECT_GCC=D:\msys64\mingw64\bin\gcc.exe
COLLECT_LTO_WRAPPER=D:/msys64/mingw64/bin/../lib/gcc/x86_64-w64-mingw32/4.9.2/lto-wrapper.exe
Target: x86_64-w64-mingw32
Configured with: ../gcc-4.9.2/configure --prefix=/mingw64 --with-local-prefix=/mingw64/local --build=x86_64-w64-mingw32 --host=x86_64-w64-mingw32 --target=x86_64-w64-mingw32 --with-native-system-header-dir=/mingw64/x86_64-w64-mingw32/include --libexecdir=/mingw64/lib --with-gxx-include-dir=/mingw64/include/c++/4.9.2 --enable-bootstrap --with-arch=x86-64 --with-tune=generic --enable-languages=c,lto,c++,objc,obj-c++,fortran,ada --enable-shared --enable-static --enable-libatomic --enable-threads=posix --enable-graphite --enable-fully-dynamic-string --enable-libstdcxx-time=yes --disable-libstdcxx-pch --disable-libstdcxx-debug --enable-cloog-backend=isl --enable-version-specific-runtime-libs --disable-cloog-version-check --disable-isl-version-check --enable-lto --enable-libgomp --disable-multilib --enable-checking=release --disable-rpath --disable-win32-registry --disable-nls --disable-werror --disable-symvers --with-libiconv --with-system-zlib --with-gmp=/mingw64 --with-mpfr=/mingw64 --with-mpc=/mingw64 --with-isl=/mingw64 --with-cloog=/mingw64 --with-pkgversion='Rev2, Built by MSYS2 project' --with-bugurl=http://sourceforge.net/projects/msys2 --with-gnu-as --with-gnu-ld
Thread model: posix
gcc version 4.9.2 (Rev2, Built by MSYS2 project)

$ clang -v
clang version 3.5.1 (tags/RELEASE_351/final)
Target: x86_64-w64-windows-gnu
Thread model: posix

CyberShadow commented 9 years ago

Strange. With MSys2, and either the gcc package or the mingw-w64-x86_64-gcc package, I'm seeing symbol names in Very Sleepy.

Let's reduce the problem to whether it lies in my compiler or how Very Sleepy runs on your machine. This is the binary my compiler produces. Do you get symbols in attempting to profile it?

ellisonch commented 9 years ago

Okay this is really strange. I have a few observations. If I take your exe and profile it for a few seconds, then stop it, I see symbol names. So I tried running mine and stopping it after a few seconds, and I see symbol names. What I had been doing is letting mine run to completion. When I let mine run to completion (the program terminates), sleepy has no symbol names.

For some reason your program is significantly slower than mine. I tried profiling it for more than 5 minutes and it never finished. When I profile mine, it finishes in about 70 seconds.

The good news is, I can reproduce this even when I shorten the program. If you edit driver.c, you can change static int TESTS = 10000; to static int TESTS = 1000; to make the program take only a few seconds instead of multiple minutes. You should be able to let the program profile to completion, and you'll see the symbol names are missing. If you stop it part way through, the symbol names are there.

Another piece of good news: the inclusive/exclusive looks really good (main is nearly 100%, some quick expectations look met). It's hard to tell if this is true without symbol names, but it definitely works if you stop the profile part way through.

I know this is weird, but I hope this helps (and that you can reproduce it).

CyberShadow commented 9 years ago

Yes, this certainly helps a lot. It makes sense that Dr. MinGW has trouble reading symbols from a process that no longer exists, but I wonder how Microsoft's DbgHelp does it. @jrfonseca, any ideas?

For some reason your program is significantly slower than mine.

Sorry, I should have warned you that I had changed the program to loop indefinitely (so I could debug the profiler without worrying that the profilee exits).

CyberShadow commented 9 years ago

Hmm, it works with Wine's DbgHelp, too...

jrfonseca commented 9 years ago

It makes sense that Dr. MinGW has trouble reading symbols from a process that no longer exists, but I wonder how Microsoft's DbgHelp does it.

Yeah, mgwhelp_module_create in https://github.com/jrfonseca/drmingw/blob/master/src/mgwhelp.c#L341 is only called on the first call to SymFromAddr/SymGetLineFromAddr. And that's probably too late if the process is dead.

MgwHelp needs to slurp the symbols on earlier calls. Not sure exactly which -- maybe SymLoadModuleExW or SymGetModuleInfo64 . But the DbgHelp documentation should tell exactly when symbols are supposed to be read, and MgwHelp need to match it instead of deferring till last minute.

jrfonseca commented 9 years ago

MgwHelp needs to slurp the symbols on earlier calls. Not sure exactly which -- maybe SymLoadModuleExW or SymGetModuleInfo64 .

This should be fixed as of https://github.com/jrfonseca/drmingw/commit/9f62d9587c6606a1a230fcf0d86ca4d1f01db4e4 .

CyberShadow commented 9 years ago

Thank you, it seems to work.

@ellisonch could you please try this build?

CyberShadow commented 7 years ago

As there has been no feedback for over a year, I am going to close this.

Please file a new issue for MinGW bugs that are still present in the build linked to from my comment above.

VerySleepy / verysleepy

profiling always shows equal values for exclusive and inclusive #14