timholy
Errors when code uses 'cfunction'
When I tried to profile this file
https://github.com/joa-quim/IUP.jl/blob/master/examples/sample_.jl
it errored with ERROR: function is not yet c-callable. This is not true since it runs and executes the callbacks when not in profiling mode.
This is Windows and sorry for not having a smaller/easier to run test case.
Joaquim
Two questions:
- Does the sampling profiler built into base not work for you? I think most people find that one so much more useful that this one is rarely used. (There are rare circumstances where the sampling profiler will give you a segfault, because signals are problematic for some C code being profiled.) See also ProfileView for a nice graphical display from the sampling profiler.
- Are you aware that you basically can't profile any more than one function at a time with this profiler? See https://github.com/timholy/IProfile.jl#limitations-of-the-instrumenting-profiler. So you shouldn't be profiling that whole file at once.
Hi, to be honest I did not know about Base.profile and also was not really aware of the iprofiler limitation (though I had quickly read that part of the docs). In my defense let me say that I had tried before with the https://github.com/joa-quim/IUP.jl/blob/master/examples/cbox_.jl file and it had apparently worked. Hence my conclusion about cfunction
I said "apparently" because there seam to be a mismatch between the times reported and the total (wall) time. In fact there seam to be something strange with those files. For example the sample_ example, which takes quite a long time to load, is (after commenting the IupMainLoop() command) reported by to take only
julia> using sample_;
julia> @profile sample()
julia> Profile.print()
4 ....jl\examples\sample_.jl; SampleTest; line: 68
4 ....jl\examples\sample_.jl; SampleTest; line: 232
1 ....jl\examples\sample_.jl; SampleTest; line: 241
So, in conclusion ... I'm still confused. Sorry.
It doesn't matter how long it takes to load, because you're not profiling the using command. How long does @time sample() take to run? If it's ~10ms, then that's consistent. If it's much longer, then it's a little confusing.
Yes, quite confusing because:
julia> using sample_;
julia> @time sample()
elapsed time: 29.950838212 seconds (6685928 bytes allocated)
now, this function has something weird because it runs fine on first call but the window does not pop out on further runs. However, that's the only one that behaves like that and all other examples work fine. And, for example, for another one I see the same patern
julia> using cbox_;
julia> @time cbox()
elapsed time: 3.48744443 seconds (1864184 bytes allocated)
now on another Julia session so that I can measure also the compile time (otherwise the thing is really fast)
julia> using cbox_;
julia> @profile cbox()
julia> Profile.print()
2 ...UP.jl\examples\cbox_.jl; cbox; line: 19
1 ...UP.jl\examples\cbox_.jl; cbox; line: 22
2 ...UP.jl\examples\cbox_.jl; func_1; line: 139
and for this function, @iprofile managed to work and gave times of only ~0.03 sec
Profiling the first execution is more about profiling base Julia itself and understanding the compile chain. If you want to optimize your own function, better to run it once and then profile.
If you say Profile.print(C=true) do you get more counts? Additionally/alternatively, if there's something funky going on, like the main julia thread having SIGUSR1 blocked, perhaps that could explain it? Is this calling some C code?
I don't have the IUP stuff installed and don't have time to do so, so can't investigate myself.
I wanted to investigate the first reun to find out why this particular one takes 30 seconds to start while all the others take less than 3. And yes, it calls lots of C. In fact almost every line make a call to ccall. Maybe this talks to you (those question marks do not antecipate good things)
julia> Profile.print(C=true)
1 ???; uv_process_timers; line: 1849539148
1 ???; ???; line: 13542128
1 ???; ???; line: 12
1 ???; ???; line: -1
1 ???; julia_process_events_3B_16978; line: 1775786122
1 ???; uv_run; line: 1849444364
1 ???; uv_process_async_wakeup_req; line: 1849442854
1 ???; GetQueuedCompletionStatusEx; line: 1996735513
1 ???; GetQueuedCompletionStatusEx; line: -48475025
1 ???; NtRemoveIoCompletionEx; line: 1998988922
Anyway, this is not pressing matter to me. I have lots of other stuff to look at (more than the available time). Anyway and FYI, when you have time/curiosity IUP says it uses GTK on Linux.
Just out of curiosity, when you try profiling the test function here or here, do you get the expected results?
(Perhaps you should run those tests in a fresh Julia session, in case something in that C code is messing with signals.)
Ai ai, no I don't
(the ProfileView test is also different but I don't know how to past images here)
_ _ _(_)_ | A fresh approach to technical computing
(_) | (_) (_) | Documentation: http://docs.julialang.org
_ _ _| |_ __ _ | Type "help()" to list help topics
| | | | | | |/ _` | |
| | |_| | | | (_| | | Version 0.3.0-prerelease+3728 (2014-06-17 19:51 UTC)
_/ |\__'_|_|_|\__'_| | Commit cd36048* (0 days old master)
|__/ | x86_64-w64-mingw32
julia> require("myfunc.jl")
julia> myfunc()
0.9999997778341867
julia> @profile myfunc()
0.999999421026639
julia> Profile.print()
2 random.jl; rand!; line: 129
2 reduce.jl; mapreduce_impl; line: 278
Aha! Looks like you're on Windows. I don't remember for sure, but I think the profiler is more limited on Windows than any other platform. This mostly has to do with limitations of Windows itself (its ability to time short intervals is pretty pathetic compared to Unix systems), and not to any lack of effort in trying to make it work in julia.
It seems from a comment above that the C backtraces are now working on Windows, too. But overall I'm not sure of the current status, CC @vtjnash. The main recommendation seems to be: run your code in a loop many times, to get more samples.