Profiling doesn't work at all on OS X

[newhouseb]

If I run the following from the documentation here: http://julia.readthedocs.org/en/latest/stdlib/profile/

julia> function myfunc()
           A = rand(100, 100, 200)
           max(A)
       end
myfunc (generic function with 1 method)

julia> myfunc()
WARNING: max(x) is deprecated, use maximum(x) instead.
0.9999994755239174

julia> @profile myfunc()
WARNING: max(x) is deprecated, use maximum(x) instead.
0.9999998409036248

julia> Profile.print()

julia>

This may be related to: #3469, as I never get any backtraces either.

I'm running Version 0.3.0-prerelease+2156 (2014-03-24 16:53 UTC), Commit c81664a* (2 days old master), x86_64-apple-darwin13.0.0. Installed through homebrew.

Happy to explore, debug, but I'm relatively new to Julia so would need some pointers on where to poke around.

[rened]

I tried to reproduce this, but on the current master, as well as on c81664a and a 24 days old build this works. In all cases julia was installed manually though, on 10.9.2.

  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 0.3.0-prerelease+2177 (2014-03-27 01:39 UTC)
 _/ |\__'_|_|_|\__'_|  |  Commit 7d475bf* (0 days old master)
|__/                   |  x86_64-apple-darwin13.1.0

julia> function myfunc()
                  A = rand(100, 100, 200)
                  max(A)
              end
myfunc (generic function with 1 method)

julia> myfunc()
WARNING: max(x) is deprecated, use maximum(x) instead.
 in max at deprecated.jl:26
 in myfunc at none:3
0.999999615846902

julia> @profile myfunc()
0.9999998838460968

julia> Profile.print()
           17 profile.jl; anonymous; line: 14
            12 none; myfunc; line: 2
             12 librandom.jl; dsfmt_gv_fill_array_close_open!; line: 129
            5  none; myfunc; line: 3
             2 deprecated.jl; max; line: 26
                 1 util.jl; warn; line: 508
                    1 set.jl; in; line: 16
                     1 dict.jl; ht_keyindex; line: 451
             3 deprecated.jl; max; line: 28
              1 reduce.jl; maximum_rgn; line: 396
              2 reduce.jl; maximum_rgn; line: 397

perhaps @staticfloat can comment on what might be different in the homebrew builds?

[staticfloat]

I can confirm that this happens in the Homebrew build. I'll try to take a look at this soon.

[staticfloat]

@timholy Do you have any idea why this might be happening? It looks to me like the profile data structures are just never getting filled.

[timholy]

@newhouseb, am I right in understanding that you don't get backtraces from any errors? #3469 is deeply annoying but relatively infrequent, and tends to happen only for functions that are inlined. If a function like

function myfunc()
    b = true
    if b
        error("1")
    else
        error("0")
    end
end

does not give you a backtrace, then (1) it's not #3469, and (2) it's not profiler-specific. Instead there's something broken in your backtraces. The profiler simply co-opts that infrastructure for its own purposes.

[timholy]

(Welcome back @staticfloat! We missed you while you were gone 😄)

[newhouseb]

Yes, running your sample above, @timholy, I get:

julia> myfunc()
ERROR: 1

If it's not working through homebrew would it be unreasonable to assume that some compiler setting/flag is doing strange things and therefore I might be able to narrow down the problem by compiling from source? I'll go ahead and try that anyway in a bit.

[staticfloat]

@newhouseb I can confirm that compiling from source works and compiling through Homebrew doesn't. Unfortunately, there's a lot of configuration done in the Homebrew formula, so narrowing down exactly what's changing this could be difficult. I'm betting it has something to do with libunwind though.

[Keno]

Are you using libosxunwind?

[dpo]

Having the same issue on 10.8.5 (clang 425), built with Homebrew. Julia 0.3.0-prerelease+2690 (2014-04-20 12:15 UTC).

[staticfloat]

I'm assigning myself so that I don't lose track of this.

[randy3k]

I have the same problem, also built with homebrew...

[staticfloat]

Alright. I spent a while digging into how this all works, and I've found the culprit.

First off, the profiler is working, but all backtraces on Homebrew-built are marked as coming from C, so unless you pass C=true to Profile.print(), nothing is going to get printed.

The reason every backtrace is marked as C is because Julia apparently is not getting any debug information about Julia-built objects. I put on my debugging hat and figured out that NotifyFunctionEmitted is not getting called at all on Homebrew-built julia versions, and that this happens any time you are running on llvm-3.4.

@loladiro @vtjnash I'm over my head in LLVM now, is this expected behavior?

For everyone else, locally applying this patch to the julia formula should get you up and running with the Profiler:

diff --git a/julia.rb b/julia.rb
index 160237c..7f4d6c8 100644
--- a/julia.rb
+++ b/julia.rb
@@ -32,7 +32,7 @@ class Julia < Formula

   head do
     url 'https://github.com/JuliaLang/julia.git', :using => GitNoDepthDownloadStrategy
-    depends_on "llvm"
+    depends_on "homebrew/versions/llvm33"
   end

   depends_on "readline"
@@ -157,7 +157,7 @@ class Julia < Formula
     end

     # Tell julia about our llc, if it's been named nonstandardly
-    if build.head?
+    if false
       if which( 'llc' ) == nil
         build_opts << "LLVM_LLC=llc-#{Formula["llvm"].version}"
       end

[ihnorton]

Yes - the issue is that we turn on MCJIT with LLVM3.4, and NotifyFunctionEmitted is no longer called. MCJIT emits everything in a module at once and then calls NotifyObjectEmitted instead. I'm partway through an implementation adding support for this as a side effect of #6635. Should have a PR tonight or tomorrow night.

IMHO binaries really should be using a consistent version of LLVM so that we don't run into weird mystery cases. [edit: which we are!]

[staticfloat]

These aren't the OSX binaries; these are user's personal Homebrew builds.

[staticfloat]

And thanks for the explanation. :) I knew that MCJIT did a lot more things on a module-by-module basis, interesting to see the small things that pop up everywhere because of that.

[ihnorton]

Ah, didn't read the rest of the thread. Anyway, that's why, and it should hopefully be fixed on master pretty soon. Nice sleuthing!

[JeffBezanson]

We really need to ensure the expected version of LLVM is used.

[staticfloat]

I don't think there's anything unusual going on here; we support compiling against LLVM 3.4, right? Julia is being compiled locally, on the user's machines with full knowledge that she's getting built against 3.4. The only bug here is that even when building against 3.4 we expect to be able to use NotifyFunctionEmitted, which we apparently cannot.

[JeffBezanson]

In my opinion LLVM 3.4 is not supported. Just for fun a few hooks were put in for it, probably for @loladiro 's own testing of MCJIT. But we knew not everything would work, which is why it is not supported.

[staticfloat]

Ah, I didn't know that. I'll go ahead and change the Homebrew formula to requiring llvm-3.3 then.

[Keno]

MCJIT basically works, but still has problems with backtraces, which I didn't get to address yet.

[pwl]

I am running Linux and have encountered exactly the same problem. For my system (archlinux) only llvm-3.4 is avaiable and there is no easy way to downgrade it to llvm-3.3. Is there any way I can get the profiler running without downgrading llvm?

[ihnorton]

You should always be able to build LLVM yourself, regardless of the system-provided version; follow the build instructions in the main README.

[timholy]

Right, just git cloneing julia and typing make should build llvm-3.3 for you. It will remain specific to julia, so it won't affect anything else on your system.

[jakebolewski]

@pwl I use Arch linux as well, you just need to edit the PKGBUILD to no use the system llvm.

[pwl]

@jakebolewski Thanks, I set the flag USE_SYSTEM_LLVM to 0 in PKGBUILD and now profiling works just fine now (although build time increased significantly). Sorry for bringing my problem up in the issue thread.

[kmsquire]

As long as LLVM is not updated, the build time should go back to normal for
future builds.

Cheers, Kevin

On Monday, May 5, 2014, Paweł Biernat notifications@github.com wrote:

@jakebolewski https://github.com/jakebolewski Thanks, I set the flag
USE_SYSTEM_LLVM to 0 in PKGBUILD and now profiling works just fine now
(although build time increased significantly). Sorry for bringing my
problem in the issue thread.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/6275#issuecomment-42194130
.

[timholy]

By happenstance I had a user of HDF5.jl file an issue that made it clear he was suffering from this problem (on Arch Linux) too. It occurred to me that not having good backtraces might lead to a "suffer in silence" kind of problem, and it might take a while for people to realize what they are missing. In a1a4701 I added an explicit test for backtraces (I can't be sure it's comprehensive enough to catch this issue), and modified the README to encourage users to run make testall before seriously using Julia. (The latter is presumably good advice anyway, as it should catch all sorts of platform-specific bugs.)

[cdsousa]

HDF5.jl user here. Indeed I was "suffering in silence" 😆 (and debugging with printlns and @whichs), although I felt I miss something since I'd got backtraces in the past. I'll forward this issue to the Julia package maintainers of Arch Linux.

[xyproto]

Packager of the Julia package on Arch Linux here. I'm looking into fixing this issue on Arch Linux. See also: https://bugs.archlinux.org/task/40231.