Closed cnuernber closed 3 months ago
It is related specifically to printing the matrix:
user> (require '[uncomplicate.neanderthal.native])
08:41:37.225 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG org.scijava.nativelib.BaseJniExtractor - mappedLib is libneanderthal-mkl-0.33.0.so
08:41:37.230 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG org.scijava.nativelib.BaseJniExtractor - URL is jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
08:41:37.231 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG org.scijava.nativelib.BaseJniExtractor - URL path is file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
08:41:37.233 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG org.scijava.nativelib.BaseJniExtractor - Extracting 'jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so' to '/tmp/libneanderthal-mkl-0.33.04985345375800592404.so'
nil
user> (import '[tech.v3 TMD])
tech.v3.TMD
user> (def mat (TMD/toNeanderthal (TMD/makeDataset {:a [1 2 3]})))
08:42:13.275 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG tech.v3.datatype.functional-api - JDK16 vector ops are not available: Syntax error compiling at (tech/v3/datatype/functional/vecopt.clj:1:1).
08:42:15.522 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG tech.v3.tensor.dimensions.global-to-local - insn custom indexing enabled!
08:42:21.220 [tech.resource.gc ref thread] INFO tech.v3.resource.gc - Reference thread starting
#'user/mat
user> (.toString mat)
"#RealGEMatrix[double, mxn:3x1, layout:column, offset:0]"
user> (println mat)
#RealGEMatrix[double, mxn:3x1, layout:column, offset:0]08:42:31.217 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG org.scijava.nativelib.BaseJniExtractor - mappedLib is libneanderthal-mkl-0.33.0.so
08:42:31.218 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG org.scijava.nativelib.BaseJniExtractor - URL is jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
08:42:31.219 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG org.scijava.nativelib.BaseJniExtractor - URL path is file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
08:42:31.221 [nREPL-session-9fb45b75-7d74-4d05-8248-429a3a23d4d1] DEBUG org.scijava.nativelib.BaseJniExtractor - Extracting 'jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so' to '/tmp/libneanderthal-mkl-0.33.09020889234163087824.so'
▥ ↓ ┓
→ 1.00
→ 2.00
→ 3.00
┗ ┛
I think that lowers the priority quite a bit.
Hi Chris,
Can you please provide a "pure" Neanderthal test where that happens, so I can investigate?
Yes, after playing a bit:
user> (require '[uncomplicate.neanderthal.native :as nt])
08:45:34.793 [nREPL-session-546486a2-3c2f-4a61-96f5-d5576c953afe] DEBUG org.scijava.nativelib.BaseJniExtractor - mappedLib is libneanderthal-mkl-0.33.0.so
08:45:34.799 [nREPL-session-546486a2-3c2f-4a61-96f5-d5576c953afe] DEBUG org.scijava.nativelib.BaseJniExtractor - URL is jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
08:45:34.799 [nREPL-session-546486a2-3c2f-4a61-96f5-d5576c953afe] DEBUG org.scijava.nativelib.BaseJniExtractor - URL path is file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
08:45:34.802 [nREPL-session-546486a2-3c2f-4a61-96f5-d5576c953afe] DEBUG org.scijava.nativelib.BaseJniExtractor - Extracting 'jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so' to '/tmp/libneanderthal-mkl-0.33.04025629859893691270.so'
nil
user> (def mt (nt/dge 3 3))
#'user/mt
user> (.toString mt)
"#RealGEMatrix[double, mxn:3x3, layout:column, offset:0]"
user> (println mt)
#RealGEMatrix[double, mxn:3x3, layout:column, offset:0]08:45:55.171 [nREPL-session-546486a2-3c2f-4a61-96f5-d5576c953afe] DEBUG org.scijava.nativelib.BaseJniExtractor - mappedLib is libneanderthal-mkl-0.33.0.so
08:45:55.173 [nREPL-session-546486a2-3c2f-4a61-96f5-d5576c953afe] DEBUG org.scijava.nativelib.BaseJniExtractor - URL is jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
08:45:55.174 [nREPL-session-546486a2-3c2f-4a61-96f5-d5576c953afe] DEBUG org.scijava.nativelib.BaseJniExtractor - URL path is file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
08:45:55.175 [nREPL-session-546486a2-3c2f-4a61-96f5-d5576c953afe] DEBUG org.scijava.nativelib.BaseJniExtractor - Extracting 'jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so' to '/tmp/libneanderthal-mkl-0.33.05567659273012275972.so'
▥ ↓ ↓ ↓ ┓
→ 0.00 0.00 0.00
→ 0.00 0.00 0.00
→ 0.00 0.00 0.00
┗ ┛
nil
Hi Chris,
I can reproduce this behavior using the Hello World example project: https://github.com/uncomplicate/neanderthal/blob/master/examples/hello-world/src/hello_world/native.clj
When the namespace is loaded the native library is extracted, which is expected.
When the result of (mm a b) is printed out in the REPL, the same DEBUG message appears. That is not expected.
Good news: it only happens at the first implicit printing in the process. Repeated evaluations do not display any logging output.
(A kind of) bad news: I have no idea why this happens, other than Clojure agent confusing the native loader of the 3rd party library.
(A kind of) good news: Loading by sending off agent before namespace loading is not strictly necessary. I introduced that to solve issues on loading native libraries on macOS that some users reported. I don't know whether this is still necessary. If anyone using macOS can check this (I don't have a Mac right now), that might simplify things a bit, and possibly solve this issue. This is the commit where it was introduced: https://github.com/uncomplicate/neanderthal/commit/029f38df9f9b8b5d20fd6cf933e0432aecebaa3a#diff-b91149db483e701376ea3134542bfcf8439747f06acc873396e7510baa161b6a
It is the static initializers for CBLAS, MKL, and LAPACK. The first time each one of these is loaded it's loader unpacks mkl so you can get the unpack to happen 3 times.
user> (defn cfn [nm] (Class/forName nm))
#'user/cfn
user> (cfn "uncomplicate.neanderthal.internal.host.CBLAS")
15:55:08.481 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - mappedLib is libneanderthal-mkl-0.33.0.so
15:55:08.484 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - URL is jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
15:55:08.485 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - URL path is file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
15:55:08.486 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - Extracting 'jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so' to '/tmp/libneanderthal-mkl-0.33.02317052827988730217.so'
uncomplicate.neanderthal.internal.host.CBLAS
user> (cfn "uncomplicate.neanderthal.internal.host.MKL")
15:55:12.460 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - mappedLib is libneanderthal-mkl-0.33.0.so
15:55:12.461 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - URL is jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
15:55:12.462 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - URL path is file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
15:55:12.464 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - Extracting 'jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so' to '/tmp/libneanderthal-mkl-0.33.03202462271287693503.so'
uncomplicate.neanderthal.internal.host.MKL
user> (cfn "uncomplicate.neanderthal.internal.host.LAPACK")
15:55:16.015 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - mappedLib is libneanderthal-mkl-0.33.0.so
15:55:16.017 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - URL is jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
15:55:16.017 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - URL path is file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so
15:55:16.019 [nREPL-session-06ddbf32-9e83-4bc4-8092-232d90583c6b] DEBUG o.scijava.nativelib.BaseJniExtractor - Extracting 'jar:file:/home/chrisn/.m2/repository/uncomplicate/neanderthal-native/0.33.0/neanderthal-native-0.33.0.jar!/lib/amd64-Linux-gpp/jni/libneanderthal-mkl-0.33.0.so' to '/tmp/libneanderthal-mkl-0.33.01772739673324170945.so'
uncomplicate.neanderthal.internal.host.LAPACK
Since 0.48.0 switched to JavaCPP, and we don't use any custom loading any more, this should no longer be a problem.
This also happens if you run a jar on the command line:
I have a feeling this involves how the classloader interacts with static class initialization. In the toNeanderthal method I dereference a delay created at class initialization time.
In the demo here, neanderthal's binary mkl distribution is unpacked 3 times -- something that I can't image is great for performance and if the symbols themselves are loaded 3 times into the executable that also isn't ideal. You can run that demo by cd'ing into that directory and typing scripts/install-run.
This is true whether the javacpp MKL bindings are included in the deps or not.
So far this doesn't matter really aside from logging output but I think it is good to track this.