jbachorik
commented
8 months ago Hi @thpoiani - first of all, thanks for reporting this!
Did you verify that profiling is not working at all? The warning message is appearing because we are trying to check for the profiler library first and then fall back to JFR. Since it is not possible to use native JVMTI agents in the native image we will always fall back to JFR. I will fix the enablement process to be aware of the native image build process and not output noisy warnings. But if you find the profiler not working at all, please, let us know - we would need to investigate because the profiling capacity should not be affected by the warning you are seeing.
thpoiani
Hello Datadog Team!
I'm attempting to activate the profiler in a Quarkus GraalVM Native Executable application, a feature introduced in the
dd-trace-java 1.25.1version. The build step is running within a Linux ARM64 container. However, I'm encountering the following warning, and it appears that the profiler is not successfully enabled:Use the following Dockerfile to reproduce this behaviour:
docker build . --progress=plain
``` #8 60.24 [INFO] --- quarkus:3.6.6:build (default) @ code-with-quarkus --- #8 60.74 [INFO] [io.quarkus.deployment.pkg.steps.JarResultBuildStep] Building native image source jar: /project/code-with-quarkus/target/code-with-quarkus-1.0.0-SNAPSHOT-native-image-source-jar/code-with-quarkus-1.0.0-SNAPSHOT-runner.jar #8 60.94 [INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Building native image from /project/code-with-quarkus/target/code-with-quarkus-1.0.0-SNAPSHOT-native-image-source-jar/code-with-quarkus-1.0.0-SNAPSHOT-runner.jar #8 60.95 [INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GRAALVM 23.1 JDK 21.0.2+13-jvmci-23.1-b30 #8 60.95 [INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] /opt/graalvm/bin/native-image -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dlogging.initial-configurator.min-level=500 -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 --features=io.quarkus.runner.Feature,io.quarkus.runtime.graal.DisableLoggingFeature -J--add-exports=java.security.jgss/sun.security.krb5=ALL-UNNAMED -J--add-opens=java.base/java.text=ALL-UNNAMED -J--add-opens=java.base/java.io=ALL-UNNAMED -J--add-opens=java.base/java.lang.invoke=ALL-UNNAMED -J--add-opens=java.base/java.util=ALL-UNNAMED -H:+UnlockExperimentalVMOptions -H:BuildOutputJSONFile=code-with-quarkus-1.0.0-SNAPSHOT-runner-build-output-stats.json -H:-UnlockExperimentalVMOptions --strict-image-heap -J-javaagent:/project/code-with-quarkus/dd-java-agent.jar -J-Ddd.profiling.enabled=true -H:+UnlockExperimentalVMOptions -H:+AllowFoldMethods -H:-UnlockExperimentalVMOptions -J-Djava.awt.headless=true --no-fallback --link-at-build-time -H:+UnlockExperimentalVMOptions -H:+ReportExceptionStackTraces -H:-UnlockExperimentalVMOptions -H:-AddAllCharsets --enable-url-protocols=http -H:NativeLinkerOption=-no-pie --enable-monitoring=heapdump -H:+UnlockExperimentalVMOptions -H:-UseServiceLoaderFeature -H:-UnlockExperimentalVMOptions -J--add-exports=org.graalvm.nativeimage/org.graalvm.nativeimage.impl=ALL-UNNAMED --exclude-config io\.netty\.netty-codec /META-INF/native-image/io\.netty/netty-codec/generated/handlers/reflect-config\.json --exclude-config io\.netty\.netty-handler /META-INF/native-image/io\.netty/netty-handler/generated/handlers/reflect-config\.json code-with-quarkus-1.0.0-SNAPSHOT-runner -jar code-with-quarkus-1.0.0-SNAPSHOT-runner.jar #8 60.97 Warning: The option '-H:ReflectionConfigurationResources=META-INF/native-image/io.netty/netty-transport/reflection-config.json' is experimental and must be enabled via '-H:+UnlockExperimentalVMOptions' in the future. #8 60.97 Warning: Please re-evaluate whether any experimental option is required, and either remove or unlock it. The build output lists all active experimental options, including where they come from and possible alternatives. If you think an experimental option should be considered as stable, please file an issue. #8 63.74 ======================================================================================================================== #8 63.74 GraalVM Native Image: Generating 'code-with-quarkus-1.0.0-SNAPSHOT-runner' (executable)... #8 63.74 ======================================================================================================================== #8 63.74 For detailed information and explanations on the build output, visit: #8 63.74 https://github.com/oracle/graal/blob/master/docs/reference-manual/native-image/BuildOutput.md #8 63.74 ------------------------------------------------------------------------------------------------------------------------ #8 65.00 [1/8] Initializing... (3.0s @ 0.13GB) #8 65.00 Java version: 21.0.2+13, vendor version: GraalVM CE 21.0.2+13.1 #8 65.00 Graal compiler: optimization level: 2, target machine: armv8-a #8 65.00 C compiler: gcc (redhat, aarch64, 8.5.0) #8 65.00 Garbage collector: Serial GC (max heap size: 80% of RAM) #8 65.00 3 user-specific feature(s): #8 65.00 - com.oracle.svm.thirdparty.gson.GsonFeature #8 65.00 - io.quarkus.runner.Feature: Auto-generated class by Quarkus from the existing extensions #8 65.00 - io.quarkus.runtime.graal.DisableLoggingFeature: Disables INFO logging during the analysis phase #8 65.00 ------------------------------------------------------------------------------------------------------------------------ #8 65.00 7 experimental option(s) unlocked: #8 65.00 - '-H:ClassInitialization' (alternative API option(s): --initialize-at-run-time=com.datadog.profiling.controller.openjdk.events.AvailableProcessorCoresEvent:build_time,com.datadog.profiling.controller.openjdk.events.ProfilerSettingEvent:build_time,com.datadog.profiling.controller.openjdk.events.TimelineEvent:build_time,datadog.trace.api.Config:rerun,datadog.trace.api.Platform:rerun,datadog.trace.api.Platform$Captured:build_time,datadog.trace.api.env.CapturedEnvironment:build_time,datadog.trace.api.ConfigCollector:rerun,datadog.trace.api.ConfigDefaults:build_time,datadog.trace.api.ConfigSetting:build_time,datadog.trace.api.InstrumenterConfig:build_time,datadog.trace.api.Functions:build_time,datadog.trace.api.GlobalTracer:build_time,datadog.trace.api.MethodFilterConfigParser:build_time,datadog.trace.api.WithGlobalTracer:build_time,datadog.trace.api.PropagationStyle:build_time,datadog.trace.bootstrap.config.provider.ConfigConverter:build_time,datadog.trace.bootstrap.config.provider.ConfigProvider:build_time,datadog.trace.bootstrap.config.provider.ConfigProvider$Singleton:build_time,datadog.trace.bootstrap.Agent:build_time,datadog.trace.bootstrap.BootstrapProxy:build_time,datadog.trace.bootstrap.CallDepthThreadLocalMap:build_time,datadog.trace.bootstrap.DatadogClassLoader:build_time,datadog.trace.bootstrap.InstrumentationClassLoader:build_time,datadog.trace.bootstrap.FieldBackedContextStores:build_time,datadog.trace.bootstrap.benchmark.StaticEventLogger:build_time,datadog.trace.bootstrap.instrumentation.java.concurrent.ConcurrentState:build_time,datadog.trace.bootstrap.instrumentation.java.concurrent.ExcludeFilter:build_time,datadog.trace.bootstrap.instrumentation.java.concurrent.QueueTimeHelper:build_time,datadog.trace.bootstrap.instrumentation.java.concurrent.TPEHelper:build_time,datadog.trace.bootstrap.instrumentation.jfr.exceptions.ExceptionCountEvent:build_time,datadog.trace.bootstrap.instrumentation.jfr.exceptions.ExceptionSampleEvent:build_time,datadog.trace.logging.LoggingSettingsDescription:build_time,datadog.trace.logging.simplelogger.SLCompatFactory:build_time,datadog.trace.util.CollectionUtils:build_time,datadog.slf4j.impl.StaticLoggerBinder:build_time,datadog.slf4j.LoggerFactory:build_time,com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap:build_time,net.bytebuddy:build_time,com.sun.proxy:build_time,jnr.enxio.channels:run_time,jnr.unixsocket:run_time, --initialize-at-run-time=io.netty.handler.codec.compression.BrotliDecoder:run_time, --initialize-at-run-time=io.netty.util.AbstractReferenceCounted:run_time,io.netty.util.concurrent.GlobalEventExecutor:run_time,io.netty.util.concurrent.ImmediateEventExecutor:run_time,io.netty.util.concurrent.ScheduledFutureTask:run_time,io.netty.util.internal.ThreadLocalRandom:run_time, --initialize-at-run-time=io.netty.util.NetUtilSubstitutions$NetUtilLocalhost4LazyHolder:run_time, --initialize-at-run-time=io.netty.util.NetUtilSubstitutions$NetUtilLocalhost6LazyHolder:run_time, --initialize-at-run-time=io.netty.util.NetUtilSubstitutions$NetUtilLocalhostLazyHolder:run_time, --initialize-at-run-time=io.netty.util.NetUtilSubstitutions$NetUtilNetworkInterfacesLazyHolder:run_time, --initialize-at-run-time=io.netty.buffer.PooledByteBufAllocator:run_time,io.netty.buffer.ByteBufAllocator:run_time,io.netty.buffer.ByteBufUtil:run_time,io.netty.buffer.AbstractReferenceCountedByteBuf:run_time, --initialize-at-run-time=io.netty.handler.ssl.util.ThreadLocalInsecureRandom:run_time, --initialize-at-run-time=io.netty:build_time, --initialize-at-run-time=io.netty.handler.codec.http.HttpObjectEncoder:run_time,io.netty.handler.codec.http.websocketx.WebSocket00FrameEncoder:run_time,io.netty.handler.codec.http.websocketx.extensions.compression.DeflateDecoder:run_time, --initialize-at-run-time=io.netty:build_time, --initialize-at-run-time=io.netty.handler.codec.http2.Http2CodecUtil:run_time,io.netty.handler.codec.http2.Http2ClientUpgradeCodec:run_time,io.netty.handler.codec.http2.Http2ConnectionHandler:run_time,io.netty.handler.codec.http2.DefaultHttp2FrameWriter:run_time, --initialize-at-run-time=io.netty.resolver.dns.DefaultDnsServerAddressStreamProvider:run_time, --initialize-at-run-time=io.netty.resolver.dns.DnsServerAddressStreamProviders$DefaultProviderHolder:run_time, --initialize-at-run-time=io.netty.resolver.dns.DnsNameResolver:run_time, --initialize-at-run-time=io.netty.resolver.HostsFileEntriesResolver:run_time; origin(s): command line) #8 65.00 - '-H:+AllowFoldMethods' (origin(s): command line) #8 65.00 - '-H:EnableURLProtocols' (alternative API option(s): --enable-http, --enable-http; origin(s): command line) #8 65.00 - '-H:BuildOutputJSONFile' (origin(s): command line) #8 65.00 - '-H:-UseServiceLoaderFeature' (origin(s): command line) #8 65.00 - '-H:IncludeResources' (origin(s): command line) #8 65.00 - '-H:ReflectionConfigurationResources' (origin(s): command line, 'META-INF/native-image/io.netty/netty-transport/native-image.properties' in 'file:///project/code-with-quarkus/target/code-with-quarkus-1.0.0-SNAPSHOT-native-image-source-jar/lib/io.netty.netty-transport-4.1.100.Final.jar') #8 65.01 ------------------------------------------------------------------------------------------------------------------------ #8 65.01 Build resources: #8 65.01 - 5.79GB of memory (75.6% of 7.66GB system memory, determined at start) #8 65.01 - 12 thread(s) (100.0% of 12 available processor(s), determined at start) #8 71.62 [dd.trace 2024-01-23 15:31:01:379 +0000] [ForkJoinPool-2-worker-10] ERROR datadog.common.version.VersionInfo - No version file found #8 73.67 [dd.trace 2024-01-23 15:31:03:439 +0000] [ForkJoinPool-2-worker-11] WARN com.datadog.profiling.ddprof.DatadogProfiler - failed to instantiate Datadog profiler on linux arm64 because: /META-INF/native-libs/linux-arm64/libjavaProfiler.so not found on classpath #8 75.61 [14.527s][warning][jfr] @Name ignored, not a valid Java identifier. #8 84.89 [2/8] Performing analysis... [*****] (19.8s @ 1.28GB) #8 84.90 13,207 reachable types (87.1% of 15,171 total) #8 84.90 19,689 reachable fields (54.4% of 36,171 total) #8 84.94 65,550 reachable methods (57.2% of 114,697 total) #8 84.94 4,087 types, 257 fields, and 3,366 methods registered for reflection #8 84.94 61 types, 61 fields, and 55 methods registered for JNI access #8 84.94 4 native libraries: dl, pthread, rt, z #8 87.58 [3/8] Building universe... (2.6s @ 1.24GB) #8 89.41 [4/8] Parsing methods... [*] (1.8s @ 1.71GB) #8 90.55 [5/8] Inlining methods... [***] (1.0s @ 1.21GB) #8 104.3 [6/8] Compiling methods... [****] (13.8s @ 1.20GB) #8 106.7 [7/8] Layouting methods... [**] (2.4s @ 1.95GB) #8 110.2 [8/8] Creating image... [**] (3.4s @ 1.47GB) #8 110.2 22.42MB (42.22%) for code area: 41,319 compilation units #8 110.2 30.33MB (57.11%) for image heap: 355,402 objects and 65 resources #8 110.2 367.14kB ( 0.68%) for other data #8 110.2 53.11MB in total #8 110.2 ------------------------------------------------------------------------------------------------------------------------ #8 110.2 Top 10 origins of code area: Top 10 object types in image heap: #8 110.2 10.81MB java.base 8.18MB byte[] for code metadata #8 110.2 1.38MB svm.jar (Native Image) 4.57MB byte[] for java.lang.String #8 110.2 798.02kB modified-io.vertx.vertx-core-4.4.6.jar 3.23MB java.lang.Class #8 110.2 744.85kB code-with-quarkus-1.0.0-SNAPSHOT-runner.jar 3.20MB java.lang.String #8 110.2 615.18kB jdk.jfr 1.21MB com.oracle.svm.core.hub.DynamicHubCompanion #8 110.2 493.80kB io.netty.netty-buffer-4.1.100.Final.jar 1001.98kB byte[] for general heap data #8 110.2 435.96kB io.netty.netty-common-4.1.100.Final.jar 742.45kB byte[] for reflection metadata #8 110.2 408.07kB java.management 648.12kB java.lang.String[] #8 110.2 385.72kB io.netty.netty-transport-4.1.100.Final.jar 484.17kB java.util.HashMap$Node #8 110.2 366.21kB io.netty.netty-codec-http-4.1.100.Final.jar 478.71kB c.o.svm.core.hub.DynamicHub$ReflectionMetadata #8 110.2 5.85MB for 189 more packages 6.66MB for 3412 more object types #8 110.2 ------------------------------------------------------------------------------------------------------------------------ #8 110.2 Recommendations: #8 110.2 HEAP: Set max heap for improved and more predictable memory usage. #8 110.2 CPU: Enable more CPU features with '-march=native' for improved performance. #8 110.2 ------------------------------------------------------------------------------------------------------------------------ #8 110.2 5.1s (10.4% of total time) in 206 GCs | Peak RSS: 3.25GB | CPU load: 8.71 #8 110.2 ------------------------------------------------------------------------------------------------------------------------ #8 110.2 Produced artifacts: #8 110.2 /project/code-with-quarkus/target/code-with-quarkus-1.0.0-SNAPSHOT-native-image-source-jar/code-with-quarkus-1.0.0-SNAPSHOT-runner (executable) #8 110.2 /project/code-with-quarkus/target/code-with-quarkus-1.0.0-SNAPSHOT-native-image-source-jar/code-with-quarkus-1.0.0-SNAPSHOT-runner-build-output-stats.json (build_info) #8 110.2 ======================================================================================================================== #8 110.2 Finished generating 'code-with-quarkus-1.0.0-SNAPSHOT-runner' in 48.2s. #8 110.7 [INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] objcopy --strip-debug code-with-quarkus-1.0.0-SNAPSHOT-runner #8 110.8 [INFO] [io.quarkus.deployment.QuarkusAugmentor] Quarkus augmentation completed in 50518ms ```Let me share some assumptions regarding this warning, it could support the investigation:
libjavaProfiler.sofileslibjavaProfile.sofiles are located within thedd-java-agent.jardocker build . --progress=plain
``` #6 5.230 profiling/META-INF: #6 5.230 MANIFEST.MF #6 5.230 native-libs #6 5.230 services #6 5.230 #6 5.230 profiling/META-INF/native-libs: #6 5.230 linux-arm64 #6 5.230 linux-arm64-musl #6 5.230 linux-x64 #6 5.230 linux-x64-musl #6 5.230 #6 5.230 profiling/META-INF/native-libs/linux-arm64: #6 5.230 libjavaProfiler.so #6 5.230 #6 5.230 profiling/META-INF/native-libs/linux-arm64-musl: #6 5.230 libjavaProfiler.so #6 5.230 #6 5.230 profiling/META-INF/native-libs/linux-x64: #6 5.230 libjavaProfiler.so #6 5.230 #6 5.230 profiling/META-INF/native-libs/linux-x64-musl: #6 5.230 libjavaProfiler.so #6 5.230 #6 5.230 profiling/META-INF/services: #6 5.230 com.datadog.profiling.auxiliary.AuxiliaryImplementation$Provider #6 5.230 com.datadog.profiling.controller.jfr.JFRAccess$Factory ```As it accesses resources using
getResourceAsStream, in Native Image you must specify the resources that should be accessible passing the-H:IncludeResourcesor-H:ResourceConfigurationFiles.☝️ Maybe the
libjavaProfiler.sofiles are not accessible during the Native Build step.Kindly request the Datadog Team to investigate this issue. 🙇
I believe that https://github.com/DataDog/dd-trace-java/issues/6443 seems somehow related, as the NativeImageGeneratorRunnerInstrumentation.java tries to include
.*dd-.*version$version files